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:gencon is set.
Resolving The Problem
The gencon (short for generational and concurrent) policy aims for a balance between optavgpause and optthruput. This policy divides the heap into two generations: the nursery, where new objects are allocated, and the tenure area, where objects that have survived several local collections reside. The local collector (the scavenger) is responsible for garbage collection in the nursery, and for moving objects into the tenure area. Since it is a copying collector, the nursery is implicitly compacted. This helps reduce fragmentation, leading to less time spent in allocation.
In addition to the verbose GC outputs seen when the Concurrent Collector and the Optimum Throughput policies are in place, the following two outputs will also be seen:
- Nursery Allocation Failures
- Scavenger Collections
Nursery Allocation Failures
<af type="nursery" id="3" timestamp="Wed Jan 14 11:30:47 2004" intervalms="88.219">
<minimum requested_bytes="60" />
<time exclusiveaccessms="0.010" />
<nursery freebytes="0" totalbytes="2097152" percent="0" />
<gc type="scavenger" id="3" totalid="5" intervalms="88.264">
<flipped objectcount="30350" bytes="1576372" />
<tenured objectcount="0" bytes="0" />
<finalization objectsqueued="0" />
<nursery freebytes="393216" totalbytes="2097152" percent="18" tenureage="9" />
<time totalms="12.538" />
</gc>
<time totalms="12.609" />
<nursery freebytes="391168" totalbytes="2097152" percent="18" />
<tenured freebytes="8261612" totalbytes="8388608" percent="98" />
</af>
| <af type=nursery> | indicates that an allocation failure has occurred when attempting to allocate to the nursery. 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. Normally, this first collection will have freed enough heap space to satisfy both allocation requests (the original one which triggered the garbage collection and the subsequently queued allocation request) however sometimes this is not the case and another garbage collect is triggered almost immediately. This additional line informs the user that the pause time displayed may be slightly misleading unless the reader is aware of the underlying threading used in Modron. |
| <nursery> | shows the status of the nursery at the time of the failure, including the percentage which was free. |
| <gc> | indicates that as a result of the allocation failure, a garbage collection was triggered. In this case a scavenger collection occurred. |
| <time> | shows the total time taken to handle the allocation failure. |
| <nursery> and <tenured> | shows the status of the different heap areas following the handling of the allocation failure, including percentage of each area free. |
Scavenger Collections
<gc type="scavenger" id="17" totalid="19" intervalms="145.701">
<failed type="tenured" objectcount="355" bytes="32964" />
<flipped objectcount="4192" bytes="655164" />
<tenured objectcount="3858" bytes="650928" />
<finalization objectsqueued="0" />
<scavenger tiltratio=?74? />
<nursery freebytes="1440760" totalbytes="2097152" percent="68" tenureage="1" />
<time totalms="6.451" />
</gc>
| <gc> | indicates that a garbage collection has been triggered, and type=?scavenger? indicates that this is a scavenger collection. The id attribute shows the number of this type of collection that have taken place and the totalid attribute shows the total number of garbage collections of all types that have taken place (including this one). intervalms gives the amount of time (in milliseconds) since the last collection of this type. |
| <failed type=?tenured?> | indicates that the scavenger failed to tenure some objects when it tried to during the collection. The number affected and the total bytes represented by these objects is shown. Additionally or alternatively, <failed type=?flipped?> could have been displayed, which would indicate that the scavenger failed to flip certain objects into the survivor space. |
| <flipped> | shows the number of objects that were flipped into the survivor space during the scavenge, together with the total number of bytes flipped. |
| <scavenger tiltratio=?x? /> | shows the amount that new-space is tilted by, following the post-scavenge retilt. The scavenger has the ability to redistribute memory between the allocate and survivor areas to maximise the time between scavenges, and the number of objects that ?die young?. |
| <tenured> | shows the number of objects that were moved into the old area during the scavenge, together with the total number of bytes tenured. |
| <nursery> | shows the amount of free and total space in the nursery area following the scavenge, along with the current number of flips an object must have survived in order to be tenured. |
| <time> | shows the total time taken to perform the scavenge, in milliseconds. |
Related Information
Was this topic helpful?
Document Information
Modified date:
15 June 2018
UID
swg21222486