Skip to content

Commit

Permalink
zap.Any add benchmarks (#1311)
Browse files Browse the repository at this point in the history
This is a prefactor for #1301, #1302, #1304, #1305, #1307, #1308 and #1310.

We're writing various approaches to reduce the stack size and it's
painful to keep copy-pasting the tests between PRs. This was suggested
in @prashantv in #1307.

The tests are mostly based on tests in #1303, but made "more generic",
as #1307 we might want to test across more than just a single type.
It does make the tests a bit harder to setup. Some of the setup is
inconvenient (we duplicate the value in both `typed` and `any` version
of the tests) but hopefully okay to understand. A fully non-duplicated
alternative would likely require something like #1310 itself.

For #1307 in particular a test against interface type would likely be
needed, so adding it here too.

The tests compare two code paths, with the same arguments, one using a
strongly typed method and second using `zap.Any`. We have:
- a simple "create field" case for a baseline
- a "create and log" case for a realistic case (we typically log the fields)
- a "create and log in a goroutine" case for the pathological case
  we're trying to solve for.
- a "create and long in goroutine in a pre-warmed system" that does the
  above, but before tries to affect the starting goroutine stack size
  to provide an realistic example.
  Without this, for any tests with 2+ goroutines, the cost of `zap.Any`
  is not visible, as we always end up expanding the stack even in the
  strongly typed methods.

The test results are:
```
goos: darwin
goarch: arm64
pkg: go.uber.org/zap
BenchmarkAny/string-typ-no-logger               166879518                6.988 ns/op           0 B/op          0 allocs/op
BenchmarkAny/string-typ-no-logger-12            167398297                6.973 ns/op           0 B/op          0 allocs/op
BenchmarkAny/string-any-no-logger               87669631                13.97 ns/op            0 B/op          0 allocs/op
BenchmarkAny/string-any-no-logger-12            86760837                14.11 ns/op            0 B/op          0 allocs/op
BenchmarkAny/string-typ-logger                   3059485               395.5 ns/op            64 B/op          1 allocs/op
BenchmarkAny/string-typ-logger-12                3141176               379.7 ns/op            64 B/op          1 allocs/op
BenchmarkAny/string-any-logger                   2995699               401.3 ns/op            64 B/op          1 allocs/op
BenchmarkAny/string-any-logger-12                3071046               391.1 ns/op            64 B/op          1 allocs/op
BenchmarkAny/string-typ-logger-go                 784323              1351 ns/op             146 B/op          2 allocs/op
BenchmarkAny/string-typ-logger-go-12             2000835               613.9 ns/op            96 B/op          2 allocs/op
BenchmarkAny/string-any-logger-go                 477486              2479 ns/op             117 B/op          2 allocs/op
BenchmarkAny/string-any-logger-go-12             1830955               680.0 ns/op           112 B/op          2 allocs/op
BenchmarkAny/string-typ-logger-go-stack           841566              1328 ns/op              96 B/op          2 allocs/op
BenchmarkAny/string-typ-logger-go-stack-12       2625226               479.6 ns/op            96 B/op          2 allocs/op
BenchmarkAny/string-any-logger-go-stack           486084              2493 ns/op             112 B/op          2 allocs/op
BenchmarkAny/string-any-logger-go-stack-12       2658640               667.9 ns/op           112 B/op          2 allocs/op
BenchmarkAny/stringer-typ-no-logger             147314238                8.034 ns/op           0 B/op          0 allocs/op
BenchmarkAny/stringer-typ-no-logger-12          157857937                7.436 ns/op           0 B/op          0 allocs/op
BenchmarkAny/stringer-any-no-logger             58872349                20.19 ns/op            0 B/op          0 allocs/op
BenchmarkAny/stringer-any-no-logger-12          60532305                20.27 ns/op            0 B/op          0 allocs/op
BenchmarkAny/stringer-typ-logger                 3094204               411.7 ns/op            64 B/op          1 allocs/op
BenchmarkAny/stringer-typ-logger-12              3163489               383.7 ns/op            64 B/op          1 allocs/op
BenchmarkAny/stringer-any-logger                 2981940               427.2 ns/op            64 B/op          1 allocs/op
BenchmarkAny/stringer-any-logger-12              2777792               394.0 ns/op            64 B/op          1 allocs/op
BenchmarkAny/stringer-typ-logger-go               911761              1335 ns/op              96 B/op          2 allocs/op
BenchmarkAny/stringer-typ-logger-go-12           2006440               605.2 ns/op            96 B/op          2 allocs/op
BenchmarkAny/stringer-any-logger-go               467934              2518 ns/op             112 B/op          2 allocs/op
BenchmarkAny/stringer-any-logger-go-12           1786076               683.1 ns/op           112 B/op          2 allocs/op
BenchmarkAny/stringer-typ-logger-go-stack         855794              1316 ns/op              96 B/op          2 allocs/op
BenchmarkAny/stringer-typ-logger-go-stack-12     2598783               434.5 ns/op            96 B/op          2 allocs/op
BenchmarkAny/stringer-any-logger-go-stack         473282              2474 ns/op             112 B/op          2 allocs/op
BenchmarkAny/stringer-any-logger-go-stack-12     2020183               651.9 ns/op           112 B/op          2 allocs/op
PASS
ok      go.uber.org/zap 53.516s
```
  • Loading branch information
rabbbit committed Aug 2, 2023
1 parent 17e02a5 commit cd2f6ac
Showing 1 changed file with 78 additions and 0 deletions.
78 changes: 78 additions & 0 deletions logger_bench_test.go
Original file line number Diff line number Diff line change
Expand Up @@ -22,6 +22,8 @@ package zap

import (
"errors"
"runtime"
"sync"
"testing"
"time"

Expand Down Expand Up @@ -238,3 +240,79 @@ func Benchmark100Fields(b *testing.B) {
logger.With(first...).Info("Child loggers with lots of context.", second...)
}
}

func BenchmarkAny(b *testing.B) {
key := "some-long-string-longer-than-16"

tests := []struct {
name string
typed func() Field
anyArg any
}{
{
name: "string",
typed: func() Field { return String(key, "yet-another-long-string") },
anyArg: "yet-another-long-string",
},
{
name: "stringer",
typed: func() Field { return Stringer(key, InfoLevel) },
anyArg: InfoLevel,
},
}

for _, tt := range tests {
b.Run(tt.name, func(b *testing.B) {
b.Run("field-only", func(b *testing.B) {
b.Run("typed", func(b *testing.B) {
withBenchedLogger(b, func(log *Logger) {
f := tt.typed()
runtime.KeepAlive(f)
})
})
b.Run("any", func(b *testing.B) {
withBenchedLogger(b, func(log *Logger) {
f := Any(key, tt.anyArg)
runtime.KeepAlive(f)
})
})
})
b.Run("log", func(b *testing.B) {
b.Run("typed", func(b *testing.B) {
withBenchedLogger(b, func(log *Logger) {
log.Info("", tt.typed())
})
})
b.Run("any", func(b *testing.B) {
withBenchedLogger(b, func(log *Logger) {
log.Info("", Any(key, tt.anyArg))
})
})
})
b.Run("log-go", func(b *testing.B) {
b.Run("typed", func(b *testing.B) {
withBenchedLogger(b, func(log *Logger) {
var wg sync.WaitGroup
wg.Add(1)
go func() {
log.Info("", tt.typed())
wg.Done()
}()
wg.Wait()
})
})
b.Run("any", func(b *testing.B) {
withBenchedLogger(b, func(log *Logger) {
var wg sync.WaitGroup
wg.Add(1)
go func() {
log.Info("", Any(key, tt.anyArg))
wg.Done()
}()
wg.Wait()
})
})
})
})
}
}

0 comments on commit cd2f6ac

Please sign in to comment.