Of course. (I forgot about that option and I'd collected those traces at a
time when I thought I'd ruled out GC-- probably misread MemStats values).
Here's the gctrace output for a repro with a 5.6 second delay ending with
finish of gc17 and a 30+ second delay ending in SIGTERM (which coincides
with completion of gc18):
gc 1 @0.022s 1%: 0.94+10+0.19 ms clock, 0.94+0.65/0.60/5.3+0.19 ms cpu,
4->4->1 MB, 5 MB goal, 4 P
gc 2 @0.048s 3%: 0.007+5.9+0.17 ms clock, 0.007+0.24/5.7/1.0+0.17 ms cpu,
4->4->1 MB, 5 MB goal, 4 P
gc 3 @0.062s 3%: 0.004+3.7+0.18 ms clock, 0.004+0.19/0.78/2.8+0.18 ms cpu,
4->4->1 MB, 5 MB goal, 4 P
gc 4 @0.075s 13%: 0.003+3.4+69 ms clock, 0.003+0.069/0.99/2.3+69 ms cpu,
4->4->2 MB, 5 MB goal, 4 P
gc 5 @0.154s 12%: 0.007+7.4+0.032 ms clock, 0.007+0.15/0/5.1+0.032 ms cpu,
4->5->3 MB, 5 MB goal, 4 P
gc 6 @0.234s 10%: 0.004+34+0.025 ms clock, 0.004+0/33/6.8+0.025 ms cpu,
6->7->5 MB, 7 MB goal, 4 P
gc 7 @0.296s 8%: 0.005+28+0.031 ms clock, 0.005+0/0.99/50+0.031 ms cpu,
10->10->5 MB, 11 MB goal, 4 P
gc 8 @0.416s 6%: 0.007+49+1.1 ms clock, 0.007+0.13/4.5/32+1.1 ms cpu,
11->11->6 MB, 12 MB goal, 4 P
gc 9 @0.591s 5%: 0.006+23+0.032 ms clock, 0.006+0/6.5/31+0.032 ms cpu,
12->12->7 MB, 13 MB goal, 4 P
gc 10 @0.640s 5%: 0.006+10+0.032 ms clock, 0.006+0/3.6/12+0.032 ms cpu,
13->13->8 MB, 14 MB goal, 4 P
gc 11 @120.657s 0%: 0.012+11+0.030 ms clock, 0.012+0/1.7/23+0.030 ms cpu,
13->13->9 MB, 16 MB goal, 4 P
gc 12 @240.674s 0%: 0.011+12+0.037 ms clock, 0.011+0/6.1/27+0.037 ms cpu,
10->10->9 MB, 18 MB goal, 4 P
gc 13 @360.691s 0%: 0.011+10+0.022 ms clock, 0.011+0/2.7/25+0.022 ms cpu,
10->10->9 MB, 18 MB goal, 4 P
gc 14 @480.711s 0%: 0.018+11+0.021 ms clock, 0.018+0/4.1/27+0.021 ms cpu,
10->10->9 MB, 18 MB goal, 4 P
gc 15 @600.727s 0%: 0.016+14+0.030 ms clock, 0.016+0/7.0/30+0.030 ms cpu,
11->11->9 MB, 18 MB goal, 4 P
gc 16 @720.746s 0%: 0.016+13+0.023 ms clock, 0.016+0/5.7/27+0.023 ms cpu,
10->10->9 MB, 18 MB goal, 4 P
gc 17 @816.508s 0%: 5560+26+0.067 ms clock, 5560+7.3/26/22+0.067 ms cpu,
18->19->11 MB, 19 MB goal, 4 P
gc 18 @824.133s 1%: 40566+16+0.035 ms clock, 40566+6.8/15/10+0.035 ms cpu,
23->24->18 MB, 24 MB goal, 4 P
I've attached a file that also includes the schedtrace=1000, health check
log messages, key app logs, and the runtime.MemStats collected at the end
of the same run.
Thanks again for any insights,
Eric
On Tuesday, December 11, 2018 at 4:32:33 PM UTC-8, robert engels wrote:
>
> I think it would be more helpful if you used gctrace=1 to report on the GC
> activity.
>
>
>
--
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.
SCHED 0ms: gomaxprocs=4 idleprocs=3 threads=4 spinningthreads=0 idlethreads=2
runqueue=0 [0 0 0 0]
gc 1 @0.022s 1%: 0.94+10+0.19 ms clock, 0.94+0.65/0.60/5.3+0.19 ms cpu, 4->4->1
MB, 5 MB goal, 4 P
gc 2 @0.048s 3%: 0.007+5.9+0.17 ms clock, 0.007+0.24/5.7/1.0+0.17 ms cpu,
4->4->1 MB, 5 MB goal, 4 P
gc 3 @0.062s 3%: 0.004+3.7+0.18 ms clock, 0.004+0.19/0.78/2.8+0.18 ms cpu,
4->4->1 MB, 5 MB goal, 4 P
gc 4 @0.075s 13%: 0.003+3.4+69 ms clock, 0.003+0.069/0.99/2.3+69 ms cpu,
4->4->2 MB, 5 MB goal, 4 P
gc 5 @0.154s 12%: 0.007+7.4+0.032 ms clock, 0.007+0.15/0/5.1+0.032 ms cpu,
4->5->3 MB, 5 MB goal, 4 P
gc 6 @0.234s 10%: 0.004+34+0.025 ms clock, 0.004+0/33/6.8+0.025 ms cpu, 6->7->5
MB, 7 MB goal, 4 P
gc 7 @0.296s 8%: 0.005+28+0.031 ms clock, 0.005+0/0.99/50+0.031 ms cpu,
10->10->5 MB, 11 MB goal, 4 P
gc 8 @0.416s 6%: 0.007+49+1.1 ms clock, 0.007+0.13/4.5/32+1.1 ms cpu, 11->11->6
MB, 12 MB goal, 4 P
gc 9 @0.591s 5%: 0.006+23+0.032 ms clock, 0.006+0/6.5/31+0.032 ms cpu,
12->12->7 MB, 13 MB goal, 4 P
gc 10 @0.640s 5%: 0.006+10+0.032 ms clock, 0.006+0/3.6/12+0.032 ms cpu,
13->13->8 MB, 14 MB goal, 4 P
SCHED 1009ms: gomaxprocs=4 idleprocs=4 threads=12 spinningthreads=0
idlethreads=3 runqueue=0 [0 0 0 0]
<elided SCHEDs until first HEALTH CHECK>
time="2018-12-12T00:58:48.733801499Z" level=error msg="HEALTH CHECK"
SCHED 96805ms: gomaxprocs=4 idleprocs=4 threads=12 spinningthreads=0
idlethreads=4 runqueue=0 [0 0 0 0]
SCHED 97810ms: gomaxprocs=4 idleprocs=4 threads=12 spinningthreads=0
idlethreads=4 runqueue=0 [0 0 0 0]
SCHED 98817ms: gomaxprocs=4 idleprocs=4 threads=12 spinningthreads=0
idlethreads=4 runqueue=0 [0 0 0 0]
SCHED 99826ms: gomaxprocs=4 idleprocs=4 threads=12 spinningthreads=0
idlethreads=4 runqueue=0 [0 0 0 0]
SCHED 100836ms: gomaxprocs=4 idleprocs=4 threads=12 spinningthreads=0
idlethreads=4 runqueue=0 [0 0 0 0]
SCHED 101845ms: gomaxprocs=4 idleprocs=4 threads=12 spinningthreads=0
idlethreads=4 runqueue=0 [0 0 0 0]
SCHED 102854ms: gomaxprocs=4 idleprocs=4 threads=12 spinningthreads=0
idlethreads=4 runqueue=0 [0 0 0 0]
SCHED 103864ms: gomaxprocs=4 idleprocs=4 threads=12 spinningthreads=0
idlethreads=4 runqueue=0 [0 0 0 0]
SCHED 104872ms: gomaxprocs=4 idleprocs=4 threads=12 spinningthreads=0
idlethreads=4 runqueue=0 [0 0 0 0]
SCHED 105881ms: gomaxprocs=4 idleprocs=4 threads=12 spinningthreads=0
idlethreads=4 runqueue=0 [0 0 0 0]
time="2018-12-12T00:58:58.733724513Z" level=error msg="HEALTH CHECK"
<eliding SCHEDs until interesting>
time="2018-12-12T00:59:08.733825981Z" level=error msg="HEALTH CHECK"
gc 11 @120.657s 0%: 0.012+11+0.030 ms clock, 0.012+0/1.7/23+0.030 ms cpu,
13->13->9 MB, 16 MB goal, 4 P
time="2018-12-12T00:59:18.733755526Z" level=error msg="HEALTH CHECK"
time="2018-12-12T00:59:28.733851601Z" level=error msg="HEALTH CHECK"
time="2018-12-12T00:59:38.735405225Z" level=error msg="HEALTH CHECK"
time="2018-12-12T00:59:48.733717194Z" level=error msg="HEALTH CHECK"
time="2018-12-12T00:59:58.733720361Z" level=error msg="HEALTH CHECK"
time="2018-12-12T01:00:08.733739735Z" level=error msg="HEALTH CHECK"
time="2018-12-12T01:00:18.733733926Z" level=error msg="HEALTH CHECK"
time="2018-12-12T01:00:28.733797431Z" level=error msg="HEALTH CHECK"
time="2018-12-12T01:00:38.735164217Z" level=error msg="HEALTH CHECK"
time="2018-12-12T01:00:48.733767361Z" level=error msg="HEALTH CHECK"
time="2018-12-12T01:00:58.73372127Z" level=error msg="HEALTH CHECK"
time="2018-12-12T01:01:08.733695071Z" level=error msg="HEALTH CHECK"
gc 12 @240.674s 0%: 0.011+12+0.037 ms clock, 0.011+0/6.1/27+0.037 ms cpu,
10->10->9 MB, 18 MB goal, 4 P
time="2018-12-12T01:01:18.73378239Z" level=error msg="HEALTH CHECK"
time="2018-12-12T01:01:28.733740079Z" level=error msg="HEALTH CHECK"
time="2018-12-12T01:01:38.733970035Z" level=error msg="HEALTH CHECK"
time="2018-12-12T01:01:48.734440685Z" level=error msg="HEALTH CHECK"
time="2018-12-12T01:01:58.733804175Z" level=error msg="HEALTH CHECK"
time="2018-12-12T01:02:08.734251135Z" level=error msg="HEALTH CHECK"
time="2018-12-12T01:02:18.847043777Z" level=error msg="HEALTH CHECK"
time="2018-12-12T01:02:28.733710838Z" level=error msg="HEALTH CHECK"
time="2018-12-12T01:02:38.733785537Z" level=error msg="HEALTH CHECK"
time="2018-12-12T01:02:48.733674788Z" level=error msg="HEALTH CHECK"
time="2018-12-12T01:02:58.733848427Z" level=error msg="HEALTH CHECK"
time="2018-12-12T01:03:08.733713731Z" level=error msg="HEALTH CHECK"
gc 13 @360.691s 0%: 0.011+10+0.022 ms clock, 0.011+0/2.7/25+0.022 ms cpu,
10->10->9 MB, 18 MB goal, 4 P
time="2018-12-12T01:03:18.733821144Z" level=error msg="HEALTH CHECK"
time="2018-12-12T01:03:28.733863148Z" level=error msg="HEALTH CHECK"
time="2018-12-12T01:03:38.733800124Z" level=error msg="HEALTH CHECK"
time="2018-12-12T01:03:48.733780917Z" level=error msg="HEALTH CHECK"
time="2018-12-12T01:03:58.733842161Z" level=error msg="HEALTH CHECK"
time="2018-12-12T01:04:08.733765202Z" level=error msg="HEALTH CHECK"
time="2018-12-12T01:04:18.733978141Z" level=error msg="HEALTH CHECK"
time="2018-12-12T01:04:28.733801102Z" level=error msg="HEALTH CHECK"
time="2018-12-12T01:04:38.733823046Z" level=error msg="HEALTH CHECK"
time="2018-12-12T01:04:48.734317831Z" level=error msg="HEALTH CHECK"
time="2018-12-12T01:04:58.733915825Z" level=error msg="HEALTH CHECK"
time="2018-12-12T01:05:08.733829512Z" level=error msg="HEALTH CHECK"
gc 14 @480.711s 0%: 0.018+11+0.021 ms clock, 0.018+0/4.1/27+0.021 ms cpu,
10->10->9 MB, 18 MB goal, 4 P
time="2018-12-12T01:05:18.733819864Z" level=error msg="HEALTH CHECK"
time="2018-12-12T01:05:28.733955635Z" level=error msg="HEALTH CHECK"
time="2018-12-12T01:05:38.733805237Z" level=error msg="HEALTH CHECK"
time="2018-12-12T01:05:44.851265805Z" level=info msg="Pulling job from queue:
ec86023f-fda9-11e8-9cb4-0a580a28074e"
time="2018-12-12T01:05:44.876726498Z" level=info msg="Executing Job:
ec86023f-fda9-11e8-9cb4-0a580a28074e"
time="2018-12-12T01:05:44.891832155Z" level=info msg="Daemon Shutting Down"
time="2018-12-12T01:05:48.73377811Z" level=error msg="HEALTH CHECK"
time="2018-12-12T01:05:58.733860976Z" level=error msg="HEALTH CHECK"
time="2018-12-12T01:06:08.733770982Z" level=error msg="HEALTH CHECK"
time="2018-12-12T01:06:18.733834296Z" level=error msg="HEALTH CHECK"
time="2018-12-12T01:06:28.733797408Z" level=error msg="HEALTH CHECK"
time="2018-12-12T01:06:38.733741273Z" level=error msg="HEALTH CHECK"
time="2018-12-12T01:06:48.734041044Z" level=error msg="HEALTH CHECK"
time="2018-12-12T01:06:58.733675765Z" level=error msg="HEALTH CHECK"
time="2018-12-12T01:07:01.277767858Z" level=info msg="Pulling job from queue:
ec86023f-fda9-11e8-9cb4-0a580a28074e"
time="2018-12-12T01:07:01.285626506Z" level=info msg="Executing Job:
ec86023f-fda9-11e8-9cb4-0a580a28074e"
time="2018-12-12T01:07:01.2896179Z" level=info msg="Daemon Shutting Down"
time="2018-12-12T01:07:08.733798666Z" level=error msg="HEALTH CHECK"
gc 15 @600.727s 0%: 0.016+14+0.030 ms clock, 0.016+0/7.0/30+0.030 ms cpu,
11->11->9 MB, 18 MB goal, 4 P
time="2018-12-12T01:07:18.733779033Z" level=error msg="HEALTH CHECK"
time="2018-12-12T01:07:28.73377746Z" level=error msg="HEALTH CHECK"
time="2018-12-12T01:07:38.733786983Z" level=error msg="HEALTH CHECK"
time="2018-12-12T01:07:48.733750992Z" level=error msg="HEALTH CHECK"
time="2018-12-12T01:07:58.733751875Z" level=error msg="HEALTH CHECK"
time="2018-12-12T01:08:08.733754037Z" level=error msg="HEALTH CHECK"
time="2018-12-12T01:08:18.733801257Z" level=error msg="HEALTH CHECK"
time="2018-12-12T01:08:28.740644595Z" level=error msg="HEALTH CHECK"
time="2018-12-12T01:08:38.733996957Z" level=error msg="HEALTH CHECK"
time="2018-12-12T01:08:48.734049212Z" level=error msg="HEALTH CHECK"
time="2018-12-12T01:08:58.733895158Z" level=error msg="HEALTH CHECK"
time="2018-12-12T01:09:08.733749545Z" level=error msg="HEALTH CHECK"
gc 16 @720.746s 0%: 0.016+13+0.023 ms clock, 0.016+0/5.7/27+0.023 ms cpu,
10->10->9 MB, 18 MB goal, 4 P
time="2018-12-12T01:09:18.733783222Z" level=error msg="HEALTH CHECK"
time="2018-12-12T01:09:28.733790967Z" level=error msg="HEALTH CHECK"
time="2018-12-12T01:09:38.733773389Z" level=error msg="HEALTH CHECK"
time="2018-12-12T01:09:48.733786491Z" level=error msg="HEALTH CHECK"
time="2018-12-12T01:09:58.733776577Z" level=error msg="HEALTH CHECK"
time="2018-12-12T01:10:08.733729517Z" level=error msg="HEALTH CHECK"
time="2018-12-12T01:10:18.733835866Z" level=error msg="HEALTH CHECK"
time="2018-12-12T01:10:28.733973249Z" level=error msg="HEALTH CHECK"
time="2018-12-12T01:10:38.733737576Z" level=error msg="HEALTH CHECK"
SCHED 806219ms: gomaxprocs=4 idleprocs=4 threads=12 spinningthreads=0
idlethreads=4 runqueue=0 [0 0 0 0]
SCHED 807229ms: gomaxprocs=4 idleprocs=4 threads=12 spinningthreads=0
idlethreads=4 runqueue=0 [0 0 0 0]
SCHED 808236ms: gomaxprocs=4 idleprocs=4 threads=12 spinningthreads=0
idlethreads=4 runqueue=0 [0 0 0 0]
SCHED 809245ms: gomaxprocs=4 idleprocs=4 threads=12 spinningthreads=0
idlethreads=4 runqueue=0 [0 0 0 0]
SCHED 810254ms: gomaxprocs=4 idleprocs=4 threads=12 spinningthreads=0
idlethreads=4 runqueue=0 [0 0 0 0]
SCHED 811263ms: gomaxprocs=4 idleprocs=4 threads=12 spinningthreads=0
idlethreads=4 runqueue=0 [0 0 0 0]
SCHED 812272ms: gomaxprocs=4 idleprocs=4 threads=12 spinningthreads=0
idlethreads=4 runqueue=0 [0 0 0 0]
SCHED 813281ms: gomaxprocs=4 idleprocs=4 threads=12 spinningthreads=0
idlethreads=4 runqueue=0 [0 0 0 0]
SCHED 814290ms: gomaxprocs=4 idleprocs=4 threads=12 spinningthreads=0
idlethreads=4 runqueue=0 [0 0 0 0]
time="2018-12-12T01:10:47.740733628Z" level=info msg="Pulling job from queue:
c1be85f2-fdaa-11e8-9cb4-0a580a28074e"
time="2018-12-12T01:10:47.747740676Z" level=info msg="Executing Job:
c1be85f2-fdaa-11e8-9cb4-0a580a28074e"
SCHED 815297ms: gomaxprocs=4 idleprocs=4 threads=12 spinningthreads=0
idlethreads=3 runqueue=0 [0 0 0 0]
time="2018-12-12T01:10:47.914373557Z" level=error msg="DEBUG: calling
OpenDirectory"
SCHED 816298ms: gomaxprocs=4 idleprocs=2 threads=13 spinningthreads=0
idlethreads=2 runqueue=0 [0 0 0 0]
SCHED 817304ms: gomaxprocs=4 idleprocs=0 threads=13 spinningthreads=0
idlethreads=4 runqueue=2 [0 0 0 0]
SCHED 818305ms: gomaxprocs=4 idleprocs=0 threads=13 spinningthreads=0
idlethreads=4 runqueue=2 [0 0 0 0]
SCHED 819310ms: gomaxprocs=4 idleprocs=0 threads=13 spinningthreads=0
idlethreads=4 runqueue=2 [0 0 0 0]
SCHED 820313ms: gomaxprocs=4 idleprocs=0 threads=13 spinningthreads=0
idlethreads=4 runqueue=2 [0 0 0 0]
SCHED 821323ms: gomaxprocs=4 idleprocs=0 threads=13 spinningthreads=0
idlethreads=4 runqueue=2 [0 0 0 0]
time="2018-12-12T01:10:54.612920315Z" level=error msg="HEALTH CHECK"
^^^ 5.9 seconds late
gc 17 @816.508s 0%: 5560+26+0.067 ms clock, 5560+7.3/26/22+0.067 ms cpu,
18->19->11 MB, 19 MB goal, 4 P
SCHED 822329ms: gomaxprocs=4 idleprocs=4 threads=13 spinningthreads=0
idlethreads=5 runqueue=0 [0 0 0 0]
time="2018-12-12T01:10:54.955754651Z" level=error msg="DEBUG: calling Create"
SCHED 823336ms: gomaxprocs=4 idleprocs=3 threads=13 spinningthreads=0
idlethreads=4 runqueue=0 [0 0 0 0]
SCHED 824344ms: gomaxprocs=4 idleprocs=0 threads=13 spinningthreads=0
idlethreads=3 runqueue=0 [0 0 0 0]
SCHED 825348ms: gomaxprocs=4 idleprocs=0 threads=13 spinningthreads=0
idlethreads=4 runqueue=1 [0 0 0 0]
>>> next HEALTH CHECK DUE HERE
SCHED 826351ms: gomaxprocs=4 idleprocs=0 threads=13 spinningthreads=0
idlethreads=5 runqueue=2 [0 0 0 0]
SCHED 827353ms: gomaxprocs=4 idleprocs=0 threads=13 spinningthreads=0
idlethreads=6 runqueue=3 [0 0 0 0]
SCHED 828359ms: gomaxprocs=4 idleprocs=0 threads=13 spinningthreads=0
idlethreads=6 runqueue=3 [0 0 0 0]
SCHED 829366ms: gomaxprocs=4 idleprocs=0 threads=13 spinningthreads=0
idlethreads=6 runqueue=3 [0 0 0 0]
SCHED 830367ms: gomaxprocs=4 idleprocs=0 threads=13 spinningthreads=0
idlethreads=6 runqueue=3 [0 0 0 0]
SCHED 831376ms: gomaxprocs=4 idleprocs=0 threads=13 spinningthreads=0
idlethreads=6 runqueue=3 [0 0 0 0]
SCHED 832379ms: gomaxprocs=4 idleprocs=0 threads=13 spinningthreads=0
idlethreads=7 runqueue=4 [0 0 0 0]
SCHED 833379ms: gomaxprocs=4 idleprocs=0 threads=13 spinningthreads=0
idlethreads=7 runqueue=4 [0 0 0 0]
SCHED 834387ms: gomaxprocs=4 idleprocs=0 threads=13 spinningthreads=0
idlethreads=7 runqueue=4 [0 0 0 0]
SCHED 835398ms: gomaxprocs=4 idleprocs=0 threads=13 spinningthreads=0
idlethreads=7 runqueue=4 [0 0 0 0]
>>> next HEALTH CHECK DUE HERE
SCHED 836407ms: gomaxprocs=4 idleprocs=0 threads=13 spinningthreads=0
idlethreads=7 runqueue=4 [0 0 0 0]
SCHED 837412ms: gomaxprocs=4 idleprocs=0 threads=13 spinningthreads=0
idlethreads=7 runqueue=4 [0 0 0 0]
SCHED 838414ms: gomaxprocs=4 idleprocs=0 threads=13 spinningthreads=0
idlethreads=8 runqueue=5 [0 0 0 0]
SCHED 839424ms: gomaxprocs=4 idleprocs=0 threads=13 spinningthreads=0
idlethreads=8 runqueue=5 [0 0 0 0]
SCHED 840431ms: gomaxprocs=4 idleprocs=0 threads=13 spinningthreads=0
idlethreads=8 runqueue=5 [0 0 0 0]
SCHED 841440ms: gomaxprocs=4 idleprocs=0 threads=13 spinningthreads=0
idlethreads=8 runqueue=5 [0 0 0 0]
SCHED 842445ms: gomaxprocs=4 idleprocs=0 threads=13 spinningthreads=0
idlethreads=8 runqueue=5 [0 0 0 0]
SCHED 843453ms: gomaxprocs=4 idleprocs=0 threads=13 spinningthreads=0
idlethreads=8 runqueue=5 [0 0 0 0]
SCHED 844457ms: gomaxprocs=4 idleprocs=0 threads=13 spinningthreads=0
idlethreads=8 runqueue=5 [0 0 0 0]
SCHED 845462ms: gomaxprocs=4 idleprocs=0 threads=13 spinningthreads=0
idlethreads=8 runqueue=8 [0 0 0 0]
>>> next HEALTH CHECK DUE HERE
SCHED 846469ms: gomaxprocs=4 idleprocs=0 threads=13 spinningthreads=0
idlethreads=8 runqueue=8 [0 0 0 0]
SCHED 847471ms: gomaxprocs=4 idleprocs=0 threads=13 spinningthreads=0
idlethreads=8 runqueue=8 [0 0 0 0]
SCHED 848474ms: gomaxprocs=4 idleprocs=0 threads=13 spinningthreads=0
idlethreads=8 runqueue=8 [0 0 0 0]
SCHED 849479ms: gomaxprocs=4 idleprocs=0 threads=13 spinningthreads=0
idlethreads=8 runqueue=8 [0 0 0 0]
SCHED 850480ms: gomaxprocs=4 idleprocs=0 threads=13 spinningthreads=0
idlethreads=8 runqueue=8 [0 0 0 0]
SCHED 851482ms: gomaxprocs=4 idleprocs=0 threads=13 spinningthreads=0
idlethreads=8 runqueue=8 [0 0 0 0]
SCHED 852485ms: gomaxprocs=4 idleprocs=0 threads=13 spinningthreads=0
idlethreads=8 runqueue=9 [0 0 0 0]
SCHED 853490ms: gomaxprocs=4 idleprocs=0 threads=13 spinningthreads=0
idlethreads=8 runqueue=9 [0 0 0 0]
SCHED 854490ms: gomaxprocs=4 idleprocs=0 threads=13 spinningthreads=0
idlethreads=8 runqueue=9 [0 0 0 0]
SCHED 855491ms: gomaxprocs=4 idleprocs=0 threads=13 spinningthreads=0
idlethreads=8 runqueue=9 [0 0 0 0]
>>> next HEALTH CHECK DUE HERE
SCHED 856497ms: gomaxprocs=4 idleprocs=0 threads=13 spinningthreads=0
idlethreads=8 runqueue=9 [0 0 0 0]
SCHED 857497ms: gomaxprocs=4 idleprocs=0 threads=13 spinningthreads=0
idlethreads=8 runqueue=9 [0 0 0 0]
SCHED 858507ms: gomaxprocs=4 idleprocs=0 threads=13 spinningthreads=0
idlethreads=8 runqueue=9 [0 0 0 0]
SCHED 859514ms: gomaxprocs=4 idleprocs=0 threads=13 spinningthreads=0
idlethreads=8 runqueue=9 [0 0 0 0]
SCHED 860517ms: gomaxprocs=4 idleprocs=0 threads=13 spinningthreads=0
idlethreads=8 runqueue=9 [0 0 0 0]
SCHED 861522ms: gomaxprocs=4 idleprocs=0 threads=13 spinningthreads=0
idlethreads=8 runqueue=9 [0 0 0 0]
SCHED 862526ms: gomaxprocs=4 idleprocs=0 threads=13 spinningthreads=0
idlethreads=8 runqueue=9 [0 0 0 0]
SCHED 863529ms: gomaxprocs=4 idleprocs=0 threads=13 spinningthreads=0
idlethreads=8 runqueue=9 [0 0 0 0]
SCHED 864534ms: gomaxprocs=4 idleprocs=0 threads=13 spinningthreads=0
idlethreads=8 runqueue=9 [0 0 0 0]
time="2018-12-12T01:11:37.24623994Z" level=error msg="HEALTH CHECK"
time="2018-12-12T01:11:37.246645166Z" level=error msg="HEALTH CHECK"
printed from SIGTERM handler:
2018/12/12 01:11:37 shutdown initiated
time="2018-12-12T01:11:37.249296948Z" level=error msg="DEBUG: BeforeShutdown
called"
time="2018-12-12T01:11:37.249499385Z" level=error msg="DEBUG: NumCPU=1
GOMAXPROCS=4"
gc 18 @824.133s 1%: 40566+16+0.035 ms clock, 40566+6.8/15/10+0.035 ms cpu,
23->24->18 MB, 24 MB goal, 4 P
time="2018-12-12T01:11:37.262484961Z" level=error msg="DEBUG: runtime stats:
runtime.MemStats{Alloc:0x12f4c70, TotalAlloc:0x40aaaf8, Sys:0x44ef8f8,
Lookups:0x0, Mallocs:0xb76de, Frees:0xa79b2,
HeapAlloc:0x12f4c70, HeapSys:0x3f10000, HeapIdle:0x2816000,
HeapInuse:0x16fa000, HeapReleased:0x0, HeapObjects:0xfd2c,
StackInuse:0xf0000, StackSys:0xf0000, MSpanInuse:0x3ad18, MSpanSys:0x4c000,
MCacheInuse:0x1b00, MCacheSys:0x4000,
BuckHashSys:0x168a77, GCSys:0x249000, OtherSys:0xede81, NextGC:0x25e90d0,
LastGC:0x156f70afba582756,
PauseTotalNs:0xac1bf7aa3,
PauseNs:[256]uint64{0x114da7, 0x2c598, 0x2d743, 0x4297672, 0x9e01, 0x775c,
0x8fe0, 0x121718, 0x98c9, 0x97ef, 0xa87b, 0xc2a6, 0x86cc, 0x9bc5, 0xb62d,
0x9e3b, 0x14b6e8a96, 0x971f7bff2},
PauseEnd:[256]uint64{0x156f6fe667494892, 0x156f6fe66879c441,
0x156f6fe66932191c, 0x156f6fe66e143ad4, 0x156f6fe66ee5a571, 0x156f6fe6753cfbf0,
0x156f6fe67898544f, 0x156f6fe68119f4d7, 0x156f6fe689e5f15a, 0x156f6fe68c0aa3ee,
0x156f70027da9deb8, 0x156f701e6f574b7b, 0x156f703a60beebc5, 0x156f70565286b687,
0x156f707244370e2d, 0x156f708e35e48a43, 0x156f70a5cdfc53b3,
0x156f70afba582756,},
NumGC:0x12, NumForcedGC:0x0, GCCPUFraction:0.013398548067885228, EnableGC:true,
DebugGC:false,
BySize:[61]struct { Size uint32; Mallocs uint64; Frees uint64 }
{struct { Size uint32; Mallocs uint64; Frees uint64 }{Size:0x0, Mallocs:0x0,
Frees:0x0},
struct { Size uint32; Mallocs uint64; Frees uint64 }{Size:0x8, Mallocs:0x33d5,
Frees:0x3063},
struct { Size uint32; Mallocs uint64; Frees uint64 }{Size:0x10,
Mallocs:0x441a3, Frees:0x3f83d},
struct { Size uint32; Mallocs uint64; Frees uint64 }{Size:0x20,
Mallocs:0x219aa, Frees:0x1dc21},
struct { Size uint32; Mallocs uint64; Frees uint64 }{Size:0x30,
Mallocs:0xf9d6, Frees:0xd913},
struct { Size uint32; Mallocs uint64; Frees uint64 }{Size:0x40,
Mallocs:0x4a9e, Frees:0x3c24},
struct { Size uint32; Mallocs uint64; Frees uint64 }{Size:0x50,
Mallocs:0x3701, Frees:0x32ef},
struct { Size uint32; Mallocs uint64; Frees uint64 }{Size:0x60,
Mallocs:0x1348, Frees:0xf7a},
struct { Size uint32; Mallocs uint64; Frees uint64 }{Size:0x70,
Mallocs:0x26b3, Frees:0x232a},
struct { Size uint32; Mallocs uint64; Frees uint64 }{Size:0x80,
Mallocs:0x366f, Frees:0x2710},
struct { Size uint32; Mallocs uint64; Frees uint64 }{Size:0x90, Mallocs:0x952,
Frees:0x388},
struct { Size uint32; Mallocs uint64; Frees uint64 }{Size:0xa0,
Mallocs:0x700f, Frees:0x6e48},
struct { Size uint32; Mallocs uint64; Frees uint64 }{Size:0xb0, Mallocs:0x2f1,
Frees:0x1f7},
struct { Size uint32; Mallocs uint64; Frees uint64 }{Size:0xc0, Mallocs:0x397,
Frees:0x25e},
struct { Size uint32; Mallocs uint64; Frees uint64 }{Size:0xd0, Mallocs:0x7d4,
Frees:0x536},
struct { Size uint32; Mallocs uint64; Frees uint64 }{Size:0xe0, Mallocs:0x476,
Frees:0x351},
struct { Size uint32; Mallocs uint64; Frees uint64 }{Size:0xf0, Mallocs:0x1a3,
Frees:0x189},
struct { Size uint32; Mallocs uint64; Frees uint64 }{Size:0x100,
Mallocs:0xdd8, Frees:0xda6},
struct { Size uint32; Mallocs uint64; Frees uint64 }{Size:0x120,
Mallocs:0x77df, Frees:0x7374},
struct { Size uint32; Mallocs uint64; Frees uint64 }{Size:0x140,
Mallocs:0x67c, Frees:0x56c},
struct { Size uint32; Mallocs uint64; Frees uint64 }{Size:0x160,
Mallocs:0x49c, Frees:0x462},
struct { Size uint32; Mallocs uint64; Frees uint64 }{Size:0x180,
Mallocs:0x119, Frees:0xa1},
struct { Size uint32; Mallocs uint64; Frees uint64 }{Size:0x1a0, Mallocs:0xe0,
Frees:0x8b},
struct { Size uint32; Mallocs uint64; Frees uint64 }{Size:0x1c0, Mallocs:0xc2,
Frees:0x92},
struct { Size uint32; Mallocs uint64; Frees uint64 }{Size:0x1e0, Mallocs:0x7a,
Frees:0x6c},
struct { Size uint32; Mallocs uint64; Frees uint64 }{Size:0x200,
Mallocs:0xb7d, Frees:0xb6c},
struct { Size uint32; Mallocs uint64; Frees uint64 }{Size:0x240,
Mallocs:0x250a, Frees:0x168c},
struct { Size uint32; Mallocs uint64; Frees uint64 }{Size:0x280, Mallocs:0x89,
Frees:0x5e},
struct { Size uint32; Mallocs uint64; Frees uint64 }{Size:0x2c0, Mallocs:0x75,
Frees:0x58},
struct { Size uint32; Mallocs uint64; Frees uint64 }{Size:0x300,
Mallocs:0x2c4, Frees:0x2bd},
struct { Size uint32; Mallocs uint64; Frees uint64 }{Size:0x380,
Mallocs:0x2a0, Frees:0x164},
struct { Size uint32; Mallocs uint64; Frees uint64 }{Size:0x400,
Mallocs:0xa83, Frees:0xa52},
struct { Size uint32; Mallocs uint64; Frees uint64 }{Size:0x480,
Mallocs:0x2e5, Frees:0x28a},
struct { Size uint32; Mallocs uint64; Frees uint64 }{Size:0x500,
Mallocs:0x1c9, Frees:0xa2},
struct { Size uint32; Mallocs uint64; Frees uint64 }{Size:0x580,
Mallocs:0x361, Frees:0x2a2},
struct { Size uint32; Mallocs uint64; Frees uint64 }{Size:0x600, Mallocs:0xe8,
Frees:0xce},
struct { Size uint32; Mallocs uint64; Frees uint64 }{Size:0x700,
Mallocs:0x1c4, Frees:0x19e},
struct { Size uint32; Mallocs uint64; Frees uint64 }{Size:0x800,
Mallocs:0x16a, Frees:0x141},
struct { Size uint32; Mallocs uint64; Frees uint64 }{Size:0x900, Mallocs:0xc9,
Frees:0x7c},
struct { Size uint32; Mallocs uint64; Frees uint64 }{Size:0xa80, Mallocs:0xaa,
Frees:0x8b},
struct { Size uint32; Mallocs uint64; Frees uint64 }{Size:0xc00, Mallocs:0xe,
Frees:0xc},
struct { Size uint32; Mallocs uint64; Frees uint64 }{Size:0xc80, Mallocs:0x11,
Frees:0x8},
struct { Size uint32; Mallocs uint64; Frees uint64 }{Size:0xd80, Mallocs:0xa,
Frees:0x9},
struct { Size uint32; Mallocs uint64; Frees uint64 }{Size:0x1000,
Mallocs:0x90, Frees:0x56},
struct { Size uint32; Mallocs uint64; Frees uint64 }{Size:0x1300,
Mallocs:0x2e, Frees:0x26},
struct { Size uint32; Mallocs uint64; Frees uint64 }{Size:0x1500,
Mallocs:0x1d, Frees:0x8},
struct { Size uint32; Mallocs uint64; Frees uint64 }{Size:0x1800, Mallocs:0xb,
Frees:0x7},
struct { Size uint32; Mallocs uint64; Frees uint64 }{Size:0x1980, Mallocs:0xb,
Frees:0x3},
struct { Size uint32; Mallocs uint64; Frees uint64 }{Size:0x1a80, Mallocs:0x3,
Frees:0x1},
struct { Size uint32; Mallocs uint64; Frees uint64 }{Size:0x1b00, Mallocs:0x0,
Frees:0x0},
struct { Size uint32; Mallocs uint64; Frees uint64 }{Size:0x2000,
Mallocs:0x21, Frees:0x12},
struct { Size uint32; Mallocs uint64; Frees uint64 }{Size:0x2500,
Mallocs:0x28, Frees:0x12},
struct { Size uint32; Mallocs uint64; Frees uint64 }{Size:0x2600, Mallocs:0x0,
Frees:0x0},
struct { Size uint32; Mallocs uint64; Frees uint64 }{Size:0x2800, Mallocs:0x0,
Frees:0x0},
struct { Size uint32; Mallocs uint64; Frees uint64 }{Size:0x2a80, Mallocs:0x2,
Frees:0x1},
struct { Size uint32; Mallocs uint64; Frees uint64 }{Size:0x3000, Mallocs:0x3,
Frees:0x0},
struct { Size uint32; Mallocs uint64; Frees uint64 }{Size:0x3500, Mallocs:0x0,
Frees:0x0},
struct { Size uint32; Mallocs uint64; Frees uint64 }{Size:0x3800, Mallocs:0x1,
Frees:0x0},
struct { Size uint32; Mallocs uint64; Frees uint64 }{Size:0x4000,
Mallocs:0x1d, Frees:0x11},
struct { Size uint32; Mallocs uint64; Frees uint64 }{Size:0x4800, Mallocs:0x3,
Frees:0x3},
struct { Size uint32; Mallocs uint64; Frees uint64 }{Size:0x4a80, Mallocs:0xa,
Frees:0x6}
}}"
SCHED 864712ms: gomaxprocs=4 idleprocs=3 threads=14 spinningthreads=0
idlethreads=4 runqueue=0 gcwaiting=0 nmidlelocked=1 stopwait=0 sysmonwait=0
