How do I enable Java garbage collection logging?

Solution Verified - Updated

Environment

  • Java
  • Red Hat JBoss Enterprise Application Platform (EAP)
  • Red Hat JBoss Enterprise Web Server (EWS)
    • Tomcat
  • Red Hat JBoss A-MQ (A-MQ) 6.x
  • Red Hat JBoss AMQ Broker (AMQ) 7.x
  • Red Hat JBoss Fuse
  • OpenShift

Issue

  • We got a OutOfMemoryError, how do we print garbage collection (GC) logs.
  • What are the best options to use for enable JVM verbose GC logging?
  • We want to troubleshoot a Java application, is there any documentation to enable GC logs?
  • How can we diagnose high cpu or memory usage on a Java application?
  • Is there any recommended way to enable GC logging?

Resolution

Enabling GC logs

Red Hat provides a JVM configuration tool to generate optimized settings for applications, including garbage collection logging. We recommend using the tool to enable garbage collection logging. Internal testing has shown GC logging overhead to be minimal. The log file isn't shared with anything else and is only written to during GC, so log contention isn't a concern. The only thing that should cause any major concerns from GC logging is if disk IO performance were poor so it is best to only use local storage for the gc log file.

For additional information and manual configuration steps, please read the section appropriate for each JVM below.

NOTE: For details on how to rotate the GC log, please refer to How can I create rolling gc.log files?.

OpenJDK 7 and earlier

-verbose:gc -Xloggc:gc.log.`date +%Y%m%d%H%M%S` -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:+PrintGCApplicationStoppedTime

  • This will log GC activity with timestamps showing seconds/milliseconds since the JVM started.

  • The following JVM options can be used on JDK 1.6 update 4 and later to log GC activity with human readable timestamps:

-verbose:gc -Xloggc:gc.log.`date +%Y%m%d%H%M%S` -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:+PrintGCDateStamps -XX:+PrintGCApplicationStoppedTime
  • If using JDK 7 update 80 or later, specify %p (pid) and %t (timestamp) instead of adding date command (date +%Y%m%d%H%M%S):
-verbose:gc -Xloggc:gc_%p_%t.log -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:+PrintGCDateStamps -XX:+PrintGCApplicationStoppedTime
  • If the -Xloggc option is not specified, output goes to standard out. Typically it is best to log to a dedicated file, so it is recommended to use the -Xloggc option.

OpenJDK 8

-XX:+PrintGC -XX:+PrintGCDetails -XX:-PrintGCTimeStamps -XX:+PrintGCDateStamps -XX:+PrintGCApplicationStoppedTime -Xloggc:/path/to/gc_%p_%t.log -XX:+UseGCLogFileRotation -XX:GCLogFileSize=3M -XX:NumberOfGCLogFiles=5

With JDK Flight Recorder JAVA_HOME/jre/lib/jfr/default.jfc settings for additional analysis:

-XX:+PrintGC -XX:+PrintGCDetails -XX:-PrintGCTimeStamps -XX:+PrintGCDateStamps -XX:+PrintGCApplicationStoppedTime -Xloggc:/path/to/gc_%p_%t.log -XX:+UseGCLogFileRotation -XX:GCLogFileSize=3M -XX:NumberOfGCLogFiles=5 -XX:+FlightRecorder -XX:StartFlightRecording=filename=/path/to/recording.jfr,maxsize=5m

Notes:

  • %p (pid) and %t (timestamp) require update 20+ (otherwise use -Xloggc:gc.log.date +%Y%m%d%H%M%S)
  • -XX:+FlightRecorder can be removed in JDK8u240+ (enabled by default).

OpenJDK 11+

JDK 11 uses unified logging. The -Xlog option is used to specify the logging level, output, decorators, and log rotation options. See JDK 11 Logging mechanism with -Xlog Option for more details.

For example, the configuration below sets the logging level to the default (info) level (gc*), safepoint logging to info level, logs output to a file (file=/path/to/gc.log), decorates (prepends) the output with the current time and date in ISO-8601 format and the number of seconds since the JVM started (time,uptime), and defines log file rotation (filecount=5,filesize=3M):

