Java Memory leak tips

Last couple of days I had to track an Out of mermory error on a production application. During this tracking I searched and use different tools for differents problems.
So this post is a reminder.

the error context environment is : a java application launch by maven (use exec:java ; benefits from transitive dependencies) launch from eclipse configuration for external tool (this tool is an eclipse one, benefits from log redirection through console)

Use java Debug Architecture

in this context the debugging could be done with java debug architecture :

So for JVM (TI) side : launch maven exec command with JVM args :
-Xdebug -Xrunjdwp:transport=dt_socket,server=y,suspend=y,address=9009
(activate debug, load jdwp, transport mode = socket, target application listen for a debugger to attach, target vm will be suspendended until debugger apps connection)

Or the new one (not use in my case)
-agentlib:jdwp=transport=dt_socket,address=localhost:9009,server=y,suspend=y

For JDI side one can use eclipse with "Remote Java Application"

Run the VM then the debugger.

Use java -verbose

this java option could takes args :

-verbose [class | gc | jni]

In our case the gc arg is usefull, it allows log of Garbage Collection event.

[GC 4416K->1055K(15872K), 0.0029002 secs]
[GC 5471K->1640K(15872K), 0.0030503 secs]
[GC 6056K->2100K(15872K), 0.0034942 secs]
[GC 6516K->2633K(15872K), 0.0027937 secs]
[GC 7049K->2846K(15872K), 0.0028010 secs]

You could also use to have more details or output to file:

-XX:+PrintGCTimeStamps
-XX:+PrintGCDetails

-Xloggc:<file>

You could then have :

 0.319: [GC 0.319: [DefNew: 4927K->512K(4928K), 0.0024456 secs]
5922K->1924K(15872K), 0.0024653 secs] [Times: user=0.02 sys=0.00, real=0.00 secs] 
 0.398: [GC 0.398: [DefNew: 4928K->512K(4928K), 0.0021861 secs] 
6340K->2307K(15872K), 0.0022057 secs] [Times: user=0.01 sys=0.00, real=0.00 secs] 
 0.465: [GC 0.465: [DefNew: 4928K->512K(4928K), 0.0025962 secs] 
6723K->2509K(15872K), 0.0026180 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
 0.545: [GC 0.545: [DefNew: 4928K->511K(4928K), 0.0022087 secs]
6925K->3017K(15872K), 0.0022284 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
 0.620: [GC 0.620: [DefNew: 4927K->511K(4928K), 0.0019218 secs] 
7433K->3584K(15872K), 0.0019427 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
 0.684: [GC 0.684: [DefNew: 4927K->395K(4928K), 0.0021938 secs] 
8000K->3580K(15872K), 0.0022122 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
Heap
 def new generation   total 4928K, used 3683K [0x24c40000, 0x25190000, 0x2a190000)
  eden space 4416K,  74% used [0x24c40000, 0x24f760d0, 0x25090000)
  from space 512K,  77% used [0x25090000, 0x250f2d70, 0x25110000)
  to   space 512K,   0% used [0x25110000, 0x25110000, 0x25190000)
 tenured generation   total 10944K, used 3185K [0x2a190000, 0x2ac40000, 0x34c40000)
   the space 10944K,  29% used [0x2a190000, 0x2a4ac688, 0x2a4ac800, 0x2ac40000)
 compacting perm gen  total 12288K, used 4456K [0x34c40000, 0x35840000, 0x38c40000)
   the space 12288K,  36% used [0x34c40000, 0x3509a390, 0x3509a400, 0x35840000)
    ro space 10240K,  45% used [0x38c40000, 0x390c7988, 0x390c7a00, 0x39640000)
    rw space 12288K,  54% used [0x39640000, 0x39ccb5d8, 0x39ccb600, 0x3a240000)

Use the dump

The get a rapid diagnosis, you could use a JVM option that allow to output a dump when Out of memory error

-XX:+HeapDumpOnOutOfMemoryError

Or use with ctrl break

-XX:+HeapDumpOnCtrlBreak

You can then use the produce dump (hprof file) in Visual VM (See below).

Use Visual VM

This tool located in ${JAVA_INSTALL_DIR}/bin/jvisualvm.exe (on windows), allow you this view many things on the VM (mainly):

• see threads, memory... behavior 
• trigger dump 

Object size Measure (Reflexion)

Using this jar (as maven deps)

<dependency>
<groupid>net.sf.ehcache</groupid>
<artifactid>ehcache</artifactid>
<version>2.8.3</version>
</dependency>

You could now use a method relying on reflexion for object size calculation :

try {
    ReflectionSizeOf reflectionSizeOf = new ReflectionSizeOf();
    Size deepSizeOf = reflectionSizeOf.deepSizeOf(1000, false, model);
    logger.info("Memory in use Model deepSize | F3 |  {}", deepSizeOf.getCalculated());
    deepSizeOf = reflectionSizeOf.deepSizeOf(1000, false, context);
    logger.info("Memory in use Context deepSize | F4 |  {}", deepSizeOf.getCalculated());
} catch (Exception e) {
    e.printStackTrace();
}

Object size Measure (Using Java Agent)

Agent could instrument java through JVM addition (transformation) of byte-codes to method.
An instrument is a class. This class should provides methods :

public static void premain(String args, Instrumentation inst) throws Exception
public static void agentmain(String args, Instrumentation inst) throws Exception

declared in META-INF/MANIFEST.MF

Agent-Class: my.package.JavaAgent
Can-Redefine-Classes: true
Can-Retransform-Classes: true
Premain-Class: my.package.JavaAgent

There is two ways that provides instrument access

• launch JVM with instrumentation flag (instrument premain method is used)
• use instrumentation dynamically (agentmain method use), implies tools.jar usage

An instrument provide access to a method :

  long     getObjectSize(Object objectToSize)

WARNING this method provide only object size without object instance references

If you encounter problem while loading instrument you could use this one

org.apache.openjpa.enhance.InstrumentationFactory

Comming from

<dependency>
 <groupId>org.apache.openjpa</groupId>
 <artifactId>openjpa-kernel</artifactId>
 <version>2.3.0</version>
</dependency>

Much more usefull information about agent here

Use TPTP

See here

Java memory map

To finish this post, I tried to build a graphic memory figure to remind me how it is approximately organized