Skip to content

Commit bceb050

Browse files
chyezhclaude
andauthored
enhance: Refactor the log library of milvus, support scoped context logging (#47610)
issue: #35917 design doc: milvus-io/milvus-design-docs#14 Summary This PR implements the mlog package - a context-aware logging library built on https://github.com/uber-go/zap, designed specifically for Milvus distributed systems. Key Features - Mandatory Context Passing - All logging operations require a context, ensuring request traceability - Zero-Overhead Abstraction - Uses type aliases to avoid wrapper overhead, performance comparable to direct zap usage - Automatic Field Accumulation - Context fields automatically accumulate through the call chain, child contexts inherit parent fields - Cross-Service Propagation - Supports propagating key fields via gRPC metadata for distributed tracing - Lazy Encoding - Uses WithLazy for deferred field encoding, avoiding encoding overhead when log level is disabled - Component-Level Logger - Provides optimized Logger type that selects the logger with more pre-encoded fields to minimize runtime encoding --------- Signed-off-by: chyezh <chyezh@outlook.com> Co-authored-by: Claude Opus 4.5 <noreply@anthropic.com>
1 parent d7f0751 commit bceb050

17 files changed

Lines changed: 5403 additions & 0 deletions

pkg/mlog/README.md

Lines changed: 519 additions & 0 deletions
Large diffs are not rendered by default.

pkg/mlog/README_AGENT.md

Lines changed: 110 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,110 @@
1+
# mlog — AI Agent Logging Guide
2+
3+
- ALWAYS USE `github.com/milvus-io/milvus/pkg/v2/mlog` PACKAGE TO LOG.
4+
- NEVER USE `zap` OR `log` PACKAGE DIRECTLY.
5+
6+
## Rules
7+
8+
1. Every log call must receive a `ctx context.Context`. Never pass `nil`. Choose ctx by priority: function parameter ctx > struct-level ctx (e.g. `s.ctx`) > `context.TODO()`.
9+
2. If the current struct has a `*mlog.Logger` field, use it. Otherwise use package-level functions like `mlog.Info(ctx, ...)`.
10+
3. When a predefined `FieldXxx` exists for a key, always use `FieldXxx(val)`. Never write `mlog.Int64("segment_id", v)`.
11+
4. In loops or hot paths, use `Rated` variants: `mlog.RatedInfo(ctx, limit, msg, fields...)`.
12+
5. For Debug logs on hot paths where field construction is expensive (`fmt.Sprintf`, serialization, iteration), guard with `LevelEnabled`.
13+
6. `mlog.Any` has poor performance. Use only when the type is unknown.
14+
15+
## Logging
16+
17+
```go
18+
// Package-level
19+
mlog.Info(ctx, "segment loaded", mlog.FieldSegmentID(id), mlog.Duration("cost", d))
20+
mlog.Error(ctx, "flush failed", mlog.Err(err))
21+
22+
// Logger method (when struct has *mlog.Logger)
23+
l.Info(ctx, "search started", mlog.Int64("nq", nq))
24+
25+
// Rate-limited (loops / hot paths). limit = events per second; rate.Inf = unlimited
26+
mlog.RatedWarn(ctx, 1.0, "lagging", mlog.Int64("gap", gap))
27+
28+
// LevelEnabled guard (hot path + expensive field construction)
29+
if mlog.LevelEnabled(mlog.DebugLevel) {
30+
mlog.Debug(ctx, "detail", mlog.String("dump", strings.Join(paths, ",")))
31+
}
32+
```
33+
34+
**Choosing log level:**
35+
36+
| Level | When to use |
37+
|---|---|
38+
| `Debug` | Internal state details useful only during development or troubleshooting. Disabled in production by default. |
39+
| `Info` | Normal operational events: startup, shutdown, configuration loaded, request completed, task finished. |
40+
| `Warn` | Unexpected but recoverable situations: timeout retry, transient RPC failure with retry, fallback path taken, deprecated API called. |
41+
| `Error` | Operation failed and cannot be completed: unrecoverable RPC failure, data corruption, invariant broken. Always attach `mlog.Err(err)`. |
42+
| `Fatal` | Process cannot continue. Calls `os.Exit(1)`. Use only during initialization for unrecoverable setup failures. |
43+
| `DPanic` / `Panic` | Reserved for "should never happen" invariant violations. Rarely used. |
44+
Each level has a corresponding `Rated` variant. Logger methods have the same signature as package-level functions.
45+
46+
## Constructing Fields
47+
48+
Priority: `FieldXxx(val)` > typed constructor like `mlog.String(key, val)` > `mlog.Any(key, val)`.
49+
50+
**Predefined FieldXxx** (key is built-in; never write the key string manually):
51+
52+
| Function | Type | Built-in Key |
53+
|---|---|---|
54+
| `FieldNodeID(v)` | int64 | `node_id` |
55+
| `FieldModule(v)` | string | `module` |
56+
| `FieldTraceID(v)` | string | `trace_id` |
57+
| `FieldSpanID(v)` | string | `span_id` |
58+
| `FieldDbID(v)` | int64 | `db_id` |
59+
| `FieldDbName(v)` | string | `db_name` |
60+
| `FieldCollectionID(v)` | int64 | `collection_id` |
61+
| `FieldCollectionName(v)` | string | `collection_name` |
62+
| `FieldPartitionID(v)` | int64 | `partition_id` |
63+
| `FieldPartitionName(v)` | string | `partition_name` |
64+
| `FieldSegmentID(v)` | int64 | `segment_id` |
65+
| `FieldIndexID(v)` | int64 | `index_id` |
66+
| `FieldFieldID(v)` | int64 | `field_id` |
67+
| `FieldTaskID(v)` | int64 | `task_id` |
68+
| `FieldBroadcastID(v)` | int64 | `broadcast_id` |
69+
| `FieldJobID(v)` | int64 | `job_id` |
70+
| `FieldBuildID(v)` | int64 | `build_id` |
71+
| `FieldVChannel(v)` | string | `vchannel` |
72+
| `FieldPChannel(v)` | string | `pchannel` |
73+
| `FieldMessageID(v)` | ObjectMarshaler | `message_id` |
74+
| `FieldMessage(v)` | ObjectMarshaler | `message` |
75+
76+
**Generic typed constructors** (use when no predefined FieldXxx exists; function names match Go types):
77+
`String` / `Int64` / `Int` / `Float64` / `Bool` / `Duration` / `Time` / `Stringer` / `Binary` / `Err` (key fixed to `"error"`), etc.
78+
Each type has pointer variant `Xxxp` and slice variant `Xxxs`. See `field.go` for the full list.
79+
80+
## Binding Fields
81+
82+
```
83+
Should the field follow the request chain (bind to ctx)?
84+
├─ Yes → ctx = mlog.WithFields(ctx, fields...)
85+
│ Lazily encoded; fields keep insertion order and duplicate keys are preserved.
86+
│ To propagate across gRPC, add OptPropagated():
87+
│ mlog.WithFields(ctx, mlog.FieldCollectionID(id, mlog.OptPropagated()))
88+
89+
└─ No → Bind to a Logger
90+
├─ Component-level (struct lifetime) → mlog.With(fields...) stored as a field
91+
├─ Function-level (shared across multiple log calls in scope) → l := mlog.With(fields...) as local var
92+
└─ Fields may be filtered by level → mlog.WithLazy(fields...) — lazily encoded
93+
```
94+
95+
```go
96+
// Bind to ctx at request entry point
97+
ctx = mlog.WithFields(ctx, mlog.FieldCollectionID(collID), mlog.String("request_id", reqID))
98+
99+
// Bind to Logger at component construction
100+
l := mlog.With(mlog.FieldModule("querynode"), mlog.FieldNodeID(nodeID))
101+
102+
// Local Logger to eliminate repeated fields within a function
103+
func (s *compactor) compact(ctx context.Context, segID int64, plan *Plan) error {
104+
l := mlog.With(mlog.FieldSegmentID(segID), mlog.Int64("planID", plan.ID))
105+
l.Info(ctx, "compact start")
106+
// ...
107+
l.Info(ctx, "compact done", mlog.Duration("cost", elapsed))
108+
return nil
109+
}
110+
```

pkg/mlog/benchmark_test.go

Lines changed: 255 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,255 @@
1+
//go:build test
2+
3+
package mlog
4+
5+
import (
6+
"context"
7+
"testing"
8+
9+
"go.uber.org/zap"
10+
"go.uber.org/zap/zapcore"
11+
"golang.org/x/time/rate"
12+
)
13+
14+
// discardWriteSyncer is a WriteSyncer that discards all output.
15+
type discardWriteSyncer struct{}
16+
17+
func (d discardWriteSyncer) Write(p []byte) (int, error) { return len(p), nil }
18+
func (d discardWriteSyncer) Sync() error { return nil }
19+
20+
// newBenchLogger creates a zap logger that encodes JSON but discards output.
21+
func newBenchLogger() *zap.Logger {
22+
enc := zapcore.NewJSONEncoder(zap.NewProductionEncoderConfig())
23+
core := zapcore.NewCore(enc, discardWriteSyncer{}, zapcore.DebugLevel)
24+
return zap.New(core)
25+
}
26+
27+
// setupBench initializes mlog with a discard logger for benchmarks.
28+
func setupBench() {
29+
SetLevel(DebugLevel)
30+
initForTest(newBenchLogger())
31+
}
32+
33+
// ---------------------------------------------------------------------------
34+
// Baseline: native zap.Logger
35+
// ---------------------------------------------------------------------------
36+
37+
func BenchmarkZapInfo(b *testing.B) {
38+
logger := newBenchLogger()
39+
b.ResetTimer()
40+
for b.Loop() {
41+
logger.Info("benchmark message")
42+
}
43+
}
44+
45+
func BenchmarkZapInfoWithFields(b *testing.B) {
46+
logger := newBenchLogger()
47+
b.ResetTimer()
48+
for b.Loop() {
49+
logger.Info("benchmark message",
50+
zap.String("key1", "value1"),
51+
zap.Int64("key2", 42),
52+
zap.String("key3", "value3"),
53+
)
54+
}
55+
}
56+
57+
func BenchmarkZapInfoDisabledLevel(b *testing.B) {
58+
enc := zapcore.NewJSONEncoder(zap.NewProductionEncoderConfig())
59+
core := zapcore.NewCore(enc, discardWriteSyncer{}, zapcore.WarnLevel)
60+
logger := zap.New(core)
61+
b.ResetTimer()
62+
for b.Loop() {
63+
logger.Info("benchmark message")
64+
}
65+
}
66+
67+
// ---------------------------------------------------------------------------
68+
// Package-level functions
69+
// ---------------------------------------------------------------------------
70+
71+
func BenchmarkMlogInfo(b *testing.B) {
72+
setupBench()
73+
defer resetLogger()
74+
ctx := context.Background()
75+
b.ResetTimer()
76+
for b.Loop() {
77+
Info(ctx, "benchmark message")
78+
}
79+
}
80+
81+
func BenchmarkMlogInfoWithFields(b *testing.B) {
82+
setupBench()
83+
defer resetLogger()
84+
ctx := context.Background()
85+
b.ResetTimer()
86+
for b.Loop() {
87+
Info(ctx, "benchmark message",
88+
String("key1", "value1"),
89+
Int64("key2", 42),
90+
String("key3", "value3"),
91+
)
92+
}
93+
}
94+
95+
func BenchmarkMlogInfoWithContextFields(b *testing.B) {
96+
setupBench()
97+
defer resetLogger()
98+
ctx := WithFields(context.Background(),
99+
String("trace_id", "abc-123"),
100+
Int64("node_id", 1),
101+
)
102+
b.ResetTimer()
103+
for b.Loop() {
104+
Info(ctx, "benchmark message")
105+
}
106+
}
107+
108+
func BenchmarkMlogInfoWithContextAndCallFields(b *testing.B) {
109+
setupBench()
110+
defer resetLogger()
111+
ctx := WithFields(context.Background(),
112+
String("trace_id", "abc-123"),
113+
Int64("node_id", 1),
114+
)
115+
b.ResetTimer()
116+
for b.Loop() {
117+
Info(ctx, "benchmark message",
118+
String("key1", "value1"),
119+
Int64("key2", 42),
120+
String("key3", "value3"),
121+
)
122+
}
123+
}
124+
125+
func BenchmarkMlogInfoDisabledLevel(b *testing.B) {
126+
setupBench()
127+
defer resetLogger()
128+
SetLevel(WarnLevel)
129+
ctx := context.Background()
130+
b.ResetTimer()
131+
for b.Loop() {
132+
Info(ctx, "benchmark message")
133+
}
134+
}
135+
136+
// ---------------------------------------------------------------------------
137+
// Logger methods
138+
// ---------------------------------------------------------------------------
139+
140+
func BenchmarkMlogLoggerInfo(b *testing.B) {
141+
setupBench()
142+
defer resetLogger()
143+
l := With(String("component", "benchmark"))
144+
ctx := context.Background()
145+
b.ResetTimer()
146+
for b.Loop() {
147+
l.Info(ctx, "benchmark message")
148+
}
149+
}
150+
151+
func BenchmarkMlogLoggerInfoWithFields(b *testing.B) {
152+
setupBench()
153+
defer resetLogger()
154+
l := With(String("component", "benchmark"))
155+
ctx := context.Background()
156+
b.ResetTimer()
157+
for b.Loop() {
158+
l.Info(ctx, "benchmark message",
159+
String("key1", "value1"),
160+
Int64("key2", 42),
161+
String("key3", "value3"),
162+
)
163+
}
164+
}
165+
166+
func BenchmarkMlogLoggerInfoWithContextFields(b *testing.B) {
167+
setupBench()
168+
defer resetLogger()
169+
l := With(String("component", "benchmark"))
170+
ctx := WithFields(context.Background(),
171+
String("trace_id", "abc-123"),
172+
Int64("node_id", 1),
173+
)
174+
b.ResetTimer()
175+
for b.Loop() {
176+
l.Info(ctx, "benchmark message")
177+
}
178+
}
179+
180+
func BenchmarkMlogLoggerInfoDisabledLevel(b *testing.B) {
181+
setupBench()
182+
defer resetLogger()
183+
SetLevel(WarnLevel)
184+
l := With(String("component", "benchmark"))
185+
ctx := context.Background()
186+
b.ResetTimer()
187+
for b.Loop() {
188+
l.Info(ctx, "benchmark message")
189+
}
190+
}
191+
192+
// ---------------------------------------------------------------------------
193+
// Rated functions
194+
// ---------------------------------------------------------------------------
195+
196+
func BenchmarkMlogRatedInfoAllowed(b *testing.B) {
197+
setupBench()
198+
defer resetLogger()
199+
resetRatedRegistry()
200+
ctx := context.Background()
201+
b.ResetTimer()
202+
for b.Loop() {
203+
RatedInfo(ctx, rate.Inf, "benchmark message")
204+
}
205+
}
206+
207+
func BenchmarkMlogRatedInfoSuppressed(b *testing.B) {
208+
setupBench()
209+
defer resetLogger()
210+
resetRatedRegistry()
211+
ctx := context.Background()
212+
// First call goes through, rest are suppressed with rate=0
213+
RatedInfo(ctx, 0, "benchmark message")
214+
b.ResetTimer()
215+
for b.Loop() {
216+
RatedInfo(ctx, 0, "benchmark message")
217+
}
218+
}
219+
220+
func BenchmarkMlogRatedInfoDisabledLevel(b *testing.B) {
221+
setupBench()
222+
defer resetLogger()
223+
SetLevel(WarnLevel)
224+
resetRatedRegistry()
225+
ctx := context.Background()
226+
b.ResetTimer()
227+
for b.Loop() {
228+
RatedInfo(ctx, rate.Inf, "benchmark message")
229+
}
230+
}
231+
232+
func BenchmarkMlogLoggerRatedInfoAllowed(b *testing.B) {
233+
setupBench()
234+
defer resetLogger()
235+
resetRatedRegistry()
236+
l := With(String("component", "benchmark"))
237+
ctx := context.Background()
238+
b.ResetTimer()
239+
for b.Loop() {
240+
l.RatedInfo(ctx, rate.Inf, "benchmark message")
241+
}
242+
}
243+
244+
func BenchmarkMlogLoggerRatedInfoSuppressed(b *testing.B) {
245+
setupBench()
246+
defer resetLogger()
247+
resetRatedRegistry()
248+
l := With(String("component", "benchmark"))
249+
ctx := context.Background()
250+
l.RatedInfo(ctx, 0, "benchmark message")
251+
b.ResetTimer()
252+
for b.Loop() {
253+
l.RatedInfo(ctx, 0, "benchmark message")
254+
}
255+
}

0 commit comments

Comments
 (0)