[Gc] Re: Understanding why GC'ing increases to the double in time?

Boehm, Hans hans.boehm at hp.com
Thu Mar 9 14:43:36 PST 2006


The only things I noticed where:

1) You seem to be running with a block size of 1K instead of the normal
4K.  That's probably good.  But if that's a consequence of the collector
having been configured with SMALL_CONFIG, it might be worth revisiting.
(It looks like that's not the case, but ...)

2) "long" log:
1024056 (atomic) + 1430164 (composite) collectable bytes in use

"short" log:
1007932 (atomic) + 806484 (composite) collectable bytes in use

There are about 640K more, or almost twice as many, composite
(pointer-containing) objects in the case of the longer pause times.  I'm
surprised that this makes that much of a difference, but it may,
depending on hardware characteristics, and on the pointer-density of
those extra objects.

The "atomic" (pointerfree) objects are not scanned.  And setting the
mark bits is likely to be relatively cheap, since they tend to be fairly
big.  The collector does have to scan 3MB of roots, which I would have
expected to cost more.  But most of those are not going to be pointers,
so each word just takes a load and a comparison or two.  And the loads
read memory sequentially, which is often a much better case, than
tracing pointer-containing objects in the heap.

If you really want to track this down further, you might be able to add
more detailed statistics to GC_print_block_descr (called by GC_dump())
to get a better handle on what the extra objects look like.  It wasn't
obvious to me from the heap dumps you included.

Hans

> -----Original Message-----
> From: gc-bounces at napali.hpl.hp.com 
> [mailto:gc-bounces at napali.hpl.hp.com] On Behalf Of Martin 
> Egholm Nielsen
> Sent: Thursday, March 09, 2006 2:23 AM
> To: gc at napali.hpl.hp.com
> Subject: [Gc] Re: Understanding why GC'ing increases to the 
> double in time?
> 
> Boehm -> ">>"
> Egholm -> ">"
> 
> >> Building the collector without SILENT defined will get you more 
> >> statistics, which might be useful.  In particular, it should be 
> >> possible to verify that the amount of live heap memory is not 
> >> drastically increasing.
> > I'll do that...
> And now, a month later, here goes. Attached is two log files, 
> with succeeding gc-dump information - one with short 
> worldstop-time and another with the long worldstop-time. 
> Below is a summary of these files, but also scanning the logs 
> does not make me able to see any big differences.
> 
> >> The collector is almost certainly spending it's time in mark_from.
> >> It would be mildly useful to confirm that. It would be 
> more useful to 
> >> confirm that this is not being called through the 
> finalization code.
> I reckon this still applies - I'll take a look into 
> GC_mark_from in a minute and see if I can measure the time 
> spent in there...
> 
> LOGS SUMMARY:
> =============
> 
> === From short ===
> ==================
> 
> Initiating full world-stop collection 21 after 2784036 allocd 
> bytes 0 bytes in heap blacklisted for interior pointers
> --> Marking for collection 21 after 2784036 allocd bytes + 
> 19052 wasted
> bytes
> Collection 20 reclaimed 2750772 bytes ---> heapsize = 6088704 
> bytes World-stopped marking took 230 msecs
> ---- 8< 8< 8< ----
> blocks = 4605, bytes = 5123072
> 
> ***Finalization statistics:
> 5021 finalization table entries; 12 disappearing links 0 
> objects are eligible for immediate finalization Bytes 
> recovered before sweep - f.l. count = -15344 Immediately 
> reclaimed 2237448 bytes in heap of size 6088704 bytes
> 1007932 (atomic) + 806484 (composite) collectable bytes in 
> use Finalize + initiate sweep took 660 + 20 msecs Complete 
> collection took 920 msecs
> 
> === From long ===
> =================
> 
> Initiating full world-stop collection 22 after 3314376 allocd 
> bytes 0 bytes in heap blacklisted for interior pointers
> --> Marking for collection 22 after 3314376 allocd bytes + 
> 27184 wasted
> bytes
> Collection 21 reclaimed 2843464 bytes ---> heapsize = 6088704 
> bytes World-stopped marking took 430 msecs
> ---- 8< 8< 8< ----
> blocks = 4374, bytes = 5645312
> 
> ***Finalization statistics:
> 5237 finalization table entries; 5 disappearing links 0 
> objects are eligible for immediate finalization Bytes 
> recovered before sweep - f.l. count = -13880 Immediately 
> reclaimed 2105796 bytes in heap of size 6088704 bytes
> 1024056 (atomic) + 1430164 (composite) collectable bytes in 
> use Finalize + initiate sweep took 690 + 20 msecs Complete 
> collection took 1160 msecs
> 
> 



More information about the Gc mailing list