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.
