Skip to content

Commit 177cd8d

Browse files
seankhliaoseankhliao
committed
log/slog: use a pooled json encoder
goos: linux goarch: amd64 pkg: log/slog/internal/benchmarks cpu: 12th Gen Intel(R) Core(TM) i7-1260P │ old.txt │ new.txt │ │ sec/op │ sec/op vs base │ Attrs/JSON_discard/5_args-16 217.4n ± 8% 217.7n ± 5% ~ (p=0.971 n=10) Attrs/JSON_discard/5_args_ctx-16 217.8n ± 8% 219.0n ± 6% ~ (p=0.723 n=10) Attrs/JSON_discard/10_args-16 482.8n ± 4% 418.5n ± 1% -13.33% (p=0.000 n=10) Attrs/JSON_discard/40_args-16 1.709µ ± 1% 1.413µ ± 1% -17.33% (p=0.000 n=10) geomean 444.5n 409.7n -7.84% │ old.txt │ new.txt │ │ B/op │ B/op vs base │ Attrs/JSON_discard/5_args-16 0.000 ± 0% 0.000 ± 0% ~ (p=1.000 n=10) ¹ Attrs/JSON_discard/5_args_ctx-16 0.000 ± 0% 0.000 ± 0% ~ (p=1.000 n=10) ¹ Attrs/JSON_discard/10_args-16 498.0 ± 0% 273.0 ± 0% -45.18% (p=0.000 n=10) Attrs/JSON_discard/40_args-16 2.383Ki ± 0% 1.614Ki ± 0% -32.25% (p=0.000 n=10) geomean ² -21.94% ² ¹ all samples are equal ² summaries must be >0 to compute geomean │ old.txt │ new.txt │ │ allocs/op │ allocs/op vs base │ Attrs/JSON_discard/5_args-16 0.000 ± 0% 0.000 ± 0% ~ (p=1.000 n=10) ¹ Attrs/JSON_discard/5_args_ctx-16 0.000 ± 0% 0.000 ± 0% ~ (p=1.000 n=10) ¹ Attrs/JSON_discard/10_args-16 7.000 ± 0% 3.000 ± 0% -57.14% (p=0.000 n=10) Attrs/JSON_discard/40_args-16 22.000 ± 0% 8.000 ± 0% -63.64% (p=0.000 n=10) geomean ² -37.17% ² ¹ all samples are equal ² summaries must be >0 to compute geomean Fixes #74645 Change-Id: I185667cd6caa6a8251e75233eb659c1fd449deaa Reviewed-on: https://go-review.googlesource.com/c/go/+/705555 LUCI-TryBot-Result: Go LUCI <golang-scoped@luci-project-accounts.iam.gserviceaccount.com> Reviewed-by: Jonathan Amsterdam <jba@google.com> Reviewed-by: Michael Knyszek <mknyszek@google.com>
1 parent 2353c15 commit 177cd8d

File tree

4 files changed

+80
-15
lines changed

4 files changed

+80
-15
lines changed

‎src/log/slog/internal/benchmarks/benchmarks.go‎

Lines changed: 7 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -31,12 +31,19 @@ import (
3131

3232
const testMessage = "Test logging, but use a somewhat realistic message length."
3333

34+
type event struct {
35+
ID string
36+
Index int
37+
Flag bool
38+
}
39+
3440
var (
3541
testTime = time.Date(2022, time.May, 1, 0, 0, 0, 0, time.UTC)
3642
testString = "7e3b3b2aaeff56a7108fe11e154200dd/7819479873059528190"
3743
testInt = 32768
3844
testDuration = 23 * time.Second
3945
testError = errors.New("fail")
46+
testEvent = event{"abcdefgh", 65536, true}
4047
)
4148

4249
var testAttrs = []slog.Attr{

‎src/log/slog/internal/benchmarks/benchmarks_test.go‎

Lines changed: 9 additions & 9 deletions
Original file line numberDiff line numberDiff line change
@@ -80,12 +80,12 @@ func BenchmarkAttrs(b *testing.B) {
8080
slog.Int("status", testInt),
8181
slog.Duration("duration", testDuration),
8282
slog.Time("time", testTime),
83-
slog.Any("error", testError),
83+
slog.Any("event", testEvent),
8484
slog.String("string", testString),
8585
slog.Int("status", testInt),
8686
slog.Duration("duration", testDuration),
8787
slog.Time("time", testTime),
88-
slog.Any("error", testError),
88+
slog.Any("event", testEvent),
8989
)
9090
},
9191
},
@@ -103,37 +103,37 @@ func BenchmarkAttrs(b *testing.B) {
103103
slog.Int("status", testInt),
104104
slog.Duration("duration", testDuration),
105105
slog.Time("time", testTime),
106-
slog.Any("error", testError),
106+
slog.Any("event", testEvent),
107107
slog.String("string", testString),
108108
slog.Int("status", testInt),
109109
slog.Duration("duration", testDuration),
110110
slog.Time("time", testTime),
111-
slog.Any("error", testError),
111+
slog.Any("event", testEvent),
112112
slog.String("string", testString),
113113
slog.Int("status", testInt),
114114
slog.Duration("duration", testDuration),
115115
slog.Time("time", testTime),
116-
slog.Any("error", testError),
116+
slog.Any("event", testEvent),
117117
slog.String("string", testString),
118118
slog.Int("status", testInt),
119119
slog.Duration("duration", testDuration),
120120
slog.Time("time", testTime),
121-
slog.Any("error", testError),
121+
slog.Any("event", testEvent),
122122
slog.String("string", testString),
123123
slog.Int("status", testInt),
124124
slog.Duration("duration", testDuration),
125125
slog.Time("time", testTime),
126-
slog.Any("error", testError),
126+
slog.Any("event", testEvent),
127127
slog.String("string", testString),
128128
slog.Int("status", testInt),
129129
slog.Duration("duration", testDuration),
130130
slog.Time("time", testTime),
131-
slog.Any("error", testError),
131+
slog.Any("event", testEvent),
132132
slog.String("string", testString),
133133
slog.Int("status", testInt),
134134
slog.Duration("duration", testDuration),
135135
slog.Time("time", testTime),
136-
slog.Any("error", testError),
136+
slog.Any("event", testEvent),
137137
)
138138
},
139139
},

