garbagecat

A command line tool that parses Java garbage collection logging and does analysis to support JVM tuning and troubleshooting for OpenJDK and Sun/Oracle JDK. It differs from other tools in that it goes beyond the simple math of calculating statistics such as maximum pause time and throughput. It analyzes collectors, triggers, JVM version, JVM options, and OS information and reports error/warn/info level analysis and recommendations.

Supports

OpenJDK derivatives:

• Adoptium/AdoptOpenJDK
• Azul
• Microsoft build of OpenJDK
• Oracle JDK
• Red Hat build of OpenJDK
• etc.

Recommended GC Logging Options

JDK9+ (time):

-Xlog:gc*,safepoint=info:file=gc_%p_%t.log:time:filecount=4,filesize=50M

[2020-02-14T15:21:55.207-0500] GC(0) Pause Young (Normal) (G1 Evacuation Pause)

JDK8 (datestamp):

-XX:+PrintGC -XX:+PrintGCDetails -XX:-PrintGCTimeStamps -XX:+PrintGCDateStamps -XX:+PrintGCApplicationStoppedTime -Xloggc:gc_%p_%t.log -XX:+UseGCLogFileRotation -XX:GCLogFileSize=50M -XX:NumberOfGCLogFiles=4


2021-10-08T20:22:22.788-0600: [GC (Allocation Failure) [PSYoungGen: 328070K->55019K(503808K)] 649122K->396284K(1078272K), 0.3093583 secs] [Times: user=0.43 sys=0.12, real=0.31 secs]

JDK5 - JDK8:

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

Running

There is no need to download or build garbagecat to run the latest code. Simply run the container release, which is updated with each commit.

For example, run the following in the directory where gc-example exists (GARBAGECAT_HOME/src/test/):

docker run --pull=always -v "$PWD":/home/garbagecat/files:z ghcr.io/mgm3746/garbagecat:latest --console -p -t 20 /home/garbagecat/files/gc-example.log > report.txt

NOTES:

1. Local directory gets mounted to the /home/garbagecat/files/ container directory.
2. The local directory must have world execute permission (Linux).
3. The report is written to stdout with the --console option.
4. Containers are automatically updated with each commit, so you are always running with the lastest updates.
5. Supported architectures are x86_64 and arm64.

Building

Get source:

$ git clone https://github.com/mgm3746/garbagecat.git

Build it:

$ cd garbagecat
$ /path/to/mvn clean (rebuilding)
$ /path/to/mvn --settings settings.xml package
$ export JAVA_HOME=/usr/lib/jvm/java/ (or wherever a JDK is installed)
$ /path/to/mvn --settings settings.xml javadoc:javadoc

If you get the following error:

org.apache.maven.surefire.booter.SurefireExecutionException: TestCase; nested exception is java.lang.NoClassDefFoundError: TestCase

Run the following command:

$ /path/to/mvn -U -fn clean install

Usage

$ docker run --pull=always -v "$PWD":/home/garbagecat/files:z ghcr.io/mgm3746/garbagecat:latest --help
usage: garbagecat [OPTION]... [FILE] 
 -c,--console               print report to stdout instead of file
 -h,--help                  help
 -j,--jvmoptions <arg>      JVM options used during JVM run
 -o,--output <arg>          output file name (default report.txt)
 -p,--preprocess            do preprocessing
 -r,--reorder               reorder logging by timestamp
 -s,--startdatetime <arg>   JVM start datetime (yyyy-MM-dd HH:mm:ss.SSS)
                            to convert uptime to datestamp in reporting
 -t,--threshold <arg>       threshold (0-100) for throughput bottleneck
                            reporting
 -v,--verbose               verbose output

Notes:

1. JVM options are can be passed in if they are not present in the gc logging header. Specifying the JVM options used during the JVM run allows for more detailed analysis.
2. By default a report called report.txt is created in the directory where the garbagecat tool is run. Specifying a custom name for the output file is useful when analyzing multiple gc logs.
3. Preprocessing is often required (e.g. when non-standard JVM options are used). It removes extraneous logging and makes any format adjustments needed for parsing (e.g. combining logging that the JVM sometimes splits across multiple lines).
4. Reordering is for gc logging that has gotten out of time/date order. Very rare, but some logging management systems/processes are susceptible to this happening (e.g. logging stored in a central repository).
5. The startdatetime option is used to convert uptime (e.g. 121.107) to datestamp (e.g. 2017-04-03T03:13:06.756-0500) in the report (e.g. throughput, inverted parallelism max, etc.).
6. If threshold is not defined, it defaults to 90.
7. 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).

Example

https://github.com/mgm3746/garbagecat/tree/master/src/test/gc-example.log

$ java -jar garbagecat.jar /path/to/garbagecat/src/test/gc-example.log

Report

