Skip to content

runtime: long GC STW pauses (≥80ms) #19378

@obeattie

Description

@obeattie

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

go1.8 linux/amd64

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

GOBIN=""
GOEXE=""
GOHOSTARCH="amd64"
GOHOSTOS="linux"
GOOS="linux"
GOPATH="/go"
GORACE=""
GOROOT="/usr/local/go"
GOTOOLDIR="/usr/local/go/pkg/tool/linux_amd64"
GCCGO="gccgo"
CC="gcc"
GOGCCFLAGS="-fPIC -m64 -pthread -fmessage-length=0"
CXX="g++"
CGO_ENABLED="1"
PKG_CONFIG="pkg-config"
CGO_CFLAGS="-g -O2"
CGO_CPPFLAGS=""
CGO_CXXFLAGS="-g -O2"
CGO_FFLAGS="-g -O2"
CGO_LDFLAGS="-g -O2"

The host where the application is running does not have go (just the compiled binary), so this is actually from the host which built it.

What did you do?

Following from a discussion on golang-nuts, I was advised to create an issue.

In our applications we are regularly seeing GC pauses of ≥80ms, even for extremely simple programs with light workloads. These long pauses seem to be sporadic; most GC's take fractions of a millisecond as I would expect, but in some runs it seems that the sweep termination phase (which I understand is STW) is taking a very long time. Given these applications are network RPC servers, pauses like these are extremely problematic for tail latencies.

I have captured a runtime/trace here showing one such pause, along with the output of GODEBUG=gctrace=1 below for the same period. The long GC is at 451,008.477 ms in the trace and corresponds to gc 12 below.

I'd really appreciate any help investigating what could cause this.

GC forced
gc 9 @1111.485s 0%: 79+1.8+0.037 ms clock, 159+0.60/1.7/0.85+0.074 ms cpu, 3->3->1 MB, 4 MB goal, 2 P
scvg7: 0 MB released
scvg7: inuse: 4, idle: 1, sys: 6, released: 0, consumed: 5 (MB)
GC forced
gc 10 @1232.068s 0%: 0.032+98+0.30 ms clock, 0.065+0/97/1.9+0.60 ms cpu, 2->2->1 MB, 4 MB goal, 2 P
scvg8: 0 MB released
scvg8: inuse: 4, idle: 1, sys: 6, released: 1, consumed: 4 (MB)
GC forced
gc 11 @1352.178s 0%: 0.037+5.7+0.021 ms clock, 0.074+0/5.6/0+0.043 ms cpu, 2->2->1 MB, 4 MB goal, 2 P
GC forced
gc 12 @1472.566s 0%: 98+2.7+0.025 ms clock, 197+0/2.7/1.9+0.051 ms cpu, 3->3->1 MB, 4 MB goal, 2 P
scvg9: inuse: 4, idle: 1, sys: 6, released: 1, consumed: 4 (MB)
GC forced
gc 13 @1593.066s 0%: 0.029+105+0.030 ms clock, 0.058+0/102/6.0+0.061 ms cpu, 3->3->1 MB, 4 MB goal, 2 P
scvg10: 0 MB released
scvg10: inuse: 4, idle: 1, sys: 6, released: 0, consumed: 5 (MB)
GC forced
gc 14 @1713.512s 0%: 0.092+55+0.051 ms clock, 0.18+53/53/1.7+0.10 ms cpu, 3->3->1 MB, 4 MB goal, 2 P
scvg11: inuse: 4, idle: 1, sys: 6, released: 0, consumed: 5 (MB)
GC forced
gc 15 @1834.066s 0%: 0.020+2.1+0.019 ms clock, 0.041+0/2.0/1.4+0.039 ms cpu, 2->2->1 MB, 4 MB goal, 2 P```

Metadata

Metadata

Assignees

No one assigned

    Labels

    FrozenDueToAgeNeedsInvestigationSomeone must examine and confirm this is a valid issue and not a duplicate of an existing one.

    Type

    No type

    Projects

    No projects

    Milestone

    Relationships

    None yet

    Development

    No branches or pull requests

    Issue actions