benchmarks/gc_latency: add new microbenchmark for tricky mutator late…

…ncy issues

When run with -bench, emits latency measurements in benchmark
format.  Includes -trace option for debugging latency issues
(omit -bench for location of worst delay).

go run . -help
Usage of /<yuck>/gc_latency:
  -bench
      output in Go benchmark format
  -fluff
      insert 'fluff' into allocation runs to break up sweeps
  -how string
      how the buffer is allocated = {stack,heap,global} (default "stack")
  -trace string
      name of trace file to create

-OR-

runs as a go benchmark:

go test -bench=B -count=10 . -- -fluff -how=stack
goos: darwin
goarch: amd64
pkg: golang.org/x/benchmarks/gc_latency
cpu: Intel(R) Core(TM) i5-1038NG7 CPU @ 2.00GHz
BenchmarkGCLatency-8           1  3722432744 ns/op         560.0 avg-ns        400.0 median-ns        1461 p29-ns      25774 p39-ns      38630 p49-ns     110696 p59-ns    4753393 p69-ns    5538766 worst-ns
BenchmarkGCLatency-8           1  4067024228 ns/op         622.0 avg-ns        407.0 median-ns        1648 p29-ns      29543 p39-ns      49744 p49-ns     122664 p59-ns    6239471 p69-ns    6593770 worst-ns
BenchmarkGCLatency-8           1  5113548640 ns/op         670.0 avg-ns        410.0 median-ns        2028 p29-ns      28188 p39-ns      66678 p49-ns    1448743 p59-ns    7695377 p69-ns   12281974 worst-ns
BenchmarkGCLatency-8           1  3975527414 ns/op         606.0 avg-ns        406.0 median-ns        1578 p29-ns      28443 p39-ns      43476 p49-ns     113114 p59-ns    6413033 p69-ns    7211445 worst-ns
BenchmarkGCLatency-8           1  4174308310 ns/op         633.0 avg-ns        409.0 median-ns        1720 p29-ns      29063 p39-ns      54298 p49-ns     373535 p59-ns    6489633 p69-ns    8041030 worst-ns
BenchmarkGCLatency-8           1  3980984757 ns/op         609.0 avg-ns        406.0 median-ns        1555 p29-ns      28855 p39-ns      45865 p49-ns     120082 p59-ns    6046351 p69-ns    6346751 worst-ns
BenchmarkGCLatency-8           1  4138732421 ns/op         601.0 avg-ns        410.0 median-ns        1550 p29-ns      27874 p39-ns      40879 p49-ns     155143 p59-ns    5705793 p69-ns    8028793 worst-ns
BenchmarkGCLatency-8           1  5552645990 ns/op         849.0 avg-ns        411.0 median-ns        1962 p29-ns      29602 p39-ns     185457 p49-ns    6228738 p59-ns   19579494 p69-ns   43328862 worst-ns
BenchmarkGCLatency-8           1  4339053770 ns/op         637.0 avg-ns        405.0 median-ns        1674 p29-ns      27410 p39-ns      50768 p49-ns     505246 p59-ns    6891708 p69-ns   88489177 worst-ns
BenchmarkGCLatency-8           1  4715056872 ns/op         719.0 avg-ns        410.0 median-ns        1827 p29-ns      28776 p39-ns      70652 p49-ns    3236747 p59-ns   14152105 p69-ns   20386545 worst-ns
PASS
ok    golang.org/x/benchmarks/gc_latency  52.349s

as a fake main package benchmark:

go run . -bench

goos: darwin
goarch: amd64
BenchmarkAverageLatency 1     574ns
BenchmarkMedianLatency  1     412ns
Benchmark99Latency      1    1791ns
Benchmark999Latency     1   25843ns
Benchmark9999Latency    1   35585ns
Benchmark99999Latency   1  109314ns
BenchmarkWorstLatency   1 6169500ns

Updates golang/go#27732.

Change-Id: I19b9060f24cda1547b8d75f762316dd5271e32c6

gc_latency/latency.go

