>1 hour to garbage collect

Previous Topic Next Topic
 
classic Classic list List threaded Threaded
2 messages Options
Reply | Threaded
Open this post in threaded view
|

>1 hour to garbage collect

Chris Muller-4
I finally figured out what I thought was a bug in my own code was actually just exposing something about Spur which I had never experienced before -- *incredibly* long time for it to garbage collect.

I kept thinking the image was locking up, but in fact it was just doing a GC and does eventually come back.  But, clearly, something has GOT to be wrong here...  Eliot?   Should GC take

I put in some debugging statements into source.squeak.org's start-up initialization which give us essential VM information at each step, check it out.

===========
*** First before doing anything, snapshot the VM parameters
2016-11-18T15:05:07.256516-06:00 Virtual Machine Parameters
2016-11-18T15:05:07.25729-06:00 --------------------------
2016-11-18T15:05:07.257693-06:00 #1 118,531,328 size of old space
2016-11-18T15:05:07.257781-06:00 #2 2,368,536 size of new space
2016-11-18T15:05:07.257838-06:00 #3 125,304,832 size of heap
2016-11-18T15:05:07.258414-06:00 #7 2 full GCs since startup
2016-11-18T15:05:07.258471-06:00 #8 330 total milliseconds in full GCs since startup
2016-11-18T15:05:07.258521-06:00 #9 72 scavenging GCs since startup
2016-11-18T15:05:07.258588-06:00 #10 26 total milliseconds in scavenging GCs since startup
2016-11-18T15:05:07.258639-06:00 #11 2,249 tenures of surving objects since startup

*** Looks good, so load the SSRepository object and indexes from Magma
2016-11-18T15:05:07.258706-06:00 Loading SSRepository...
2016-11-18T15:07:54.675452-06:00 Loading Indexes...
2016-11-18T15:07:54.679669-06:00 Virtual Machine Parameters
2016-11-18T15:07:54.679771-06:00 --------------------------
2016-11-18T15:07:54.679842-06:00 #1 806,397,184 size of old space
2016-11-18T15:07:54.679909-06:00 #2 1,086,968 size of new space
2016-11-18T15:07:54.679985-06:00 #3 813,170,688 size of heap
2016-11-18T15:07:54.680058-06:00 #7 17 full GCs since startup
2016-11-18T15:07:54.680126-06:00 #8 6,699 total milliseconds in full GCs since startup
2016-11-18T15:07:54.680191-06:00 #9 8,977 scavenging GCs since startup
2016-11-18T15:07:54.680255-06:00 #10 96,048 total milliseconds in scavenging GCs since startup
2016-11-18T15:07:54.680319-06:00 #11 15,015,301 tenures of surving objects since startup

*** 2 minutes since startup, so far so good, but now do a "Smalltalk garbageCollect"...
2016-11-18T15:07:54.680384-06:00 Garbage collecting now...
2016-11-18T16:25:38.072284-06:00 0:01:17:43.39 to GC after initialization.
2016-11-18T16:25:38.075849-06:00 Virtual Machine Parameters
2016-11-18T16:25:38.075949-06:00 --------------------------
2016-11-18T16:25:38.076023-06:00 #1 705,733,888 size of old space
2016-11-18T16:25:38.076092-06:00 #2 694,752 size of new space
2016-11-18T16:25:38.076158-06:00 #3 712,507,392 size of heap
2016-11-18T16:25:38.076227-06:00 #7 18 full GCs since startup
2016-11-18T16:25:38.076297-06:00 #8 4,670,088 total milliseconds in full GCs since startup
2016-11-18T16:25:38.076366-06:00 #9 8,977 scavenging GCs since startup
2016-11-18T16:25:38.076434-06:00 #10 96,048 total milliseconds in scavenging GCs since startup
2016-11-18T16:25:38.076506-06:00 #11 15,015,301 tenures of surving objects since startup
2016-11-18T16:25:44.141442-06:00 *** Checking integrity of the repository...
============

I *think* there is only one such of these super-long GC's, afterward it returns to normal, short GC times.

So, I guess I will move forward with deploying my latest code which I thought was locking the image, but apparently not.  But this super-long GC is problematic in any case.  Eliot, is there any case for Spur to take so long and report those numbers which I could avoid?  In years of using Spur, I've never actually noticed this issue before...  I'm really puzzled.


Reply | Threaded
Open this post in threaded view
|

Re: >1 hour to garbage collect

Eliot Miranda-2
Hi Chris,

