Does Java Garbage Collection Logging Impact Application Performance?

We sometimes encounter Java users who believe enabling Garbage Collection Logging will significantly impact their performance metrics. Let’s examine the facts and myths…

About the garbage collector

The Java Garbage Collector is a crucial part of the Java Virtual Machine (JVM) that impacts your application’s performance and reliability. If you want to dive into the details of the different types of garbage collectors that are available in the Java runtime and how they work, check out this earlier blog post: “What Should I Know About Garbage Collection as a Java Developer.”

What is GC logging?

Garbage Collection (GC) logging is a feature of the JVM that provides information about the Garbage Collection process. Thanks to the generated log files, you can get insights into how the JVM manages memory dynamically at runtime by collecting and disposing of objects that are no longer needed by the program. This is very useful when you want to monitor the performance of a Java application, diagnose memory leaks, and tune the JVM’s garbage collection configuration.

“Some of our customers chase every microsecond to improve the performance of their applications,” says Azul Sales Engineer Daniel Witkowki. “But they still enable GC Logging! Because it has minimal impact on application performance and allows debugging many different problems, it is vital for these companies to always be able to retrieve the GC logs after a problem has occurred.”

When garbage collection logging is enabled, every time the JVM performs a Garbage Collection, the following information is stored in a log file:

• Type of GC event
  • Minor GC: Cleaning the Young Generation space
  • Major GC: Cleaning the Old Generation space
  • Full GC: Cleaning the entire Heap space
• The time when the GC event started.
• The duration of the GC event.
• The amount of memory before and after the GC event for each memory pool.
• The total available memory in each pool.

The log file is human-readable, and the content looks like this:

[0.005s][info][gc] Using G1
[0.110s][info][safepoint] Safepoint "ICBufferFull", Time since last: 98355917 ns, Reaching safepoint: 2000 ns, Cleanup: 53416 ns, At safepoint: 7167 ns, Total: 62583 ns
[0.186s][info][safepoint] Safepoint "ICBufferFull", Time since last: 75998125 ns, Reaching safepoint: 1792 ns, Cleanup: 56000 ns, At safepoint: 4458 ns, Total: 62250 ns
[0.235s][info][safepoint] Safepoint "ICBufferFull", Time since last: 48961667 ns, Reaching safepoint: 2125 ns, Cleanup: 45208 ns, At safepoint: 4042 ns, Total: 51375 ns
[0.259s][info][gc       ] GC(0) Pause Young (Normal) (G1 Evacuation Pause) 49M->4M(1032M) 1.472ms
...
[2.290s][info][gc       ] GC(13) Pause Young (Concurrent Start) (Metadata GC Threshold) 120M->23M(560M) 2.647ms
[2.290s][info][gc       ] GC(14) Concurrent Mark Cycle
[2.290s][info][safepoint] Safepoint "CollectForMetadataAllocation", Time since last: 31224333 ns, Reaching safepoint: 1542 ns, Cleanup: 45042 ns, At safepoint: 2700833 ns, Total: 2747417 ns
[2.302s][info][gc       ] GC(14) Pause Remark 28M->28M(112M) 1.986ms
[2.302s][info][safepoint] Safepoint "G1PauseRemark", Time since last: 10354500 ns, Reaching safepoint: 1917 ns, Cleanup: 14125 ns, At safepoint: 2028625 ns, Total: 2044667 ns
[2.306s][info][gc       ] GC(14) Pause Cleanup 28M->28M(112M) 0.048ms
[2.306s][info][safepoint] Safepoint "G1PauseCleanup", Time since last: 3311666 ns, Reaching safepoint: 169500 ns, Cleanup: 11084 ns, At safepoint: 79583 ns, Total: 260167 ns
[2.306s][info][gc       ] GC(14) Concurrent Mark Cycle 16.086ms
...

The stored information and format may vary depending on the JVM and the GC algorithm you use.

Enabling GC logging

GC logging is enabled with the java command line argument -Xlog. This has been available since Java 9, thanks to JEP 158 “Unified JVM Logging”:

• -Xlog:gc,safepoint:gc.log to enable default logging of the important garbage collection events including all safepoint pauses.
• -Xlog:gc*,safepoint:gc.log to enable more detailed logging, including all safepoint pauses and smaller garbage collector events and phases that are normally not logged.  For OpenJDK, this is often needed as otherwise some Java heap memory metrics are not recorded, and not all pauses are tracked. On Zing, it is not needed as all necessary data is already logged by default with just gc. The tradeoff between gc and gc* is usually 10 times more log data amount, which will reduce the time interval your log covers.
• -Xlog:gc,safepoint to write the log data to stdout, which can be helpful in containers to avoid storing local log files.
• -Xlog:gc,safepoint:gc.log::filecount=10,filesize=100M to change the default log rotation of 5 files of 20 MBytes each to 10 files of 100 MBytes each.
• -Xlog:gc,safepoint:gc.log::filecount=0 to disable log file rotation, useful for quick test runs or for processes that are restarted often. Note the double colon.

