internal/trace: event timestamps change between Go versions #73558
Comments
|
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 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. |
|
Change https://go.dev/cl/669257 mentions this issue: |
|
Change https://go.dev/cl/669258 mentions this issue: |
|
Change https://go.dev/cl/669259 mentions this issue: |
|
@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. |
|
@rhysh I moved it to the Go 1.25 milestone. Thanks for pointing that out. |
Disable a test that counts Sync events. Re-enable it after pulling in the Go 1.25 parser. For golang/go#73558 Change-Id: I5ab2a2ce34c1e4a3d31fd599c2ae683334433474 Reviewed-on: https://go-review.googlesource.com/c/exp/+/669257 Auto-Submit: Rhys Hiltner <rhys.hiltner@gmail.com> LUCI-TryBot-Result: Go LUCI <golang-scoped@luci-project-accounts.iam.gserviceaccount.com> Reviewed-by: Carlos Amedee <carlos@golang.org> Reviewed-by: Cherry Mui <cherryyz@google.com>
For golang/go#73558 With go version devel go1.25-12e5efd710 Wed Apr 30 11:40:17 2025 -0700: [git-generate] cd ./trace ./gen.bash $GOROOT sed -i'.tmp' -e 's golang.org/x/exp/trace/internal/event/go122 golang.org/x/exp/trace/internal/tracev2 ' flightrecorder.go sed -i'.tmp' -e 's go122 tracev2 ' flightrecorder.go rm flightrecorder.go.tmp Change-Id: I74888e2f43f346c3311bf0053d57e144b7381892 Reviewed-on: https://go-review.googlesource.com/c/exp/+/669258 LUCI-TryBot-Result: Go LUCI <golang-scoped@luci-project-accounts.iam.gserviceaccount.com> Reviewed-by: Carlos Amedee <carlos@golang.org> Reviewed-by: Cherry Mui <cherryyz@google.com> Auto-Submit: Rhys Hiltner <rhys.hiltner@gmail.com>
For golang/go#73558 Change-Id: I27bf3916b13af581c68921b3719c330ec4db9827 Reviewed-on: https://go-review.googlesource.com/c/exp/+/669259 Reviewed-by: Cherry Mui <cherryyz@google.com> LUCI-TryBot-Result: Go LUCI <golang-scoped@luci-project-accounts.iam.gserviceaccount.com> Auto-Submit: Rhys Hiltner <rhys.hiltner@gmail.com> Reviewed-by: Carlos Amedee <carlos@golang.org>
Go version
go version devel go1.25-1e756dc5f7 Tue Apr 29 07:38:24 2025 -0700 darwin/arm64
Output of
go envin your module/workspace: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.
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
The text was updated successfully, but these errors were encountered: