13
Java applications can ask the garbage collector to run by calling the System.gc() method. Generally, this is a bad idea: the garbage collector is designed to run with good performance without intervention from your application. In fact, forcing the garbage collector to run unnecessarily can degrade performance significantly.
When System.gc() is called, output similar to the following appears in your -verbose:gc log:
<sys id="5" timestamp="Oct 05 17:43:43 2010" intervalms="9443535.145">
<time exclusiveaccessms="0.602" meanexclusiveaccessms="0.125" threads="16" lastthreadtid="0x000000003318B500" />
<refs soft="2588" weak="41710" phantom="1091" dynamicSoftReferenceThreshold="19" maxSoftReferenceThreshold="32" />
<nursery freebytes="61725488" totalbytes="7730940928" percent="0" />
<tenured freebytes="405050688" totalbytes="2007028736" percent="20" >
<soa freebytes="405050688" totalbytes="2007028736" percent="20" />
<loa freebytes="0" totalbytes="0" percent="0" />
</tenured>
<gc type="global" id="20" totalid="1628" intervalms="3600002.483">
<compaction movecount="12694538" movebytes="736459224" reason="compact on aggressive collection" />
<classunloading classloaders="0" classes="0" timevmquiescems="0.000" timetakenms="9.614" />
<finalization objectsqueued="61" />
<timesms mark="264.843" sweep="9.691" compact="439.676" total="725.084" />
<nursery freebytes="7651956968" totalbytes="7730940928" percent="98" />
<tenured freebytes="1329341512" totalbytes="2007028736" percent="66" >
<soa freebytes="1329341512" totalbytes="2007028736" percent="66" />
<loa freebytes="0" totalbytes="0" percent="0" />
</tenured>
</gc>
<nursery freebytes="7651956968" totalbytes="7730940928" percent="98" />
<tenured freebytes="1329341512" totalbytes="2007028736" percent="66" >
<soa freebytes="1329341512" totalbytes="2007028736" percent="66" />
<loa freebytes="0" totalbytes="0" percent="0" />
</tenured>
<refs soft="2582" weak="39492" phantom="1074" dynamicSoftReferenceThreshold="21" maxSoftReferenceThreshold="32" />
<time totalms="726.439" />
</sys>
You can tell that this GC was caused by a call to System.gc() because it is contained within a <sys> stanza.
Because sometimes calls to System.gc() originate from within third-party code that you don't have control over, IBM provide the -Xdisableexplicitgc option which disables calls to System.gc() so they are ignored by the garbage collector. If you are using code containing lots of System.gc() calls which are affecting performance, and you can't change that code, we recommend using the -Xdisableexplicitgc option.
I was recently contacted by a customer who had set the -Xdisableexplicitgc option, but still saw a <sys> stanza in their -verbose:gc output. Once we had worked out the reason why, I thought others might be interested in how this can be the case.
It turned out that an additional JVM option had been specified: -Xdump:heap:events=user
This option tells the JVM to write a heapdump file to disk when SIGQUIT is sent to the JVM. By default, we write a javacore file — this option makes us write a heapdump as well.
When we write a heapdump, by default we run a full garbage collection beforehand. The reason we do this is to remove all un-referenced objects from the heap, so the heapdump only contains live objects. This makes analysing the heapdump easier, and has the nice side-effect of making the heapdump file itself smaller.
This garbage collection appears in the -verbose:gc output. And because it's a "forced" GC (triggered because a heapdump is being taken) it appears as a <sys> stanza, despite the fact that -Xdisableexplicitgc is specified.
