As discussed in a past blog post, if you're experiencing performance problems, the first thing to check is whether your garbage collection (GC) is healthy. If the proportion of time in garbage collection is greater than ~10%, then garbage collection is likely unhealthy and the application is not performing much useful work.
The steps to determine the proportion of time in GC are:
- Install the tool IBM Monitoring and Diagnostic Tools - Garbage Collection and Memory Visualizer (GCMV)
- Enable verbosegc on your target Java processes
- Load the verbosegc files into GCMV
- Crop to the time of interest
- Calculate the proportion of time in GC
Step 1: Install GCMV
To help evaluate garbage collection, IBM provides a free tool called the IBM Monitoring and Diagnostic Tools - Garbage Collection and Memory Visualizer (GCMV). This tool is provided "as is" without any warranty or support but fixes and updates are made as time permits.
Previously, GCMV was a bit complicated to install, but the above link provides a new and simplified way to install GCMV.
Step 2: Enable verbosegc on your target Java processes
In general, we recommend customers always run with verbosegc enabled, even in production. Benchmarks show the overhead is less than about 0.2%.
If you're running WebSphere Application Server traditional 9, then verbosegc is already enabled. For older versions, and for WebSphere Liberty or other Java runtimes, enable verbosegc as follows:
For IBM Java, Semeru, and OpenJ9, restart with:
For HotSpot Java > 8, restart with:
For HotSpot Java <= 8, restart with:
-Xloggc:logs/verbosegc.log -XX:+UseGCLogFileRotation -XX:NumberOfGCLogFiles=5 -XX:GCLogFileSize=20M -XX:+PrintGCDateStamps -XX:+PrintGCDetails
Step 3: Load the verbosegc files into GCMV
Start GCMV and click File } Load File …
Select the verbosegc*log file.
Initially, you'll see a line plot with various statistics such as heap usage:
Often, the first thing to do is to change the X-axis to "date" so that you can see wallclock timestamps for easier cropping.
Step 4: Crop to the time of interest
If you want to calculate statistics based on a subset of the verbosegc file (for example, if users were only active for part of the time covered by the file), then you may crop the x-axis to the time period.
In the X Axis view, either use the sliders or manually type in the start and end times and press Enter within the text boxes. After cropping, you'll see vertical lines showing the period GCMV is cropped for. The area in white is the period of interest for which the proportion of time in GC will be calculated, and the areas in gray will be excluded from the calculations.
Finally, click the Report tab at the bottom left of the line plot to switch to the statistics view. Scroll down to the Summary table and review the row, "Proportion of time spent in garbage collection pauses (%)". In the following example, the proportion of time in GC is 52.1% which is very unhealthy.
In this example, we know that we need to do further investigation to optimize garbage collection. This may be as simple as increasing the maximum heap size. For how to tune GC, review and follow the series by the WAS Performance Team:
Bonus tip: Plotting proportion of time in GC
In recent versions of GCMV, you may plot proportion of time in GC over time. Simply go to the Line Plot view, select the Data Selector, change the category to VGC Pause, and check the "Proportion of time in garbage collection" series. As shown in the following example, the proportion of time in GC was less than 10% until about 22:31 after which it shot up and the Java process became very unhealthy.
Documentation for the GCMV tool is available at https://www.ibm.com/docs/en/mon-diag-tools?topic=monitoring-diagnostic-tools-garbage-collection-memory-visualizer