Under what circumstances does GC trigger?

[Peter Vessenes]

Hi all, I'm running on tip, but this behaviour happens on 1.4.2 as well.

I have a long-running server program, and it makes (and then destroys) a lot of objects and then settles down. While I'm waiting around for 1.5's GC work to be done, I'm still trying to get the server in shape, and it has a few behaviours I don't understand; in particular, frequent GC runs with no input on the server side.

Here's some sample output from GODEBUG=gtrace=1:

gc1059(32): 1+114+404221+119 us, 62419 -> 62419 MB, 4443477 (2168576896-2164133419) objects, 8 goroutines, 10348105/198683/0 sweeps, 315(1876) handoff, 332(24345) steal, 4037/455/80539 yields                                                                                                     

gc1060(32): 662660+100+123886+73 us, 62419 -> 62419 MB, 4443477 (2168576896-2164133419) objects, 8 goroutines, 10348105/0/0 sweeps, 1(4) handoff, 230(14869) steal, 3294/310/25156 yields                                                                                                           

GC forced

gc1061(32): 1+118+466053+144 us, 62419 -> 62419 MB, 4443477 (2168576896-2164133419) objects, 8 goroutines, 10348105/198683/0 sweeps, 349(2118) handoff, 277(19996) steal, 4053/602/92093 yields                                                                                                     

gc1062(32): 725431+116+119396+187 us, 62419 -> 62419 MB, 4443477 (2168576896-2164133419) objects, 8 goroutines, 10348105/0/0 sweeps, 0(0) handoff, 245(12647) steal, 3286/310/24260 yields      

You'll note that I created and destroyed two billion objects or so on startup, leaving me with 4 million. The wait times are long, but I believe they'll go down  as debug info gets pulled out on the way to 1.5, and they will be distributed out through the cores in any event making for much lower stop-the-world pauses. 

I'm assuming gc1059 is the mark phase, and gc1060 is the sweep phase of the collector. What I don't understand though is why the GC is triggered; if I leave my server alone doing absolutely nothing, it will re-GC often, call it every minute to every few minutes? the GC doesn't log the timestamp, so I don't have precise numbers, but in this case the server was loaded 12 hours go, and has been idle for 11 hours, and has over 1000 GC's called. 

Note that there are no object differences between the two runs.

Can someone help me understand why the GC is force triggered under these circumstances?

[Dave Cheney]

Are you filtering these log files ? The most likely cause is the scavenger, which should also be outputting to the log with a svg prefix

[Peter Vessenes]

I am not filtering them, except in my post. :) Yes, each is preceded by a scavenger run: sample line:

scvg54: inuse: 62455, idle: 120133, sys: 182589, released: 120133, consumed: 62455 (MB)

Peter

[Dave Cheney]

That's your answer then. The scavenger will trigger a GC if one has not been performed in the last 300 seconds. I may be slightly wrong on those numbers, I do seem to always be a incorrect then talking about the behaviour of the scavenger, but suffice to say, it triggers the GC periodically so that heap pages are free (of live data) so that it may return them to the operating system (on its next run)

[Peter Vessenes]

Thanks.

For my use case, seems like running the first phase and then punting if there's no major changes would save a lot of stop the world time. Or just turning this off; the scavenger isn't the only thing that will trigger a GC, is it?

Can it just scavenge what was previously freed, without doing the free? That would let me chew up memory as I see fit and not worry about the stops so often if nothing is happening.

--
You received this message because you are subscribed to a topic in the Google Groups "golang-nuts" group.
To unsubscribe from this topic, visit https://groups.google.com/d/topic/golang-nuts/_uWOKYFFyXc/unsubscribe.
To unsubscribe from this group and all its topics, send an email to golang-nuts...@googlegroups.com.
For more options, visit https://groups.google.com/d/optout.

--

---

PETER VESSENES 
CEO

pe...@coinlab.com  /  206.486.6856  / SKYPE: vessenes 
900 Winslow Way East / SUITE 100  /  Bainbridge Island, WA 98110

[Dave Cheney]

On 24 Mar 2015 08:06, "Peter Vessenes" <pe...@coinlab.com> wrote:
>
> Thanks.
>
> For my use case, seems like running the first phase and then punting if there's no major changes would save a lot of stop the world time. Or just turning this off; the scavenger isn't the only thing that will trigger a GC, is it?
>

There may be an environment variable for this, I don't know it.

> Can it just scavenge what was previously freed, without doing the free? That would let me chew up memory as I see fit and not worry about the stops so often if nothing is happening.

If no gc cycle is run, then nothing will be freed. That's the problem with this line of argument. The scavenger relies on the gc to free allocations on a page size piece of memory so it can advise the OS that the contents are not needed.

