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>

diff --git a/src/log/slog/internal/benchmarks/benchmarks.go b/src/log/slog/internal/benchmarks/benchmarks.go
index 3a28523beb44aeb11c893bde975083cf557160f2..a94ecfa7435663a24cf259fb4e1bdc6a0b444697 100644 (file)
--- a/src/log/slog/internal/benchmarks/benchmarks.go
+++ b/src/log/slog/internal/benchmarks/benchmarks.go
@@ -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{

diff --git a/src/log/slog/internal/benchmarks/benchmarks_test.go b/src/log/slog/internal/benchmarks/benchmarks_test.go
index 18643b73e6c8a0f62586311aa2a8d84218917237..3fec2612797f2ed4a62e3e6f673ab2b4b052d221 100644 (file)
--- a/src/log/slog/internal/benchmarks/benchmarks_test.go
+++ b/src/log/slog/internal/benchmarks/benchmarks_test.go
@@ -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),
                                                )
                                        },
                                },

diff --git a/src/log/slog/json_handler.go b/src/log/slog/json_handler.go
index f139c5413912bf2610cf802e8e175d38256ca331..9c7045cda917691b5278dbb248a55ebdb51105bd 100644 (file)
--- a/src/log/slog/json_handler.go
+++ b/src/log/slog/json_handler.go
@@ -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
 }

diff --git a/src/log/slog/json_handler_test.go b/src/log/slog/json_handler_test.go
index 65130f2426e70d9139037b36a0b6c19f203313f3..fd6b2e39d4bd0298642978501945f98fc21ebac2 100644 (file)
--- a/src/log/slog/json_handler_test.go
+++ b/src/log/slog/json_handler_test.go
@@ -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