Skip to content

Commit

Permalink
zap.Any add benchmarks
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 stock 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 Jul 30, 2023
1 parent 8db347b commit 7c0529b
Showing 1 changed file with 129 additions and 0 deletions.
129 changes: 129 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,130 @@ func Benchmark100Fields(b *testing.B) {
logger.With(first...).Info("Child loggers with lots of context.", second...)
}
}

func dummy(wg *sync.WaitGroup, s string, i int) string {
if i == 0 {
wg.Wait()
return "1" + s
}
return dummy(wg, s, i-1)
}

func stackGrower(n int) *sync.WaitGroup {
wg := sync.WaitGroup{}
wg.Add(1)

go dummy(&wg, "hi", n)
return &wg
}

func BenchmarkAny(b *testing.B) {
var (
logger = New(
zapcore.NewCore(
zapcore.NewJSONEncoder(NewProductionConfig().EncoderConfig),
&ztest.Discarder{},
DebugLevel,
),
)
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+"-typ-no-logger", func(b *testing.B) {
for i := 0; i < b.N; i++ {
f := tt.typed()
runtime.KeepAlive(f)
}
})
b.Run(tt.name+"-any-no-logger", func(b *testing.B) {
for i := 0; i < b.N; i++ {
f := Any(key, tt.anyArg)
runtime.KeepAlive(f)
}
})
b.Run(tt.name+"-typ-logger", func(b *testing.B) {
for i := 0; i < b.N; i++ {
logger.Info("", tt.typed())
}
})
b.Run(tt.name+"-any-logger", func(b *testing.B) {
for i := 0; i < b.N; i++ {
logger.Info("", Any(key, tt.anyArg))
}
})
b.Run(tt.name+"-typ-logger-go", func(b *testing.B) {
wg := sync.WaitGroup{}
wg.Add(b.N)
b.ResetTimer()
for i := 0; i < b.N; i++ {
go func() {
logger.Info("", tt.typed())
wg.Done()
}()
}
wg.Wait()
})
b.Run(tt.name+"-any-logger-go", func(b *testing.B) {
wg := sync.WaitGroup{}
wg.Add(b.N)
b.ResetTimer()
for i := 0; i < b.N; i++ {
go func() {
logger.Info("", Any(key, tt.anyArg))
wg.Done()
}()
}
wg.Wait()
})
// The stack growing below simulates production setup where some other
// goroutines exist and affect the starting goroutine stack size up.
// Otherwise, for tests with 2+ goroutines, the cost of starting the goroutine
// dominates and the cost of `any` stack overallocation is not visible.
b.Run(tt.name+"-typ-logger-go-stack", func(b *testing.B) {
wg := sync.WaitGroup{}
wg.Add(b.N)
defer stackGrower(2000).Done()
b.ResetTimer()
for i := 0; i < b.N; i++ {
go func() {
logger.Info("", tt.typed())
wg.Done()
}()
}
wg.Wait()
b.StopTimer()
})
b.Run(tt.name+"-any-logger-go-stack", func(b *testing.B) {
wg := sync.WaitGroup{}
wg.Add(b.N)
defer stackGrower(2000).Done()
b.ResetTimer()
for i := 0; i < b.N; i++ {
go func() {
logger.Info("", Any(key, tt.anyArg))
wg.Done()
}()
}
wg.Wait()
b.StopTimer()
})
}
}

0 comments on commit 7c0529b

Please sign in to comment.