>
> On Fri, Mar 20, 2015 at 5:39 PM, Dave Cheney <da...@cheney.net> wrote:
>>
>> That's your answer then. The scavenger will trigger a GC if one has not been performed in the last 300 seconds. I may be slightly wrong on those numbers, I do seem to always be a incorrect then talking about the behaviour of the scavenger, but suffice to say, it triggers the GC periodically so that heap pages are free (of live data) so that it may return them to the operating system (on its next run)
>>
>>
>> On Saturday, 21 March 2015 09:34:54 UTC+11, Peter Vessenes wrote:
>>>
>>> I am not filtering them, except in my post. :) Yes, each is preceded by a scavenger run: sample line:
>>>
>>> scvg54: inuse: 62455, idle: 120133, sys: 182589, released: 120133, consumed: 62455 (MB)
>>>
>>>
>>> Peter
>>>
>>> On Friday, March 20, 2015 at 3:12:20 PM UTC-7, Dave Cheney wrote:
>>>>
>>>> Are you filtering these log files ? The most likely cause is the scavenger, which should also be outputting to the log with a svg prefix
>>
>> --
>> You received this message because you are subscribed to a topic in the Google Groups "golang-nuts" group.
>> To unsubscribe from this topic, visit https://groups.google.com/d/topic/golang-nuts/_uWOKYFFyXc/unsubscribe.
>> To unsubscribe from this group and all its topics, send an email to golang-nuts...@googlegroups.com.
>> For more options, visit https://groups.google.com/d/optout.
>
>
>
>
> --
>
> ________________________________
>

[Peter Vessenes]

On Mon, Mar 23, 2015 at 2:37 PM, Dave Cheney <da...@cheney.net> wrote:

On 24 Mar 2015 08:06, "Peter Vessenes" <pe...@coinlab.com> wrote:
>
> Thanks.
>
> For my use case, seems like running the first phase and then punting if there's no major changes would save a lot of stop the world time. Or just turning this off; the scavenger isn't the only thing that will trigger a GC, is it?
>

There may be an environment variable for this, I don't know it.

> Can it just scavenge what was previously freed, without doing the free? That would let me chew up memory as I see fit and not worry about the stops so often if nothing is happening.

If no gc cycle is run, then nothing will be freed. That's the problem with this line of argument. The scavenger relies on the gc to free allocations on a page size piece of memory so it can advise the OS that the contents are not needed.

Right, but a server doing nothing is not allocating (much); if we want the server to be greedy or prefer uninterrupted availability, perhaps the scavenger just takes what it's given. the GC would presumably still be run when memory allocations exceed some threshold. To my mind, I'd like to make that call as the server developer; I'm not complaining about the default behavior particularly, and if it happened in 50ms chunks with no perceivable downtime, I wouldn't complain at all. As it is, it happens in 1 to 5 second chunks very often. 

>
> On Fri, Mar 20, 2015 at 5:39 PM, Dave Cheney <da...@cheney.net> wrote:
>>
>> That's your answer then. The scavenger will trigger a GC if one has not been performed in the last 300 seconds. I may be slightly wrong on those numbers, I do seem to always be a incorrect then talking about the behaviour of the scavenger, but suffice to say, it triggers the GC periodically so that heap pages are free (of live data) so that it may return them to the operating system (on its next run)
>>
>>
>> On Saturday, 21 March 2015 09:34:54 UTC+11, Peter Vessenes wrote:
>>>
>>> I am not filtering them, except in my post. :) Yes, each is preceded by a scavenger run: sample line:
>>>
>>> scvg54: inuse: 62455, idle: 120133, sys: 182589, released: 120133, consumed: 62455 (MB)
>>>
>>>
>>> Peter
>>>
>>> On Friday, March 20, 2015 at 3:12:20 PM UTC-7, Dave Cheney wrote:
>>>>
>>>> Are you filtering these log files ? The most likely cause is the scavenger, which should also be outputting to the log with a svg prefix
>>
>> --
>> You received this message because you are subscribed to a topic in the Google Groups "golang-nuts" group.
>> To unsubscribe from this topic, visit https://groups.google.com/d/topic/golang-nuts/_uWOKYFFyXc/unsubscribe.
>> To unsubscribe from this group and all its topics, send an email to golang-nuts...@googlegroups.com.
>> For more options, visit https://groups.google.com/d/optout.
>
>
>
>
> --
>
> ________________________________
>
> PETER VESSENES 
> CEO
>
> pe...@coinlab.com  /  206.486.6856  / SKYPE: vessenes 
> 900 Winslow Way East / SUITE 100  /  Bainbridge Island, WA 98110

--

---

PETER VESSENES 
CEO

[Dave Cheney]

On 24 Mar 2015 08:45, "Peter Vessenes" <pe...@coinlab.com> wrote:
>
>
>
> On Mon, Mar 23, 2015 at 2:37 PM, Dave Cheney <da...@cheney.net> wrote:
>>
>>
>> On 24 Mar 2015 08:06, "Peter Vessenes" <pe...@coinlab.com> wrote:
>> >
>> > Thanks.
>> >
>> > For my use case, seems like running the first phase and then punting if there's no major changes would save a lot of stop the world time. Or just turning this off; the scavenger isn't the only thing that will trigger a GC, is it?
>> >
>>
>> There may be an environment variable for this, I don't know it.
>>
>> > Can it just scavenge what was previously freed, without doing the free? That would let me chew up memory as I see fit and not worry about the stops so often if nothing is happening.
>>
>> If no gc cycle is run, then nothing will be freed. That's the problem with this line of argument. The scavenger relies on the gc to free allocations on a page size piece of memory so it can advise the OS that the contents are not needed.
>
> Right, but a server doing nothing is not allocating (much); if we want the server to be greedy or prefer uninterrupted availability, perhaps the scavenger just takes what it's given. the GC would presumably still be run when memory allocations exceed some threshold. To my mind, I'd like to make that call as the server developer; I'm not complaining about the default behavior particularly, and if it happened in 50ms chunks with no perceivable downtime, I wouldn't complain at all. As it is, it happens in 1 to 5 second chunks very often. 

If a server is doing nothing then does time spent on housekeeping matter?

The general philosophy of the go runtime is to eschew knobs and dials and choose sensible defaults that work for the majority case. I suggest raising a bug. There may be a way to disable the scavenger but I don't know it.

You may also want to try GOGC=off and see the effect it has on your application.

[Peter Vessenes]

On Mon, Mar 23, 2015 at 2:50 PM, Dave Cheney <da...@cheney.net> wrote:

On 24 Mar 2015 08:45, "Peter Vessenes" <pe...@coinlab.com> wrote:
>
>
>
> On Mon, Mar 23, 2015 at 2:37 PM, Dave Cheney <da...@cheney.net> wrote:
>>
>>
>> On 24 Mar 2015 08:06, "Peter Vessenes" <pe...@coinlab.com> wrote:
>> >
>> > Thanks.
>> >
>> > For my use case, seems like running the first phase and then punting if there's no major changes would save a lot of stop the world time. Or just turning this off; the scavenger isn't the only thing that will trigger a GC, is it?
>> >
>>
>> There may be an environment variable for this, I don't know it.
>>
>> > Can it just scavenge what was previously freed, without doing the free? That would let me chew up memory as I see fit and not worry about the stops so often if nothing is happening.
>>
>> If no gc cycle is run, then nothing will be freed. That's the problem with this line of argument. The scavenger relies on the gc to free allocations on a page size piece of memory so it can advise the OS that the contents are not needed.
>
> Right, but a server doing nothing is not allocating (much); if we want the server to be greedy or prefer uninterrupted availability, perhaps the scavenger just takes what it's given. the GC would presumably still be run when memory allocations exceed some threshold. To my mind, I'd like to make that call as the server developer; I'm not complaining about the default behavior particularly, and if it happened in 50ms chunks with no perceivable downtime, I wouldn't complain at all. As it is, it happens in 1 to 5 second chunks very often. 

If a server is doing nothing then does time spent on housekeeping matter?

The general philosophy of the go runtime is to eschew knobs and dials and choose sensible defaults that work for the majority case. I suggest raising a bug. There may be a way to disable the scavenger but I don't know it.

You may also want to try GOGC=off and see the effect it has on your application.

Thanks Dave. I'm probably wait and see right now how 1.5's work turns out; it's enough to understand the source at this point. I agree with your perspective that the long runtimes are the thing bugging me, not the frequency of scavenging, per-se. I also agree that reducing cognitive load is one of the many benefits of using go, so my first response isn't "more options for scavenging!" 

But, I do maintain a small patchset already for our tool, and some adjustments might go in there. In answer to your question on GOGC=off, the total lifetime memory allocation is well in excess of our server RAM, on the order of 300-500GB, so we do need that collection. I would LOVE to be able to turn off GC during certain phases of the server lifecycle, though, then turn it back on later. Can this be done, to your knowledge? I don't know how to fake commandline settings to the runtime like that, if there is in fact a way.

Peter 

--

---

PETER VESSENES 
CEO

[Carlos Castillo]

http://golang.org/pkg/runtime/debug/#SetGCPercent ... it's essentially the same knob that the GOGC env variable adjusts. I don't know how it affects the scavenger, or if there is a direct way to affect it.

Be careful, if you're not mostly sure of where and how your code allocates memory you're just asking for a OOM panic (or heavy thrashing) should you turn off GC.

[Peter Vessenes]

On Tue, Mar 24, 2015 at 12:04 AM, Carlos Castillo <cook...@gmail.com> wrote:

http://golang.org/pkg/runtime/debug/#SetGCPercent ... it's essentially the same knob that the GOGC env variable adjusts. I don't know how it affects the scavenger, or if there is a direct way to affect it.

Be careful, if you're not mostly sure of where and how your code allocates memory you're just asking for a OOM panic (or heavy thrashing) should you turn off GC.

Right, we do use that feature, although from the command line, it's nice to know there's a runtime twiddle for it. But GOGC=off is a totally different codepath I think; at least the docs don't make clear how to get there with an int in the function call. 

Best,

Peter

[Carlos Castillo]

RTFM (eg: click on the link).

"A negative percentage disables garbage collection."

[Peter Vessenes]

Shit, sorry! I did read, but not carefully enough, clearly.