From cd2f6ac1a5d416e832fe4f658a2b9e5e9d889a63 Mon Sep 17 00:00:00 2001 From: Pawel Krolikowski Date: Sun, 30 Jul 2023 16:26:45 -0400 Subject: [PATCH] zap.Any add benchmarks (#1311) 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 ``` --- logger_bench_test.go | 78 ++++++++++++++++++++++++++++++++++++++++++++ 1 file changed, 78 insertions(+) diff --git a/logger_bench_test.go b/logger_bench_test.go index 41e661577..bcf501a3f 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,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() + }) + }) + }) + }) + } +}