go-pulse/log/handler.go
Martin Holst Swende dd0d0a2522
slog: faster and less memory-consumption (#28621)
These changes improves the performance of the non-coloured terminal formatting, _quite a lot_. 

```
name               old time/op    new time/op    delta
TerminalHandler-8    10.2µs ±15%     5.4µs ± 9%  -47.02%  (p=0.008 n=5+5)

name               old alloc/op   new alloc/op   delta
TerminalHandler-8    2.17kB ± 0%    0.40kB ± 0%  -81.46%  (p=0.008 n=5+5)

name               old allocs/op  new allocs/op  delta
TerminalHandler-8      33.0 ± 0%       5.0 ± 0%  -84.85%  (p=0.008 n=5+5)
```

I tried to _somewhat_ organize the commits, but the it might still be a bit chaotic. Some core insights: 

- The function `terminalHandler.Handl` uses a mutex, and writes all output immediately to 'upstream'. Thus, it can reuse a scratch-buffer every time. 
- This buffer can be propagated internally, making all the internal formatters either write directly to it,
- OR, make  use of the `tmp := buf.AvailableBuffer()` in some cases, where a byte buffer "extra capacity" can be temporarily used. 
- The `slog` package  uses `Attr` by value. It makes sense to minimize operating on them, since iterating / collecting into a new slice, iterating again etc causes copy-on-heap. Better to operate on them only once. 
- If we want to do padding, it's better to copy from a constant `space`-buffer than to invoke `bytes.Repeat` every single time.
2023-12-01 13:28:20 +01:00

228 lines
5.9 KiB
Go

package log
import (
"context"
"fmt"
"io"
"math/big"
"reflect"
"sync"
"time"
"github.com/holiman/uint256"
"golang.org/x/exp/slog"
)
// Lazy allows you to defer calculation of a logged value that is expensive
// to compute until it is certain that it must be evaluated with the given filters.
//
// You may wrap any function which takes no arguments to Lazy. It may return any
// number of values of any type.
type Lazy struct {
Fn interface{}
}
func evaluateLazy(lz Lazy) (interface{}, error) {
t := reflect.TypeOf(lz.Fn)
if t.Kind() != reflect.Func {
return nil, fmt.Errorf("INVALID_LAZY, not func: %+v", lz.Fn)
}
if t.NumIn() > 0 {
return nil, fmt.Errorf("INVALID_LAZY, func takes args: %+v", lz.Fn)
}
if t.NumOut() == 0 {
return nil, fmt.Errorf("INVALID_LAZY, no func return val: %+v", lz.Fn)
}
value := reflect.ValueOf(lz.Fn)
results := value.Call([]reflect.Value{})
if len(results) == 1 {
return results[0].Interface(), nil
}
values := make([]interface{}, len(results))
for i, v := range results {
values[i] = v.Interface()
}
return values, nil
}
type discardHandler struct{}
// DiscardHandler returns a no-op handler
func DiscardHandler() slog.Handler {
return &discardHandler{}
}
func (h *discardHandler) Handle(_ context.Context, r slog.Record) error {
return nil
}
func (h *discardHandler) Enabled(_ context.Context, level slog.Level) bool {
return false
}
func (h *discardHandler) WithGroup(name string) slog.Handler {
panic("not implemented")
}
func (h *discardHandler) WithAttrs(attrs []slog.Attr) slog.Handler {
return &discardHandler{}
}
type TerminalHandler struct {
mu sync.Mutex
wr io.Writer
lvl slog.Level
useColor bool
attrs []slog.Attr
// fieldPadding is a map with maximum field value lengths seen until now
// to allow padding log contexts in a bit smarter way.
fieldPadding map[string]int
buf []byte
}
// NewTerminalHandler returns a handler which formats log records at all levels optimized for human readability on
// a terminal with color-coded level output and terser human friendly timestamp.
// This format should only be used for interactive programs or while developing.
//
// [LEVEL] [TIME] MESSAGE key=value key=value ...
//
// Example:
//
// [DBUG] [May 16 20:58:45] remove route ns=haproxy addr=127.0.0.1:50002
func NewTerminalHandler(wr io.Writer, useColor bool) *TerminalHandler {
return NewTerminalHandlerWithLevel(wr, levelMaxVerbosity, useColor)
}
// NewTerminalHandlerWithLevel returns the same handler as NewTerminalHandler but only outputs
// records which are less than or equal to the specified verbosity level.
func NewTerminalHandlerWithLevel(wr io.Writer, lvl slog.Level, useColor bool) *TerminalHandler {
return &TerminalHandler{
wr: wr,
lvl: lvl,
useColor: useColor,
fieldPadding: make(map[string]int),
}
}
func (h *TerminalHandler) Handle(_ context.Context, r slog.Record) error {
h.mu.Lock()
defer h.mu.Unlock()
buf := h.TerminalFormat(h.buf, r, h.useColor)
h.wr.Write(buf)
h.buf = buf[:0]
return nil
}
func (h *TerminalHandler) Enabled(_ context.Context, level slog.Level) bool {
return level >= h.lvl
}
func (h *TerminalHandler) WithGroup(name string) slog.Handler {
panic("not implemented")
}
func (h *TerminalHandler) WithAttrs(attrs []slog.Attr) slog.Handler {
return &TerminalHandler{
wr: h.wr,
lvl: h.lvl,
useColor: h.useColor,
attrs: append(h.attrs, attrs...),
fieldPadding: make(map[string]int),
}
}
// ResetFieldPadding zeroes the field-padding for all attribute pairs.
func (t *TerminalHandler) ResetFieldPadding() {
t.mu.Lock()
t.fieldPadding = make(map[string]int)
t.mu.Unlock()
}
type leveler struct{ minLevel slog.Level }
func (l *leveler) Level() slog.Level {
return l.minLevel
}
func JSONHandler(wr io.Writer) slog.Handler {
return slog.NewJSONHandler(wr, &slog.HandlerOptions{
ReplaceAttr: builtinReplaceJSON,
})
}
// LogfmtHandler returns a handler which prints records in logfmt format, an easy machine-parseable but human-readable
// format for key/value pairs.
//
// For more details see: http://godoc.org/github.com/kr/logfmt
func LogfmtHandler(wr io.Writer) slog.Handler {
return slog.NewTextHandler(wr, &slog.HandlerOptions{
ReplaceAttr: builtinReplaceLogfmt,
})
}
// LogfmtHandlerWithLevel returns the same handler as LogfmtHandler but it only outputs
// records which are less than or equal to the specified verbosity level.
func LogfmtHandlerWithLevel(wr io.Writer, level slog.Level) slog.Handler {
return slog.NewTextHandler(wr, &slog.HandlerOptions{
ReplaceAttr: builtinReplaceLogfmt,
Level: &leveler{level},
})
}
func builtinReplaceLogfmt(_ []string, attr slog.Attr) slog.Attr {
return builtinReplace(nil, attr, true)
}
func builtinReplaceJSON(_ []string, attr slog.Attr) slog.Attr {
return builtinReplace(nil, attr, false)
}
func builtinReplace(_ []string, attr slog.Attr, logfmt bool) slog.Attr {
switch attr.Key {
case slog.TimeKey:
if attr.Value.Kind() == slog.KindTime {
if logfmt {
return slog.String("t", attr.Value.Time().Format(timeFormat))
} else {
return slog.Attr{Key: "t", Value: attr.Value}
}
}
case slog.LevelKey:
if l, ok := attr.Value.Any().(slog.Level); ok {
attr = slog.Any("lvl", LevelString(l))
return attr
}
}
switch v := attr.Value.Any().(type) {
case time.Time:
if logfmt {
attr = slog.String(attr.Key, v.Format(timeFormat))
}
case *big.Int:
if v == nil {
attr.Value = slog.StringValue("<nil>")
} else {
attr.Value = slog.StringValue(v.String())
}
case *uint256.Int:
if v == nil {
attr.Value = slog.StringValue("<nil>")
} else {
attr.Value = slog.StringValue(v.Dec())
}
case fmt.Stringer:
if v == nil || (reflect.ValueOf(v).Kind() == reflect.Pointer && reflect.ValueOf(v).IsNil()) {
attr.Value = slog.StringValue("<nil>")
} else {
attr.Value = slog.StringValue(v.String())
}
}
return attr
}