Re: [go-nuts] Excessive garbage collection

[Jiří Šimša]

Thank you for your explanation.

I was able to track this problem down to logic in one of the handlers
periodically invoked by the page; the handler logic would result in the
allocation pattern you described.

Best,

--
Jiří Šimša

On Tue, Oct 18, 2016 at 6:13 AM,  wrote:

> From the trace (4->4->0) it looks like the app is allocating about 4MB
> every 10ms. The app also has little (0 rounded) reachable data, sometimes
> called heap ballast. Since there is little ballast the GC is attempting to
> keep the heap from growing beyond 5MB. The GC is using about 2% of the CPU
> resources to do its job.
>
> All of this seems perfectly reasonable from the GC's perspective.
>
>
> On Tuesday, October 18, 2016 at 12:32:47 AM UTC-4, Jiří Šimša wrote:
>>
>> go version go1.7.1 darwin/amd64
>>
>> --
>> Jiří Šimša
>>
>> On Mon, Oct 17, 2016 at 8:02 PM, Ian Lance Taylor 
>> wrote:
>>
>>> On Mon, Oct 17, 2016 at 6:20 PM,   wrote:
>>> >
>>> > The backend of my web server (written in Go) have recently started
>>> consuming
>>> > large amounts of CPU. AFAICT, the CPU seems to be consumed by the
>>> garbage
>>> > collector and I would appreciate any information that would help me
>>> track
>>> > down the root cause.
>>>
>>> What version of Go?  What platform?
>>>
>>> Ian
>>>
>>
>>

-- 
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] Excessive garbage collection

[rlh]

>From the trace (4->4->0) it looks like the app is allocating about 4MB 
every 10ms. The app also has little (0 rounded) reachable data, sometimes 
called heap ballast. Since there is little ballast the GC is attempting to 
keep the heap from growing beyond 5MB. The GC is using about 2% of the CPU 
resources to do its job. 

All of this seems perfectly reasonable from the GC's perspective.


On Tuesday, October 18, 2016 at 12:32:47 AM UTC-4, Jiří Šimša wrote:
>
> go version go1.7.1 darwin/amd64
>
> --
> Jiří Šimša
>
> On Mon, Oct 17, 2016 at 8:02 PM, Ian Lance Taylor  > wrote:
>
>> On Mon, Oct 17, 2016 at 6:20 PM,   
>> wrote:
>> >
>> > The backend of my web server (written in Go) have recently started 
>> consuming
>> > large amounts of CPU. AFAICT, the CPU seems to be consumed by the 
>> garbage
>> > collector and I would appreciate any information that would help me 
>> track
>> > down the root cause.
>>
>> What version of Go?  What platform?
>>
>> Ian
>>
>
>

-- 
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] Excessive garbage collection

[Jiří Šimša]

go version go1.7.1 darwin/amd64

--
Jiří Šimša

On Mon, Oct 17, 2016 at 8:02 PM, Ian Lance Taylor  wrote:

> On Mon, Oct 17, 2016 at 6:20 PM,   wrote:
> >
> > The backend of my web server (written in Go) have recently started
> consuming
> > large amounts of CPU. AFAICT, the CPU seems to be consumed by the garbage
> > collector and I would appreciate any information that would help me track
> > down the root cause.
>
> What version of Go?  What platform?
>
> Ian
>

-- 
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] Excessive garbage collection

[Ian Lance Taylor]

On Mon, Oct 17, 2016 at 6:20 PM,   wrote:
>
> The backend of my web server (written in Go) have recently started consuming
> large amounts of CPU. AFAICT, the CPU seems to be consumed by the garbage
> collector and I would appreciate any information that would help me track
> down the root cause.

What version of Go?  What platform?

Ian

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

[go-nuts] Excessive garbage collection

[jiri . simsa]

Hello,

The backend of my web server (written in Go) have recently started 
consuming large amounts of CPU. AFAICT, the CPU seems to be consumed by the 
garbage collector and I would appreciate any information that would help me 
track down the root cause.

When I run the web server with gctrace=1, I see the following trace:

