Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

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

Closed
Wieku opened this issue Feb 28, 2024 · 9 comments
Closed

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

Wieku opened this issue Feb 28, 2024 · 9 comments
Assignees
@mknyszek
Labels
compiler/runtime Issues related to the Go compiler and/or runtime. NeedsFix The path to resolution is known, but the work has not been done.
Milestone
Go1.23

Comments

@Wieku
Copy link

Wieku commented Feb 28, 2024

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:

2024-02-28_12-38-57_Oy93U

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()):
2024-02-28_14-04-59_UDWQx

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:
2024-02-28_12-38-19_biwwS

Minified example (VSync on 144hz monitor):
image

As we can see, delta in both examples is ~6.9ms, so it is correct.
@prattmic prattmic changed the title runtime/trace v2: Incorrect timestamps are being recorded runtime/trace: trace v2 incorrect timestamps are being recorded Feb 28, 2024
@gopherbot gopherbot added the compiler/runtime Issues related to the Go compiler and/or runtime. label Feb 28, 2024
@prattmic
Copy link
Member

cc @mknyszek

@prattmic prattmic added this to the Go1.23 milestone Feb 28, 2024
@prattmic
Copy link
Member

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 mknyszek changed the title runtime/trace: trace v2 incorrect timestamps are being recorded runtime/trace: v2 traces show incorrect timestamps in the UI on Windows Feb 28, 2024
@mknyszek mknyszek self-assigned this Feb 28, 2024
@mknyszek
Copy link
Contributor

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
Copy link
Contributor

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

@mknyszek mknyszek changed the title runtime/trace: v2 traces show incorrect timestamps in the UI on Windows runtime/trace: v2 traces contain an incorrect timestamp scaling factor on Windows Feb 28, 2024
@mknyszek
Copy link
Contributor

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
Copy link

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

@mknyszek mknyszek added the NeedsFix The path to resolution is known, but the work has not been done. label Feb 28, 2024
@mknyszek
Copy link
Contributor

mknyszek commented Mar 8, 2024

@gopherbot Please open a backport issue for Go 1.22.

@gopherbot gopherbot mentioned this issue Mar 8, 2024
Closed
@gopherbot
Copy link

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
Copy link

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

gopherbot pushed a commit that referenced this issue Mar 27, 2024
@mknyszek @gopherbot
[release-branch.go1.22] runtime: fix EvFrequency event value on Windo…
abfd578 
…ws in the new tracer

The value produced for the EvFrequency event on Windows is missing the
fact that the cputicks clock gets divided. This results in durations
that are consistently wrong by the same factor (about 256).

For #65997.
Fixes #66201.

Change-Id: I930cbfce3499d435c20699f41c11e3227d84f911
Reviewed-on: https://go-review.googlesource.com/c/go/+/567937
LUCI-TryBot-Result: Go LUCI <golang-scoped@luci-project-accounts.iam.gserviceaccount.com>
Auto-Submit: Michael Knyszek <mknyszek@google.com>
Reviewed-by: Michael Pratt <mpratt@google.com>
(cherry picked from commit 707eba9)
Reviewed-on: https://go-review.googlesource.com/c/go/+/570195
Reviewed-by: Than McIntosh <thanm@google.com>
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees

@mknyszek mknyszek

Labels
compiler/runtime Issues related to the Go compiler and/or runtime. NeedsFix The path to resolution is known, but the work has not been done.
Projects
Go Compiler / Runtime
Status: Done
Milestone
Go1.23
Development

No branches or pull requests
4 participants
@mknyszek @prattmic @Wieku @gopherbot