No problems! If I can get a beta running I'll revisit this thread. Cheers,
On Tue, Dec 5, 2017, 19:41 Rick Hudson <r...@golang.org> wrote: > Henrik, > Thanks for the kind offer but there isn't much the runtime team can do > with the logs since 1.9 isn't likely to be changed due to this issue. > > > > On Tue, Dec 5, 2017 at 10:43 AM, Henrik Johansson <dahankz...@gmail.com> > wrote: > >> I would gladly help with this but afaik Heroku only makes stable versions >> available: >> https://github.com/heroku/heroku-buildpack-go/blob/master/data.json >> I guess I could deploy a docker container but I don't know if it changes >> everything and I doubt I have time before christmas at least. >> >> Maybe someone more versed in Herokus Go support can chime in on if it is >> possible. >> >> I will provide the logs from tonight though. Do you want them zipped here >> in the thread? >> >> >> tis 5 dec. 2017 kl 15:37 skrev Rick Hudson <r...@golang.org>: >> >>> 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.
