/ September 2011 ~ Java EE Support Patterns

9.20.2011

GC overhead limit exceeded - Java Heap analysis

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.

9.15.2011

JAXBContext Performance Problem – Case Study

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)
  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.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)
  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.getOrCreate(JAXBContextImpl.java:510)
  at com.sun.xml.bind.v2.runtime.property.ArrayElementProperty.<init>(ArrayElementProperty.java:108)
  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 javax.xml.bind.JAXB$Cache.<init>(JAXB.java:98)
  at javax.xml.bind.JAXB.getContext(JAXB.java:125)
  at javax.xml.bind.JAXB._marshal(JAXB.java:549)
  at javax.xml.bind.JAXB.marshal(JAXB.java:442)
  at com.<app>.AppClass(AppClass.java)
  ...................................................................



As you can see, this Thread is spending quite a bit of time searching through the class loader and JAR files. The parent callers are JAXBContext.newInstance which was invoked from our application code and JAXB.marshal; also triggered by our application code.

Problem isolation: high contention was isolated during the creation of a new JAXBContext instance and the marshal process via JAXB.marshal!

The Thread Dump analysis did reveal severe contention triggered from the creation of a new instance of the JAXBContext before the marshalling of the JAXB request and response data.

// Create a new instance of JAXBContext before every marshalling of the request and response
JAXBContext jaxbContext = JAXBContext.newInstance("jaxbcontext.app.xyz.instance");

// Invocation the JAXB marshal “convenience” method for marshalling
JAXB.marshal(jaxbElement, requestObject);

Root cause : non optimal JAXB client code implementation!

Further investigation with JAXB documentation, a full code review and Oracle support did confirm that our application was creating an excessive number of JAXBContext instances leading to severe performance degradation since JAXBContext.newInstance() triggers heavy IO and CPU operations (JAR files); as per Thread Dump analysis.

Also, the usage of the convenience method JAXB.marshal() and JAXB.unmarshal() was amplifying the problem by also invoking JAXBContext.newInstance() internally.

Solution: singleton pattern and JAXB marshal tuning!

The resolution of this problem was done in 2 steps.

#1 Implementation of the Singleton Pattern for the JAXBContext

The JAXB 2.0 JAXBContext is a Thread Safe object. This means that any instance can be shared across multiple Threads without having to create more than 1 instance. Our application code was changed as per below:



#2 Removal of the JAXB.marshal() convenience method

The JAXB 2.0 Marshaller & Unmarshaller objects are not Thread Safe but the idea was to re-use the JAXBContext Singleton instance in order to eliminate the overhead of the JAXB.marshal() convenience method which triggers internally the creation of a new JAXBContext instance. The same approach was implemented for the unmarshalling process.


The official JAXB 2.0 API documentation for JAXB related objects can be found below:

Results: 60% CPU reduction and increase of throughput!

A load testing cycle performed after the code change did reveal a significant drop in average CPU utilization from 100% to 40% and getting very close to pre Weblogic 11g upgrade levels. The overall throughput of our application did also increase following the elimination of this JAXB contention.

Conclusion and recommendations

·         JVM Thread Dump is very powerful and can also help you pinpoint high CPU contributors at the application code level so please don’t be afraid to use it more often in your day to day tasks and / or load testing analysis
·         Any production grade JAXB client implementation should ensure to rely on the Singleton Pattern for the JAXBContext instance creation. Such singleton instance should also be reused when creating your Marshaller and Unmarshaller instances
·         Please do not implement the Singleton Pattern for the Marshaller / Unmarshaller since these are non Thread Safe objects in the current JAXB 2.0 release

For those in the market for the latest computer, try this Newegg Promotional Code and possibly save some money.