You might want to review this https://github.com/golang/go/issues/10958
> On Dec 11, 2018, at 10:16 PM, robert engels <reng...@ix.netcom.com> wrote: > > Reviewing the code, the 5s of cpu time is technically the stop-the-world > (STW) sweep termination > > So, I think the cause of your problem is that you have a tight / “infinite” > loop that is not calling runtime.Gosched(), so it is taking a very long time > for the sweep termination to complete. > > >> On Dec 11, 2018, at 9:43 PM, robert engels <reng...@ix.netcom.com >> <mailto:reng...@ix.netcom.com>> wrote: >> >> Well, your pause is clearly related to the GC - the first phase, the mark, >> is 5s in #17. Are you certain you don’t have an incorrect highly recursive >> loop that is causing the stack marking to take a really long time… ? >> >> >>> On Dec 11, 2018, at 8:45 PM, Eric Hamilton <e...@kasten.io >>> <mailto:e...@kasten.io>> wrote: >>> >>> 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 >>> <mailto:golang-nuts+unsubscr...@googlegroups.com>. >>> For more options, visit https://groups.google.com/d/optout >>> <https://groups.google.com/d/optout>. >>> <trace.medium.txt> >> >> >> -- >> 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 >> <mailto:golang-nuts+unsubscr...@googlegroups.com>. >> For more options, visit https://groups.google.com/d/optout >> <https://groups.google.com/d/optout>. > > > -- > 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 > <mailto:golang-nuts+unsubscr...@googlegroups.com>. > For more options, visit https://groups.google.com/d/optout > <https://groups.google.com/d/optout>. -- 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.
