slog-handler-guide: speed section Change-Id: If06f51747e6e4926d95e88840ab5fdce5f9a0189 Reviewed-on: https://go-review.googlesource.com/c/example/+/513457 Reviewed-by: Ian Cottrell <iancottrell@google.com> TryBot-Result: Gopher Robot <gobot@golang.org> Run-TryBot: Jonathan Amsterdam <jba@google.com>
diff --git a/slog-handler-guide/README.md b/slog-handler-guide/README.md index cadc501..3172f0e 100644 --- a/slog-handler-guide/README.md +++ b/slog-handler-guide/README.md
@@ -894,6 +894,122 @@ ## Speed -TODO(jba): discuss +Most programs don't need fast logging. +Before making your handler fast, gather data—preferably production data, +not benchmark comparisons—that demonstrates that it needs to be fast. +Avoid premature optimization. -TODO(jba): show how to pool a []byte. +If you need a fast handler, start with pre-formatting. It may provide dramatic +speed-ups in cases where a single call to `Logger.With` is followed by many +calls to the resulting logger. + +If log output is the bottleneck, consider making your handler asynchronous. +Do the minimal amount of processing in the handler, then send the record and +other information over a channel. Another goroutine can collect the incoming log +entries and write them in bulk and in the background. +You might want to preserve the option to log synchronously +so you can see all the log output to debug a crash. + +Allocation is often a major cause of a slow system. +The `slog` package already works hard at minimizing allocations. +If your handler does it own allocation, and profiling shows it to be +a problem, then see if you can minimize it. + +One simple change you can make is to replace calls to `fmt.Sprintf` or `fmt.Appendf` +with direct appends to the buffer. For example, our IndentHandler appends string +attributes to the buffer like so: + + buf = fmt.Appendf(buf, "%s: %q\n", a.Key, a.Value.String()) + +As of Go 1.21, that results in two allocations, one for each argument passed to +an `any` parameter. We can get that down to zero by using `append` directly: + + buf = append(buf, a.Key...) + buf = append(buf, ": "...) + buf = strconv.AppendQuote(buf, a.Value.String()) + buf = append(buf, '\n') + +Another worthwhile change is to use a `sync.Pool` to manage the one chunk of +memory that most handlers need: +the `[]byte` buffer holding the formatted output. + +Our example `Handle` method began with this line: + + buf := make([]byte, 0, 1024) + +As we said above, providing a large initial capacity avoids repeated copying and +re-allocation of the slice as it grows, reducing the number of allocations to +one. +But we can get it down to zero in the steady state by keeping a global pool of buffers. +Initially, the pool will be empty and new buffers will be allocated. +But eventually, assuming the number of concurrent log calls reaches a steady +maximum, there will be enough buffers in the pool to share among all the +ongoing `Handler` calls. As long as no log entry grows past a buffer's capacity, +there will be no allocations from the garbage collector's point of view. + +We will hide our pool behind a pair of functions, `allocBuf` and `freeBuf`. +The single line to get a buffer at the top of `Handle` becomes two lines: + + bufp := allocBuf() + defer freeBuf(bufp) + +One of the subtleties involved in making a `sync.Pool` of slices +is suggested by the variable name `bufp`: your pool must deal in +_pointers_ to slices, not the slices themselves. +Pooled values must always be pointers. If they aren't, then the `any` arguments +and return values of the `sync.Pool` methods will themselves cause allocations, +defeating the purpose of pooling. + +There are two ways to proceed with our slice pointer: we can replace `buf` +with `*bufp` throughout our function, or we can dereference it and remember to +re-assign it before freeing: + + bufp := allocBuf() + buf := *bufp + defer func() { + *bufp = buf + freeBuf(bufp) + }() + + +Here is our pool and its associated functions: + +``` +var bufPool = sync.Pool{ + New: func() any { + b := make([]byte, 0, 1024) + return &b + }, +} + +func allocBuf() *[]byte { + return bufPool.Get().(*[]byte) +} + +func freeBuf(b *[]byte) { + // To reduce peak allocation, return only smaller buffers to the pool. + const maxBufferSize = 16 << 10 + if cap(*b) <= maxBufferSize { + *b = (*b)[:0] + bufPool.Put(b) + } +} +``` + +The pool's `New` function does the same thing as the original code: +create a byte slice with 0 length and plenty of capacity. +The `allocBuf` function just type-asserts the result of the pool's +`Get` method. + +The `freeBuf` method truncates the buffer before putting it back +in the pool, so that `allocBuf` always returns zero-length slices. +It also implements an important optimization: it doesn't return +large buffers to the pool. +To see why this important, consider what would happen if there were a single, +unusually large log entry—say one that was a megabyte when formatted. +If that megabyte-sized buffer were put in the pool, it could remain +there indefinitely, constantly being reused, but with most of its capacity +wasted. +The extra memory might never be used again by the handler, and since it was in +the handler's pool, it might never be garbage-collected for reuse elsewhere. +We can avoid that situation by keeping large buffers out of the pool.
diff --git a/slog-handler-guide/guide.md b/slog-handler-guide/guide.md index 229589b..92bcd26 100644 --- a/slog-handler-guide/guide.md +++ b/slog-handler-guide/guide.md
@@ -612,6 +612,102 @@ ## Speed -TODO(jba): discuss +Most programs don't need fast logging. +Before making your handler fast, gather data—preferably production data, +not benchmark comparisons—that demonstrates that it needs to be fast. +Avoid premature optimization. -TODO(jba): show how to pool a []byte. +If you need a fast handler, start with pre-formatting. It may provide dramatic +speed-ups in cases where a single call to `Logger.With` is followed by many +calls to the resulting logger. + +If log output is the bottleneck, consider making your handler asynchronous. +Do the minimal amount of processing in the handler, then send the record and +other information over a channel. Another goroutine can collect the incoming log +entries and write them in bulk and in the background. +You might want to preserve the option to log synchronously +so you can see all the log output to debug a crash. + +Allocation is often a major cause of a slow system. +The `slog` package already works hard at minimizing allocations. +If your handler does its own allocation, and profiling shows it to be +a problem, then see if you can minimize it. + +One simple change you can make is to replace calls to `fmt.Sprintf` or `fmt.Appendf` +with direct appends to the buffer. For example, our IndentHandler appends string +attributes to the buffer like so: + + buf = fmt.Appendf(buf, "%s: %q\n", a.Key, a.Value.String()) + +As of Go 1.21, that results in two allocations, one for each argument passed to +an `any` parameter. We can get that down to zero by using `append` directly: + + buf = append(buf, a.Key...) + buf = append(buf, ": "...) + buf = strconv.AppendQuote(buf, a.Value.String()) + buf = append(buf, '\n') + +Another worthwhile change is to use a `sync.Pool` to manage the one chunk of +memory that most handlers need: +the `[]byte` buffer holding the formatted output. + +Our example `Handle` method began with this line: + + buf := make([]byte, 0, 1024) + +As we said above, providing a large initial capacity avoids repeated copying and +re-allocation of the slice as it grows, reducing the number of allocations to +one. +But we can get it down to zero in the steady state by keeping a global pool of buffers. +Initially, the pool will be empty and new buffers will be allocated. +But eventually, assuming the number of concurrent log calls reaches a steady +maximum, there will be enough buffers in the pool to share among all the +ongoing `Handler` calls. As long as no log entry grows past a buffer's capacity, +there will be no allocations from the garbage collector's point of view. + +We will hide our pool behind a pair of functions, `allocBuf` and `freeBuf`. +The single line to get a buffer at the top of `Handle` becomes two lines: + + bufp := allocBuf() + defer freeBuf(bufp) + +One of the subtleties involved in making a `sync.Pool` of slices +is suggested by the variable name `bufp`: your pool must deal in +_pointers_ to slices, not the slices themselves. +Pooled values must always be pointers. If they aren't, then the `any` arguments +and return values of the `sync.Pool` methods will themselves cause allocations, +defeating the purpose of pooling. + +There are two ways to proceed with our slice pointer: we can replace `buf` +with `*bufp` throughout our function, or we can dereference it and remember to +re-assign it before freeing: + + bufp := allocBuf() + buf := *bufp + defer func() { + *bufp = buf + freeBuf(bufp) + }() + + +Here is our pool and its associated functions: + +%include indenthandler4/indent_handler.go pool - + +The pool's `New` function does the same thing as the original code: +create a byte slice with 0 length and plenty of capacity. +The `allocBuf` function just type-asserts the result of the pool's +`Get` method. + +The `freeBuf` method truncates the buffer before putting it back +in the pool, so that `allocBuf` always returns zero-length slices. +It also implements an important optimization: it doesn't return +large buffers to the pool. +To see why this important, consider what would happen if there were a single, +unusually large log entry—say one that was a megabyte when formatted. +If that megabyte-sized buffer were put in the pool, it could remain +there indefinitely, constantly being reused, but with most of its capacity +wasted. +The extra memory might never be used again by the handler, and since it was in +the handler's pool, it might never be garbage-collected for reuse elsewhere. +We can avoid that situation by keeping large buffers out of the pool.
diff --git a/slog-handler-guide/indenthandler4/indent_handler.go b/slog-handler-guide/indenthandler4/indent_handler.go new file mode 100644 index 0000000..bf96c5d --- /dev/null +++ b/slog-handler-guide/indenthandler4/indent_handler.go
@@ -0,0 +1,208 @@ +//go:build go1.21 + +package indenthandler + +import ( + "context" + "fmt" + "io" + "log/slog" + "runtime" + "slices" + "strconv" + "sync" + "time" +) + +// !+IndentHandler +type IndentHandler struct { + opts Options + preformatted []byte // data from WithGroup and WithAttrs + unopenedGroups []string // groups from WithGroup that haven't been opened + indentLevel int // same as number of opened groups so far + mu *sync.Mutex + out io.Writer +} + +//!-IndentHandler + +type Options struct { + // Level reports the minimum level to log. + // Levels with lower levels are discarded. + // If nil, the Handler uses [slog.LevelInfo]. + Level slog.Leveler +} + +func New(out io.Writer, opts *Options) *IndentHandler { + h := &IndentHandler{out: out, mu: &sync.Mutex{}} + if opts != nil { + h.opts = *opts + } + if h.opts.Level == nil { + h.opts.Level = slog.LevelInfo + } + return h +} + +func (h *IndentHandler) Enabled(ctx context.Context, level slog.Level) bool { + return level >= h.opts.Level.Level() +} + +// !+WithGroup +func (h *IndentHandler) WithGroup(name string) slog.Handler { + if name == "" { + return h + } + h2 := *h + // Add an unopened group to h2 without modifying h. + h2.unopenedGroups = make([]string, len(h.unopenedGroups)+1) + copy(h2.unopenedGroups, h.unopenedGroups) + h2.unopenedGroups[len(h2.unopenedGroups)-1] = name + return &h2 +} + +//!-WithGroup + +// !+WithAttrs +func (h *IndentHandler) WithAttrs(attrs []slog.Attr) slog.Handler { + if len(attrs) == 0 { + return h + } + h2 := *h + // Force an append to copy the underlying array. + pre := slices.Clip(h.preformatted) + // Add all groups from WithGroup that haven't already been added. + h2.preformatted = h2.appendUnopenedGroups(pre, h2.indentLevel) + // Each of those groups increased the indent level by 1. + h2.indentLevel += len(h2.unopenedGroups) + // Now all groups have been opened. + h2.unopenedGroups = nil + // Pre-format the attributes. + for _, a := range attrs { + h2.preformatted = h2.appendAttr(h2.preformatted, a, h2.indentLevel) + } + return &h2 +} + +func (h *IndentHandler) appendUnopenedGroups(buf []byte, indentLevel int) []byte { + for _, g := range h.unopenedGroups { + buf = fmt.Appendf(buf, "%*s%s:\n", indentLevel*4, "", g) + indentLevel++ + } + return buf +} + +//!-WithAttrs + +// !+Handle +func (h *IndentHandler) Handle(ctx context.Context, r slog.Record) error { + bufp := allocBuf() + buf := *bufp + defer func() { + *bufp = buf + freeBuf(bufp) + }() + if !r.Time.IsZero() { + buf = h.appendAttr(buf, slog.Time(slog.TimeKey, r.Time), 0) + } + buf = h.appendAttr(buf, slog.Any(slog.LevelKey, r.Level), 0) + if r.PC != 0 { + fs := runtime.CallersFrames([]uintptr{r.PC}) + f, _ := fs.Next() + // Optimize to minimize allocation. + srcbufp := allocBuf() + defer freeBuf(srcbufp) + *srcbufp = append(*srcbufp, f.File...) + *srcbufp = append(*srcbufp, ':') + *srcbufp = strconv.AppendInt(*srcbufp, int64(f.Line), 10) + buf = h.appendAttr(buf, slog.String(slog.SourceKey, string(*srcbufp)), 0) + } + + buf = h.appendAttr(buf, slog.String(slog.MessageKey, r.Message), 0) + // Insert preformatted attributes just after built-in ones. + buf = append(buf, h.preformatted...) + if r.NumAttrs() > 0 { + buf = h.appendUnopenedGroups(buf, h.indentLevel) + r.Attrs(func(a slog.Attr) bool { + buf = h.appendAttr(buf, a, h.indentLevel+len(h.unopenedGroups)) + return true + }) + } + buf = append(buf, "---\n"...) + h.mu.Lock() + defer h.mu.Unlock() + _, err := h.out.Write(buf) + return err +} + +//!-Handle + +func (h *IndentHandler) appendAttr(buf []byte, a slog.Attr, indentLevel int) []byte { + // Resolve the Attr's value before doing anything else. + a.Value = a.Value.Resolve() + // Ignore empty Attrs. + if a.Equal(slog.Attr{}) { + return buf + } + // Indent 4 spaces per level. + buf = fmt.Appendf(buf, "%*s", indentLevel*4, "") + switch a.Value.Kind() { + case slog.KindString: + // Quote string values, to make them easy to parse. + buf = append(buf, a.Key...) + buf = append(buf, ": "...) + buf = strconv.AppendQuote(buf, a.Value.String()) + buf = append(buf, '\n') + case slog.KindTime: + // Write times in a standard way, without the monotonic time. + buf = append(buf, a.Key...) + buf = append(buf, ": "...) + buf = a.Value.Time().AppendFormat(buf, time.RFC3339Nano) + buf = append(buf, '\n') + case slog.KindGroup: + attrs := a.Value.Group() + // Ignore empty groups. + if len(attrs) == 0 { + return buf + } + // If the key is non-empty, write it out and indent the rest of the attrs. + // Otherwise, inline the attrs. + if a.Key != "" { + buf = fmt.Appendf(buf, "%s:\n", a.Key) + indentLevel++ + } + for _, ga := range attrs { + buf = h.appendAttr(buf, ga, indentLevel) + } + + default: + buf = append(buf, a.Key...) + buf = append(buf, ": "...) + buf = append(buf, a.Value.String()...) + buf = append(buf, '\n') + } + return buf +} + +// !+pool +var bufPool = sync.Pool{ + New: func() any { + b := make([]byte, 0, 1024) + return &b + }, +} + +func allocBuf() *[]byte { + return bufPool.Get().(*[]byte) +} + +func freeBuf(b *[]byte) { + // To reduce peak allocation, return only smaller buffers to the pool. + const maxBufferSize = 16 << 10 + if cap(*b) <= maxBufferSize { + *b = (*b)[:0] + bufPool.Put(b) + } +} + +//!-pool
diff --git a/slog-handler-guide/indenthandler4/indent_handler_norace_test.go b/slog-handler-guide/indenthandler4/indent_handler_norace_test.go new file mode 100644 index 0000000..bddfd4d --- /dev/null +++ b/slog-handler-guide/indenthandler4/indent_handler_norace_test.go
@@ -0,0 +1,46 @@ +//go:build go1.21 && !race + +package indenthandler + +import ( + "fmt" + "io" + "log/slog" + "strconv" + "testing" +) + +func TestAlloc(t *testing.T) { + a := slog.String("key", "value") + t.Run("Appendf", func(t *testing.T) { + buf := make([]byte, 0, 100) + g := testing.AllocsPerRun(2, func() { + buf = fmt.Appendf(buf, "%s: %q\n", a.Key, a.Value.String()) + }) + if g, w := int(g), 2; g != w { + t.Errorf("got %d, want %d", g, w) + } + }) + t.Run("appends", func(t *testing.T) { + buf := make([]byte, 0, 100) + g := testing.AllocsPerRun(2, func() { + buf = append(buf, a.Key...) + buf = append(buf, ": "...) + buf = strconv.AppendQuote(buf, a.Value.String()) + buf = append(buf, '\n') + }) + if g, w := int(g), 0; g != w { + t.Errorf("got %d, want %d", g, w) + } + }) + + t.Run("Handle", func(t *testing.T) { + l := slog.New(New(io.Discard, nil)) + got := testing.AllocsPerRun(10, func() { + l.LogAttrs(nil, slog.LevelInfo, "hello", slog.String("a", "1")) + }) + if g, w := int(got), 6; g > w { + t.Errorf("got %d, want at most %d", g, w) + } + }) +}
diff --git a/slog-handler-guide/indenthandler4/indent_handler_test.go b/slog-handler-guide/indenthandler4/indent_handler_test.go new file mode 100644 index 0000000..8f6e99c --- /dev/null +++ b/slog-handler-guide/indenthandler4/indent_handler_test.go
@@ -0,0 +1,107 @@ +//go:build go1.21 + +package indenthandler + +import ( + "bytes" + "log/slog" + "reflect" + "regexp" + "testing" + "testing/slogtest" + + "gopkg.in/yaml.v3" +) + +// !+TestSlogtest +func TestSlogtest(t *testing.T) { + var buf bytes.Buffer + err := slogtest.TestHandler(New(&buf, nil), func() []map[string]any { + return parseLogEntries(t, buf.Bytes()) + }) + if err != nil { + t.Error(err) + } +} + +// !-TestSlogtest + +func Test(t *testing.T) { + var buf bytes.Buffer + l := slog.New(New(&buf, nil)) + l.Info("hello", "a", 1, "b", true, "c", 3.14, slog.Group("g", "h", 1, "i", 2), "d", "NO") + got := buf.String() + wantre := `time: [-0-9T:.]+Z? +level: INFO +source: ".*/indent_handler_test.go:\d+" +msg: "hello" +a: 1 +b: true +c: 3.14 +g: + h: 1 + i: 2 +d: "NO" +` + re := regexp.MustCompile(wantre) + if !re.MatchString(got) { + t.Errorf("\ngot:\n%q\nwant:\n%q", got, wantre) + } + + buf.Reset() + l.Debug("test") + if got := buf.Len(); got != 0 { + t.Errorf("got buf.Len() = %d, want 0", got) + } +} + +// !+parseLogEntries +func parseLogEntries(t *testing.T, data []byte) []map[string]any { + entries := bytes.Split(data, []byte("---\n")) + entries = entries[:len(entries)-1] // last one is empty + var ms []map[string]any + for _, e := range entries { + var m map[string]any + if err := yaml.Unmarshal([]byte(e), &m); err != nil { + t.Fatal(err) + } + ms = append(ms, m) + } + return ms +} + +// !-parseLogEntries + +func TestParseLogEntries(t *testing.T) { + in := ` +a: 1 +b: 2 +c: 3 +g: + h: 4 + i: five +d: 6 +--- +e: 7 +--- +` + want := []map[string]any{ + { + "a": 1, + "b": 2, + "c": 3, + "g": map[string]any{ + "h": 4, + "i": "five", + }, + "d": 6, + }, + { + "e": 7, + }, + } + got := parseLogEntries(t, []byte(in[1:])) + if !reflect.DeepEqual(got, want) { + t.Errorf("\ngot:\n%v\nwant:\n%v", got, want) + } +}