Using verbose:gc information

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 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 subsequently 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 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 distort Metronome Garbage Collector pause time targets and, as N gets smaller, the distortion can become quite 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:
<gc type="trigger start" id="7" timestamp="Oct 20 20:42:49 2008" intervalms="317.456" /> 

<gc type="heartbeat" id="17" timestamp="Oct 20 20:42:50 2008" intervalms="1008.280"> 
  <summary quantumcount="51"> 
    <quantum minms="0.362" meanms="3.015" maxms="3.096" /> 
    <exclusiveaccess minms="0.003" meanms="0.014" maxms="0.044" /> 
    <heap minfree="532568668" meanfree="855123353" maxfree="1152691352" /> 
  </summary> 
</gc> 

<gc type="heartbeat" id="18" timestamp="Oct 20 20:42:51 2008" intervalms="1011.684"> 
  <summary quantumcount="54"> 
    <quantum minms="0.106" meanms="2.829" maxms="3.113" /> 
    <exclusiveaccess minms="0.003" meanms="0.018" maxms="0.055" /> 
    <heap minfree="410376144" meanfree="623433365" maxfree="818067840" /> 
  </summary> 
</gc> 

<gc type="heartbeat" id="19" timestamp="Oct 20 20:42:51 2008" intervalms="432.527"> 
  <summary quantumcount="21"> 
    <quantum minms="3.017" meanms="3.069" maxms="3.105" /> 
    <exclusiveaccess minms="0.004" meanms="0.025" maxms="0.053" /> 
    <classunloading classloaders="2" classes="1" /> 
    <refs_cleared soft="14" threshold="20" maxThreshold="32" weak="0" phantom="0" /> 
    <heap minfree="301004952" meanfree="420760698" maxfree="538701108" /> 
  </summary> 
</gc> 

<gc type="synchgc" id="6" timestamp="Oct 20 20:42:51 2008" intervalms="14.628"> 
  <details reason="out of memory" /> 
  <duration timems="185.741" /> 
  <heap freebytesbefore="290197120" /> 
  <heap freebytesafter="1462221448" /> 
</gc> 

<gc type="trigger end" id="7" timestamp="Oct 20 20:42:51 2008" intervalms="2653.000" /> 

The following event types can occur:

<gc type="trigger start" ...>
The start of a garbage collection cycle. The used memory became higher than the trigger threshold. The default threshold is 50% of heap. You can change the threshold by using the -XXgc:trigger=NN, where NN is an absolute amount of memory. The intervalms attribute is the interval between the previous trigger end event (with id-1) and this trigger start event.
<gc type="trigger end" ...>
A garbage collection cycle successfully lowered the amount of used memory to below the trigger threshold. If a garbage collection cycle ended, but used memory did not drop below the trigger threshold, a new garbage collection cycle is started as part of the same trigger ID. For each trigger start event, there is a matching trigger end event with same ID. The intervalms attribute is the interval between the previous trigger start event (with the same id) and the current trigger end event. During this period of time, one or more garbage collection cycles will have completed until used memory has dropped below the trigger threshold.
<gc type="heartbeat" ...>
A periodic event that gathers information (on memory and time) about all garbage collection quanta for the period of time it covers. A heartbeat event can occur only between a matching pair of triggerstart and triggerend 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 type="syncgc" ...>
A synchronous (nondeterministic) garbage collection event. See Synchronous garbage collections
The XML tags in this example have the following meanings:
<summary ...>
A summary of the garbage collection activity during the heartbeat interval. The quantumcount attribute is the number of garbage collection quanta run in the summary period.
<quantum ...>
A summary of the length of quantum pause times during the heartbeat interval in milliseconds.
<heap ...>
A summary of the amount of free heap space during the heartbeat interval, sampled at the end of each garbage collection quantum.
<classunloading ...>
The number of classloaders and classes unloaded during the heartbeat interval.
<refs_cleared ...>
Is the number 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, and therefore the minimum, maximum, and mean amounts given in the heartbeat summary are all equal.
  • 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, will be 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 to give the Garbage Collector more time to work, or you might want to increase the heap size using 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 using the -Xverbosegclog:<file> option; for example, -Xverbosegclog:out writes the -verbose:gc output to the file out.
  • The priority listed in gcthreadpriority is the underlying OS 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 example of a System.gc() entry is:
