runtime: scvg information is spamming with GODEBUG=gctrace=1

[SunRunAway]

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

$ go version
go version go1.13beta1 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="on"
GOARCH="amd64"
GOBIN=""
GOCACHE="/Users/sunrunaway/Library/Caches/go-build"
GOENV="/Users/sunrunaway/Library/Application Support/go/env"
GOEXE=""
GOFLAGS=""
GOHOSTARCH="amd64"
GOHOSTOS="darwin"
GONOPROXY=""
GONOSUMDB=""
GOOS="darwin"
GOPATH="/Users/sunrunaway/Code/gopath"
GOPRIVATE=""
GOPROXY="https://goproxy.io"
GOROOT="/Users/sunrunaway/myapp/go1.13beta1"
GOSUMDB="sum.golang.org"
GOTMPDIR=""
GOTOOLDIR="/Users/sunrunaway/myapp/go1.13beta1/pkg/tool/darwin_amd64"
GCCGO="gccgo"
AR="ar"
CC="clang"
CXX="clang++"
CGO_ENABLED="1"
GOMOD="/dev/null"
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/b7/wthf4xmj5qg27h5tsyxtd8240000gn/T/go-build343541563=/tmp/go-build -gno-record-gcc-switches -fno-common"

What did you do?

package main

import "time"

func a() {
	a := make([]byte, 10000000)
	_ = a
}
func main() {
	a()
	time.Sleep(100e9)
}

GODEBUG=gctrace=1 /Users/sunrunaway/myapp/go1.13beta1/bin/go run 1.go

What did you expect to see?

What did you see instead?

scvg information is printing Infinitely.

scvg: 0 MB released
scvg: inuse: 0, idle: 63, sys: 63, released: 54, consumed: 9 (MB)
scvg: 0 MB released
scvg: inuse: 0, idle: 63, sys: 63, released: 54, consumed: 9 (MB)
scvg: 0 MB released
scvg: inuse: 0, idle: 63, sys: 63, released: 54, consumed: 9 (MB)
scvg: 0 MB released
scvg: inuse: 0, idle: 63, sys: 63, released: 54, consumed: 9 (MB)
scvg: 0 MB released
scvg: inuse: 0, idle: 63, sys: 63, released: 54, consumed: 9 (MB)
scvg: 0 MB released
scvg: inuse: 0, idle: 63, sys: 63, released: 54, consumed: 9 (MB)
scvg: 0 MB released
scvg: inuse: 0, idle: 63, sys: 63, released: 54, consumed: 8 (MB)
scvg: 0 MB released
scvg: inuse: 0, idle: 63, sys: 63, released: 54, consumed: 8 (MB)

[ALTree]

cc @mknyszek @aclements to see if this is expected/intentional.

[mknyszek]

I intentionally added this for Go 1.13 to reflect the change in policy but retain the original semantics. The reason you see it print so often is because it prints every time the scavenger scavenges. I figured that this was generally useful information to have, since the scavenger's pacing information is updated with each GC cycle, but you're right that it's kind of a lot for such a small program.

I can move it behind gctrace=2 or something, or summarize it (don't print every time, just at most once per GC cycle or something). I'm open to suggestions.

Also: you mention that it's scavenging infinitely, but I can't reproduce that. It's paced to finish in about 2.5 seconds on darwin/amd64 and I can confirm that it does just about that on my machine. Which version of MacOS are you running? I'm on 10.14.5.

[mknyszek]

Oh and for more information on what changed with scavenging, please see #30333.

[mknyszek]

Setting Go 1.13 milestone because this could conceivably be fixed before the release; it's a very low-risk fix and would make debugging a bit easier. Just needs a decision on what degree of logging is appropriate.

[SunRunAway]

Sorry for my incorrect information before, it's finished in about 2.5 seconds on my laptop too.

[aclements]

@mknyszek, would it make sense to rate limit the scvg debug lines and only print out a "cumulative" line every, say, 30 seconds?

[gopherbot]

Change https://golang.org/cl/186924 mentions this issue: runtime: limit scvg debug prints to once per 30 seconds

[howardjohn]

Is there anyway to turn this off in 1.13, given cl/186924 doesn't appear to have been added to go1.13? This is incredibly spammy for us, we will need to disable GODEBUG if not

[rhysh]

To give another perspective on the user impact of this: In the program I'm working with today, I get 134 to 138 "scvg" lines following each "gc N" line. The lines I want to see (showing the timing/parameters/results of garbage collections) end up hidden in the backscroll.

When I'm using a shell, I can add a 2> >(grep -v ^scvg) suffix to go along with the GODEBUG=gctrace=1 prefix. But I often set that variable in service run scripts to give a little bit more context in an application's logs, and now have quite a bit of extra context.

Printing a line or two of summary, either after each GC run or every 30 seconds, seems like a good compromise.

[austinmills]

I ran into this just today. In golang 1.12 we ran with gctrace on so that we can track trends in GC from the logfiles. In our large-heap application that we were testing with 1.13, of a 2.6Gb log file that was created, 3.2Mb were NOT lines from scavenging. It would be very helpful to have the ability to reduce that.

[gopherbot]

Change https://golang.org/cl/212640 mentions this issue: runtime: add scavtrace debug flag and remove scavenge info from gctrace