Skip to content

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

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
Closed
ardan-bkennedy opened this issue Aug 22, 2017 · 14 comments
Closed

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

ardan-bkennedy opened this issue Aug 22, 2017 · 14 comments
Labels
CherryPickApproved Used during the release process for point releases FrozenDueToAge release-blocker
Milestone
Go1.9.2

Comments

@ardan-bkennedy
Copy link

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 ALTree added the NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one. label Aug 22, 2017
@ALTree
Copy link
Member

ALTree commented Aug 22, 2017

cc @aclements

@aclements
Copy link
Member

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

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

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

@aclements
Copy link
Member

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

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

@aclements
Copy link
Member

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

ardan-bkennedy commented Aug 25, 2017 via email

@rsc rsc modified the milestones: Go1.9.1, Go1.9.2 Oct 4, 2017
@ianlancetaylor ianlancetaylor added release-blocker and removed NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one. labels Oct 13, 2017
@rsc
Copy link
Contributor

rsc commented Oct 13, 2017 •
edited
Loading

CL 58690 OK for Go 1.9.2.

@rsc rsc added the CherryPickApproved Used during the release process for point releases label Oct 14, 2017
@rsc rsc mentioned this issue Oct 15, 2017
Closed
@gopherbot
Copy link
Contributor

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

@aclements aclements mentioned this issue Oct 25, 2017
Closed
gopherbot pushed a commit that referenced this issue Oct 25, 2017
@aclements @rsc
[release-branch.go1.9] runtime: capture runtimeInitTime after nanotim…
c6388d3 
…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
Copy link
Contributor

rsc 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 as completed Oct 26, 2017
@ardan-bkennedy
Copy link
Author

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

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

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.
Assignees
No one assigned
Labels
CherryPickApproved Used during the release process for point releases FrozenDueToAge release-blocker
Projects
None yet
Milestone
Go1.9.2
Development

No branches or pull requests
6 participants
@rsc @ardan-bkennedy @aclements @ianlancetaylor @ALTree @gopherbot