internal/trace: event timestamps change between Go versions

[rhysh]

Go version

go version devel go1.25-1e756dc5f7 Tue Apr 29 07:38:24 2025 -0700 darwin/arm64

Output of go env in your module/workspace:

AR='ar'
CC='clang'
CGO_CFLAGS='-O2 -g'
CGO_CPPFLAGS=''
CGO_CXXFLAGS='-O2 -g'
CGO_ENABLED='1'
CGO_FFLAGS='-O2 -g'
CGO_LDFLAGS='-O2 -g'
CXX='clang++'
GCCGO='gccgo'
GO111MODULE=''
GOARCH='arm64'
GOARM64='v8.0'
GOAUTH='netrc'
GOBIN=''
GOCACHE='/Users/rhysh/Library/Caches/go-build'
GOCACHEPROG=''
GODEBUG=''
GOENV='/Users/rhysh/Library/Application Support/go/env'
GOEXE=''
GOEXPERIMENT=''
GOFIPS140='off'
GOFLAGS=''
GOGCCFLAGS='-fPIC -arch arm64 -pthread -fno-caret-diagnostics -Qunused-arguments -fmessage-length=0 -ffile-prefix-map=/var/folders/pw/d_qmtcrd3vs0890gvmrq8qx80000gn/T/go-build1656212783=/tmp/go-build -gno-record-gcc-switches -fno-common'
GOHOSTARCH='arm64'
GOHOSTOS='darwin'
GOINSECURE=''
GOMOD='/dev/null'
GOMODCACHE='/Users/rhysh/go/pkg/mod'
GONOPROXY=''
GONOSUMDB=''
GOOS='darwin'
GOPATH='/Users/rhysh/go'
GOPRIVATE=''
GOPROXY='https://proxy.golang.org,direct'
GOROOT='/Users/rhysh/sdk/go-bisect'
GOSUMDB='sum.golang.org'
GOTELEMETRY='local'
GOTELEMETRYDIR='/Users/rhysh/Library/Application Support/go/telemetry'
GOTMPDIR=''
GOTOOLCHAIN='auto'
GOTOOLDIR='/Users/rhysh/sdk/go-bisect/pkg/tool/darwin_arm64'
GOVCS=''
GOVERSION='devel go1.25-1e756dc5f7 Tue Apr 29 07:38:24 2025 -0700'
GOWORK=''
PKG_CONFIG='pkg-config'

What did you do?

A colleague and I used different Go versions' "go tool trace" to open the same execution trace, and attempted to communicate about specific events we were seeing in the HTML UI. We attempted to direct each other to interesting parts of the execution trace by referring to precise timestamps.

What did you see happen?

We couldn't find the event that the other was referring to. We discovered that the timestamp rendered the "go tool trace" HTML UI changed between Go 1.24 and tip.

With pre-1.25 tip, I see a "Sync" event that isn't present in Go 1.24's output. Previously the first timestamp in this particular trace (which the tool uses for the relative timestamps it calculates for display) was 1319851905344, but the new "Sync" event has a timestamp of 1319851891521. And sure enough, all of the timestamps in the HTML UI are off by 13823 nanoseconds.

$ go tool trace -d=parsed ./trace.out | head -n 3
M=-1 P=-1 G=-1 Sync Time=1319851891521
M=8 P=-1 G=-1 StateTransition Time=1319851905344 Resource=Proc(1) Reason="" ProcID=1 Undetermined->Running
M=8 P=1 G=-1 StateTransition Time=1319851905600 Resource=Goroutine(726965) Reason="" GoID=726965 Undetermined->Running

$ ~/sdk/go1.24/bin/go tool trace -d=parsed ./trace.out | head -n 3
M=8 P=-1 G=-1 StateTransition Time=1319851905344 Resource=Proc(1) Reason="" ProcID=1 Undetermined->Running
M=8 P=1 G=-1 StateTransition Time=1319851905600 Resource=Goroutine(726965) Reason="" GoID=726965 Undetermined->Running
M=8 P=1 G=726965 Metric Time=1319851908672 Name="/sched/gomaxprocs:threads" Value=Uint64(8)

I bisected to ca1cfea, which emits the "Sync" event (for good reason, of course).

What did you expect to see?

Execution trace tooling would be helped by having a stable identifier for each event. Previously when the execution trace parser stopped being deterministic across runs with the same tool version (in #68277, due to map iteration order), @mknyszek has said "this is an important property of the trace parser to maintain". This is a different case — of stability across Go versions. Overall, it's probably "unfortunate", and as long as we don't have many more breaks like this, everyone will eventually be on versions of the tools that have consistent behavior.

Are there any similar changes on the horizon, or do we expect the Sync event will keep being the timeline's zero point for versions at and beyond Go 1.25? Thanks.

CC @mknyszek @golang/runtime

[mknyszek]

Ugh. :( Sorry for the breakage and thanks for the detailed report. We should have an explicit test for this to make sure we don't break it in the future.

I think we should consider going back to the old behavior, but I don't know if that would just create more of a mess. EDIT: I see. This is at the UI level. Sigh, I'm not sure there's a lot we can do here. The Sync event is actually more accurate since it represents the true minimum timestamp in the trace. I think we should keep this behavior, but add a test to make sure it doesn't change again.

[rhysh]

I suspect that it would be more of a mess, yes.

And yes, the more-accurate timestamp from the Sync event is probably good in other ways too (such as measuring the startup time / overhead of tracing).

I expect it'll be less of a problem for tools other than "go tool trace", since those would depend on a particular version of the x/exp module. Users of those can pick a time to take the update that's decoupled from their Go toolchain changes.

Is Sync likely to remain the (new) first event, or is there potential for an even earlier event? It would be nice to not change it again in 1.26 or 1.27. Locking in the new behavior with a test sounds good.

[gabyhelp]

Related Issues

• cmd/trace, x/exp/trace: nondeterministic output, seems related to timestamp tie-breaking #68277 (closed)
• runtime, cmd/trace: recent regression: "failed to parse trace: no consistent ordering of events possible #36186 (closed)
• runtime/trace: v2 traces contain an incorrect timestamp scaling factor on Windows #65997 (closed)
• cmd/trace: go tool trace trace time stamps out of order #24663 (closed)
• misc/trace: events disappear at high zoom #19496
• cmd/trace: "failed to parse trace: no consistent ordering of events possible" #29707 (closed)
• runtime/trace: generated timestamps have a jump in them #15102 (closed)

Related Code Changes

• runtime: use per-goroutine sequence numbers in tracer
• runtime/trace: record event sequence numbers explicitly
• runtime: formalize the trace clock

_{(Emoji vote if this was helpful or unhelpful; more detailed feedback welcome in this discussion.)}

[gopherbot]

Change https://go.dev/cl/669257 mentions this issue: trace: update gen.bash for Go 1.25 renames

[gopherbot]

Change https://go.dev/cl/669258 mentions this issue: trace: regenerate to include CL 644215

[gopherbot]

Change https://go.dev/cl/669259 mentions this issue: trace: re-enable Sync event test

[rhysh]

@cagedmantis the x/exp/trace version of the parser is "Unreleased", but the original issue affects cmd/trace for the upcoming Go 1.25 release.

Should this be in the Go 1.25 milestone until there's consensus that the new Sync event is staying? That seems like a likely outcome, but it doesn't look to me like there's a clear decision on that yet. Following that, the remaining parts of this issue are indeed Unreleased.

[cagedmantis]

@rhysh I moved it to the Go 1.25 milestone. Thanks for pointing that out.