On Fri, Nov 18, 2016 at 2:49 PM, Chris Muller <[hidden email]> wrote:
I finally figured out what I thought was a bug in my own code was actually just exposing something about Spur which I had never experienced before -- *incredibly* long time for it to garbage collect.

I kept thinking the image was locking up, but in fact it was just doing a GC and does eventually come back.  But, clearly, something has GOT to be wrong here...  Eliot?   Should GC take

I put in some debugging statements into source.squeak.org's start-up initialization which give us essential VM information at each step, check it out.

===========
*** First before doing anything, snapshot the VM parameters
2016-11-18T15:05:07.256516-06:00 Virtual Machine Parameters
2016-11-18T15:05:07.25729-06:00 --------------------------
2016-11-18T15:05:07.257693-06:00 #1 118,531,328 size of old space
2016-11-18T15:05:07.257781-06:00 #2 2,368,536 size of new space
2016-11-18T15:05:07.257838-06:00 #3 125,304,832 size of heap
2016-11-18T15:05:07.258414-06:00 #7 2 full GCs since startup
2016-11-18T15:05:07.258471-06:00 #8 330 total milliseconds in full GCs since startup
2016-11-18T15:05:07.258521-06:00 #9 72 scavenging GCs since startup
2016-11-18T15:05:07.258588-06:00 #10 26 total milliseconds in scavenging GCs since startup
2016-11-18T15:05:07.258639-06:00 #11 2,249 tenures of surving objects since startup

*** Looks good, so load the SSRepository object and indexes from Magma
2016-11-18T15:05:07.258706-06:00 Loading SSRepository...
2016-11-18T15:07:54.675452-06:00 Loading Indexes...
2016-11-18T15:07:54.679669-06:00 Virtual Machine Parameters
2016-11-18T15:07:54.679771-06:00 --------------------------
2016-11-18T15:07:54.679842-06:00 #1 806,397,184 size of old space
2016-11-18T15:07:54.679909-06:00 #2 1,086,968 size of new space
2016-11-18T15:07:54.679985-06:00 #3 813,170,688 size of heap
2016-11-18T15:07:54.680058-06:00 #7 17 full GCs since startup
2016-11-18T15:07:54.680126-06:00 #8 6,699 total milliseconds in full GCs since startup
2016-11-18T15:07:54.680191-06:00 #9 8,977 scavenging GCs since startup
2016-11-18T15:07:54.680255-06:00 #10 96,048 total milliseconds in scavenging GCs since startup
2016-11-18T15:07:54.680319-06:00 #11 15,015,301 tenures of surving objects since startup

*** 2 minutes since startup, so far so good, but now do a "Smalltalk garbageCollect"...
2016-11-18T15:07:54.680384-06:00 Garbage collecting now...
2016-11-18T16:25:38.072284-06:00 0:01:17:43.39 to GC after initialization.
2016-11-18T16:25:38.075849-06:00 Virtual Machine Parameters
2016-11-18T16:25:38.075949-06:00 --------------------------
2016-11-18T16:25:38.076023-06:00 #1 705,733,888 size of old space
2016-11-18T16:25:38.076092-06:00 #2 694,752 size of new space
2016-11-18T16:25:38.076158-06:00 #3 712,507,392 size of heap
2016-11-18T16:25:38.076227-06:00 #7 18 full GCs since startup
2016-11-18T16:25:38.076297-06:00 #8 4,670,088 total milliseconds in full GCs since startup
2016-11-18T16:25:38.076366-06:00 #9 8,977 scavenging GCs since startup
2016-11-18T16:25:38.076434-06:00 #10 96,048 total milliseconds in scavenging GCs since startup
2016-11-18T16:25:38.076506-06:00 #11 15,015,301 tenures of surving objects since startup
2016-11-18T16:25:44.141442-06:00 *** Checking integrity of the repository...
============

I *think* there is only one such of these super-long GC's, afterward it returns to normal, short GC times.

So, I guess I will move forward with deploying my latest code which I thought was locking the image, but apparently not.  But this super-long GC is problematic in any case.  Eliot, is there any case for Spur to take so long and report those numbers which I could avoid?  In years of using Spur, I've never actually noticed this issue before...  I'm really puzzled.

I know that the compaction algorithm in global GC is, um, sub-optimal.  But this is an extraordinarily long time.  Is there any way you can send me a snapshot of the image (with a changes file) immediately before the GC (I guess not; snapshot involves a huge GC).  OK, is there some way I can reproduce this to profile?  I'm intending to implement a new compaction algorithm before years' end and it would be good to have this example as a test case, both to understand the old algorithm and to stress the new one.

_,,,^..^,,,_
best, Eliot