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: Bad HeapGoal/NextGC Metric #63864

Open
felixge opened this issue Nov 1, 2023 · 3 comments
Open

runtime/trace: Bad HeapGoal/NextGC Metric #63864

felixge opened this issue Nov 1, 2023 · 3 comments
Assignees
@mknyszek
Labels
compiler/runtime Issues related to the Go compiler and/or runtime.
Milestone
Go1.23

Comments

@felixge
Copy link
Contributor

felixge commented Nov 1, 2023 •
edited

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

$ go version go1.21.3 darwin/arm64

Does this issue reproduce with the latest release?

Yes, including tip.

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

go env Output
$ go env
GO111MODULE='auto'
GOARCH='arm64'
GOBIN=''
GOCACHE='/Users/USER/Library/Caches/go-build'
GOENV='/Users/USER/Library/Application Support/go/env'
GOEXE=''
GOEXPERIMENT=''
GOFLAGS='-count=1'
GOHOSTARCH='arm64'
GOHOSTOS='darwin'
GOINSECURE=''
GOMODCACHE='/Users/USER/go/pkg/mod'
GONOPROXY='github.com/Org'
GONOSUMDB='github.com/Org,go.orgbuild.io'
GOOS='darwin'
GOPATH='/Users/USER/go'
GOPRIVATE='github.com/Org'
GOPROXY='binaries.orgbuild.io,proxy.golang.org,direct'
GOROOT='/opt/homebrew/Cellar/go/1.21.3/libexec'
GOSUMDB='sum.golang.org'
GOTMPDIR=''
GOTOOLCHAIN='auto'
GOTOOLDIR='/opt/homebrew/Cellar/go/1.21.3/libexec/pkg/tool/darwin_arm64'
GOVCS=''
GOVERSION='go1.21.3'
GCCGO='gccgo'
AR='ar'
CC='clang'
CXX='c++'
CGO_ENABLED='1'
GOMOD=''
GOWORK=''
CGO_CFLAGS='-O2 -g'
CGO_CPPFLAGS=''
CGO_CXXFLAGS='-O2 -g'
CGO_FFLAGS='-O2 -g'
CGO_LDFLAGS='-O2 -g'
PKG_CONFIG='pkg-config'
GOGCCFLAGS='-fPIC -arch arm64 -pthread -fno-caret-diagnostics -Qunused-arguments -fmessage-length=0 -ffile-prefix-map=/var/folders/0t/nwrdnfnd2mjdgr0z_p_f6xww0000gq/T/go-build3503366670=/tmp/go-build -gno-record-gcc-switches -fno-common'

What did you do?

Capture a trace of running the encoding/json tests and then viewing it in go tool trace:

$ go test -trace json.trace encoding/json

CleanShot 2023-11-01 at 09 07 26@2x

(I did this while implementing heap metrics for CL 538515. At first I thought it's a bug in my code, but then I realized the problem exists in the old tracer as well 😅.)

What did you expect to see?

A reasonable NextGC metric value.

What did you see instead?

An unreasonable NextGC metric value. Maybe caused by a uint64 underflow?

As far as I can tell, the problem appears to be in the data, not the trace viewer.

$ go tool trace -d ./json.trace | grep HeapGoal
2023/11/01 09:10:58 Parsing trace...
2704 HeapGoal p=0 g=1 off=142 mem=4194304
3983536 HeapGoal p=3 g=36 off=133427 mem=5988680
7451664 HeapGoal p=0 g=35 off=4877 mem=10640088
12998705 HeapGoal p=8 g=19 off=144611 mem=18734952
22220882 HeapGoal p=5 g=19 off=141308 mem=32462632
41322629 HeapGoal p=2 g=36 off=117962 mem=49052584
73809753 HeapGoal p=1 g=36 off=95052 mem=38877592
100867596 HeapGoal p=0 g=34 off=49758 mem=17658824
103327101 HeapGoal p=1 g=80 off=95363 mem=49754376
106035005 HeapGoal p=1 g=34 off=95542 mem=55731352
112637966 HeapGoal p=1 g=34 off=95774 mem=67923528
122922303 HeapGoal p=0 g=50 off=57951 mem=91832744
127586144 HeapGoal p=1 g=146 off=97325 mem=8946670875736242639
128176272 HeapGoal p=1 g=146 off=97379 mem=91832744
135046177 HeapGoal p=6 g=15 off=143059 mem=19712536
144138898 HeapGoal p=7 g=14 off=144046 mem=35340824
165010277 HeapGoal p=1 g=14 off=104248 mem=53870584
185668071 HeapGoal p=0 g=121 off=80009 mem=8946670875735194404
186297063 HeapGoal p=0 g=121 off=80048 mem=53870584
199934729 HeapGoal p=4 g=34 off=138916 mem=33694248
214716523 HeapGoal p=1 g=50 off=115986 mem=50463048
233048733 HeapGoal p=3 g=18 off=136782 mem=22212712
250342656 HeapGoal p=3 g=19 off=136882 mem=34606152
260790321 HeapGoal p=2 g=35 off=132457 mem=35196680
265980994 HeapGoal p=2 g=14 off=132538 mem=62106312

cc @mknyszek @prattmic
@gopherbot gopherbot added the compiler/runtime Issues related to the Go compiler and/or runtime. label Nov 1, 2023
@felixge felixge changed the title runtime/trace: Bad NextGC Metric runtime/trace: Bad HeapGoal/NextGC Metric Nov 1, 2023
@mknyszek
Copy link
Contributor

mknyszek commented Nov 1, 2023

Ugh. I think this might not be a bug, just an artifact of what happens when SetGCPercent(-1) is called. It sets the GC percent goal to defaultHeapMinimum*uint64(-1)/100. The heap goal calculation may then subtract some relatively small number from this, hence why it waffles a little.

I've always disliked this logic. Perhaps it's time to finally fix it.

This also made me realize we definitely do not emit enough HeapGoal events. We only emit one at the start of the trace and when SetGCPercent or SetMemoryLimit is called, AFAICT. We should be emitting one at least once per GC cycle.

@mknyszek
Copy link
Contributor

mknyszek commented Nov 1, 2023

Actually, how should we represent setting GOGC=off in the trace viewer? Just picking a high number doesn't seem quite right because they both make the graph look weird. I guess ideally the graph would just not have any data in that region, so maybe that means it should be zero?

@mknyszek mknyszek added this to the Go1.22 milestone Nov 1, 2023
@mknyszek mknyszek self-assigned this Nov 1, 2023
@felixge
Copy link
Contributor Author

felixge commented Nov 4, 2023

Ah, I didn't realize the encoding/json tests are calling SetGCPercent(-1).

I think zero is a good value for the reason you mentioned. And it also works out nicely with the current cmd/trace code. So +1 to zero.

@mknyszek mknyszek modified the milestones: Go1.22, Go1.23 Nov 28, 2023
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.
Projects
Go Compiler / Runtime
Status: In Progress
Milestone
Go1.23
Development

No branches or pull requests
3 participants
@felixge @mknyszek @gopherbot