<div dir="ltr">Hi Chris,<div class="gmail_extra"><br><div class="gmail_quote">On Fri, Nov 18, 2016 at 2:49 PM, Chris Muller <span dir="ltr"><<a href="mailto:ma.chris.m@gmail.com" target="_blank">ma.chris.m@gmail.com</a>></span> wrote:<br><blockquote class="gmail_quote" style="margin:0 0 0 .8ex;border-left:1px #ccc solid;padding-left:1ex"><div dir="ltr">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.<br><br>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<br><br>I put in some debugging statements into <a href="http://source.squeak.org" target="_blank">source.squeak.org</a>'s start-up initialization which give us essential VM information at each step, check it out.<br><br>===========<br><font color="#0000ff">*** First before doing anything, snapshot the VM parameters</font><br>2016-11-18T15:05:07.256516-06:<wbr>00 Virtual Machine Parameters<br>2016-11-18T15:05:07.25729-06:<wbr>00 --------------------------<br>2016-11-18T15:05:07.257693-06:<wbr>00 #1 118,531,328 size of old space<br>2016-11-18T15:05:07.257781-06:<wbr>00 #2 2,368,536 size of new space<br>2016-11-18T15:05:07.257838-06:<wbr>00 #3 125,304,832 size of heap<br>2016-11-18T15:05:07.258414-06:<wbr>00 #7 2 full GCs since startup<br>2016-11-18T15:05:07.258471-06:<wbr>00 #8 330 total milliseconds in full GCs since startup<br>2016-11-18T15:05:07.258521-06:<wbr>00 #9 72 scavenging GCs since startup<br>2016-11-18T15:05:07.258588-06:<wbr>00 #10 26 total milliseconds in scavenging GCs since startup<br>2016-11-18T15:05:07.258639-06:<wbr>00 #11 2,249 tenures of surving objects since startup<div><br></div><div><font color="#0000ff">*** Looks good, so load the SSRepository object and indexes from Magma</font></div><div>2016-11-18T15:05:07.258706-06:<wbr>00 Loading SSRepository...<br>2016-11-18T15:07:54.675452-06:<wbr>00 Loading Indexes...<br>2016-11-18T15:07:54.679669-06:<wbr>00 Virtual Machine Parameters<br>2016-11-18T15:07:54.679771-06:<wbr>00 --------------------------<br>2016-11-18T15:07:54.679842-06:<wbr>00 #1 806,397,184 size of old space<br>2016-11-18T15:07:54.679909-06:<wbr>00 #2 1,086,968 size of new space<br>2016-11-18T15:07:54.679985-06:<wbr>00 #3 813,170,688 size of heap<br>2016-11-18T15:07:54.680058-06:<wbr>00 #7 17 full GCs since startup<br>2016-11-18T15:07:54.680126-06:<wbr>00 #8 6,699 total milliseconds in full GCs since startup<br>2016-11-18T15:07:54.680191-06:<wbr>00 #9 8,977 scavenging GCs since startup<br>2016-11-18T15:07:54.680255-06:<wbr>00 #10 96,048 total milliseconds in scavenging GCs since startup<br>2016-11-18T15:07:54.680319-06:<wbr>00 #11 15,015,301 tenures of surving objects since startup</div><div><br></div><div><font color="#0000ff">*** 2 minutes since startup, so far so good, but now do a "Smalltalk garbageCollect"...</font></div><div>2016-11-18T15:07:54.680384-06:<wbr>00 Garbage collecting now...<br>2016-11-18T16:25:38.072284-06:<wbr>00 <font color="#cc0000"><b>0:01:17:43.39 to GC after initialization.</b></font><br>2016-11-18T16:25:38.075849-06:<wbr>00 Virtual Machine Parameters<br>2016-11-18T16:25:38.075949-06:<wbr>00 --------------------------<br>2016-11-18T16:25:38.076023-06:<wbr>00 #1 705,733,888 size of old space<br>2016-11-18T16:25:38.076092-06:<wbr>00 #2 694,752 size of new space<br>2016-11-18T16:25:38.076158-06:<wbr>00 #3 712,507,392 size of heap<br>2016-11-18T16:25:38.076227-06:<wbr>00 #7 18 full GCs since startup<br>2016-11-18T16:25:38.076297-06:<wbr>00 #8 4,670,088 total milliseconds in full GCs since startup<br>2016-11-18T16:25:38.076366-06:<wbr>00 #9 8,977 scavenging GCs since startup<br>2016-11-18T16:25:38.076434-06:<wbr>00 #10 96,048 total milliseconds in scavenging GCs since startup<br>2016-11-18T16:25:38.076506-06:<wbr>00 #11 15,015,301 tenures of surving objects since startup<br>2016-11-18T16:25:44.141442-06:<wbr>00 *** Checking integrity of the repository...</div><div>============</div><div><br></div><div>I *think* there is only one such of these super-long GC's, afterward it returns to normal, short GC times.</div><div><br></div><div>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.</div></div></blockquote><div><br></div><div>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.</div></div><br><div class="gmail_signature" data-smartmail="gmail_signature"><div dir="ltr"><div><span style="font-size:small;border-collapse:separate"><div>_,,,^..^,,,_<br></div><div>best, Eliot</div></span></div></div></div>
</div></div>