-Xlog:gc*,safepoint=info:file=/path/to/gc.log:time:filecount=5,filesize=3M

With JDK Flight Recorder JAVA_HOME/lib/jfr/default.jfc settings for additional analysis:

-Xlog:gc*,safepoint=info:file=/path/to/gc.log:time:filecount=5,filesize=3M -XX:StartFlightRecording=filename=/path/to/recording.jfr,maxsize=5m

IBM JDK

Add the following JVM options

-verbose:gc -Xverbosegclog:gc.log.`date +%Y%m%d%H%M%S`

JRockit JDK

Add the following JVM options:

-Xverbose:gcpause -Xverbose:memdbg -Xverboselog:gc.log.`date +%Y%m%d%H%M%S`

Note

  • gc.log is recreated every time the JVM starts, so be sure to back up gc.log . In the above examples, the .date +%Y%m%d%H%M%S postfix has already been added so that the gc logs are not overwritten when the JVM is restarted on Unix based OSes. For Windows, add the following:
for /f "tokens=2-4 delims=/ " %%a in ('date /t') do (set mydate=%%c-%%a-%%b)
for /f "tokens=1-2 delims=/:" %%a in ("%TIME%") do (set mytime=%%a%%b)

and then

IBM JDK 

   `set "JAVA_OPTS=%JAVA_OPTS% -verbose:gc -Xverboselog:C:\log\gc.log.%mydate%_%mytime%"`

JRockit JDK

   ` set "JAVA_OPTS=%JAVA_OPTS% -Xverbose:gcpause -Xverbose:memdbg -Xverboselog:C:\log\gc.log.%mydate%_%mytime%"`

OpenJDK / Sun JDK

   ` set "JAVA_OPTS=%JAVA_OPTS% -verbose:gc -Xloggc:C:\log\gc.log.%mydate%_%mytime% -XX:+PrintGCDetails -XX:+PrintGCDateStamps -XX:+PrintGCApplicationStoppedTime`

  • Another option to try for unique data appended file names on Windows is:

      set "JAVA_OPTS=%JAVA_OPTS% -verbose:gc -Xloggc:gc.log.%DATE:~-4,4%%DATE:~-10,2%%DATE:~-7,2%%TIME:~0,2%%TIME:~3,2% -XX:+PrintGCDetails -XX:+PrintGCDateStamps -XX:+PrintGCApplicationStoppedTime"

  • gc.log will be created in the directory defined by the user.dir environment variable if no path is provided. Check the JBoss EAP boot.log to see the value of the user.dir environment variable (e.g. $JBOSS_HOME/bin)

Where to configure the parameters

JBoss EAP 5 and earlier

Unix based OSes:
The options should be placed in run.conf, not run.sh. The run.conf in the server configuration directory (e.g.  $JBOSS_HOME/server/$CONFIG/run.conf) takes precedence over the run.conf in the $JBOSS_HOME/bin directory (except in JBoss EAP 5.0.0 due to a regression fixed in version 5.0.1).

Windows:
The options need to be added to run.bat, as run.bat does not read run.conf.

NOTE: When running multiple instances of JBoss against the same $JBOSS_HOME directory e.g 

        ./run.sh -c node1 -b 127.0.0.1 -Djboss.messaging.ServerPeerID=1
        ./run.sh -c node2 -b 127.0.0.1 -Djboss.messaging.ServerPeerID=2 -Djboss.service.binding.set=ports-01

For the gc.log files to be properly separated, make sure each $PROFILE has a unique run.conf with the JVM_OPTS specific to that $PROFILE.  For example node1 will contain a $JBOSS\_HOME/server/node1/run.conf with contents:

JAVA_OPTS="$JAVA_OPTS -verbose:gc -Xloggc:gc_node1.log -XX:+PrintGCDetails -XX:+PrintGCDateStamps -XX:+PrintGCApplicationStoppedTime"

And $JBOSS_HOME/server/node2/run.conf with contents:

JAVA_OPTS="$JAVA_OPTS -verbose:gc -Xloggc:gc_node2.log -XX:+PrintGCDetails -XX:+PrintGCDateStamps -XX:+PrintGCApplicationStoppedTime"

JBoss EAP 7/6

