Glad to have helped. The runtime team would be interested in seeing what these pauses look like in the beta. If you have the time could you send them to us after the beta comes out.
On Tue, Dec 5, 2017 at 9:06 AM, Henrik Johansson <dahankz...@gmail.com> wrote: > 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.
