1
0
mirror of https://github.com/golang/go synced 2024-11-18 14:04:45 -07:00
go/internal/telemetry/bench_test.go

150 lines
3.4 KiB
Go
Raw Normal View History

package telemetry_test
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>
2019-12-19 09:57:21 -07:00
import (
"context"
"log"
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>
2019-12-19 09:57:21 -07:00
"testing"
"golang.org/x/tools/internal/telemetry/event"
"golang.org/x/tools/internal/telemetry/export"
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>
2019-12-19 09:57:21 -07:00
)
type Hooks struct {
A func(ctx context.Context, a int) (context.Context, func())
B func(ctx context.Context, b string) (context.Context, func())
}
var (
aValue = event.NewIntKey("a", "")
bValue = event.NewStringKey("b", "")
aCount = event.NewInt64Key("aCount", "Count of time A is called.")
aStat = event.NewIntKey("aValue", "A value.")
bCount = event.NewInt64Key("B", "Count of time B is called.")
bLength = event.NewIntKey("BLen", "B length.")
Baseline = Hooks{
A: func(ctx context.Context, a int) (context.Context, func()) {
return ctx, func() {}
},
B: func(ctx context.Context, b string) (context.Context, func()) {
return ctx, func() {}
},
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>
2019-12-19 09:57:21 -07:00
}
StdLog = Hooks{
A: func(ctx context.Context, a int) (context.Context, func()) {
log.Printf("A where a=%d", a)
return ctx, func() {}
},
B: func(ctx context.Context, b string) (context.Context, func()) {
log.Printf("B where b=%q", b)
return ctx, func() {}
},
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>
2019-12-19 09:57:21 -07:00
}
Log = Hooks{
A: func(ctx context.Context, a int) (context.Context, func()) {
internal/telemetry: add fast non variadic event functions This adds variants of the main event functions that take specific numbers of tags, rather than a tag slice. This reduces the allocation cost when using those functions with no exporter to zero. name old time/op new time/op delta /Baseline-8 158ns ± 7% 154ns ± 1% ~ /StdLog-8 6.90µs ± 1% 6.83µs ± 1% ~ /LogNoExporter-8 1.78µs ± 5% 1.20µs ± 3% -32.37% /TraceNoExporter-8 3.11µs ± 3% 2.48µs ± 2% -20.39% /StatsNoExporter-8 3.18µs ± 5% 1.87µs ± 3% -41.16% /Log-8 46.8µs ± 2% 44.8µs ± 1% -4.33% /Trace-8 55.1µs ± 5% 54.3µs ± 3% ~ /Stats-8 15.8µs ± 3% 13.4µs ± 1% -15.00% name old alloc/op new alloc/op delta /Baseline-8 0.00B 0.00B ~ /StdLog-8 552B ± 0% 552B ± 0% ~ /LogNoExporter-8 1.02kB ± 0% 0.00kB -100.00% /TraceNoExporter-8 1.54kB ± 0% 0.51kB ± 0% -66.67% /StatsNoExporter-8 2.05kB ± 0% 0.00kB -100.00% /Log-8 26.0kB ± 0% 24.0kB ± 0% -7.87% /Trace-8 28.7kB ± 0% 27.1kB ± 0% ~ /Stats-8 13.3kB ± 0% 10.2kB ± 0% -23.08% name old allocs/op new allocs/op delta /Baseline-8 0.00 0.00 ~ /StdLog-8 30.0 ± 0% 30.0 ± 0% ~ /LogNoExporter-8 16.0 ± 0% 0.0 -100.00% /TraceNoExporter-8 32.0 ± 0% 16.0 ± 0% -50.00% /StatsNoExporter-8 32.0 ± 0% 0.0 -100.00% /Log-8 430 ± 0% 382 ± 0% -11.16% /Trace-8 496 ± 0% 464 ± 0% -6.45% /Stats-8 192 ± 0% 128 ± 0% -33.33% Change-Id: I629c0d506ab07de6f12b0acbecfc7407f59a4285 Reviewed-on: https://go-review.googlesource.com/c/tools/+/225580 Run-TryBot: Ian Cottrell <iancottrell@google.com> TryBot-Result: Gobot Gobot <gobot@golang.org> Reviewed-by: Emmanuel Odeke <emm.odeke@gmail.com> Reviewed-by: Robert Findley <rfindley@google.com>
2020-03-25 20:50:00 -06:00
event.Print1(ctx, "A", aValue.Of(a))
return ctx, func() {}
},
B: func(ctx context.Context, b string) (context.Context, func()) {
internal/telemetry: add fast non variadic event functions This adds variants of the main event functions that take specific numbers of tags, rather than a tag slice. This reduces the allocation cost when using those functions with no exporter to zero. name old time/op new time/op delta /Baseline-8 158ns ± 7% 154ns ± 1% ~ /StdLog-8 6.90µs ± 1% 6.83µs ± 1% ~ /LogNoExporter-8 1.78µs ± 5% 1.20µs ± 3% -32.37% /TraceNoExporter-8 3.11µs ± 3% 2.48µs ± 2% -20.39% /StatsNoExporter-8 3.18µs ± 5% 1.87µs ± 3% -41.16% /Log-8 46.8µs ± 2% 44.8µs ± 1% -4.33% /Trace-8 55.1µs ± 5% 54.3µs ± 3% ~ /Stats-8 15.8µs ± 3% 13.4µs ± 1% -15.00% name old alloc/op new alloc/op delta /Baseline-8 0.00B 0.00B ~ /StdLog-8 552B ± 0% 552B ± 0% ~ /LogNoExporter-8 1.02kB ± 0% 0.00kB -100.00% /TraceNoExporter-8 1.54kB ± 0% 0.51kB ± 0% -66.67% /StatsNoExporter-8 2.05kB ± 0% 0.00kB -100.00% /Log-8 26.0kB ± 0% 24.0kB ± 0% -7.87% /Trace-8 28.7kB ± 0% 27.1kB ± 0% ~ /Stats-8 13.3kB ± 0% 10.2kB ± 0% -23.08% name old allocs/op new allocs/op delta /Baseline-8 0.00 0.00 ~ /StdLog-8 30.0 ± 0% 30.0 ± 0% ~ /LogNoExporter-8 16.0 ± 0% 0.0 -100.00% /TraceNoExporter-8 32.0 ± 0% 16.0 ± 0% -50.00% /StatsNoExporter-8 32.0 ± 0% 0.0 -100.00% /Log-8 430 ± 0% 382 ± 0% -11.16% /Trace-8 496 ± 0% 464 ± 0% -6.45% /Stats-8 192 ± 0% 128 ± 0% -33.33% Change-Id: I629c0d506ab07de6f12b0acbecfc7407f59a4285 Reviewed-on: https://go-review.googlesource.com/c/tools/+/225580 Run-TryBot: Ian Cottrell <iancottrell@google.com> TryBot-Result: Gobot Gobot <gobot@golang.org> Reviewed-by: Emmanuel Odeke <emm.odeke@gmail.com> Reviewed-by: Robert Findley <rfindley@google.com>
2020-03-25 20:50:00 -06:00
event.Print1(ctx, "B", bValue.Of(b))
return ctx, func() {}
},
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>
2019-12-19 09:57:21 -07:00
}
Trace = Hooks{
A: func(ctx context.Context, a int) (context.Context, func()) {
internal/telemetry: add fast non variadic event functions This adds variants of the main event functions that take specific numbers of tags, rather than a tag slice. This reduces the allocation cost when using those functions with no exporter to zero. name old time/op new time/op delta /Baseline-8 158ns ± 7% 154ns ± 1% ~ /StdLog-8 6.90µs ± 1% 6.83µs ± 1% ~ /LogNoExporter-8 1.78µs ± 5% 1.20µs ± 3% -32.37% /TraceNoExporter-8 3.11µs ± 3% 2.48µs ± 2% -20.39% /StatsNoExporter-8 3.18µs ± 5% 1.87µs ± 3% -41.16% /Log-8 46.8µs ± 2% 44.8µs ± 1% -4.33% /Trace-8 55.1µs ± 5% 54.3µs ± 3% ~ /Stats-8 15.8µs ± 3% 13.4µs ± 1% -15.00% name old alloc/op new alloc/op delta /Baseline-8 0.00B 0.00B ~ /StdLog-8 552B ± 0% 552B ± 0% ~ /LogNoExporter-8 1.02kB ± 0% 0.00kB -100.00% /TraceNoExporter-8 1.54kB ± 0% 0.51kB ± 0% -66.67% /StatsNoExporter-8 2.05kB ± 0% 0.00kB -100.00% /Log-8 26.0kB ± 0% 24.0kB ± 0% -7.87% /Trace-8 28.7kB ± 0% 27.1kB ± 0% ~ /Stats-8 13.3kB ± 0% 10.2kB ± 0% -23.08% name old allocs/op new allocs/op delta /Baseline-8 0.00 0.00 ~ /StdLog-8 30.0 ± 0% 30.0 ± 0% ~ /LogNoExporter-8 16.0 ± 0% 0.0 -100.00% /TraceNoExporter-8 32.0 ± 0% 16.0 ± 0% -50.00% /StatsNoExporter-8 32.0 ± 0% 0.0 -100.00% /Log-8 430 ± 0% 382 ± 0% -11.16% /Trace-8 496 ± 0% 464 ± 0% -6.45% /Stats-8 192 ± 0% 128 ± 0% -33.33% Change-Id: I629c0d506ab07de6f12b0acbecfc7407f59a4285 Reviewed-on: https://go-review.googlesource.com/c/tools/+/225580 Run-TryBot: Ian Cottrell <iancottrell@google.com> TryBot-Result: Gobot Gobot <gobot@golang.org> Reviewed-by: Emmanuel Odeke <emm.odeke@gmail.com> Reviewed-by: Robert Findley <rfindley@google.com>
2020-03-25 20:50:00 -06:00
return event.StartSpan1(ctx, "A", aValue.Of(a))
},
B: func(ctx context.Context, b string) (context.Context, func()) {
internal/telemetry: add fast non variadic event functions This adds variants of the main event functions that take specific numbers of tags, rather than a tag slice. This reduces the allocation cost when using those functions with no exporter to zero. name old time/op new time/op delta /Baseline-8 158ns ± 7% 154ns ± 1% ~ /StdLog-8 6.90µs ± 1% 6.83µs ± 1% ~ /LogNoExporter-8 1.78µs ± 5% 1.20µs ± 3% -32.37% /TraceNoExporter-8 3.11µs ± 3% 2.48µs ± 2% -20.39% /StatsNoExporter-8 3.18µs ± 5% 1.87µs ± 3% -41.16% /Log-8 46.8µs ± 2% 44.8µs ± 1% -4.33% /Trace-8 55.1µs ± 5% 54.3µs ± 3% ~ /Stats-8 15.8µs ± 3% 13.4µs ± 1% -15.00% name old alloc/op new alloc/op delta /Baseline-8 0.00B 0.00B ~ /StdLog-8 552B ± 0% 552B ± 0% ~ /LogNoExporter-8 1.02kB ± 0% 0.00kB -100.00% /TraceNoExporter-8 1.54kB ± 0% 0.51kB ± 0% -66.67% /StatsNoExporter-8 2.05kB ± 0% 0.00kB -100.00% /Log-8 26.0kB ± 0% 24.0kB ± 0% -7.87% /Trace-8 28.7kB ± 0% 27.1kB ± 0% ~ /Stats-8 13.3kB ± 0% 10.2kB ± 0% -23.08% name old allocs/op new allocs/op delta /Baseline-8 0.00 0.00 ~ /StdLog-8 30.0 ± 0% 30.0 ± 0% ~ /LogNoExporter-8 16.0 ± 0% 0.0 -100.00% /TraceNoExporter-8 32.0 ± 0% 16.0 ± 0% -50.00% /StatsNoExporter-8 32.0 ± 0% 0.0 -100.00% /Log-8 430 ± 0% 382 ± 0% -11.16% /Trace-8 496 ± 0% 464 ± 0% -6.45% /Stats-8 192 ± 0% 128 ± 0% -33.33% Change-Id: I629c0d506ab07de6f12b0acbecfc7407f59a4285 Reviewed-on: https://go-review.googlesource.com/c/tools/+/225580 Run-TryBot: Ian Cottrell <iancottrell@google.com> TryBot-Result: Gobot Gobot <gobot@golang.org> Reviewed-by: Emmanuel Odeke <emm.odeke@gmail.com> Reviewed-by: Robert Findley <rfindley@google.com>
2020-03-25 20:50:00 -06:00
return event.StartSpan1(ctx, "B", bValue.Of(b))
},
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>
2019-12-19 09:57:21 -07:00
}
Stats = Hooks{
A: func(ctx context.Context, a int) (context.Context, func()) {
internal/telemetry: add fast non variadic event functions This adds variants of the main event functions that take specific numbers of tags, rather than a tag slice. This reduces the allocation cost when using those functions with no exporter to zero. name old time/op new time/op delta /Baseline-8 158ns ± 7% 154ns ± 1% ~ /StdLog-8 6.90µs ± 1% 6.83µs ± 1% ~ /LogNoExporter-8 1.78µs ± 5% 1.20µs ± 3% -32.37% /TraceNoExporter-8 3.11µs ± 3% 2.48µs ± 2% -20.39% /StatsNoExporter-8 3.18µs ± 5% 1.87µs ± 3% -41.16% /Log-8 46.8µs ± 2% 44.8µs ± 1% -4.33% /Trace-8 55.1µs ± 5% 54.3µs ± 3% ~ /Stats-8 15.8µs ± 3% 13.4µs ± 1% -15.00% name old alloc/op new alloc/op delta /Baseline-8 0.00B 0.00B ~ /StdLog-8 552B ± 0% 552B ± 0% ~ /LogNoExporter-8 1.02kB ± 0% 0.00kB -100.00% /TraceNoExporter-8 1.54kB ± 0% 0.51kB ± 0% -66.67% /StatsNoExporter-8 2.05kB ± 0% 0.00kB -100.00% /Log-8 26.0kB ± 0% 24.0kB ± 0% -7.87% /Trace-8 28.7kB ± 0% 27.1kB ± 0% ~ /Stats-8 13.3kB ± 0% 10.2kB ± 0% -23.08% name old allocs/op new allocs/op delta /Baseline-8 0.00 0.00 ~ /StdLog-8 30.0 ± 0% 30.0 ± 0% ~ /LogNoExporter-8 16.0 ± 0% 0.0 -100.00% /TraceNoExporter-8 32.0 ± 0% 16.0 ± 0% -50.00% /StatsNoExporter-8 32.0 ± 0% 0.0 -100.00% /Log-8 430 ± 0% 382 ± 0% -11.16% /Trace-8 496 ± 0% 464 ± 0% -6.45% /Stats-8 192 ± 0% 128 ± 0% -33.33% Change-Id: I629c0d506ab07de6f12b0acbecfc7407f59a4285 Reviewed-on: https://go-review.googlesource.com/c/tools/+/225580 Run-TryBot: Ian Cottrell <iancottrell@google.com> TryBot-Result: Gobot Gobot <gobot@golang.org> Reviewed-by: Emmanuel Odeke <emm.odeke@gmail.com> Reviewed-by: Robert Findley <rfindley@google.com>
2020-03-25 20:50:00 -06:00
event.Record1(ctx, aStat.Of(a))
event.Record1(ctx, aCount.Of(1))
return ctx, func() {}
},
B: func(ctx context.Context, b string) (context.Context, func()) {
internal/telemetry: add fast non variadic event functions This adds variants of the main event functions that take specific numbers of tags, rather than a tag slice. This reduces the allocation cost when using those functions with no exporter to zero. name old time/op new time/op delta /Baseline-8 158ns ± 7% 154ns ± 1% ~ /StdLog-8 6.90µs ± 1% 6.83µs ± 1% ~ /LogNoExporter-8 1.78µs ± 5% 1.20µs ± 3% -32.37% /TraceNoExporter-8 3.11µs ± 3% 2.48µs ± 2% -20.39% /StatsNoExporter-8 3.18µs ± 5% 1.87µs ± 3% -41.16% /Log-8 46.8µs ± 2% 44.8µs ± 1% -4.33% /Trace-8 55.1µs ± 5% 54.3µs ± 3% ~ /Stats-8 15.8µs ± 3% 13.4µs ± 1% -15.00% name old alloc/op new alloc/op delta /Baseline-8 0.00B 0.00B ~ /StdLog-8 552B ± 0% 552B ± 0% ~ /LogNoExporter-8 1.02kB ± 0% 0.00kB -100.00% /TraceNoExporter-8 1.54kB ± 0% 0.51kB ± 0% -66.67% /StatsNoExporter-8 2.05kB ± 0% 0.00kB -100.00% /Log-8 26.0kB ± 0% 24.0kB ± 0% -7.87% /Trace-8 28.7kB ± 0% 27.1kB ± 0% ~ /Stats-8 13.3kB ± 0% 10.2kB ± 0% -23.08% name old allocs/op new allocs/op delta /Baseline-8 0.00 0.00 ~ /StdLog-8 30.0 ± 0% 30.0 ± 0% ~ /LogNoExporter-8 16.0 ± 0% 0.0 -100.00% /TraceNoExporter-8 32.0 ± 0% 16.0 ± 0% -50.00% /StatsNoExporter-8 32.0 ± 0% 0.0 -100.00% /Log-8 430 ± 0% 382 ± 0% -11.16% /Trace-8 496 ± 0% 464 ± 0% -6.45% /Stats-8 192 ± 0% 128 ± 0% -33.33% Change-Id: I629c0d506ab07de6f12b0acbecfc7407f59a4285 Reviewed-on: https://go-review.googlesource.com/c/tools/+/225580 Run-TryBot: Ian Cottrell <iancottrell@google.com> TryBot-Result: Gobot Gobot <gobot@golang.org> Reviewed-by: Emmanuel Odeke <emm.odeke@gmail.com> Reviewed-by: Robert Findley <rfindley@google.com>
2020-03-25 20:50:00 -06:00
event.Record1(ctx, bLength.Of(len(b)))
event.Record1(ctx, bCount.Of(1))
return ctx, func() {}
},
}
initialList = []int{0, 1, 22, 333, 4444, 55555, 666666, 7777777}
stringList = []string{
"A value",
"Some other value",
"A nice longer value but not too long",
"V",
"",
"ı",
"prime count of values",
}
)
type namedBenchmark struct {
name string
test func(*testing.B)
}
func Benchmark(b *testing.B) {
b.Run("Baseline", Baseline.runBenchmark)
b.Run("StdLog", StdLog.runBenchmark)
benchmarks := []namedBenchmark{
{"Log", Log.runBenchmark},
{"Trace", Trace.runBenchmark},
{"Stats", Stats.runBenchmark},
}
event.SetExporter(nil)
for _, t := range benchmarks {
b.Run(t.name+"NoExporter", t.test)
}
event.SetExporter(noopExporter)
for _, t := range benchmarks {
b.Run(t.name, t.test)
}
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>
2019-12-19 09:57:21 -07:00
}
func A(ctx context.Context, hooks Hooks, a int) int {
ctx, done := hooks.A(ctx, a)
defer done()
return B(ctx, hooks, a, stringList[a%len(stringList)])
}
func B(ctx context.Context, hooks Hooks, a int, b string) int {
_, done := hooks.B(ctx, b)
defer done()
return a + len(b)
}
func (hooks Hooks) runBenchmark(b *testing.B) {
ctx := context.Background()
b.ReportAllocs()
b.ResetTimer()
var acc int
for i := 0; i < b.N; i++ {
for _, value := range initialList {
acc += A(ctx, hooks, value)
}
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>
2019-12-19 09:57:21 -07:00
}
}
func init() {
log.SetOutput(new(noopWriter))
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>
2019-12-19 09:57:21 -07:00
}
type noopWriter int
func (nw *noopWriter) Write(b []byte) (int, error) {
return len(b), nil
}
var noopExporter = export.Spans(export.LogWriter(new(noopWriter), false))