gc 1 @6.033s 0%: 0.096+0.92+0.053 ms clock, 0.19+0.056/0.51/0.89+0.10 ms cpu, 
4->4->0 MB, 5 MB goal, 2 P
gc 2 @19.072s 0%: 0.010+0.89+0.043 ms clock, 0.021+0.015/0.55/0.67+0.086 ms 
cpu, 4->4->0 MB, 5 MB goal, 2 P
gc 3 @32.111s 0%: 0.031+0.95+0.051 ms clock, 0.062+0/0.80/0.38+0.10 ms cpu, 
4->4->0 MB, 5 MB goal, 2 P
gc 4 @45.151s 0%: 0.098+0.80+0.28 ms clock, 0.19+0/0.44/0.77+0.57 ms cpu, 
4->4->0 MB, 5 MB goal, 2 P
gc 5 @58.193s 0%: 0.010+1.1+0.045 ms clock, 0.020+0.050/0.33/1.0+0.090 ms cpu, 
4->4->0 MB, 5 MB goal, 2 P
gc 6 @71.235s 0%: 0.026+0.73+0.056 ms clock, 0.053+0/0.72/0.42+0.11 ms cpu, 
4->4->0 MB, 5 MB goal, 2 P


In particular, garbage collection happens every 10-15 seconds. Now when I 
use a browser to navigate to a page that triggers the odd behavior, I see 
the following trace:

gc 7640 @187.367s 1%: 0.007+0.66+0.23 ms clock, 0.014+0.008/0.35/0.62+0.47 ms 
cpu, 4->4->0 MB, 5 MB goal, 2 P
gc 7641 @187.376s 1%: 0.007+0.56+0.23 ms clock, 0.014+0.008/0.46/0.53+0.46 ms 
cpu, 4->4->0 MB, 5 MB goal, 2 P
gc 7642 @187.386s 1%: 0.008+0.63+0.24 ms clock, 0.016+0.008/0.59/0.35+0.49 ms 
cpu, 4->4->0 MB, 5 MB goal, 2 P
gc 7643 @187.395s 1%: 0.008+0.61+0.28 ms clock, 0.016+0.009/0.37/0.58+0.56 ms 
cpu, 4->4->0 MB, 5 MB goal, 2 P
gc 7644 @187.405s 1%: 0.009+0.55+0.030 ms clock, 0.018+0.009/0.46/0.52+0.060 ms 
cpu, 4->4->0 MB, 5 MB goal, 2 P
gc 7645 @187.414s 2%: 0.008+0.56+0.25 ms clock, 0.017+0.008/0.47/0.52+0.51 ms 
cpu, 4->4->0 MB, 5 MB goal, 2 P
gc 7646 @187.424s 2%: 0.008+0.69+0.017 ms clock, 0.016+0.008/0.66/0.36+0.034 ms 
cpu, 4->4->0 MB, 5 MB goal, 2 P
gc 7647 @187.433s 2%: 0.008+0.61+0.018 ms clock, 0.017+0.008/0.35/0.60+0.037 ms 
cpu, 4->4->0 MB, 5 MB goal, 2 P
gc 7648 @187.442s 2%: 0.008+0.67+0.26 ms clock, 0.017+0.008/0.65/0.38+0.52 ms 
cpu, 4->4->0 MB, 5 MB goal, 2 P
gc 7649 @187.452s 2%: 0.008+0.65+0.24 ms clock, 0.016+0.008/0.36/0.61+0.48 ms 
cpu, 4->4->0 MB, 5 MB goal, 2 P


In particular, garbage collection happens every 10 ms. The page that 
triggers this behavior periodically fetches and displays some in-memory 
state from the backend and the excessive GC behavior continues even after 
the page that triggers the behavior is closed.

I should add that the web server backend has multiple goroutines running in 
the background performing periodic activity, but none of the background 
activity is triggered or influenced by the incoming HTTP request for the 
culprit page.

Any suggestions as to what steps I can take to investigate this problem 
further would be greatly appreciated. 

I am happy to provide more details about the implementation of the web 
server but I am not sure what else could be relevant.

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.