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: gc: fatal issue: stopTheWorldWithSema cost 158 seconds #37754

Closed
Anteoy opened this issue Mar 9, 2020 · 8 comments
Closed

runtime: gc: fatal issue: stopTheWorldWithSema cost 158 seconds #37754

Anteoy opened this issue Mar 9, 2020 · 8 comments
Labels
FrozenDueToAge WaitingForInfo Issue is not actionable because of missing required information, which needs to be provided.

Comments

@Anteoy
Copy link

Anteoy commented Mar 9, 2020

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

$ go version
go version go1.12.8 linux/amd64

Does this issue reproduce with the latest release?

uncertain

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

go env Output
$ go env
GOARCH="amd64"
GOBIN="/home/zhoudazhuang/gobin/"
GOCACHE="/home/zhoudazhuang/.cache/go-build"
GOEXE=""
GOFLAGS=""
GOHOSTARCH="amd64"
GOHOSTOS="linux"
GOOS="linux"
GOPATH="/home/zhoudazhuang/db11/jm/pro"
GOPROXY=""
GORACE=""
GOROOT="/home/zhoudazhuang/usr/local/go1.12.8/go"
GOTMPDIR=""
GOTOOLDIR="/home/zhoudazhuang/usr/local/go1.12.8/go/pkg/tool/linux_amd64"
GCCGO="gccgo"
CC="gcc"
CXX="g++"
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 -fmessage-length=0 -fdebug-prefix-map=/tmp/go-build045404538=/tmp/go-build -gno-record-gcc-switches"

What did you do?

Occasional gc issues with my online service
I added the code in mgo.go

        now1 := nanotime()
	systemstack(stopTheWorldWithSema)
	now2 := nanotime()
	println("stopTheWorldWithSema, cost: ", now2 - now1)

So it can print the time it cost. I got the log:

SCHED 1830050412ms: gomaxprocs=48 idleprocs=0 threads=144 spinningthreads=0 idlethreads=137 runqueue=154445 [0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0
 0 0 0 0 0 0]
stopTheWorldWithSema, cost:  158588882087

What did you expect to see?

this func cost too long to my service during gc.

What did you see instead?

gc log:

gc 51606 @1829883.099s 2%: 4.8+856+1.3 ms clock, 233+0/39785/0+65 ms cpu, 2593->2608->1325 MB, 2659 MB goal, 48 P
gc bg mark start workers :  0
gc 51607 @1829891.917s 2%: 158596+2074+0.45 ms clock, 7612622+0/16431/0+21 ms cpu, 5765->6516->6133 MB, 5766 MB goal, 48 P

I want to know how this happened, could anyone have any suggestions ?
@Anteoy
Copy link
Author

Anteoy commented Mar 9, 2020

during this gc, no normal business log except schedule log:

SCHED 1829936070ms: gomaxprocs=48 idleprocs=0 threads=144 spinningthreads=0 idlethreads=137 runqueue=56977 [0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0]
SCHED 1829936171ms: gomaxprocs=48 idleprocs=0 threads=144 spinningthreads=0 idlethreads=137 runqueue=57101 [0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0]
SCHED 1829936272ms: gomaxprocs=48 idleprocs=0 threads=144 spinningthreads=0 idlethreads=137 runqueue=57241 [0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0]
SCHED 1829936373ms: gomaxprocs=48 idleprocs=0 threads=144 spinningthreads=0 idlethreads=137 runqueue=57361 [0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0]

the numbers of runqueue increase .

@Anteoy
Copy link
Author

Anteoy commented Mar 9, 2020

and a scvg log:

SCHED 1829910351ms: gomaxprocs=48 idleprocs=0 threads=144 spinningthreads=0 idlethreads=137 runqueue=23752 [0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 
0 0 0 0 0 0]
scvg12198: 39 MB released
scvg12198: inuse: 6643, idle: 7187, sys: 13830, released: 6600, consumed: 7230 (MB)
SCHED 1829913113ms: gomaxprocs=48 idleprocs=0 threads=144 spinningthreads=0 idlethreads=137 runqueue=23883 [0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 
0 0 0 0 0 0]

@Anteoy
Copy link
Author

Anteoy commented Mar 9, 2020

I suspect that a certain gouroutine is constantly creating new goroutines and is unable to reach the safe point. STW cannot be completed.

@Anteoy
Copy link
Author

Anteoy commented Mar 9, 2020 •
edited 

 0 0 0 0 0 0]
SCHED 1830050210ms: gomaxprocs=48 idleprocs=0 threads=144 spinningthreads=0 idlethreads=137 runqueue=154425 [0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0
 0 0 0 0 0 0]
SCHED 1830050311ms: gomaxprocs=48 idleprocs=0 threads=144 spinningthreads=0 idlethreads=137 runqueue=154435 [0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0
 0 0 0 0 0 0]
SCHED 1830050412ms: gomaxprocs=48 idleprocs=0 threads=144 spinningthreads=0 idlethreads=137 runqueue=154445 [0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0
 0 0 0 0 0 0]
stopTheWorldWithSema, cost:  158588882087
finishsweep_m, cost:  26941
SCHED 1830050512ms: gomaxprocs=48 idleprocs=0 threads=144 spinningthreads=0 idlethreads=138 runqueue=154458 [0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0clearp
ools, cost:  7324163

at last , the idle thread from 'idlethreads=137' to 'idlethreads=138', then it finished.

@DisposaBoy
Copy link

I'm no expert or stakeholder, but I noticed you're using go1.12...

In go1.14 goroutines are now asynchronously pre-emptible: https://golang.org/doc/go1.14#runtime so maybe it's worth upgrading.
IIUC, go1.12 is also no longer supported anyway.

@Anteoy
Copy link
Author

Anteoy commented Mar 9, 2020

Can't find the relevant problem point, any suggestions?

@Anteoy
Copy link
Author

Anteoy commented Mar 9, 2020

I'm no expert or stakeholder, but I noticed you're using go1.12...

In go1.14 goroutines are now asynchronously pre-emptible: https://golang.org/doc/go1.14#runtime so maybe it's worth upgrading.
IIUC, go1.12 is also no longer supported anyway.

Thanks, I will try it.

@dmitshur dmitshur added the WaitingForInfo Issue is not actionable because of missing required information, which needs to be provided. label Mar 9, 2020
@gopherbot
Copy link

Timed out in state WaitingForInfo. Closing.

(I am just a bot, though. Please speak up if this is a mistake or you have the requested information.)

@golang golang locked and limited conversation to collaborators Apr 9, 2021
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Assignees
No one assigned
Labels
FrozenDueToAge WaitingForInfo Issue is not actionable because of missing required information, which needs to be provided.
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
4 participants
@DisposaBoy @dmitshur @gopherbot @Anteoy