So you enabled verbose GC logs and obtained the logs. Congratulations. You have done one of the most important steps in troubleshooting JVM memory issues. But merely having the log does not do any good. You need to analyze and determine if there is a smoking gun. Here is how to do it.
1. First make sure you collect the logs for at least few hours. Longer the better.
2. Open the log file in a text editor.
3. You are primarily looking for two things
a. Is the GC happening very frequently?
b. Is each GC cycle taking long time?
Is the GC happening very frequently:
In a healthy application GC cycles should be spaced out – at least by few minutes (especially the Majorcollection aka full gc). If you see GC kicking in ever few seconds, you may have an issue.
Is the GC cycle taking log time:
Ideally minor GCs should take few milliseconds and Full GCs can take about a second (even this is not acceptable in real time transactions environments)
Remember: Even with Concurrent Mark/Sweep collector, there is ‘JVM Pausing’ involved – meaning the entire JVM is paused. This can result in significant user experience degradation.
Let us look at an excerpt from an actual verbose GC log – Note that the exact format varies by JVM vendor and by version.
18015.9631: [GC [PSYoungGen2: 399742K3->800K4(641984K5)] 818698K6–
>420282K7(2040128K8), 0.01727179 secs] [Times: user=0.0210 sys=0.0011,
18015.981: [Full GC13 (System) [PSYoungGen: 800K->0K(641984K)]
[PSOldGen: 419482K->420201K(1398144K)] 420282K->420201K(2040128K)
[PSPermGen: 128361K->128361K(262144K)], 1.2065614 secs] [Times:
user=1.20 sys=0.00, real=1.20 secs]
1: Time elapsed since the start of the application, in seconds. Useful to find out how often the GC runs
2: Indicates it is a YoungGen Collection (Minor collection)
3: Total Size of live objects before collection, in Kilo Bytes
4: Total Size of live objects after collection, in Kilo Bytes
5: Committed size of the heap in Young generation, in Kilo Bytes (i.e) the amount of heap available for
future allocation requests without expanding the heap
6: Total Size of the heap before collection, in Kilo Bytes
7. Total Size of the heap after collection, in Kilo Bytes
8: Total Committed size of heap (the amount of heap available for future allocation requests without
expanding the heap)
9: Time taken to perform this GC cycle, in seconds
10,11,12 : Break up of time spent in user,sys and wallclock time
13: Indicates it is a Full GC (Major collection)
Notice couple of things in the Full GC cycle
Hardly any space was reclaimed from Permgen. This is because permgen is used to hold class objects (metadata). Some third party applications (like javaagents) are known to consume lot of permgen space.
The time taken by Full GC is much more than Minor GC (1.2 seconds compared to 0.01 seconds). Imagine yours is a stock trading application. Pausing the application for couple of seconds for Full GC Is a huge deal indeed.
4. From the information above, determine if GC is occurring too frequently and/or taking lot of time for each cycle. From this, you can decided on what to do next (perhaps you need to increase the YoungGen size, perhaps the Max Heap size , perhaps pergmen size or perhaps all or none of the above). You see how useful verbose GC logs can be?
To update Permgen:
To update Max heap:
To update New Gen:
Also see -XXNewRatio
5. Once you update any of the GC parameters mentioned above, collect verbose GC logs for few more hours and compare. You may have to do this few times to arrive at a sweet spot.
Note: Make sure you save the old gc logs whenever you restart the application
Note: Some JDK vendors like IBM provide much more detailed GC logs than the one shown above. So, make use of it.
Now that you know how to use verbose GC logs, let’s look at an important built-in tool that can be useful in troubleshooting JVM memory issues – jconsole
Coming up: Troubleshooting GC: Using Jconsole