Using verbose:gc information (AIX, Linux only)

You can use the -verbose:gc option with the -Xgc:verboseGCCycleTime=N option to write information to the console about Metronome Garbage Collector activity. Not all XML properties in the -verbose:gc output from the standard JVM are created or apply to the output of the Metronome Garbage Collector.

Use the -verbose:gc option to view the minimum, maximum, and mean free space in the heap. In this way, you can check the level of activity and use of the heap, and then adjust the values if necessary. The -verbose:gc option writes Metronome statistics to the console.

The -Xgc:verboseGCCycleTime=N option controls the frequency of retrieval of the information. It determines the time in milliseconds that the summaries are dumped. The default value for N is 1000 milliseconds. The cycle time does not mean that the summary is dumped precisely at that time, but when the last garbage collection event that meets this time criterion passes. The collection and display of these statistics can increase Metronome Garbage Collector pause times and, as N gets smaller, the pause times can become large.

A quantum is a single period of Metronome Garbage Collector activity, causing an interruption or pause time for an application.

Example of verbose:gc output

Enter:

java -Xgcpolicy:metronome -verbose:gc -Xgc:verboseGCCycleTime=N myApplication
When garbage collection is triggered, a trigger start event occurs, followed by any number of heartbeat events, then a trigger end event when the trigger is satisfied. This example shows a triggered garbage collection cycle as verbose:gc output:
<trigger-start id="25" timestamp="2011-07-12T09:32:04.503" /> 

<cycle-start id="26" type="global" contextid="26" timestamp="2011-07-12T09:32:04.503" intervalms="984.285" /> 

<gc-op id="27" type="heartbeat" contextid="26" timestamp="2011-07-12T09:32:05.209">   
  <quanta quantumCount="321" quantumType="mark" minTimeMs="0.367" meanTimeMs="0.524" maxTimeMs="1.878" 
    maxTimestampMs="598704.070" />   
  <exclusiveaccess-info minTimeMs="0.006" meanTimeMs="0.062" maxTimeMs="0.147" />   
  <free-mem type="heap" minBytes="99143592" meanBytes="114374153" maxBytes="134182032" />   
  <thread-priority maxPriority="11" minPriority="11" />
</gc-op> 

<gc-op id="28" type="heartbeat" contextid="26" timestamp="2011-07-12T09:32:05.458">   
  <quanta quantumCount="115" quantumType="sweep" minTimeMs="0.430" meanTimeMs="0.471" maxTimeMs="0.511" 
    maxTimestampMs="599475.654" />   
  <exclusiveaccess-info minTimeMs="0.007" meanTimeMs="0.067" maxTimeMs="0.173" />   
  <classunload-info classloadersunloaded=9 classesunloaded=156  />     
  <references type="weak" cleared="660" />   
  <free-mem type="heap" minBytes="24281568" meanBytes="55456028" maxBytes="87231320" />   
  <thread-priority maxPriority="11" minPriority="11" />
</gc-op> 

<gc-op id="29" type="syncgc" timems="136.945" contextid="26" timestamp="2011-07-12T09:32:06.046">   
  <syncgc-info reason="out of memory" exclusiveaccessTimeMs="0.006" threadPriority="11" />   
  <free-mem-delta type="heap" bytesBefore="21290752" bytesAfter="171963656" />
</gc-op> 

<cycle-end id="30" type="global" contextid="26" timestamp="2011-07-12T09:32:06.046" /> 

<trigger-end id="31" timestamp="2011-07-12T09:32:06.046" />

The following event types can occur:

<trigger-start ...>
The start of a garbage collection cycle, when the amount of used memory became higher than the trigger threshold. The default threshold is 50% of the heap. The intervalms attribute is the interval between the previous trigger end event (with id-1) and this trigger start event.
<trigger-end ...>
A garbage collection cycle successfully lowered the amount of used memory beneath the trigger threshold. If a garbage collection cycle ended, but used memory did not drop beneath the trigger threshold, a new garbage collection cycle is started with the same context ID. For each trigger start event, there is a matching trigger end event with same context ID. The intervalms attribute is the interval between the previous trigger start event and the current trigger end event. During this time, one or more garbage collection cycles will have completed until used memory has dropped beneath the trigger threshold.
<gc-op id="28" type="heartbeat"...>
A periodic event that gathers information (on memory and time) about all garbage collection quanta for the time covered. A heartbeat event can occur only between a matching pair of trigger start and trigger end events; that is, while an active garbage collection cycle is in process. The intervalms attribute is the interval between the previous heartbeat event (with id -1) and this heartbeat event.
<gc-op id="29" type="syncgc"...>
A synchronous (nondeterministic) garbage collection event. See Synchronous garbage collections
The XML tags in this example have the following meanings:
<quanta ...>
A summary of quantum pause times during the heartbeat interval, including the length of the pauses in milliseconds.
<free-mem type="heap" ...>
A summary of the amount of free heap space during the heartbeat interval, sampled at the end of each garbage collection quantum.
<classunload-info classloadersunloaded=9 classesunloaded=156 />
The number of classloaders and classes unloaded during the heartbeat interval.
<references type="weak" cleared="660 />
The number and type of Java™ reference objects that were cleared during the heartbeat interval.
Note:
  • If only one garbage collection quantum occurred in the interval between two heartbeats, the free memory is sampled only at the end of this one quantum. Therefore the minimum, maximum, and mean amounts given in the heartbeat summary are all equal.
  • The interval between two heartbeat events might be significantly larger than the cycle time specified if the heap is not full enough to require garbage collection activity. For example, if your program requires garbage collection activity only once every few seconds, you are likely to see a heartbeat only once every few seconds.
  • It is possible that the interval might be significantly larger than the cycle time specified because the garbage collection has no work on a heap that is not full enough to warrant garbage collection activity. For example, if your program requires garbage collection activity only once every few seconds, you are likely to see a heartbeat only once every few seconds.

    If an event such as a synchronous garbage collection or a priority change occurs, the details of the event and any pending events, such as heartbeats, are immediately produced as output.

  • If the maximum garbage collection quantum for a given period is too large, you might want to reduce the target utilization using the -Xgc:targetUtilization option. This action gives the Garbage Collector more time to work. Alternatively, you might want to increase the heap size with the -Xmx option. Similarly, if your application can tolerate longer delays than are currently being reported, you can increase the target utilization or decrease the heap size.
  • The output can be redirected to a log file instead of the console with the -Xverbosegclog:<file> option; for example, -Xverbosegclog:out writes the -verbose:gc output to the file out.
  • The priority listed in thread-priority is the underlying operating system thread priority, not a Java thread priority.

