runtime/trace: Bad HeapGoal/NextGC Metric

[felixge]

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

(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

[mknyszek]

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]

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?

[felixge]

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.