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 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- we decided it's not worth the complication. The test results are: ``` ❯ go test -bench BenchmarkAny -benchmem -cpu 1 goos: darwin goarch: arm64 pkg: go.uber.org/zap BenchmarkAny/string/field-only/typed 161981473 7.374 ns/op 0 B/op 0 allocs/op BenchmarkAny/string/field-only/any 82343354 14.67 ns/op 0 B/op 0 allocs/op BenchmarkAny/string/log/typed 2965648 416.1 ns/op 64 B/op 1 allocs/op BenchmarkAny/string/log/any 2920292 418.8 ns/op 64 B/op 1 allocs/op BenchmarkAny/string/log-go/typed 1000000 1158 ns/op 112 B/op 3 allocs/op BenchmarkAny/string/log-go/any 553144 2152 ns/op 128 B/op 3 allocs/op BenchmarkAny/stringer/field-only/typed 160509367 7.548 ns/op 0 B/op 0 allocs/op BenchmarkAny/stringer/field-only/any 51330402 23.45 ns/op 0 B/op 0 allocs/op BenchmarkAny/stringer/log/typed 3221404 377.0 ns/op 64 B/op 1 allocs/op BenchmarkAny/stringer/log/any 2726443 393.5 ns/op 64 B/op 1 allocs/op BenchmarkAny/stringer/log-go/typed 1000000 1129 ns/op 112 B/op 3 allocs/op BenchmarkAny/stringer/log-go/any 558602 2147 ns/op 128 B/op 3 allocs/op PASS ok go.uber.org/zap 19.426s ``` On gotip: ``` ❯ gotip test -bench BenchmarkAny -benchmem -cpu 1 goos: darwin goarch: arm64 pkg: go.uber.org/zap BenchmarkAny/string/field-only/typed 155084869 7.603 ns/op 0 B/op 0 allocs/op BenchmarkAny/string/field-only/any 82740788 14.55 ns/op 0 B/op 0 allocs/op BenchmarkAny/string/log/typed 2800495 411.6 ns/op 64 B/op 1 allocs/op BenchmarkAny/string/log/any 2896258 411.7 ns/op 64 B/op 1 allocs/op BenchmarkAny/string/log-go/typed 1000000 1155 ns/op 112 B/op 3 allocs/op BenchmarkAny/string/log-go/any 551599 2168 ns/op 128 B/op 3 allocs/op BenchmarkAny/stringer/field-only/typed 159505488 7.578 ns/op 0 B/op 0 allocs/op BenchmarkAny/stringer/field-only/any 51406354 23.78 ns/op 0 B/op 0 allocs/op BenchmarkAny/stringer/log/typed 3011210 388.6 ns/op 64 B/op 1 allocs/op BenchmarkAny/stringer/log/any 3010370 395.1 ns/op 64 B/op 1 allocs/op BenchmarkAny/stringer/log-go/typed 1000000 1161 ns/op 112 B/op 3 allocs/op BenchmarkAny/stringer/log-go/any 553860 2161 ns/op 128 B/op 3 allocs/op PASS ok go.uber.org/zap 19.391s ``` on amd64 (similar, 2x worse stack growth impact) ``` % go test -bench BenchmarkAny -benchmem -cpu 1 goos: linux goarch: amd64 pkg: go.uber.org/zap cpu: AMD EPYC 7B13 BenchmarkAny/string/field-only/typed 47534053 25.23 ns/op 0 B/op 0 allocs/op BenchmarkAny/string/field-only/any 36913526 32.57 ns/op 0 B/op 0 allocs/op BenchmarkAny/string/log/typed 1693508 725.7 ns/op 64 B/op 1 allocs/op BenchmarkAny/string/log/any 1576172 765.3 ns/op 64 B/op 1 allocs/op BenchmarkAny/string/log-go/typed 516832 2343 ns/op 112 B/op 3 allocs/op BenchmarkAny/string/log-go/any 243692 4404 ns/op 128 B/op 3 allocs/op BenchmarkAny/stringer/field-only/typed 48735537 24.73 ns/op 0 B/op 0 allocs/op BenchmarkAny/stringer/field-only/any 26115684 47.24 ns/op 0 B/op 0 allocs/op BenchmarkAny/stringer/log/typed 1761630 677.5 ns/op 64 B/op 1 allocs/op BenchmarkAny/stringer/log/any 1646913 705.4 ns/op 64 B/op 1 allocs/op BenchmarkAny/stringer/log-go/typed 534187 2275 ns/op 112 B/op 3 allocs/op BenchmarkAny/stringer/log-go/any 273787 4348 ns/op 128 B/op 3 allocs/op PASS ok go.uber.org/zap 18.890s ```
uber-go · Aug 1, 2023 · ae3953e · ae3953e
2 parents 8db347b + a094551
commit ae3953e
Showing 1 changed file with 78 additions and 0 deletions.
diff --git 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()
+					})
+				})
+			})
+		})
+	}
+}