You can even repeat the -Xlog argument and use it to specify different outputs at the same time, for example, the following writes it to stdout and to a local file:

$ java -Xlog:gc,safepoint -Xlog:gc,safepoint:/opt/log/gc.log -jar myApp.jar

There are more options available with the unified logging system, as you can see when you run the following command:

$ java -Xlog:logging=debug -version
 
[0.017s][info][logging] Log configuration fully initialized.
[0.017s][info][logging] Available log levels: off, trace, debug, info, warning, error
[0.017s][info][logging] Available log decorators: time (t), utctime (utc), uptime (u), timemillis (tm), uptimemillis (um),...
[0.017s][info][logging] Available log tags: add, age,... gc,...
[0.017s][info][logging] Described tag sets:
[0.017s][info][logging]  logging: Logging for the log framework itself
[0.019s][debug][logging] Available tag sets: , arguments, attach, cds, cds+class, cds+dynamic, cds+hashtables, cds+heap,...
[0.023s][info ][logging] Log output configuration:
[0.023s][info ][logging]  #0: stdout all=warning,logging=debug uptime,level,tags foldmultilines=false
[0.023s][info ][logging]  #1: stderr all=off uptime,level,tags foldmultilines=false
openjdk version "22" 2024-03-19
OpenJDK Runtime Environment Zulu22.28+91-CA (build 22+36)
OpenJDK 64-Bit Server VM Zulu22.28+91-CA (build 22+36, mixed mode, sharing)

Impact of GC logging

Enabling GC logging in a Java application generally has minimal performance impact, especially with modern JVMs. However, the exact impact may vary based on the JVM version, the GC algorithm used, the settings of GC logging, and the I/O performance of the system where logs are written. These are a few facts you need to take into consideration:

• Risk of filling the filesystem: Filling a file system to or near 100% is the most practical performance impact often seen in relation to logging and needs to be avoided. By default, Java 9 and newer have log file rotation enabled by default and will only write 5 log fragments of each 20 MB size.
• I/O Operations: GC logs are written directly to the disk. This creates I/O operations and can, therefore, slow down the application if the disk is slow or there’s a high disk usage.
• Memory Buffering: Modern JVMs typically use a memory buffer for GC logs. When the buffer is full, the logs are written in one go to disk to reduce the I/O impact. However, the buffer takes up memory that the application could otherwise use.
• Detailed GC Logs: If detailed GC logs are enabled, such as those that record per-thread timing or object statistics, the performance impact may become noticeable as this data needs to be recorded and processed, which can consume CPU resources.
• Safe Points: All GC logging activity happens at ‘safe points’ in the application’s execution, meaning it doesn’t cause more ‘stop the world’ pauses than would occur naturally due to GC activity itself.

Consider the amount of data in the filesystem. A system halt due to a full filesystem would result in really bad performance. When using only -Xlog:gc:gc.log  for Zing or -Xlog:gc,safepoint:gc.log for OpenJDK, you get all necessary performance-relevant metrics without wasting too much space. Especially on Zing, -XX:+PrintGCDetails, gc*, and safepoint are not needed as they don’t add more graphs in GCLogAnalyzer.

“A big part of the GC log tasks is saving the data to a log file,” notes Deepak Sreedhar, principal software engineer at Azul. “The type of I/O used to store these files can impact the logging performance, not directly the application itself. So, some of the problems that may occur are not related to the performance of the GC logging but to the speed of the I/O. If the logs can’t be saved fast enough in real time, OpenJDK has the option to use asynchronous unified logging with Xlog:async.”

GC log with Azul Zing

When using Azul Zing you only need to add -Xlog:gc:gc.log to instruct Zing to store garbage collector log files. Extra arguments like gc* or safepoint to increase the detail level are not needed as Zing always logs safepoint pauses and even additional information not seen in OpenJDK GC logs by default, like JIT compiler activity, CPU and memory usage, Linux page cache metrics, and a few more metrics often relevant for system performance analysis.

Analyzing GC logs

There are various tools available to analyze the content of GC log files:

• JVM’s built-in jstat command: This utility displays performance statistics and can be used to output garbage collector statistics.
• VisualVM: This tool offers several views into different JVM aspects, like garbage collection. It also provides live metrics, which can be helpful for analyzing issues in real-time. You can download this tool from GitHub.
• Azul GC Log Analyzer: Reads GC log and visualizes it as a set of graphs over time (wall clock and uptime). It shows information about the garbage collector, the JIT compiler, system metrics and ReadyNow. statistics This graphical desktop application is documented here, and a video walk-through is available here.

Conclusion

Although garbage collection logs can introduce minimal performance costs, the trade-off is usually worthwhile, as the logs are often invaluable when tuning garbage collection and diagnosing memory issues. Without GC logs enabled, you can lose insights into how the JVM manages memory dynamically at runtime. This information is very useful for monitoring the performance of a Java application, diagnosing memory leaks and tuning the JVM’s garbage collection configuration.

Note: This is an edited version of an article that originally ran on The New Stack on May 23, 2024.