Hi Chris,

On Fri, Nov 18, 2016 at 2:49 PM, Chris Muller <ma.chris.m at gmail.com> 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
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.squeakfoundation.org/pipermail/squeak-dev/attachments/20161118/cf1af47b/attachment.html>