Java Just-In-Time compilation: more than just a buzzword

A recent Java production performance problem forced me to revisit and truly appreciate the Java VM Just-In-Time (JIT) compiler. Most Java developers and support individuals have heard of this JVM run time performance optimization but how many truly understand and appreciate its benefits?

This article will share with you a troubleshooting exercise I was involved with following the addition of a new virtual server (capacity improvement and horizontal scaling project).

For a more in-depth coverage of JIT, I recommend the following articles:

## Just-in-time compilation

http://en.wikipedia.org/wiki/Just-in-time_compilation

## The Java HotSpot Performance Engine Architecture

http://www.oracle.com/technetwork/java/whitepaper-135217.html

## Understanding Just-In-Time Compilation and Optimization

http://docs.oracle.com/cd/E15289_01/doc.40/e15058/underst_jit.htm

## How the JIT compiler optimizes code

http://pic.dhe.ibm.com/infocenter/java7sdk/v7r0/index.jsp?topic=%2Fcom.ibm.java.zos.70.doc%2Fdiag%2Funderstanding%2Fjit_overview.html

JIT compilation overview

The JIT compilation is essentially a process that improves the performance of your Java applications at run time.

The diagram below illustrates the different JVM layers and interaction. It describes the following high level process:

1. Java source files are compiled by the Java compiler into platform independent bytecode or Java class files.
2. After your fire your Java application, the JVM loads the compiled classes at run time and execute the proper computation semantic via the Java interpreter.
3. When JIT is enabled, the JVM will analyze the Java application method calls and compile the bytecode (after some internal thresholds are reached) into native, more efficient, machine code. The JIT process is normally prioritized by the busiest method calls first.
4. Once such method call is compiled into machine code, the JVM executes it directly instead of “interpreting” it.
5. The above process leads to improved run time performance over time.

Case study

Now here is the background on the project I was referring to earlier. The primary goal was to add a new IBM P7 AIX virtual server (LPAR) to the production environment in order to improve the platform’s capacity. Find below the specifications of the platform itself:

• Java EE server: IBM WAS 6.1.0.37 & IBM WCC 7.0.1
• OS: AIX 6.1
• JDK: IBM J2RE 1.5.0 (SR12 FP3 +IZ94331) @64-bit
• RDBMS: Oracle 10g
• Platform type: Middle tier and batch processing

In order to achieve the existing application performance levels, the exact same hardware specifications were purchased. The AIX OS version and other IBM software’s were also installed using the same version as per existing production.

The following items (check list) were all verified in order to guarantee the same performance level of the application:

