Negative GC observed in GC logs

Off late in our JEE Web application tests we observed Negative GC in the JBoss GC logs. After some reading we found that the clock of the Servers were not properly Synched up using Network  time Protocol. 

Possibly the time of the server had gone out of synch and NTP kicked in and corrected the time before GC finished. Note the values in the first column indicating the number of seconds from the JVM at which the GC ran. It also shows a similar trend. After 8175 seconds it shows 8137 seconds.

We are yet to validate if this server suffers from going out of synch by checking with the drift file generated.  Learnt that to enable drift file one an use this configuration driftfile /var/lib/ntp/ntp.drift in the ntp configuration file.

How to Read GC Logs in Java ?

Java provides an built-in garbage collection logging system through which you can quickly and easily troubleshoot Java applications. It helps in understanding the application in terms of memory usage, heap size and GC metrics.

Following are the sample GC Logs

    12345.094: [GC 695486K->557348K(806720K), 0.0191830 secs]
    167741.549: [Full GC 695054K->51454K(806720K), 1. 8452160 secs]

Information provided by Sample 1 :

12345.094: [GC 695486K->507268K (803840K), 0.0178593 secs]

    12345.094 – Time stamp since the JVM has started
    GC – Partial GC occurrence
    695486K – Heap (in KB) in used before GC runs
    507268K – Heap (in KB) in used after GC runs
    803840K – Total JVM size
    0.0178593 secs – Time taken for GC run

Information provided by Sample 2 :

167741.549: [Full GC 695054K->551454K (806720K), 1. 8452160 secs]

    167741.549 – Time stamp since the JVM has started
    Full GC – Full GC occurrence
    695054K – Heap (in KB) in used before GC runs
    51454K – Heap (in KB) in used after GC runs
    806720K – Total JVM size
    1. 8452160 secs – Time taken for GC run

Out of Memory - Permanent Generation Space

The permanent generation is the area of heap that holds all the reflective data of the virtual machine itself, such as class and method objects  +  it also holds internalized strings.

 If an application loads “too many” classes or uses “too many” internalized strings, then it is possible it will abort with an OutOfMemoryError. The specific error is Exception in thread XXXX java.lang.OutOfMemoryError: PermGen space.

A way to find out whats occupying the PermGen space is using a simple command ->  jmap -permstat

Internalized strings can occupy space due to wrong usage of intern() in the code. You can find more details about this here - http://www.codeinstructions.com/2009/01/busting-javalangstringintern-myths.html

Refer URL for more details -
http://www.oracle.com/technetwork/java/javase/tooldescr-136044.html#gblmm

Handy Jmap command options

Heap Space

jmap -heap pid
- To get Heap details. Here look at the section named - "PS Old generation" -  if its above 90% then fire the next two commands in that order

jmap -histo pid
For each Java class, number of objects, memory size in bytes, and fully qualified class names are printed. VM internal class names are printed with '*' prefix. This helps to find who is occupying the heap.
If If the live suboption is specified, only live objects are counted
Note - jmap –histo:live triggers a FULL GC as compared to jmap -histo

jmap -dump:live,format=b,file=file name pid
jmap -dump:format=b,file=file name pid

The dump can be equal to the size of the heap set. For e.g. 3 GB hence ensure that much disk space is available.  One of the ways to view the dump is using a IBM heap dump analyzer which shows top leak suspects. Its been observed that the memory required to open the dump is usually at least twice as the size of the dump.

Permanent Generation Space

jmap –permstat pid

Categories of objects in JVM heap

Objects created and stored on the heap generally fall into three categories:

1) Short-lived objects - life-cycle of these is bound to a http request

2) Medium-lived objects - usually represent cache entries with shorter TTL (time to live)

3) Long-lived objects - represent cache entries with big TTL, settings and infrastructure objects (plugin framework, rendering engine, etc), cache entries taking most of the space.