GC locker: Trying a full collection because scavenge failed
Hi,
We've got the following message using PrintGCDetails option in a java 1.4.2 virtual machine (We are not using any GC jvm modifiers beside PrintGCDetails):
"GC locker: Trying a full collection because scavenge failed"
We've got this message just once and after that, we've got lots of minor GC cycles collecting both new and tenured generations. As far as I know, the cause of this is the "full promotion guarantee" (we realized that we had oversized young generation), but
What's does this message mean?Why we're getting this messsage just once (within 24h of gc.log) if we are having many GC cycles collecting both generations?
Thx.
[679 byte] By [
david327a] at [2007-11-26 14:07:18]
# 2
Yes we did it, and we haven磘 understand why this situation happend just once in many hours. We consider it strange because system load is almost the same during some hours (high load). Is that "scavenge fail" such an exceptional situation?
Thx.
gc.log (the only exceptional situation in some hours):
...
32495,327: [GC 972495,328: [DefNew: 411264K->411264K(424064K), 0,0000451 secs]972495,328: [Tenured: 520751K->522081K(873856K), 5,3183627 secs] 932015K->522081K(1297920K), 6,4090851 secs]
32527,839: [GC 972527,839: [DefNew: 411264K->411264K(424064K), 0,0000463 secs]972527,839: [Tenured: 522081K->517745K(873856K), 7,5234545 secs] 933345K->517745K(1297920K), 9,1496927 secs]
32557,473: [Full GC 972557,473: [DefNew: 411264K->411264K(424064K), 0,0000404 secs] 929009K->929009K(1297920K), 1,3890446 secs]
GC locker: Trying a full collection because scavenge failed
32558,862: [Full GC 972558,862: [Tenured: 517745K->520179K(873856K), 5,2098964 secs] 929009K->520179K(1297920K), [Perm : 1878K->91878K(91904K)], 6,2891004 secs]
32583,843: [GC 972583,843: [DefNew: 411264K->411264K(424064K), 0,0000481 secs]972583,843: [Tenured: 520179K->515880K(873856K), 5,7079640 secs] 931443K->515880K(1297920K), 6,7821902 secs]
32606,741: [GC 972606,742: [DefNew: 411264K->411264K(424064K), 0,0000445 secs]972606,742: [Tenured: 515880K->519105K(873856K), 5,4717780 secs] 927144K->519105K(1297920K), 6,6073060 secs]
...
# 6
Poonam has it right. The HotSpot JVM doesn't pin objects that are used in JNI critical regions, so we have to prevent garbage collections while the critical region is in progress. That's what a GC_locker is for. (See the comments on the public methods on class GC_locker at http://12.101.252.19/hotspot/xref/src/share/vm/memory/gcLocker.hpp for details, and follow the implementation if you like.) If a GC_locker notices that it when it exits a JNI critical region that it delayed a collection, it prints that message and forces a full collection.
(I note also that your heap is shaped weirdly, having 424064KB in the young generation and only 873856KB in the old generation. Mostly you seem to be running with 411264KB in the young generation and around 519105KB of live data in the old generation, so given that you are using the serial collector, and there isn't room for all of the young generation in the old generation, we are abandoning young generation collections (quickly, e.g., 0,0000445 secs), but essentially only doing full collections, which might not be as efficient as using young generation collections. Usually for that collector we recommend that the heap be large enough for all your live data plus at least two young generations. See http://java.sun.com/docs/hotspot/gc5.0/gc_tuning_5.html for more details. I'd be surprised if you couldn't reduce your GC load by reshaping your heap, given that your young generation seems to be mostly filled with garbage (though it's hard to tell from the trace you've shown).)
