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.

Sign up for GitHub

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: trace2: some stacks don't skip tracer's own frames #64862

Open
dominikh opened this issue Dec 25, 2023 · 3 comments
Open

runtime: trace2: some stacks don't skip tracer's own frames #64862

dominikh opened this issue Dec 25, 2023 · 3 comments
Assignees
@mknyszek
Labels
compiler/runtime Issues related to the Go compiler and/or runtime. NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one.
Milestone
Backlog

Comments

@dominikh
Copy link
Member

I've found the following 3 kinds of events in my trace that include the tracer in the stack when they probably shouldn't:

M=1125110 P=0 G=1 RangeBegin Time=704285462306048 Name="GC incremental sweep" Scope=Proc(0)
Stack=
        runtime.traceLocker.GCSweepSpan @ 0x462575
                /home/dominikh/prj/go/src/runtime/trace2runtime.go:352
        runtime.(*sweepLocked).sweep @ 0x428584
                /home/dominikh/prj/go/src/runtime/mgcsweep.go:521
        runtime.(*mcentral).cacheSpan @ 0x418ebc
                /home/dominikh/prj/go/src/runtime/mcentral.go:147
        runtime.(*mcache).refill @ 0x4185d2
                /home/dominikh/prj/go/src/runtime/mcache.go:182
        runtime.(*mcache).nextFree @ 0x40f644
                /home/dominikh/prj/go/src/runtime/malloc.go:948
        runtime.mallocgc @ 0x40fc64
                /home/dominikh/prj/go/src/runtime/malloc.go:1149
        runtime.newobject @ 0x410204
                /home/dominikh/prj/go/src/runtime/malloc.go:1390
[...]

M=1125121 P=2 G=1870 RangeBegin Time=704285696073408 Name="GC mark assist" Scope=Goroutine(1870)
Stack=
        runtime.traceLocker.GCMarkAssistStart @ 0x462741
                /home/dominikh/prj/go/src/runtime/trace2runtime.go:378
        runtime.gcAssistAlloc @ 0x42121c
                /home/dominikh/prj/go/src/runtime/mgcmark.go:536
        runtime.deductAssistCredit @ 0x410113
                /home/dominikh/prj/go/src/runtime/malloc.go:1353
        runtime.mallocgc @ 0x40f88b
                /home/dominikh/prj/go/src/runtime/malloc.go:1025
        runtime.growslice @ 0x454abb
[...]

M=1125107 P=14 G=136 StateTransition Time=704285616667520 Resource=Goroutine(615) Reason="" GoID=615 Waiting->Runnable
Stack=
        runtime.traceLocker.stack @ 0x462f57
                /home/dominikh/prj/go/src/runtime/trace2event.go:166
        runtime.traceLocker.GoUnpark @ 0x462f12
                /home/dominikh/prj/go/src/runtime/trace2runtime.go:445
        runtime.injectglist @ 0x444a7d
                /home/dominikh/prj/go/src/runtime/proc.go:3768
        runtime.gcWakeAllAssists @ 0x421919
                /home/dominikh/prj/go/src/runtime/mgcmark.go:714
        runtime.gcMarkDone @ 0x41d5f6
                /home/dominikh/prj/go/src/runtime/mgc.go:910
        runtime.gcBgMarkWorker @ 0x41ebe4
                /home/dominikh/prj/go/src/runtime/mgc.go:1446

/cc @mknyszek
@gopherbot gopherbot added the compiler/runtime Issues related to the Go compiler and/or runtime. label Dec 25, 2023
@smiletrl
Copy link
Contributor

@dominikh hey, may I know which command you used to generate above trace output? This doesn't look like one trace.out from https://pkg.go.dev/runtime/trace.

@dominikh
Copy link
Member Author

@smiletrl This is with Go 1.22's runtime/trace and go tool trace.

@thanm thanm added the NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one. label Dec 27, 2023
@smiletrl
Copy link
Contributor

@dominikh hey, sorry for more naive questions. I tried 1.22 go tool trace trace.out, which generates similar graph output in web browser. How can I generate output like yours?

M=1125110 P=0 G=1 RangeBegin Time=704285462306048 Name="GC incremental sweep" Scope=Proc(0)
Stack=
        runtime.traceLocker.GCSweepSpan @ 0x462575
                /home/dominikh/prj/go/src/runtime/trace2runtime.go:352
        runtime.(*sweepLocked).sweep @ 0x428584
                /home/dominikh/prj/go/src/runtime/mgcsweep.go:521
        runtime.(*mcentral).cacheSpan @ 0x418ebc
                /home/dominikh/prj/go/src/runtime/mcentral.go:147
        runtime.(*mcache).refill @ 0x4185d2
                /home/dominikh/prj/go/src/runtime/mcache.go:182
        runtime.(*mcache).nextFree @ 0x40f644
                /home/dominikh/prj/go/src/runtime/malloc.go:948
        runtime.mallocgc @ 0x40fc64
                /home/dominikh/prj/go/src/runtime/malloc.go:1149
        runtime.newobject @ 0x410204
                /home/dominikh/prj/go/src/runtime/malloc.go:1390
[...]

For tracker in stack

3 kinds of events in my trace that include the tracer in the stack when they probably shouldn't:

Do you mean above three events should not be tracked at all? Or you mean just part of trace log is the tracer in the stack?

Do you have some code samples that I can reproduce this issue?

Thanks!

@mknyszek mknyszek self-assigned this Jan 3, 2024
@mknyszek mknyszek added this to the Backlog milestone Jan 3, 2024
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees

@mknyszek mknyszek

Labels
compiler/runtime Issues related to the Go compiler and/or runtime. NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one.
Projects
Go Compiler / Runtime
Status: Todo
Milestone
Backlog
Development

No branches or pull requests
5 participants
@dominikh @mknyszek @smiletrl @gopherbot @thanm