• Hardware specifications (# CPU cores, physical RAM, SAN…).
• OS version and patch level; including AIX kernel parameters.
• IBM WAS & IBM WCC version, patch level; including tuning parameters.
• IBM JRE version, patch level and tuning parameters (start-up arguments, Java heap size…).
• The network connectivity and performance were also assessed properly.

After the new production server build was completed, functional testing was performed which did also confirm a proper behaviour of the online and batch applications.

However, a major performance problem was detected on the very first day of its production operation. You will find below a summary matrix of the performance problems observed.

Production server	Operation elapsed time	Volume processed (# orders)	CPU % (average)	Middleware health
Existing server	10 hours	250 000 (baseline)	20%	healthy
*New* server	10 hours	50 000   -500%	80%  +400%	High thread utilization

As you can see from the above view, the performance results were quite disastrous on the first production day. Not only much less orders were processed by the new production server but the physical resource utilization such as CPU % was much higher compared with the existing production servers.

The situation was quite puzzling given the amount of time spent ensuring that the new server was built exactly like the existing ones. At that point, another core team was engaged in order to perform extra troubleshooting and identify the source of the performance problem.

Troubleshooting: searching for the culprit...

The troubleshooting team was split in 2 in order to focus on the items below:

• Identify the source of CPU % from the IBM WAS container and compare the CPU footprint with the existing production server.
• Perform more data and file compares between the existing and new production server.

In order to understand the source of the CPU %, we did perform an AIX CPU per Thread analysis from the IBM JVM running IBM WAS and IBM WCC. As you can see from the screenshot below, many threads were found using between 5-20% each. The same analysis performed on the existing production server did reveal fewer # of threads with CPU footprint always around 5%.

Conclusion: the same type of business process was using 3-4 times more CPU vs. the existing production server.

In order to understand the type of processing performed, JVM thread dumps were captured at the same time of the CPU per Thread data. Now the first thing that we realized after reviewing the JVM thread dump (Java core) is that JIT was indeed disabled! The problem was also confirmed by running the java –version command from the running JVM processes.

This finding was quite major, especially given that JIT was enabled on the existing production servers. Around the same time, the other team responsible of comparing the servers did finally find differences between the environment variables of the AIX user used to start the application. Such compare exercise was missed from the earlier gap analysis. What they found is that the new AIX production server had the following extra entry:

JAVA_COMPILER=NONE

As per the IBM documentation, adding such environment variable is one of the ways to disable JIT.

Complex root cause analysis, simple solution

In order to understand the impact of disabling JIT in our environment, you have to understand its implication. Disabling JIT essentially means that the entire JVM is now running in interpretation mode. For our application, running in full interpretation mode not only reduces the application throughput significantly but also increases the pressure point on the server CPU utilization since each request/thread takes 3-4 more times CPU than a request executed with JIT (remember, when JIT is enabled, the JVM will perform many calls to the machine/native code directly).

As expected, the removal of this environment variable along with the restart of the affected JVM processes did resolve the problem and restore the performnance level.

Assessing the JIT benefits for your application

I hope you appreciated this case study and short revisit of the JVM JIT compilation process. In order to understand the impact of not using JIT for your Java application, I recommend that you preform the following experiment:

• Generate load to your application with JIT enabled and capture some baseline data such as CPU %, response time, # requests etc.
• Disable JIT.
• Redo the same testing and compare the results.

I’m looking forward for your comments and please share any experience you may have with JIT.

Read More

Java GC tool from IBM: Tutorial on JCG – Part 1

This post is to inform you that we just released on Java Code Geeks the first article of a new series dedicated to the free IBM Garbage Collection and Memory Visualizer tool.

GCMV is a great and free tool, developed by IBM, which allows you to “visualize” and analyze the internal JVM memory usage and GC activity of your Java application(s).

The part 1 can be found here.

As usual, please feel free to comment and share your experience with GCMV.

Best regards,

P-H

Senior IT Consultant

Java EE Support Patterns

Read More

IT Cloud Providers: A definitive guide from DZone

This post is to inform you that DZone has released a comprehensive guide that can help you and your client to choose the right Cloud provider for your business needs. This reference guide includes:

• 100 pages of cloud product analysis.
• 9 categories of cloud providers analyzed and compared.
• 35+ of the most active cloud solutions and their feature sets.
• Surveys of 400+ IT professionals on their cloud preferences.

I highly recommend that you download your own copy today!

Please feel free to also comment and share your experience with your current Cloud provider.

Download: DZone’s Definitive Guide to Cloud Providers.

Best regards,

P-H

Senior IT Consultant

Java EE Support Patterns

Read More

HotSpot 32-bit to 64-bit upgrade: what to look for

This short post will test your knowledge on JVM and project delivery skills; especially regarding JVM upgrades. I’m looking forward for your comments and answers on how to approach this type of projects in order to say away from performance problems.

Background

I was recently involved in a recent problem case affecting a production environment running on Weblogic 10 and using the HotSpot JVM 1.6 @32-bit. Given recent challenges and load increase forecast, the decision was taken to upgrade the HotSpot JVM 1.6 from 32-bit to 64-bit.

Please note that no change was applied to the JVM arguments.

After a few weeks of functional testing and planning, the upgrade was deployed successfully to the production environment. However, the support team did observe the next day major performance degradation, including thread lock contention, forcing the deployment team to rollback the upgrade.

The root cause was eventually found and the upgrade will be re-attempted in the near future.

Question:

Based on the above background, provide a list of possible root causes that may explain this performance degradation.

Propose a list of improvements to the project delivery and recommendations on how to properly manage and de-risk this type of upgrade.

Answer:

I often hear the assumption that switching from a 32-bit JVM to 64-bit JVM will automatically bring performance improvement. This is partially true. Performance improvements will only be observed if you are dealing with existing memory footprint problem(s) prior to the upgrade such as excessive GC or java.lang.outofmemoryerrorjava heap space conditions and if you performed proper tuning & Java heap sizing.

Unfortunately, we often overlook the fact that for a 64-bit JVM process, native pointers in the system takes up 8 bytes instead of 4. This can result in an increased memory footprint of your application and leading to more frequent GC and performance degradation.

Here is the official explanation from Oracle:

What are the performance characteristics of 64-bit versus 32-bit VMs?

"Generally, the benefits of being able to address larger amounts of memory come with a small performance loss in 64-bit VMs versus running the same application on a 32-bit VM.  This is due to the fact that every native pointer in the system takes up 8 bytes instead of 4.  The loading of this extra data has an impact on memory usage which translates to slightly slower execution depending on how many pointers get loaded during the execution of your Java program.  The good news is that with AMD64 and EM64T platforms running in 64-bit mode, the Java VM gets some additional registers which it can use to generate more efficient native instruction sequences.  These extra registers increase performance to the point where there is often no performance loss at all when comparing 32 to 64-bit execution speed.  

The performance difference comparing an application running on a 64-bit platform versus a 32-bit platform on SPARC is on the order of 10-20% degradation when you move to a 64-bit VM.  On AMD64 and EM64T platforms this difference ranges from 0-15% depending on the amount of pointer accessing your application performs."   

Now back to our original problem case, this memory footprint increase was found to be significant and at the root cause of our problem. Depending of the GC policy that you are using, an increase in GC major collections will lead to higher JVM & thread pause times, opening the door for thread lock contention and other problems. As you can see below, the upgrade to 64-bit JVM did increase our existing application static memory footprint (tenured space) by 45%. 

Java Heap footprint ~900 MB after major collections (32-bit)

 Java Heap footprint ~1.3 GB after major collections (64-bit)

** 45% increase of the application Java heap memory footprint (retained tenured space). Again, this is due to the expanded size of managed native pointers.

The other part of the problem is that no performance and load testing was performed prior to production implementation, functional testing only. Also, since no change or tuning was applied to the JVM settings, this automatically triggered an increased frequency of major collections and JVM pause time. The final solution did involve increasing the Java heap capacity form 2 GB to 2.5 GB and using the Compressed Oops option available with HotSpot JDK 6u23.

Now that you understand the root cause, find below my recommendations when performing this type of upgrade:

• Execute performance and load testing cycles and compare your application memory footprint and GC behaviour before (32-bit) and after (64-bit).
• Ensure you spend enough time tuning your GC settings and the Java heap size in order to minimize the JVM pause time.
• If you are using HotSpot JVM 1.6 6u23 and later, take advantage of the Compressed Oops tuning parameter. Compressed oops will allow the HotSpot JVM to represent many (not all) managed pointers as 32-bit object offsets from the 64-bit Java heap base address; resulting in a reduced memory footprint following the upgrade.
• Perform proper capacity planning of the hardware hosting your JVM processes. Ensure that you have enough physical RAM and CPU capacity to handle the extra memory and CPU footprint associated with this upgrade.
• Develop a low risk implementation strategy by upgrading only a certain percentage of your production environment to 64-bit JVM e.g. 25%-50%. This will also allow you to compare the behavior with the existing 32-bit JVM processes and make sure performance is aligned with your P & L results.

Read More

java.lang.NullPointerException Minecraft

I have been receiving recently many comments and emails related to Minecraft Java related errors such as java.lang.NullPointerException. 

I recommend to look at the following YouTube video:

While this Blog is dedicated to general Java and Java EE troubleshooting, I’m still willing to help non Java programmers and Minecraft gamers who are facing these problems such as java.lang.NullPointerException when developing Mods and understand what is null in Java.

If you are in fact facing such problem, please follow the steps below:

• Provide me with the Java error and complete stack trace from Minecraft and/or your code.
• Post the complete error as a comment of this post (Post a Comment section below).

I also encourage you to search and post your problems to the Minecraft community forum.

Read More

HotSpot GC Thread CPU footprint on Linux

The following question will test your knowledge on garbage collection and high CPU troubleshooting for Java applications running on Linux OS. This troubleshooting technique is especially crucial when investigating excessive GC and / or CPU utilization.

It will assume that you do not have access to advanced monitoring tools such as Compuware dynaTrace or even JVisualVM. Future tutorials using such tools will be presented in the future but please ensure that you first master the base troubleshooting principles.

Question:

How can you monitor and calculate how much CPU % each of the Oracle HotSpot or JRockit JVM garbage collection (GC) threads is using at runtime on Linux OS?

Answer:

On the Linux OS, Java threads are implemented as native Threads, which results in each thread being a separate Linux process. This means that you are able to monitor the CPU % of any Java thread created by the HotSpot JVM using the top –H command (Threads toggle view).

That said, depending of the GC policy that you are using and your server specifications, the HotSpot & JRockit JVM will create a certain number of GC threads that will be performing young and old space collections. Such threads can be easily identified by generating a JVM thread dump. As you can see below in our example, the Oracle JRockit JVM did create 4 GC threads identified as "(GC Worker Thread X)”.

===== FULL THREAD DUMP ===============

Fri Nov 16 19:58:36 2012

BEA JRockit(R) R27.5.0-110-94909-1.5.0_14-20080204-1558-linux-ia32

"Main Thread" id=1 idx=0x4 tid=14911 prio=5 alive, in native, waiting

    -- Waiting for notification on: weblogic/t3/srvr/T3Srvr@0xfd0a4b0[fat lock]

    at jrockit/vm/Threads.waitForNotifySignal(JLjava/lang/Object;)Z(Native Method)

    at java/lang/Object.wait(J)V(Native Method)

    at java/lang/Object.wait(Object.java:474)

    at weblogic/t3/srvr/T3Srvr.waitForDeath(T3Srvr.java:730)

    ^-- Lock released while waiting: weblogic/t3/srvr/T3Srvr@0xfd0a4b0[fat lock]

    at weblogic/t3/srvr/T3Srvr.run(T3Srvr.java:380)

    at weblogic/Server.main(Server.java:67)

    at jrockit/vm/RNI.c2java(IIIII)V(Native Method)

    -- end of trace

"(Signal Handler)" id=2 idx=0x8 tid=14920 prio=5 alive, in native, daemon

"(GC Main Thread)" id=3 idx=0xc tid=14921 prio=5 alive, in native, native_waiting, daemon

"(GC Worker Thread 1)" id=? idx=0x10 tid=14922 prio=5 alive, in native, daemon

"(GC Worker Thread 2)" id=? idx=0x14 tid=14923 prio=5 alive, in native, daemon

"(GC Worker Thread 3)" id=? idx=0x18 tid=14924 prio=5 alive, in native, daemon

"(GC Worker Thread 4)" id=? idx=0x1c tid=14925 prio=5 alive, in native, daemon

………………………

Now let’s put all of these principles together via a simple example.

Step #1 - Monitor the GC thread CPU utilization

The first step of the investigation is to monitor and determine:

• Identify the native Thread ID for each GC worker thread shown via the Linux top –H command.
• Identify the CPU % for each GC worker thread.

Step #2 – Generate and analyze JVM Thread Dumps

At the same time of Linux top –H, generate 2 or 3 JVM Thread Dump snapshots via kill -3 <Java PID>.

• Open the JVM Thread Dump and locate the JVM GC worker threads.
• Now correlate the "top -H" output data with the JVM Thread Dump data by looking at the native thread id (tid attribute).

As you can see in our example, such analysis did allow us to determine that all our GC worker threads were using around 20% CPU each. This was due to major collections happening at that time. Please note that it is also very useful to enable verbose:gc as it will allow you to correlate such CPU spikes with minor and major collections and determine how much your JVM GC process is contributing to the overall server CPU utilization.

Read More

OpenJPA: Memory Leak Case Study

This article will provide the complete root cause analysis details and resolution of a Java heap memory leak (Apache OpenJPA leak) affecting an Oracle Weblogic server 10.0 production environment.

This post will also demonstrate the importance to follow the Java Persistence API best practices when managing the javax.persistence.EntityManagerFactory lifecycle.

Environment specifications

• Java EE server: Oracle Weblogic Portal 10.0
• OS: Solaris 10
• JDK: Oracle/Sun HotSpot JVM 1.5 32-bit @2 GB capacity
• Java Persistence API: Apache OpenJPA 1.0.x (JPA 1.0 specifications)
• RDBMS: Oracle 10g
• Platform type: Web Portal

Troubleshooting tools

• Quest Foglight for Java (Java heap monitoring)
• MAT (Java heap dump analysis)

Problem description & observations

The problem was initially reported by our Weblogic production support team following production outages. An initial root cause analysis exercise did reveal the following facts and observations:

• Production outages were observed on regular basis after ~2 weeks of traffic.
• The failures were due to Java heap (OldGen) depletion e.g. OutOfMemoryError: Java heap space error found in the Weblogic logs.
• A Java heap memory leak was confirmed after reviewing the Java heap OldGen space utilization over time from Foglight monitoring tool along with the Java verbose GC historical data.

Following the discovery of the above problems, the decision was taken to move to the next phase of the RCA and perform a JVM heap dump analysis of the affected Weblogic (JVM) instances.

JVM heap dump analysis

** A video explaining the following JVM Heap Dump analysis is now available here.

In order to generate a JVM heap dump, the supported team did use the HotSpot 1.5 jmap utility which generated a heap dump file (heap.bin) of about ~1.5 GB. The heap dump file was then analyzed using the Eclipse Memory Analyzer Tool. Now let’s review the heap dump analysis so we can understand the source of the OldGen memory leak.

MAT provides an initial Leak Suspects report which can be very useful to highlight your high memory contributors. For our problem case, MAT was able to identify a leak suspect contributing to almost 600 MB or 40% of the total OldGen space capacity.

At this point we found one instance of java.util.LinkedList using almost 600 MB of memory and loaded to one of our application parent class loader (@ 0x7e12b708). The next step was to understand the leaking objects along with the source of retention.

MAT allows you to inspect any class loader instance of your application, providing you with capabilities to inspect the loaded classes & instances. Simply search for the desired object by providing the address e.g. 0x7e12b708 and then inspect the loaded classes & instances by selecting List Objects > with outgoing references.

As you can see from the above snapshot, the analysis was quite revealing. What we found was one instance of org.apache.openjpa.enhance.PCRegistry at the source of the memory retention; more precisely the culprit was the _listeners field implemented as a LinkedList.

For your reference, the Apache OpenJPA PCRegistry is used internally to track the registered persistence-capable classes. Find below a snippet of the PCRegistry source code from Apache OpenJPA version 1.0.4 exposing the _listeners field.

/**

 * Tracks registered persistence-capable classes.

 *

 * @since 0.4.0

 * @author Abe White

 */

public class PCRegistry {

    // DO NOT ADD ADDITIONAL DEPENDENCIES TO THIS CLASS

    private static final Localizer _loc = Localizer.forPackage

        (PCRegistry.class);

    // map of pc classes to meta structs; weak so the VM can GC classes

    private static final Map _metas = new ConcurrentReferenceHashMap

        (ReferenceMap.WEAK, ReferenceMap.HARD);

    // register class listeners

    private static final Collection _listeners = new LinkedList();

……………………………………………………………………………………

Now the question is why is the memory footprint of this internal data structure so big and potentially leaking over time? The next step was to deep dive into the _listeners LinkedLink instance in order to review the leaking objects.

We finally found that the leaking objects were actually the JDBC & SQL mapping definitions (metadata) used by our application in order to execute various queries against our Oracle database. A review of the JPA specifications, OpenJPA documentation and source did confirm that the root cause was associated with a wrong usage of the  javax.persistence.EntityManagerFactory such of lack of closure of a newly created EntityManagerFactory instance.

If you look closely at the above code snapshot, you will realize that the close() method is indeed responsible to cleanup any recently used metadata repository instance. It did also raise another concern, why are we creating such Factory instances over and over…

The next step of the investigation was to perform a code walkthrough of our application code, especially around the life cycle management of the JPA EntityManagerFactory and EntityManager objects.

Root cause and solution

A code walkthrough of the application code did reveal that the application was creating a new instance of EntityManagerFactory on each single request and not closing it properly.

public class Application {

      

       @Resource

       private UserTransaction utx = null;

       

       // Initialized on each application request and not closed!

       @PersistenceUnit(unitName = "UnitName")

       private EntityManagerFactory emf = Persistence.createEntityManagerFactory("PersistenceUnit"); 

       public EntityManager getEntityManager() {

             return this.emf.createEntityManager();

       }

      

       public void businessMethod() {

            

             // Create a new EntityManager instance via from the newly created EntityManagerFactory instance

             // Do something...

             // Close the EntityManager instance

       }

}

This code defect and improver use of JPA EntityManagerFactory was causing a leak or accumulation of metadata repository instances within the OpenJPA _listeners data structure demonstrated from the earlier JVM heap dump analysis.

The solution of the problem was to centralize the management & life cycle of the thread safe javax.persistence.EntityManagerFactory via the Singleton pattern. The final solution was implemented as per below:

• Create and maintain only one static instance of javax.persistence.EntityManagerFactory per application class loader and implemented via the Singleton Pattern.
• Create and dispose new instances of EntityManager for each application request.

Please review this discussion from Stackoverflow as the solution we implemented is quite similar.

Following the implementation of the solution to our production environment, no more Java heap OldGen memory leak is observed.

Please feel free to provide your comments and share your experience on the same.

Read More