runtime/pprof: TestLabelSystemstack failures with labeled "runtime/pprof.parallelLabelHog.func1"

[bcmills]

--- FAIL: TestLabelSystemstack (0.22s)
    pprof_test.go:524: total 30 CPU profile samples collected:
        1: 0x8178ffc (runtime/pprof.parallelLabelHog.func1:1533) labels: map[key:[value]]
        
        1: 0x8071ac9 (runtime/internal/sys.Len64:49 runtime/internal/sys.LeadingZeros64:130 runtime.(*pallocBits).summarize:147) 0x806e74e (runtime.(*pageAlloc).update:446) 0x806feda (runtime.(*pageAlloc).free:917) 0x806d2a5 (runtime.(*mheap).freeSpanLocked:1511) 0x806cfc0 (runtime.(*mheap).freeSpan.func1:1440) 0x80a83b4 (runtime.systemstack:370) 0x806cf6c (runtime.(*mheap).freeSpan:1426) 0x8069edd (runtime.(*sweepLocked).sweep:680) 0x806976d (runtime.sweepone:369) 0x805d56e (runtime.GC:451) 0x8178e53 (runtime/pprof.labelHog:1514) 0x817900c (runtime/pprof.parallelLabelHog.func1:1534) labels: map[key:[value]]
        
        1: 0x80980ca (runtime.libcCall:48) 0x8098680 (runtime.nanotime1:177) 0x808413b (runtime.nanotime:19 runtime.checkTimers:3456) 0x8083d38 (runtime.schedule:3337) 0x80845e9 (runtime.goschedImpl:3540) 0x808464a (runtime.gosched_m:3548) 0x80a835f (runtime.mcall:325) labels: map[]
        
        1: 0x8098680 (runtime.nanotime1:177) 0x807f93f (runtime.nanotime:19 runtime.casgstatus:1001) 0x8082267 (runtime.execute:2686) 0x8083fe7 (runtime.schedule:3415) 0x80845e9 (runtime.goschedImpl:3540) 0x808464a (runtime.gosched_m:3548) 0x80a835f (runtime.mcall:325) labels: map[key:[value]]
        
        1: 0x80a94a6 (runtime.procyield:572) 0x80515c6 (runtime.lock2:69) 0x806cfa7 (runtime.lockWithRank:22 runtime.lock:36 runtime.(*mheap).freeSpan.func1:1427) 0x80a83b4 (runtime.systemstack:370) 0x806cf6c (runtime.(*mheap).freeSpan:1426) 0x8069edd (runtime.(*sweepLocked).sweep:680) 0x806976d (runtime.sweepone:369) 0x805d56e (runtime.GC:451) 0x8178e53 (runtime/pprof.labelHog:1514) 0x817900c (runtime/pprof.parallelLabelHog.func1:1534) labels: map[key:[value]]
        
        3: 0x8098280 (runtime.thrwakeup:27) 0x8078656 (runtime.semawakeup:123) 0x805173d (runtime.unlock2:117) 0x8066973 (runtime.unlockWithRank:31 runtime.unlock:97 runtime.setGCPercent.func1:1232) 0x80a83b4 (runtime.systemstack:370) 0x80a5ae4 (runtime/debug.setGCPercent:1227) 0x8178e62 (runtime/debug.SetGCPercent:92 runtime/pprof.labelHog:1521) 0x817900c (runtime/pprof.parallelLabelHog.func1:1534) labels: map[key:[value]]
        
        5: 0x80a94a6 (runtime.procyield:572) 0x80515c6 (runtime.lock2:69) 0x80668ff (runtime.lockWithRank:22 runtime.lock:36 runtime.setGCPercent.func1:1228) 0x80a83b4 (runtime.systemstack:370) 0x80a5ae4 (runtime/debug.setGCPercent:1227) 0x8178e62 (runtime/debug.SetGCPercent:92 runtime/pprof.labelHog:1521) 0x817900c (runtime/pprof.parallelLabelHog.func1:1534) labels: map[key:[value]]
        
        7: 0x8098250 (runtime.thrsleep:17) 0x80784f0 (runtime.semasleep:113) 0x8051651 (runtime.lock2:89) 0x80668ff (runtime.lockWithRank:22 runtime.lock:36 runtime.setGCPercent.func1:1228) 0x80a83b4 (runtime.systemstack:370) 0x80a5ae4 (runtime/debug.setGCPercent:1227) 0x8178e62 (runtime/debug.SetGCPercent:92 runtime/pprof.labelHog:1521) 0x817900c (runtime/pprof.parallelLabelHog.func1:1534) labels: map[key:[value]]
        
        8: 0x80982a8 (runtime.osyield:33) 0x80515b4 (runtime.lock2:71) 0x80668ff (runtime.lockWithRank:22 runtime.lock:36 runtime.setGCPercent.func1:1228) 0x80a83b4 (runtime.systemstack:370) 0x80a5ae4 (runtime/debug.setGCPercent:1227) 0x8178e62 (runtime/debug.SetGCPercent:92 runtime/pprof.labelHog:1521) 0x817900c (runtime/pprof.parallelLabelHog.func1:1534) labels: map[key:[value]]
        
        1: 0x8066aef (runtime.gcPaceScavenger:132) 0x8066963 (runtime.setGCPercent.func1:1231) 0x80a83b4 (runtime.systemstack:370) 0x80a5ae4 (runtime/debug.setGCPercent:1227) 0x8178e62 (runtime/debug.SetGCPercent:92 runtime/pprof.labelHog:1521) 0x817900c (runtime/pprof.parallelLabelHog.func1:1534) labels: map[key:[value]]
        
        1: 0x8066b13 (runtime.gcPaceScavenger:133) 0x8066963 (runtime.setGCPercent.func1:1231) 0x80a83b4 (runtime.systemstack:370) 0x80a5ae4 (runtime/debug.setGCPercent:1227) 0x8178e62 (runtime/debug.SetGCPercent:92 runtime/pprof.labelHog:1521) 0x817900c (runtime/pprof.parallelLabelHog.func1:1534) labels: map[key:[value]]
        
    pprof_test.go:595: runtime.systemstack;key=value: 27
    pprof_test.go:1504: Sample labeled got true want false:  0x8178ffc (runtime/pprof.parallelLabelHog.func1:1533)
FAIL
FAIL	runtime/pprof	10.854s

greplogs --dashboard -md -l -e 'Sample labeled got true want false: .* \(runtime/pprof\.parallelLabelHog\.func1'

2022-01-20T16:31:11-59122f8/openbsd-386-70
2022-01-20T14:59:17-9284279/openbsd-386-70
2022-01-19T22:56:09-e4ab8b0/openbsd-386-70

---

I suspect that the case on this line just needs to be expanded:

go/src/runtime/pprof/pprof_test.go

Line 1451 in 59122f8

case "runtime/pprof.labelHog", "runtime/pprof.parallelLabelHog":

I'm not entirely sure why this failure mode only seems to crop up on the openbsd-386-70 builder, though. 🤔

(attn @prattmic @felixge)

[bcmills]

(This is a release blocker for Go 1.18 because the test is new as of 1.18.)

[prattmic]

Yup, you are correct, I missed this. The vast majority of the time will be spent in labelHog, but this is at the wg.Done. I also don't know why openbsd would be most likely to see this.

[gopherbot]

Change https://golang.org/cl/380055 mentions this issue: runtime/pprof: TestLabelSystemstack parallelLabelHog.func1 must be labeled