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>
This commit is contained in:
Sean Liao
2025-09-20 12:33:03 +01:00
parent 2353c15785
commit 177cd8d763
4 changed files with 80 additions and 15 deletions

View File

@@ -31,12 +31,19 @@ import (
const testMessage = "Test logging, but use a somewhat realistic message length."
type event struct {
ID string
Index int
Flag bool
}
var (
testTime = time.Date(2022, time.May, 1, 0, 0, 0, 0, time.UTC)
testString = "7e3b3b2aaeff56a7108fe11e154200dd/7819479873059528190"
testInt = 32768
testDuration = 23 * time.Second
testError = errors.New("fail")
testEvent = event{"abcdefgh", 65536, true}
)
var testAttrs = []slog.Attr{

View File

@@ -80,12 +80,12 @@ func BenchmarkAttrs(b *testing.B) {
slog.Int("status", testInt),
slog.Duration("duration", testDuration),
slog.Time("time", testTime),
slog.Any("error", testError),
slog.Any("event", testEvent),
slog.String("string", testString),
slog.Int("status", testInt),
slog.Duration("duration", testDuration),
slog.Time("time", testTime),
slog.Any("error", testError),
slog.Any("event", testEvent),
)
},
},
@@ -103,37 +103,37 @@ func BenchmarkAttrs(b *testing.B) {
slog.Int("status", testInt),
slog.Duration("duration", testDuration),
slog.Time("time", testTime),
slog.Any("error", testError),
slog.Any("event", testEvent),
slog.String("string", testString),
slog.Int("status", testInt),
slog.Duration("duration", testDuration),
slog.Time("time", testTime),
slog.Any("error", testError),
slog.Any("event", testEvent),
slog.String("string", testString),
slog.Int("status", testInt),
slog.Duration("duration", testDuration),
slog.Time("time", testTime),
slog.Any("error", testError),
slog.Any("event", testEvent),
slog.String("string", testString),
slog.Int("status", testInt),
slog.Duration("duration", testDuration),
slog.Time("time", testTime),
slog.Any("error", testError),
slog.Any("event", testEvent),
slog.String("string", testString),
slog.Int("status", testInt),
slog.Duration("duration", testDuration),
slog.Time("time", testTime),
slog.Any("error", testError),
slog.Any("event", testEvent),
slog.String("string", testString),
slog.Int("status", testInt),
slog.Duration("duration", testDuration),
slog.Time("time", testTime),
slog.Any("error", testError),
slog.Any("event", testEvent),
slog.String("string", testString),
slog.Int("status", testInt),
slog.Duration("duration", testDuration),
slog.Time("time", testTime),
slog.Any("error", testError),
slog.Any("event", testEvent),
)
},
},

View File

@@ -137,15 +137,40 @@ func appendJSONValue(s *handleState, v Value) error {
return nil
}
func appendJSONMarshal(buf *buffer.Buffer, v any) error {
type jsonEncoder struct {
buf *bytes.Buffer
// Use a json.Encoder to avoid escaping HTML.
var bb bytes.Buffer
enc := json.NewEncoder(&bb)
enc.SetEscapeHTML(false)
if err := enc.Encode(v); err != nil {
json *json.Encoder
}
var jsonEncoderPool = &sync.Pool{
New: func() any {
enc := &jsonEncoder{
buf: new(bytes.Buffer),
}
enc.json = json.NewEncoder(enc.buf)
enc.json.SetEscapeHTML(false)
return enc
},
}
func appendJSONMarshal(buf *buffer.Buffer, v any) error {
j := jsonEncoderPool.Get().(*jsonEncoder)
defer func() {
// To reduce peak allocation, return only smaller buffers to the pool.
const maxBufferSize = 16 << 10
if j.buf.Cap() > maxBufferSize {
return
}
j.buf.Reset()
jsonEncoderPool.Put(j)
}()
if err := j.json.Encode(v); err != nil {
return err
}
bs := bb.Bytes()
bs := j.buf.Bytes()
buf.Write(bs[:len(bs)-1]) // remove final newline
return nil
}

View File

@@ -142,6 +142,39 @@ func jsonValueString(v Value) string {
return string(buf)
}
func TestJSONAllocs(t *testing.T) {
ctx := t.Context()
l := New(NewJSONHandler(io.Discard, &HandlerOptions{}))
testErr := errors.New("an error occurred")
testEvent := struct {
ID int
Scope string
Enabled bool
}{
123456, "abcdefgh", true,
}
t.Run("message", func(t *testing.T) {
wantAllocs(t, 0, func() {
l.LogAttrs(ctx, LevelInfo,
"hello world",
)
})
})
t.Run("attrs", func(t *testing.T) {
wantAllocs(t, 1, func() {
l.LogAttrs(ctx, LevelInfo,
"hello world",
String("component", "subtest"),
Int("id", 67890),
Bool("flag", true),
Any("error", testErr),
Any("event", testEvent),
)
})
})
}
func BenchmarkJSONHandler(b *testing.B) {
for _, bench := range []struct {
name string