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: 1.13.5 continuous CPU consumption with memory balast #36374

Closed
pmalekn opened this issue Jan 3, 2020 · 7 comments
Closed

runtime: 1.13.5 continuous CPU consumption with memory balast #36374

pmalekn opened this issue Jan 3, 2020 · 7 comments
Milestone

Comments

@pmalekn
Copy link

@pmalekn pmalekn commented Jan 3, 2020

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

$ go version
go version go1.13.5 darwin/amd64

Does this issue reproduce with the latest release?

Yes (1.13.5)

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

go env Output
$ go env
GO111MODULE=""
GOARCH="amd64"
GOBIN=""
GOCACHE="/Users/pmalek/Library/Caches/go-build"
GOENV="/Users/pmalek/Library/Application Support/go/env"
GOEXE=""
GOFLAGS=""
GOHOSTARCH="amd64"
GOHOSTOS="darwin"
GONOPROXY=""
GONOSUMDB=""
GOOS="darwin"
GOPATH="/Users/pmalek/.gvm/pkgsets/go1.13.5/global"
GOPRIVATE=""
GOPROXY="https://proxy.golang.org,direct"
GOROOT="/Users/pmalek/.gvm/gos/go1.13.5"
GOSUMDB="sum.golang.org"
GOTMPDIR=""
GOTOOLDIR="/Users/pmalek/.gvm/gos/go1.13.5/pkg/tool/darwin_amd64"
GCCGO="gccgo"
AR="ar"
CC="clang"
CXX="clang++"
CGO_ENABLED="1"
GOMOD=""
CGO_CFLAGS="-g -O2"
CGO_CPPFLAGS=""
CGO_CXXFLAGS="-g -O2"
CGO_FFLAGS="-g -O2"
CGO_LDFLAGS="-g -O2"
PKG_CONFIG="pkg-config"
GOGCCFLAGS="-fPIC -m64 -pthread -fno-caret-diagnostics -Qunused-arguments -fmessage-length=0 -fdebug-prefix-map=/var/folders/zy/lzyp__pd7vx6762s5jcgkkl80000gn/T/go-build447181729=/tmp/go-build -gno-record-gcc-switches -fno-common"

What did you do?

Run the following snippet

package main

import "time"

func main() {
	balast := make([]byte, 10<<30) // 10G
	_ = balast
	time.Sleep(time.Hour)
}

under go1.13.5 and go1.12.14

What did you expect to see?

No CPU being consumed on both versions

What did you see instead?

Continuous CPU consumption on go1.13.5.

CONTAINER ID        NAME                CPU %               MEM USAGE / LIMIT     MEM %               NET I/O             BLOCK I/O           PIDS
95ae3972c485        1.12.14             0.00%               332.1MiB / 7.294GiB   4.45%               758B / 0B           0B / 0B             5
e2b0b1654941        1.13.5              30.10%              332.2MiB / 7.294GiB   4.45%               578B / 0B           0B / 0B             6

after adding GODEBUG=gctrace=1 one can observe scavenger prints:

scvg: 0 MB released
scvg: inuse: 0, idle: 10303, sys: 10303, released: 108, consumed: 10195 (MB)
scvg: 0 MB released
scvg: inuse: 0, idle: 10303, sys: 10303, released: 108, consumed: 10194 (MB)
scvg: 0 MB released
scvg: inuse: 0, idle: 10303, sys: 10303, released: 108, consumed: 10194 (MB)
scvg: 0 MB released
@ianlancetaylor ianlancetaylor changed the title 1.13.5 continuous CPU consumption with memory balast runtime: 1.13.5 continuous CPU consumption with memory balast Jan 3, 2020
@ianlancetaylor

This comment has been minimized.

Copy link
Contributor

@ianlancetaylor ianlancetaylor commented Jan 3, 2020

@ianlancetaylor ianlancetaylor added this to the Go1.15 milestone Jan 3, 2020
@mknyszek

This comment has been minimized.

Copy link
Contributor

@mknyszek mknyszek commented Jan 3, 2020

That 10 GiB ballast is freed (notice that inuse is 0) because the compiler determines the ballast value is no longer live before the sleep. The scavenger is trying to reclaim the space, so that object is not actually a ballast because it gets garbage collected. This is all WAI.

