Java GC Tuning using GarbageCat Tool

A bottleneck is when throughput between two consecutive GC events of the same type is less than the specified throughput threshold.
Throughput = (Time spent not doing GC) / (Total Time). Throughput of 100 means no time spent doing GC (good). Throughput of 0 means all time spent doing GC (bad).

To optimise bottlenecks we need to start GC logging to do this we shall use below parameters in JAVA_OPTIONS while starting the JVM

-XX:+PrintGC -Xloggc:gc.log -XX:+PrintGCDetails -XX:+PrintGCTimeStamps

Sample Log with above options

133.720: [GC 133.763: [ParNew: 272640K->34047K(306688K), 0.0689257 secs] 272640K->34419K(490240K), 0.0690454 secs] [Times: user=0.12 sys=0.00, real=0.11 secs] 
141.334: [GC [1 CMS-initial-mark: 371K(183552K)] 157824K(490240K), 0.0449396 secs] [Times: user=0.05 sys=0.00, real=0.05 secs] 
141.380: [CMS-concurrent-mark-start]
141.429: [CMS-concurrent-mark: 0.050/0.050 secs] [Times: user=0.06 sys=0.00, real=0.05 secs] 
141.429: [CMS-concurrent-preclean-start]
141.438: [CMS-concurrent-preclean: 0.008/0.008 secs] [Times: user=0.02 sys=0.00, real=0.01 secs] 
141.438: [CMS-concurrent-abortable-preclean-start]
160.214: [GC 160.214: [ParNew: 306687K->33063K(306688K), 0.1172920 secs] 307059K->46885K(490240K), 0.1173882 secs] [Times: user=0.26 sys=0.02, real=0.12 secs] 
 CMS: abort preclean due to time 170.056: [CMS-concurrent-abortable-preclean: 1.740/28.618 secs] [Times: user=8.28 sys=1.17, real=28.62 secs] 
170.056: [GC[YG occupancy: 159094 K (306688 K)]170.056: [Rescan (parallel) , 0.0541180 secs]170.110: [weak refs processing, 0.0000096 secs]170.110: [scrub string table, 0.0012853 secs] [1 CMS-remark: 13821K(183552K)] 172916K(490240K), 0.0555534 secs] [Times: user=0.20 sys=0.00, real=0.06 secs] 
170.111: [CMS-concurrent-sweep-start]
170.128: [CMS-concurrent-sweep: 0.017/0.017 secs] [Times: user=0.00 sys=0.00, real=0.02 secs] 
170.128: [CMS-concurrent-reset-start]
170.138: [CMS-concurrent-reset: 0.010/0.010 secs] [Times: user=0.02 sys=0.00, real=0.01 secs] 
181.785: [GC 181.786: [ParNew: 305703K->34048K(306688K), 0.0822464 secs] 319525K->62154K(490240K) icms_dc=19 , 0.0823457 secs] [Times: user=0.28 sys=0.00, real=0.08 secs] 
192.445: [GC [1 CMS-initial-mark: 28106K(183552K)] 173067K(490240K), 0.0997967 secs] [Times: user=0.09 sys=0.00, real=0.10 secs] 
192.545: [CMS-concurrent-mark-start]
192.694: [CMS-concurrent-mark: 0.149/0.149 secs] [Times: user=0.27 sys=0.05, real=0.15 secs] 
192.694: [CMS-concurrent-preclean-start]
192.701: [CMS-concurrent-preclean: 0.006/0.007 secs] [Times: user=0.00 sys=0.00, real=0.01 secs] 
192.701: [CMS-concurrent-abortable-preclean-start]

OR

-XX:+PrintGC -Xloggc:gc.log -XX:+PrintGCDetails -XX:+PrintGCDateStamps

Sample Log with above options

009-10-14 08:02:13,871: [Full GC 2009-10-14 08:02:13,871: [CMS (concurrent mode failure): 1179647K->1179648K(1179648K), 7.7971770 secs] 1441599K->1440481K(1441600K), [CMS Perm : 72831K->72830K(262144K)], 7.7974610 secs]
2009-10-14 08:02:21,681: [Full GC 2009-10-14 08:02:21,681: [CMS (concurrent mode failure): 1179648K->1179648K(1179648K), 7.9398610 secs] 1441599K->1440455K(1441600K), [CMS Perm : 72832K->72832K(262144K)], 7.9401510 secs]
2009-10-14 08:02:29,636: [Full GC 2009-10-14 08:02:29,636: [CMS (concurrent mode failure): 1179648K->1179648K(1179648K), 7.9886750 secs] 1441599K->1440570K(1441600K), [CMS Perm : 72834K->72833K(262144K)], 7.9889480 secs]
2009-10-14 08:02:37,643: [Full GC 2009-10-14 08:02:37,644: [CMS (concurrent mode failure): 1179648K->1179647K(1179648K), 8.7149400 secs] 1441600K->1440451K(1441600K), [CMS Perm : 72839K->72831K(262144K)], 8.7153850 secs]
2009-10-14 08:02:46,789: [Full GC 2495523.446 (concurrent mode failure): 1179647K->1179647K(1179648K), 12.9441410 secs] 1441599K->1440523K(1441600K), [CMS Perm : 72832K->72831K(262144K)], 12.9444090 secs]
...
2009-10-14 08:02:59,743: [Full GC 2009-10-14 08:02:59,743: [CMS (concurrent mode failure): 1179647K->1179647K(1179648K), 7.8316830 secs] 1441599K->1440330K(1441600K), [CMS Perm : 72831K->72824K(262144K)], 7.8319710 secs]
2009-10-14 08:03:07,591: [Full GC 2009-10-14 08:03:07,592: [CMS (concurrent mode failure): 1179648K->1179647K(1179648K), 7.2906420 secs] 1441599K->1440451K(1441600K), [CMS Perm : 72835K->72827K(262144K)], 7.2910060 secs]
2009-10-14 08:03:14,908: [Full GC 2009-10-14 08:03:14,908: [CMS (concurrent mode failure): 1179647K->1179647K(1179648K), 7.5929380 secs] 1441599K->1440526K(1441600K), [CMS Perm : 72844K->72834K(262144K)], 7.5933150 secs]
2009-10-14 08:03:22,981: [Full GC 2495559.638 (concurrent mode failure): 1179647K->1179647K(1179648K), 12.0032770 secs] 1441599K->1440585K(1441600K), [CMS Perm : 72841K->72832K(262144K)], 12.0035460 secs]

