telemetry/log: sample reference for benchmarking harness

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 <emm.odeke@gmail.com>
TryBot-Result: Gobot Gobot <gobot@golang.org>
Reviewed-by: Ian Cottrell <iancottrell@google.com>

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)
+			}
+		}
+	}
+}