‎src/log/slog/json_handler.go‎

Lines changed: 31 additions & 6 deletions
Original file line numberDiff line numberDiff line change
@@ -137,15 +137,40 @@ func appendJSONValue(s *handleState, v Value) error {
137137
return nil
138138
}
139139

140-
func appendJSONMarshal(buf *buffer.Buffer, v any) error {
140+
type jsonEncoder struct {
141+
buf *bytes.Buffer
141142
// Use a json.Encoder to avoid escaping HTML.
142-
var bb bytes.Buffer
143-
enc := json.NewEncoder(&bb)
144-
enc.SetEscapeHTML(false)
145-
if err := enc.Encode(v); err != nil {
143+
json *json.Encoder
144+
}
145+
146+
var jsonEncoderPool = &sync.Pool{
147+
New: func() any {
148+
enc := &jsonEncoder{
149+
buf: new(bytes.Buffer),
150+
}
151+
enc.json = json.NewEncoder(enc.buf)
152+
enc.json.SetEscapeHTML(false)
153+
return enc
154+
},
155+
}
156+
157+
func appendJSONMarshal(buf *buffer.Buffer, v any) error {
158+
j := jsonEncoderPool.Get().(*jsonEncoder)
159+
defer func() {
160+
// To reduce peak allocation, return only smaller buffers to the pool.
161+
const maxBufferSize = 16 << 10
162+
if j.buf.Cap() > maxBufferSize {
163+
return
164+
}
165+
j.buf.Reset()
166+
jsonEncoderPool.Put(j)
167+
}()
168+
169+
if err := j.json.Encode(v); err != nil {
146170
return err
147171
}
148-
bs := bb.Bytes()
172+
173+
bs := j.buf.Bytes()
149174
buf.Write(bs[:len(bs)-1]) // remove final newline
150175
return nil
151176
}

‎src/log/slog/json_handler_test.go‎

Lines changed: 33 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -142,6 +142,39 @@ func jsonValueString(v Value) string {
142142
return string(buf)
143143
}
144144

145+
func TestJSONAllocs(t *testing.T) {
146+
ctx := t.Context()
147+
l := New(NewJSONHandler(io.Discard, &HandlerOptions{}))
148+
testErr := errors.New("an error occurred")
149+
testEvent := struct {
150+
ID int
151+
Scope string
152+
Enabled bool
153+
}{
154+
123456, "abcdefgh", true,
155+
}
156+
157+
t.Run("message", func(t *testing.T) {
158+
wantAllocs(t, 0, func() {
159+
l.LogAttrs(ctx, LevelInfo,
160+
"hello world",
161+
)
162+
})
163+
})
164+
t.Run("attrs", func(t *testing.T) {
165+
wantAllocs(t, 1, func() {
166+
l.LogAttrs(ctx, LevelInfo,
167+
"hello world",
168+
String("component", "subtest"),
169+
Int("id", 67890),
170+
Bool("flag", true),
171+
Any("error", testErr),
172+
Any("event", testEvent),
173+
)
174+
})
175+
})
176+
}
177+
145178
func BenchmarkJSONHandler(b *testing.B) {
146179
for _, bench := range []struct {
147180
name string

0 commit comments

Comments
 (0)