search

golang / go

The Go programming language
https://go.dev
BSD 3-Clause "New" or "Revised" License
124.13k stars 17.68k forks source link

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

Open dominikh opened 10 months ago

dominikh commented 10 months ago

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

smiletrl commented 10 months ago

@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 commented 10 months ago

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

smiletrl commented 10 months ago

@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!