Verbose garbage collection

Use different verbose garbage collection command-line parameters depending on the operating system and the runtime environment that you are using.

IBM SDK, Java Technology Edition, Version 6 with an IBM J9 2.6 virtual machine, and later versions

Note: If you are using an IBM® J9 2.4 virtual machine, see the following section. To find out which IBM J9 virtual machine (VM) you are using, enter the following command:
java -version
The output includes the build level for the IBM J9 VM. For example:
IBM J9 VM (build 2.4, J2RE 1.6.0 IBM...

Example verbose garbage collection output:

<cycle-start id="14" type="partial gc"
contextid="0" timestamp="2010-11-23T09:41:11.164" intervalms="28.543"
/>
<gc-start id="15" type="partial gc" contextid="14" timestamp="2010-11-23T09:41:11.164">
  <mem-info id="16" free="217055232" total="242745344" percent="89">
    <mem type="eden" free="0" total="13107200" percent="0">
    <pending-finalizers system="6" default="0" reference="0" classloader="0"
/>
    <remembered-set free="9659136" total="9660032" percent="99"
regionsoverflowed="0"/>
  </mem-info>
</gc-start>
<allocation-stats totalBytes="0" >
  <allocated-bytes non-tlh="0" tlh="0" />
  <largest-consumer threadName="Attach API wait loop" threadId="16390200"
bytes="0" />
</allocation-stats>
<gc-op id="17" type="copy forward" timems="2.758" contextid="14"
timestamp="2010-11-23T09:41:11.167">
  <memory-copied type="eden" objects="0" bytes="0" bytesdiscarded="0"
/>
  <memory-copied type="other" objects="9909" bytes="600604" bytesdiscarded="53040"
/>
  <memory-cardclean objects="0" bytes="0" />
  <finalization candidates="81" enqueued="81" />
  <references type="soft" candidates="7" cleared="0" enqueued="0"
dynamicThreshold="30" maxThreshold="32" />
  <references type="weak" candidates="12" cleared="0" enqueued="0"
/>
  <references type="phantom" candidates="1" cleared="0" enqueued="0"
/>
</gc-op>
<gc-op id="18" type="classunload" timems="0.006" contextid="14"
timestamp="2010-11-23T09:41:11.167">
  <classunload-info classloadercandidates="3" classloadersunloaded="0"
classesunloaded="0" quiescems="0.000" setupms="0.002" scanms="0.001"
postms="0.002" />
</gc-op>
<heap-resize id="19" type="expand" space="default" amount="71303168"
count="1" timems="4.550" reason="satisfy allocation request" timestamp="2010-11-23T09:41:11.171"
/>
<gc-end id="20" type="partial gc" contextid="14" durationms="7.943"
timestamp="2010-11-23T09:41:11.171">
  <mem-info id="21" free="288358400" total="314048512" percent="91">
    <pending-finalizers system="6" default="0" reference="0" classloader="0"
/>
    <remembered-set free="12496640" total="12497536" percent="99"
regionsoverflowed="0"/>
  </mem-info>
</gc-end>
<cycle-end id="22" type="partial gc" contextid="14" timestamp="2010-11-23T09:41:11.171"
/>

IBM SDK, Java Technology Edition, Versions 5.0 and 6, and IBM WebSphere Real Time

Consider using the -Xverbosegclog command-line parameter instead of the -verbose:gc command-line parameter. The -Xverbosegclog parameter writes the verbose garbage collection data to a file instead of the standard error (stderr) stream. Verbose garbage collection logs are created in XML format. If the logs are output to the stderr stream, the verbose garbage collection data can be mixed with other output from your application. This other output could prevent the garbage collection log file from being well-formed XML.

The GCMV parsers for these Java™ products can still process such mixed output, because they do not use a standard XML parser. The parsers attempt to parse only the verbose garbage collection data, and ignore other information that is mixed with it. However, applications can generate output that prevents the parsers from being able to process the file. In these situations, you must use the -Xverbosegclog parameter to isolate the verbose garbage collection data from any other output.

Parameter usage:
-Xverbosegclog:[DIR_PATH][FILE_NAME]
DIR_PATH is the path to the output file, and FILE_NAME is the name of the output file. For example, -Xverbosegclog:c:\vgc\out.xml writes the verbose garbage collection output to the file C:\vgc\out.xml.

Timestamps are reported in the verbose garbage collection logs with second-precision. The parsers use the reported intervals to estimate a more precise time stamp, however, this extra precision is an estimate. The timestamps have only second-level accuracy.

For WebSphere® Real Time, pause times are reported in milliseconds in the verbose garbage collection logs.

Example output for WebSphere Real Time:
<gc type="heartbeat" id="130" timestamp="Feb 09 11:50:06 2010" intervalms="1005.411">
  <summary quantumcount="108">
    <quantum minms="0.192" meanms="0.497" maxms="0.538" />
    <exclusiveaccess minms="0.633" meanms="2.256" maxms="7.967" />
    <heap minfree="529443904" meanfree="551106127" maxfree="568143452" />
    <immortal minfree="201328804" meanfree="201328819" maxfree="201328884" />
    <gcthreadpriority max="11" min="11" />
  </summary>
</gc>

<gc type="heartbeat" id="131" timestamp="Feb 09 11:50:07 2010" intervalms="1000.556">
  <summary quantumcount="117">
    <quantum minms="0.030" meanms="0.459" maxms="0.543" />
    <exclusiveaccess minms="0.115" meanms="1.888" maxms="5.027" />
    <heap minfree="501523620" meanfree="515507724" maxfree="529443904" />
    <immortal minfree="201328804" meanfree="201328804" maxfree="201328804" />
    <gcthreadpriority max="11" min="11" />
  </summary>
</gc>
Example output for IBM SDK, Java Technology Edition, Version 5.0:
<af type="nursery" id="11" timestamp="Mon Nov 07 05:31:25 2005" intervalms="3392.068">
  <minimum requested_bytes="8216" />
  <time exclusiveaccessms="2.663" />
  <nursery freebytes="3200" totalbytes="234317824" percent="0" />
  <tenured freebytes="523109400" totalbytes="524288000" percent="99" >
    <soa freebytes="496895000" totalbytes="498073600" percent="99" />
    <loa freebytes="26214400" totalbytes="26214400" percent="100" />
  </tenured>
  <gc type="scavenger" id="11" totalid="11" intervalms="3395.279">
    <flipped objectcount="179035" bytes="45439568" />
    <tenured objectcount="160864" bytes="17525464" />
    <refs_cleared soft="0" weak="3" phantom="0" />
    <finalization objectsqueued="5656" />
    <scavenger tiltratio="75" />
    <nursery freebytes="189675936" totalbytes="236904448" percent="80" tenureage="10" />
    <tenured freebytes="504900216" totalbytes="524288000" percent="96" >
      <soa freebytes="478685816" totalbytes="498073600" percent="96" />
      <loa freebytes="26214400" totalbytes="26214400" percent="100" />
    </tenured>
    <time totalms="244.167" />

IBM SDK, Java Technology Edition, Version 1.4.2

Example output:
<AF[1]: Allocation Failure. need 528 bytes, 0 ms since last AF>
<AF[1]: managing allocation failure, action=1 (0/1494219336) (78643128/78643128)>
  <GC(3): GC cycle started Tue May 17 19:11:56 2005
  <GC(3): freed 647776512 bytes, 46% free (726419640/1572862464), in 717 ms>
  <GC(3): mark: 559 ms, sweep: 158 ms, compact: 0 ms>
  <GC(3): refs: soft 0 (age >= 32), weak 0, final 5, phantom 0>
<AF[1]: completed in 717 ms>

IBM SDK for Node.js

Use one of the following command-line parameters to generate garbage collection data:

--trace_gc
This parameter is the basic option, and outputs a single line after each garbage collection.
--trace_gc_nvp
You can use this parameter in addition to the basic option to produce more detailed, single-line output in the format name=value.
--trace_gc-verbose
You can use this parameter in addition to the basic option to produce more detailed, multiple-line output after each garbage collection.
For example:
node --trace_gc example.js
Example output from the combined --trace_gc --trace_gc-verbose command:
[1240]      454 ms: Mark-sweep 5.0 (38.0) -> 1.7 (36.0) MB, 5 ms [allocation failure] [GC in old space requested].
[1240] Memory allocator,   used:  36865 KB, available: 1462271 KB
[1240] New space,          used:      0 KB, available:   1023 KB, committed:   2048 KB
[1240] Old pointers,       used:    886 KB, available:     11 KB, committed:   1519 KB
[1240] Old data space,     used:    381 KB, available:     10 KB, committed:   1199 KB
[1240] Code space,         used:    423 KB, available:    572 KB, committed:    996 KB
[1240] Map space,          used:     71 KB, available:     56 KB, committed:    128 KB
[1240] Cell space,         used:     15 KB, available:    112 KB, committed:    128 KB
[1240] Large object space, used:      0 KB, available: 1461230 KB, committed:      0 KB
[1240] All spaces,         used:   1777 KB, available:   1787 KB, committed:   6019 KB
[1240] Total time spent in GC  : 5 ms

HP-UX operating system and IBM SDK, Java Technology Edition

Use the -Xverbosegclog command-line parameter to generate verbose garbage collection data.

Example output:
<GC: 1 40  36.578367 1 128 7 100663296 128 100663296 0 7053760 16777216 0 0 402653184 25784112 25784112 67108864 4.354989 4.354989 >
<GC: 1 40  64.982976 2 40 7 100663296 40 201326592 7053760 10045016 16777216 0 0 402653184 40529744 40529744 67108864 1.639658 1.639658 >
<GC: 1 40  85.551265 3 8208 7 201326592 8208 201326592 10045016 16416768 16777216 0 0 402653184 55980376 55980376 67108864 1.064654 1.064654 >

iSeries operating system and IBM SDK, Java Technology Edition

iSeries garbage collection logs are supported.

Solaris operating system and IBM SDK, Java Technology Edition

Use the following command-line parameters to generate all the information that the IBM Monitoring and Diagnostic Tools - Garbage Collection and Memory Visualizer (GCMV) can parse from a Solaris Java virtual machine log:
  • -XX:+PrintGCDateStamps. This parameter prints a full time stamp of the following form: 2012-10-08T14:24:03.501+0100:
  • -XX:+PrintGCDetails
  • -XX:+PrintGCTimeStamps. This parameter prints a relative time stamp at the start of each garbage collection. If you do not use this parameter, you can plot only against collection number in GCMV.
  • -XX:+PrintHeapAtGC. This parameter provides additional information about the layout of the Java heap, but produces a lot of output. Omit this parameter if log size is a concern.

Consider using the -Xloggc parameter, which writes the verbose garbage collection data to a specified file. This behavior prevents the data being mixed with other information that the application might write to the standard error stream, which can cause problems when you open the file in GCMV.

If you use the -XX:+UseG1GC parameter, the Garbage First (G1) collector is enabled. GCMV can parse the following data from a G1-generated log, for full, partial, and young garbage collection types:
  • The mean pause time for each collection.
  • The mean interval time between collections.
  • The size of the eden and survivor spaces, and of the total heap, before and after garbage collection.
  • The amount of the eden and survivor spaces, and of the total heap, that is in use before and after garbage collection.

Solaris verbose garbage collection has many configurable parameters. Depending on which garbage collection-related options are enabled when the runtime environment starts, some menu items might not be available when you open the log file in GCMV.

Parent topic: Supported data types
Related information:
Java technology, IBM style: Garbage collection policies, Part 1
IBM Systems Journal: Tuning Garbage Collection With IBM Technology for Java
developerWorks Java zone
Documentation for IBM SDK, Java Technology Edition



© Copyright IBM Corporation 2005, 2016.

US Government Users Restricted Rights - Use, duplication or disclosure restricted by GSA ADP Schedule Contract with IBM Corp.