≡ Menu

Troubleshooting GC: Step by Step instructions to analyze verbose GC logs

  •  
  •  
  •  

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,

real=0.02 secs12]

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:

-XX:MaxPermSize

To update Max heap:

-Xmx

To update New Gen:

-XX:MaxNewSize.

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

Previous: Troubleshooting GC: Using Verbose GC logs


  •  
  •  
  •  
{ 4 comments… add one }
  • Naveen Sharma January 11, 2018, 1:10 pm

    Please subscribe me.

  • PRAVEEN October 30, 2018, 3:05 am

    Very nice article. Keep up the good work.

  • KK August 29, 2019, 3:37 am

    Easier to understand, do we need to know how to calculate heap usage? and also can we determine how long the server need to be restarted in order to reset the GC collection?

    • Karun Subramanian August 31, 2019, 3:21 am

      Hi, KK.
      Heap usage must be closely monitored and JVM must be tuned if needed. Garbage Collection log is an excellent source for observing Heap usage.
      As far restarting, the server should never be restarted to reset heap usage. If you are forced to restart to clear heap, you are most likely running into a memory leak problem. You can take heap dumps to analyze heap in order to find leaking objects. Check out my post on this http://karunsubramanian.com/jboss/how-to-obtain-heap-dump-and-core-dump-in-jboss/

Leave a Comment