runtime: block and mutex profile aren't meaningful with faketime

[rhysh]

The faketime mechanism used for The Go Playground doesn't cover the timers used in the block and mutex profiles. That makes the playground unhelpful for demonstrating behaviors of those profiles.

It does seem to work with the execution tracer!

It's easiest to see the problem with the block profile, run with "Go 1.24": https://go.dev/play/p/gczXjd0_kT1

I'd expect delays attributable to lines 14, 15, and 16. I'd expect line 15 to have 2x the delay of line 14, and for line 16 to have 3x delay. I'd expect the delays, when divided by the "cycles/second" figure, to correspond with 100, 200, and 300ms.

Instead, line 16 has the shortest reported delay of the three and is reported as 193328/197107886 = 980 µs.

package main

import (
	"log"
	"os"
	"runtime"
	"runtime/pprof"
	"time"
)

func main() {
	runtime.SetBlockProfileRate(1)

	<-time.After(100 * time.Millisecond)
	<-time.After(200 * time.Millisecond)
	<-time.After(300 * time.Millisecond)

	if err := pprof.Lookup("block").WriteTo(os.Stdout, 1); err != nil {
		log.Fatal(err)
	}
}

--- contention:
cycles/second=197107886
14356016 1 @ 0x40beb2 0x4d1bb0 0x43cc3d 0x472781
#	0x40beb1	runtime.chanrecv1+0x11	/usr/local/go-faketime/src/runtime/chan.go:506
#	0x4d1baf	main.main+0x2f		/tmp/sandbox2369965660/prog.go:14
#	0x43cc3c	runtime.main+0x27c	/usr/local/go-faketime/src/runtime/proc.go:283

572950 1 @ 0x40beb2 0x4d1bc5 0x43cc3d 0x472781
#	0x40beb1	runtime.chanrecv1+0x11	/usr/local/go-faketime/src/runtime/chan.go:506
#	0x4d1bc4	main.main+0x44		/tmp/sandbox2369965660/prog.go:15
#	0x43cc3c	runtime.main+0x27c	/usr/local/go-faketime/src/runtime/proc.go:283

193328 1 @ 0x40beb2 0x4d1bd9 0x43cc3d 0x472781
#	0x40beb1	runtime.chanrecv1+0x11	/usr/local/go-faketime/src/runtime/chan.go:506
#	0x4d1bd8	main.main+0x58		/tmp/sandbox2369965660/prog.go:16
#	0x43cc3c	runtime.main+0x27c	/usr/local/go-faketime/src/runtime/proc.go:283

Here's the execution tracer working: https://go.dev/play/p/ZOMrkPAUbWM

Which after base64-decoding and viewing with "go tool trace" shows a task log of:

When	Elapsed	Goroutine	Events
0.000001215s	49.99904ms		Task 1 (goroutine view) (complete)
0.000001215	 .     1215	1	task "task" (D 1, parent 18446744073709551615) begin
0.010000255	 .  9999040	1	log "10ms"
0.020000191	 .  9999936	1	log "20ms"
0.030000191	 . 10000000	1	log "30ms"
0.040000191	 . 10000000	1	log "40ms"
0.050000191	 . 10000000	1	log "50ms"
0.050000255	 .       64	1	task end

[gabyhelp]

Related Issues

• runtime/pprof: under-samples work on short-lived threads #40435 (closed)
• runtime/pprof: block/mutex profile stacks can sometimes miss leaf frames #69747
• pprof block profile does not report on blocking pipe? bug? #54138 (closed)
• runtime/pprof: blockprofile test fails in VMs #7696 (closed)
• sync: mutex profiling information is confusing (wrong?) for mutexes with >2 contenders #24877
• runtime/pprof: block and mutex profile stacks sometimes have "gowrap" root frames #69294
• runtime/pprof: collecting a CPU profile takes ~200ms of wall time #63043
• runtime/pprof: TestBlockProfile fails on windows #6975 (closed)
• runtime/pprof: collecting mutex or block profiles add ~100ms of wall time #63078 (closed)

Related Code Changes

• runtime/pprof: increase contention upper bound in TestMutexProfile

_{(Emoji vote if this was helpful or unhelpful; more detailed feedback welcome in this discussion.)}

[mknyszek]

In triage, we agree it would be nice if these worked correctly under faketime. Not a super high priority for us, but patches welcome. :) (Hopefully this isn't that complicated to do...)

[mknyszek]

OK actually, it sounds like this might be as simple as stubbing cputicks under faketime as well? (Or just making an exception for time tracking under faketime for these profiles.)

[rhysh]

this might be as simple as stubbing cputicks under faketime as well?

That's how I read it, yes. There's no indirection for cputicks currently; code that uses it calls cputicks, and the cputicks functions are defined in assembly. The approach with the lowest runtime overhead is probably to factor out all of those assembly implementations into files that only build without the faketime tag, and then write a faketime implementation of cputicks that's backed by nanotime.

Unless a trivial wrapper (cputicks/cputicks1) would allow inlining into its callers, without propagating too much of a change to the callers' inlining budgets?

If you can say which approach you'd prefer, and if the code would be mergable right away (the freeze has just started), then I can send a patch. Otherwise, it can wait. Thanks for the triage!