runtime/trace: v2 traces contain an incorrect timestamp scaling factor on Windows

[Wieku]

Go version

go version go1.22.0 windows/amd64

Output of go env in your module/workspace:

set GO111MODULE=on
set GOARCH=amd64
set GOBIN=
set GOCACHE=C:\Users\Wieku\AppData\Local\go-build
set GOENV=C:\Users\Wieku\AppData\Roaming\go\env
set GOEXE=.exe
set GOEXPERIMENT=
set GOFLAGS=
set GOHOSTARCH=amd64
set GOHOSTOS=windows
set GOINSECURE=
set GOMODCACHE=C:\Users\Wieku\go\pkg\mod
set GONOPROXY=
set GONOSUMDB=
set GOOS=windows
set GOPATH=C:\Users\Wieku\go
set GOPRIVATE=
set GOPROXY=https://proxy.golang.org,direct
set GOROOT=C:/Program Files/Go
set GOSUMDB=sum.golang.org
set GOTMPDIR=
set GOTOOLCHAIN=auto
set GOTOOLDIR=C:\Program Files\Go\pkg\tool\windows_amd64
set GOVCS=
set GOVERSION=go1.22.0
set GCCGO=gccgo
set GOAMD64=v1
set AR=ar
set CC=gcc
set CXX=g++
set CGO_ENABLED=1
set GOMOD=C:\Users\Wieku\projects\danser\danser-go\go.mod
set GOWORK=
set CGO_CFLAGS=-O2 -g
set CGO_CPPFLAGS=
set CGO_CXXFLAGS=-O2 -g
set CGO_FFLAGS=-O2 -g
set CGO_LDFLAGS=-O2 -g
set PKG_CONFIG=pkg-config
set GOGCCFLAGS=-m64 -mthreads -Wl,--no-gc-sections -fmessage-length=0 -ffile-prefix-map=C:\Users\Wieku\AppData\Local\Temp\go-build2797386340=/tmp/go-build -gno-record-gcc-switches

What did you do?

I'm trying to record a trace of a program that utilizes glfw/opengl and other c/c++ libraries to check why in rare occasions 1ms sleep or runtime.Gosched can take up to 2-20 seconds. I wanted to check the new tracing introduced in go 1.22, but noticed that timestamps are completely wrong.

Minified example that also has this issue: glfwtest.zip

What did you see happen?

Main thread is set to pace at ~144Hz (pacing is done using time.Sleep(time.Millisecond)+runtime.Gosched), so it means rendering function should run every ~7ms. But looking at trace tool page it shows that it is running every 28us:

I see the same delta between other frames.

That's how it looks for the minified example (VSync is on, I'm measuring time between glfw.PollEvents()):

Again, 27us where 6.9-7ms is expected

What did you expect to see?

Both screenshots are from traces recorded by programs compiled with GOEXPERIMENT=noexectracer2.

Main program:

Minified example (VSync on 144hz monitor):

As we can see, delta in both examples is ~6.9ms, so it is correct.

[prattmic]

cc @mknyszek

[prattmic]

I wonder if this could be a Windows-specific bug, given that tracing handles clocks on Windows differently from other systems. Is there a chance you can test this on Linux to see if the problem reproduces there?

Additionally, if you could attach a v1 and v2 trace for comparison, that would help.

[mknyszek]

Thanks for the detailed reporting!

FTR, the clock used by both the old tracer and the new one on Windows is nearly identical, so I suspect the timestamps in the wire format should be OK. I think this is a bug in the time conversion code, either with the "EvFrequency" event getting emitted incorrectly, or somewhere in the parser.

[mknyszek]

'Doh. Yep. We emit a very wrong EvFrequency event. This is an easy fix.

[mknyszek]

I sent out a fix. It's so small and simple that I think it may be worth backporting this (even though there is a workaround).

[gopherbot]

Change https://go.dev/cl/567937 mentions this issue: runtime: fix EvFrequency event value on Windows in the new tracer

[mknyszek]

@gopherbot Please open a backport issue for Go 1.22.

[gopherbot]

Backport issue(s) opened: #66201 (for 1.22).

Remember to create the cherry-pick CL(s) as soon as the patch is submitted to master, according to https://go.dev/wiki/MinorReleases.

[gopherbot]

Change https://go.dev/cl/570195 mentions this issue: [release-branch.go1.22] runtime: fix EvFrequency event value on Windows in the new tracer