Block profiler overhead example

bench_test.go

package main

import (
	"html/template"
	"os"
	"runtime"
	"strconv"
	"sync"
	"testing"
	"time"
)

func init() {
        rate := os.Getenv("BLOCK_RATE")
	if len(rate) > 0 {
		n, err := strconv.Atoi(rate)
		if err != nil {
			panic(err)
		}
		runtime.SetBlockProfileRate(n)
	}
}

var sinktmpl *template.Template

// Inspired by a real example where the block profiler introduced extremely
// high overhead. Go template parsing actually involves a lot of channel use
// under the hood, which means the block profiler can have a very severe impact.
func BenchmarkTemplate(b *testing.B) {
	for i := 0; i < b.N; i++ {
		tmpl, err := template.New("test").Parse("{{.Count}} items are made of {{.Material}}")
		if err != nil {
			b.Fatal(err)
		}
		sinktmpl = tmpl
	}
}

example.md

Generate the baseline for comparison:

$ env go test -bench=Template -count=10 > no-block-profiler.txt

Block rate of 1000 (or 1 microsecond) shows a 140% increase in latency:

$ env BLOCK_RATE=1000 go test -bench=Template -count=10 > block-profiler-rate-1000.txt  
$ ~/go/bin/benchstat no-block-profiler.txt block-profiler-rate-1000.txt               
name        old time/op  new time/op   delta
Template-8  6.76µs ± 3%  16.56µs ± 1%  +144.94%  (p=0.000 n=10+10)

Block rate of 10000 (10 microseconds) shows 10% increase:

$ env BLOCK_RATE=10000 go test -bench=Template -count=10 > block-profiler-rate-10000.txt
$ ~/go/bin/benchstat no-block-profiler.txt block-profiler-rate-10000.txt 
name        old time/op  new time/op  delta
Template-8  6.76µs ± 3%  7.52µs ± 2%  +11.27%  (p=0.000 n=10+9)

Block rate of 10000000 (1 millisecond) shows 5% increase:

$ env BLOCK_RATE=1000000 go test -bench=Template -count=10 > block-profiler-rate-1000000.txt
$ ~/go/bin/benchstat no-block-profiler.txt block-profiler-rate-1000000.txt                  
name        old time/op  new time/op  delta
Template-8  6.76µs ± 3%  7.15µs ± 4%  +5.84%  (p=0.000 n=10+9)