understanding GC logs

[Jon Masamitsu]

On 4/14/10 1:29 PM, Shaun Hennessy wrote:
> ...
>
>>
>>>
>>>
>>>
>>> promotion failed, and full GC
>>> 50786.124: [GC 50786.124: [ParNew: 4606713K->338518K(5017600K), 
>>> 0.0961884 secs] 12303455K->8081859K(13619200K), 0.0963907 secs] 
>>> [Times: user=0.91 sys=0.01, real=0.10 secs]
>>> 50787.373: [GC 50787.373: [ParNew: 4639318K->272229K(5017600K), 
>>> 0.0749353 secs] 12382659K->8053730K(13619200K), 0.0751408 secs] 
>>> [Times: user=0.75 sys=0.00, real=0.08 secs]
>>> 50788.483: [GC 50788.483: [ParNew: 4573029K->393397K(5017600K), 
>>> 0.0837182 secs] 12354530K->8185595K(13619200K), 0.0839321 secs] 
>>> [Times: user=1.03 sys=0.00, real=0.08 secs]
>>> 50789.590: [GC 50789.590: [ParNew (promotion failed): 
>>> 4694264K->4612345K(5017600K), 1.5974678 secs] 
>>> 12486461K->12447305K(13619200K), 1.5976765 secs] [Times : user=2.38 
>>> sys=0.20, real=1.60 secs]
>>> GC locker: Trying a full collection because scavenge failed
>>> 50791.188: [Full GC 50791.188: [CMS: 7834959K->1227325K(8601600K), 
>>> 6.7102106 secs] 12447305K->1227325K(13619200K), [CMS Perm : 
>>> 670478K->670478K(819200K)], 6.7103417 secs] [Times: user=6.71 
>>> sys=0.00, real=6.71 secs]
>>> 50798.982: [GC 50798.982: [ParNew: 4300800K->217359K(5017600K), 
>>> 0.0364557 secs] 5528125K->1444685K(13619200K), 0.0366630 secs] 
>>> [Times: user=0.44 sys=0.00, real=0.04 secs]
>>> 50800.246: [GC 50800.246: [ParNew: 4518167K->198753K(5017600K), 
>>> 0.0368620 secs] 5745493K->1426078K(13619200K), 0.0370604 secs] 
>>> [Times: user=0.46 sys=0.01, real=0.04 secs]
>>> 9) Probably once I understand what the scavenge is doing will help 
>>> me understand this case, but logic seems
>>>  simply enough - fullgc on promotionfailure&scavenge failed.
>>
>> Yes, full STW compaction.
>>
> 3) So in the prevous case (promotion failed)  you said it was "full 
> STW compaction of the entire heap is done" and
> here in the (promotion failed; GC locker; Full GC) also "full STW 
> compaction" --- what is the difference between
> the 2 scenarios (ie cause and effect)?   From below your "/The "GC 
> locker" message says that after a JNI critical
> section was exited the GC wanted to do a scavenge but did not think 
> there was enough room in  the old gen so it
> does a full STW compaction."   -- /so the cause of the difference 
> between the 2 cases  is simply the fact the tenured
> generation was more full in this latest case?     So in terms of 
> effect  -- is anything different actually
> being done regarding the between the 2 cases or is just the log 
> messages being displayed are different - but they
> are the exact same type of GC?
>
The collections are the same (both full STW compactions).  The only 
difference are
the circumstances under which the GC were done.  JNI critical sections can
temporarily delay a GC and whenthe critical section is exited the delayed
GC happens.  That's about all I know about that.
>
> 4) Forgetting these specific examples, if we are having 
> frequent/troublesome promotion failures
>  is there anything beyond

Those are the usual remedies.  I suppose you could also try to reduce the
amount of allocations you do.

>
> a) Try 6u20
> b) Try a lower InitiatingOccupancy
> c) Try a smaller Eden Gen &  bigger Tenured / or simply bigger Heap
> - Does the use of Survivor Space vs not using Survivor make it more or 
> less likely to have promotion failures?
Having survivor spaces are better in general.

-------------- next part --------------
An HTML attachment was scrubbed...
URL: <https://mail.openjdk.org/pipermail/hotspot-gc-dev/attachments/20100416/49f446f0/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