compaction reporting in ibm's verbose gc log

[peter.doyle]

all,

here's a snippet from an ibm verbose gc log ...

<AF[226]: Allocation Failure. need 528 bytes, 82818 ms since last AF>
<AF[226]: managing allocation failure, action=1 (0/530963816)
(5128264/5905560)>
<GC(226): mark stack overflow[225]>
<GC(226): GC cycle started Mon Feb 14 12:26:03 2005
<GC(226): freed 369385864 bytes, 69% free (374514128/536869376), in
317 ms>
<GC(226): mark: 284 ms, sweep: 32 ms, compact: 1 ms>
<GC(226): refs: soft 3 (age >= 32), weak 1, final 558, phantom 0>
<AF[226]: completed in 319 ms>

and here are my questions ...

1. compaction is not trivial - what did the collector do in this 1ms ?
2. why is there no "moved" line showing numbers of objects and bytes
moved during the compaction, and the reason for the compaction ?

all suggstions appreciated - thanks,

peter.

 

[John C. Bollinger]

all,

here's a snippet from an ibm verbose gc log ...

<AF[226]: Allocation Failure. need 528 bytes, 82818 ms since last AF>
<AF[226]: managing allocation failure, action=1 (0/530963816)
(5128264/5905560)>
<GC(226): mark stack overflow[225]>
<GC(226): GC cycle started Mon Feb 14 12:26:03 2005
<GC(226): freed 369385864 bytes, 69% free (374514128/536869376), in
317 ms>
<GC(226): mark: 284 ms, sweep: 32 ms, compact: 1 ms>
<GC(226): refs: soft 3 (age >= 32), weak 1, final 558, phantom 0>
<AF[226]: completed in 319 ms>

and here are my questions ...

1. compaction is not trivial - what did the collector do in this 1ms ?

Compaction certainly is trivial if the GC decides not to perform it on
a particular pass, which is what I would guess happened here. Clever
allocation and GC strategy can greatly reduce the need to perform heap
compaction.

I would be much more concerned that my application was discarding nearly
370MB (!) worth of objects in less than a minute and a half. I hope
you're getting a lot of work done for all that memory usage, but since
you're looking at GC logs I suspect you are trying to trace down a
performance problem.

2. why is there no "moved" line showing numbers of objects and bytes
moved during the compaction, and the reason for the compaction ?

See above. There may be no "moved" because there was no compaction.

 

[peter.doyle]

thanks john

your guess certainly fits what i'm seeing - have you seen it documented
at this level anywhere ? i've looked through a bunch of ibm sites and
documents without finding anything at this level of detail.

are you very familiar with garbage collection in the ibm jvm ? i ask
because i recently posted a question regarding thread stop/start times
- i had one reply which didn't resolve the question

regarding the discarding of large volumes of garbage, the output is
from a long-running server application which supports hundreds of
call-centre users - at times it turns over much faster than that

the reason i'm looking into the verbose output is that i'm working on
some scripts to summarise the output into small reports

pete.

 

[John C. Bollinger]

your guess certainly fits what i'm seeing - have you seen it documented
at this level anywhere ? i've looked through a bunch of ibm sites and
documents without finding anything at this level of detail.

are you very familiar with garbage collection in the ibm jvm ? i ask
because i recently posted a question regarding thread stop/start times
- i had one reply which didn't resolve the question

No, I'm afraid I don't have any special knowledge of IBM's GC
implementation. And you may indeed not find much documentation -- or at
least not find it easily. Such information falls into the
"implementation details" category, and as such it is rarely prominent
(and is subject to change).

regarding the discarding of large volumes of garbage, the output is
from a long-running server application which supports hundreds of
call-centre users - at times it turns over much faster than that

Well at least GC seems to occupy a pretty minor component of the total
clock time consumed. If it ain't broke, don't fix it.

the reason i'm looking into the verbose output is that i'm working on
some scripts to summarise the output into small reports

Ah, that makes sense. Unfortunately, I'm not going to be much help in
that regard.