gc 347 @6564.164s 0%: 0.89+518+1.0 ms clock, 28+3839/4091/3959+33 ms cpu, 23813->23979->12265 MB, 24423 MB goal, 32 P
What I'm seeing here is that you have 32 HW threads and you spend .89+518+1 or 520 ms wall clock in the GC. You also spend 28+3839+4091+3959+33 or 11950 ms CPU time out of total of 520*32 or 16640 available CPU cycles while the GC is running. The GC will reserve 25% of the CPU to do its work. That's 16640*.25 or 4160 ms. If the GC finds any of the remaining 24 threads idle it will aggressively enlist them to do GC work. The graph only shows the 8 HW threads but not the other 24 so it is hard to tell what is going on with them. This may well be related to issue 12812 <https://github.com/golang/go/issues/14812> so you might want to read that thread for more insight. On Wed, May 31, 2017 at 10:25 AM, Xun Liu <pas...@gmail.com> wrote: > $ go version > > go version go1.8 linux/amd64 > > On Wednesday, May 31, 2017 at 7:13:38 AM UTC-7, Ian Lance Taylor wrote: >> >> [ +rlh, austin ] >> >> Which version of Go are you running? >> >> Ian >> >> On Tue, May 30, 2017 at 10:01 PM, Xun Liu <pas...@gmail.com> wrote: >> >>> Hi, we see a clear correlation between GC and latency spike in our Go >>> server. The server uses fairly large amount of memory (20G) and does mostly >>> CPU work. The server runs on a beefy box with 32 cores and the load is >>> pretty light (average CPU 20-30%). GC kicks in once every 10-20 seconds >>> and whenever it runs we observe pretty big latency spike ranging from 30% >>> to 100% across p50-p90 percentiles (e.g. p90 can jump from 100-120ms to >>> 160-250ms) >>> >>> I captured a trace of a gc and noticed the following: >>> >>> 1. user gorountines seem run longer during gc. This is through ad-hoc >>> check. I don't really know how to get stats to confirm this. >>> The gc log is as following (tiny pauses but is very aggressive in assist >>> and idle time) >>> gc 347 @6564.164s 0%: 0.89+518+1.0 ms clock, 28+3839/4091/3959+33 ms >>> cpu, 23813->23979->12265 MB, 24423 MB goal, 32 P >>> >>> 2. during gc, goroutines can queue up. In this particular case there is >>> a stretch of time (~20ms) where we see many goroutines are GCWaiting. See >>> below -- the second row is goroutines with light grey indicating GCWaiting >>> count and light green Runnable. >>> >>> >>> >>> <https://lh3.googleusercontent.com/-5NWj8HzrzyI/WS5Hg0c6WiI/AAAAAAAAqL8/_P-S9vXuGU0FVZV1tG_dHX-14tDHhTsnwCLcB/s1600/Screen%2BShot%2B2017-05-30%2Bat%2B9.32.27%2BPM.png> >>> >>> >>> <https://lh3.googleusercontent.com/-EdVRp4FjhPw/WS5MjjiwdrI/AAAAAAAAqMM/vE5Srmu9e9A5MV0d50NpDiqFsFrkn-E-QCLcB/s1600/Screen%2BShot%2B2017-05-30%2Bat%2B9.54.06%2BPM.png> >>> >>> Any idea what's going on here? What can I do to reduce the spikes? >>> >>> >>> >>> -- >>> 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. >>> 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.
