cmd/trace: go tool trace mishandles goroutine that extends beyond the current span. #21911
Comments
|
That's a limitation of the current hack that splits the big trace into multiple chunks. |
|
A little bit more detail and runtime scheduling related question: From 1.73ms, the main goroutine gets P and until it's preempted around 1.43s, the only events generated from P is GC sweep events, heap allocation events, and a lot of GoCreate events. 1.730705ms 1730705 GoStart p=1 g=1 off=676 g=1 seq=0 link=off:19101341 I don't understand why runtime didn't preempt the main goroutine but allow it to occupy P for more than 1s. My guess is probably most goroutines are short-lived, so other 3 Ps are sufficient to Going back to the limitation of the current execution tracer's visualization: Due to the limitation of the chrome trace viewer that can't handle large size input, go execution tracer arbitrarily splits the trace based on the event timestamp into multiple chunks. In this case, the first chunk includes events that started within 0-256ms. The slice (the block in the viewer) that represents the period of time the main goroutine has the start time that is inside the chunk, but its end time is outside the chunk (256ms < 1.431362065s from the GoPreempt event), so the runtime.main slice was presented strangely here. The only events the runtime.main goroutine resulted in during this execution were GoCreate events but that events are represented as the arrows which will not show up unless "View Options" flow events box is selected. One workaround is truncate the last slice so it ends at the end of the presented chunks. But that's a hack. |
hyangah
changed the title
ianlancetaylor
added
the
NeedsFix
|
@hyangah Is this likely to be fixed in 1.11? |
gopherbot
added
the
compiler/runtime
Please answer these questions before submitting your issue. Thanks!
What version of Go are you using (
go version)?% go version
go version devel +f351dbfa4d Thu Sep 14 04:49:58 2017 +0000 darwin/amd64
Does this issue reproduce with the latest release?
yes
What operating system and processor architecture are you using (
go env)?% uname -a
Darwin zapf.fritz.box 16.7.0 Darwin Kernel Version 16.7.0: Thu Jun 15 17:36:27 PDT 2017; root:xnu-3789.70.16~2/RELEASE_X86_64 x86_64
What did you do?
Download the attached px.out trace
go tool trace px.out
Open the first span (0s-256.629789ms)
px.out.zip
What did you expect to see?
The trace to terminate at 256ms with the G1 runtime.main goroutine constrained to the 256ms boundry.
What did you see instead?
G1 runtime.main extends the length of the runtime of the program, 1.7s. Zooming into the trace G1 runtime.main does not appear to be valid, there are no breaks in the sequence and it doesn't seem to represent the real trace.
The text was updated successfully, but these errors were encountered: