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:optavgpause is set.
Resolving The Problem
This policy minimizes garbage collection pause times at the expense of slightly less throughput. Reduced pause times are achieved by enabling concurrent mark, which performs liveness detection concurrently with normal program execution. In addition to reducing pause times, the optavgpause option limits the effect of increasing heap size on the pause times. This option is particularly relevant to configurations that have large heaps. However, with the reduced pause time, you might experience some reduction of application throughput, which varies from application to application.
Concurrent GC
In addition to the verbose GC outputs seen when the Optimum Throughput GC policy is in place, the following four outputs will also been seen:
- Concurrent Kickoff
- Concurrent Aborted
- Concurrent Halted
- Concurrent Collection
Concurrent Kickoff
When the concurrent mark process is triggered, the following output is produced:
<con event="kickoff" timestamp="Fri Nov 14 15:14:27 2003">
<stats tenurefreebytes="439416" tracetarget="4346357" kickoff="543294" tracerate="8" />
</con>
| <con event="kickoff> | shows that concurrent mark was kicked off, and gives a local timestamp for this. |
| <stats> | shows the amount of free space in the tenured area, the target amount of tracing to be performed by concurrent mark, the kickoff threshold at which concurrent is triggered, and the initial tracerate. tracerate represents the amount of tracing each mutator thread should perform relative to the amount of space it is attempting to allocate within the heap |
Concurrent Aborted
<af type="tenured" id="7" timestamp="Fri Nov 14 15:18:44 2003" intervalms="2108.509">
<minimum requested_bytes="36" />
<tenured freebytes="0" totalbytes="38263808" percent="0" />
<con event="aborted">
<stats tracetarget="2127800">
<traced total="528784" mutators="528784" helpers=?0? percent="25" />
</stats>
</con>
<gc type="global" id="16" totalid="16" timestamp="Fri Nov 14 15:18:44 2003" intervalms="1993.718">
<refs_cleared soft="2" weak="0" phantom="0" />
<finalization objectsqueued="5" />
<timesms mark="21.013" sweep="19.438" compact="0.000" total="40.533" />
<heap freebytes="31890452" totalbytes="38263808" percent="83" />
</gc>
<expansion type="tenured? amount="512" newsize="38264320" timetaken="0.052" reason=?excessive time being spent in gc? />
<time totalms="42.617" />
<tenured freebytes="31890964" totalbytes="38264320" percent="83" />
</af>
| <con event="aborted"> | shows that as a result of the allocation failure, concurrent mark tracing was aborted. |
| <stats> | shows the target amount of tracing to be performed by concurrent mark, along with the amount actually traced so far. |
Note: The other fields are the same as for a standard allocation failure.
Concurrent Halted: Allocation Failure
<af type="tenured" id="1" timestamp="Wed Jan 14 12:48:50 2004" intervalms="0.000">
<minimum requested_bytes="28" />
<time exclusiveaccessms="0.007" />
<tenured freebytes="0" totalbytes="21676032" percent="0" />
<con event="halted" mode="clean trace">
<stats tracetarget="5204261">
<traced total="4058780" mutators="4058780" helpers="0" percent=?78? />
<cards cleaned="5" estimateddirty="5" kickoff="443556" />
</stats>
</con>
<con event="final card cleaning">
<stats cardscleaned="6" traced=?2432? durationms="0.156" />
</con>
<gc type="global" id="6" totalid="43" intervalms="1416.726">
<compaction movecount="208435" movebytes="21087264" />
<refs_cleared soft="0" weak="0" phantom="0" />
<finalization objectsqueued="0" />
<timesms mark="1.058" sweep="6.905" compact="142.778" total="150.786" />
<nursery freebytes="903500" totalbytes="2097152" percent="43" />
<tenured freebytes="523328" totalbytes="21676032" percent="2" />
</gc>
<expansion>
<tenured increase="8542208" newsize="30218240" />
<time takenms="0.123" />
</expansion>
<time totalms="167.050" />
<tenured freebytes="9065508" totalbytes="30218240" percent="30" />
</af>
| <con event=halted> | shows that concurrent mark tracing was halted as a result of the allocation failure. |
| <cards cleaned=5> | shows that 5 dirty cards in the card table were cleaned during concurrent mark. Card cleaning occurs during concurrent mark once all available tracing has been exhausted. An estimation of the number of dirty cards is given. |
| <con event=final card cleaning> | shows that final card cleaning occurred before the garbage collection was triggered. The number of cards cleaned during the process and the number of bytes traced is shown, along with the total time taken by the process. |
Note: The other fields are the same as for a standard allocation failure.
Concurrent Halted: System.gc()
<sys id="11" timestamp="Wed Jan 14 12:16:06 2004" intervalms="3988.669">
<con event="halted" mode="exhausted">
<stats tracetarget="35386516">
<traced total="19307804" mutators="19307804" helpers="0" percent=?5? />
<cards cleaned="87" estimateddirty="87" kickoff="2211657" />
</stats>
</con>
<con event="final card cleaning">
<stats cardscleaned="345" traced=?2543? durationms="5.062" />
</con>
<gc type="global" id="197" totalid="197" intervalms="3994.143">
<compaction movecount="719044" movebytes="90813316" />
<refs_cleared soft="0" weak="0" phantom="0" />
<finalization objectsqueued="0" />
<timesms mark="1.777" sweep="38.296" compact="565.708" total="605.824" />
<tenured freebytes="21631284" totalbytes="112857088" percent="19" />
</gc>
<time totalms="610.999" />
</sys>
Note: The fields are the same as for a concurrent collection halted due to an allocation failure, and for a call to System.gc().
Concurrent Collection
If concurrent mark completes all tracing and card-cleaning, a concurrent collection is triggered.
<con event="collection" id="5" timestamp="Wed Jan 14 12:48:59 2004" intervalms="7810.298">
<time exclusiveaccessms="0.009" />
<tenured freebytes="0" totalbytes="30218240" percent="0" />
<stats tracetarget="8060116">
<traced total="5509424" mutators="5509424" helpers="0" percent=?68? />
<cards cleaned="110" kickoff="503757" />
</stats>
<con event="final card cleaning">
<stats cardscleaned="78" traced=?4232? durationms="4.329" />
</con>
<gc type="global" id="9" totalid="95" intervalms="4364.041">
<compaction movecount="268267" movebytes="25955224" />
<refs_cleared soft="0" weak="0" phantom="0" />
<finalization objectsqueued="0" />
<timesms mark="9.330" sweep="35.326" compact="158.164" total="202.882" />
<nursery freebytes="1135852" totalbytes="2097152" percent="54" />
<tenured freebytes="4926264" totalbytes="30218240" percent="16" />
</gc>
<expansion type=?tenured? amount="5913600" newsize="36131840" timetaken="0.120" reason=?insufficient free space following gc? />
<tenured freebytes="10839864" totalbytes="36131840" percent="30" />
<time totalms="209.324" />
</con>
| <con event=collection> | shows that a concurrent collection has been triggered. The id attribute shows the number of this concurrent collection, a local timestamp is outputted, and intervalms is the number of milliseconds since the previous concurrent collection. |
| <stats> | show the tracing statistics for the concurrent tracing that has taken place previously. The target amount of tracing is shown, together with that which actually took place (both by mutators threads and helper threads). Information is displayed showing the number of cards in the card table which were cleaned during the concurrent mark process, and an estimation of the total number of dirty cards. |
| <con event=final card cleaning> | shows that final card cleaning has been triggered. The number of cards cleaned is displayed, together with the number of milliseconds taken to do so. |
Following this, a normal global collection is triggered.
Related Information
Was this topic helpful?
Document Information
Modified date:
15 June 2018
UID
swg21222459