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:

http://download.oracle.com/javase/6/docs/api/javax/xml/bind/JAXBContext.html

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.

Posted in: Web Service Performance Problems