My Workday

I find often time very useful to use this script to evaluate GC behavior/RCA which is published at java.net (http://java.net/projects/printgcstats/sources/svn/show).

# PrintGCStats - summarize statistics about garbage collection, in particular gc
# pause time totals, averages, maximum and standard deviations.
#
# Attribution: written by John Coomes, based on earlier work by Peter Kessler,
# Ross Knippel and Jon Masamitsu.
# This version is based off of a version posted on the OpenJDK
# mailing list on 04/20/2007 and available at:-
# http://article.gmane.org/gmane.comp.java.openjdk.hotspot.gc.devel/51/match=gc+log+reader
# Modifications by Y. Srinivas Ramakrishna
#
# The input to this script should be the output from the HotSpot(TM)
# Virtual Machine when run with one or more of the following flags:
#
# -verbose:gc # produces minimal output so statistics are
# # limited, but available in all VMs
#
# -XX:+PrintGCTimeStamps # enables time-based statistics (e.g.,
# # allocation rates, intervals), but only
# # available in JDK 1.4.0 and later.
#
# -XX:+PrintGCDetails # enables more detailed statistics gathering,
# # but only available in JDK 1.4.1 and later.
#
# -XX:-TraceClassUnloading # [1.5.0 and later] disable messages about class
# # unloading, which are enabled as a side-effect
# # by -XX:+PrintGCDetails. The class unloading
# # messages confuse this script and will cause
# # some GC information in the log to be ignored.
# #
# # Note: This option only has an effect in 1.5.0
# # and later. Prior to 1.5.0, the option is
# # accepted, but is overridden by
# # -XX:+PrintGCDetails. In 1.4.2 and earlier
# # releases, use -XX:-ClassUnloading instead (see
# # below).
#
# -XX:-ClassUnloading # disable class unloading, since PrintGCDetails
# # turns on TraceClassUnloading, which cannot be
# # overridden from the command line until 1.5.0.
#
# Recommended command-line with JDK 1.5.0 and later:
#
# java -verbose:gc -XX:+PrintGCTimeStamps -XX:+PrintGCDetails \
# -XX:-TraceClassUnloading ...
#
# Recommended command-line with JDK 1.4.1 and 1.4.2:
#
# java -verbose:gc -XX:+PrintGCTimeStamps -XX:+PrintGCDetails \
# -XX:-ClassUnloading ...
#
# ------------------------------------------------------------------------------
#
# Usage:
#
# PrintGCStats -v cpus=<n> [-v interval=<seconds>] [-v verbose=1] [file ...]
# PrintGCStats -v plot=name [-v plotcolumns=<n>] [-v verbose=1] [file ...]
#
# cpus - number of cpus on the machine where java was run, used to
# compute cpu time available and gc 'load' factors. No default;
# must be specified on the command line (defaulting to 1 is too
# error prone).
#
# ncpu - synonym for cpus, accepted for backward compatibility
#
# interval - print statistics at the end of each interval; requires
# output from -XX:+PrintGCTimeStamps. Default is 0 (disabled).
#
# plot - generate data points useful for plotting one of the collected
# statistics instead of the normal statistics summary. The name
# argument is the name of one of the output statistics, e.g.,
# "gen0t(s)", "cmsRM(s)", "commit0(MB)", etc.
#
# The default output format for time-based statistics such as
# "gen0t(s)" includes four columns, described below. The
# default output format for size-based statistics such as
# "commit0(MB)" includes just the first two columns. The
# number of columns in the output can be set on the command
# line with -v plotcolumns=<N>.
#
# The output columns are:
#
# 1) the starting timestamp if timestamps are present, or a
# simple counter if not
#
# 2) the value of the desired statistic (e.g., the length of a
# cms remark pause).
#
# 3) the ending timestamp (or counter)
#
# 4) the value of the desired statistic (again)
#
# The last column is to make plotting start & stop events
# easier.
#
# plotcolumns - the number of columns to include in the plot data.
#
# verbose - if non-zero, print each item on a separate line in addition
# to the summary statistics
#
# Typical usage:
#
# PrintGCStats -v cpus=4 gc.log > gc.stats
#
# ------------------------------------------------------------------------------
#
# Basic Output statistics:
#
# gen0(s) - young gen collection time, excluding gc_prologue & gc_epilogue.
# gen0t(s) - young gen collection time, including gc_prologue & gc_epilogue
# gen1i(s) - train generation incremental collection
# gen1t(s) - old generation collection/full GC
# cmsIM(s) - CMS initial mark pause
# cmsRM(s) - CMS remark pause
# cmsRS(s) - CMS resize pause
# GC(s) - all stop-the-world GC pauses
# cmsCM(s) - CMS concurrent mark phase
# cmsCP(s) - CMS concurrent preclean phase
# cmsCS(s) - CMS concurrent sweep phase
# cmsCR(s) - CMS concurrent reset phase
# alloc(MB) - object allocation in MB (approximate***)
# promo(MB) - object promotion in MB (approximate***)
# used0(MB) - young gen used memory size (before gc)
# used1(MB) - old gen used memory size (before gc)
# used(MB) - heap space used memory size (before gc) (excludes perm gen)
# commit0(MB) - young gen committed memory size (after gc)
# commit1(MB) - old gen committed memory size (after gc)
# commit(MB) - heap committed memory size (after gc) (excludes perm gen)
# apptime(s) - amount of time application threads were running
# safept(s) - amount of time the VM spent at safepoints (app threads stopped)
#
# *** - these values are approximate because there is no way to track
# allocations that occur directly into older generations.
#
# Some definitions:
#
# 'mutator' or 'mutator thread': a gc-centric term referring to a non-GC
# thread that modifies or 'mutates' the heap by allocating memory and/or
# updating object fields.
#
# promotion: when an object that was allocated in the young generation has
# survived long enough, it is copied, or promoted, into the old generation.
#
# Time-based Output Statistics (require -XX:+PrintGCTimeStamps):
#
# alloc/elapsed_time - allocation rate, based on elapsed time
# alloc/tot_cpu_time - allocation rate, based on total cpu time
# alloc/mut_cpu_time - allocation rate, based on cpu time available to mutators
# promo/elapsed_time - promotion rate, based on elapsed time
# promo/gc0_time - promotion rate, based on young gen gc time
# gc_seq_load - the percentage of cpu cycles used by gc 'serially'
# (i.e., while java application threads are stopped)
# gc_conc_load - the percentage of cpu cycles used by gc 'concurrently'
# (i.e., while java application threads are also running)
# gc_tot_load - the percentage of cpu cycles spent in gc