Re: [go-nuts] Re: GC SW times on Heroku (Beta metrics)

2017-12-05 Thread Henrik Johansson 
No problems! If I can get a beta running I'll revisit this thread.

Cheers,

On Tue, Dec 5, 2017, 19:41 Rick Hudson  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 
> 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 :
>>
>>> 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 
>>> 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 :

> 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 :
>>
> Oh yeah, I forgot someone added that a while back. That should work.
>>>
>>> On Tue, Dec 5, 2017 at 6:23 PM, Henrik Johansson 
>>> 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 :
>>> >>
>>> >> 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 <
>>>

Re: [go-nuts] Re: GC SW times on Heroku (Beta metrics)

2017-12-05 Thread Rick Hudson 
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 
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 :
>
>> 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 
>> 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 :
>>>
 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 :
>
 Oh yeah, I forgot someone added that a while back. That should work.
>>
>> On Tue, Dec 5, 2017 at 6:23 PM, Henrik Johansson 
>> 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 :
>> >>
>> >> 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
>> %:
>> 0.032+3.3+0.46 ms clock,

Re: [go-nuts] Re: GC SW times on Heroku (Beta metrics)

2017-12-05 Thread Henrik Johansson 
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 :

> 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 
> 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 :
>>
>>> 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 :

>>> Oh yeah, I forgot someone added that a while back. That should work.
>
> On Tue, Dec 5, 2017 at 6:23 PM, Henrik Johansson 
> 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 :
> >>
> >> 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  >


> >> 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
> %:
> 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

Re: [go-nuts] Re: GC SW times on Heroku (Beta metrics)

2017-12-05 Thread Rick Hudson 
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 
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 :
>
>> 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 :
>>>
>> Oh yeah, I forgot someone added that a while back. That should work.

 On Tue, Dec 5, 2017 at 6:23 PM, Henrik Johansson 
 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 :
 >>
 >> 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 
>>>
>>>
 >> 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
 %:
 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?
 >> >>

Re: [go-nuts] Re: GC SW times on Heroku (Beta metrics)

2017-12-05 Thread Henrik Johansson 
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 :

> 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 :
>>
> Oh yeah, I forgot someone added that a while back. That should work.
>>>
>>> On Tue, Dec 5, 2017 at 6:23 PM, Henrik Johansson 
>>> 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 :
>>> >>
>>> >> 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 
>>
>>
>>> >> 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 >> >:
>>> >> >>
>>> >> >> I have just added the gc tracing and it looks like this more or
>>> less
>>> >> >> all
>>> >> >> the time:
>>> >> >>
>>> >> >> gc 78 @253.095s 0
>>> %:
>>> 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>:
>>> >> >>>
>>> >> >>> 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,

Re: [go-nuts] Re: GC SW times on Heroku (Beta metrics)

2017-12-05 Thread rlh 
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  >:
>
>> Oh yeah, I forgot someone added that a while back. That should work.
>>
>> On Tue, Dec 5, 2017 at 6:23 PM, Henrik Johansson > > 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 > >:
>> >>
>> >> 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 > >
>> >> 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 > >:
>> >> >>
>> >> >> I have just added the gc tracing and it looks like this more or less
>> >> >> all
>> >> >> the time:
>> >> >>
>> >> >> gc 78 @253.095s 0 
>> %: 
>> 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 > >:
>> >> >>>
>> >> >>> 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
>> >> >>>  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 
>>

Re: [go-nuts] Re: GC SW times on Heroku (Beta metrics)

2017-12-04 Thread Henrik Johansson 
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 :

> Oh yeah, I forgot someone added that a while back. That should work.
>
> On Tue, Dec 5, 2017 at 6:23 PM, Henrik Johansson 
> 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 :
> >>
> >> 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 
> >> 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  >:
> >> >>
> >> >> I have just added the gc tracing and it looks like this more or less
> >> >> all
> >> >> the time:
> >> >>
> >> >> gc 78 @253.095s 0
> %:
> 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 <
> dahankz...@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
> >> >>>  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
> >> >

Re: [go-nuts] Re: GC SW times on Heroku (Beta metrics)

2017-12-04 Thread Henrik Johansson 
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 :

> 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 
> 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 :
> >>
> >> I have just added the gc tracing and it looks like this more or less all
> >> the time:
> >>
> >> gc 78 @253.095s 0%: 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 :
> >>>
> >>> 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
> >>>  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+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.

Re: [go-nuts] Re: GC SW times on Heroku (Beta metrics)

2017-12-04 Thread Dave Cheney 
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  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 :
>>
>> I have just added the gc tracing and it looks like this more or less all
>> the time:
>>
>> gc 78 @253.095s 0%: 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 :
>>>
>>> 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
>>>  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+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.

Re: [go-nuts] Re: GC SW times on Heroku (Beta metrics)

2017-12-04 Thread Henrik Johansson 
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 :

> I have just added the gc tracing and it looks like this more or less all
> the time:
>
> gc 78 @253.095s 0%: 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 :
>
>> 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 <
>> golang-nuts@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+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.

Re: [go-nuts] Re: GC SW times on Heroku (Beta metrics)

2017-12-04 Thread Henrik Johansson 
I have just added the gc tracing and it looks like this more or less all
the time:

gc 78 @253.095s 0%: 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 :

> 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 <
> golang-nuts@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+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.

Re: [go-nuts] Re: GC SW times on Heroku (Beta metrics)

2017-12-02 Thread Henrik Johansson 
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 
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+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.