<gc type="synchgc" id="1" timestamp="Oct 20 20:42:27 2008" intervalms="0.055"> 
  <details reason="system garbage collect" /> 
  <duration timems="3.395" /> 
  <refs_cleared soft="0" threshold="31" maxThreshold="32" weak="2" phantom="0" /> 
  <finalization objectsqueued="2" /> 
  <heap freebytesbefore="2303633908" /> 
  <heap freebytesafter="2304483260" /> 
</gc> 
An example of a synchronous garbage collection entry as a result of JVM shutting down is:
<gc type="synchgc" id="1" timestamp="Oct 20 20:48:35 2008" intervalms="3.513"> 
  <details reason="vm shutdown" /> 
  <duration timems="3.295" /> 
  <refs_cleared soft="0" threshold="29" maxThreshold="32" weak="2" phantom="0" /> 
  <heap freebytesbefore="32765764" /> 
  <heap freebytesafter="62231696" /> 
</gc> 
The XML tags and attributes in this example have the following meanings:
<gc type="syncgc" ...>
Is the event specifying that this is a synchronous garbage collection. The intervalms attribute is the interval between previous event (heartbeat, trigger start, trigger end, or another synchgc) and the beginning of this synchronous garbage collection.
<details ...>
Is the cause of the synchronous garbage collection.
<duration ...>
Is the time it took to complete this garbage collection cycle synchronously in milliseconds.
<heap ...>
Is the free Java heap memory before and after the synchronous garbage collection in bytes.
<finalization ...>
Is the number of objects awaiting finalization.
<classunloading ...>
The number of classloaders and classes unloaded during the heartbeat interval.
<refs_cleared ...>
Is the number of Java reference objects that were cleared during the heartbeat interval.

Synchronous garbage collection due to out-of-memory conditions or VM shut down 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 Global GC Start and Global GC End 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 will look similar to:
03:44:35.281 0x833cd00 j9mm.52 - GlobalGC start: weakrefs=7 soft=11 phantom=0 finalizers=75 globalcount=3 scavengecount=0

03:44:35.284 0x833cd00 j9mm.91 - GlobalGC end: workstackoverflow=0 overflowcount=0 weakrefs=7 soft=11 threshold=31 phantom=0 finalizers=75 newspace=0/0 oldspace=2385610372/2621440000 loa=0/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:
<event details="out of memory" timestamp="Oct 20 21:03:19 2008" memoryspace="Metronome" J9MemorySpace="0x080B85B4" />

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

0SECTION       MEMINFO subcomponent dump routine 
NULL           ================================= 
NULL 
1STMEMTYPE     Object Memory 
NULL           region     start      end        size       name 
1STHEAP        0x080B85B4 0xF4F20000 0xF6F10000 0x01FF0000 Default 
NULL 
1STMEMUSAGE    Total memory available: 33554432 (0x02000000) 
1STMEMUSAGE    Total memory in use:    29396464 (0x01C08DF0) 
1STMEMUSAGE    Total memory free:      04157968 (0x003F7210) 


© Copyright IBM Corporation 2005, 2010. All Rights Reserved.
© Copyright Sun Microsystems, Inc. 1997, 2007, 901 San Antonio Rd., Palo Alto, CA 94303 USA. All rights reserved.
US Government Users Restricted Rights - Use, duplication or disclosure restricted by GSA ADP Schedule Contract with IBM Corp.
This information center is powered by Eclipse technology. (http://www.eclipse.org/)