Ok so it's not bad, thats good! The inital ~20 sec numbers come from the graphs that Herokus Go Metrics (Beta) provides. These must be sums in the given graph bucket which may for a 24H period add up to the high numbers I guess.
I will let it run over night and see what it looks like tomorrow, thx for your thoughts on this! tis 5 dec. 2017 kl 14:58 skrev <r...@golang.org>: > 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 >> <https://maps.google.com/?q=5+MB,+10+MB&entry=gmail&source=g> 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 >> <https://maps.google.com/?q=4+MB,+11+MB&entry=gmail&source=g> 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 >> <https://maps.google.com/?q=5+MB,+10+MB&entry=gmail&source=g> 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>: >> > 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> >>> 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>: >>> >> >>> >> 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> >> >> >>> >> 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 >>> >: >>> >> >> >>> >> >> 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 >>> <https://maps.google.com/?q=4+MB,+12+MB&entry=gmail&source=g> 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 >>> <https://maps.google.com/?q=4+MB,+10+MB&entry=gmail&source=g> 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 >>> <https://maps.google.com/?q=5+MB,+10+MB&entry=gmail&source=g> 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>: >>> >> >>> >>> >> >>> 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> 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. >> >> >>> >> >>>> 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. > -- 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.
