understanding GC logs

[Jon Masamitsu]

Shaun,

I'm going to answer over several replies.  Here are
the first 2 answers.

On 04/14/10 13:29, Shaun Hennessy wrote:
> Still working on log output w/ different releases / log options,
> but a few other follow up questions on the substance
>
>>>
>>> - Promotion Failure
>>> 4896.478: [GC 4896.478: [ParNew: 4894353K->587864K(5017600K), 
>>> 0.4789909 secs] 8473688K->4268560K(13619200K), 0.4791812 secs] 
>>> [Times: user=1.00 sys=0.61, real=0.48 secs]
>>> 4897.812: [GC 4897.812: [ParNew: 4888664K->545903K(5017600K), 
>>> 0.4105613 secs] 8569360K->4326583K(13619200K), 0.4107560 secs] 
>>> [Times: user=1.06 sys=0.55, real=0.41 secs]
>>> 4899.057: [GC 4899.058: [ParNew: 4846703K->638966K(5017600K), 
>>> 0.2759734 secs] 8627383K->4496987K(13619200K), 0.2761637 secs] 
>>> [Times: user=1.13 sys=0.36, real=0.28 secs]
>>> 4900.101: [GC 4900.101: [ParNew: 4939768K->630721K(5017600K), 
>>> 0.5117751 secs] 8797789K->4607020K(13619200K), 0.5119662 secs] 
>>> [Times: user=0.84 sys=0.66, real=0.51 secs]
>>> 4900.615: [GC 4900.615: [ParNew: 651487K->487288K(5017600K), 
>>> 0.0780183 secs] 4627786K->4463587K(13619200K), 0.0781687 secs] 
>>> [Times: user=0.96 sys=0.00, real=0.08 secs]
>>> *4901.581: [GC 4901.581: [ParNew (promotion failed): 
>>> 4788088K->4780999K(5017600K), 2.8947499 secs]4904.476: [CMS: 
>>> 4003090K->1530872K(8601600K), 7.5122451 secs] 
>>> 8764387K->1530872K(13619200K), [CMS Perm : 
>>> 671102K->671102K(819200K)], 10.4072102 secs] [Times: user=11.03 
>>> sys=1.09, real=10.41 secs]*
>>> 4913.024: [GC 4913.024: [ParNew: 4300800K->316807K(5017600K), 
>>> 0.0615917 secs] 5831672K->1847679K(13619200K), 0.0617857 secs] 
>>> [Times: user=0.74 sys=0.00, real=0.06 secs]
>>> 4914.015: [GC 4914.015: [ParNew: 4617607K->475077K(5017600K), 
>>> 0.0771389 secs] 6148479K->2005949K(13619200K), 0.0773290 secs] 
>>> [Times: user=0.95 sys=0.00, real=0.08 secs]
>>> 4914.908: [GC 4914.908: [ParNew: 4775877K->586339K(5017600K), 
>>> 0.0857102 secs] 6306749K->2117211K(13619200K), 0.0859046 secs] 
>>> [Times: user=1.06 sys=0.00, real=0.09 secs]
>>> 4915.816: [GC 4915.816: [ParNew: 4887139K->476398K(5017600K), 
>>> 0.1841627 secs] 6418011K->2152868K(13619200K), 0.1843556 secs] 
>>> [Times: user=1.32 sys=0.07, real=0.18 secs]
>>
>>> 8) What exactly is occurring during this promotion failed 
>>> collection?  Based on the next example I assume
>>>   it's a (successful) scavenge.  What exactly is this - which 
>>> thread(s) serial / ParallelGCThreads?,
>>>   STW?, are we simply compacting the tenured gen or are we can 
>>> actually GC the tenured?
>>
>> A promotion failure is a scavenge that does not succeed because there 
>> is not enough
>> space in the old gen to do all the  needed promotions.  The scavenge 
>> is in essence
>> unwound and then a full STW compaction of the entire heap is done.
> 1) Just so I am clear "compaction" is compacting of the heap (making a 
> contiguous heap) AND
> garbage collection at the same time?  -- the "CMS: 
> 4003090K->1530872K(8601600K)"
> shows me my total heap is 1.5GB following this action, whereas the
> previous ParNew showed total heap was at 4.4GB.
"compaction" is a feature of some garbage collectors and in this case,  
a garbage
collection with compaction is happening.
>
>
> 2) Also just noticed this, what is the reason for the previous minor 
> collection ?
> 4900.615 [ParNew: 651487K->487288K(5017600K)  -->   Normally the 
> minors are
> at 4.8GB and get reduced to about 600K, whereas this one started at 
> 650K. 
> Using survivor isn't impacting/changing anything is it?
>
> Maybe it's because at 4900.615 we finished at 487K and than less than
> 1 second later at 4901.581 we have a another ParNew (the failure) and the
> 4788088K->4780999K entry --- so in less than 1 second we allocated 4GB.
> So perhaps does this answer my previous question about why a minor comes
> along at only 651K - we're trying to allocate a 4GB object / 4GB worth 
> of large objects?
> I guess this explains why I had a promotion failure / confirms 
> fragmentation
> despite having more than 4GB free in tenured I probably didn't 4GB 
> contiguous.

Hard to say why the collection with only 651487k used.  You're using JNI 
critical sections which
affects garbage collection so something could be going wrong with that 
interaction.

-------------- next part --------------
An HTML attachment was scrubbed...
URL: <https://mail.openjdk.org/pipermail/hotspot-gc-dev/attachments/20100415/23bbd60f/attachment.htm>
-------------- next part --------------
_______________________________________________
hotspot-gc-use mailing list
hotspot-gc-use at openjdk.java.net
http://mail.openjdk.java.net/mailman/listinfo/hotspot-gc-use