=======================================================================
JVM:
-----------------------------------------------------------------------
Version: Java HotSpot(TM) 64-Bit Server VM (25.102-b14) for linux-amd64 JRE (1.8.0_102-b14), built on Jun 22 2016 18:43:17 by "java_re" with gcc 4.3.0 20080428 (Red Hat 4.3.0-8)
Options: -XX:CMSInitiatingOccupancyFraction=80 -XX:+CMSParallelRemarkEnabled -XX:+DisableExplicitGC -XX:+DoEscapeAnalysis -XX:ErrorFile=/home/jbcures/errors/hs_err_pid%p.log -XX:+HeapDumpOnOutOfMemoryError -XX:HeapDumpPath=/jboss/app-files/crash/cures/ -XX:InitialHeapSize=8589934592 -XX:MaxHeapSize=8589934592 -XX:MaxNewSize=174485504 -XX:MaxTenuringThreshold=6 -XX:NewSize=174485504 -XX:OldPLABSize=16 -XX:OldSize=348971008 -XX:ParallelGCThreads=2 -XX:+PrintGC -XX:+PrintGCDateStamps -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:+UseCMSInitiatingOccupancyOnly -XX:+UseCompressedClassPointers -XX:+UseCompressedOops -XX:+UseConcMarkSweepGC -XX:+UseParNewGC 
Memory: Memory: 4k page, physical 32878232k(18756444k free), swap 4194300k(4194300k free)
=======================================================================
SUMMARY:
-----------------------------------------------------------------------
Datestamp First: 2016-10-10T18:43:49.025-0700
Timestamp First: 1.362 secs
Datestamp Last: 2016-10-11T12:34:47.720-0700
Timestamp Last: 64260.057 secs
# GC Events: 36546
Event Types: PAR_NEW, CMS_INITIAL_MARK, CMS_CONCURRENT, CMS_REMARK, CMS_SERIAL_OLD
# Parallel Events: 36545
# Inverted Parallelism: 2
Inverted Parallelism Max: 2016-10-11T08:06:39.037-0700: 48171.374: [GC (CMS Initial Mark) [1 CMS-initial-mark: 6578959K(8218240K)] 6599305K(8371584K), 0.0118105 secs] [Times: user=0.01 sys=0.00, real=0.02 secs] 
# Serial Events: 1
NewRatio: 54
Heap Used Max: 7092037K
Heap After GC Max: 6988066K
Heap Allocation Max: 8371584K
Metaspace Used Max: 167164K
Metaspace After GC Max: 167164K
Metaspace Allocation Max: 1204224K
GC Throughput: 96%
GC Pause Max: 7.528 secs
GC Pause Total: 2623.500 secs
=======================================================================
ANALYSIS:
-----------------------------------------------------------------------
error
-----------------------------------------------------------------------
*The CMS_SERIAL_OLD collector is being invoked for one of the following reasons: (1) Fragmentation. The concurrent low pause collector does not compact. When fragmentation becomes an issue a serial collection compacts the heap. If the old generation has available space, the cause is likely fragmentation. Fragmentation can be avoided by increasing the heap size. (2) Metaspace class metadata or compressed class pointers allocation failure. The GC attempts to free/resize metaspace. (3) Resizing perm gen. If perm gen occupancy is near perm gen allocation, the cause is likely perm gen. Perm gen resizing can be avoided by setting the minimum perm gen size equal to the the maximum perm gen size. For example: -XX:PermSize=256M -XX:MaxPermSize=256M. (4) Undetermined reasons. Possibly the JVM requires a certain amount of heap or combination of resources that is not being met, and consequently the concurrent low pause collector is not used despite being specified with the -XX:+UseConcMarkSweepGC option. The CMS_SERIAL_OLD collector is a serial (single-threaded) collector, which means it can take a very long time to collect a large heap. For optimal performance, tune to avoid serial collections.
*CMS promotion failed. A young generation collection is not able to complete because there is not enough space in the old generation for promotion. The old generation has available space, but it is not contiguous. When fragmentation is an issue, the concurrent low pause collector invokes a slow (single-threaded) serial collector to compact the heap. Tune to avoid fragmentation: (1) Increase the heap size. (2) Use -XX:CMSInitiatingOccupancyFraction=N (default 92) to run the CMS cycle more frequently to increase sweeping of dead objects in the old generation to free lists (e.g. -XX:CMSInitiatingOccupancyFraction=85 -XX:+UseCMSInitiatingOccupancyOnly). (3) Do heap dump analysis to determine if there is unintended object retention that can be addressed to decrease heap demands. Or move to a collector that handles fragmentation more efficiently: (1) G1 compacts the young and old generations during evacuation using a multi-threaded collector. (2) Shenandoah compacts concurrently. Temporarily add -XX:PrintFLSStatistics=1 and -XX:+PrintPromotionFailure to get additional insight into fragmentation.
*Unidentified log line(s). Try running with the -p (preparsing) option.   
-----------------------------------------------------------------------
warn
-----------------------------------------------------------------------
*CMS remark low parallelism: (1) If using JDK7 or