go-profiler-notes/examples/block-sample/main.go

package main

import (
	"context"
	"fmt"
	"os"
	"runtime"
	"runtime/pprof"
	"time"

	"golang.org/x/sync/errgroup"
)

func main() {
	if err := run(); err != nil {
		fmt.Fprintln(os.Stderr, err)
		os.Exit(1)
	}
}

func run() error {
	labels := pprof.Labels("test_label", "test_value")
	ctx := pprof.WithLabels(context.Background(), labels)
	pprof.SetGoroutineLabels(ctx)

	runtime.SetBlockProfileRate(int((40 * time.Microsecond).Nanoseconds()))
	done := make(chan struct{})
	g := errgroup.Group{}
	g.Go(func() error {
		return eventA(done)
	})
	g.Go(func() error {
		return eventB(done)
	})
	time.Sleep(time.Second)
	close(done)
	if err := g.Wait(); err != nil {
		return err
	}

	f, err := os.Create("block.pb.gz")
	if err != nil {
		return err
	}
	defer f.Close()
	if err := pprof.Lookup("block").WriteTo(f, 0); err != nil {
		return err
	}
	return nil
}

func eventA(done chan struct{}) error {
	return simulateBlockEvents(20*time.Microsecond, done)
}

func eventB(done chan struct{}) error {
	return simulateBlockEvents(40*time.Microsecond, done)
}

const tolerance = 1.1

func simulateBlockEvents(meanDuration time.Duration, done chan struct{}) error {
	var (
		prev   time.Time
		sum    time.Duration
		count  int
		ticker = time.NewTicker(meanDuration)
	)
	defer ticker.Stop()
	for {
		select {
		case <-ticker.C:
			now := time.Now()
			if !prev.IsZero() {
				sum += now.Sub(prev)
				count += 1
				if count > 1000 {
					actualMean := float64(sum) / float64(count)
					max := tolerance * float64(meanDuration)
					min := float64(meanDuration) / tolerance
					if actualMean <= min || actualMean >= max {
						return fmt.Errorf("low clock accuracy: got=%s want=%s", time.Duration(actualMean), meanDuration)
					}
				}
			}
			prev = now
		case <-done:
			return nil
		}
	}
}

/*

Bias in current go version:

	$ go version
	go version go1.15.6 darwin/amd64
	$ go run . && go tool pprof -raw block.pb.gz
	PeriodType: contentions count
	Period: 1
	Time: 2021-02-05 15:27:01.371414 +0100 CET
	Samples:
	contentions/count delay/nanoseconds
				23271  892063188: 1 2 3 4
				22612  438270491: 1 2 5 4
	Locations
			 1: 0x10453af M=1 runtime.selectgo /usr/local/Cellar/go/1.15.6/libexec/src/runtime/select.go:511 s=0
			 2: 0x10cf56b M=1 main.simulateBlockEvents /Users/felix.geisendoerfer/go/src/github.com/felixge/go-profiler-notes/examples/block-sample/main.go:66 s=0
			 3: 0x10cf8b2 M=1 main.eventB /Users/felix.geisendoerfer/go/src/github.com/felixge/go-profiler-notes/examples/block-sample/main.go:52 s=0
							 main.run.func2 /Users/felix.geisendoerfer/go/src/github.com/felixge/go-profiler-notes/examples/block-sample/main.go:28 s=0
			 4: 0x10cefd8 M=1 golang.org/x/sync/errgroup.(*Group).Go.func1 /Users/felix.geisendoerfer/go/pkg/mod/golang.org/x/sync@v0.0.0-20201207232520-09787c993a3a/errgroup/errgroup.go:57 s=0
			 5: 0x10cf852 M=1 main.eventA /Users/felix.geisendoerfer/go/src/github.com/felixge/go-profiler-notes/examples/block-sample/main.go:48 s=0
							 main.run.func1 /Users/felix.geisendoerfer/go/src/github.com/felixge/go-profiler-notes/examples/block-sample/main.go:25 s=0
	Mappings
	1: 0x0/0x0/0x0   [FN]

After removing bias with this patch:
https://github.com/felixge/go/commit/7c3f70c378d3f9a331a2079d17cd4cc420c70190

	$ sgo version
	go version devel +7c3f70c378 2021-02-05 15:19:48 +0100 darwin/amd64
	$ sgo run . && go tool pprof -raw block.pb.gz
	PeriodType: contentions count
	Period: 1
	Time: 2021-02-05 15:18:56.401244 +0100 CET
	Samples:
	contentions/count delay/nanoseconds
				22833  931500628: 1 2 3 4
				22453  902100036: 1 2 5 4
						1      39999: 6 7 8 9 10
	Locations
			 1: 0x10471d9 M=1 runtime.selectgo /Users/felix.geisendoerfer/go/src/github.com/golang/go/src/runtime/select.go:492 s=0
			 2: 0x10d023e M=1 main.simulateBlockEvents /Users/felix.geisendoerfer/go/src/github.com/felixge/go-profiler-notes/examples/block-sample/main.go:66 s=0
			 3: 0x10d0592 M=1 main.eventB /Users/felix.geisendoerfer/go/src/github.com/felixge/go-profiler-notes/examples/block-sample/main.go:52 s=0
							 main.run.func2 /Users/felix.geisendoerfer/go/src/github.com/felixge/go-profiler-notes/examples/block-sample/main.go:28 s=0
			 4: 0x10cfcd8 M=1 golang.org/x/sync/errgroup.(*Group).Go.func1 /Users/felix.geisendoerfer/go/pkg/mod/golang.org/x/sync@v0.0.0-20201207232520-09787c993a3a/errgroup/errgroup.go:57 s=0
			 5: 0x10d0532 M=1 main.eventA /Users/felix.geisendoerfer/go/src/github.com/felixge/go-profiler-notes/examples/block-sample/main.go:48 s=0
							 main.run.func1 /Users/felix.geisendoerfer/go/src/github.com/felixge/go-profiler-notes/examples/block-sample/main.go:25 s=0
			 6: 0x107b024 M=1 sync.(*WaitGroup).Wait /Users/felix.geisendoerfer/go/src/github.com/golang/go/src/sync
	/waitgroup.go:130 s=0
			 7: 0x10cfb30 M=1 golang.org/x/sync/errgroup.(*Group).Wait /Users/felix.geisendoerfer/go/pkg/mod/golang.org/x/sync@v0.0.0-20201207232520-09787c993a3a/errgroup/errgroup.go:40 s=0
			 8: 0x10cff7a M=1 main.run /Users/felix.geisendoerfer/go/src/github.com/felixge/go-profiler-notes/examples/block-sample/main.go:32 s=0
			 9: 0x10cfda5 M=1 main.main /Users/felix.geisendoerfer/go/src/github.com/felixge/go-profiler-notes/examples/block-sample/main.go:14 s=0
			10: 0x10371b5 M=1 runtime.main /Users/felix.geisendoerfer/go/src/github.com/golang/go/src/runtime/proc.go:225 s=0
	Mappings
	1: 0x0/0x0/0x0   [FN]

*/