Thanks for getting back to me. I have posted the output from a 30-second runtime/trace session here, which appears to show three 80ms GC's:
https://www.dropbox.com/s/wc3hp6k17txaofh/staging-trace.tar.gz?dl=0 I'm struggling a bit to interpret what's there though. On Thursday, February 23, 2017 at 7:46:42 PM UTC, Austin Clements wrote: > > AFAIK, the only thing that can cause this in Go 1.8 is a non-preemptible > loop. It's not related to the heap size at all. > > To test this theory, you can set GOEXPERIMENT=preemptibleloops and rebuild > your Go tree (the compiler has to be built with this, so you can't just > turn it on to build your project). I wouldn't recommend running in > production with this, but if it eliminates the long pauses, we'll at least > know that's the culprit. > > Since these are quite long, the other thing you can do is run with the > execution tracer (https://godoc.org/runtime/trace). You'll be able to see > exactly what's happening at the beginning of each GC cycle. If you do have > non-preemptible loops, you should also see goroutines executing for much > longer than 10ms at a time, which is the default preemption bound. > > On Thu, Feb 23, 2017 at 1:46 PM, Oliver Beattie <oli...@obeattie.com > <javascript:>> wrote: > >> I am looking for some advice about how I can debug some long GC pauses I >> am observing in our production workloads under go 1.8 (the problem is not >> specific to 1.8, though). This is a very simple network server – basically >> a HTTP ping endpoint – but I regularly see tail request latencies of >> >100ms. I have enabled GODEBUG=gctrace=1, and I can see some quite long >> STW pauses amid lots of much less worrying pauses: >> >> gc 54 @348.007s 0%: 0.061+81+0.040 ms clock, 0.12+0.39/81/81+0.081 ms >> cpu, 4->4->1 MB, 5 MB goal, 2 P >> gc 55 @358.007s 0%: 0.21+83+0.019 ms clock, 0.43+80/2.7/81+0.039 ms cpu, >> 4->4->1 MB, 5 MB goal, 2 P >> *gc 56 @367.507s 0%: 80+1.3+0.065 ms clock, 161+0.080/1.2/82+0.13 ms cpu, >> 4->4->1 MB, 5 MB goal, 2 P* >> gc 57 @377.726s 0%: 0.054+63+0.023 ms clock, 0.10+0.68/61/0.44+0.046 ms >> cpu, 4->4->1 MB, 5 MB goal, 2 P >> gc 58 @388.007s 0%: 0.033+81+0.036 ms clock, 0.067+0.32/80/81+0.072 ms >> cpu, 4->4->1 MB, 5 MB goal, 2 P >> gc 59 @398.007s 0%: 0.021+82+0.019 ms clock, 0.043+0.17/80/82+0.038 ms >> cpu, 4->4->1 MB, 5 MB goal, 2 P >> gc 60 @407.630s 0%: 0.012+57+0.031 ms clock, 0.025+0.25/0.64/57+0.063 ms >> cpu, 4->4->1 MB, 5 MB goal, 2 P >> gc 61 @418.007s 0%: 0.19+1.0+79 ms clock, 0.38+0.28/0.69/0.98+159 ms cpu, >> 4->4->1 MB, 5 MB goal, 2 P >> gc 62 @427.507s 0%: 0.21+81+0.29 ms clock, 0.42+81/0.96/81+0.58 ms cpu, >> 4->4->1 MB, 5 MB goal, 2 P >> gc 63 @437.507s 0%: 0.015+81+0.053 ms clock, 0.031+0.29/0.98/80+0.10 ms >> cpu, 4->4->1 MB, 5 MB goal, 2 P >> *gc 64 @443.507s 0%: 81+1.2+0.032 ms clock, 162+0.040/1.2/0.44+0.065 ms >> cpu, 4->4->1 MB, 5 MB goal, 2 P* >> scvg2: inuse: 4, idle: 2, sys: 7, released: 0, consumed: 7 (MB) >> gc 65 @453.507s 0%: 0.13+81+0.051 ms clock, 0.26+0.20/81/82+0.10 ms cpu, >> 4->4->1 MB, 5 MB goal, 2 P >> >> If I am reading this correctly, some of these STW pauses are 80+ >> milliseconds, in order to scan a minuscule heap. I am not experienced with >> debugging the GC in Go, so I'd appreciate any pointers as to why this could >> happening and what I can do to get to the bottom of the behaviour. Many >> thanks :) >> >> -- >> 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...@googlegroups.com <javascript:>. >> For more options, visit 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.
