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

Jump to bottom

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

Closed
SunRunAway opened this issue Jul 5, 2019 · 11 comments
Closed

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

SunRunAway opened this issue Jul 5, 2019 · 11 comments
Labels
FrozenDueToAge NeedsDecision Feedback is required from experts, contributors, and/or the community before a change can be made.
Milestone
Backlog

Comments

@SunRunAway
Copy link

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
Copy link
Member

ALTree commented Jul 6, 2019

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

@ALTree ALTree added the NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one. label Jul 6, 2019
@ALTree ALTree added this to the Go1.14 milestone Jul 6, 2019
@mknyszek
Copy link
Contributor

mknyszek commented Jul 8, 2019

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
Copy link
Contributor

mknyszek commented Jul 8, 2019

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

@mknyszek mknyszek self-assigned this Jul 8, 2019
@mknyszek mknyszek added the NeedsDecision Feedback is required from experts, contributors, and/or the community before a change can be made. label Jul 8, 2019
@gopherbot gopherbot removed the NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one. label Jul 8, 2019
@mknyszek mknyszek modified the milestones: Go1.14, Go1.13 Jul 8, 2019
@mknyszek
Copy link
Contributor

mknyszek commented Jul 8, 2019

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.

@andybons andybons modified the milestones: Go1.13, Go1.14 Jul 8, 2019
@SunRunAway
Copy link
Author

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

@aclements
Copy link
Member

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

@gopherbot
Copy link

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

@howardjohn
Copy link
Contributor

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

@howardjohn howardjohn mentioned this issue Sep 4, 2019
Closed
16 tasks
@rsc rsc modified the milestones: Go1.14, Backlog Oct 9, 2019
@rhysh
Copy link
Contributor

rhysh commented Oct 29, 2019

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
Copy link

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
Copy link

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

@mknyszek mknyszek mentioned this issue Jan 3, 2020
Closed
@golang golang locked and limited conversation to collaborators Jan 8, 2021
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Assignees
No one assigned
Labels
FrozenDueToAge NeedsDecision Feedback is required from experts, contributors, and/or the community before a change can be made.
Projects
None yet
Milestone
Backlog
Development

No branches or pull requests
10 participants
@rsc @rhysh @austinmills @andybons @howardjohn @SunRunAway @mknyszek @aclements @ALTree @gopherbot