September 2011 ~ Java EE Support Patterns

This post is the continuation of our original GC overhead limit exceeded problem patterns post. Proper Java Heap analysis is critical in order to eliminate your OutOfMemoryError: GC overhead problem. If you are not familiar with this Java HotSpot 1.6 error, I recommend that you first review my First Article on this subject.

This article will provide you with a sample program and a tutorial on how to analyze your Java HotSpot Heap footprint using Memory Analyzer following an OutOfMemoryError. I highly recommend that you execute and analyse the Heap Dump yourself using this tutorial in order to better understand these principles.

Troubleshooting tools

** all these tools can be downloaded for free **

· Eclipse Indigo Release

· Memory Analyzer via IBM Support Assistant 4.1 (HotSpot Heap Dump analysis)

· Java VM: Windows HotSpot JRE 1.6.0_24 64-bit

Sample Java program

The simple sample Java program below will be used to triggered an OutOfMemoryError; allowing us to analyze the generated HotSpot Heap Dump file. Simply create a new Java class : JVMOutOfMemoryErrorSimulator.java to the Eclipse project of your choice and either rename or keep the current package as is.

This program is basically creating multiple String instances within a Map data structure until the Java Heap depletion.

** please make sure your Eclipse compiler and JRE is 1.6 **

package org.ph.javaee.javaheap;

import java.util.Map;

import java.util.HashMap;

