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 explicit System.gc() call in the code.
- The JVM running out of memory and performing a synchronous garbage
collection to avoid an OutOfMemoryErrorcondition.
- The JVM shutting down, while there is a continuous garbage collection.
The JVM cannot just cancel that collection, but finishes it synchronously
and only then exits.
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)