Different Full GCs?

[Y. S. Ramakrishna]

Hello --

On 10/14/10 10:42, Hi Guava wrote:
> I've seen different full GC messages and I don't quite understand them:
> 13011:1474.283: [Full GC 1474.283: [CMS:
> 3333048K->1021496K(12540352K), 6.3444520 secs]
> 3363388K->1021496K(12582848K), [CMS Perm : 30528K->30483K(30656K)],
> 6.3447880 secs]

This is a full gc; it collects the whole heap.

> 34822:4101.808: [Full GC 4101.808: [ParNew: 667K->0K(42496K),
> 0.0210030 secs] 5953849K->5953209K(12582848K), 0.0211110 secs]
> 51586:25535.616: [Full GC 25535.616: [ParNew: 750K->0K(42496K),
> 0.0324350 secs] 5341677K->5340939K(12582848K), 0.0326130 secs]

These two are not full gc's. They are mislabelled. They are likely
scavenge's forced by the allocation policy interacting with
JNI critical sections preventing a scavenge attempt made previously.
I think the labelling has been fixed in 6uXX.

> 63486:26306.646: [Full GC 26306.646: [CMS[Unloading class
> sun.reflect.GeneratedConstructorAccessor20]

Yes this is also a full gc.

In 6uXX, the first and the last would be labelled with an additional
"System.gc()"  label, and the two middle ones would not say "Full".
I don't have a bug id handy to point you to, but i might be able to
dig one up after some archeology.

> 
> Both GC #1 and #4 are triggered by System.gc() in our code. I believe
> they are the same type. There was less memory available during #4 so
> it unloaded classes (soft reference?).
> But full gc is the stop-the-world gc. Why does it mention CMS in the message?

You are right that the "CMS" is misleading in that sense.
The idea was that it collects the old generation which is typically
collected by CMS. I agree that the CMS label is misleading and probably
should be fixed; it's a consequence of our internal naming scheme for
generation "types".

> GC #2 and #3 look weird to me. They were not triggered by System.gc().
> They are always very short and the duration is about the same as young
> generation GCs. In fact, the message is exact like young generation
> GCs except the extra word "Full". What are these short full gcs? Are
> there different level of full GCs?

No, and you are right that these are just scavenges. What must have happened
is that your application probably does a few short-lived JNI critical
sections (JNI_Get{Array,String}Critical) which happens around the time
when another thread wants to do a large allocation which will not fit in
the current space available in Eden, so the allocator attempts to do a
scavenge, but is prevented from doing so because of the JNI critical section.
This is remembered and when the critical section is exited, a scavenge
is forced. At least that's my guess based on the messages above.
(BTW, what's the size of your Eden or Young Gen? The policy should
probably be a little smarter and not do those scavenges until an
allocation request (would) fail.)

> I spent some time searching for answer but I am still confused. Can
> somebody help explain and suggest some reading materials?

Hope that helps a bit. Try JDK 7 or 6u21 (or whatever is the latest) and
see if the confusing messages are gone. If they are still there,
let us know.

thanks.
-- ramki

> 
> Thanks!
> 
> The environment:
> Java HotSpot(TM) 64-Bit Server VM Version 1.5.0_19-b02
> Linux Version 2.6.9-89.0.20.ELsmp
> amd64
> 
> -Xms12g
> -Xmx12g
> -XX:+PrintGC
> -XX:+PrintGCDetails
> -XX:+PrintGCTimeStamps
> -XX:+UseConcMarkSweepGC
> _______________________________________________
> hotspot-gc-use mailing list
> hotspot-gc-use at openjdk.java.net
> http://mail.openjdk.java.net/mailman/listinfo/hotspot-gc-use