understanding GC logs
jon.masamitsu at oracle.com
Thu Apr 15 15:51:52 PDT 2010
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:
> 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,
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
> 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
> despite having more than 4GB free in tenured I probably didn't 4GB
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
-------------- next part --------------
An HTML attachment was scrubbed...
-------------- next part --------------
hotspot-gc-use mailing list
hotspot-gc-use at openjdk.java.net
More information about the hotspot-gc-dev