runtime: gctrace and gcpacer trace report different cpu usage

[MikeMitchellWebDev]

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

$ go version
go version go1.22.0 darwin/amd64

Does this issue reproduce with the latest release?

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

go env Output

$ go env
GO111MODULE=''
GOARCH='amd64'
GOBIN=''
GOCACHE='/Users/mm/Library/Caches/go-build'
GOENV='/Users/mm/Library/Application Support/go/env'
GOEXE=''
GOEXPERIMENT=''
GOFLAGS=''
GOHOSTARCH='amd64'
GOHOSTOS='darwin'
GOINSECURE=''
GOMODCACHE='/Users/mm/go/pkg/mod'
GONOPROXY=''
GONOSUMDB=''
GOOS='darwin'
GOPATH='/Users/mm/go'
GOPRIVATE=''
GOPROXY='https://proxy.golang.org,direct'
GOROOT='/usr/local/go'
GOSUMDB='sum.golang.org'
GOTMPDIR=''
GOTOOLCHAIN='auto'
GOTOOLDIR='/usr/local/go/pkg/tool/darwin_amd64'
GOVCS=''
GOVERSION='go1.22.0'
GCCGO='gccgo'
GOAMD64='v1'
AR='ar'
CC='/usr/bin/clang'
CXX='clang++'
CGO_ENABLED='1'
GOMOD='/Users/mm/go/src/github.com/MikeMitchellWebDev/gc-2024-front/go.mod'
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 x86_64 -m64 -pthread -fno-caret-diagnostics -Qunused-arguments -fmessage-length=0 -ffile-prefix-map=/var/folders/5y/wtzzmjlj5v52pg7wr8ptbg_m0000gp/T/go-build304339508=/tmp/go-build -gno-record-gcc-switches -fno-common'
uname -v: Darwin Kernel Version 20.6.0: Thu Jul  6 22:12:47 PDT 2023; root:xnu-7195.141.49.702.12~1/RELEASE_X86_64
ProductName:	macOS
ProductVersion:	11.7.10
BuildVersion:	20G1427
lldb --version: lldb-1300.0.42.3
Swift version 5.5.2-dev

What did you do?

Ran GODEBUG=gctrace=1; with GODEBUG=gcpacertrace=1 and compared the cpu % output

What did you expect to see?

cpu usage calculations between the two metrics approximately the same

What did you see instead?

Unless I am misinterpreting the data in GODEBUG=gctrace=1, gcpacertrace is reporting much higher cpu usage than gctrace

Taking gc38 as an example, I calculate cpu usage in gctrace like this. 38 shows 55 ms of wall time for the mark phase. As GOMAXPROCs is 4, the gc thinks 210 ms (55 *4) are available during the mark phase. But only 45 ms of cpu time are being used, so cpu time is about 20%.

However, the pacer in the next line reports cpu usage of 51%.

In gc39, there is 86 ms of wall time for the mark phase. 344 ms are available, and 86ms of cpu time are used so 25% is used.

Summary, in between gcs 38 and 39, which report 20% and 25% cpu time respectively, the pacer reports 51% usage.

gc 38 @35.742s 0%: 0.10+55+0.085 ms clock, 0.40+25/45/71+0.34 ms cpu, 971->972->970 MB, 972 MB goal, 0 MB stacks, 0 MB globals, 4 P
pacer: assist ratio=+4.395162e+001 (scan 15 MB in 971->972 MB) workers=1++0.000000e+000
pacer: 51% CPU (25 exp.) for 16158064+18488+488544 B work (16658104 B exp.) in 1018988056 B -> 1019364368 B (∆goal -105555, cons/mark +8.123204e-002)
gc 39 @35.820s 0%: 0.10+86+0.14 ms clock, 0.42+91/86/91+0.59 ms cpu, 971->972->970 MB, 972 MB goal, 0 MB stacks, 0 MB globals, 4 P
pacer: assist ratio=+3.441907e+001 (scan 15 MB in 971->972 MB) workers=1++0.000000e+000

[gabyhelp]

Similar Issues

• runtime: heap target increased by significantly more than GOGC should allow #67592
• runtime: change in pacer behavior on ppc64le in go1.20 #66600
• cmd/trace: the "GC pause" column in the user-defined regions table doesn't make sense #62443
• runtime: concurrent GC starves mutator and netpoller #16432
• runtime: incorrect forced information in gctrace #52515

_{(Emoji vote if this was helpful or unhelpful; more detailed feedback welcome in this discussion.)}

[mknyszek]

It's a bit confusing, but the output is correct. This line:

pacer: 51% CPU (25 exp.) for 16158064+18488+488544 B work (16658104 B exp.) in 1018988056 B -> 1019364368 B (∆goal -105555, cons/mark +8.123204e-002)

Refers to this line:

gc 39 @35.820s 0%: 0.10+86+0.14 ms clock, 0.42+91/86/91+0.59 ms cpu, 971->972->970 MB, 972 MB goal, 0 MB stacks, 0 MB globals, 4 P

86 ms wall clock, 86 ms dedicated GC CPU, 91 ms GC assists. (86 + 91 cpu-ms) / (86 ms * 4 cpu) = 51.4%

The gcpacertrace output is really an expert tool, so it's not designed with most users in mind. It has some rough edges if you're not already familiar with the codebase. It's a debugging tool for the pacer, really. gctrace is a bit more friendly, but still less user-focused than, say, CPU profiling.

Closing, since I don't think there's anything actionable. If you think something should change about the output, feel free to send a CL and we can hash it out there. Thanks.