Verbose garbage collection

When you turn the verbose garbage collection on, WAS will start printing garbage collection related information in your native_stderr.log file. You can turn the vebose garbage collection on using WAS Admin Console by going to Application servers < servername servers < Process Definition servers < Java Virtual Machine. Once you enable the verbose garbage collection on the WAS server will start writing messages into native_stderr.log file every time it executes garbage collection.

These are couple of entries from my native_stderr.log file.


<af type="tenured" id="49" timestamp="Jul 05 13:13:17 2009" intervalms="32.872">
<minimum requested_bytes="16776" />
<time exclusiveaccessms="0.044" />
<tenured freebytes="3624584" totalbytes="116873216" percent="3" >
<soa freebytes="3624584" totalbytes="116873216" percent="3" />
<loa freebytes="0" totalbytes="0" percent="0" />
</tenured>
<gc type="global" id="49" totalid="49" intervalms="34.359">
<refs_cleared soft="0" threshold="32" weak="0" phantom="0" />
<finalization objectsqueued="0" />
<timesms mark="107.399" sweep="1.583" compact="0.000" total="109.117" />
<tenured freebytes="43894704" totalbytes="116873216" percent="37" >
<soa freebytes="43894704" totalbytes="116873216" percent="37" />
<loa freebytes="0" totalbytes="0" percent="0" />
</tenured>
</gc>
<tenured freebytes="43877928" totalbytes="116873216" percent="37" >
<soa freebytes="43877928" totalbytes="116873216" percent="37" />
<loa freebytes="0" totalbytes="0" percent="0" />
</tenured>
<time totalms="110.648" />
</af>

<af type="tenured" id="50" timestamp="Jul 05 13:13:18 2009" intervalms="232.708">
<minimum requested_bytes="32" />
<time exclusiveaccessms="0.031" />
<tenured freebytes="0" totalbytes="116873216" percent="0" >
<soa freebytes="0" totalbytes="116873216" percent="0" />
<loa freebytes="0" totalbytes="0" percent="0" />
</tenured>
<gc type="global" id="50" totalid="50" intervalms="234.140">
<classloadersunloaded count="13" timetakenms="48.694" />
<expansion type="tenured" amount="19868672" newsize="136741888" timetaken="0.152" reason="excessive time being spent in gc" gctimepercent="49" />
<refs_cleared soft="0" threshold="32" weak="3" phantom="0" />
<finalization objectsqueued="0" />
<timesms mark="118.982" sweep="2.639" compact="0.000" total="170.899" />
<tenured freebytes="55392816" totalbytes="136741888" percent="40" >
<soa freebytes="55392816" totalbytes="136741888" percent="40" />
<loa freebytes="0" totalbytes="0" percent="0" />
</tenured>
</gc>
<tenured freebytes="55392176" totalbytes="136741888" percent="40" >
<soa freebytes="55392176" totalbytes="136741888" percent="40" />
<loa freebytes="0" totalbytes="0" percent="0" />
</tenured>
<time totalms="172.525" />
</af>

The way IBM JDK works is if it is not able to allocate a memory then it will execute garbage collection to free up the memory. The J9 VM used in WAS 6.1 generates one <af> element every time a garbage collection works.

The af element has following elements

• type:


• id: The id represents how many times the gc was executed


• intervalms: The time in ms since last time gc was executed


• timestamp: time of gc

The minimum represents the number of bytes that were requested and JVM couldnot allocate them so it had to trigger garbage collection cycle.

The af element has 3 main child elements first tenured element has data about the tenured memory position before gc then gc element represents data about what happened during gc, such as time spent in mark, sweep and compact phases, The second tenured element represents the position of tenured memory after gc.


The IBM Support assistance has IBM Pattern modeling and Analysis tool for Java Garbage collection tool that can be used to analyze the garbage collection.