Benchmarking with details

I’ve been optimizing Go code for a while and trying to improve my benchmarking game.

Let’s take a look at a simple example:

func BenchmarkReport(b *testing.B) {
runtime.GC()
for i := 0; i < b.N; i++ {
r := fmt.Sprintf("hello, world %d", 123)
runtime.KeepAlive(r)
}
}

Running go test -bench . will give us the result:

BenchmarkReport-32      20000000               107 ns/op

This might be enough for getting a rough estimate where you stand in terms of performance, but a more detailed output is required for optimization. Condensing everything into a single number is bound to be simplistic.

github.com/loov/hrtime

Let me introduce you to the hrtime package which I wrote to get a more extensive output from benchmarks.

Histogram

The first approach to using it, is to use hrtime.NewBenchmark. Rewriting the initial example as a regular program.

func main() {
bench := hrtime.NewBenchmark(20000000)
for bench.Next() {
r := fmt.Sprintf("hello, world %d", 123)
runtime.KeepAlive(r)
}
fmt.Println(bench.Histogram(10))
}

Which will print:

  avg 372ns;  min 300ns;  p50 400ns;  max 295µs;
p90 400ns; p99 500ns; p999 1.8µs; p9999 4.3µs;
300ns [ 7332554] ███████████████████████
400ns [12535735] ████████████████████████████████████████
600ns [ 18955]
800ns [ 2322]
1µs [ 20413]
1.2µs [ 34854]
1.4µs [ 25096]
1.6µs [ 10009]
1.8µs [ 4688]
2µs+[ 15374]

As we can see that P99 is 500ns, which means that 1% of all our measurements are above 500ns. We can try to optimizing this by allocating less strings:

func main() {
bench := hrtime.NewBenchmark(20000000)
var back [1024]byte
for bench.Next() {
buffer := back[:0]
buffer = append(buffer, []byte("hello, world ")...)
buffer = strconv.AppendInt(buffer, 123, 10)
runtime.KeepAlive(buffer)
}
fmt.Println(bench.Histogram(10))
}

And the result:

  avg 267ns;  min 200ns;  p50 300ns;  max 216µs;
p90 300ns; p99 300ns; p999 1.1µs; p9999 3.6µs;
200ns [ 7211285] ██████████████████████▌
300ns [12658260] ████████████████████████████████████████
400ns [ 81076]
500ns [ 3226]
600ns [ 343]
700ns [ 136]
800ns [ 729]
900ns [ 8108]
1µs [ 15436]
1.1µs+[ 21401]

We can now see that the 99% has gone from 500ns to 300ns.

If you have a keen eye, you may have noticed that Go benchmark gave an average 107ns/op however hrtime gave us 372ns/op. This is the unfortunate side-effect in trying to measure more — it always has an overhead. The final results include this overhead.

Note: depending on the operating-system the overhead can be significantly less and hrtime does support repeated calls inside with https://godoc.org/github.com/loov/hrtime#Histogram.Divide.

Stopwatch

Sometimes you also want to measure concurrent operations. For this there is Stopwatch . https://godoc.org/github.com/loov/hrtime#Stopwatch

Lets say you want to measure how long does a send take on a highly contended channel. This of course is a contrived example, but roughly shows the idea how we can start the measurement from one goroutine, stop it in another and finally print it all out.

func main() {
const numberOfExperiments = 1000
bench := hrtime.NewStopwatch(numberOfExperiments)
    ch := make(chan int32, 10)
wait := make(chan struct{})
    // start senders
for i := 0; i < numberOfExperiments; i++ {
go func() {
<-wait
ch <- bench.Start()
}()
}
    // start one receiver
go func() {
for lap := range ch {
bench.Stop(lap)
}
}()
    // wait for all goroutines to be created
time.Sleep(time.Second)
// release all goroutines at the same time
close(wait)
    // wait for all measurements to be completed
bench.Wait()
fmt.Println(bench.Histogram(10))
}

hrtesting

Of course writing a separate binary for all of the tests isn’t that convenient. For that there’s github.com/loov/hrtime/hrtesting, which provides wrappers for testing.B.

func BenchmarkReport(b *testing.B) {
bench := hrtesting.NewBenchmark(b)
defer bench.Report()
    for bench.Next() {
r := fmt.Sprintf("hello, world %d", 123)
runtime.KeepAlive(r)
}
}

It will print out 50%, 90% and 99% percentiles.

BenchmarkReport-32               3000000               427 ns/op
--- BENCH: BenchmarkReport-32
benchmark_old.go:11: 24.5µs₅₀ 24.5µs₉₀ 24.5µs₉₉ N=1
benchmark_old.go:11: 400ns₅₀ 500ns₉₀ 12.8µs₉₉ N=100
benchmark_old.go:11: 400ns₅₀ 500ns₉₀ 500ns₉₉ N=10000
benchmark_old.go:11: 400ns₅₀ 500ns₉₀ 600ns₉₉ N=1000000
benchmark_old.go:11: 400ns₅₀ 500ns₉₀ 500ns₉₉ N=3000000

Unfortunately with Go 1.12 it will print all of the runs of Benchmark instead of just the last. However with Go 1.13 the output will be much nicer:

BenchmarkReport-32   3174566  379 ns/op  400 ns/p50  400 ns/p90 ...

And comparing results with benchstat will work as well.

hrplot

Leaving the best for last github.com/loov/hrtime/hrplot. Using my experimental plotting package, I decided to add a convenient way to plot the benchmark results.

func BenchmarkReport(b *testing.B) {
bench := hrtesting.NewBenchmark(b)
defer bench.Report()
defer hrplot.All("all.svg", bench)

runtime.GC()
for bench.Next() {
r := fmt.Sprintf("hello, world %d", 123)
runtime.KeepAlive(r)
}
}

Will create an SVG file called all.svg. It contains a line plot, which shows how much time each iteration took. Second is density plot, which shows the distribution of timing measurements. And finally a percentiles plot.

Conclusion

Performance optimization is fun, but having tools to help you out makes it even more enjoyable.

Go try out github.com/loov/hrtime and let me know what you think.