It takes a while to return 10 GiB of memory back to the OS (pacing is 1 page per ms, in this case 4 KiB per ms => ~43 minutes) if the system doesn't support transparent huge pages, which darwin does not. I'm not sure why you're seeing 30% CPU utilization specifically, but when running any non-trivial application we haven't seen additional costs associated with the scavenger on that order of magnitude (in fact, it's paced to try to use about 1% of 1 CPU, which is consistent with performance regressions I've encountered). I suspect the increased CPU utilization is actually coming from the fact that scavenging prints very often in gctrace which is a known issue we need to fix (#32952).

If you modify the program to instead be:

package main

import "time"

var ballast []byte

func main() {
	ballast = make([]byte, 10<<30)
	time.Sleep(time.Hour)
}

you'll notice that with GODEBUG=gctrace=1 that the scavenger is no longer doing any work, since the ballast never dies. Alternatively, you could add a runtime.KeepAlive after the time.Sleep to achieve a similar effect.

@mknyszek mknyszek closed this Jan 3, 2020
@pmalekn

This comment has been minimized.

Copy link
Author

@pmalekn pmalekn commented Jan 3, 2020

@mknyszek ok thanks

As a side note I have to mention that running without GODEBUG=gctrace=1 consumes similar amount of cpu

@mknyszek

This comment has been minimized.

Copy link
Contributor

@mknyszek mknyszek commented Jan 3, 2020

@pmalekn Interesting. I notice that you're running this inside docker (and maybe a linux image?)? It may be that docker's indirection makes the syscalls to return memory to the OS much more expensive, since running a linux image in docker on darwin spins up a VM.

If I run it directly on darwin, I instead see utilization on the order of 6-7%. Still higher than expected but not as bad as 30%.

@mknyszek

This comment has been minimized.

Copy link
Contributor

@mknyszek mknyszek commented Jan 3, 2020

@pmalekn I forgot to finish my last comment.

On a separate note, in Go 1.14, the scavenger is now paced according to how long each scavenging operation actually took, so it's more likely to be close to 1%. Trying this out with Go 1.14 and the scavenger actually... halts. Sigh. This is related to #35788. But anyway the high utilization you're seeing is gone.

@pmalekn

This comment has been minimized.

Copy link
Author

@pmalekn pmalekn commented Jan 3, 2020

@mknyszek I can confirm that running on MacOS it seems to be fixed.

Without GODEBUG=gctrace=1.

USER               PID  %CPU %MEM      VSZ    RSS   TT  STAT STARTED      TIME COMMAND
pmalek           12496   5.8  2.0 15198892 340336 s007  S+    8:38PM   0:03.51 ./go1.13.5
pmalek           12529   0.0  2.0 15799180 340932 s006  S+    8:38PM   0:00.20 ./go1.14beta1
pmalek           12463   0.0  2.0 15197640 340324 s002  S+    8:38PM   0:00.15 ./go1.12.14

and with GODEBUG=gctrace=1

USER               PID  %CPU %MEM      VSZ    RSS   TT  STAT STARTED      TIME COMMAND
pmalek           12960   8.5  2.0 15199660 340348 s007  R+    8:41PM   0:01.34 ./go1.13.5
pmalek           12976   0.0  2.0 15799436 340856 s006  S+    8:41PM   0:00.20 ./go1.14beta1
pmalek           12944   0.0  2.0 15196616 340324 s002  S+    8:41PM   0:00.14 ./go1.12.14
@pmalekn

This comment has been minimized.

Copy link
Author

@pmalekn pmalekn commented Jan 3, 2020

Same inside the container:

CONTAINER ID        NAME                CPU %               MEM USAGE / LIMIT     MEM %               NET I/O             BLOCK I/O           PIDS
04645753d3a0        go1.12.14           0.00%               332.1MiB / 7.294GiB   4.45%               898B / 0B           0B / 0B             5
34a8ec402dd9        go1.13.5            30.47%              332.2MiB / 7.294GiB   4.45%               718B / 0B           0B / 0B             6
54ecde1bf6bd        go1.14beta1         0.00%               332.5MiB / 7.294GiB   4.45%               648B / 0B           0B / 0B             5

and inside the container with GODEBUG=gctrace=1

CONTAINER ID        NAME                CPU %               MEM USAGE / LIMIT     MEM %               NET I/O             BLOCK I/O           PIDS
8f9184764bf7        go1.13.5            27.75%              332.1MiB / 7.294GiB   4.45%               828B / 0B           0B / 0B             6
9ee0b6809517        go1.12.14           0.00%               332.1MiB / 7.294GiB   4.45%               738B / 0B           0B / 0B             5
e5eaa5bb2d88        go1.14beta1         0.00%               332.5MiB / 7.294GiB   4.45%               578B / 0B           0B / 0B             5
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Projects
None yet
Linked pull requests

Successfully merging a pull request may close this issue.

None yet
3 participants
You can’t perform that action at this time.