+rlh, austin Interesting behavior. I would recommend filing a bug. It would be most helpful if you can create a complete repro case including either the production code or some minimization of it that demonstrates the same pauses.
On Thu, Feb 23, 2017 at 10:46 AM, Oliver Beattie <oli...@obeattie.com> 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+unsubscr...@googlegroups.com. > 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.