If Garbagecat is used then the report will look like below but to get below kind of report and analysis you have to use a GC log which is old enough or having multi full GC’s to get more accurate results.

Garbage Cat can be downloaded from here.

Sample Report

========================================
Throughput less than 90% for PARALLEL_SCAVENGE
========================================
18020.492: [GC [PSYoungGen: 161888K->1376K(166016K)] 949359K->789159K(1214592K), 0.0294550 secs]
18020.680: [GC [PSYoungGen: 3431K->288K(159936K)] 791214K->788615K(1208512K), 0.0206630 secs]
...
36039.921: [GC [PSYoungGen: 165776K->8752K(166784K)] 1024637K->867893K(1215360K), 0.0340270 secs]
36040.106: [GC [PSYoungGen: 39649K->1024K(167744K)] 898790K->861694K(1216320K), 0.0269690 secs]
...
191119.769: [GC [PSYoungGen: 195760K->6208K(197888K)] 1157602K->968330K(1246464K), 0.0333630 secs]
191119.803: [GC [PSYoungGen: 6615K->96K(201984K)] 968738K->968480K(1250560K), 0.0289500 secs]
========================================
SUMMARY:
========================================
JVM options: -Xms1024m -Xmx2048m
# GC Events: 46044
GC Event Types: PARALLEL_SCAVENGE, PARALLEL_SERIAL_OLD
Max Heap Space: 1566912K
Max Heap Occupancy: 1562164K
Max Perm Space: 77864K
Max Perm Occupancy: 46645K
Throughput: 99%
Max Pause: 4098 ms
Total Pause: 1703657 ms
First Timestamp: 4616 ms
Last Timestamp: 232465068 ms
========================================
0 UNIDENTIFIED LOG LINE(S):
========================================

– The report contains three sections: (1) Bottlenecks, (2) Summary, and (3) Unidentified log lines.
– A bottleneck is when throughput between two consecutive GC events of the same type is less than the specified throughput threshold.
– Bottlenecks are reported within the same GC event type because there does not seem to be a correlation between timestamps between event types (due to different threads, perhaps?). For example, the duration of a tenured collection can exceed the time interval elapsed since the previous young collection. Also, it makes sense to look for bottlenecks within an event type, as typical issues are continuous young collections one after another or continuous old collections one after another.
– An ellipsis (…) between log lines in the bottleneck section indicates time periods when throughput was above the threshold.
– If the bottleneck section is missing, then no bottlenecks were found for the given threshold.
– See the org.eclipselabs.garbagecat.domain.jdk package summary javadoc for GC event type definitions. There is a table that lists all the event types with links to detailed explanations and example logging.
– A garbage collection event corresponds to a single garbage collection log line.
– You can get a good idea where hot spots are by running the report multiple times with varying throughput threshold levels.
– There is a limit of 1000 unidentified log lines that will be reported.
– If there are any unidentifed logging lines, run the report again with the -p preprocessing option enabled. Preprocessing removes extraneous information (e.g. application logging when there is not a dedicated log file) and makes any format adjustments needed for parsing (e.g. combining logging that the JVM sometimes splits across two lines).
– Once prepocessing is done once, do not use the -p preprocessing option again, but instead specify the preprocessed file as input (e.g. java -jar /path/to/garbagecat-1.0.0.jar gc.log.pp).

You can have more detailed description over here

If you want to force full garbage collection when memory occupation goes beyond a certain threshold, you can use below option in your JVM options to force GC at certain percentage.

-XX:CMSInitiatingOccupancyFraction=percent

where % is the % of memory in use that will trigger a full GC.You can also analyse through a tool jvisualvm to get which part of JVM is giving the trouble.

More references on tuning GC can be taken from here

In case of any ©Copyright or missing credits issue please check CopyRights page for faster resolutions.