Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

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

Closed
bcmills opened this issue Jan 21, 2022 · 3 comments
Closed

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

bcmills opened this issue Jan 21, 2022 · 3 comments
Assignees
@prattmic
Labels
FrozenDueToAge NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one. release-blocker
Milestone
Go1.18

Comments

@bcmills
Copy link
Contributor

bcmills commented Jan 21, 2022 

--- 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 bcmills added NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one. release-blocker labels Jan 21, 2022
@bcmills bcmills added this to the Go1.18 milestone Jan 21, 2022
@bcmills
Copy link
Contributor Author

bcmills commented Jan 21, 2022

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

@bcmills bcmills changed the title runtime/pprof: TestLabelSystemstack failure with labeled "runtime/pprof.parallelLabelHog.func1" runtime/pprof: TestLabelSystemstack failures with labeled "runtime/pprof.parallelLabelHog.func1" Jan 21, 2022
@prattmic
Copy link
Member

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.

@prattmic prattmic self-assigned this Jan 21, 2022
@gopherbot
Copy link

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

jproberts pushed a commit to jproberts/go that referenced this issue Jun 21, 2022
@prattmic @jproberts
runtime/pprof: TestLabelSystemstack parallelLabelHog.func1 must be la…
c6a36f0 
…beled

The closure in parallelLabelHog should be labeled in a addition to
parallelLabelHog itself. Generally samples on that goroutine land on
labelHog, but there is a small portion of the closure outside of
labelHog.

Fixes golang#50740.

Change-Id: I363b6d8eec2e6920c215686e2039fce6d5b29a98
Reviewed-on: https://go-review.googlesource.com/c/go/+/380055
Reviewed-by: Bryan Mills <bcmills@google.com>
Trust: Michael Pratt <mpratt@google.com>
@prattmic prattmic self-assigned this Jun 24, 2022
@golang golang locked and limited conversation to collaborators Jun 24, 2023
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Assignees

@prattmic prattmic

Labels
FrozenDueToAge NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one. release-blocker
Projects
None yet
Milestone
Go1.18
Development

No branches or pull requests
3 participants
@prattmic @bcmills @gopherbot