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).
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.
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.
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.
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.
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.