From 7c0529b7eff913c1c8d88df26bf43b4cc0358405 Mon Sep 17 00:00:00 2001 From: Pawel Krolikowski Date: Sun, 30 Jul 2023 16:26:45 -0400 Subject: [PATCH 1/6] zap.Any add benchmarks 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 ``` --- logger_bench_test.go | 129 +++++++++++++++++++++++++++++++++++++++++++ 1 file changed, 129 insertions(+) diff --git a/logger_bench_test.go b/logger_bench_test.go index 41e661577..48d73e585 100644 --- a/logger_bench_test.go +++ b/logger_bench_test.go @@ -22,6 +22,8 @@ package zap import ( "errors" + "runtime" + "sync" "testing" "time" @@ -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() + }) + } +} From 38f524a2a643de8d1fa804cf31996c833d595159 Mon Sep 17 00:00:00 2001 From: Pawel Krolikowski Date: Mon, 31 Jul 2023 16:53:57 -0400 Subject: [PATCH 2/6] reviews --- logger_bench_test.go | 178 ++++++++++++++++++++++--------------------- 1 file changed, 90 insertions(+), 88 deletions(-) diff --git a/logger_bench_test.go b/logger_bench_test.go index 48d73e585..6ea1abb8e 100644 --- a/logger_bench_test.go +++ b/logger_bench_test.go @@ -249,7 +249,11 @@ func dummy(wg *sync.WaitGroup, s string, i int) string { return dummy(wg, s, i-1) } -func stackGrower(n int) *sync.WaitGroup { +// avgStackIncreaser starts a background goroutine with a variable +// stack size. The goal is to move the average stack size higher, +// since https://go-review.googlesource.com/c/go/+/345889 this affects +// goroutine starting stack size. +func avgStackIncreaser(n int) *sync.WaitGroup { wg := sync.WaitGroup{} wg.Add(1) @@ -258,16 +262,7 @@ func stackGrower(n int) *sync.WaitGroup { } func BenchmarkAny(b *testing.B) { - var ( - logger = New( - zapcore.NewCore( - zapcore.NewJSONEncoder(NewProductionConfig().EncoderConfig), - &ztest.Discarder{}, - DebugLevel, - ), - ) - key = "some-long-string-longer-than-16" - ) + key := "some-long-string-longer-than-16" tests := []struct { name string @@ -287,83 +282,90 @@ func BenchmarkAny(b *testing.B) { } 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() + 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) { + wg := sync.WaitGroup{} + wg.Add(b.N) + b.ResetTimer() + withBenchedLogger(b, func(log *Logger) { + go func() { + log.Info("", tt.typed()) + wg.Done() + }() + }) + wg.Wait() + }) + b.Run("any", func(b *testing.B) { + wg := sync.WaitGroup{} + wg.Add(b.N) + b.ResetTimer() + withBenchedLogger(b, func(log *Logger) { + go func() { + log.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("log-go-stack", func(b *testing.B) { + defer avgStackIncreaser(5000).Done() + b.ResetTimer() + b.Run("typed", func(b *testing.B) { + wg := sync.WaitGroup{} + wg.Add(b.N) + withBenchedLogger(b, func(log *Logger) { + go func() { + log.Info("", tt.typed()) + wg.Done() + }() + }) + wg.Wait() + }) + b.Run("any", func(b *testing.B) { + wg := sync.WaitGroup{} + wg.Add(b.N) + withBenchedLogger(b, func(log *Logger) { + go func() { + log.Info("", Any(key, tt.anyArg)) + wg.Done() + }() + }) + wg.Wait() + }) + b.StopTimer() + }) }) } } From 2c66690b36c804b20fe050f3fcaeffade2c77e30 Mon Sep 17 00:00:00 2001 From: Pawel Krolikowski Date: Mon, 31 Jul 2023 17:40:32 -0400 Subject: [PATCH 3/6] rename --- logger_bench_test.go | 6 +++--- 1 file changed, 3 insertions(+), 3 deletions(-) diff --git a/logger_bench_test.go b/logger_bench_test.go index 6ea1abb8e..a364132a7 100644 --- a/logger_bench_test.go +++ b/logger_bench_test.go @@ -249,11 +249,11 @@ func dummy(wg *sync.WaitGroup, s string, i int) string { return dummy(wg, s, i-1) } -// avgStackIncreaser starts a background goroutine with a variable +// increaseAvgStack starts a background goroutine with a variable // stack size. The goal is to move the average stack size higher, // since https://go-review.googlesource.com/c/go/+/345889 this affects // goroutine starting stack size. -func avgStackIncreaser(n int) *sync.WaitGroup { +func increaseAvgStack(n int) *sync.WaitGroup { wg := sync.WaitGroup{} wg.Add(1) @@ -340,7 +340,7 @@ func BenchmarkAny(b *testing.B) { // 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("log-go-stack", func(b *testing.B) { - defer avgStackIncreaser(5000).Done() + defer increaseAvgStack(5000).Done() b.ResetTimer() b.Run("typed", func(b *testing.B) { wg := sync.WaitGroup{} From f590283aff840d36665edac7f5c334ab45370dfa Mon Sep 17 00:00:00 2001 From: Pawel Krolikowski Date: Mon, 31 Jul 2023 18:51:41 -0400 Subject: [PATCH 4/6] review --- logger_bench_test.go | 26 +++++++++++++------------- 1 file changed, 13 insertions(+), 13 deletions(-) diff --git a/logger_bench_test.go b/logger_bench_test.go index a364132a7..b53260ee4 100644 --- a/logger_bench_test.go +++ b/logger_bench_test.go @@ -311,28 +311,26 @@ func BenchmarkAny(b *testing.B) { }) b.Run("log-go", func(b *testing.B) { b.Run("typed", func(b *testing.B) { - wg := sync.WaitGroup{} - wg.Add(b.N) - b.ResetTimer() withBenchedLogger(b, func(log *Logger) { + var wg sync.WaitGroup + wg.Add(1) go func() { log.Info("", tt.typed()) wg.Done() }() + wg.Wait() }) - wg.Wait() }) b.Run("any", func(b *testing.B) { - wg := sync.WaitGroup{} - wg.Add(b.N) - b.ResetTimer() withBenchedLogger(b, func(log *Logger) { + var wg sync.WaitGroup + wg.Add(1) go func() { log.Info("", Any(key, tt.anyArg)) wg.Done() }() + wg.Wait() }) - wg.Wait() }) }) // The stack growing below simulates production setup where some other @@ -340,29 +338,31 @@ func BenchmarkAny(b *testing.B) { // 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("log-go-stack", func(b *testing.B) { - defer increaseAvgStack(5000).Done() + defer increaseAvgStack(1000).Done() b.ResetTimer() b.Run("typed", func(b *testing.B) { - wg := sync.WaitGroup{} - wg.Add(b.N) withBenchedLogger(b, func(log *Logger) { + var wg sync.WaitGroup + wg.Add(1) go func() { log.Info("", tt.typed()) wg.Done() }() + wg.Wait() }) - wg.Wait() }) b.Run("any", func(b *testing.B) { wg := sync.WaitGroup{} wg.Add(b.N) withBenchedLogger(b, func(log *Logger) { + var wg sync.WaitGroup + wg.Add(1) go func() { log.Info("", Any(key, tt.anyArg)) wg.Done() }() + wg.Wait() }) - wg.Wait() }) b.StopTimer() }) From cd52de1798324326f6ae48e3ae9b3c83b7235ae0 Mon Sep 17 00:00:00 2001 From: Pawel Krolikowski Date: Mon, 31 Jul 2023 21:55:18 -0400 Subject: [PATCH 5/6] farewell, my friend --- logger_bench_test.go | 45 -------------------------------------------- 1 file changed, 45 deletions(-) diff --git a/logger_bench_test.go b/logger_bench_test.go index b53260ee4..9938f8ef8 100644 --- a/logger_bench_test.go +++ b/logger_bench_test.go @@ -249,18 +249,6 @@ func dummy(wg *sync.WaitGroup, s string, i int) string { return dummy(wg, s, i-1) } -// increaseAvgStack starts a background goroutine with a variable -// stack size. The goal is to move the average stack size higher, -// since https://go-review.googlesource.com/c/go/+/345889 this affects -// goroutine starting stack size. -func increaseAvgStack(n int) *sync.WaitGroup { - wg := sync.WaitGroup{} - wg.Add(1) - - go dummy(&wg, "hi", n) - return &wg -} - func BenchmarkAny(b *testing.B) { key := "some-long-string-longer-than-16" @@ -333,39 +321,6 @@ func BenchmarkAny(b *testing.B) { }) }) }) - // 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("log-go-stack", func(b *testing.B) { - defer increaseAvgStack(1000).Done() - b.ResetTimer() - 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) { - wg := sync.WaitGroup{} - wg.Add(b.N) - withBenchedLogger(b, func(log *Logger) { - var wg sync.WaitGroup - wg.Add(1) - go func() { - log.Info("", Any(key, tt.anyArg)) - wg.Done() - }() - wg.Wait() - }) - }) - b.StopTimer() - }) }) } } From a094551b6e86138bceb7efeb496c7e3d44866bc4 Mon Sep 17 00:00:00 2001 From: Pawel Krolikowski Date: Mon, 31 Jul 2023 21:58:45 -0400 Subject: [PATCH 6/6] dummy --- logger_bench_test.go | 8 -------- 1 file changed, 8 deletions(-) diff --git a/logger_bench_test.go b/logger_bench_test.go index 9938f8ef8..bcf501a3f 100644 --- a/logger_bench_test.go +++ b/logger_bench_test.go @@ -241,14 +241,6 @@ func Benchmark100Fields(b *testing.B) { } } -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 BenchmarkAny(b *testing.B) { key := "some-long-string-longer-than-16"