runtime/pprof: TestMutexBlockFullAggregation failures

[gopherbot]

#!watchflakes
default <- pkg == "runtime/pprof" && test == "TestMutexBlockFullAggregation"

Issue created automatically to collect these failures.

Example (log):

=== RUN   TestMutexBlockFullAggregation
    pprof_test.go:2713: saw duplicate entry in mutex profile with stack:
        runtime.unlock /opt/golang/swarm/.swarming/w/ir/x/w/goroot/src/runtime/lock_spinbit.go:261
        runtime.stkbucket /opt/golang/swarm/.swarming/w/ir/x/w/goroot/src/runtime/mprof.go:348
        runtime.mProf_Malloc /opt/golang/swarm/.swarming/w/ir/x/w/goroot/src/runtime/mprof.go:450
        runtime.profilealloc /opt/golang/swarm/.swarming/w/ir/x/w/goroot/src/runtime/malloc.go:1806
        runtime.mallocgcSmallScanNoHeader /opt/golang/swarm/.swarming/w/ir/x/w/goroot/src/runtime/malloc.go:1422
        runtime.mallocgc /opt/golang/swarm/.swarming/w/ir/x/w/goroot/src/runtime/malloc.go:1061
        runtime.convTstring /opt/golang/swarm/.swarming/w/ir/x/w/goroot/src/runtime/iface.go:423
        runtime/pprof.awaitBlockedGoroutine /opt/golang/swarm/.swarming/w/ir/x/w/goroot/src/runtime/pprof/pprof_test.go:1016
        runtime/pprof.blockChanDeep.func1 /opt/golang/swarm/.swarming/w/ir/x/w/goroot/src/runtime/pprof/pprof_test.go:2586
        runtime.goexit /opt/golang/swarm/.swarming/w/ir/x/w/goroot/src/runtime/asm_amd64.s:1693
--- FAIL: TestMutexBlockFullAggregation (0.25s)

— watchflakes

[gopherbot]

Found new dashboard test flakes for:

#!watchflakes
default <- pkg == "runtime/pprof" && test == "TestMutexBlockFullAggregation"

2025-05-08 18:09 gotip-solaris-amd64 go@b877f04e runtime/pprof.TestMutexBlockFullAggregation (log)

=== RUN   TestMutexBlockFullAggregation
    pprof_test.go:2713: saw duplicate entry in mutex profile with stack:
        runtime.unlock /opt/golang/swarm/.swarming/w/ir/x/w/goroot/src/runtime/lock_spinbit.go:261
        runtime.stkbucket /opt/golang/swarm/.swarming/w/ir/x/w/goroot/src/runtime/mprof.go:348
        runtime.mProf_Malloc /opt/golang/swarm/.swarming/w/ir/x/w/goroot/src/runtime/mprof.go:450
        runtime.profilealloc /opt/golang/swarm/.swarming/w/ir/x/w/goroot/src/runtime/malloc.go:1806
        runtime.mallocgcSmallScanNoHeader /opt/golang/swarm/.swarming/w/ir/x/w/goroot/src/runtime/malloc.go:1422
        runtime.mallocgc /opt/golang/swarm/.swarming/w/ir/x/w/goroot/src/runtime/malloc.go:1061
        runtime.convTstring /opt/golang/swarm/.swarming/w/ir/x/w/goroot/src/runtime/iface.go:423
        runtime/pprof.awaitBlockedGoroutine /opt/golang/swarm/.swarming/w/ir/x/w/goroot/src/runtime/pprof/pprof_test.go:1016
        runtime/pprof.blockChanDeep.func1 /opt/golang/swarm/.swarming/w/ir/x/w/goroot/src/runtime/pprof/pprof_test.go:2586
        runtime.goexit /opt/golang/swarm/.swarming/w/ir/x/w/goroot/src/runtime/asm_amd64.s:1693
--- FAIL: TestMutexBlockFullAggregation (0.25s)

— watchflakes

[gopherbot]

Found new dashboard test flakes for:

#!watchflakes
default <- pkg == "runtime/pprof" && test == "TestMutexBlockFullAggregation"

2025-05-08 20:39 gotip-solaris-amd64 go@cad1fc52 runtime/pprof.TestMutexBlockFullAggregation (log)

=== RUN   TestMutexBlockFullAggregation
    pprof_test.go:2713: saw duplicate entry in mutex profile with stack:
        runtime.unlock /opt/golang/swarm/.swarming/w/ir/x/w/goroot/src/runtime/lock_spinbit.go:261
        runtime.stkbucket /opt/golang/swarm/.swarming/w/ir/x/w/goroot/src/runtime/mprof.go:348
        runtime.mProf_Malloc /opt/golang/swarm/.swarming/w/ir/x/w/goroot/src/runtime/mprof.go:450
        runtime.profilealloc /opt/golang/swarm/.swarming/w/ir/x/w/goroot/src/runtime/malloc.go:1806
        runtime.mallocgcSmallScanNoHeader /opt/golang/swarm/.swarming/w/ir/x/w/goroot/src/runtime/malloc.go:1422
        runtime.mallocgc /opt/golang/swarm/.swarming/w/ir/x/w/goroot/src/runtime/malloc.go:1061
        runtime.convTstring /opt/golang/swarm/.swarming/w/ir/x/w/goroot/src/runtime/iface.go:423
        runtime/pprof.awaitBlockedGoroutine /opt/golang/swarm/.swarming/w/ir/x/w/goroot/src/runtime/pprof/pprof_test.go:1016
        runtime/pprof.blockChanDeep.func1 /opt/golang/swarm/.swarming/w/ir/x/w/goroot/src/runtime/pprof/pprof_test.go:2586
        runtime.goexit /opt/golang/swarm/.swarming/w/ir/x/w/goroot/src/runtime/asm_amd64.s:1693