/**

* JVMOutOfMemoryErrorSimulator

* @author PH

public class JVMOutOfMemoryErrorSimulator {

private final static int NB_ITERATIONS = 500000;

// ~1 KB data footprint

private final static String LEAKING_DATA_PREFIX = "datadatadatadatadatadatadatadatadatadatadatadatadatadatadatadatadatadatadatadatadatadatadatadatadatadatadatadatadatadatadatadatadatadatadatadatadatadatadatadatadatadatadatadatadatadatadatadatadatadatadatadatadatadatadatadatadatadatadatadatadatadatadatadatadatadatadatadatadatadatadatadatadatadatadatadatadatadatadatadatadatadatadatadatadatadatadatadatadatadatadatadatadatadatadatadatadatadatadatadatadatadatadatadatadatadatadatadatadatadatadatadatadatadatadatadatadatadatadata";

// Map used to stored our leaking String instances

private static Map<String, String> leakingMap;

static {

leakingMap = new HashMap<String, String>();

}

/**

* @param args

public static void main(String[] args) {

System.out.println("JVM OutOfMemoryError Simulator 1.0");

System.out.println("Author: Pierre-Hugues Charbonneau");

System.out.println("http://javaeesupportpatterns.blogspot.com/");

try {

for (int i = 0; i < NB_ITERATIONS; i++) {

String data = LEAKING_DATA_PREFIX + i;

// Add data to our leaking Map data structure...

leakingMap.put(data, data);

}

} catch (Throwable any) {

if (any instanceof java.lang.OutOfMemoryError) {

System.out.println("OutOfMemoryError triggered! "

+ any.getMessage() + " [" + any + "]");

} else {

System.out.println("Unexpected Exception! " + any.getMessage()

+ " [" + any + "]");

}

System.out.println("simulator done!");

}

Step #1 - Setup your JVM start-up arguments

First, setup your Eclipse Java runtime arguments as per below. For our example, we used an external JRE 1.6 outside the Eclipse IDE with a Java Heap maximum capacity of 512 MB.

The key JVM argument allowing us to generate a Heap Dump is -XX:+HeapDumpOnOutOfMemoryError which tells the JVM to generate a Heap Dump following an OutOfMemoryError condition.

Step #2 - Run the sample Java program

The next step is to run our Java program. Depending on your computer specs, this program will run between 5-30 seconds before existing with an OutOfMemoryError.

As you can see, the JVM generated a Heap Dump file java_pid3880.hprof. It is now time to fire the Memory Analyzer tool and analyze the JVM Heap Dump.

Step #3 - Load the Heap Dump

Analyzing a Heap Dump is an analysis activity that can be simple or very complex. The goal of this tutorial is to give you the basics of Heap Dump analysis. For more Heap Dump analysis, please refer to the other case studies of this Blog.

Step #4 - Analyze Heap Dump

Below are the snapshots and analysis steps that you can follow to understand the memory leak that we simulated in our sample Java program.

As you can see, the Heap Dump analysis using the Memory Analyzer tool was able to easily identify our primary leaking Java class and data structure.

Conclusion

I hope this simple Java program and Heap Dump analysis tutorial has helped you understand the basic principles of Java Heap analysis using the raw Heap Dump data. This analysis is critical when dealing with OutOfMemoryError: GC overhead problems since those are symptoms of either Java Heap leak of Java Heap footprint / tuning problem.

Please feel free to post any comment, question or email me if you have any question.

Having the latest technology really helps for all projects. A Lenovo coupons can save money on a new computer.

This case study describes the complete root cause analysis and resolution of a performance problem (major slowdown and contention under heavy load) that we faced following a migration our Web Service integration layer from Oracle Weblogic 8.1 Web Service RPC to Oracle Weblogic 11g & JAXB 2.0.

This article will also demonstrate how you can generate and analysis JVM Thread Dump snapshots to pinpoint the source of high CPU and IO contention from Java code.

Environment specifications

· Java EE server: Oracle Weblogic Server 11g (10.3.4)

· Middleware OS: IBM AIX 5.3 TL12.1

· Java VM: IBM JRE 1.6.0 SR9 – 64 bit

· Platform type: Middle tier

Problem overview

· Problem type: Major slowdown and very high CPU was observed during our performance testing following a migration from Weblogic 8.1 SP6 (using Web Service RPC) to Weblogic 11g (using JAXB 2.0)

Such problem was observed during high load and caused the server CPU utilization to quickly jump to full saturation level with a significant increase of the response time from our transactions.

Gathering and validation of facts

As usual, a Java EE problem investigation requires gathering of technical and non technical facts so we can either derived other facts and/or conclude on the root cause. Before applying a corrective measure, the facts below were verified in order to conclude on the root cause:

· What is the client impact? HIGH; CPU at 100% utilization

· Recent change of the affected platform? Yes, Weblogic 8.1 migrated to Weblogic 11g. Our application integration layer is now using JAXB 2.0 for our remote Web Service calls vs. Web Service RPC before

· Any recent traffic increase to the affected platform? No, the load testing activity was performed using the same load level originally performed with Weblogic 8.1

· What is the health of the Weblogic server? Investigation did not reveal any problem with the physical server itself and no rogue process consuming any CPU

· Did a restart of the Weblogic Integration server resolve the problem? No, the problem can be replicated easily for every load testing cycle

· Conclusion #1: The problem appears to be triggered following the upgrade to Oracle Weblogic 11g upgrade. More analysis is required to pinpoint the source of slowdown and high CPU utilization.

JVM Thread Dump - background

The JVM Thread Dump is one of the most powerful tools available in the Java EE world to investigate Threads and performance related problems and the best part is that it available out-of-the-box and can be generated at any time with very low impact on the JVM.

In my opinion, JVM Thread Dump should be used much more often by any team involved in production system support, load testing, performance breakdown analysis etc.

Thread Dump analysis is especially great when combined pure Java profilers such as JProfiler e.g. use Thread Dump to identify potential culprit(s) then use Java profilers to drill down further.

The analysis can be tricky but once you master this skill set this will allow you to quickly pinpoint performance and code problems much beyond the classic Thread deadlock scenarios.

Please stay tuned for a series of posts on this topic.

Thread Dump analysis for high CPU?

You may be wondering why I keep referring to Thread Dump analysis for this high CPU problem. The reason is that high CPU contributors (Threads) under heavy load always show up within the Thread Dump snapshot data.

The Thread Dump will not give you the % of CPU used for each Thread but you can analyze it to identify a list of potential culprits. You can also combine it with Solaris prstat and AIX tprof and CPU % correlation analysis.

Now back to our case study, several Thread Dump snapshots were generated during high CPU utilization which did reveal many Threads involved in 2 offending operations / patterns below:

### JAXBContext.newInstance contention ###

ExecuteThread: '32' for queue: 'weblogic.kernel.Default (self-tuning)'" RUNNABLE native

at java.util.zip.ZipFile.getEntry(Native Method)

at java.util.zip.ZipFile.getEntry(ZipFile.java:172)

at java.util.jar.JarFile.getEntry(JarFile.java:269)

at java.util.jar.JarFile.getJarEntry(JarFile.java:252)

at sun.misc.URLClassPath$JarLoader.getResource(URLClassPath.java:989)

at sun.misc.URLClassPath$JarLoader.findResource(URLClassPath.java:967)

at sun.misc.URLClassPath.findResource(URLClassPath.java:262)

at java.net.URLClassLoader$4.run(URLClassLoader.java:763)

at java.security.AccessController.doPrivileged(AccessController.java:224)

at java.net.URLClassLoader.findResource(URLClassLoader.java:760)

at java.lang.ClassLoader.getResource(ClassLoader.java:444)

at java.lang.ClassLoader.getResourceAsStream(ClassLoader.java:504)

at com.sun.xml.bind.v2.runtime.reflect.opt.AccessorInjector.tailor(AccessorInjector.java:113)

at com.sun.xml.bind.v2.runtime.reflect.opt.AccessorInjector.prepare(AccessorInjector.java:79)

at com.sun.xml.bind.v2.runtime.reflect.opt.OptimizedAccessorFactory.get(OptimizedAccessorFactory.java:165)

at com.sun.xml.bind.v2.runtime.reflect.Accessor$FieldReflection.optimize(Accessor.java:253)

at com.sun.xml.bind.v2.runtime.property.ArrayProperty.<init>(ArrayProperty.java:65)

at com.sun.xml.bind.v2.runtime.property.ArrayERProperty.<init>(ArrayERProperty.java:84)

at com.sun.xml.bind.v2.runtime.property.ArrayElementProperty.<init>(ArrayElementProperty.java:96)

at sun.reflect.GeneratedConstructorAccessor53.newInstance(Unknown Source)

at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:39)

at java.lang.reflect.Constructor.newInstance(Constructor.java:527)

at com.sun.xml.bind.v2.runtime.property.PropertyFactory.create(PropertyFactory.java:124)

at com.sun.xml.bind.v2.runtime.ClassBeanInfoImpl.<init>(ClassBeanInfoImpl.java:171)

at com.sun.xml.bind.v2.runtime.JAXBContextImpl.getOrCreate(JAXBContextImpl.java:491)

at com.sun.xml.bind.v2.runtime.JAXBContextImpl.<init>(JAXBContextImpl.java:325)

at com.sun.xml.bind.v2.ContextFactory.createContext(ContextFactory.java:139)

at com.sun.xml.bind.v2.ContextFactory.createContext(ContextFactory.java:117)

at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)

at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:60)

at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:37)

at java.lang.reflect.Method.invoke(Method.java:611)

at javax.xml.bind.ContextFinder.newInstance(ContextFinder.java:213)

at javax.xml.bind.ContextFinder.find(ContextFinder.java:374)

at javax.xml.bind.JAXBContext.newInstance(JAXBContext.java:585)

at javax.xml.bind.JAXBContext.newInstance(JAXBContext.java:533)

at com.<app>.AppClass(AppClass.java)

...............................................................................................................

### JAXB.marshal contention ###

ExecuteThread: '5' for queue: 'weblogic.kernel.Default (self-tuning)'" RUNNABLE native

at java.util.zip.ZipFile.getEntry(Native Method)

at java.util.zip.ZipFile.getEntry(ZipFile.java:172)

at java.util.jar.JarFile.getEntry(JarFile.java:269)

at java.util.jar.JarFile.getJarEntry(JarFile.java:252)

at sun.misc.URLClassPath$JarLoader.getResource(URLClassPath.java:989)

at sun.misc.URLClassPath$JarLoader.findResource(URLClassPath.java:967)

at sun.misc.URLClassPath.findResource(URLClassPath.java:262)

at java.net.URLClassLoader$4.run(URLClassLoader.java:763)

at java.security.AccessController.doPrivileged(AccessController.java:224)

at java.net.URLClassLoader.findResource(URLClassLoader.java:760)

at java.lang.ClassLoader.getResource(ClassLoader.java:444)

at java.lang.ClassLoader.getResource(ClassLoader.java:439)

at java.lang.ClassLoader.getResourceAsStream(ClassLoader.java:504)

at com.sun.xml.bind.v2.runtime.reflect.opt.AccessorInjector.tailor(AccessorInjector.java:113)

at com.sun.xml.bind.v2.runtime.reflect.opt.AccessorInjector.prepare(AccessorInjector.java:79)

at com.sun.xml.bind.v2.runtime.reflect.opt.OptimizedAccessorFactory.get(OptimizedAccessorFactory.java:165)

at com.sun.xml.bind.v2.runtime.reflect.Accessor$FieldReflection.optimize(Accessor.java:253)

at com.sun.xml.bind.v2.runtime.property.SingleElementLeafProperty.<init>(SingleElementLeafProperty.java:81)

at sun.reflect.GeneratedConstructorAccessor51.newInstance(Unknown Source)

at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:39)

at java.lang.reflect.Constructor.newInstance(Constructor.java:527)

at com.sun.xml.bind.v2.runtime.property.PropertyFactory.create(PropertyFactory.java:124)

at com.sun.xml.bind.v2.runtime.ClassBeanInfoImpl.<init>(ClassBeanInfoImpl.java:171)

at com.sun.xml.bind.v2.runtime.JAXBContextImpl.getOrCreate(JAXBContextImpl.java:491)

at com.sun.xml.bind.v2.runtime.JAXBContextImpl.getOrCreate(JAXBContextImpl.java:510)

at com.sun.xml.bind.v2.runtime.property.SingleElementNodeProperty.<init>(SingleElementNodeProperty.java:100)

at sun.reflect.GeneratedConstructorAccessor52.newInstance(Unknown Source)

at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:39)

at java.lang.reflect.Constructor.newInstance(Constructor.java:527)

at com.sun.xml.bind.v2.runtime.property.PropertyFactory.create(PropertyFactory.java:124)

at com.sun.xml.bind.v2.runtime.ClassBeanInfoImpl.<init>(ClassBeanInfoImpl.java:171)

at com.sun.xml.bind.v2.runtime.JAXBContextImpl.getOrCreate(JAXBContextImpl.java:491)

at com.sun.xml.bind.v2.runtime.JAXBContextImpl.getOrCreate(JAXBContextImpl.java:510)

at com.sun.xml.bind.v2.runtime.property.ArrayElementProperty.<init>(ArrayElementProperty.java:108)