cmd/trace: go tool trace mishandles goroutine that extends beyond the current span.

[davecheney]

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.

[hyangah]

That's a limitation of the current hack that splits the big trace into multiple chunks.
I think I can address this in go1.11.

[hyangah]

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
1.732538ms 1732538 GCSweepStart p=1 g=1 off=679 link=off:682
1.736349ms 1736349 GCSweepDone p=1 g=1 off=682 swept=8192 reclaimed=0
1.737425ms 1737425 GCSweepStart p=1 g=1 off=694 link=off:697
1.834356ms 1834356 GCSweepDone p=1 g=1 off=697 swept=3579904 reclaimed=0
1.841338ms 1841338 GCSweepStart p=1 g=1 off=705 link=off:709
1.84605ms 1846050 GCSweepDone p=1 g=1 off=709 swept=57344 reclaimed=896
1.858036ms 1858036 GCSweepStart p=1 g=1 off=730 link=off:734
1.862632ms 1862632 GCSweepDone p=1 g=1 off=734 swept=65536 reclaimed=2192
1.870138ms 1870138 GCSweepStart p=1 g=1 off=755 link=off:758
1.87549ms 1875490 GCSweepDone p=1 g=1 off=758 swept=57344 reclaimed=784
... a lot of GoCreate events...
1.431362065s 1431362065 GoPreempt p=1 g=1 off=19101341 link=off:19101365

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
handle the newly created goroutines and runtime didn't have to preempt the main goroutine. cc
@aclements

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.

[ianlancetaylor]

@hyangah Is this likely to be fixed in 1.11?