diff --git a/README.md b/README.md index 193e151..613cb96 100644 --- a/README.md +++ b/README.md @@ -72,4 +72,191 @@ BenchmarkLoggers/dummy-4 1239873 893.2 ns/op BenchmarkLoggers/console-4 483354 2338 ns/op 128 B/op 1 allocs/op BenchmarkLoggers/std-text-4 368828 3141 ns/op 132 B/op 3 allocs/op BenchmarkLoggers/std-json-4 393322 2909 ns/op 248 B/op 4 allocs/op +``` + +## Indentation +Indentation of functions can occasionally be useful for delineating +calls by indenting callees more than callers. +This can sometimes help interpret logs during development. + +The specific case of runaway recursion shows up clearly as the messages +march repeatedly across the screen. + +Indentation is configured using `console.HandlerOptins.Indent` which uses the following type: +```go +// Indentation configures indentation for message and attribute data. +// If both Prefix and Tab strings are empty ("") indentation will not occur. +// When indenting, the message is prepended by the Prefix string (if not empty) +// followed by the depth level iterations of the Tab string. +// The depth level is provided by an attribute named by the Key string. +// This should be either an integer or a pointer to a DepthLevel object. +type Indentation struct { +// Prefix string used before indentation (optional). +Prefix string + +// Tab represents the additional indentation per depth level. +// It is probably better to not use an actual tab character here, +// but instead use some number of spaces. +Tab string + +// Key is the attribute key that will hold the depth number. +// When not provided the key is set to "depth". +Key string +}} +``` +A convenience function can be used instead of +filling out the `console.HandlerOptins.Indent` object manually for simple cases: +```go +// DefaultIndentation returns an Indentation struct with the specified tag string, +// no Prefix string, and Key set to the default indentation key. +// Other configurations (e.g. featuring a Prefix or non-default Key) +// must be set manually. +func DefaultIndentation(tab string) Indentation +``` + +### Example + +```go +package main + +import ( + "log/slog" + "os" + + "github.com/phsym/console-slog" +) + +func main() { + slog.SetDefault(slog.New(console.NewHandler(os.Stderr, &console.HandlerOptions{ + Level: slog.LevelDebug, + Indent: console.DefaultIndentation(" "), + }))) + slog.Info("factorial", "result", factorial(7, 0)) +} + +func factorial(number, depth int64) int64 { + slog.Debug("factorial", "number", number, "depth", depth) + var result int64 + if number < 2 { + result = 1 + } else { + result = number * factorial(number-1, depth+1) + } + slog.Debug("factorial", "result", result, "depth", depth) + return result +} +``` + +![factorial-indent](./doc/img/factorial-indent.png) + +Where passing the depth number as an argument is contraindicated or just plain irritating +it is possible to use the following object for the depth value in logging statements: +```go +// DepthValuer represents an indentation depth object (an int64). +// These objects can be incremented on entry to a function and decremented in a defer statement. +// This object is not thread safe. Using it as a global variable (the mostly likely usage) +// in a multithreaded application will result in unpredictable values in different threads. +type DepthValuer struct { + depth int +} + +// LogValue implements the slog.LogValuer interface. +func (dv *DepthValuer) LogValue() slog.Value { + return slog.IntValue(int(dv.depth)) +} + +// Increment the depth value. +// Use this at the head of a function or important code block. +func (dv *DepthValuer) Increment() { + dv.depth += 1 +} + +// Decrement the depth value. +// Use this after an important code block or as a defer statement in a function. +func (dv *DepthValuer) Decrement() { + dv.depth -= 1 +} +``` + +The use case for `DepthValuer` is to invoke its `Increment()` function at the start of a function, +followed by a `defer` of its `Decrement()` object. +All logging calls in the function need to append the `Indentation.Key` and a pointer to the `DepthValuer`. + +_It is not possible_ to add this attribute via a `WithAttrs()` call as the value is +only evaluated once and cached by the `console.Handler` for performance reasons. +The `Indentation.Key` and `DepthValuer` pointer must be specified in each logging call. + +This mechanism should be usable in code blocks but `defer` doesn't work in this case. +The programmer is responsible for making certain that the `Decrement()` call is made in all situations. + +### Example: +```go +package main + +import ( + "log/slog" + "os" + + "github.com/phsym/console-slog" +) + +var depthValuer = &console.DepthValuer{} + +func main() { + slog.SetDefault(slog.New(console.NewHandler(os.Stderr, &console.HandlerOptions{ + Level: slog.LevelDebug, + Indent: console.DefaultIndentation(" "), + }))) + slog.Info("factorial", "result", factorial(7)) +} + +func factorial(number int64) int64 { + depthValuer.Increment() + defer depthValuer.Decrement() + slog.Debug("factorial", "number", number, "depth", depthValuer) + var result int64 + if number < 2 { + result = 1 + } else { + result = number * factorial(number-1) + } + slog.Debug("factorial", "result", result, "depth", depthValuer) + return result +} +``` +### Performances +See [benchmark file](./bench_test.go) for details. + +Benchmark results comparing console numbers with and without indentation testing: +``` +goos: linux +goarch: amd64 +pkg: github.com/phsym/console-slog +cpu: Intel(R) Core(TM) i7-7820HQ CPU @ 2.90GHz +enchmark iter time/iter bytes alloc allocs +--------- ---- --------- ----------- ------ +BenchmarkHandlers/dummy-8 167386000 7.28 ns/op 0 B/op 0 allocs/op +BenchmarkHandlers/console-8 773392 1490.00 ns/op 0 B/op 0 allocs/op +BenchmarkHandlers/console-indent-8 724384 1601.00 ns/op 0 B/op 0 allocs/op +BenchmarkHandlers/std-text-8 682894 1676.00 ns/op 2 B/op 1 allocs/op +BenchmarkHandlers/std-json-8 793027 1501.00 ns/op 120 B/op 3 allocs/op +BenchmarkHandlersIndent/dummy-8 166353291 7.38 ns/op 0 B/op 0 allocs/op +BenchmarkHandlersIndent/console-8 644863 1657.00 ns/op 0 B/op 0 allocs/op +BenchmarkHandlersIndent/console-indent-8 699098 1754.00 ns/op 0 B/op 0 allocs/op +BenchmarkHandlersIndent/std-text-8 608865 1781.00 ns/op 2 B/op 1 allocs/op +BenchmarkHandlersIndent/std-json-8 696843 1574.00 ns/op 120 B/op 3 allocs/op +BenchmarkLoggersIndent/dummy-8 2955999 406.40 ns/op 128 B/op 1 allocs/op +BenchmarkLoggersIndent/console-8 543122 1953.00 ns/op 128 B/op 1 allocs/op +BenchmarkLoggersIndent/console-indent-8 540606 2033.00 ns/op 128 B/op 1 allocs/op +BenchmarkLoggersIndent/std-text-8 484188 2158.00 ns/op 130 B/op 2 allocs/op +BenchmarkLoggersIndent/std-json-8 562014 1996.00 ns/op 248 B/op 4 allocs/op +BenchmarkHandlersFactorial/dummy-8 8170125 145.30 ns/op 16 B/op 2 allocs/op +BenchmarkHandlersFactorial/console-8 7995117 144.20 ns/op 16 B/op 2 allocs/op +BenchmarkHandlersFactorial/console-indent-8 8149261 145.80 ns/op 16 B/op 2 allocs/op +BenchmarkHandlersFactorial/std-text-8 7979374 144.70 ns/op 16 B/op 2 allocs/op +BenchmarkHandlersFactorial/std-json-8 8365809 144.20 ns/op 16 B/op 2 allocs/op +BenchmarkBuffer/std-8 160528912 7.57 ns/op 0 B/op 0 allocs/op +BenchmarkBuffer/buffer-8 297744796 4.11 ns/op 0 B/op 0 allocs/op +BenchmarkDuration/std-8 30995145 38.00 ns/op 0 B/op 0 allocs/op +BenchmarkDuration/append-8 36095490 32.81 ns/op 0 B/op 0 allocs/op ``` \ No newline at end of file diff --git a/bench_test.go b/bench_test.go index 88736ac..2a0ddd7 100644 --- a/bench_test.go +++ b/bench_test.go @@ -1,5 +1,8 @@ package console +// Run with go test -bench=. -test.benchmem | prettybench +// Get pretty bench with go install github.com/cespare/prettybench@latest + import ( "context" "errors" @@ -22,6 +25,7 @@ var handlers = []struct { }{ {"dummy", &DummyHandler{}}, {"console", NewHandler(io.Discard, &HandlerOptions{Level: slog.LevelDebug, AddSource: false})}, + {"console-indent", NewHandler(io.Discard, &HandlerOptions{Level: slog.LevelDebug, Indent: DefaultIndentation(" ")})}, {"std-text", slog.NewTextHandler(io.Discard, &slog.HandlerOptions{Level: slog.LevelDebug, AddSource: false})}, {"std-json", slog.NewJSONHandler(io.Discard, &slog.HandlerOptions{Level: slog.LevelDebug, AddSource: false})}, } @@ -63,10 +67,34 @@ func BenchmarkHandlers(b *testing.B) { } } -func BenchmarkLoggers(b *testing.B) { +func BenchmarkHandlersIndent(b *testing.B) { + ctx := context.Background() + rec := slog.NewRecord(time.Now(), slog.LevelInfo, "hello", 0) + rec.AddAttrs(attrs...) + rec.AddAttrs(slog.Attr{ + Key: "depth", + Value: slog.IntValue(5), + }) + + for _, tc := range handlers { + b.Run(tc.name, func(b *testing.B) { + l := tc.hdl.WithAttrs(attrs).WithGroup("test").WithAttrs(attrs) + // Warm-up + _ = l.Handle(ctx, rec) + b.ResetTimer() + for i := 0; i < b.N; i++ { + _ = l.Handle(ctx, rec) + } + }) + } +} + +func BenchmarkLoggersIndent(b *testing.B) { for _, tc := range handlers { ctx := context.Background() b.Run(tc.name, func(b *testing.B) { + attrsIndent := attrs + attrsIndent = append(attrsIndent, slog.Int64("depth", 5)) l := slog.New(tc.hdl).With(attrsAny...).WithGroup("test").With(attrsAny...) // Warm-up l.LogAttrs(ctx, slog.LevelInfo, "hello", attrs...) @@ -77,3 +105,29 @@ func BenchmarkLoggers(b *testing.B) { }) } } + +// BenchmarkHandlersFactorial tests the performance of the DepthValuer. +func BenchmarkHandlersFactorial(b *testing.B) { + for _, tc := range handlers { + b.Run(tc.name, func(b *testing.B) { + b.ResetTimer() + for i := 0; i < b.N; i++ { + factorial(slog.New(tc.hdl), 7) + } + }) + } +} + +var depthValuer = &DepthValuer{} + +func factorial(logger *slog.Logger, number int) int { + depthValuer.Increment() + depthValuer.Decrement() + slog.Debug("factorial", "number", number, "depth", depthValuer) + if number <= 1 { + return 1 + } + result := number * factorial(logger, number-1) + slog.Debug("factorial", "result", result, "depth", depthValuer) + return result +} diff --git a/doc/img/factorial-indent.png b/doc/img/factorial-indent.png new file mode 100644 index 0000000..575aea2 Binary files /dev/null and b/doc/img/factorial-indent.png differ diff --git a/example/main.go b/examples/basic/main.go similarity index 100% rename from example/main.go rename to examples/basic/main.go diff --git a/examples/indent/main.go b/examples/indent/main.go new file mode 100644 index 0000000..60c4f0f --- /dev/null +++ b/examples/indent/main.go @@ -0,0 +1,28 @@ +package main + +import ( + "log/slog" + "os" + + "github.com/phsym/console-slog" +) + +func main() { + slog.SetDefault(slog.New(console.NewHandler(os.Stderr, &console.HandlerOptions{ + Level: slog.LevelDebug, + Indent: console.DefaultIndentation(" "), + }))) + slog.Info("factorial", "result", factorial(7, 0)) +} + +func factorial(number, depth int64) int64 { + slog.Debug("factorial", "number", number, "depth", depth) + var result int64 + if number < 2 { + result = 1 + } else { + result = number * factorial(number-1, depth+1) + } + slog.Debug("factorial", "result", result, "depth", depth) + return result +} diff --git a/examples/indentValuer/main.go b/examples/indentValuer/main.go new file mode 100644 index 0000000..a965894 --- /dev/null +++ b/examples/indentValuer/main.go @@ -0,0 +1,32 @@ +package main + +import ( + "log/slog" + "os" + + "github.com/phsym/console-slog" +) + +var depthValuer = &console.DepthValuer{} + +func main() { + slog.SetDefault(slog.New(console.NewHandler(os.Stderr, &console.HandlerOptions{ + Level: slog.LevelDebug, + Indent: console.DefaultIndentation(" "), + }))) + slog.Info("factorial", "result", factorial(7)) +} + +func factorial(number int64) int64 { + depthValuer.Increment() + defer depthValuer.Decrement() + slog.Debug("factorial", "number", number, "depth", depthValuer) + var result int64 + if number < 2 { + result = 1 + } else { + result = number * factorial(number-1) + } + slog.Debug("factorial", "result", result, "depth", depthValuer) + return result +} diff --git a/handler.go b/handler.go index 82ce3ea..cc0cccb 100644 --- a/handler.go +++ b/handler.go @@ -38,6 +38,53 @@ type HandlerOptions struct { // Theme defines the colorized output using ANSI escape sequences Theme Theme + + // Indent defines a way for the message and attributes to be indented. + Indent Indentation +} + +const defaultIndentKey = "depth" + +// Indentation configures indentation for message and attribute data. +// If both Prefix and Tab strings are empty ("") indentation will not occur. +// When indenting, the message is prepended by the Prefix string (if not empty) +// followed by the depth level iterations of the Tab string. +// The depth level is provided by an attribute named by the Key string. +// This should be either an integer or a pointer to a DepthLevel object. +type Indentation struct { + // Prefix string used before indentation (optional). + Prefix string + + // Tab represents the additional indentation per depth level. + // It is probably better to not use an actual tab character here, + // but instead use some number of spaces. + Tab string + + // Key is the attribute key that will hold the depth number. + // When not provided the key is set to "depth". + Key string +} + +func (indent *Indentation) indentString(depth int64) string { + if indent.isZero() || depth <= 0 { + return "" + } + return indent.Prefix + strings.Repeat(indent.Tab, int(depth)) +} + +// DefaultIndentation returns an Indentation struct with the specified tag string, +// no Prefix string, and Key set to the default indentation key. +// Other configurations (e.g. featuring a Prefix or non-default Key) +// must be set manually. +func DefaultIndentation(tab string) Indentation { + return Indentation{ + Tab: " ", + Key: defaultIndentKey, + } +} + +func (indent *Indentation) isZero() bool { + return indent.Prefix == "" && indent.Tab == "" } type Handler struct { @@ -66,6 +113,9 @@ func NewHandler(out io.Writer, opts *HandlerOptions) *Handler { if opts.Theme == nil { opts.Theme = NewDefaultTheme() } + if opts.Indent.Key == "" { + opts.Indent.Key = defaultIndentKey + } return &Handler{ opts: *opts, // Copy struct out: out, @@ -75,7 +125,7 @@ func NewHandler(out io.Writer, opts *HandlerOptions) *Handler { } } -// Enabled implements slog.Handler. +// / Enabled implements slog.Handler. func (h *Handler) Enabled(_ context.Context, l slog.Level) bool { return l >= h.opts.Level.Level() } @@ -89,12 +139,40 @@ func (h *Handler) Handle(_ context.Context, rec slog.Record) error { if h.opts.AddSource && rec.PC > 0 { h.enc.writeSource(buf, rec.PC, cwd) } - h.enc.writeMessage(buf, rec.Level, rec.Message) - buf.copy(&h.context) - rec.Attrs(func(a slog.Attr) bool { - h.enc.writeAttr(buf, a, h.group) - return true - }) + if h.opts.Indent.isZero() { + h.enc.writeMessage(buf, rec.Level, rec.Message) + buf.copy(&h.context) + rec.Attrs(func(a slog.Attr) bool { + h.enc.writeAttr(buf, a, h.group) + return true + }) + } else { + + // Indent the message and attributes. + // Can't just ask for the depth key, must iterate through attributes to find it. + var depth int64 + rec.Attrs(func(a slog.Attr) bool { + if a.Key == h.opts.Indent.Key { + value := a.Value + if value.Kind() == slog.KindLogValuer { + value = a.Value.LogValuer().LogValue() + } + if value.Kind() == slog.KindInt64 { + depth = value.Int64() + // If multiple depth key entries only the first one is used. + return false + } + } + return true + }) + h.enc.writeMessage(buf, rec.Level, h.opts.Indent.indentString(depth)+rec.Message) + buf.copy(&h.context) + // Second iteration over attributes to push them onto the encoder. + rec.Attrs(func(a slog.Attr) bool { + h.enc.writeAttr(buf, a, h.group) + return true + }) + } h.enc.NewLine(buf) if _, err := buf.WriteTo(h.out); err != nil { buf.Reset() @@ -135,3 +213,29 @@ func (h *Handler) WithGroup(name string) slog.Handler { enc: h.enc, } } + +// DepthValuer represents an indentation depth object (an int64). +// These objects can be incremented on entry to a function and decremented in a defer statement. +// Use a pointer to a DepthValuer object in logging statements, do not pass the object itself. +// This object is not thread safe. Using it as a global variable (the mostly likely usage) +// in a multithreaded application will result in unpredictable values in different threads. +type DepthValuer struct { + depth int +} + +// LogValue implements the slog.LogValuer interface. +func (dv *DepthValuer) LogValue() slog.Value { + return slog.IntValue(int(dv.depth)) +} + +// Increment the depth value. +// Use this at the head of a function or important code block. +func (dv *DepthValuer) Increment() { + dv.depth += 1 +} + +// Decrement the depth value. +// Use this after an important code block or as a defer statement in a function. +func (dv *DepthValuer) Decrement() { + dv.depth -= 1 +}