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
