From 2ad5dca7a53ca93a6dc1cbdf40753c1291f63eec Mon Sep 17 00:00:00 2001 From: Emmanuel T Odeke Date: Thu, 19 Dec 2019 08:57:21 -0800 Subject: [PATCH] telemetry/log: sample reference for benchmarking harness MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Serves as a reference harness to get benchmarking started. Steps to run benchmark: $ go test -run=^$ -bench=. -count=10 After you grab the output, put the various comparisons into files before.txt and after.txt then edit those result names to have a common name e.g. s/BenchmarkLoggingNoExporter/BenchmarkIt/g s/BenchmarkNoTracingNoMetricsNoLogging/BenchmarkIt/g s/BenchmarkLoggingStdlib/BenchmarkIt/g Now run benchstat: * All compared $ benchstat no_log.txt tellog.txt stdlog.txt name \ time/op no_log.txt tellog.txt stdlog.txt It-8 289ns ± 2% 2780ns ± 3% 5100ns ± 3% name \ alloc/op no_log.txt tellog.txt stdlog.txt It-8 80.0B ± 0% 728.0B ± 0% 568.0B ± 0% name \ allocs/op no_log.txt tellog.txt stdlog.txt It-8 5.00 ± 0% 32.00 ± 0% 28.00 ± 0% * No logging vs telemetry log $ benchstat no_log.txt tellog.txt name old time/op new time/op delta It-8 289ns ± 2% 2780ns ± 3% +862.31% (p=0.000 n=10+9) name old alloc/op new alloc/op delta It-8 80.0B ± 0% 728.0B ± 0% +810.00% (p=0.000 n=10+10) name old allocs/op new allocs/op delta It-8 5.00 ± 0% 32.00 ± 0% +540.00% (p=0.000 n=10+10) * No logging vs Standard library "log" $ benchstat no_log.txt stdlog.txt name old time/op new time/op delta It-8 289ns ± 2% 5100ns ± 3% +1665.16% (p=0.000 n=10+9) name old alloc/op new alloc/op delta It-8 80.0B ± 0% 568.0B ± 0% +610.00% (p=0.000 n=10+10) name old allocs/op new allocs/op delta It-8 5.00 ± 0% 28.00 ± 0% +460.00% (p=0.000 n=10+10) * telemetry log vs Standard library "log" $ benchstat tellog.txt stdlog.txt name old time/op new time/op delta It-8 2.78µs ± 3% 5.10µs ± 3% +83.43% (p=0.000 n=9+9) name old alloc/op new alloc/op delta It-8 728B ± 0% 568B ± 0% -21.98% (p=0.000 n=10+10) name old allocs/op new allocs/op delta It-8 32.0 ± 0% 28.0 ± 0% -12.50% (p=0.000 n=10+10) Change-Id: I53b15e9da315615278c576f3a60108435417a9f7 Reviewed-on: https://go-review.googlesource.com/c/tools/+/212078 Run-TryBot: Emmanuel Odeke TryBot-Result: Gobot Gobot Reviewed-by: Ian Cottrell --- internal/telemetry/log/bench_test.go | 110 +++++++++++++++++++++++++++ 1 file changed, 110 insertions(+) create mode 100644 internal/telemetry/log/bench_test.go diff --git a/internal/telemetry/log/bench_test.go b/internal/telemetry/log/bench_test.go new file mode 100644 index 0000000000..dc77bd6a1e --- /dev/null +++ b/internal/telemetry/log/bench_test.go @@ -0,0 +1,110 @@ +package log_test + +import ( + "context" + stdlog "log" + "strings" + "testing" + + tellog "golang.org/x/tools/internal/telemetry/log" + "golang.org/x/tools/internal/telemetry/tag" +) + +func init() { + stdlog.SetOutput(new(noopWriter)) +} + +type noopWriter int + +func (nw *noopWriter) Write(b []byte) (int, error) { + return len(b), nil +} + +func A(a int) int { + if a > 0 { + _ = 10 * 12 + } + return B("Called from A") +} + +func B(b string) int { + b = strings.ToUpper(b) + if len(b) > 1024 { + b = strings.ToLower(b) + } + return len(b) +} + +func A_log(ctx context.Context, a int) int { + if a > 0 { + tellog.Print(ctx, "a > 0", tag.Of("a", a)) + _ = 10 * 12 + } + tellog.Print(ctx, "calling b") + return B_log(ctx, "Called from A") +} + +func B_log(ctx context.Context, b string) int { + b = strings.ToUpper(b) + tellog.Print(ctx, "b uppercased, so lowercased", tag.Of("len_b", len(b))) + if len(b) > 1024 { + b = strings.ToLower(b) + tellog.Print(ctx, "b > 1024, so lowercased", tag.Of("b", b)) + } + return len(b) +} + +func A_log_stdlib(a int) int { + if a > 0 { + stdlog.Printf("a > 0 where a=%d", a) + _ = 10 * 12 + } + stdlog.Print("calling b") + return B_log_stdlib("Called from A") +} + +func B_log_stdlib(b string) int { + b = strings.ToUpper(b) + stdlog.Printf("b uppercased, so lowercased where len_b=%d", len(b)) + if len(b) > 1024 { + b = strings.ToLower(b) + stdlog.Printf("b > 1024, so lowercased where b=%s", b) + } + return len(b) +} + +func BenchmarkNoTracingNoMetricsNoLogging(b *testing.B) { + b.ReportAllocs() + values := []int{0, 10, 20, 100, 1000} + for i := 0; i < b.N; i++ { + for _, value := range values { + if g := A(value); g <= 0 { + b.Fatalf("Unexpected got g(%d) <= 0", g) + } + } + } +} + +func BenchmarkLoggingNoExporter(b *testing.B) { + b.ReportAllocs() + values := []int{0, 10, 20, 100, 1000} + for i := 0; i < b.N; i++ { + for _, value := range values { + if g := A_log(context.TODO(), value); g <= 0 { + b.Fatalf("Unexpected got g(%d) <= 0", g) + } + } + } +} + +func BenchmarkLoggingStdlib(b *testing.B) { + b.ReportAllocs() + values := []int{0, 10, 20, 100, 1000} + for i := 0; i < b.N; i++ { + for _, value := range values { + if g := A_log_stdlib(value); g <= 0 { + b.Fatalf("Unexpected got g(%d) <= 0", g) + } + } + } +}