Synchronous garbage collections

An entry is also written to the -verbose:gc log when a synchronous (nondeterministic) garbage collection occurs. This event has three possible causes:
  • An explicit System.gc() call in the code.
  • The JVM runs out of memory then performs a synchronous garbage collection to avoid an OutOfMemoryError condition.
  • The JVM shuts down during a continuous garbage collection. The JVM cannot cancel the collection, so it completes the collection synchronously, and then exits.
An example of a System.gc() entry is: 
<gc-op id="9" type="syncgc" timems="12.92" contextid="8" timestamp=
"2011-07-12T09:41:40.808">
  <syncgc-info reason="system GC" totalBytesRequested="260" exclusiveaccessTimeMs="0.009" 
  threadPriority="11" />
  <free-mem-delta type="heap" bytesBefore="22085440" bytesAfter="136023450" />
  <classunload-info classloadersunloaded="54" classesunloaded="234" />
  <references type="soft" cleared="21" dynamicThreshold="29" maxThreshold="32" />
  <references type="weak" cleared="523" />
  <finalization enqueued="124" />
</gc-op>
An example of a synchronous garbage collection entry as a result of the JVM shutting down is:
<gc-op id="24" type="syncgc" timems="6.439" contextid="19" timestamp="2011-07-12T09:43:14.524">   
  <syncgc-info reason="VM shut down" exclusiveaccessTimeMs="0.009" threadPriority="11" />   
  <free-mem-delta type="heap" bytesBefore="56182430" bytesAfter="151356238" />   
  <classunload-info classloadersunloaded="14" classesunloaded="276" />   
  <references type="soft" cleared="154" dynamicThreshold="29" maxThreshold="32" /> 
  <references type="weak" cleared="53" />   
  <finalization enqueued="34" />
</gc-op>
The XML tags and attributes in this example have the following meanings:
<gc-op id="9" type="syncgc" timems="6.439" ...
This line indicates that the event type is a synchronous garbage collection. The timems attribute is the duration of the synchronous garbage collection in milliseconds.
<syncgc-info reason="..."/>
The cause of the synchronous garbage collection.
<free-mem-delta.../>
The free Java heap memory before and after the synchronous garbage collection in bytes.
<finalization .../>
The number of objects awaiting finalization.
<classunload-info .../>
The number of classloaders and classes unloaded during the heartbeat interval.
<references type="weak" cleared="53" .../>
The number and type of Java reference objects that were cleared during the heartbeat interval.

Synchronous garbage collection due to out-of-memory conditions or VM shutdown can happen only when the Garbage Collector is active. It has to be preceded by a trigger start event, although not necessarily immediately. Some heartbeat events probably occur between a trigger start event and the synchgc event. Synchronous garbage collection caused by System.gc() can happen at any time.

Tracking all GC quanta

Individual GC quanta can be tracked by enabling the GlobalGCStart and GlobalGCEnd tracepoints. These tracepoints are produced at the beginning and end of all Metronome Garbage Collector activity including synchronous garbage collections. The output for these tracepoints looks similar to: 
03:44:35.281 0x833cd00 j9mm.52 - GlobalGC start: globalcount=3

03:44:35.284 0x833cd00 j9mm.91 - GlobalGC end: workstackoverflow=0 overflowcount=0

Out-of-memory entries

When the heap runs out of free space, an entry is written to the -verbose:gc log before the OutOfMemoryError exception is thrown. An example of this output is: 
<out-of-memory id="71" timestamp="2011-07-12T10:21:50.135" memorySpaceName="Metronome" 
  memorySpaceAddress="0806DFDC"/>

By default a Javadump is produced as a result of an OutOfMemoryError exception. This dump contains information about the memory used by your program. 

NULL
1STSEGTOTAL    Total memory:           4066080 (0x003E0B20)
1STSEGINUSE    Total memory in use:    3919440 (0x003BCE50)
1STSEGFREE     Total memory free:       146640 (0x00023CD0)