The wall clock is the first set of numbers, the second set is CPU. So 8P running for 8ms wall clock will result in 64ms CPU. The word "wall" was dropped to keep the line short.
There will be a beta out in the proverbial next few days that could help reduce even these STW times. The original post talked about 20 second and 400 and 900 ms pauses. From what I'm seeing here it is hard to attribute them to GC STW pauses. Also the GC is taking up (a rounded) 0% of the CPU which is pretty good (insert fancy new emoji). It is also doing it with a budget of 10 or 11 MBtyes on a machine that likely has 8 GB of Ram. To further test whether this is a GC issue or not try increasing GOGC until the MB goal on the gctrace line is 10x or 100x larger. This will reduce GC frequency by 10x or 100x and if your tail latency is a GC problem the 99%tile latency numbers will become 99.9%tile or 99.99%tile numbers. On Tuesday, December 5, 2017 at 2:39:53 AM UTC-5, Henrik Johansson wrote: > > I am watching with childlike fascination... > This is interesting perhaps: > > gc 130 @2834.158s 0%: 0.056+3.4+2.9 ms clock, 0.45+2.8/5.6/0+23 ms cpu, > 8->8->4 MB, 9 MB goal, 8 P > gc 131 @2834.178s 0%: 0.023+7.3+0.12 ms clock, 0.18+1.2/5.4/9.2+1.0 ms > cpu, 9->9->5 MB, 10 MB goal, 8 P > > ---> gc 132 @2836.882s 0%: 3.5+34+8.0 ms clock, 28+1.6/3.8/27+64 ms cpu, > 10->11->4 MB, 11 MB goal, 8 P > > gc 133 @2836.961s 0%: 0.022+14+1.0 ms clock, 0.18+2.1/12/0+8.4 ms cpu, > 8->9->5 MB, 9 MB goal, 8 P > gc 134 @2837.010s 0%: 7.0+18+0.16 ms clock, 56+14/21/1.6+1.2 ms cpu, > 9->10->5 MB, 10 MB goal, 8 P > > 28 + 64 ms SW (if I understand this correctly) to collect what 6-7 MB? > > > > tis 5 dec. 2017 kl 08:25 skrev Dave Cheney <da...@cheney.net <javascript:> > >: > >> Oh yeah, I forgot someone added that a while back. That should work. >> >> On Tue, Dec 5, 2017 at 6:23 PM, Henrik Johansson <dahan...@gmail.com >> <javascript:>> wrote: >> > So it has to run the program? I thought I saw "logfile" scenario in the >> > examples? >> > >> > GODEBUG=gctrace=1 godoc -index -http=:6060 2> stderr.log >> > cat stderr.log | gcvis >> > >> > I have shuffled the Heroku logs into Papertrail so I should be able to >> > extract the log lines from there. >> > >> > >> > tis 5 dec. 2017 kl 08:10 skrev Dave Cheney <da...@cheney.net >> <javascript:>>: >> >> >> >> Probably not for your scenario, gcviz assumes it can run your program >> >> as a child. >> >> >> >> On Tue, Dec 5, 2017 at 6:07 PM, Henrik Johansson <dahan...@gmail.com >> <javascript:>> >> >> wrote: >> >> > I found https://github.com/davecheney/gcvis from +Dave Cheney is it >> a >> >> > good >> >> > choice for inspecting the gc logs? >> >> > >> >> > tis 5 dec. 2017 kl 07:57 skrev Henrik Johansson <dahan...@gmail.com >> <javascript:>>: >> >> >> >> >> >> I have just added the gc tracing and it looks like this more or less >> >> >> all >> >> >> the time: >> >> >> >> >> >> gc 78 @253.095s 0 >> <https://maps.google.com/?q=@253.095s+0&entry=gmail&source=g>%: >> 0.032+3.3+0.46 ms clock, 0.26+0.24/2.6/2.4+3.6 ms >> >> >> cpu, >> >> >> 11->12->4 MB, 12 MB goal, 8 P >> >> >> gc 79 @253.109s 0%: 0.021+2.1+0.17 ms clock, 0.16+0.19/3.6/1.2+1.3 >> ms >> >> >> cpu, >> >> >> 9->9->4 MB, 10 MB goal, 8 P >> >> >> gc 80 @253.120s 0%: 0.022+2.8+2.2 ms clock, 0.17+0.27/4.8/0.006+18 >> ms >> >> >> cpu, >> >> >> 8->8->4 MB, 9 MB goal, 8 P >> >> >> gc 81 @253.138s 0%: 0.019+2.3+0.10 ms clock, 0.15+0.73/3.9/3.1+0.81 >> ms >> >> >> cpu, 9->9->5 MB, 10 MB goal, 8 P >> >> >> >> >> >> Heroku already reports a SW of 343 ms but I can't find it by manual >> >> >> inspection. I will download the logs later today and try to generate >> >> >> realistic load. >> >> >> What is the overhead of running like this, aside from the obvious >> extra >> >> >> logging? >> >> >> Are there any automatic tools to analyze these logs? >> >> >> >> >> >> lör 2 dec. 2017 kl 22:36 skrev Henrik Johansson <dahan...@gmail.com >> <javascript:>>: >> >> >>> >> >> >>> I am sorry, I was unclear. The app uses very little ram but the >> >> >>> provisioned available memory is 512 MB. >> >> >>> >> >> >>> I will try to experiment with GC toggles as you suggest and report >> >> >>> back. >> >> >>> >> >> >>> Thx! >> >> >>> >> >> >>> >> >> >>> On Sat, Dec 2, 2017, 22:18 rlh via golang-nuts >> >> >>> <golan...@googlegroups.com <javascript:>> wrote: >> >> >>>> >> >> >>>> Hard telling what it going on. 35MB, even for 1 CPU, seems very >> >> >>>> small. >> >> >>>> Most modern system provision more than 1GB per HW thread though >> I've >> >> >>>> seen >> >> >>>> some provision as little as 512MB. GOGC (SetGCPercent) can be >> adjust >> >> >>>> so that >> >> >>>> the application uses more of the available RAM. Running with >> >> >>>> GODEBUG=gctrace=1 will give you a sense of the GC's view of the >> >> >>>> application. >> >> >>>> >> >> >>>> In any case these kinds of numbers, running on a real systems, and >> >> >>>> duplicatable on tip are worth filing an issue. >> >> >>>> >> >> >>>> On Saturday, December 2, 2017 at 3:02:30 AM UTC-5, Henrik >> Johansson >> >> >>>> wrote: >> >> >>>>> >> >> >>>>> Hi, >> >> >>>>> >> >> >>>>> I am befuddled by GC SW times on several seconds (seen 20s once) >> in >> >> >>>>> the >> >> >>>>> metrics page for our app. There are several things that are >> strange >> >> >>>>> but >> >> >>>>> perhaps I am misreading it. The same metrics page reports Max >> Total >> >> >>>>> 35 MB >> >> >>>>> out of which 1 MB s swap the rest RSS. The response times on the >> >> >>>>> service is >> >> >>>>> has 99% ~400 ms which is not good but 95% is ~120 ms usually. >> >> >>>>> The app reloads an in memory cache as needed using atomic,Value >> as a >> >> >>>>> holder and the size is no more than a few thousand at any given >> >> >>>>> time. >> >> >>>>> Basically a map with pointers to simple structs and lists with >> >> >>>>> pointers >> >> >>>>> to the same structs to allow for some simple access scenarios. >> >> >>>>> >> >> >>>>> Now I haven't profiled the app yet but even in a very pathologial >> >> >>>>> case >> >> >>>>> it seems as though the GC would be able to keep up easily with >> such >> >> >>>>> little >> >> >>>>> amount of memory being used. Granted this is a Standard 1x dyno >> but >> >> >>>>> even so >> >> >>>>> once the machiine is stopped the GC should be able to complete >> it's >> >> >>>>> work in >> >> >>>>> a very short time given the low used memory. >> >> >>>>> >> >> >>>>> Has anyone seen this as well? Could the Go metrics on Heroku >> simply >> >> >>>>> report erroneously? Perhaps a couple of orders of magnitide? >> >> >>>>> >> >> >>>>> Cheers, >> >> >>>>> >> >> >>>> -- >> >> >>>> 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.
