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: 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

Comments

@Anteoy
Copy link

@Anteoy 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

This comment has been minimized.

Copy link
Author

@Anteoy 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

This comment has been minimized.

Copy link
Author

@Anteoy 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

This comment has been minimized.

Copy link
Author

@Anteoy 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

This comment has been minimized.

Copy link
Author

@Anteoy Anteoy commented Mar 9, 2020

 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

This comment has been minimized.

Copy link

@DisposaBoy DisposaBoy 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.

@Anteoy

This comment has been minimized.

Copy link
Author

@Anteoy Anteoy commented Mar 9, 2020

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

@Anteoy

This comment has been minimized.

Copy link
Author

@Anteoy 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.

@gopherbot

This comment has been minimized.

Copy link

@gopherbot gopherbot commented Apr 9, 2020

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.)

@gopherbot gopherbot closed this Apr 9, 2020
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
4 participants
You can’t perform that action at this time.