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.

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

runtime: GODEBUG gctrace bug with time ran on Mac #21554

Closed
ardan-bkennedy opened this issue Aug 22, 2017 · 14 comments

Comments

Projects
None yet
6 participants
@ardan-bkennedy
Copy link

commented Aug 22, 2017

What version of Go are you using (go version)?

go version go1.9rc2 darwin/amd64

Does this issue reproduce with the latest release?

Yes, only in 1.9 and since beta.

What operating system and processor architecture are you using (go env)?

GOARCH="amd64"
GOHOSTARCH="amd64"
GOHOSTOS="darwin"
GOOS="darwin"

macOS Sierra  Version 10.12.6

What did you do?

Using this program:
https://github.com/ardanlabs/gotraining/tree/master/topics/go/profiling/project

Build the code and run it using:
$ GODEBUG=gctrace=1 ./project > /dev/null

Then open the browser and run a search. Be sure to check the three boxes for cnn, bbc and nyt and you get some results.
http://localhost:5000/search

This will produce a gctrace immediately.

What did you expect to see?

gc 1 @1.186s 0%: 0.092+0.47+0.038 ms clock, 0.37+0.15/0.81/1.8+0.15 ms cpu, 4->4->1 MB, 5 MB goal, 8 P

What did you see instead?

gc 1 18446653480.186s 0%: 0.092+0.47+0.038 ms clock, 0.37+0.15/0.81/1.8+0.15 ms cpu, 4->4->1 MB, 5 MB goal, 8 P

@ALTree ALTree changed the title GODEBUG gctrace bug with time ran on Mac runtime: GODEBUG gctrace bug with time ran on Mac Aug 22, 2017

@ALTree

This comment has been minimized.

Copy link
Member

commented Aug 22, 2017

@aclements

This comment has been minimized.

Copy link
Member

commented Aug 24, 2017

It took me some work, but I was able to reproduce this on a gomote

git checkout go1.9rc2
VM=$(gomote create darwin-amd64-10_12)
gomote push $VM
gomote ssh $VM
cd $GOROOT/src
./make.bash
cd ../bin
PATH=$PWD:$PATH
go get -d github.com/ardanlabs/gotraining/topics/go/profiling/project
cd $GOPATH/src/github.com/ardanlabs/gotraining/topics/go/profiling/project
go build
GODEBUG=gctrace=1 ./project > /dev/null

In another terminal:

gomote ssh $VM
curl -d cnn=on -d nyt=on -d bbc=on -d term=test http://localhost:5000/search
@aclements

This comment has been minimized.

Copy link
Member

commented Aug 24, 2017

Ah, the problem is we have two different time bases in the runtime as of e4371fb. That commit made nanotime() return a value relative to runtime.startNano. However, runtime.main does runtimeInitTime = nanotime() before runtime_init(), which sets startNano = nanotime(). The gctrace times are computed as nanotime() - runtimeInitTime, so when the time base changes, this no longer makes sense.

@gopherbot

This comment has been minimized.

Copy link

commented Aug 24, 2017

Change https://golang.org/cl/58690 mentions this issue: runtime: capture runtimeInitTime after nanotime is initialized

@gopherbot gopherbot closed this in 9d17e17 Aug 25, 2017

@aclements

This comment has been minimized.

Copy link
Member

commented Aug 25, 2017

Re-opening for cherry-pick to Go 1.9.1

@aclements aclements reopened this Aug 25, 2017

@aclements aclements added this to the Go1.9.1 milestone Aug 25, 2017

@ianlancetaylor

This comment has been minimized.

Copy link
Contributor

commented Aug 25, 2017

Is this worth cherry picking? It seems a very minor problem.

@aclements

This comment has been minimized.

Copy link
Member

commented Aug 25, 2017

Rick and I pretty frequently ask people for gctrace output when debugging performance issues. This could make that harder to interpret. It's also a simple fix, so I think whenever 1.9.1 happens we might as well include it.

@ardan-bkennedy

This comment has been minimized.

Copy link
Author

commented Aug 25, 2017

@rsc rsc modified the milestones: Go1.9.1, Go1.9.2 Oct 4, 2017

@rsc

This comment has been minimized.

Copy link
Contributor

commented Oct 13, 2017

CL 58690 OK for Go 1.9.2.

@gopherbot

This comment has been minimized.

Copy link

commented Oct 15, 2017

Change https://golang.org/cl/70848 mentions this issue: [release-branch.go1.9] runtime: capture runtimeInitTime after nanotime is initialized

gopherbot pushed a commit that referenced this issue Oct 25, 2017

[release-branch.go1.9] runtime: capture runtimeInitTime after nanotim…
…e is initialized

CL 36428 changed the way nanotime works so on Darwin and Windows it
now depends on runtime.startNano, which is computed at runtime.init
time. Unfortunately, the `runtimeInitTime = nanotime()` initialization
happened *before* runtime.init, so on these platforms runtimeInitTime
is set incorrectly. The one (and only) consequence of this is that the
start time printed in gctrace lines is bogus:

gc 1 18446653480.186s 0%: 0.092+0.47+0.038 ms clock, 0.37+0.15/0.81/1.8+0.15 ms cpu, 4->4->1 MB, 5 MB goal, 8 P

To fix this, this commit moves the runtimeInitTime initialization to
shortly after runtime.init, at which point nanotime is safe to use.

This also requires changing the condition in newproc1 that currently
uses runtimeInitTime != 0 simply to detect whether or not the main M
has started. Since runtimeInitTime could genuinely be 0 now, this
introduces a separate flag to newproc1.

Fixes #21554.

Change-Id: Id874a4b912d3fa3d22f58d01b31ffb3548266d3b
Reviewed-on: https://go-review.googlesource.com/58690
Run-TryBot: Austin Clements <austin@google.com>
TryBot-Result: Gobot Gobot <gobot@golang.org>
Reviewed-by: Rick Hudson <rlh@golang.org>
Reviewed-by: Ian Lance Taylor <iant@golang.org>
Reviewed-on: https://go-review.googlesource.com/70848
Run-TryBot: Russ Cox <rsc@golang.org>
Reviewed-by: Austin Clements <austin@google.com>
@rsc

This comment has been minimized.

Copy link
Contributor

commented Oct 26, 2017

go1.9.2 has been packaged and includes:

The release is posted at golang.org/dl.

— golang.org/x/build/cmd/releasebot, Oct 26 21:09:07 UTC

@rsc rsc closed this Oct 26, 2017

@ardan-bkennedy

This comment has been minimized.

Copy link
Author

commented Oct 27, 2017

Just tried it out on darwin and it looks good! Thank You.

Is there anyway this can get fixed as well for 1.9? It is broken on both darwin and linux.
#21697

@aclements

This comment has been minimized.

Copy link
Member

commented Oct 27, 2017

@ardan-bkennedy, this isn't really the place to ask about the other issue. If you're interested in having #21697 fixed in 1.9, you should argue that on that issue (and understand that whether or not the fix gets backported also depends on the risk involved in the actual fix).

@ardan-bkennedy

This comment has been minimized.

Copy link
Author

commented Oct 27, 2017

New to all this so thanks for laying out the policy I am supposed to follow. It won’t happen again.

@golang golang locked and limited conversation to collaborators Oct 27, 2018

Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
You can’t perform that action at this time.