@@ -0,0 +1,188 @@
+package main
+
+import (
+	"flag"
+	"fmt"
+	"math"
+	"os"
+	"runtime/trace"
+	"sort"
+	"testing"
+	"time"
+	"unsafe"
+)
+
+const (
+	bufferLen = 200000
+	msgCount0 = 1000000 // warmup
+	msgCount1 = 5000000 // run (5 million)
+)
+
+type kbyte []byte
+type circularBuffer [bufferLen]kbyte
+
+var worst time.Duration
+
+// For making sense of the bad outcome.
+var total time.Duration
+var worstIndex int
+var allStart time.Time
+var worstElapsed time.Duration
+
+var fluff kbyte
+var doFluff bool
+
+// newSlice allocates a 1k slice of bytes and initializes them all to byte(n)
+func newSlice(n int) kbyte {
+	m := make(kbyte, 1024)
+	if doFluff && n&63 == 0 {
+		fluff = make(kbyte, 1024)
+	}
+	for i := range m {
+		m[i] = byte(n)
+	}
+	return m
+}
+
+var delays []time.Duration
+
+// storeSlice stores a newly allocated 1k slice of bytes at circularBuffer[count%bufferLen]
+// (bufferLen is the length of the array circularBuffer)
+// It also checks the time needed to do this and records the worst case.
+func storeSlice(c *circularBuffer, highID int) {
+	start := time.Now()
+	c[highID%bufferLen] = newSlice(highID)
+	elapsed := time.Since(start)
+
+	candElapsed := time.Since(allStart) // Record location of worst in trace
+	if elapsed > worst {
+		worst = elapsed
+		worstIndex = highID
+		worstElapsed = candElapsed
+	}
+	total = time.Duration(total.Nanoseconds() + elapsed.Nanoseconds())
+	delays = append(delays, elapsed)
+}
+
+//go:noinline
+func work(c *circularBuffer, count int) {
+	for i := 0; i < count; i++ {
+		storeSlice(c, i)
+	}
+}
+
+//go:noinline
+func stack() {
+	var c circularBuffer
+	work(&c, msgCount1)
+}
+
+var global_c circularBuffer
+
+//go:noinline
+func global() {
+	work(&global_c, msgCount1)
+}
+
+var sink *circularBuffer
+
+//go:noinline
+func heap() {
+	c := &circularBuffer{}
+	sink = c // force to heap
+	work(c, msgCount1)
+}
+
+var traceFile string
+var howAllocated = "stack"
+var asBench bool
+
+func flags() {
+	flag.StringVar(&traceFile, "trace", traceFile, "name of trace file to create")
+	flag.StringVar(&howAllocated, "how", howAllocated, "how the buffer is allocated = {stack,heap,global}")
+	flag.BoolVar(&doFluff, "fluff", doFluff, "insert 'fluff' into allocation runs to break up sweeps")
+	flag.BoolVar(&asBench, "bench", asBench, "output in Go benchmark format")
+	flag.Parse()
+}
+
+func bench(b *testing.B) {
+	var c *circularBuffer = &circularBuffer{}
+	delays = make([]time.Duration, 0, msgCount1)
+	// Warmup
+	work(c, msgCount0)
+	c = nil
+	delays = delays[:0]
+
+	total = time.Duration(0)
+	worstElapsed = time.Duration(0)
+	worst = time.Duration(0)
+	worstIndex = 0
+
+	if traceFile != "" {
+		f, err := os.Create(traceFile)
+		if err != nil {
+			fmt.Fprintf(os.Stderr, "Could not create trace file '%s'\n", traceFile)
+			os.Exit(1)
+		}
+		defer f.Close()
+		trace.Start(f)
+		defer trace.Stop()
+	}
+	if b != nil {
+		b.ResetTimer()
+	}
+	allStart = time.Now()
+	c = nil
+
+	switch howAllocated {
+	case "stack":
+		stack()
+	case "heap":
+		heap()
+	case "global":
+		global()
+	default:
+		fmt.Fprintf(os.Stderr, "-how needs to be one of 'heap', 'stack' or 'global, saw '%s' instead\n", howAllocated)
+		os.Exit(1)
+	}
+
+	sort.Slice(delays, func(i, j int) bool { return delays[i] < delays[j] })
+
+	average, median := time.Duration(total.Nanoseconds()/msgCount1), delays[len(delays)/2]
+	p29, p39, p49, p59, p69 := delays[int(0.99*float64(len(delays)))], delays[int(0.999*float64(len(delays)))], delays[int(0.9999*float64(len(delays)))], delays[int(0.99999*float64(len(delays)))], delays[int(0.999999*float64(len(delays)))]
+
+	if asBench {
+		width := int(math.Ceil(math.Log10(float64(1 + worst))))
+		if b != nil {
+			b.ReportMetric(float64(average.Nanoseconds()), "avg-ns")
+			b.ReportMetric(float64(median), "median-ns")
+			b.ReportMetric(float64(p29), "p29-ns")
+			b.ReportMetric(float64(p39), "p39-ns")
+			b.ReportMetric(float64(p49), "p49-ns")
+			b.ReportMetric(float64(p59), "p59-ns")
+			b.ReportMetric(float64(p69), "p69-ns")
+			b.ReportMetric(float64(worst), "worst-ns")
+		} else {
+			fmt.Printf("BenchmarkAverageLatency 1 %[1]*dns\n", width, average)
+			fmt.Printf("BenchmarkMedianLatency  1 %[1]*dns\n", width, median)
+			fmt.Printf("Benchmark99Latency      1 %[1]*dns\n", width, p29)
+			fmt.Printf("Benchmark999Latency     1 %[1]*dns\n", width, p39)
+			fmt.Printf("Benchmark9999Latency    1 %[1]*dns\n", width, p49)
+			fmt.Printf("Benchmark99999Latency   1 %[1]*dns\n", width, p59)
+			fmt.Printf("Benchmark999999Latency  1 %[1]*dns\n", width, p69)
+			fmt.Printf("BenchmarkWorstLatency   1 %[1]*dns\n", width, worst)
+		}
+	} else {
+		fmt.Println("Worst allocation latency:", worst)
+		fmt.Println("Worst allocation index:", worstIndex)
+		fmt.Println("Worst allocation occurs at run elapsed time:", worstElapsed)
+		fmt.Println("Average allocation latency:", average)
+		fmt.Println("Median allocation latency:", median)
+		fmt.Println("99% allocation latency:", p29)
+		fmt.Println("99.9% allocation latency:", p39)
+		fmt.Println("99.99% allocation latency:", p49)
+		fmt.Println("99.999% allocation latency:", p59)
+		fmt.Println("Sizeof(circularBuffer) =", unsafe.Sizeof(*c))
+		fmt.Println("Approximate live memory =", unsafe.Sizeof(*c)+bufferLen*1024)
+	}
+}

gc_latency/latency_test.go

@@ -0,0 +1,10 @@
+package main
+
+import (
+	"testing"
+)
+
+func BenchmarkGCLatency(b *testing.B) {
+	asBench = true
+	bench(b)
+}

gc_latency/main.go

@@ -0,0 +1,6 @@
+package main
+
+func main() {
+	flags()
+	bench(nil)
+}