--- FAIL: TestMutexBlockFullAggregation (0.25s)

2025-05-08 22:17 gotip-solaris-amd64 go@f4e37b8a runtime/pprof.TestMutexBlockFullAggregation (log)

=== RUN   TestMutexBlockFullAggregation
    pprof_test.go:2713: saw duplicate entry in mutex profile with stack:
        runtime.unlock /opt/golang/swarm/.swarming/w/ir/x/w/goroot/src/runtime/lock_spinbit.go:261
        runtime.stkbucket /opt/golang/swarm/.swarming/w/ir/x/w/goroot/src/runtime/mprof.go:348
        runtime.mProf_Malloc /opt/golang/swarm/.swarming/w/ir/x/w/goroot/src/runtime/mprof.go:450
        runtime.profilealloc /opt/golang/swarm/.swarming/w/ir/x/w/goroot/src/runtime/malloc.go:1806
        runtime.mallocgcSmallScanNoHeader /opt/golang/swarm/.swarming/w/ir/x/w/goroot/src/runtime/malloc.go:1422
        runtime.mallocgc /opt/golang/swarm/.swarming/w/ir/x/w/goroot/src/runtime/malloc.go:1061
        runtime.convTstring /opt/golang/swarm/.swarming/w/ir/x/w/goroot/src/runtime/iface.go:423
        runtime/pprof.awaitBlockedGoroutine /opt/golang/swarm/.swarming/w/ir/x/w/goroot/src/runtime/pprof/pprof_test.go:1016
        runtime/pprof.TestProfilerStackDepth /opt/golang/swarm/.swarming/w/ir/x/w/goroot/src/runtime/pprof/pprof_test.go:2502
        testing.tRunner /opt/golang/swarm/.swarming/w/ir/x/w/goroot/src/testing/testing.go:1801
        runtime.goexit /opt/golang/swarm/.swarming/w/ir/x/w/goroot/src/runtime/asm_amd64.s:1693
--- FAIL: TestMutexBlockFullAggregation (0.24s)

— watchflakes

[gopherbot]

Found new dashboard test flakes for:

#!watchflakes
default <- pkg == "runtime/pprof" && test == "TestMutexBlockFullAggregation"

2025-05-09 00:40 gotip-solaris-amd64 go@d65c209b runtime/pprof.TestMutexBlockFullAggregation (log)

=== RUN   TestMutexBlockFullAggregation
    pprof_test.go:2713: saw duplicate entry in mutex profile with stack:
        runtime.unlock /opt/golang/swarm/.swarming/w/ir/x/w/goroot/src/runtime/lock_spinbit.go:261
        runtime.stkbucket /opt/golang/swarm/.swarming/w/ir/x/w/goroot/src/runtime/mprof.go:348
        runtime.mProf_Malloc /opt/golang/swarm/.swarming/w/ir/x/w/goroot/src/runtime/mprof.go:450
        runtime.profilealloc /opt/golang/swarm/.swarming/w/ir/x/w/goroot/src/runtime/malloc.go:1806
        runtime.mallocgcSmallScanNoHeader /opt/golang/swarm/.swarming/w/ir/x/w/goroot/src/runtime/malloc.go:1422
        runtime.mallocgc /opt/golang/swarm/.swarming/w/ir/x/w/goroot/src/runtime/malloc.go:1061
        runtime.convTstring /opt/golang/swarm/.swarming/w/ir/x/w/goroot/src/runtime/iface.go:423
        runtime/pprof.awaitBlockedGoroutine /opt/golang/swarm/.swarming/w/ir/x/w/goroot/src/runtime/pprof/pprof_test.go:1016
        runtime/pprof.blockChanDeep.func1 /opt/golang/swarm/.swarming/w/ir/x/w/goroot/src/runtime/pprof/pprof_test.go:2586
        runtime.goexit /opt/golang/swarm/.swarming/w/ir/x/w/goroot/src/runtime/asm_amd64.s:1693
--- FAIL: TestMutexBlockFullAggregation (0.23s)

— watchflakes

[mknyszek]

Possibly related to frame pointer tracebacks? Curiously, it only happens on Solaris. CC @nsrip-dd maybe.

[mknyszek]

The test looks at the text output, but it's totally possible for two stacks of PCs to produce the same text output. If there are two convTstring calls on the same line in the example above.

This might just be a test-level issue.

[mknyszek]

In triage, it does look like there are actually two conversions on the same line. Both of which may be an allocation that follows this path. This is probably a test-only problem.

[nsrip-dd]

@mknyszek I'm happy to send a quick fix if you're not already working on it