runtime/sema: incorrect mutex contention time

[func25]

Go version

go1.23.9

Output of go env in your module/workspace:

none

What did you do?

I tried a simple snippet to evaluate the mutex profile:

var mtx sync.Mutex
var wg sync.WaitGroup

func acquire(n time.Duration) {
	mtx.Lock()
	defer mtx.Unlock()

	time.Sleep(n)
	wg.Done()
}

func main() {
	runtime.SetMutexProfileFraction(1)

	wg.Add(5)
	go acquire(1 * time.Second) // gowrap1
	go acquire(2 * time.Second) // gowrap2
	go acquire(3 * time.Second) // gowrap3
	go acquire(4 * time.Second) // gowrap4
	go acquire(5 * time.Second) // gowrap5

	wg.Wait()

	// Write mutex profile to file
	f, err := os.Create("mutex.prof")
	if err != nil {
		log.Fatal(err)
	}
	defer f.Close()

	if err := pprof.Lookup("mutex").WriteTo(f, 0); err != nil {
		log.Fatal(err)
	}
}

What did you see happen?

The order in which goroutines acquire the lock is: gowrap1 → gowrap5 → gowrap2 → gowrap3 → gowrap4. However, the result shows an overshoot in gowrap3's contention time and underestimates gowrap2:

What did you expect to see?

The expected contention time for gowrap2 should be 4 seconds. The contention time for gowrap3 should be 3 seconds. Not sure if this behavior is intentional.

[gabyhelp]

Related Issues

• runtime: contended mutex profiling doesn't work for sync.RWMutex #18496 (closed)
• sync: mutex profiling information is confusing (wrong?) for mutexes with >2 contenders #24877
• runtime: correct attribution of internal mutex contention #66999 (closed)
• runtime: MutexProfile missing root frames in go1.23 #69335 (closed)
• RWMutex.Unlock() appearing in mutex contention profiles #19102 (closed)
• runtime/pprof: block and mutex profile stacks sometimes have "gowrap" root frames #69294

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.)}