Troubleshooting
Problem
Verbose GC data gives an insight into the actions that the Garbage Collector is taking, and is vital for performance tuning. In addition it is one means of determining if the application is "leaking" Java objects, and what size leak has occurred which is useful when carrying out heapdump analysis. The information below explains the output that will be seen when -Xgcpolicy:optthruput is set.
Resolving The Problem
Garbage collection cycles introduce occasional unexpected pauses in the execution of application code. Because applications grow in size and complexity, and heaps become correspondingly larger, this garbage collection pause time tends to grow in size and significance. The default garbage collection policy, -Xgcpolicy:optthruput, delivers very high throughput to applications, but at the cost of these occasional pauses, which can vary from a few milliseconds to many seconds, depending on the size of the heap and the quantity of garbage.
When this is occurring two different types of Verbose GC output can be seen:
- System.gc() call
- An allocation failure
The expected Verbose GC output and an explanation of the terms seen is below:
System.gc() call:
<sys id="1" timestamp="Wed Jan 14 11:30:46 2004" intervalms="0.000">
<gc type="global" id="1" totalid="2" intervalms="0.000">
<compaction movecount="9138" movebytes="409188" />
<refs_cleared soft="0" weak="7" phantom="0" />
<finalization objectsqueued="0" />
<timesms mark="3.187" sweep="0.524" compact="4.629" total="8.392" />
<tenured freebytes="8278684" totalbytes="8388608" percent="98" />
</gc>
<time totalms="9.668" />
</sys>
| <sys> | indicates that a System.gc() has occurred. The id attribute gives the number of this System.gc call; in this case, this is the first System.gc() call in the life of this VM. timestamp gives the local timestamp when the System.gc() call was made and intervalms gives the number of milliseconds that have elapsed since the previous System.gc() call. In this case, as this is the first System.gc() call the number returned is zero. |
| <gc> | indicates that a garbage collection was triggered on the heap. type=global indicates that this was a global collection (mark, sweep, possibly compact). The id attribute gives the occurrence number of this global collection. The totalid indicates the total number of garbage collections (of all types) that have taken place. Currently this is the sum of the number of global collections and the number of scavenger collections. intervalms gives the number of milliseconds since the previous global collection. |
| <compaction> | shows the number of objects which were moved during compaction, and the total number of bytes these objects represented. This line only appears if compaction occurred during the collection. |
| <refs_cleared> | provides information relating to the number of Java reference objects that were cleared during the collection. In this example, no references were cleared. |
| <finalization> | provides information detailing the number of objects containing finalizers that were enqueued for VM finalization during the collection. Note that this is not equal to the number of finalizers which were run during the collection, as finalizers are scheduled by the VM. |
| <timems> | provides information detailing the respectively times taken for each of the mark, sweep, and compact phases, as well as the total time taken. When compaction was not triggered, the number returned is zero. Note that if the VM being run is not compiled with compaction support, the compact field will not be displayed. |
| <tenured> | the status of the tenured area following the collection. The optimum throughput collector has only the tenured area. |
| <time> | shows the total amount of time taken to handle the System.gc call (in milliseconds). |
Allocation failure:
<af type="tenured" id="4" timestamp="Wed Jan 14 11:49:22 2004" intervalms="366.559">
<minimum requested_bytes="148" />
<time exclusiveaccessms="0.008" />
<tenured freebytes="0" totalbytes="11337472" percent="0" />
<gc type="global" id="6" totalid="6" intervalms="366.676">
<compaction movecount="139926" movebytes="9478888" />
<refs_cleared soft="0" weak="0" phantom="0" />
<finalization objectsqueued="0" />
<timesms mark="34.155" sweep="1.762" compact="65.891" total="101.849" />
<tenured freebytes="1784720" totalbytes="11337472" percent="15" />
</gc>
<expansion type=?tenured? amount="2310400" newsize="13647872" timetaken="0.052" reason=?insufficient free space following gc? />
<time totalms="101.973" />
<tenured freebytes="4094548" totalbytes="13647872" percent="30" />
</af>
| <af type="tenured"> | indicates that an allocation failure has occurred when attempting to allocate an object onto the Java heap. The id attribute shows the index of that type of allocation failure that has occurred. timestamp shows a local timestamp at the time of the allocation failure, and intervalms shows the number of milliseconds elapsed since the previous allocation failure of that type. |
| <minimum> | shows the number of bytes requested by the allocate which triggered the failure. Note that following the garbage collection freespace may drop by more than this amount, due to possible freelist discard or TLH refresh. |
| <time exclusiveaccessms=> | shows the amount of time taken to obtain exclusive VM access. Note that a further optional line <warning details=exclusive access time includes previous garbage collections /> may occasionally appear. This informs the user that the following garbage collection was queued as the allocation failure was triggered while another thread was already performing a garbage collection. |
| <tenured> | The first occurrance shows the status of the nJava heap at the time of the failure, including the percentage which was free. The second occurrance shows the status of the different heap areas following the handling of the allocation failure, including percentage of each area free. |
Note: The other fields as the same as for a garbage collection cycles started by a call to System.gc().
[{"Product":{"code":"SSNVBF","label":"Runtimes for Java Technology"},"Business Unit":{"code":"BU059","label":"IBM Software w\/o TPS"},"Component":"Debugging Options","Platform":[{"code":"PF002","label":"AIX"},{"code":"PF016","label":"Linux"},{"code":"PF027","label":"Solaris"},{"code":"PF033","label":"Windows"},{"code":"PF035","label":"z\/OS"}],"Version":"5.0","Edition":"J2SE","Line of Business":{"code":"LOB36","label":"IBM Automation"}}]
Was this topic helpful?
Document Information
Modified date:
15 June 2018
UID
swg21222443