SUN JVM: potential memory leak

After running the JVM for a while, check the amount of objects remaining after a Full GC to see if there are potential memory leaks (please see OutOfMemory exceptions).

Old heap too small

If you see successive Full GCs and the "heap after GC" number is consistently larger than the size of the Old Generation, the amount of live objects is larger than the Old Generation.

GC times

Watch for GC times that take over 2-5 seconds. Recall that all threads are paused for the duration of the GC. A transaction that normally takes 1 second grows to 3-6 seconds. More importantly, blocked threads that are holding on to database locks could start to block other threads in other JVMs.

PrintGCStats script

Oracle has developed a script, PrintGCStats, to interpret the results from the output file generated by "-Xloggc:filename".. The PrintGCStats script can be downloaded from http://java.net/projects/printgcstats/. Other tools like IBM® Pattern Modeling and Analysis Tool for Java™ Garbage Collector can alternatively be used to generate graphical representation of GC logs for easier analysis.

   
Note: The PrintGCStats script can only produce meaningful results of the -Xloggc:filename output if the JVM is started with the "-verbose:gc -XX:+PrintGCTimeStamps -XX:+PrintGCDetails" flags.

An example output of the script is as follows:

   what         count       total      mean      max   stddev
   gen0(s)          9       0.591   0.06563    0.297   0.0870
   gen0t(s)         9       0.600   0.06665    0.305   0.0895
   gen1t(s)         9       7.890   0.87667    1.637   0.4381
   GC(s)           18       8.490   0.47166    1.637   0.5175
   alloc(MB)        9     721.889  80.20985   80.312   0.3079
   promo(MB)        9       0.000   0.00000    0.000   0.0000
   
   alloc/elapsed_time    =    721.889 MB /   4045.460 s  =   0.178 MB/s
   alloc/tot_cpu_time    =    721.889 MB /  32363.680 s  =   0.022 MB/s
   alloc/mut_cpu_time    =    721.889 MB /  32295.761 s  =   0.022 MB/s
   promo/elapsed_time    =      0.000 MB /   4045.460 s  =   0.000 MB/s
   promo/gc0_time        =      0.000 MB /      0.600 s  =   0.000 MB/s
   gc_seq_load           =     67.919 s  /  32363.680 s  =   0.210%
   gc_conc_load          =      0.000 s  /  32363.680 s  =   0.000%
   gc_tot_load           =     67.919 s  /  32363.680 s  =   0.210%

The following table describes what each of the tags in the above excerpt means.

Table 1. PrintGCStats output statistics
Item Name Description
gen0(s) Young generation collection time in seconds
cmsIM(s) CMS initial mark pause in seconds
cmsRM(s) CMS remark pause in seconds
GC(s) All stop-the-world GC pauses in seconds
cmsCM(s) CMS concurrent mark phase in seconds
cmsCS(s) CMS concurrent sweep phase in seconds
alloc(MB) Object allocation in young generation in MB
promo(MB) Object promotion to old generation in MB
elapsed_time(s) Total wall clock elapsed time for the application run in seconds
tot_cpu_time(s) Total CPU time = no. of CPUs * elapsed_time
mut_cpu_time(s) Total time that was available to the application in seconds
gc0_time(s) Total time used by GC during young generation pauses
alloc/elapsed_time(MB/s) Allocation rate per unit of elapsed time in MB/seconds
alloc/tot_cpu_time(MB/s) Allocation rate per unit of total CPU time in MB/seconds
alloc/mut_cpu_time(MB/s) Allocation rate per unit of total application time in MB/seconds
promo/gc0_time(MB/s) Promotion rate per unit of GC time in MB/seconds
gc_seq_load(%) Percentage of total time spent in stop-the-world GCs
gc_conc_load(%) Percentage of total time spent in concurrent GCs
gc_tot_load(%) Total percentage of GC time (sequential and concurrent)

There are two statistics generated by this script that are very useful in tuning the JVM. The statistic gc_seq_load generates the total stop the world GC time as a percent of total application time. The statistic gc_tot_load is the total GC time for both full and scavenge GCs as a percentage of total application time. When making changes to the JVM this script should be run before and after to see if there is a positive change in these numbers. It is important to note that by lowering the gc_tot_load, and increasing the gc_seq_load, there would be a degradation in performance of the application overall. The reason for this is that the gc_seq_load is the total time the application spends in "Stop the World" GCs during which all threads are stopped.