The options in the section above will need to be placed into the configuration file based on the mode in which JBoss is starting up.

Standalone mode:

  • For Unix based OSes add the options into standalone.conf.
  • For Windows add the options to standalone.conf.bat.

NOTE: Since EAP 6.3, GC log is enabled by default in the standalone mode.

Domain mode:

For domain mode, take account of what is the target Java process to collect GC log against. Because there are usually more than 3 java processes on the same host, Process Controller, Host Controller (Domain Controller if domain consists of only one single host) and managed server processes. In most cases, the target java process is a managed server and its java option should be written in host.xml. See How to enable Garbage Collection (GC) logging in EAP domain mode for more details

Tomcat

  • Note that these settings should be set on CATALINA_OPTS instead of JAVA_OPTS as described in How to set the JVM options for Tomcat on Linux
  • EWS ZIP distribution:
    • The JVM arguments specified above, depending upon on which JDK is being used, will need to be added to the catalina.sh (or bat for Windows).
      *If the full file path for the gc.log is not specified, then it will be located in the directory that the bin/startup script is executed from.
  • Yum installed distribution of Tomcat:
    • The JVM arguments specified above, depending upon on which JDK is being used, will need to be added to one of the following files:
      • /etc/tomcat5/tomcat5.conf
      • /etc/tomcat6/tomcat6.conf
    • If the full file path for the gc.log is not specified, then it should be located under /usr/share/tomcat/ or the directory specified for catalina.base.

A-MQ

For a standalone broker:

edit:

   bin/activemq

after:

   # CONFIGURATION
ACTIVEMQ_CONFIGS="/etc/default/activemq $HOME/.activemqrc"

add:

   ACTIVEMQ_OPTS="-verbose:gc -Xloggc:/var/log/activemq/gc.log.`date +%Y%m%d%H%M%S` -XX:+PrintGCDetails -XX:+PrintGCDateStamps -XX:+PrintGCApplicationStoppedTime"

For broker running as a Service on Linux:

edit:
/etc/activemq/wrapper.conf

after:

wrapper.java.additional.11=-Dactivemq.data=%ACTIVEMQ_DATA%

add:

#GC Logging
wrapper.java.additional.12=-verbose:gc
wrapper.java.additional.13=-Xloggc:/var/log/activemq/gc.log 
wrapper.java.additional.14=-XX:+PrintGCDetails 
wrapper.java.additional.15=-XX:+PrintGCDateStamps
wrapper.java.additional.16=-XX:-UseGCLogFileRotation
wrapper.java.additional.17=-XX:+PrintGCApplicationStoppedTime

Be sure to make the number after 'additional.' a continual sequence, don't skip any numbers or the JVM args won't be picked up.

AMQ Broker

For a standalone broker:

edit:

   etc/artemis.profile

add:
e.g;

   JAVA_ARGS="$JAVA_ARGS -verbose:gc -Xloggc:/home/jboss/amq-broker/log/gc.log.`date +%Y%m%d%H%M%S` -XX:+PrintGCDetails -XX:+PrintGCDateStamps -XX:+PrintGCApplicationStoppedTime"

JBoss Fuse

edit:

   `bin/setenv`

after:

   `# export KARAF_BASE # Karaf base folder`

add:

   export KARAF_OPTS="-verbose:gc -Xloggc:data/gc.log.`date +%Y%m%d%H%M%S` -XX:+PrintGCDetails -XX:+PrintGCDateStamps -XX:+PrintGCApplicationStoppedTime"

Fuse Fabric

When creating a child container specify the JVM Arguments with the --jvm-opts option, eg:

fabric:container-create-child --jvm-opts="-verbose:gc -Xloggc:gc.log.`date +%Y%m%d%H%M%S` -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:+PrintGCApplicationStoppedTime" root child1

The log file can be found under instances/child1/

Analysis

How do I analyze Java garbage collection logging?

SBR
Product(s)
Components
Category
Tags

This solution is part of Red Hat’s fast-track publication program, providing a huge library of solutions that Red Hat engineers have created while supporting our customers. To give you the knowledge you need the instant it becomes available, these articles may be presented in a raw and unedited form.