I am observing pause failures in an application and it appears to me that
I’m seeing it take from 5 to 28 seconds or more for the StopTheWorld to
take effect for GC.
In all likelihood the problem lies in the application, but before I start
changing it or attempting to tune GC, I’d like to understand what’s
happening. I’d appreciate any assistance in decoding what I’m seeing in
schedtrace output.
Details are below but here are 4 consecutive samples at 1 second
intervals. For brevity I’ve pruned out lines with ‘M.* p=-1’ and ‘G.*
status=[34]’ (syscall or waiting in runtime).
The first two are after we start the part of the workload that triggers the
failure and before the expected health check arrives. The second two are
as we try to StopTheWorld, which holds off the health check.
SCHED 674246ms: gomaxprocs=4 idleprocs=4 threads=14 spinningthreads=0
idlethreads=4 runqueue=0 gcwaiting=0 nmidlelocked=1 stopwait=0 sysmonwait=0
P0: status=0 schedtick=7112 syscalltick=1916 m=-1 runqsize=0 gfreecnt=6
P1: status=0 schedtick=3545 syscalltick=1452 m=-1 runqsize=0 gfreecnt=8
P2: status=0 schedtick=4549 syscalltick=1465 m=-1 runqsize=0 gfreecnt=7
P3: status=0 schedtick=1616 syscalltick=1223 m=-1 runqsize=0 gfreecnt=0
M7: p=1 curg=301 mallocing=0 throwing=0 preemptoff= locks=0 dying=0
helpgc=0 spinning=false blocked=false lockedg=-1
^^^ I suspect G301/M7 was in transition when sampled without locks or in a
state I don’t understand. For reference, it reported:
G301: status=3(IO wait) m=7 lockedm=-1
SCHED 675256ms: gomaxprocs=4 idleprocs=2 threads=14 spinningthreads=0
idlethreads=3 runqueue=0 gcwaiting=0 nmidlelocked=1 stopwait=0 sysmonwait=0
P0: status=0 schedtick=7118 syscalltick=1921 m=-1 runqsize=0 gfreecnt=6
P1: status=1 schedtick=3548 syscalltick=2656 m=7 runqsize=0 gfreecnt=8
P2: status=1 schedtick=4551 syscalltick=1465 m=2 runqsize=0 gfreecnt=7
P3: status=0 schedtick=1620 syscalltick=1225 m=-1 runqsize=0 gfreecnt=0
M7: p=1 curg=301 mallocing=1 throwing=0 preemptoff= locks=2 dying=0
helpgc=0 spinning=false blocked=false lockedg=-1
M2: p=2 curg=7 mallocing=0 throwing=0 preemptoff= locks=1 dying=0
helpgc=0 spinning=false blocked=true lockedg=-1
G7: status=2(GC worker (idle)) m=2 lockedm=-1
G301: status=2(IO wait) m=7 lockedm=-1
^^^ G301 is now running on M7/P1. M7 is marked as mallocing=1, locks=2
^^^ G7 is a GC worker that is now running on M2/P2. M2 has locks=1
>>> Health check log expected here
SCHED 676264ms: gomaxprocs=4 idleprocs=1 threads=14 spinningthreads=0
idlethreads=2 runqueue=0 gcwaiting=0 nmidlelocked=1 stopwait=0 sysmonwait=0
P0: status=1 schedtick=7120 syscalltick=1927 m=6 runqsize=0 gfreecnt=5
P1: status=1 schedtick=3548 syscalltick=2656 m=7 runqsize=0 gfreecnt=8
P2: status=1 schedtick=4551 syscalltick=1465 m=2 runqsize=0 gfreecnt=7
P3: status=0 schedtick=1622 syscalltick=1229 m=-1 runqsize=0 gfreecnt=0
M7: p=1 curg=301 mallocing=1 throwing=0 preemptoff= locks=2 dying=0
helpgc=0 spinning=false blocked=false lockedg=-1
M6: p=0 curg=188 mallocing=1 throwing=0 preemptoff= locks=2 dying=0
helpgc=0 spinning=false blocked=false lockedg=-1
M2: p=2 curg=7 mallocing=0 throwing=0 preemptoff= locks=1 dying=0
helpgc=0 spinning=false blocked=true lockedg=-1
G7: status=2(GC worker (idle)) m=2 lockedm=-1
G301: status=2(IO wait) m=7 lockedm=-1
G188: status=2() m=6 lockedm=-1
^^^ total of 3 P in use, 1 GC worker, 2 mallocing
SCHED 677271ms: gomaxprocs=4 idleprocs=0 threads=14 spinningthreads=0
idlethreads=3 runqueue=1 gcwaiting=1 nmidlelocked=1 stopwait=1 sysmonwait=0
P0: status=1 schedtick=7120 syscalltick=1927 m=6 runqsize=0 gfreecnt=5
P1: status=3 schedtick=3550 syscalltick=2656 m=7 runqsize=0 gfreecnt=8
P2: status=3 schedtick=4552 syscalltick=1465 m=-1 runqsize=0 gfreecnt=7
P3: status=3 schedtick=1622 syscalltick=1229 m=-1 runqsize=0 gfreecnt=0
M7: p=1 curg=6 mallocing=0 throwing=0 preemptoff=gcing locks=0 dying=0
helpgc=0 spinning=false blocked=true lockedg=-1
M6: p=0 curg=188 mallocing=1 throwing=0 preemptoff= locks=2 dying=0
helpgc=0 spinning=false blocked=false lockedg=-1
G6: status=2(GC worker (idle)) m=7 lockedm=-1
G301: status=1(IO wait) m=-1 lockedm=-1
G188: status=2() m=6 lockedm=-1
^^^ Someone has called stopTheWorldWithSema, either directly or via
stopTheWorld. It hasn’t returned because stopwait is > 0.
^^^. Looks like call is not likely stopTheWorld and caller is likely G6
GC worker that is running on M7/P1 (stopTheWorldSema marks its own P as
gcstop).
^^^ stopTheWorldWithSema called from gcStart and gcMarkDone is caller.
^^^ stopTheWorldWithSema is poll-waiting for preemptall() to take effect
(for P0/M6/G188 to notice preemption)
For the next 4 samples there are no changes in P* or M*.
After that we see a health check handler logged and in the sample after
that gcwaiting and stopwait are 0.
What can G188/M6/P0 be doing such that it doesn’t notice the request to
preempt itself for 5 seconds? And while having mallocing=1?
Thanks for any insights or suggestions,
Eric
=============
Details:
go version go1.11.1 linux/amd64
System: Containerized Linux (Alpine)
GOMAXPROCS=4
Container reports NumCPU=1 so GOMAXPROCS defaults to 1. Problem occurs on
both GOMAXPROCS=1 and GOMAXPROCS=4.
The application is a fairly basic Kubernetes application with an http
server that services a health check, a separate goroutine that periodically
makes an http client request to poll for work, and a pool of worker
goroutines that pick up work from a channel. The system is configured
to issue a health check every 10 seconds. Intermittently during testing
the health check fails repeatedly and the app is restarted by Kubernetes.
The test load is not particularly high— often the workers are idle and at
most 2 are active active at a time. The pause failure can be seen with
only 1 request in flight at a time.
I added a log message to the health check handler, set
GODEBUG=schedtrace=1000,scheddetail=1 and reproduced the failure. When the
system is running normally, we see 1 health check log message every 10
seconds with 10 SCHED traces in between each.
In looking at the failure I observed one instance of the health check being
serviced 5+ seconds late after which the system recovered and then a set of
late health checks where it was over 28 seconds and where Kubernetes
terminated the job.
The extract above is from the 5+ second pause. I happy to share the fuller
logs and also have runtime.MemStat dumped after the second failure. It
reports PauseTotalNs of 39.7 seconds with last 3 pauses being 5.7s, 5.2s,
and 28.6s.
========================
Even more details:
Might as well include MemStats:
memstats
"Alloc”:35820624
"TotalAlloc”:87362776
"Sys”:72284408
"Lookups”:0
"Mallocs":913917
"Frees”:732071
"HeapAlloc”:35820624
"HeapSys”:66027520
"HeapIdle”:25460736
"HeapInuse”:40566784
"HeapReleased”:0
"HeapObjects”:181846
"StackInuse”:1048576
"StackSys”:1048576
"MSpanInuse”:361000
"MSpanSys”:409600
"MCacheInuse”:6912
"MCacheSys”:16384
"BuckHashSys”:1495863
"GCSys”:2441216
"OtherSys”:845249
"NextGC”:42461456
"LastGC”:1544141699097608371
"PauseTotalNs”:39724621006
"PauseNs":[121384
3326024
3534690
525590
54645
22208743
98898
250651
37238
2034238
33731
38616
41163
35875
37798
5794188053
5265243818
28632809851]
”PauseEnd":[1544140960164525406
1544140960182034741
1544140960209848541
1544140960278986107
1544140960733914972
1544140961198224758
1544140961290430652
1544140961374230055
1544140961455867822
1544140961561961827
1544141081577752402
1544141201598823342
1544141321622343360
1544141441643055123
1544141561665242451
1544141599296615758
1544141641227906209
1544141699097608371]
"NumGC”:18
"NumForcedGC”:0
"GCCPUFraction”:0.013482378367869897
"EnableGC”:true
"DebugGC”:false
"BySize”:[
{"Size":0,"Mallocs":0,"Frees":0}
{"Size":8,"Mallocs":19587,"Frees":16601}
{"Size":16,"Mallocs":329030,"Frees":254713}
{"Size":32,"Mallocs":169516,"Frees":119550}
{"Size":48,"Mallocs":89240,"Frees":73834}
{"Size":64,"Mallocs":27676,"Frees":20629}
{"Size":80,"Mallocs":19143,"Frees":13042}
{"Size":96,"Mallocs":8042,"Frees":6076}
{"Size":112,"Mallocs":12250,"Frees":10569}
{"Size":128,"Mallocs":23168,"Frees":16902}
{"Size":144,"Mallocs":3305,"Frees":1499}
{"Size":160,"Mallocs":29309,"Frees":28151}
{"Size":176,"Mallocs":799,"Frees":325}
{"Size":192,"Mallocs":1486,"Frees":1043}
{"Size":208,"Mallocs":2884,"Frees":1687}
{"Size":224,"Mallocs":1196,"Frees":530}
{"Size":240,"Mallocs":823,"Frees":671}
{"Size":256,"Mallocs":4766,"Frees":4442}
{"Size":288,"Mallocs":31701,"Frees":30325}
{"Size":320,"Mallocs":2082,"Frees":1431}
{"Size":352,"Mallocs":2775,"Frees":2370}
{"Size":384,"Mallocs":387,"Frees":250}
{"Size":416,"Mallocs":429,"Frees":284}
{"Size":448,"Mallocs":229,"Frees":116}
{"Size":480,"Mallocs":151,"Frees":133}
{"Size":512,"Mallocs":3240,"Frees":3053}
{"Size":576,"Mallocs":9709,"Frees":5829}
{"Size":640,"Mallocs":192,"Frees":137}
{"Size":704,"Mallocs":203,"Frees":131}
{"Size":768,"Mallocs":739,"Frees":427}
{"Size":896,"Mallocs":829,"Frees":401}
{"Size":1024,"Mallocs":2817,"Frees":2677}
{"Size":1152,"Mallocs":983,"Frees":812}
{"Size":1280,"Mallocs":467,"Frees":109}
{"Size":1408,"Mallocs":923,"Frees":335}
{"Size":1536,"Mallocs":429,"Frees":289}
{"Size":1792,"Mallocs":644,"Frees":547}
{"Size":2048,"Mallocs":390,"Frees":210}
{"Size":2304,"Mallocs":249,"Frees":144}
{"Size":2688,"Mallocs":190,"Frees":106}
{"Size":3072,"Mallocs":20,"Frees":16}
{"Size":3200,"Mallocs":23,"Frees":13}
{"Size":3456,"Mallocs":14,"Frees":11}
{"Size":4096,"Mallocs":201,"Frees":127}
{"Size":4864,"Mallocs":52,"Frees":42}
{"Size":5376,"Mallocs":29,"Frees":8}
{"Size":6144,"Mallocs":12,"Frees":7}
{"Size":6528,"Mallocs":11,"Frees":3}
{"Size":6784,"Mallocs":3,"Frees":1}
{"Size":6912,"Mallocs":0,"Frees":0}
{"Size":8192,"Mallocs":50,"Frees":32}
{"Size":9472,"Mallocs":46,"Frees":24}
{"Size":9728,"Mallocs":0,"Frees":0}
{"Size":10240,"Mallocs":0,"Frees":0}
{"Size":10880,"Mallocs":2,"Frees":1}
{"Size":12288,"Mallocs":3,"Frees":0}
{"Size":13568,"Mallocs":0,"Frees":0}
{"Size":14336,"Mallocs":7,"Frees":3}
{"Size":16384,"Mallocs":30,"Frees":17}
{"Size":18432,"Mallocs":3,"Frees":3}
{"Size":19072,"Mallocs":16,"Frees":12}
]}
Pause durations in milliseconds and end times:
0 2018-12-07 00:02:40.164525406 +0000 UTC
3 2018-12-07 00:02:40.182034741 +0000 UTC
3 2018-12-07 00:02:40.209848541 +0000 UTC
0 2018-12-07 00:02:40.278986107 +0000 UTC
0 2018-12-07 00:02:40.733914972 +0000 UTC
22 2018-12-07 00:02:41.198224758 +0000 UTC
0 2018-12-07 00:02:41.290430652 +0000 UTC
0 2018-12-07 00:02:41.374230055 +0000 UTC
0 2018-12-07 00:02:41.455867822 +0000 UTC
2 2018-12-07 00:02:41.561961827 +0000 UTC
0 2018-12-07 00:04:41.577752402 +0000 UTC
0 2018-12-07 00:06:41.598823342 +0000 UTC
0 2018-12-07 00:08:41.62234336 +0000 UTC
0 2018-12-07 00:10:41.643055123 +0000 UTC
0 2018-12-07 00:12:41.665242451 +0000 UTC
5794 2018-12-07 00:13:19.296615758 +0000 UTC
5265 2018-12-07 00:14:01.227906209 +0000 UTC
28632 2018-12-07 00:14:59.097608371 +0000 UTC
--
You received this message because you are subscribed to the Google Groups
"golang-nuts" group.
To unsubscribe from this group and stop receiving emails from it, send an email
to golang-nuts+unsubscr...@googlegroups.com.
For more options, visit https://groups.google.com/d/optout.
