Pierre - Hugues Charbonneau

The following question will again test your knowledge of the Oracle Weblogic threading model. I’m looking forward for your comments and experience on the same. If you are a Weblogic administrator, I’m certain that you heard of this common problem: stuck threads. This is one of the most common problems you will face when supporting a Weblogic production environment. A Weblogic stuck thread simply means a thread performing the same request for a very long time and more than the configurable Stuck Thread Max Time. Question: How can you detect the presence of STUCK threads during and following a production incident? Answer: As we saw from our last article “Weblogic Thread Monitoring Tips”, Weblogic provides functionalities allowing us to closely monitor its internal self-tuning thread pool. It will also highlight you the presence of any stuck thread. This monitoring view is very useful when you do a live analysis but what about after a production incident? The good news is that Oracle Weblogic will also log any detected stuck thread to the server log. Such information includes details on the request and more importantly, the thread stack trace. This data is crucial and will allow you to potentially better understand the root cause of any slowdown condition that occurred at a certain time. < ExecuteThread: '11' for queue: 'weblogic.kernel.Default (self-tuning)'> <[STUCK] ExecuteThread: '35' for queue: 'weblogic.kernel.Default (self-tuning)' has been busy for "608" seconds working on the request "Workmanager: default, Version: 0, Scheduled=true, Started=true, Started time: 608213 ms POST /App1/jsp/test.jsp HTTP/1.1 Accept: application/x-ms-application... Referer: http://.. Accept-Language: en-US User-Agent: Mozilla/4.0 .. Content-Type: application/x-www-form-urlencoded Accept-Encoding: gzip, deflate Content-Length: 539 Connection: Keep-Alive Cache-Control: no-cache Cookie: JSESSIONID= ]", which is more than the configured time (StuckThreadMaxTime) of "600" seconds. Stack trace: ................................... javax.servlet.http.HttpServlet.service(HttpServlet.java:727) javax.servlet.http.HttpServlet.service(HttpServlet.java:820) weblogic.servlet.internal.StubSecurityHelper$ServletServiceAction.run(StubSecurityHelper.java:227) weblogic.servlet.internal.StubSecurityHelper.invokeServlet(StubSecurityHelper.java:125) weblogic.servlet.internal.ServletStubImpl.execute(ServletStubImpl.java:301) weblogic.servlet.internal.ServletStubImpl.execute(ServletStubImpl.java:184) weblogic.servlet.internal.WebAppServletContext$ServletInvocationAction.... weblogic.servlet.internal.WebAppServletContext$ServletInvocationAction.run() weblogic.security.acl.internal.AuthenticatedSubject.doAs(AuthenticatedSubject.java:321) weblogic.security.service.SecurityManager.runAs(SecurityManager.java:120) weblogic.servlet.internal.WebAppServletContext.securedExecute(WebAppServletContext.java:2281) weblogic.servlet.internal.WebAppServletContext.execute(WebAppServletContext.java:2180) weblogic.servlet.internal.ServletRequestImpl.run(ServletRequestImpl.java:1491) weblogic.work.ExecuteThread.execute(ExecuteThread.java:256) weblogic.work.ExecuteThread.run(ExecuteThread.java:221) Here is one more tip: the generation and analysis of a JVM thread dump will also highlight you stuck threads. As we can see from the snapshot below, the Weblogic thread state is now updated to STUCK, which means that this particular request is being executed since at least 600 seconds or 10 minutes. This is very useful information since the native thread state will typically remain to RUNNABLE. The native thread state will only get updated when dealing with BLOCKED threads etc. You have to keep in mind that RUNNABLE simply means that this thread is healthy from a JVM perspective. However, it does not mean that it truly is from a middleware or Java EE container perspective. This is why Oracle Weblogic has its own internal ExecuteThread state. Finally, if your organization or client is using any commercial monitoring tool, I recommend that you enable some alerting around both hogging thread and stuck thread. This will allow your support team to take some pro-active actions before the affected Weblogic managed server(s) become fully unresponsive.

If you are working as a middleware administrator or application support individual, you may have realized by now how crucial it is to have proper knowledge of the JVM along with a good understanding of the Java concurrency principles (yes you have to learn how to analyze thread dumps). There is one principle I’m sure about: it is never too late to improve our knowledge and troubleshooting skills. Reaching a skill “plateau” is quite common and typically not due to our ability to learn but because of our fear and lack of willingness to embrace the challenges. One of such challenges is possibly your ability to understand and assess the health of the JVM & middleware threads of the Java EE container you are responsible for such as Oracle Weblogic Server. If this is your situation then this post is for you. Question: How can you monitor the JVM threads in an efficient manner using the Weblogic admin console? Also, please elaborate how you can differentiate between healthy threads vs. slow running threads. Finally, what other tools can help you achieve this task? Answer: Please note that Weblogic Server 10.3.5 was used for the following example. Oracle Weblogic Server is always installed with an admin console that provides you with out-of-the-box monitoring functions of the various Java EE resources exposed via the JMX API. Weblogic threads (created and assigned by the WLS kernel to the default self-tuning thread pool) are also fully exposed. This monitoring page allows you to: Monitor the full list of all Java threads under Weblogic control. Correlate any slow running thread with your application, request and assigned Work Manager, if any. Generate a JVM Thread Dump of the Weblogic managed server directly from the page via the Dump Thread Stacks button. Thread states - summary view This section provides a summary of all different Weblogic threads and states. Thread states - detailed view The detailed view is much more interesting. This is where you will be spending most of your analysis time. Make sure that you add all proper columns including the associated Work Manager, application name etc. The live Weblogic thread monitoring analysis process I usually follow is as per below. This approach is very useful for production environments when you are trying to determine the source of a performance slowdown or just to give you an idea of the health of the Weblogic threads. Refresh the page every 3-5 seconds. In between the refresh actions, identify the threads that are still executing the same request (slow running threads). This can be determined if you see the same Weblogic thread “Name” executing the same “Current Request” with the same “Total requests” value. Other criteria’s would be if Weblogic “promote” the affected thread(s) to Hogger or STUCK. Continue until you are done with your monitoring activity. As soon as one or a few slow running threads are found, identify the affected request(s) and application(s). Immediately after, generate a JVM Thread Dump using the Dump Thread Stacks button and copy/paste the output to a text editor for live or future analysis. I also recommend that you use other tools to monitor the JVM and threads such as JVisualVM. JVisualVM will give a full view of all the threads, including GC related threads. It will also allow you to monitor the Java heap and correlate any finding with the health of the activity of the garbage collector. Finally, if you suspect that you are dealing with a deeper thread concurrency problem such as thread lock contention or Java-level deadlock, you will need to generate a native thread dump (JVisualVM, kill -3 PID, jstack etc.) which will allow you to review the different monitor locks and locked ownable synchronizers.

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: Java source files are compiled by the Java compiler into platform independent bytecode or Java class files. 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. 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. Once such method call is compiled into machine code, the JVM executes it directlyinstead of “interpreting” it. 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 disableJIT. 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 ininterpretation 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.

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 . 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.

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 */ publicclass PCRegistry { // DO NOT ADD ADDITIONAL DEPENDENCIES TO THIS CLASS privatestaticfinal Localizer _loc = Localizer.forPackage (PCRegistry.class); // map of pc classes to meta structs; weak so the VM can GC classes privatestaticfinal Map _metas = new ConcurrentReferenceHashMap (ReferenceMap.WEAK, ReferenceMap.HARD); // register class listeners privatestaticfinal 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.

As you may be aware, the JDK 8 Early Access is now available for download. This allows Java developers to experiment with some of the new language and runtime features of Java 8. One of these features is the complete removal of the Permanent Generation (PermGen) space which has been announced by Oracle since the release of JDK 7. Interned strings, for example, have already been removed from the PermGen space since JDK 7. The JDK 8 release finalizes its decommissioning. This article will share the information that we found so far on the PermGen successor: Metaspace. We will also compare the runtime behavior of the HotSpot 1.7 vs. HotSpot 1.8 (b75) when executing a Java program “leaking” class metadata objects. The final specifications, tuning flags and documentation around Metaspace should be available once Java 8 is officially released. Metaspace: A new memory space is born The JDK 8 HotSpot JVM is now using native memory for the representation of class metadata and is called Metaspace; similar to the Oracle JRockit and IBM JVM's. The good news is that it means no more java.lang.OutOfMemoryError: PermGen space problems and no need for you to tune and monitor this memory space anymore…not so fast. While this change is invisible by default, we will show you next that you will still need to worry about the class metadata memory footprint. Please also keep in mind that this new feature does not magically eliminate class and classloader memory leaks. You will need to track down these problems using a different approach and by learning the new naming convention. I recommend that you read the PermGen removal summary and comments from Jon on this subject. In summary: PermGen space situation This memory space is completely removed. The PermSize and MaxPermSize JVM arguments are ignored and a warning is issued if present at start-up. Metaspace memory allocation model Most allocations for the class metadata are now allocated out of native memory. The klasses that were used to describe class metadata have been removed. Metaspace capacity By default class metadata allocation is limited by the amount of available native memory (capacity will of course depend if you use a 32-bit JVM vs. 64-bit along with OS virtual memory availability). A new flag is available (MaxMetaspaceSize), allowing you to limit the amount of native memory used for class metadata. If you don’t specify this flag, the Metaspace will dynamically re-size depending of the application demand at runtime. Metaspace garbage collection Garbage collection of the dead classes and classloaders is triggered once the class metadata usage reaches the “MaxMetaspaceSize”. Proper monitoring & tuning of the Metaspace will obviously be required in order to limit the frequency or delay of such garbage collections. Excessive Metaspace garbage collections may be a symptom of classes, classloaders memory leak or inadequate sizing for your application. Java heap space impact Some miscellaneous data has been moved to the Java heap space. This means you may observe an increase of the Java heap space following a future JDK 8 upgrade. Metaspace monitoring Metaspace usage is available from the HotSpot 1.8 verbose GC log output. Jstat & JVisualVM have not been updated at this point based on our testing with b75 and the old PermGen space references are still present. Enough theory now, let’s see this new memory space in action via our leaking Java program… PermGen vs. Metaspace runtime comparison In order to better understand the runtime behavior of the new Metaspace memory space, we created a class metadata leaking Java program. You can download the source here. The following scenarios will be tested: Run the Java program using JDK 1.7 in order to monitor & deplete the PermGen memory space set at 128 MB. Run the Java program using JDK 1.8 (b75) in order to monitor the dynamic increase and garbage collection of the new Metaspace memory space. Run the Java program using JDK 1.8 (b75) in order to simulate the depletion of the Metaspace by setting the MaxMetaspaceSize value at 128 MB. JDK 1.7 @64-bit – PermGen depletion Java program with 50K configured iterations Java heap space of 1024 MB Java PermGen space of 128 MB (-XX:MaxPermSize=128m) As you can see form JVisualVM, the PermGen depletion was reached after loading about 30K+ classes. We can also see this depletion from the program and GC output. Class metadata leak simulator Author: Pierre-Hugues Charbonneau http://javaeesupportpatterns.blogspot.com ERROR: java.lang.OutOfMemoryError: PermGen space Now let’s execute the program using the HotSpot JDK 1.8 JRE. JDK 1.8 @64-bit – Metaspace dynamic re-size Java program with 50K configured iterations Java heap space of 1024 MB Java Metaspace space: unbounded (default) As you can see from the verbose GC output, the JVM Metaspace did expand dynamically from 20 MB up to 328 MB of reserved native memory in order to honor the increased class metadata memory footprint from our Java program. We could also observe garbage collection events in the attempt by the JVM to destroy any dead class or classloader object. Since our Java program is leaking, the JVM had no choice but to dynamically expand the Metaspace memory space. The program was able to run its 50K of iterations with no OOM event and loaded 50K+ Classes. Let's move to our last testing scenario. JDK 1.8 @64-bit – Metaspace depletion Java program with 50K configured iterations Java heap space of 1024 MB Java Metaspace space: 128 MB (-XX:MaxMetaspaceSize=128m) As you can see form JVisualVM, the Metaspace depletion was reached after loading about 30K+ classes; very similar to the run with the JDK 1.7. We can also see this from the program and GC output. Another interesting observation is that the native memory footprint reserved was twice as much as the maximum size specified. This may indicate some opportunities to fine tune the Metaspace re-size policy, if possible, in order to avoid native memory waste. Now find below the Exception we got from the Java program output. Class metadata leak simulator Author: Pierre-Hugues Charbonneau http://javaeesupportpatterns.blogspot.com ERROR: java.lang.OutOfMemoryError: Metadata space Done! As expected, capping the Metaspace at 128 MB like we did for the baseline run with JDK 1.7 did not allow us to complete the 50K iterations of our program. A new OOM error was thrown by the JVM. The above OOM event was thrown by the JVM from the Metaspace following a memory allocation failure. #metaspace.cpp Final words I hope you appreciated this early analysis and experiment with the new Java 8 Metaspace. The current observations definitely indicate that proper monitoring & tuning will be required in order to stay away from problems such as excessive Metaspace GC or OOM conditions triggered from our last testing scenario. Future articles may include performance comparisons in order to identify potential performance improvements associated with this new feature. Please feel free to provide any comment.

Most Java programmers are familiar with the Java thread deadlock concept. It essentially involves 2 threads waiting forever for each other. This condition is often the result of flat (synchronized) or ReentrantLock (read or write) lock-ordering problems. Found one Java-level deadlock: ============================= "pool-1-thread-2": waiting to lock monitor 0x0237ada4 (object 0x272200e8, a java.lang.Object), which is held by "pool-1-thread-1" "pool-1-thread-1": waiting to lock monitor 0x0237aa64 (object 0x272200f0, a java.lang.Object), which is held by "pool-1-thread-2" The good news is that the HotSpot JVM is always able to detect this condition for you…or is it? A recent thread deadlock problem affecting an Oracle Service Bus production environment has forced us to revisit this classic problem and identify the existence of “hidden” deadlock situations. This article will demonstrate and replicate via a simple Java program a very special lock-ordering deadlock condition which is not detected by the latest HotSpot JVM 1.7. You will also find a video at the end of the article explaining you the Java sample program and the troubleshooting approach used. The crime scene I usually like to compare major Java concurrency problems to a crime scene where you play the lead investigator role. In this context, the “crime” is an actual production outage of your client IT environment. Your job is to: Collect all the evidences, hints & facts (thread dump, logs, business impact, load figures…) Interrogate the witnesses & domain experts (support team, delivery team, vendor, client…) The next step of your investigation is to analyze the collected information and establish a potential list of one or many “suspects” along with clear proofs. Eventually, you want to narrow it down to a primary suspect or root cause. Obviously the law “innocent until proven guilty” does not apply here, exactly the opposite. Lack of evidence can prevent you to achieve the above goal. What you will see next is that the lack of deadlock detection by the Hotspot JVM does not necessary prove that you are not dealing with this problem. The suspect In this troubleshooting context, the “suspect” is defined as the application or middleware code with the following problematic execution pattern. Usage of FLAT lock followed by the usage of ReentrantLock WRITE lock (execution path #1) Usage of ReentrantLock READ lock followed by the usage of FLAT lock (execution path #2) Concurrent execution performed by 2 Java threads but via a reversed execution order The above lock-ordering deadlock criteria’s can be visualized as per below: Now let’s replicate this problem via our sample Java program and look at the JVM thread dump output. Sample Java program This above deadlock conditions was first identified from our Oracle OSB problem case. We then re-created it via a simple Java program. You can download the entire source code of our program here. The program is simply creating and firing 2 worker threads. Each of them execute a different execution path and attempt to acquire locks on shared objects but in different orders. We also created a deadlock detector thread for monitoring and logging purposes. For now, find below the Java class implementing the 2 different execution paths. package org.ph.javaee.training8; import java.util.concurrent.locks.ReentrantReadWriteLock; /** * A simple thread task representation * @author Pierre-Hugues Charbonneau * */ public class Task { // Object used for FLAT lock private final Object sharedObject = new Object(); // ReentrantReadWriteLock used for WRITE & READ locks private final ReentrantReadWriteLock lock = new ReentrantReadWriteLock(); /** * Execution pattern #1 */ public void executeTask1() { // 1. Attempt to acquire a ReentrantReadWriteLock READ lock lock.readLock().lock(); // Wait 2 seconds to simulate some work... try { Thread.sleep(2000);}catch (Throwable any) {} try { // 2. Attempt to acquire a Flat lock... synchronized (sharedObject) {} } // Remove the READ lock finally { lock.readLock().unlock(); } System.out.println("executeTask1() :: Work Done!"); } /** * Execution pattern #2 */ public void executeTask2() { // 1. Attempt to acquire a Flat lock synchronized (sharedObject) { // Wait 2 seconds to simulate some work... try { Thread.sleep(2000);}catch (Throwable any) {} // 2. Attempt to acquire a WRITE lock lock.writeLock().lock(); try { // Do nothing } // Remove the WRITE lock finally { lock.writeLock().unlock(); } } System.out.println("executeTask2() :: Work Done!"); } public ReentrantReadWriteLock getReentrantReadWriteLock() { return lock; } } As soon ad the deadlock situation was triggered, a JVM thread dump was generated using JVisualVM. As you can see from the Java thread dump sample. The JVM did not detect this deadlock condition (e.g. no presence of Found one Java-level deadlock) but it is clear these 2 threads are in deadlock state. Root cause: ReetrantLock READ lock behavior The main explanation we found at this point is associated with the usage of the ReetrantLock READ lock. The read locks are normally not designed to have a notion of ownership. Since there is not a record of which thread holds a read lock, this appears to prevent the HotSpot JVM deadlock detector logic to detect deadlock involving read locks. Some improvements were implemented since then but we can see that the JVM still cannot detect this special deadlock scenario. Now if we replace the read lock (execution pattern #2) in our program by a write lock, the JVM will finally detect the deadlock condition but why? Found one Java-level deadlock: ============================= "pool-1-thread-2": waiting for ownable synchronizer 0x272239c0, (a java.util.concurrent.locks.ReentrantReadWriteLock$NonfairSync), which is held by "pool-1-thread-1" "pool-1-thread-1": waiting to lock monitor 0x025cad3c (object 0x272236d0, a java.lang.Object), which is held by "pool-1-thread-2" Found one Java-level deadlock: ============================= "pool-1-thread-2": waiting for ownable synchronizer 0x272239c0, (a java.util.concurrent.locks.ReentrantReadWriteLock$NonfairSync), which is held by "pool-1-thread-1" "pool-1-thread-1": waiting to lock monitor 0x025cad3c (object 0x272236d0, a java.lang.Object), which is held by "pool-1-thread-2" Java stack information for the threads listed above: =================================================== "pool-1-thread-2": at sun.misc.Unsafe.park(Native Method) - parking to wait for <0x272239c0> (a java.util.concurrent.locks.ReentrantReadWriteLock$NonfairSync) at java.util.concurrent.locks.LockSupport.park(LockSupport.java:186) at java.util.concurrent.locks.AbstractQueuedSynchronizer.parkAndCheckInterrupt(AbstractQueuedSynchronizer.java:834) at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquireQueued(AbstractQueuedSynchronizer.java:867) at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquire(AbstractQueuedSynchronizer.java:1197) at java.util.concurrent.locks.ReentrantReadWriteLock$WriteLock.lock(ReentrantReadWriteLock.java:945) at org.ph.javaee.training8.Task.executeTask2(Task.java:54) - locked <0x272236d0> (a java.lang.Object) at org.ph.javaee.training8.WorkerThread2.run(WorkerThread2.java:29) at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1110) at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:603) at java.lang.Thread.run(Thread.java:722) "pool-1-thread-1": at org.ph.javaee.training8.Task.executeTask1(Task.java:31) - waiting to lock <0x272236d0> (a java.lang.Object) at org.ph.javaee.training8.WorkerThread1.run(WorkerThread1.java:29) at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1110) at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:603) at java.lang.Thread.run(Thread.java:722) This is because write locks are tracked by the JVM similar to flat locks. This means the HotSpot JVM deadlock detector appears to be currently designed to detect: Deadlock on Object monitors involving FLAT locks Deadlock involving Locked ownable synchronizers associated with WRITE locks The lack of read lock per-thread tracking appears to prevent deadlock detection for this scenario and significantly increase the troubleshooting complexity. I suggest that you read Doug Lea’s comments on this whole issue since concerns were raised back in 2005 regarding the possibility to add per-thread read-hold tracking due to some potential lock overhead. Find below my troubleshooting recommendations if you suspect a hidden deadlock condition involving read locks: Analyze closely the thread call stack trace, it may reveal some code potentially acquiring read locks and preventing other threads to acquire write locks. If you are the owner of the code, keep track of the read lock count via the usage of the lock.getReadLockCount() method I’m looking forward for your feedback, especially from individuals with experience on this type of deadlock involving read locks. Finally, find below a video explaining such findings via the execution and monitoring of our sample Java program.

This article will provide you with a tutorial allowing you to determine how much and where Java heap space is retained from your active application Java threads. A true case study from an Oracle Weblogic 10.0 production environment will be presented in order for you to better understand the analysis process. We will also attempt to demonstrate that excessive garbage collection or Java heap space memory footprint problems are often not caused by true memory leaks but instead due to thread execution patterns and high amount of short lived objects. Background As you may have seen from my past JVM overview article, Java threads are part of the JVM fundamentals. Your Java heap space memory footprint is driven not only by static and long lived objects but also by short lived objects. OutOfMemoryError problems are often wrongly assumed to be due to memory leaks. We often overlook faulty thread execution patterns and short lived objects they “retain” on the Java heap until their executions are completed. In this problematic scenario: Your “expected” application short lived / stateless objects (XML, JSON data payload etc.) become retained by the threads for too long (thread lock contention, huge data payload, slow response time from remote system etc.) Eventually such short lived objects get promoted to the long lived object space e.g. OldGen/tenured space by the garbage collector As a side effect, this is causing the OldGen space to fill up rapidly, increasing the Full GC (major collections) frequency Depending of the severity of the situation this can lead to excessive GC garbage collection, increased JVM paused time and ultimately OutOfMemoryError: Java heap space Your application is now down, you are now puzzled on what is going on Finally, you are thinking to either increase the Java heap or look for memory leaks…are you really on the right track? In the above scenario, you need to look at the thread execution patterns and determine how much memory each of them retain at a given time. OK I get the picture but what about the thread stack size? It is very important to avoid any confusion between thread stack size and Java memory retention. The thread stack size is a special memory space used by the JVM to store each method call. When a thread calls method A, it “pushes” the call onto the stack. If method A calls method B, it gets also pushed onto the stack. Once the method execution completes, the call is “popped” off the stack. The Java objects created as a result of such thread method calls are allocated on the Java heap space. Increasing the thread stack size will definitely not have any effect. Tuning of the thread stack size is normally required when dealing with java.lang.stackoverflowerror or OutOfMemoryError: unable to create new native thread problems. Case study and problem context The following analysis is based on a true production problem we investigated recently. Severe performance degradation was observed from a Weblogic 10.0 production environment following some changes to the user web interface (using Google Web Toolkit and JSON as data payload) Initial analysis did reveal several occurrences of OutOfMemoryError: Java heap space errors along with excessive garbage collection. Java heap dump files were generated automatically (-XX:+HeapDumpOnOutOfMemoryError) following OOM events Analysis of the verbose:gc logs did confirm full depletion of the 32-bit HotSpot JVM OldGen space (1 GB capacity) Thread dump snapshots were also generated before and during the problem The only problem mitigation available at that time was to restart the affected Weblogic server when problem was observed A rollback of the changes was eventually performed which did resolve the situation The team first suspected a memory leak problem from the new code introduced. Thread dump analysis: looking for suspects… The first analysis step we did was to perform an analysis of the generated thread dump data. Thread dump will often show you the culprit threads allocating memory on the Java heap. It will also reveal any hogging or stuck thread attempting to send and receive data payload from a remote system. The first pattern we noticed was a good correlation between OOM events and STUCK threads observed from the Weblogic managed servers (JVM processes). Find below the primary thread pattern found: <10-Dec-2012 1:27:59 o'clock PM EST> <[STUCK] ExecuteThread: '22' for queue: 'weblogic.kernel.Default (self-tuning)' has been busy for "672" seconds working on the request which is more than the configured time of "600" seconds. As you can see, the above thread appears to be STUCK or taking very long time to read and receive the JSON response from the remote server. Once we found that pattern, the next step was to correlate this finding with the JVM heap dump analysis and determine how much memory these stuck threads were taking from the Java heap. Heap dump analysis: retained objects exposed! The Java heap dump analysis was performed using MAT. We will now list the different analysis steps which did allow us to pinpoint the retained memory size and source. 1. Load the HotSpot JVM heap dump 2. Select the HISTOGRAM view and filter by “ExecuteThread” * ExecuteThread is the Java class used by the Weblogic kernel for thread creation & execution * As you can see, this view was quite revealing. We can see a total of 210 Weblogic threads created. The total retained memory footprint from these threads is 806 MB. This is pretty significant for a 32-bit JVM process with 1 GB OldGen space. This view alone is telling us that the core of the problem and memory retention originates from the threads themselves. 3. Deep dive into the thread memory footprint analysis The next step was to deep dive into the thread memory retention. To do this, simply right click over the ExecuteThread class and select: List objects > with outgoing references. As you can see, we were able to correlate STUCK threads from the thread dump analysis with high memory retention from the heap dump analysis. The finding was quite surprising. 3. Thread Java Local variables identification The final analysis step did require us to expand a few thread samples and understand the primary source of memory retention. As you can see, this last analysis step did reveal huge JSON response data payload at the root cause. That pattern was also exposed earlier via the thread dump analysis where we found a few threads taking very long time to read & receive the JSON response; a clear symptom of huge data payload footprint. It is crucial to note that short lived objects created via local method variables will show up in the heap dump analysis. However, some of those will only be visible from their parent threads since they are not referenced by other objects, like in this case. You will also need to analyze the thread stack trace in order to identify the true caller, followed by a code review to confirm the root cause. Following this finding, our delivery team was able to determine that the recent JSON faulty code changes were generating, under some scenarios, huge JSON data payload up to 45 MB+. Given the fact that this environment is using a 32-bit JVM with only 1 GB of OldGen space, you can understand that only a few threads were enough to trigger severe performance degradation. This case study is clearly showing the importance of proper capacity planning and Java heap analysis, including the memory retained from your active application & Java EE container threads. Learning is experience. Everything else is just information I hope this article has helped you understand how you can pinpoint the Java heap memory footprint retained by your active threads by combining thread dump and heap dump analysis. Now, this article will remain just words if you don’t experiment so I highly recommend that you take some time to learn this analysis process yourself for your application(s). Please feel free to post any comment or question.

This article will describe the complete root cause analysis and solution of a HashMap High CPU problem (infinite looping) affecting a Weblogic 10.0 environment running on the Java HotSpot VM 1.5. This case study will again demonstrate this importance of mastering Thread Dump analysis skill and CPU correlation techniques such as Solaris prstat. Environment specifications Java EE server: Oracle Weblogic Portal 10.0 Middleware OS: Solaris 10 Java VM: Java HotSpot VM 1.5 Platform type: Portal application Monitoring and troubleshooting tools JVM Thread Dump (HotSpot format) Solaris prstat (CPU contributors analysis) Problem overview Problem type: High CPUobserved from our Weblogic production environment A high CPU problem was observed from our Solaris physical servers hosting a Weblogic Portal 10 environment. Users also reporting major slowdown of the portal application. 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 Recent change of the affected platform? No Any recent traffic increase to the affected platform? Yes How does this high CPU manifest itself? A sudden CPU increase was observed and is not going down; even after load goes down e.g. near zero level. Did an Oracle OSB recycle resolve the problem? Yes, but problem is returning after few hours or few days (unpredictable pattern) - Conclusion #1: The high CPU problem appears to be intermittent vs. pure correlation with load - Conclusion #2: Since high CPU remains after load goes down, this typically indicates either the presence of some infinite looping or heavy processing Threads Solaris CPU analysis using prstat Solaris prstat is a powerful OS command allowing you to obtain the CPU per process but more importantly CPU per Thread within a process. As you can see below from our case study, the CPU utilization was confirmed to go up as high as 100% utilization (saturation level). ## PRSTAT (CPU per Java Thread analysis) prstat -L -p 8223 1 1 PID USERNAME SIZE RSS STATE PRI NICE TIME CPU PROCESS/LWPID 8223 bea10 2809M 2592M sleep 59 0 14:52:59 38.6%java/494 8223 bea10 2809M 2592M sleep 57 0 12:28:05 22.3% java/325 8223 bea10 2809M 2592M sleep 59 0 11:52:02 28.3% java/412 8223 bea10 2809M 2592M sleep 59 0 5:50:00 0.3% java/84 8223 bea10 2809M 2592M sleep 58 0 2:27:20 0.2% java/43 8223 bea10 2809M 2592M sleep 59 0 1:39:42 0.2% java/41287 8223 bea10 2809M 2592M sleep 59 0 4:41:44 0.2% java/30503 8223 bea10 2809M 2592M sleep 59 0 5:58:32 0.2% java/36116 …………………………………………………………………………………… As you can see from above data, 3 Java Threads were found using together close to 100% of the CPU utilization. For our root cause analysis, we did focus on Thread #494 (decimal format) corresponding to 0x1ee (HEXA format). Thread Dump analysis and PRSTAT correlation Once the culprit Threads were identified, the next step was to correlate this data with the Thread Dump data (which was captured exactly at the same time as prstat). A quick search within the generated Thread Dump file did reveal the Thread Stack Trace (Weblogic Stuck Thread #125) for 0x1ee as per below. "[STUCK] ExecuteThread: '125' for queue: 'weblogic.kernel.Default (self-tuning)'" daemon prio=1 tid=0x014c5030 nid=0x1ee runnable [0x536fb000..0x536ffc70] at java.util.HashMap.get(HashMap.java:346) at org.apache.axis.encoding.TypeMappingImpl.getClassForQName(TypeMappingImpl.java:715) at org.apache.axis.encoding.TypeMappingDelegate.getClassForQName(TypeMappingDelegate.java:170) at org.apache.axis.encoding.TypeMappingDelegate.getClassForQName(TypeMappingDelegate.java:160) at org.apache.axis.encoding.TypeMappingImpl.getDeserializer(TypeMappingImpl.java:454) at org.apache.axis.encoding.TypeMappingDelegate.getDeserializer(TypeMappingDelegate.java:108) at org.apache.axis.encoding.TypeMappingDelegate.getDeserializer(TypeMappingDelegate.java:102) at org.apache.axis.encoding.DeserializationContext.getDeserializer(DeserializationContext.java:457) at org.apache.axis.encoding.DeserializationContext.getDeserializerForType(DeserializationContext.java:547) at org.apache.axis.encoding.ser.BeanDeserializer.getDeserializer(BeanDeserializer.java:514) at org.apache.axis.encoding.ser.BeanDeserializer.onStartChild(BeanDeserializer.java:286) at org.apache.axis.encoding.DeserializationContext.startElement(DeserializationContext.java:1035) at org.apache.axis.message.SAX2EventRecorder.replay(SAX2EventRecorder.java:165) at org.apache.axis.message.MessageElement.publishToHandler(MessageElement.java:1141) at org.apache.axis.message.RPCElement.deserialize(RPCElement.java:236) at org.apache.axis.message.RPCElement.getParams(RPCElement.java:384) at org.apache.axis.client.Call.invoke(Call.java:2467) at org.apache.axis.client.Call.invoke(Call.java:2366) at org.apache.axis.client.Call.invoke(Call.java:1812) Thread Dump analysis – HashMap.get() infinite loop condition! As you can see from the above Thread Stack Trace, the Thread is currently stuck in an infinite loop over a java.util.HashMap that originates from the Apache Axis TypeMappingImpl Java class. This finding was quite revealing. The 2 others Threads using high CPU also did reveal infinite looping condition within the same Apache Axis HashMap Object. Root cause: non Thread safe HashMap in Apache Axis 1.4 Additional research did reveal this known defect affecting Apache Axis 1.4; which is the version that our application was using. As you may already know, usage of non Thread safe / non synchronized HashMap under concurrent Threads condition is very dangerous and can easily lead to internal HashMap index corruption and / or infinite looping. This is also a golden rule for any middleware software such as Oracle Weblogic, IBM WAS, Red Hat JBoss which rely heavily on HashMap data structures from various Java EE and caching services. Such best practice is also applicable for any Open Source third party API such as Apache Axis. The most common solution is to use the ConcurrentHashMap data structure which is designed for that type of concurrent Thread execution context. Solution Our team did apply the proposed patch from Apache (synchronize the non Thread safe HashMap) which did resolve the problem. We are also currently looking at upgrading our application to a newer version of Apache Axis. Conclusion I hope this case study has helped you understand how to pinpoint the root cause of high CPU Threads and the importance of proper Thread safe data structure for high concurrent Thread / processing applications. Please don’t hesitate to post any comment or question. Find office supplies promo codes to save money for your department's bottom line, so you can spend more on the latest software.

This is the first post of a new series that will bring you frequent and short “question of the day” articles. This new format will complement my existing writing and is designed to provide you with fast answers for common problems and questions that I often get from work colleagues, IT clients and readers. Each of these QOTD posts will be archived and you will have access to the entire list via a separate page. I also encourage you to post your feedback, recommendations along with your own complement answer for each question. Now let’s get started with our first question of the day! Question: What is the difference between Oracle Weblogic thread states & attributes (Total, Standby, Active, idle, Hogging, Stuck)? Answer: Weblogic thread state can be a particularly confusing topic for Weblogic administrators and individuals starting to learn and monitor Weblogic threads. The thread monitoring section can be accessed for each managed server Managed server under the Monitoring > Threads tab. As you can see, the thread monitoring tab provides a complete view of each Weblogic thread along with its state. Now let’s review each section and state so you can properly understand how to assess the health. # Summary section Execute Thread Total Count: This is the total number of threads “created” from the Weblogic self-tuning pool and visible from the JVM Thread Dump. This value correspond to the sum of: Active + Standby threads Active Execute Threads: This is the number of threads “eligible” to process a request. When thread demand goes up, Weblogic will start promoting threads from Standby to Active state which will enable them to process future client requests Standby Thread Count: This is the number of threads waiting to be marked “eligible” to process client requests. These threads are created and visible from the JVM Thread Dump but not available yet to process a client request Hogging Thread Count: This is the number of threads taking much more time than the current execution time in average calculated by the Weblogic kernel Execute Thread Idle Count: This is the number of Active threads currently “available” to process a client request In the above snapshots, we have: Total of 43 threads, 29 in Standby state and 14 in Active state Out of the 14 Active threads, we have 1 Hogging thread and 7 Idle threads e.g. 7 threads “available” for request processing Another way to see the situation: we have a total of 7 threads currently “processing” client request with 1 out of 7 in Hogging state (e.g. taking more time than current calculated average) # Thread matrix This matrix gives you a view of each thread along with its current state. There is one more state that you must also understand: STUCK: A stuck thread is identified by Weblogic when it is taking more time than the configured stuck thread time (default is 600 seconds). When facing slowdown conditions, you will normally see Weblogic threads transitioning from the Hogging state followed by STUCK, depending how long these threads remain stuck executing their current request

This article will provide you with a quick reference guide on how to calculate the Java process size memory footprint for Java VM processes running on IBM AIX 5.3+ OS. This is a complementary post to my original article on this subject: how to monitor the Java native memory on AIX. I highly recommend this article to any individual involved in production support or development of Java applications deployed on AIX. Why is this knowledge important? From my perspective, basic knowledge on how the OS is managing the memory allocation of your JVM processes is very important. We often overlook this monitoring aspect and only focus on the Java heap itself. From my experience, most Java memory related problems are observed from the Java heap itself such as garbage collection problems, leaks etc. However, I’m confident that you will face situations in the future involving native memory problems or OS memory challenges. Proper knowledge of your OS and virtual memory management is crucial for proper root causes analysis, recommendations and solutions. AIX memory vs. pages As you may have seen from my earlier post, the AIX Virtual Memory Manager (VMM) is responsible to manage memory requests from the system and its applications. The actual physical memory is converted and partitioned in units called pages; allocated either in physical RAM or stored on disk until it is needed. Each page can have a size of 4 KB (small page), 64 KB (medium page) or 16 MB (large page). Typically for a 64-bit Java process you will see a mix of all of the above. What about the topas command? The typical reflex when supporting applications on AIX is to run the topas command, similar to Solaris top. Find below an example of output from AIX 5.3: As you can see, the topas command is not very helpful to get a clear view on the memory utilization since it is not providing the breakdown view that we need for our analysis. It is still useful to get a rough idea of the paging space utilization which can give you a quick idea of your top "paging space" consumer processes. Same can be achieved via the ps aux command. AIX OS command to the rescue: svmon The AIX svmon command is by far my preferred command to deep dive into the Java process memory utilization. This is a very powerful command, similar to Solaris pmap. It allows you to monitor the current memory “pages” allocation along with each segment e.g. Java Heap vs. native heap segments. Analyzing the svmon output will allow you to calculate the memory footprint for each page type (4 KB, 64 KB, and 16 MB). Now find below a real example which will allow you to understand how the calculation is done: # 64-bit JVM with -Xms2048m & -Xmx2048m (2 GB Java Heap) # Command: svmon –P As you can see, the total footprint of our Java process size was found at 2.2 GB which is aligned with current Java heap settings. You should be able to easily perform the same memory footprint analysis from your AIX environment. I hope this article has helped you to understand how to calculate the Java process size on AIX OS. Please feel free to post any comment or question.

This article is intended for Java beginners currently facing java.lang.ClassNotFoundException challenges. It will provide you with an overview of this common Java exception, a sample Java program to support your learning process and resolution strategies. If you are interested on more advanced class loader related problems, I recommended that you review my article series on java.lang.NoClassDefFoundError since these Java exceptions are closely related. java.lang.ClassNotFoundException: Overview As per the Oracle documentation, ClassNotFoundException is thrown following the failure of a class loading call, using its string name, as per below: The Class.forName method The ClassLoader.findSystemClass method The ClassLoader.loadClass method In other words, it means that one particular Java class was not found or could not be loaded at “runtime” from your application current context class loader. This problem can be particularly confusing for Java beginners. This is why I always recommend to Java developers to learn and refine their knowledge on Java class loaders. Unless you are involved in dynamic class loading and using the Java Reflection API, chances are that the ClassNotFoundException error you are getting is not from your application code but from a referencing API. Another common problem pattern is a wrong packaging of your application code. We will get back to the resolution strategies at the end of the article. java.lang.ClassNotFoundException: Sample Java program Now find below a very simple Java program which simulates the 2 most common ClassNotFoundException scenarios via Class.forName() & ClassLoader.loadClass(). Please simply copy/paste and run the program with the IDE of your choice (Eclipse IDE was used for this example). The Java program allows you to choose between problem scenario #1 or problem scenario #2 as per below. Simply change to 1 or 2 depending of the scenario you want to study. # Class.forName() private static final int PROBLEM_SCENARIO = 1; # ClassLoader.loadClass() private static final int PROBLEM_SCENARIO = 2; # ClassNotFoundExceptionSimulator package org.ph.javaee.training5; /** * ClassNotFoundExceptionSimulator * @author Pierre-Hugues Charbonneau * */ public class ClassNotFoundExceptionSimulator { private static final String CLASS_TO_LOAD = "org.ph.javaee.training5.ClassA"; private static final int PROBLEM_SCENARIO = 1; /** * @param args */ public static void main(String[] args) { System.out.println("java.lang.ClassNotFoundException Simulator - Training 5"); System.out.println("Author: Pierre-Hugues Charbonneau"); System.out.println("http://javaeesupportpatterns.blogspot.com"); switch(PROBLEM_SCENARIO) { // Scenario #1 - Class.forName() case 1: System.out.println("\n** Problem scenario #1: Class.forName() **\n"); try { Class newClass = Class.forName(CLASS_TO_LOAD); System.out.println("Class "+newClass+" found successfully!"); } catch (ClassNotFoundException ex) { ex.printStackTrace(); System.out.println("Class "+CLASS_TO_LOAD+" not found!"); } catch (Throwable any) { System.out.println("Unexpected error! "+any); } break; // Scenario #2 - ClassLoader.loadClass() case 2: System.out.println("\n** Problem scenario #2: ClassLoader.loadClass() **\n"); try { ClassLoader classLoader = Thread.currentThread().getContextClassLoader(); Class callerClass = classLoader.loadClass(CLASS_TO_LOAD); Object newClassAInstance = callerClass.newInstance(); System.out.println("SUCCESS!: "+newClassAInstance); } catch (ClassNotFoundException ex) { ex.printStackTrace(); System.out.println("Class "+CLASS_TO_LOAD+" not found!"); } catch (Throwable any) { System.out.println("Unexpected error! "+any); } break; } System.out.println("\nSimulator done!"); } } # ClassA package org.ph.javaee.training5; /** * ClassA * @author Pierre-Hugues Charbonneau * */ public class ClassA { private final static Class CLAZZ = ClassA.class; static { System.out.println("Class loading of "+CLAZZ+" from ClassLoader '"+CLAZZ.getClassLoader()+"' in progress..."); } public ClassA() { System.out.println("Creating a new instance of "+ClassA.class.getName()+"..."); doSomething(); } private void doSomething() { // Nothing to do... } } f you run the program as is, you will see the output as per below for each scenario: #Scenario 1 output (baseline) java.lang.ClassNotFoundException Simulator - Training 5 Author: Pierre-Hugues Charbonneau http://javaeesupportpatterns.blogspot.com ** Problem scenario #1: Class.forName() ** Class loading of class org.ph.javaee.training5.ClassA from ClassLoader 'sun.misc.Launcher$AppClassLoader@bfbdb0' in progress... Class class org.ph.javaee.training5.ClassA found successfully! Simulator done! #Scenario 2 output (baseline) java.lang.ClassNotFoundException Simulator - Training 5 Author: Pierre-Hugues Charbonneau http://javaeesupportpatterns.blogspot.com ** Problem scenario #2: ClassLoader.loadClass() ** Class loading of class org.ph.javaee.training5.ClassA from ClassLoader 'sun.misc.Launcher$AppClassLoader@2a340e' in progress... Creating a new instance of org.ph.javaee.training5.ClassA... SUCCESS!: org.ph.javaee.training5.ClassA@6eb38a Simulator done! For the “baseline” run, the Java program is able to load ClassA successfully. Now let’s voluntary change the full name of ClassA and re-run the program for each scenario. The following output can be observed: #ClassA changed to ClassB private static final String CLASS_TO_LOAD = "org.ph.javaee.training5.ClassB"; #Scenario 1 output (problem replication) java.lang.ClassNotFoundException Simulator - Training 5 Author: Pierre-Hugues Charbonneau http://javaeesupportpatterns.blogspot.com ** Problem scenario #1: Class.forName() ** java.lang.ClassNotFoundException: org.ph.javaee.training5.ClassB at java.net.URLClassLoader$1.run(URLClassLoader.java:366) at java.net.URLClassLoader$1.run(URLClassLoader.java:355) at java.security.AccessController.doPrivileged(Native Method) at java.net.URLClassLoader.findClass(URLClassLoader.java:354) at java.lang.ClassLoader.loadClass(ClassLoader.java:423) at sun.misc.Launcher$AppClassLoader.loadClass(Launcher.java:308) at java.lang.ClassLoader.loadClass(ClassLoader.java:356) at java.lang.Class.forName0(Native Method) at java.lang.Class.forName(Class.java:186) at org.ph.javaee.training5.ClassNotFoundExceptionSimulator.main(ClassNotFoundExceptionSimulator.java:29) Class org.ph.javaee.training5.ClassB not found! Simulator done! #Scenario 2 output (problem replication) java.lang.ClassNotFoundException Simulator - Training 5 Author: Pierre-Hugues Charbonneau http://javaeesupportpatterns.blogspot.com ** Problem scenario #2: ClassLoader.loadClass() ** java.lang.ClassNotFoundException: org.ph.javaee.training5.ClassB at java.net.URLClassLoader$1.run(URLClassLoader.java:366) at java.net.URLClassLoader$1.run(URLClassLoader.java:355) at java.security.AccessController.doPrivileged(Native Method) at java.net.URLClassLoader.findClass(URLClassLoader.java:354) at java.lang.ClassLoader.loadClass(ClassLoader.java:423) at sun.misc.Launcher$AppClassLoader.loadClass(Launcher.java:308) at java.lang.ClassLoader.loadClass(ClassLoader.java:356) at org.ph.javaee.training5.ClassNotFoundExceptionSimulator.main(ClassNotFoundExceptionSimulator.java:51) Class org.ph.javaee.training5.ClassB not found! Simulator done! What happened? Well since we changed the full class name to org.ph.javaee.training5.ClassB, such class was not found at runtime (does not exist), causing both Class.forName() and ClassLoader.loadClass() calls to fail. You can also replicate this problem by packaging each class of this program to its own JAR file and then omit the jar file containing ClassA.class from the main class path Please try this and see the results for yourself…(hint: NoClassDefFoundError) Now let’s jump to the resolution strategies. java.lang.ClassNotFoundException: Resolution strategies Now that you understand this problem, it is now time to resolve it. Resolution can be fairly simple or very complex depending of the root cause. Don’t jump on complex root causes too quickly, rule out the simplest causes first. First review the java.lang.ClassNotFoundException stack trace as per the above and determine which Java class was not loaded properly at runtime e.g. application code, third party API, Java EE container itself etc. Identify the caller e.g. Java class you see from the stack trace just before the Class.forName() or ClassLoader.loadClass() calls. This will help you understand if your application code is at fault vs. a third party API. Determine if your application code is not packaged properly e.g. missing JAR file(s) from your classpath If the missing Java class is not from your application code, then identify if it belongs to a third party API you are using as per of your Java application. Once you identify it, you will need to add the missing JAR file(s) to your runtime classpath or web application WAR/EAR file. If still struggling after multiple resolution attempts, this could means a more complex class loader hierarchy problem. In this case, please review my NoClassDefFoundError article series for more examples and resolution strategies I hope this article has helped you to understand and revisit this common Java exception. Please feel free to post any comment or question if you are still struggling with your java.lang.ClassNotFoundException problem.

This article will provide you with a quick reference guide on how to calculate the Java process size memory footprint for Java VM processes running on IBM AIX 5.3+ OS. This is a complementary post to my original article on this subject: how to monitor the Java native memory on AIX. I highly recommend this read to any individual involved in production support or development of Java applications deployed on AIX. Why is this knowledge important? From my perspective, basic knowledge on how the OS is managing the memory allocation of your JVM processes is very important. We often overlook this monitoring aspect and only focus on the Java heap itself. From my experience, most Java memory related problems are observed from the Java heap itself such as garbage collection problems, leaks etc. However, I’m confident that you will face situations in the future involving native memory problems or OS memory challenges. Proper knowledge of your OS and virtual memory management is crucial for proper root causes analysis, recommendations and solutions. AIX memory vs. pages As you may have seen from my earlier post, the AIX Virtual Memory Manager (VMM) is responsible to manage memory requests from the system and its applications. The actual physical memory is converted and partitioned in units called pages; allocated either in physical RAM or stored on disk until it is needed. Each page can have a size of 4 KB (small page), 64 KB (medium page) or 16 MB (large page). Typically for a 64-bit Java process you will see a mix of all of the above. What about the topas command? The typical reflex when supporting applications on AIX is to run the topas command, similar to Solaris top. Find below an example of output from AIX 5.3: As you can see, the topas command is not very helpful to get a clear view on the memory utilization since it is not providing the breakdown view that we need for our analysis. It is still useful to get a rough idea of the paging space utilization which can give you a quick idea of your top "paging space" consumer processes. Same can be achieved via the ps aux command. AIX OS command to the rescue: svmon The AIX svmon command is by far my preferred command to deep dive into the Java process memory utilization. This is a very powerful command, similar to Solaris pmap. It allows you to monitor the current memory “pages” allocation along with each segment e.g. Java Heap vs. native heap segments. Analyzing the svmon output will allow you to calculate the memory footprint for each page type (4 KB, 64 KB, and 16 MB). Now find below a real example which will allow you to understand how the calculation is done: # 64-bit JVM with -Xms2048m & -Xmx2048m (2 GB Java Heap) # Command: svmon –P As you can see, the total footprint of our Java process size was found at 2.2 GB which is aligned with current Java heap settings. You should be able to easily perform the same memory footprint analysis from your AIX environment I hope this article has helped you to understand how to calculate the Java process size on AIX OS. Please feel free to post any comment or question.

This case study describes the complete root cause analysis and resolution of an Apache Log4j thread race problem affecting a Weblogic Portal 10.0 production environment. It will also demonstrate the importance of proper Java classloader knowledge when developing and supporting Java EE applications. This article is also another opportunity for you to improve your thread dump analysis skills and understand thread race conditions. Environment specifications Java EE server: Oracle Weblogic Portal 10.0 OS: Solaris 10 JDK: Oracle/Sun HotSpot JVM 1.5 Logging API: Apache Log4j 1.2.15 RDBMS: Oracle 10g Platform type: Web Portal Troubleshooting tools Quest Foglight for Java (monitoring and alerting) Java VM Thread Dump (thread race analysis) Problem overview Major performance degradation was observed from one of our Weblogic Portal production environments. Alerts were also sent from the Foglight agents indicating a significant surge in Weblogic threads utilization up to the upper default limit of 400. 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 Recent change of the affected platform? Yes, a recent deployment was performed involving minor content changes and some Java libraries changes & refactoring Any recent traffic increase to the affected platform? No Since how long this problem has been observed? New problem observed following the deployment Did a restart of the Weblogic server resolve the problem? No, any restart attempt did result in an immediate surge of threads Did a rollback of the deployment changes resolve the problem? Yes Conclusion #1: The problem appears to be related to the recent changes. However, the team was initially unable to pinpoint the root cause. This is now what we will discuss for the rest of the article. Weblogic hogging thread report The initial thread surge problem was reported by Foglight. As you can see below, the threads utilization was significant (up to 400) leading to a high volume of pending client requests and ultimately major performance degradation. As usual, thread problems require proper thread dump analysis in order to pinpoint the source of threads contention. Lack of this critical analysis skill will prevent you to go any further in the root cause analysis. For our case study, a few thread dump snapshots were generated from our Weblogic servers using the simple Solaris OS command kill -3 . Thread Dump data was then extracted from the Weblogic standard output log files. Thread Dump analysis The first step of the analysis was to perform a fast scan of all stuck threads and pinpoint a problem “pattern”. We found 250 threads stuck in the following execution path: "[ACTIVE] ExecuteThread: '20' for queue: 'weblogic.kernel.Default (self-tuning)'" daemon prio=10 tid=0x03c4fc38 nid=0xe6 waiting for monitor entry [0x3f99e000..0x3f99f970] at org.apache.log4j.Category.callAppenders(Category.java:186) - waiting to lock <0x8b3c4c68> (a org.apache.log4j.spi.RootCategory) at org.apache.log4j.Category.forcedLog(Category.java:372) at org.apache.log4j.Category.log(Category.java:864) at org.apache.commons.logging.impl.Log4JLogger.debug(Log4JLogger.java:110) at org.apache.beehive.netui.util.logging.Logger.debug(Logger.java:119) at org.apache.beehive.netui.pageflow.DefaultPageFlowEventReporter.beginPageRequest(DefaultPageFlowEventReporter.java:164) at com.bea.wlw.netui.pageflow.internal.WeblogicPageFlowEventReporter.beginPageRequest(WeblogicPageFlowEventReporter.java:248) at org.apache.beehive.netui.pageflow.PageFlowPageFilter.doFilter(PageFlowPageFilter.java:154) at weblogic.servlet.internal.FilterChainImpl.doFilter(FilterChainImpl.java:42) at com.bea.p13n.servlets.PortalServletFilter.doFilter(PortalServletFilter.java:336) at weblogic.servlet.internal.FilterChainImpl.doFilter(FilterChainImpl.java:42) at weblogic.servlet.internal.RequestDispatcherImpl.invokeServlet(RequestDispatcherImpl.java:526) at weblogic.servlet.internal.RequestDispatcherImpl.forward(RequestDispatcherImpl.java:261) at .AppRedirectFilter.doFilter(RedirectFilter.java:83) at weblogic.servlet.internal.FilterChainImpl.doFilter(FilterChainImpl.java:42) at .AppServletFilter.doFilter(PortalServletFilter.java:336) at weblogic.servlet.internal.FilterChainImpl.doFilter(FilterChainImpl.java:42) at weblogic.servlet.internal.WebAppServletContext$ServletInvocationAction.run(WebAppServletContext.java:3393) at weblogic.security.acl.internal.AuthenticatedSubject.doAs(AuthenticatedSubject.java:321) at weblogic.security.service.SecurityManager.runAs(Unknown Source) at weblogic.servlet.internal.WebAppServletContext.securedExecute(WebAppServletContext.java:2140) at weblogic.servlet.internal.WebAppServletContext.execute(WebAppServletContext.java:2046) at weblogic.servlet.internal.ServletRequestImpl.run(Unknown Source) at weblogic.work.ExecuteThread.execute(ExecuteThread.java:200) at weblogic.work.ExecuteThread.run(ExecuteThread.java:172) As you can see, it appears that all the threads are waiting to acquire a lock on an Apache Log4j object monitor (org.apache.log4j.spi.RootCategory) when attempting to log debug information to the configured appender and log file. How did we figure that out from this thread stack trace? Let’s dissect this thread stack trace in order for you to better understand this thread race condition e.g. 250 threads attempting to acquire the same object monitor concurrently. At this point the main question is why are we seeing this problem suddenly? An increase of the logging level or load was also ruled out at this point after proper verification. The fact that the rollback of the previous changes did fix the problem did naturally lead us to perform a deeper review of the promoted changes. Before we go to the final root cause section, we will perform a code review of the affected Log4j code e.g. exposed to thread race conditions. Apache Log4j 1.2.15 code review ## org.apache.log4j.Category /** * Call the appenders in the hierrachy starting at this. If no * appenders could be found, emit a warning. * * * This method calls all the appenders inherited from the hierarchy * circumventing any evaluation of whether to log or not to log the * particular log request. * * @param event * the event to log. */ public void callAppenders(LoggingEvent event) { int writes = 0; for (Category c = this; c != null; c = c.parent) { // Protected against simultaneous call to addAppender, // removeAppender,... synchronized (c) { if (c.aai != null) { writes += c.aai.appendLoopOnAppenders(event); } if (!c.additive) { break; } } } if (writes == 0) { repository.emitNoAppenderWarning(this); } As you can see, the Catelogry.callAppenders() is using a synchronized block at the Category level which can lead to a severe thread race condition under heavy concurrent load. In this scenario, the usage of a re-entrant read write lock would have been more appropriate (e.g. such lock strategy allows concurrent “read” but single “write”). You can find reference to this known Apache Log4j limitation below along with some possible solutions. https://issues.apache.org/bugzilla/show_bug.cgi?id=41214 Does the above Log4j behaviour is the actual root cause of our problem? Not so fast… Let’s remember that this problem got exposed only following a recent deployment. The real question is what application change triggered this problem & side effect from the Apache Log4j logging API? Root cause: a perfect storm! Deep dive analysis of the recent changes deployed did reveal that some Log4j libraries at the child classloader level were removed along with the associated “child first” policy. This refactoring exercise ended-up moving the delegation of both Commons logging and Log4j at the parent classloader level. What is the problem? Before this change, the logging events were split between Weblogic Beehive Log4j calls at the parent classloader and web application logging events at the child class loader. Since each classloader had its own copy of the Log4j objects, the thread race condition problem was split in half and not exposed (masked) under the current load conditions. Following the refactoring, all Log4j calls were moved to the parent classloader (Java EE app); adding significant concurrency level to the Log4j components such as Category. This increase concurrency level along with this known Category.java thread race / deadlock behaviour was a perfect storm for our production environment. In other to mitigate this problem, 2 immediate solutions were applied to the environment: Rollback the refactoring and split Log4j calls back between parent and child classloader Reduce logging level for some appenders from DEBUG to WARNING This problem case again re-enforce the importance of performing proper testing and impact assessment when applying changes such as library and class loader related changes. Such changes can appear simple at the "surface" but can trigger some deep execution pattern changes, exposing your application(s) to known thread race conditions. A future upgrade to Apache Log4j 2 (or other logging API’s) will also be explored as it is expected to bring some performance enhancements which may address some of these thread race & scalability concerns. Please provide any comment or share your experience on thread race related problems with logging API's.

As you may have seen from my previous tutorials and case studies, Java Heap Space OutOfMemoryError problems can be complex to pinpoint and resolve. One of the common problems I have observed from Java EE production systems is OutOfMemoryError: unable to create new native thread; error thrown when the HotSpot JVM is unable to further create a new Java thread. This article will revisit this HotSpot VM error and provide you with recommendations and resolution strategies. If you are not familiar with the HotSpot JVM, I first recommend that you look at a high level view of its internal HotSpot JVM memory spaces. This knowledge is important in order for you to understand OutOfMemoryError problems related to the native (C-Heap) memory space. OutOfMemoryError: unable to create new native thread – what is it? Let’s start with a basic explanation. This HotSpot JVM error is thrown when the internal JVM native code is unable to create a new Java thread. More precisely, it means that the JVM native code was unable to create a new “native” thread from the OS (Solaris, Linux, MAC, Windows...). We can clearly see this logic from the OpenJDK 1.6 and 1.7 implementations as per below: Unfortunately at this point you won’t get more detail than this error, with no indication of why the JVM is unable to create a new thread from the OS… HotSpot JVM: 32-bit or 64-bit? Before you go any further in the analysis, one fundamental fact that you must determine from your Java or Java EE environment is which version of HotSpot VM you are using e.g. 32-bit or 64-bit. Why is it so important? What you will learn shortly is that this JVM problem is very often related to native memory depletion; either at the JVM process or OS level. For now please keep in mind that: A 32-bit JVM process is in theory allowed to grow up to 4 GB (even much lower on some older 32-bit Windows versions). For a 32-bit JVM process, the C-Heap is in a race with the Java Heap and PermGen space e.g. C-Heap capacity = 2-4 GB – Java Heap size (-Xms, -Xmx) – PermGen size (-XX:MaxPermSize) A 64-bit JVM process is in theory allowed to use most of the OS virtual memory available or up to 16 EB (16 million TB) As you can see, if you allocate a large Java Heap (2 GB+) for a 32-bit JVM process, the native memory space capacity will be reduced automatically, opening the door for JVM native memory allocation failures. For a 64-bit JVM process, your main concern, from a JVM C-Heap perspective, is the capacity and availability of the OS physical, virtual and swap memory. OK great but how does native memory affect Java threads creation? Now back to our primary problem. Another fundamental JVM aspect to understand is that Java threads created from the JVM requires native memory from the OS. You should now start to understand the source of your problem… The high level thread creation process is as per below: A new Java thread is requested from the Java program & JDK The JVM native code then attempt to create a new native thread from the OS The OS then attempts to create a new native thread as per attributes which include the thread stack size. Native memory is then allocated (reserved) from the OS to the Java process native memory space; assuming the process has enough address space (e.g. 32-bit process) to honour the request The OS will refuse any further native thread & memory allocation if the 32-bit Java process size has depleted its memory address space e.g. 2 GB, 3 GB or 4 GB process size limit The OS will also refuse any further Thread & native memory allocation if the virtual memory of the OS is depleted (including Solaris swap space depletion since thread access to the stack can generate a SIGBUS error, crashing the JVM * http://bugs.sun.com/view_bug.do?bug_id=6302804 In summary: Java threads creation require native memory available from the OS; for both 32-bit & 64-bit JVM processes For a 32-bit JVM, Java thread creation also requires memory available from the C-Heap or process address space Problem diagnostic Now that you understand native memory and JVM thread creation a little better, is it now time to look at your problem. As a starting point, I suggest that your follow the analysis approach below: Determine if you are using HotSpot 32-bit or 64-bit JVM When problem is observed, take a JVM Thread Dump and determine how many Threads are active Monitor closely the Java process size utilization before and during the OOM problem replication Monitor closely the OS virtual memory utilization before and during the OOM problem replication; including the swap memory space utilization if using Solaris OS Proper data gathering as per above will allow you to collect the proper data points, allowing you to perform the first level of investigation. The next step will be to look at the possible problem patterns and determine which one is applicable for your problem case. Problem pattern #1 – C-Heap depletion (32-bit JVM) From my experience, OutOfMemoryError: unable to create new native thread is quite common for 32-bit JVM processes. This problem is often observed when too many threads are created vs. C-Heap capacity. JVM Thread Dump analysis and Java process size monitoring will allow you to determine if this is the cause. Problem pattern #2 – OS virtual memory depletion (64-bit JVM) In this scenario, the OS virtual memory is fully depleted. This could be due to a few 64-bit JVM processes taking lot memory e.g. 10 GB+ and / or other high memory footprint rogue processes. Again, Java process size & OS virtual memory monitoring will allow you to determine if this is the cause. Problem pattern #3 – OS virtual memory depletion (32-bit JVM) The third scenario is less frequent but can still be observed. The diagnostic can be a bit more complex but the key analysis point will be to determine which processes are causing a full OS virtual memory depletion. Your 32-bit JVM processes could be either the source or the victim such as rogue processes using most of the OS virtual memory and preventing your 32-bit JVM processes to reserve more native memory for its thread creation process. Please note that this problem can also manifest itself as a full JVM crash (as per below sample) when running out of OS virtual memory or swap space on Solaris. # # A fatal error has been detected by the Java Runtime Environment: # # java.lang.OutOfMemoryError: requested 32756 bytes for ChunkPool::allocate. Out of swap space? # # Internal Error (allocation.cpp:166), pid=2290, tid=27 # Error: ChunkPool::allocate # # JRE version: 6.0_24-b07 # Java VM: Java HotSpot(TM) Server VM (19.1-b02 mixed mode solaris-sparc ) # If you would like to submit a bug report, please visit: # http://java.sun.com/webapps/bugreport/crash.jsp # --------------- T H R E A D --------------- Current thread (0x003fa800): JavaThread "CompilerThread1" daemon [_thread_in_native, id=27, stack(0x65380000,0x65400000)] Stack: [0x65380000,0x65400000], sp=0x653fd758, free space=501k Native frames: (J=compiled Java code, j=interpreted, Vv=VM code, C=native code) ……………… Native memory depletion: symptom or root cause? You now understand your problem and know which problem pattern you are dealing with. You are now ready to provide recommendations to address the problem…are you? Your work is not done yet, please keep in mind that this JVM OOM event is often just a “symptom” of the actual root cause of the problem. The root cause is typically much deeper so before providing recommendations to your client I recommend that you really perform deeper analysis. The last thing you want to do is to simply address and mask the symptoms. Solutions such as increasing OS physical / virtual memory or upgrading all your JVM processes to 64-bit should only be considered once you have a good view on the root cause and production environment capacity requirements. The next fundamental question to answer is how many threads were active at the time of the OutOfMemoryError? In my experience with Java EE production systems, the most common root cause is actually the application and / or Java EE container attempting to create too many threads at a given time when facing non happy paths such as thread stuck in a remote IO call, thread race conditions etc. In this scenario, the Java EE container can start creating too many threads when attempting to honour incoming client requests, leading to increase pressure point on the C-Heap and native memory allocation. Bottom line, before blaming the JVM, please perform your due diligence and determine if you are dealing with an application or Java EE container thread tuning problem as the root cause. Once you understand and address the root cause (source of thread creations), you can then work on tuning your JVM and OS memory capacity in order to make it more fault tolerant and better “survive” these sudden thread surge scenarios. Recommendations: First perform a JVM Thread Dump analysis and determine the source of all the active threads vs. an established baseline. Determine what is causing your Java application or Java EE container to create so many threads at the time of the failure Please ensure that your monitoring tools closely monitor both your Java VM processes size & OS virtual memory. This crucial data will be required in order to perform a full root cause analysis Do not assume that you are dealing with an OS memory capacity problem. Look at all running processes and determine if your JVM processes are actually the source of the problem or victim of other processes consuming all the virtual memory Revisit your Java EE container thread configuration & JVM thread stack size. Determine if the Java EE container is allowed to create more threads than your JVM process and / or OS can handle Determine if the Java Heap size of your 32-bit JVM is too large, preventing the JVM to create enough threads to fulfill your client requests. In this scenario, you will have to consider reducing your Java Heap size (if possible), vertical scaling or upgrade to a 64-bit JVM Capacity planning analysis to the rescue As you may have seen from my past article on the Top 10 Causes of Java EE Enterprise Performance Problems, lack of capacity planning analysis is often the source of the problem. Any comprehensive load and performance testing exercise should also properly determine the Java EE container threads, JVM & OS native memory requirement for your production environment; including impact measurements of "non-happy" paths. This approach will allow your production environment to stay away from this type of problem and lead to better system scalability and stability in the long run. Please provide any comment and share your experience with JVM native thread troubleshooting.

As you may have seen from my past performance related articles and HashMap case studies, Java thread safety problems can bring down your Java EE application and the Java EE container fairly easily. One of most common problems I have observed when troubleshooting Java EE performance problems is infinite looping triggered from the non-thread safe HashMap get() and put() operations. This problem is known since several years but recent production problems have forced me to revisit this issue one more time. This article will revisit this classic thread safety problem and demonstrate, using a simple Java program, the risk associated with a wrong usage of the plain old java.util.HashMap data structure involved in a concurrent threads context. This proof of concept exercise will attempt to achieve the following 3 goals: Revisit and compare the Java program performance level between the non-thread safe and thread safe Map data structure implementations (HashMap, Hashtable, synchronized HashMap, ConcurrentHashMap) Replicate and demonstrate the HashMap infinite looping problem using a simple Java program that everybody can compile, run and understand Review the usage of the above Map data structures in a real-life and modern Java EE container implementation such as JBoss AS7 For more detail on the ConcurrentHashMap implementation strategy, I highly recommend the great article from Brian Goetz on this subject. Tools and server specifications As a starting point, find below the different tools and software’s used for the exercise: Sun/Oracle JDK & JRE 1.7 64-bit Eclipse Java EE IDE Windows Process Explorer (CPU per Java Thread correlation) JVM Thread Dump (stuck thread analysis and CPU per Thread correlation) The following local computer was used for the problem replication process and performance measurements: Intel(R) Core(TM) i5-2520M CPU @ 2.50Ghz (2 CPU cores, 4 logical cores) 8 GB RAM Windows 7 64-bit * Results and performance of the Java program may vary depending of your workstation or server specifications. Java program In order to help us achieve the above goals, a simple Java program was created as per below: The main Java program is HashMapInfiniteLoopSimulator.java A worker Thread class WorkerThread.java was also created The program is performing the following: Initialize different static Map data structures with initial size of 2 Assign the chosen Map to the worker threads (you can chose between 4 Map implementations) Create a certain number of worker threads (as per the header configuration). 3 worker threads were created for this proof of concept NB_THREADS = 3; Each of these worker threads has the same task: lookup and insert a new element in the assigned Map data structure using a random Integer element between 1 – 1 000 000. Each worker thread perform this task for a total of 500K iterations The overall program performs 50 iterations in order to allow enough ramp up time for the HotSpot JVM The concurrent threads context is achieved using the JDK ExecutorService As you can see, the Java program task is fairly simple but complex enough to generate the following critical criteria’s: Generate concurrency against a shared / static Map data structure Use a mix of get() and put() operations in order to attempt to trigger internal locks and / or internal corruption (for the non-thread safe implementation) Use a small Map initial size of 2, forcing the internal HashMap to trigger an internal rehash/resize Finally, the following parameters can be modified at your convenience: ## Number of worker threads private static final int NB_THREADS = 3; ## Number of Java program iterations private static final int NB_TEST_ITERATIONS = 50; ## Map data structure assignment. You can choose between 4 structures // Plain old HashMap (since JDK 1.2) nonThreadSafeMap = new HashMap(2); // Plain old Hashtable (since JDK 1.0) threadSafeMap1 = new Hashtable(2); // Fully synchronized HashMap threadSafeMap2 = new HashMap(2); threadSafeMap2 = Collections.synchronizedMap(threadSafeMap2); // ConcurrentHashMap (since JDK 1.5) threadSafeMap3 = new ConcurrentHashMap(2); /*** Assign map at your convenience ****/ assignedMapForTest = threadSafeMap3; Now find below the source code of our sample program. #### HashMapInfiniteLoopSimulator.java package org.ph.javaee.training4; import java.util.Collections; import java.util.Map; import java.util.HashMap; import java.util.Hashtable; import java.util.concurrent.ConcurrentHashMap; import java.util.concurrent.ExecutorService; import java.util.concurrent.Executors; /** * HashMapInfiniteLoopSimulator * @author Pierre-Hugues Charbonneau * */ public class HashMapInfiniteLoopSimulator { private static final int NB_THREADS = 3; private static final int NB_TEST_ITERATIONS = 50; private static Map assignedMapForTest = null; private static Map nonThreadSafeMap = null; private static Map threadSafeMap1 = null; private static Map threadSafeMap2 = null; private static Map threadSafeMap3 = null; /** * Main program * @param args */ public static void main(String[] args) { System.out.println("Infinite Looping HashMap Simulator"); System.out.println("Author: Pierre-Hugues Charbonneau"); System.out.println("http://javaeesupportpatterns.blogspot.com"); for (int i=0; i(2); // Plain old Hashtable (since JDK 1.0) threadSafeMap1 = new Hashtable(2); // Fully synchronized HashMap threadSafeMap2 = new HashMap(2); threadSafeMap2 = Collections.synchronizedMap(threadSafeMap2); // ConcurrentHashMap (since JDK 1.5) threadSafeMap3 = new ConcurrentHashMap(2); // ConcurrentHashMap /*** Assign map at your convenience ****/ assignedMapForTest = threadSafeMap3; long timeBefore = System.currentTimeMillis(); long timeAfter = 0; Float totalProcessingTime = null; ExecutorService executor = Executors.newFixedThreadPool(NB_THREADS); for (int j = 0; j < NB_THREADS; j++) { /** Assign the Map at your convenience **/ Runnable worker = new WorkerThread(assignedMapForTest); executor.execute(worker); } // This will make the executor accept no new threads // and finish all existing threads in the queue executor.shutdown(); // Wait until all threads are finish while (!executor.isTerminated()) { } timeAfter = System.currentTimeMillis(); totalProcessingTime = new Float( (float) (timeAfter - timeBefore) / (float) 1000); System.out.println("All threads completed in "+totalProcessingTime+" seconds"); } } } #### WorkerThread.java package org.ph.javaee.training4; import java.util.Map; /** * WorkerThread * * @author Pierre-Hugues Charbonneau * */ public class WorkerThread implements Runnable { private Map map = null; public WorkerThread(Map assignedMap) { this.map = assignedMap; } @Override public void run() { for (int i=0; i<500000; i++) { // Return 2 integers between 1-1000000 inclusive Integer newInteger1 = (int) Math.ceil(Math.random() * 1000000); Integer newInteger2 = (int) Math.ceil(Math.random() * 1000000); // 1. Attempt to retrieve a random Integer element Integer retrievedInteger = map.get(String.valueOf(newInteger1)); // 2. Attempt to insert a random Integer element map.put(String.valueOf(newInteger2), newInteger2); } } } Performance comparison between thread safe Map implementations The first goal is to compare the performance level of our program when using different thread safe Map implementations: Plain old Hashtable (since JDK 1.0) Fully synchronized HashMap (via Collections.synchronizedMap()) ConcurrentHashMap (since JDK 1.5) Find below the graphical results of the execution of the Java program for each iteration along with a sample of the program console output. # Output when using ConcurrentHashMap Infinite Looping HashMap Simulator Author: Pierre-Hugues Charbonneau http://javaeesupportpatterns.blogspot.com All threads completed in 0.984 seconds All threads completed in 0.908 seconds All threads completed in 0.706 seconds All threads completed in 1.068 seconds All threads completed in 0.621 seconds All threads completed in 0.594 seconds All threads completed in 0.569 seconds All threads completed in 0.599 seconds ……………… As you can see, the ConcurrentHashMap is the clear winner here, taking in average only half a second (after an initial ramp-up) for all 3 worker threads to concurrently read and insert data within a 500K looping statement against the assigned shared Map. Please note that no problem was found with the program execution e.g. no hang situation. The performance boost is definitely due to the improved ConcurrentHashMap performance such as the non-blocking get() operation. The 2 other Map implementations performance level was fairly similar with a small advantage for the synchronized HashMap. HashMap infinite looping problem replication The next objective is to replicate the HashMap infinite looping problem observed so often from Java EE production environments. In order to do that, you simply need to assign the non-thread safe HashMap implementation as per code snippet below: /*** Assign map at your convenience ****/ assignedMapForTest = nonThreadSafeMap; Running the program as is using the non-thread safe HashMap should lead to: No output other than the program header Significant CPU increase observed from the system At some point the Java program will hang and you will be forced to kill the Java process What happened? In order to understand this situation and confirm the problem, we will perform a CPU per Thread analysis from the Windows OS using Process Explorer and JVM Thread Dump. 1 - Run the program again then quickly capture the thread per CPU data from Process Explorer as per below. Under explore.exe you will need to right click over the javaw.exe and select properties. The threads tab will be displayed. We can see overall 4 threads using almost all the CPU of our system. 2 – Now you have to quickly capture a JVM Thread Dump using the JDK 1.7 jstack utility. For our example, we can see our 3 worker threads which seems busy/stuck performing get() and put() operations. ..\jdk1.7.0\bin>jstack 272 2012-08-29 14:07:26 Full thread dump Java HotSpot(TM) 64-Bit Server VM (21.0-b17 mixed mode): "pool-1-thread-3" prio=6 tid=0x0000000006a3c000 nid=0x18a0 runnable [0x0000000007ebe000] java.lang.Thread.State: RUNNABLE at java.util.HashMap.put(Unknown Source) at org.ph.javaee.training4.WorkerThread.run(WorkerThread.java:32) at java.util.concurrent.ThreadPoolExecutor.runWorker(Unknown Source) at java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source) at java.lang.Thread.run(Unknown Source) "pool-1-thread-2" prio=6 tid=0x0000000006a3b800 nid=0x6d4 runnable [0x000000000805f000] java.lang.Thread.State: RUNNABLE at java.util.HashMap.get(Unknown Source) at org.ph.javaee.training4.WorkerThread.run(WorkerThread.java:29) at java.util.concurrent.ThreadPoolExecutor.runWorker(Unknown Source) at java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source) at java.lang.Thread.run(Unknown Source) "pool-1-thread-1" prio=6 tid=0x0000000006a3a800 nid=0x2bc runnable [0x0000000007d9e000] java.lang.Thread.State: RUNNABLE at java.util.HashMap.put(Unknown Source) at org.ph.javaee.training4.WorkerThread.run(WorkerThread.java:32) at java.util.concurrent.ThreadPoolExecutor.runWorker(Unknown Source) at java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source) at java.lang.Thread.run(Unknown Source) .............. 3 – CPU per thread correlation It is now time to convert the Process Explorer thread ID DECIMAL format to HEXA format as per below. The HEXA value allows us to map and identify each thread as per below: ## TID: 1748 (nid=0X6D4) Thread name: pool-1-thread-2 CPU @25.71% Task: Worker thread executing a HashMap.get() operation at java.util.HashMap.get(Unknown Source) at org.ph.javaee.training4.WorkerThread.run(WorkerThread.java:29) at java.util.concurrent.ThreadPoolExecutor.runWorker(Unknown Source) at java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source) at java.lang.Thread.run(Unknown Source) ## TID: 700 (nid=0X2BC) Thread name: pool-1-thread-1 CPU @23.55% Task: Worker thread executing a HashMap.put() operation at java.util.HashMap.put(Unknown Source) at org.ph.javaee.training4.WorkerThread.run(WorkerThread.java:32) at java.util.concurrent.ThreadPoolExecutor.runWorker(Unknown Source) at java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source) at java.lang.Thread.run(Unknown Source) ## TID: 6304 (nid=0X18A0) Thread name: pool-1-thread-3 CPU @12.02% Task: Worker thread executing a HashMap.put() operation at java.util.HashMap.put(Unknown Source) at org.ph.javaee.training4.WorkerThread.run(WorkerThread.java:32) at java.util.concurrent.ThreadPoolExecutor.runWorker(Unknown Source) at java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source) at java.lang.Thread.run(Unknown Source) ## TID: 5944 (nid=0X1738) Thread name: pool-1-thread-1 CPU @20.88% Task: Main Java program execution "main" prio=6 tid=0x0000000001e2b000 nid=0x1738 runnable [0x00000000029df000] java.lang.Thread.State: RUNNABLE at org.ph.javaee.training4.HashMapInfiniteLoopSimulator.main(HashMapInfiniteLoopSimulator.java:75) As you can see, the above correlation and analysis is quite revealing. Our main Java program is in a hang state because our 3 worker threads are using lot of CPU and not going anywhere. They may appear "stuck" performing HashMap get() & put() but in fact they are all involved in an infinite loop condition. This is exactly what we wanted to replicate. HashMap infinite looping deep dive Now let’s push the analysis one step further to better understand this looping condition. For this purpose, we added tracing code within the JDK 1.7 HashMap Java class itself in order to understand what is happening. Similar logging was added for the put() operation and also a trace indicating that the internal & automatic rehash/resize got triggered. The tracing added in get() and put() operations allows us to determine if the for() loop is dealing with circular dependency which would explain the infinite looping condition. #### HashMap.java get() operation public V get(Object key) { if (key == null) return getForNullKey(); int hash = hash(key.hashCode()); /*** P-H add-on- iteration counter ***/ int iterations = 1; for (Entry e = table[indexFor(hash, table.length)]; e != null; e = e.next) { /*** Circular dependency check ***/ Entry currentEntry = e; Entry nextEntry = e.next; Entry nextNextEntry = e.next != null?e.next.next:null; K currentKey = currentEntry.key; K nextNextKey = nextNextEntry != null?(nextNextEntry.key != null?nextNextEntry.key:null):null; System.out.println("HashMap.get() #Iterations : "+iterations++); if (currentKey != null && nextNextKey != null ) { if (currentKey == nextNextKey || currentKey.equals(nextNextKey)) System.out.println(" ** Circular Dependency detected! ["+currentEntry+"]["+nextEntry+"]"+"]["+nextNextEntry+"]"); } /***** END ***/ Object k; if (e.hash == hash && ((k = e.key) == key || key.equals(k))) return e.value; } return null; } HashMap.get() #Iterations : 1 HashMap.put() #Iterations : 1 HashMap.put() #Iterations : 1 HashMap.put() #Iterations : 1 HashMap.put() #Iterations : 1 HashMap.resize() in progress... HashMap.put() #Iterations : 1 HashMap.put() #Iterations : 2 HashMap.resize() in progress... HashMap.resize() in progress... HashMap.put() #Iterations : 1 HashMap.put() #Iterations : 2 HashMap.put() #Iterations : 1 HashMap.get() #Iterations : 1 HashMap.get() #Iterations : 1 HashMap.put() #Iterations : 1 HashMap.get() #Iterations : 1 HashMap.get() #Iterations : 1 HashMap.put() #Iterations : 1 HashMap.get() #Iterations : 1 HashMap.put() #Iterations : 1 ** Circular Dependency detected! [362565=362565][333326=333326]][362565=362565] HashMap.put() #Iterations : 2 ** Circular Dependency detected! [333326=333326][362565=362565]][333326=333326] HashMap.put() #Iterations : 1 HashMap.put() #Iterations : 1 HashMap.get() #Iterations : 1 HashMap.put() #Iterations : 1 ............................. HashMap.put() #Iterations : 56823 Again, the added logging was quite revealing. We can see that following a few internal HashMap.resize() the internal structure became affected, creating circular dependency conditions and triggering this infinite looping condition (#iterations increasing and increasing...) with no exit condition. It is also showing that the resize() / rehash operation is the most at risk of internal corruption, especially when using the default HashMap size of 16. This means that the initial size of the HashMap appears to be a big factor in the risk & problem replication. Finally, it is interesting to note that we were able to successfully run the test case with the non-thread safe HashMap by assigning an initial size setting at 1000000, preventing any resize at all. Find below the merged graph results: The HashMap was our top performer but only when preventing an internal resize. Again, this is definitely not a solution to the thread safe risk but just a way to demonstrate that the resize operation is the most at risk given the entire manipulation of the HashMap performed at that time. The ConcurrentHashMap, by far, is our overall winner by providing both fast performance and thread safety against that test case. JBoss AS7 Map data structures usage We will now conclude this article by looking at the different Map implementations within a modern Java EE container implementation such as JBoss AS 7.1.2. You can obtain the latest source code from the github master branch. Find below the report: Total JBoss AS7.1.2 Java files (August 28, 2012 snapshot): 7302 Total Java classes using java.util.Hashtable: 72 Total Java classes using java.util.HashMap: 512 Total Java classes using synchronized HashMap: 18 Total Java classes using ConcurrentHashMap: 46 Hashtable references were found mainly within the test suite components and from naming and JNDI related implementations. This low usage is not a surprise here. References to the java.util.HashMap were found from 512 Java classes. Again not a surprise given how common this implementation is since the last several years. However, it is important to mention that a good ratio was found either from local variables (not shared across threads), synchronized HashMap or manual synchronization safeguard so “technically” thread safe and not exposed to the above infinite looping condition (pending/hidden bugs is still a reality given the complexity with Java concurrency programming…this case study involving Oracle Service Bus 11g is a perfect example). A low usage of synchronized HashMap was found with only 18 Java classes from packages such as JMS, EJB3, RMI and clustering. Finally, find below a breakdown of the ConcurrentHashMap usage which was our main interest here. As you will see below, this Map implementation is used by critical JBoss components layers such as the Web container, EJB3 implementation etc. ## JBoss Single Sign On Used to manage internal SSO ID's involving concurrent Thread access Total: 1 ## JBoss Java EE & Web Container Not surprising here since lot of internal Map data structures are used to manage the http sessions objects, deployment registry, clustering & replication, statistics etc. with heavy concurrent Thread access. Total: 11 ## JBoss JNDI & Security Layer Used by highly concurrent structures such as internal JNDI security management. Total: 4 ## JBoss domain & managed server management, rollout plans... Total: 7 ## JBoss EJB3 Used by data structures such as File Timer persistence store, application Exception, Entity Bean cache, serialization, passivation... Total: 8 ## JBoss kernel, Thread Pools & protocol management Used by high concurrent Threads Map data structures involved in handling and dispatching/processing incoming requests such as HTTP. Total: 3 ## JBoss connectors such as JDBC/XA DataSources... Total: 2 ## Weld (reference implementation of JSR-299: Contexts and Dependency Injection for the JavaTM EE platform) Used in the context of ClassLoader and concurrent static Map data structures involving concurrent Threads access. Total: 3 ## JBoss Test Suite Used in some integration testing test cases such as an internal Data Store, ClassLoader testing etc. Total: 3 Final words I hope this article has helped you revisit this classic problem and understand one of the common problems and risks associated with a wrong usage of the non-thread safe HashMap implementation. My main recommendation to you is to be careful when using an HashMap in a concurrent threads context. Unless you are a Java concurrency expert, I recommend that you use ConcurrentHashMap instead which offers a very good balance between performance and thread safety. As usual, extra due diligence is always recommended such as performing cycles of load & performance testing. This will allow you to detect thread safety and / or performance problems before you promote the solution to your client production environment. Please provide any comments and share your experience with ConcurrentHashMap or HashMap implementations and troubleshooting.

This article will provide you with 8 ways to improve your production support skills which may help you better enjoy your IT support job.

This article is part 3 of our NoClassDefFoundError troubleshooting series. As I mentioned in my first article, there are many possible issues that can lead to a NoClassDefFoundError. This article will focus and describe one of the most common causes of this problem: failure of a Java class static initializer block or variable. A sample Java program will be provided and I encourage you to compile and run this example from your workstation in order to properly replicate and understand this type of NoClassDefFoundError problem. Java static initializer revisited The Java programming language provides you with the capability to “statically” initialize variables or a block of code. This is achieved via the “static” variable identifier or the usage of a static {} block at the header of a Java class. Static initializers are guaranteed to be executed only once in the JVM life cycle and are Thread safe by design which make their usage quite appealing for static data initialization such as internal object caches, loggers etc. What is the problem? I will repeat again, static initializers are guaranteed to be executed only once in the JVM life cycle…This means that such code is executed at the Class loading time and never executed again until you restart your JVM. Now what happens if the code executed at that time (@Class loading time) terminates with an unhandled Exception? Welcome to the java.lang.NoClassDefFoundError problem case #2! NoClassDefFoundError problem case 2 – static initializer failure This type of problem is occurring following the failure of static initializer code combined with successive attempts to create a new instance of the affected (non-loaded) class. Sample Java program The following simple Java program is split as per below: The main Java program NoClassDefFoundErrorSimulator The affected Java class ClassA ClassA provides you with a ON/OFF switch allowing you the replicate the type of problem that you want to study This program is simply attempting to create a new instance of ClassA 3 times (one after each other). It will demonstrate that an initial failure of either a static variable or static block initializer combined with successive attempt to create a new instance of the affected class triggers java.lang.NoClassDefFoundError. #### NoClassDefFoundErrorSimulator.java package org.ph.javaee.tools.jdk7.training2; /** * NoClassDefFoundErrorSimulator * @author Pierre-Hugues Charbonneau * */ public class NoClassDefFoundErrorSimulator { /** * @param args */ public static void main(String[] args) { System.out.println("java.lang.NoClassDefFoundError Simulator - Training 2"); System.out.println("Author: Pierre-Hugues Charbonneau"); System.out.println("http://javaeesupportpatterns.blogspot.com\n\n"); try { // Create a new instance of ClassA (attempt #1) System.out.println("FIRST attempt to create a new instance of ClassA...\n"); ClassA classA = new ClassA(); } catch (Throwable any) { any.printStackTrace(); } try { // Create a new instance of ClassA (attempt #2) System.out.println("\nSECOND attempt to create a new instance of ClassA...\n"); ClassA classA = new ClassA(); } catch (Throwable any) { any.printStackTrace(); } try { // Create a new instance of ClassA (attempt #3) System.out.println("\nTHIRD attempt to create a new instance of ClassA...\n"); ClassA classA = new ClassA(); } catch (Throwable any) { any.printStackTrace(); } System.out.println("\n\ndone!"); } } #### ClassA.java package org.ph.javaee.tools.jdk7.training2; /** * ClassA * @author Pierre-Hugues Charbonneau * */ public class ClassA { private final static String CLAZZ = ClassA.class.getName(); // Problem replication switch ON/OFF private final static boolean REPLICATE_PROBLEM1 = true; // static variable initializer private final static boolean REPLICATE_PROBLEM2 = false; // static block{} initializer // Static variable executed at Class loading time private static String staticVariable = initStaticVariable(); // Static initializer block executed at Class loading time static { // Static block code execution... if (REPLICATE_PROBLEM2) throw new IllegalStateException("ClassA.static{}: Internal Error!"); } public ClassA() { System.out.println("Creating a new instance of "+ClassA.class.getName()+"..."); } /** * * @return */ private static String initStaticVariable() { String stringData = ""; if (REPLICATE_PROBLEM1) throw new IllegalStateException("ClassA.initStaticVariable(): Internal Error!"); return stringData; } } Problem reproduction In order to replicate the problem, we will simply “voluntary” trigger a failure of the static initializer code. Please simply enable the problem type that you want to study e.g. either static variable or static block initializer failure: // Problem replication switch ON (true) / OFF (false) private final static boolean REPLICATE_PROBLEM1 = true; // static variable initializer private final static boolean REPLICATE_PROBLEM2 = false; // static block{} initializer Now, let’s run the program with both switch at OFF (both boolean values at false) ## Baseline (normal execution) java.lang.NoClassDefFoundError Simulator - Training 2 Author: Pierre-Hugues Charbonneau http://javaeesupportpatterns.blogspot.com FIRST attempt to create a new instance of ClassA... Creating a new instance of org.ph.javaee.tools.jdk7.training2.ClassA... SECOND attempt to create a new instance of ClassA... Creating a new instance of org.ph.javaee.tools.jdk7.training2.ClassA... THIRD attempt to create a new instance of ClassA... Creating a new instance of org.ph.javaee.tools.jdk7.training2.ClassA... done! For the initial run (baseline), the main program was able to create 3 instances of ClassA successfully with no problem. ## Problem reproduction run (static variable initializer failure) java.lang.NoClassDefFoundError Simulator - Training 2 Author: Pierre-Hugues Charbonneau http://javaeesupportpatterns.blogspot.com FIRST attempt to create a new instance of ClassA... java.lang.ExceptionInInitializerError at org.ph.javaee.tools.jdk7.training2.NoClassDefFoundErrorSimulator.main(NoClassDefFoundErrorSimulator.java:21) Caused by: java.lang.IllegalStateException: ClassA.initStaticVariable(): Internal Error! at org.ph.javaee.tools.jdk7.training2.ClassA.initStaticVariable(ClassA.java:37) at org.ph.javaee.tools.jdk7.training2.ClassA.(ClassA.java:16) ... 1 more SECOND attempt to create a new instance of ClassA... java.lang.NoClassDefFoundError: Could not initialize class org.ph.javaee.tools.jdk7.training2.ClassA at org.ph.javaee.tools.jdk7.training2.NoClassDefFoundErrorSimulator.main(NoClassDefFoundErrorSimulator.java:30) THIRD attempt to create a new instance of ClassA... java.lang.NoClassDefFoundError: Could not initialize class org.ph.javaee.tools.jdk7.training2.ClassA at org.ph.javaee.tools.jdk7.training2.NoClassDefFoundErrorSimulator.main(NoClassDefFoundErrorSimulator.java:39) done! ## Problem reproduction run (static block initializer failure) java.lang.NoClassDefFoundError Simulator - Training 2 Author: Pierre-Hugues Charbonneau http://javaeesupportpatterns.blogspot.com FIRST attempt to create a new instance of ClassA... java.lang.ExceptionInInitializerError at org.ph.javaee.tools.jdk7.training2.NoClassDefFoundErrorSimulator.main(NoClassDefFoundErrorSimulator.java:21) Caused by: java.lang.IllegalStateException: ClassA.static{}: Internal Error! at org.ph.javaee.tools.jdk7.training2.ClassA.(ClassA.java:22) ... 1 more SECOND attempt to create a new instance of ClassA... java.lang.NoClassDefFoundError: Could not initialize class org.ph.javaee.tools.jdk7.training2.ClassA at org.ph.javaee.tools.jdk7.training2.NoClassDefFoundErrorSimulator.main(NoClassDefFoundErrorSimulator.java:30) THIRD attempt to create a new instance of ClassA... java.lang.NoClassDefFoundError: Could not initialize class org.ph.javaee.tools.jdk7.training2.ClassA at org.ph.javaee.tools.jdk7.training2.NoClassDefFoundErrorSimulator.main(NoClassDefFoundErrorSimulator.java:39) done! What happened? As you can see, the first attempt to create a new instance of ClassA did trigger a java.lang.ExceptionInInitializerError. This exception indicates the failure of our static initializer for our static variable & bloc which is exactly what we wanted to achieve. The key point to understand at this point is that this failure did prevent the whole class loading of ClassA. As you can see, attempt #2 and attempt #3 both generated a java.lang.NoClassDefFoundError, why? Well since the first attempt failed, class loading of ClassA was prevented. Successive attempts to create a new instance of ClassA within the current ClassLoader did generate java.lang.NoClassDefFoundError over and over since ClassA was not found within current ClassLoader. As you can see, in this problem context, the NoClassDefFoundError is just a symptom or consequence of another problem. The original problem is the ExceptionInInitializerError triggered following the failure of the static initializer code. This clearly demonstrates the importance of proper error handling and logging when using Java static initializers. Recommendations and resolution strategies Now find below my recommendations and resolution strategies for NoClassDefFoundError problem case 2: - Review the java.lang.NoClassDefFoundError error and identify the missing Java class - Perform a code walkthrough of the affected class and determine if it contains static initializer code (variables & static block) - Review your server and application logs and determine if any error (e.g. ExceptionInInitializerError) originates from the static initializer code - Once confirmed, analyze the code further and determine the root cause of the initializer code failure. You may need to add some extra logging along with proper error handling to prevent and better handle future failures of your static initializer code going forward Please feel free to post any question or comment. The part 4 will start coverage of NoClassDefFoundError problems related to class loader problems.

Determination of proper Java Heap size for a production system is not a straightforward exercise. In my Java EE enterprise experience, I have seen multiple performance problem cases due to inadequate Java Heap capacity and tuning. This article will provide you with 5 tips that can help you determine optimal Java Heap size, as a starting point, for your current or new production environment. Some of these tips are also very useful regarding the prevention and resolution of java.lang.OutOfMemoryError problems; including memory leaks. Please note that these tips are intended to “help you” determine proper Java Heap size. Since each IT environment is unique, you are actually in the best position to determine precisely the required Java Heap specifications of your client’s environment. Some of these tips may also not be applicable in the context of a very small Java standalone application but I still recommend you to read the entire article. Future articles will include tips on how to choose the proper Java VM garbage collector type for your environment and applications. #1 – JVM: you always fear what you don't understand How can you expect to configure, tune and troubleshoot something that you don’t understand? You may never have the chance to write and improve Java VM specifications but you are still free to learn its foundation in order to improve your knowledge and troubleshooting skills. Some may disagree, but from my perspective, the thinking that Java programmers are not required to know the internal JVM memory management is an illusion. Java Heap tuning and troubleshooting can especially be a challenge for Java & Java EE beginners. Find below a typical scenario: - Your client production environment is facing OutOfMemoryError on a regular basis and causing lot of business impact. Your support team is under pressure to resolve this problem - A quick Google search allows you to find examples of similar problems and you now believe (and assume) that you are facing the same problem - You then grab JVM -Xms and -Xmx values from another person OutOfMemoryError problem case, hoping to quickly resolve your client’s problem - You then proceed and implement the same tuning to your environment. 2 days later you realize problem is still happening (even worse or little better)…the struggle continues… What went wrong? - You failed to first acquire proper understanding of the root cause of your problem - You may also have failed to properly understand your production environment at a deeper level (specifications, load situation etc.). Web searches is a great way to learn and share knowledge but you have to perform your own due diligence and root cause analysis - You may also be lacking some basic knowledge of the JVM and its internal memory management, preventing you to connect all the dots together My #1 tip and recommendation to you is to learn and understand the basic JVM principles along with its different memory spaces. Such knowledge is critical as it will allow you to make valid recommendations to your clients and properly understand the possible impact and risk associated with future tuning considerations. Now find below a quick high level reference guide for the Java VM: The Java VM memory is split up to 3 memory spaces: The Java Heap. Applicable for all JVM vendors, usually split between YoungGen (nursery) & OldGen (tenured) spaces. The PermGen (permanent generation). Applicable to the Sun HotSpot VM only (PermGen space will be removed in future Java 7 or Java 8 updates) The Native Heap (C-Heap). Applicable for all JVM vendors. I recommend that you review each article below, including Sun white paper on the HotSpot Java memory management. I also encourage you to download and look at the OpenJDK implementation. ## Sun HotSpot VM http://javaeesupportpatterns.blogspot.com/2011/08/java-heap-space-hotspot-vm.html ## IBM VM http://javaeesupportpatterns.blogspot.com/2012/02/java-heap-space-ibm-vm.html ## Oracle JRockit VM http://javaeesupportpatterns.blogspot.com/2012/02/java-heap-space-jrockit-vm.html ## Sun (Oracle) – Java memory management white paper http://java.sun.com/j2se/reference/whitepapers/memorymanagement_whitepaper.pdf ## OpenJDK – Open-source Java implementation http://openjdk.java.net/ As you can see, the Java VM memory management is more complex than just setting up the biggest value possible via –Xmx. You have to look at all angles, including your native and PermGen space requirement along with physical memory availability (and # of CPU cores) from your physical host(s). It can get especially tricky for 32-bit JVM since the Java Heap and native Heap are in a race. The bigger your Java Heap, smaller the native Heap. Attempting to setup a large Heap for a 32-bit VM e.g .2.5 GB+ increases risk of native OutOfMemoryError depending of your application(s) footprint, number of Threads etc. 64-bit JVM resolves this problem but you are still limited to physical resources availability and garbage collection overhead (cost of major GC collections go up with size). The bottom line is that the bigger is not always the better so please do not assume that you can run all your 20 Java EE applications on a single 16 GB 64-bit JVM process. #2 – Data and application is king: review your static footprint requirement Your application(s) along with its associated data will dictate the Java Heap footprint requirement. By static memory, I mean “predictable” memory requirements as per below. - Determine how many different applications you are planning to deploy to a single JVM process e.g. number of EAR files, WAR files, jar files etc. The more applications you deploy to a single JVM, higher demand on native Heap - Determine how many Java classes will be potentially loaded at runtime; including third part API’s. The more class loaders and classes that you load at runtime, higher demand on the HotSpot VM PermGen space and internal JIT related optimization objects - Determine data cache footprint e.g. internal cache data structures loaded by your application (and third party API’s) such as cached data from a database, data read from a file etc. The more data caching that you use, higher demand on the Java Heap OldGen space - Determine the number of Threads that your middleware is allowed to create. This is very important since Java threads require enough native memory or OutOfMemoryError will be thrown For example, you will need much more native memory and PermGen space if you are planning to deploy 10 separate EAR applications on a single JVM process vs. only 2 or 3. Data caching not serialized to a disk or database will require extra memory from the OldGen space. Try to come up with reasonable estimates of the static memory footprint requirement. This will be very useful to setup some starting point JVM capacity figures before your true measurement exercise (e.g. tip #4). For 32-bit JVM, I usually do not recommend a Java Heap size high than 2 GB (-Xms2048m, -Xmx2048m) since you need enough memory for PermGen and native Heap for your Java EE applications and threads. This assessment is especially important since too many applications deployed in a single 32-bit JVM process can easily lead to native Heap depletion; especially in a multi threads environment. For a 64-bit JVM, a Java Heap size of 3 GB or 4 GB per JVM process is usually my recommended starting point. #3 – Business traffic set the rules: review your dynamic footprint requirement Your business traffic will typically dictate your dynamic memory footprint. Concurrent users & requests generate the JVM GC “heartbeat” that you can observe from various monitoring tools due to very frequent creation and garbage collections of short & long lived objects. As you saw from the above JVM diagram, a typical ratio of YoungGen vs. OldGen is 1:3 or 33%. For a typical 32-bit JVM, a Java Heap size setup at 2 GB (using generational & concurrent collector) will typically allocate 500 MB for YoungGen space and 1.5 GB for the OldGen space. Minimizing the frequency of major GC collections is a key aspect for optimal performance so it is very important that you understand and estimate how much memory you need during your peak volume. Again, your type of application and data will dictate how much memory you need. Shopping cart type of applications (long lived objects) involving large and non-serialized session data typically need large Java Heap and lot of OldGen space. Stateless and XML processing heavy applications (lot of short lived objects) require proper YoungGen space in order to minimize frequency of major collections. Example: - You have 5 EAR applications (~2 thousands of Java classes) to deploy (which include middleware code as well…) - Your native heap requirement is estimated at 1 GB (has to be large enough to handle Threads creation etc.) - Your PermGen space is estimated at 512 MB - Your internal static data caching is estimated at 500 MB - Your total forecast traffic is 5000 concurrent users at peak hours - Each user session data footprint is estimated at 500 K - Total footprint requirement for session data alone is 2.5 GB under peak volume As you can see, with such requirement, there is no way you can have all this traffic sent to a single JVM 32-bit process. A typical solution involves splitting (tip #5) traffic across a few JVM processes and / or physical host (assuming you have enough hardware and CPU cores available). However, for this example, given the high demand on static memory and to ensure a scalable environment in the long run, I would also recommend 64-bit VM but with a smaller Java Heap as a starting point such as 3 GB to minimize the GC cost. You definitely want to have extra buffer for the OldGen space so I typically recommend up to 50% memory footprint post major collection in order to keep the frequency of Full GC low and enough buffer for fail-over scenarios. Most of the time, your business traffic will drive most of your memory footprint, unless you need significant amount of data caching to achieve proper performance which is typical for portal (media) heavy applications. Too much data caching should raise a yellow flag that you may need to revisit some design elements sooner than later. #4 – Don’t guess it, measure it! At this point you should: - Understand the basic JVM principles and memory spaces - Have a deep view and understanding of all applications along with their characteristics (size, type, dynamic traffic, stateless vs. stateful objects, internal memory caches etc.) - Have a very good view or forecast on the business traffic (# of concurrent users etc.) and for each application - Some ideas if you need a 64-bit VM or not and which JVM settings to start with - Some ideas if you need more than one JVM (middleware) processes But wait, your work is not done yet. While this above information is crucial and great for you to come up with “best guess” Java Heap settings, it is always best and recommended to simulate your application(s) behaviour and validate the Java Heap memory requirement via proper profiling, load & performance testing. You can learn and take advantage of tools such as JProfiler (future articles will include tutorials on JProfiler). From my perspective, learning how to use a profiler is the best way to properly understand your application memory footprint. Another approach I use for existing production environments is heap dump analysis using the Eclipse MAT tool. Heap Dump analysis is very powerful and allow you to view and understand the entire memory footprint of the Java Heap, including class loader related data and is a must do exercise in any memory footprint analysis; especially memory leaks. Java profilers and heap dump analysis tools allow you to understand and validate your application memory footprint, including detection and resolution of memory leaks. Load and performance testing is also a must since this will allow you to validate your earlier estimates by simulating your forecast concurrent users. It will also expose your application bottlenecks and allow you to further fine tune your JVM settings. You can use tools such as Apache JMeter which is very easy to learn and use or explore other commercial products. Finally, I have seen quite often Java EE environments running perfectly fine until the day where one piece of the infrastructure start to fail e.g. hardware failure. Suddenly the environment is running at reduced capacity (reduced # of JVM processes) and the whole environment goes down. What happened? There are many scenarios that can lead to domino effects but lack of JVM tuning and capacity to handle fail-over (short term extra load) is very common. If your JVM processes are running at 80%+ OldGen space capacity with frequent garbage collections, how can you expect to handle any fail-over scenario? Your load and performance testing exercise performed earlier should simulate such scenario and you should adjust your tuning settings properly so your Java Heap has enough buffer to handle extra load (extra objects) at short term. This is mainly applicable for the dynamic memory footprint since fail-over means redirecting a certain % of your concurrent users to the available JVM processes (middleware instances). #5 – Divide and conquer At this point you have performed dozens of load testing iterations. You know that your JVM is not leaking memory. Your application memory footprint cannot be reduced any further. You tried several tuning strategies such as using a large 64-bit Java Heap space of 10 GB+, multiple GC policies but still not finding your performance level acceptable? In my experience I found that, with current JVM specifications, proper vertical and horizontal scaling which involved creating a few JVM processes per physical host and across several hosts will give you the throughput and capacity that you are looking for. Your IT environment will also more fault tolerant if you break your application list in a few logical silos, with their own JVM process, Threads and tuning values. This “divide and conquer” strategy involves splitting your application(s) traffic to multiple JVM processes and will provide you with: - Reduced Java Heap size per JVM process (both static & dynamic footprint) - Reduced complexity of JVM tuning - Reduced GC elapsed and pause time per JVM process - Increased redundancy and fail-over capabilities - Aligned with latest Cloud and IT virtualization strategies The bottom line is that when you find yourself spending too much time in tuning that single elephant 64-bit JVM process, it is time to revisit your middleware and JVM deployment strategy and take advantage of vertical & horizontal scaling. This implementation strategy is more taxing for the hardware but will really pay off in the long run. Please provide any comment and share your experience on JVM Heap sizing and tuning.

Performance problems are one of the biggest challenges to expect when designing and implementing Java EE related technologies.

This article is part 2 of our NoClassDefFoundError troubleshooting series. It will focus and describe the simplest type of NoClassDefFoundError problem. This article is ideal for Java beginners and I highly recommend that you compile and run the sample Java program yourself. The following writing format will be used going forward and will provide you with: - Description of the problem case and type of NoClassDefFoundError - Sample Java program “simulating” the problem case - ClassLoader chain view - Recommendations and resolution strategies NoClassDefFoundError problem case 1 – missing JAR file The first problem case we will cover is related to a Java program packaging and / or classpath problem. A typical Java program can include one or many JAR files created at compile time. NoClassDefFoundError can often be observed when you forget to add JAR file(s) containing Java classes referenced by your Java or Java EE application. This type of problem is normally not hard to resolve once you analyze the Java Exception and missing Java class name. Sample Java program The following simple Java program is split as per below: - The main Java program NoClassDefFoundErrorSimulator - The caller Java class CallerClassA - The referencing Java class ReferencingClassA - A util class for ClassLoader and logging related facilities JavaEETrainingUtil This program is simple attempting to create a new instance and execute a method of the Java class CallerClassA which is referencing the class ReferencingClassA.It will demonstrate how a simple classpath problem can trigger NoClassDefFoundError. The program is also displaying detail on the current class loader chain at class loading time in order to help you keep track of this process. This will be especially useful for future and more complex problem cases when dealing with larger class loader chains. #### NoClassDefFoundErrorSimulator.java package org.ph.javaee.training1; import org.ph.javaee.training.util.JavaEETrainingUtil; /** * NoClassDefFoundErrorTraining1 * @author Pierre-Hugues Charbonneau * */ public class NoClassDefFoundErrorSimulator { /** * @param args */ public static void main(String[] args) { System.out.println("java.lang.NoClassDefFoundError Simulator - Training 1"); System.out.println("Author: Pierre-Hugues Charbonneau"); System.out.println("http://javaeesupportpatterns.blogspot.com"); // Print current Classloader context System.out.println("\nCurrent ClassLoader chain: "+JavaEETrainingUtil.getCurrentClassloaderDetail()); // 1. Create a new instance of CallerClassA CallerClassA caller = new CallerClassA(); // 2. Execute method of the caller caller.doSomething(); System.out.println("done!"); } } #### CallerClassA.java package org.ph.javaee.training1; import org.ph.javaee.training.util.JavaEETrainingUtil; /** * CallerClassA * @author Pierre-Hugues Charbonneau * */ public class CallerClassA { private final static String CLAZZ = CallerClassA.class.getName(); static { System.out.println("Classloading of "+CLAZZ+" in progress..."+JavaEETrainingUtil.getCurrentClassloaderDetail()); } public CallerClassA() { System.out.println("Creating a new instance of "+CallerClassA.class.getName()+"..."); } public void doSomething() { // Create a new instance of ReferencingClassA ReferencingClassA referencingClass = new ReferencingClassA(); } } #### ReferencingClassA.java package org.ph.javaee.training1; import org.ph.javaee.training.util.JavaEETrainingUtil; /** * ReferencingClassA * @author Pierre-Hugues Charbonneau * */ public class ReferencingClassA { private final static String CLAZZ = ReferencingClassA.class.getName(); static { System.out.println("Classloading of "+CLAZZ+" in progress..."+JavaEETrainingUtil.getCurrentClassloaderDetail()); } public ReferencingClassA() { System.out.println("Creating a new instance of "+ReferencingClassA.class.getName()+"..."); } public void doSomething() { //nothing to do... } } #### JavaEETrainingUtil.java package org.ph.javaee.training.util; import java.util.Stack; import java.lang.ClassLoader; /** * JavaEETrainingUtil * @author Pierre-Hugues Charbonneau * */ public class JavaEETrainingUtil { /** * getCurrentClassloaderDetail * @return */ public static String getCurrentClassloaderDetail() { StringBuffer classLoaderDetail = new StringBuffer(); Stack classLoaderStack = new Stack(); ClassLoader currentClassLoader = Thread.currentThread().getContextClassLoader(); classLoaderDetail.append("\n-----------------------------------------------------------------\n"); // Build a Stack of the current ClassLoader chain while (currentClassLoader != null) { classLoaderStack.push(currentClassLoader); currentClassLoader = currentClassLoader.getParent(); } // Print ClassLoader parent chain while(classLoaderStack.size() > 0) { ClassLoader classLoader = classLoaderStack.pop(); // Print current classLoaderDetail.append(classLoader); if (classLoaderStack.size() > 0) { classLoaderDetail.append("\n--- delegation ---\n"); } else { classLoaderDetail.append(" **Current ClassLoader**"); } } classLoaderDetail.append("\n-----------------------------------------------------------------\n"); return classLoaderDetail.toString(); } } Problem reproduction In order to replicate the problem, we will simply “voluntary” omit one of the JAR files from the classpath that contains the referencing Java class ReferencingClassA. The Java program is packaged as per below: - MainProgram.jar (contains NoClassDefFoundErrorSimulator.class and JavaEETrainingUtil.class) - CallerClassA.jar (contains CallerClassA.class) - ReferencingClassA.jar (contains ReferencingClassA.class) Now, let’s run the program as is: ## Baseline (normal execution) .\bin>java -classpath CallerClassA.jar;ReferencingClassA.jar;MainProgram.jar org.ph.javaee.training1.NoClassDefFoundErrorSimulator java.lang.NoClassDefFoundError Simulator - Training 1 Author: Pierre-Hugues Charbonneau http://javaeesupportpatterns.blogspot.com Current ClassLoader chain: ----------------------------------------------------------------- sun.misc.Launcher$ExtClassLoader@17c1e333 --- delegation --- sun.misc.Launcher$AppClassLoader@214c4ac9 **Current ClassLoader** ----------------------------------------------------------------- Classloading of org.ph.javaee.training1.CallerClassA in progress... ----------------------------------------------------------------- sun.misc.Launcher$ExtClassLoader@17c1e333 --- delegation --- sun.misc.Launcher$AppClassLoader@214c4ac9 **Current ClassLoader** ----------------------------------------------------------------- Creating a new instance of org.ph.javaee.training1.CallerClassA... Classloading of org.ph.javaee.training1.ReferencingClassA in progress... ----------------------------------------------------------------- sun.misc.Launcher$ExtClassLoader@17c1e333 --- delegation --- sun.misc.Launcher$AppClassLoader@214c4ac9 **Current ClassLoader** ----------------------------------------------------------------- Creating a new instance of org.ph.javaee.training1.ReferencingClassA... done! For the initial run (baseline), the main program was able to create a new instance of CallerClassA and execute its method successfully; including successful class loading of the referencing class ReferencingClassA. ## Problem reproduction run (with removal of ReferencingClassA.jar) ../bin>java -classpath CallerClassA.jar;MainProgram.jar org.ph.javaee.training1.NoClassDefFoundErrorSimulator java.lang.NoClassDefFoundError Simulator - Training 1 Author: Pierre-Hugues Charbonneau http://javaeesupportpatterns.blogspot.com Current ClassLoader chain: ----------------------------------------------------------------- sun.misc.Launcher$ExtClassLoader@17c1e333 --- delegation --- sun.misc.Launcher$AppClassLoader@214c4ac9 **Current ClassLoader** ----------------------------------------------------------------- Classloading of org.ph.javaee.training1.CallerClassA in progress... ----------------------------------------------------------------- sun.misc.Launcher$ExtClassLoader@17c1e333 --- delegation --- sun.misc.Launcher$AppClassLoader@214c4ac9 **Current ClassLoader** ----------------------------------------------------------------- Creating a new instance of org.ph.javaee.training1.CallerClassA... Exception in thread "main" java.lang.NoClassDefFoundError: org/ph/javaee/training1/ReferencingClassA at org.ph.javaee.training1.CallerClassA.doSomething(CallerClassA.java:25) at org.ph.javaee.training1.NoClassDefFoundErrorSimulator.main(NoClassDefFoundErrorSimulator.java:28) Caused by: java.lang.ClassNotFoundException: org.ph.javaee.training1.ReferencingClassA at java.net.URLClassLoader$1.run(Unknown Source) at java.net.URLClassLoader$1.run(Unknown Source) at java.security.AccessController.doPrivileged(Native Method) at java.net.URLClassLoader.findClass(Unknown Source) at java.lang.ClassLoader.loadClass(Unknown Source) at sun.misc.Launcher$AppClassLoader.loadClass(Unknown Source) at java.lang.ClassLoader.loadClass(Unknown Source) ... 2 more What happened? The removal of the ReferencingClassA.jar, containing ReferencingClassA, did prevent the current class loader to locate this referencing Java class at runtime leading to ClassNotFoundException and NoClassDefFoundError. This is the typical Exception that you will get if you omit JAR file(s) from your Java start-up classpath or within an EAR / WAR for Java EE related applications. ClassLoader view Now let’s review the ClassLoader chain so you can properly understand this problem case. As you saw from the Java program output logging, the following Java ClassLoaders were found: Classloading of org.ph.javaee.training1.CallerClassA in progress... ----------------------------------------------------------------- sun.misc.Launcher$ExtClassLoader@17c1e333 --- delegation --- sun.misc.Launcher$AppClassLoader@214c4ac9 **Current ClassLoader** ----------------------------------------------------------------- ** Please note that the Java bootstrap class loader is responsible to load the core JDK classes and is written in native code ** ## sun.misc.Launcher$AppClassLoader This is the system class loader responsible to load our application code found from the Java classpath specified at start-up. ##sun.misc.Launcher$ExtClassLoader This is the extension class loader responsible to load code in the extensions directories (/lib/ext, or any other directory specified by the java.ext.dirs system property). As you can see from the Java program logging output, the extension class loader is the actual super parent of the system class loader. Our sample Java program was loaded at the system class loader level. Please note that this class loader chain is very simple for this problem case since we did not create child class loaders at this point. This will be covered in future articles. Recommendations and resolution strategies Now find below my recommendations and resolution strategies for NoClassDefFoundError problem case 1: - Review the java.lang.NoClassDefFoundError error and identify the missing Java class - Verify and locate the missing Java class from your compile / build environment - Determine if the missing Java class is from your application code, third part API or even the Java EE container itself. Verify where the missing JAR file(s) is / are expected to be found - Once found, verify your runtime environment Java classpath for any typo or missing JAR file(s) - If the problem is triggered from a Java EE application, perform the same above steps but verify the packaging of your EAR / WAR file for missing JAR and other library file dependencies such as MANIFEST Please feel free to post any question or comment. The part 3 will be available shortly.

This article is part 4 of our Thread Dump analysis series which will provide you with an overview of what is a JVM Thread Dump for the IBM VM and the different Threads and data points that you will find. As you will see and learn, the IBM VM Thread Dump format is different but provides even more out-of-the-box troubleshooting data. At this point, you should know how Threads interact with the Java EE container and what a Thread Dump is. Before we go any further in the deep dive analysis patterns, you also need to understand the IBM VM Thread Dump format since this is the typical Thread Dump data to expect when using IBM WAS on IBM VM. IBM VM Thread Dump breakdown overview In order for you to better understand, find below a diagram showing you a visual breakdown of an IBM 1.6 VM Thread Dump and its common data points found: As you can, there are extra runtime data that you will not find from a HotSpot VM Thread Dump. Please keep in mind that you may not need to review all these data points but you still need to understand what data is available depending of your problem case. The rest of the article will cover each Thread Dump portion in more detail. # Thread Dump generation event The first portion provides you with detail on how this Thread Dump was generated. IBM Thread Dump can be generated as a result of a “signal 3” or “user” e.g. kill -3 or automatically as a result of severe JVM conditions such as an OutOfMemoryError. 0SECTION TITLE subcomponent dump routine NULL =============================== 1TISIGINFO Dump Event "user" (00004000) received 1TIDATETIME Date: 2012/03/12 at 20:52:13 1TIFILENAME Javacore filename: /apps/wl11g/domains/app/javacore.20120312.205205.1949928.0004.txt 1TIREQFLAGS Request Flags: 0x81 (exclusive+preempt) 1TIPREPSTATE Prep State: 0x4 (exclusive_vm_access) 0SECTION TITLE subcomponent dump routine NULL =============================== 1TISIGINFO OUTOFMEMORY received 1TIDATETIME Date: 2012/06/01 at 09:52:12 1TIFILENAME Javacore filename: /usr/WebSphere/AppServer/javacore311328.1338524532.txt # HW and OS environment detail The next section provides you with some detail on the current hardware and OS that this IBM VM is running from: 0SECTION GPINFO subcomponent dump routine NULL ================================ 2XHOSLEVEL OS Level : AIX 5.3 2XHCPUS Processors - 3XHCPUARCH Architecture : ppc64 3XHNUMCPUS How Many : 6 3XHNUMASUP NUMA is either not supported or has been disabled by user # JRE detail and Java start-up arguments This section is very useful as it provides you with a full view on your JRE major version and patch level along with all JVM start-up arguments. 0SECTION ENVINFO subcomponent dump routine NULL ================================= 1CIJAVAVERSION JRE 1.6.0 IBM J9 2.4 AIX ppc64-64 build jvmap6460sr9-20101124_69295 1CIVMVERSION VM build 20101124_069295 1CIJITVERSION JIT enabled, AOT enabled - r9_20101028_17488ifx2 1CIGCVERSION GC - 20101027_AA 1CIRUNNINGAS Running as a standalone JVM ………………………………………………………………………………………… # User and environment variables This section provides you with a listing of current user and environment variables such as File Descriptor limit. 1CIUSERLIMITS User Limits (in bytes except for NOFILE and NPROC) NULL ------------------------------------------------------------------------ NULL type soft limit hard limit 2CIUSERLIMIT RLIMIT_AS unlimited unlimited 2CIUSERLIMIT RLIMIT_CORE 1073741312 unlimited 2CIUSERLIMIT RLIMIT_CPU unlimited unlimited 2CIUSERLIMIT RLIMIT_DATA unlimited unlimited 2CIUSERLIMIT RLIMIT_FSIZE unlimited unlimited 2CIUSERLIMIT RLIMIT_NOFILE 4096 4096 2CIUSERLIMIT RLIMIT_RSS 33554432 unlimited 2CIUSERLIMIT RLIMIT_STACK 33554432 4294967296 # Java Heap detail and GC history Similar to HotSpot VM 1.6+, IBM VM Thread Dump also contains information on the Java Heap capacity and utilization along with memory segments allocated for each memory space of the Java process. Please keep in mind that deeper Java Heap analysis will require you to analyze the Heap Dump binary snapshot as per below tutorial. http://javaeesupportpatterns.blogspot.com/2011/02/ibm-sdk-heap-dump-httpsession-footprint.htm Finally, a history of the garbage collection process is also present. 0SECTION MEMINFO subcomponent dump routine NULL ================================= 1STHEAPFREE Bytes of Heap Space Free: 51104BC8 1STHEAPALLOC Bytes of Heap Space Allocated: 80000000 1STSEGTYPE Internal Memory ………………………………………………………………………………………… 1STSEGTYPE Object Memory ………………………………………………………………………………………… 1STSEGTYPE Class Memory ………………………………………………………………………………………… 1STSEGTYPE JIT Code Cache ………………………………………………………………………………………… 1STSEGTYPE JIT Data Cache ………………………………………………………………………………………… STGCHTYPE GC History 3STHSTTYPE 00:52:07:523048405 GMT j9mm.51 - SystemGC end: newspace=466136480/483183616 oldspace=899251600/1610612736 loa=80530432/80530432 3STHSTTYPE 00:52:07:523046694 GMT j9mm.139 - Reference count end: weak=40149 soft=87504 phantom=33 threshold=17 maxThreshold=32 3STHSTTYPE 00:52:07:522164027 GMT j9mm.91 - GlobalGC end: workstackoverflow=0 overflowcount=0 weakrefs=40149 soft=87504 threshold=17 phantom=33 finalizers=4947 newspace=466136480/483183616 oldspace=899251600/1610612736 loa=80530432/80530432 3STHSTTYPE 00:52:07:522152764 GMT j9mm.90 - GlobalGC collect complete # Java and JVM object monitor lock and deadlock detail This Thread Dump portion is very important. Quite often Thread problems involve Threads waiting between each other due to locks on particular Object monitors e.g. Thread B waiting to acquire a lock on Object monitor held by Thread A. Deadlock conditions can also be triggered from time to time; especially for non-Thread safe implementations. The IBM VM Thread Dump provides a separate section where you can analyze lock(s) held by each Thread including waiting chain(s) e.g. Many Threads waiting to acquire the same Object monitor lock. 0SECTION LOCKS subcomponent dump routine NULL =============================== NULL 1LKPOOLINFO Monitor pool info: 2LKPOOLTOTAL Current total number of monitors: 1034 NULL 1LKMONPOOLDUMP Monitor Pool Dump (flat & inflated object-monitors): 2LKMONINUSE sys_mon_t:0x0000000115B53060 infl_mon_t: 0x0000000115B530A0: 3LKMONOBJECT java/util/Timer$TimerImpl@0x0700000000C92AA0/0x0700000000C92AB8: 3LKNOTIFYQ Waiting to be notified: 3LKWAITNOTIFY "Thread-7" (0x0000000114CAB400) ………………………………………………………………………… ## Threads waiting chain 2LKMONINUSE sys_mon_t:0x000000012462FE00 infl_mon_t: 0x000000012462FE40: 3LKMONOBJECT com/inc/server/app/Request@0x07000000142ADF30/0x07000000142ADF48: owner "Thread-30" (0x000000012537F300), entry count 1 3LKNOTIFYQ Waiting to be notified: 3LKWAITNOTIFY "Thread-26" (0x0000000125221F00) 3LKWAITNOTIFY "Thread-27" (0x0000000125252000) 3LKWAITNOTIFY "Thread-28" (0x000000012527B800) 3LKWAITNOTIFY "Thread-29" (0x00000001252DDA00) 3LKWAITNOTIFY "Thread-31" (0x0000000125386200) 3LKWAITNOTIFY "Thread-32" (0x0000000125423600) 3LKWAITNOTIFY "Thread-33" (0x000000012548C500) 3LKWAITNOTIFY "Thread-34" (0x00000001255D6000) 3LKWAITNOTIFY "Thread-35" (0x00000001255F7900) ………………………………………………………………………… # Java EE middleware, third party & custom application Threads Similar to the HotSpot VM Thread Dump format, this portion is the core of the Thread Dump and where you will typically spend most of your analysis time. The number of Threads found will depend on your middleware software that you use, third party libraries (that might have its own Threads) and your application (if creating any custom Thread, which is generally not a best practice). The following Thread in the example below is in BLOCK state which typically means it is waiting to acquire a lock on an Object monitor. You will need to search in the earlier section and determine which Thread is holding the lock so you can pinpoint the root cause. 3XMTHREADINFO "[STUCK] ExecuteThread: '162' for queue: 'weblogic.kernel.Default (self-tuning)'" J9VMThread:0x000000013ACF0800, j9thread_t:0x000000013AC88B20, java/lang/Thread:0x070000001F945798, state:B, prio=1 3XMTHREADINFO1 (native thread ID:0x1AD0F3, native priority:0x1, native policy:UNKNOWN) 3XMTHREADINFO3 Java callstack: 4XESTACKTRACE at org/springframework/jms/connection/SingleConnectionFactory.createConnection(SingleConnectionFactory.java:207(Compiled Code)) 4XESTACKTRACE at org/springframework/jms/connection/SingleConnectionFactory.createQueueConnection(SingleConnectionFactory.java:222(Compiled Code)) 4XESTACKTRACE at org/springframework/jms/core/JmsTemplate102.createConnection(JmsTemplate102.java:169(Compiled Code)) 4XESTACKTRACE at org/springframework/jms/core/JmsTemplate.execute(JmsTemplate.java:418(Compiled Code)) 4XESTACKTRACE at org/springframework/jms/core/JmsTemplate.send(JmsTemplate.java:475(Compiled Code)) 4XESTACKTRACE at org/springframework/jms/core/JmsTemplate.send(JmsTemplate.java:467(Compiled Code)) ………………………………………………………………………………………………………… # JVM class loader summary Finally, the last section of the IBM VM Thread Dump provides you with a detailed class loader summary. This is very crucial data when dealing with Class Loader related issues and leaks. You will find the number and type of loaded Classes for each active Class loader in the running JVM. I suggest that you review the following case study for a complete tutorial on how to pinpoint root cause for this type of issues when using IBM VM. http://javaeesupportpatterns.blogspot.com/2011/04/class-loader-memory-leak-debugging.html 0SECTION CLASSES subcomponent dump routine NULL ================================= 1CLTEXTCLLOS Classloader summaries 1CLTEXTCLLSS 12345678: 1=primordial,2=extension,3=shareable,4=middleware,5=system,6=trusted,7=application,8=delegating 2CLTEXTCLLOADER p---st-- Loader *System*(0x0700000000878898) 3CLNMBRLOADEDLIB Number of loaded libraries 6 3CLNMBRLOADEDCL Number of loaded classes 3721 2CLTEXTCLLOADER -x--st-- Loader sun/misc/Launcher$ExtClassLoader(0x0700000000AE8F40), Parent *none*(0x0000000000000000) 3CLNMBRLOADEDLIB Number of loaded libraries 0 3CLNMBRLOADEDCL Number of loaded classes 91 2CLTEXTCLLOADER -----ta- Loader sun/misc/Launcher$AppClassLoader(0x07000000008786D0), Parent sun/misc/Launcher$ExtClassLoader(0x0700000000AE8F40) 3CLNMBRLOADEDLIB Number of loaded libraries 3 3CLNMBRLOADEDCL Number of loaded classes 15178 …………………………………………………………………………………………… I hope this article has helped to understand the basic view of an IBM VM Thread Dump. The next article (part 5) will provide you with a tutorial on how to analyze a JVM Thread Dump via a step by step tutorial and technique I have used over the last 10 years. Please feel free to post any comment and question.

This article will describe the complete root cause analysis of a recent Java deadlock problem observed from a Weblogic 11g production system running on the IBM JVM 1.6.This case study will also demonstrate the importance of mastering Thread Dump analysis skills; including for the IBM JVM Thread Dump format. Environment specification Java EE server: Oracle Weblogic Server 11g & Spring 2.0 OS: AIX 5.3 Java VM: IBM JRE 1.6.0 Platform type: Portal & ordering application Monitoring and troubleshooting tools JVM Thread Dump (IBM JVM format) Compuware Server Vantage (Weblogic JMX monitoring & alerting) Problem overview A major stuck Threads problem was observed & reported from Compuware Server Vantage and affecting 2 of our Weblogic 11g production managed servers causing application impact and timeout conditions from our end users. 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? MEDIUM (only 2 managed servers / JVM affected out of 16) · Recent change of the affected platform? Yes (new JMS related asynchronous component) · Any recent traffic increase to the affected platform? No · How does this problem manifest itself? A sudden increase of Threads was observed leading to rapid Thread depletion · Did a Weblogic managed server restart resolve the problem? Yes, but problem is returning after few hours (unpredictable & intermittent pattern) - Conclusion #1: The problem is related to an intermittent stuck Threads behaviour affecting only a few Weblogic managed servers at the time - Conclusion #2: Since problem is intermittent, a global root cause such as a non-responsive downstream system is not likely Thread Dump analysis – first pass The first thing to do when dealing with stuck Thread problems is to generate a JVM Thread Dump. This is a golden rule regardless of your environment specifications & problem context. A JVM Thread Dump snapshot provides you with crucial information about the active Threads and what type of processing / tasks they are performing at that time. Now back to our case study, an IBM JVM Thread Dump (javacore.xyz format) was generated which did reveal the following Java Thread deadlock condition below: 1LKDEADLOCK Deadlock detected !!! NULL --------------------- NULL 2LKDEADLOCKTHR Thread "[STUCK] ExecuteThread: '8' for queue: 'weblogic.kernel.Default (self-tuning)'" (0x000000012CC08B00) 3LKDEADLOCKWTR is waiting for: 4LKDEADLOCKMON sys_mon_t:0x0000000126171DF8 infl_mon_t: 0x0000000126171E38: 4LKDEADLOCKOBJ weblogic/jms/frontend/FESession@0x07000000198048C0/0x07000000198048D8: 3LKDEADLOCKOWN which is owned by: 2LKDEADLOCKTHR Thread "[STUCK] ExecuteThread: '10' for queue: 'weblogic.kernel.Default (self-tuning)'" (0x000000012E560500) 3LKDEADLOCKWTR which is waiting for: 4LKDEADLOCKMON sys_mon_t:0x000000012884CD60 infl_mon_t: 0x000000012884CDA0: 4LKDEADLOCKOBJ weblogic/jms/frontend/FEConnection@0x0700000019822F08/0x0700000019822F20: 3LKDEADLOCKOWN which is owned by: 2LKDEADLOCKTHR Thread "[STUCK] ExecuteThread: '8' for queue: 'weblogic.kernel.Default (self-tuning)'" (0x000000012CC08B00) This deadlock situation can be translated as per below: - Weblogic Thread #8 is waiting to acquire an Object monitor lock owned by Weblogic Thread #10 - Weblogic Thread #10 is waiting to acquire an Object monitor lock owned by Weblogic Thread #8 Conclusion: both Weblogic Threads #8 & #10 are waiting on each other; forever! Now before going any deeper in this root cause analysis, let me provide you a high level overview on Java Thread deadlocks. Java Thread deadlock overview Most of you are probably familiar with Java Thread deadlock principles but did you really experience a true deadlock problem? From my experience, true Java deadlocks are rare and I have only seen ~5 occurrences over the last 10 years. The reason is that most stuck Threads related problems are due to Thread hanging conditions (waiting on remote IO call etc.) but not involved in a true deadlock condition with other Thread(s). A Java Thread deadlock is a situation for example where Thread A is waiting to acquire an Object monitor lock held by Thread B which is itself waiting to acquire an Object monitor lock held by Thread A. Both these Threads will wait for each other forever. This situation can be visualized as per below diagram: Thread deadlock is confirmed…now what can you do? Once the deadlock is confirmed (most JVM Thread Dump implementations will highlight it for you), the next step is to perform a deeper dive analysis by reviewing each Thread involved in the deadlock situation along with their current task & wait condition.Find below the partial Thread Stack Trace from our problem case for each Thread involved in the deadlock condition: ** Please note that the real application Java package name was renamed for confidentiality purposes ** Weblogic Thread #8 "[STUCK] ExecuteThread: '8' for queue: 'weblogic.kernel.Default (self-tuning)'" J9VMThread:0x000000012CC08B00, j9thread_t:0x00000001299E5100, java/lang/Thread:0x070000001D72EE00, state:B, prio=1 (native thread ID:0x111200F, native priority:0x1, native policy:UNKNOWN) Java callstack: at weblogic/jms/frontend/FEConnection.stop(FEConnection.java:671(Compiled Code)) at weblogic/jms/frontend/FEConnection.invoke(FEConnection.java:1685(Compiled Code)) at weblogic/messaging/dispatcher/Request.wrappedFiniteStateMachine(Request.java:961(Compiled Code)) at weblogic/messaging/dispatcher/DispatcherImpl.syncRequest(DispatcherImpl.java:184(Compiled Code)) at weblogic/messaging/dispatcher/DispatcherImpl.dispatchSync(DispatcherImpl.java:212(Compiled Code)) at weblogic/jms/dispatcher/DispatcherAdapter.dispatchSync(DispatcherAdapter.java:43(Compiled Code)) at weblogic/jms/client/JMSConnection.stop(JMSConnection.java:863(Compiled Code)) at weblogic/jms/client/WLConnectionImpl.stop(WLConnectionImpl.java:843) at org/springframework/jms/connection/SingleConnectionFactory.closeConnection(SingleConnectionFactory.java:342) at org/springframework/jms/connection/SingleConnectionFactory.resetConnection(SingleConnectionFactory.java:296) at org/app/JMSReceiver.receive() …………………………………………………………………… Weblogic Thread #10 "[STUCK] ExecuteThread: '10' for queue: 'weblogic.kernel.Default (self-tuning)'" J9VMThread:0x000000012E560500, j9thread_t:0x000000012E35BCE0, java/lang/Thread:0x070000001ECA9200, state:B, prio=1 (native thread ID:0x4FA027, native priority:0x1, native policy:UNKNOWN) Java callstack: at weblogic/jms/frontend/FEConnection.getPeerVersion(FEConnection.java:1381(Compiled Code)) at weblogic/jms/frontend/FESession.setUpBackEndSession(FESession.java:755(Compiled Code)) at weblogic/jms/frontend/FESession.consumerCreate(FESession.java:1025(Compiled Code)) at weblogic/jms/frontend/FESession.invoke(FESession.java:2995(Compiled Code)) at weblogic/messaging/dispatcher/Request.wrappedFiniteStateMachine(Request.java:961(Compiled Code)) at weblogic/messaging/dispatcher/DispatcherImpl.syncRequest(DispatcherImpl.java:184(Compiled Code)) at weblogic/messaging/dispatcher/DispatcherImpl.dispatchSync(DispatcherImpl.java:212(Compiled Code)) at weblogic/jms/dispatcher/DispatcherAdapter.dispatchSync(DispatcherAdapter.java:43(Compiled Code)) at weblogic/jms/client/JMSSession.consumerCreate(JMSSession.java:2982(Compiled Code)) at weblogic/jms/client/JMSSession.setupConsumer(JMSSession.java:2749(Compiled Code)) at weblogic/jms/client/JMSSession.createConsumer(JMSSession.java:2691(Compiled Code)) at weblogic/jms/client/JMSSession.createReceiver(JMSSession.java:2596(Compiled Code)) at weblogic/jms/client/WLSessionImpl.createReceiver(WLSessionImpl.java:991(Compiled Code)) at org/springframework/jms/core/JmsTemplate102.createConsumer(JmsTemplate102.java:204(Compiled Code)) at org/springframework/jms/core/JmsTemplate.doReceive(JmsTemplate.java:676(Compiled Code)) at org/springframework/jms/core/JmsTemplate$10.doInJms(JmsTemplate.java:652(Compiled Code)) at org/springframework/jms/core/JmsTemplate.execute(JmsTemplate.java:412(Compiled Code)) at org/springframework/jms/core/JmsTemplate.receiveSelected(JmsTemplate.java:650(Compiled Code)) at org/springframework/jms/core/JmsTemplate.receiveSelected(JmsTemplate.java:641(Compiled Code)) at org/app/JMSReceiver.receive() …………………………………………………………… As you can see in the above Thread Strack Traces, such deadlock did originate from our application code which is using the Spring framework API for the JMS consumer implementation (very useful when not using MDB’s). The Stack Traces are quite interesting and revealing that both Threads are in a race condition against the same Weblogic JMS consumer session / connection and leading to a deadlock situation: - Weblogic Thread #8 is attempting to reset and close the current JMS connection - Weblogic Thread #10 is attempting to use the same JMS Connection / Session in order to create a new JMS consumer - Thread deadlock is triggered! Root cause: non Thread safe Spring JMS SingleConnectionFactory implementation A code review and a quick research from Spring JIRA bug database did reveal the following Thread safe defect below with a perfect correlation with the above analysis: # SingleConnectionFactory's resetConnection is causing deadlocks with underlying OracleAQ's JMS connection https://jira.springsource.org/browse/SPR-5987 A patch for Spring SingleConnectionFactory was released back in 2009 which did involve adding proper synchronized{} block in order to prevent Thread deadlock in the event of a JMS Connection reset operation: synchronized (connectionMonitor) { //if condition added to avoid possible deadlocks when trying to reset the target connection if (!started) { this.target.start(); started = true; } } Solution Our team is currently planning to integrate this Spring patch in to our production environment shortly. The initial tests performed in our test environment are positive. Conclusion I hope this case study has helped understand a real-life Java Thread deadlock problem and how proper Thread Dump analysis skills can allow you to quickly pinpoint the root cause of stuck Thread related problems at the code level. Please don’t hesitate to post any comment or question.

This article will provide you with a tutorial on how you can quickly pinpoint the Java Thread contributors to a high CPU problem on the Windows OS. Windows, like other OS such as Linux, Solaris & AIX allow you to monitor the CPU utilization at the process level but also for individual Thread executing a task within a process. For this tutorial, we created a simple Java program that will allow you to learn this technique in a step by step manner. Troubleshooting tools The following tools will be used below for this tutorial: - Windows Process Explorer (to pinpoint high CPU Thread contributors) - JVM Thread Dump (for Thread correlation and root cause analysis at code level) High CPU simulator Java program The simple program below is simply looping and creating new String objects. It will allow us to perform this CPU per Thread analysis. I recommend that you import it in an IDE of your choice e.g. Eclipse and run it from there. You should observe an increase of CPU on your Windows machine as soon as you execute it. package org.ph.javaee.tool.cpu; /** * HighCPUSimulator * @author Pierre-Hugues Charbonneau * http://javaeesupportpatterns.blogspot.com * */ public class HighCPUSimulator { private final static int NB_ITERATIONS = 500000000; // ~1 KB data footprint private final static String DATA_PREFIX = "datadatadatadatadatadatadatadatadatadatadatadatadatadatadatadatadatadatadatadatadatadatadatadatadatadatadatadatadatadatadatadatadatadatadatadatadatadatadatadatadatadatadatadatadatadatadatadatadatadatadatadatadatadatadatadatadatadatadatadatadatadatadatadatadatadatadatadatadatadatadatadatadatadatadatadatadatadatadatadatadatadatadatadatadatadatadatadatadatadatadatadatadatadatadatadatadatadatadatadatadatadatadatadatadatadatadatadatadatadatadatadatadatadatadatadatadatadatadata"; /** * @param args */ public static void main(String[] args) { System.out.println("HIGH CPU 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++) { // Perform some String manipulations to slowdown and expose looping process... String data = DATA_PREFIX + i; } } catch (Throwable any) { System.out.println("Unexpected Exception! " + any.getMessage() + " [" + any + "]"); } System.out.println("HighCPUSimulator done!"); } } Step #1 – Launch Process Explorer The Process Explorer tool visually shows the CPU usage dynamically. It is good for live analysis. If you need historical data on CPU per Thread then you can also use Windows perfmon with % Processor Time & Thread Id data counters. You can download Process Explorer from the link below: http://technet.microsoft.com/en-us/sysinternals/bb896653 In our example, you can see that the Eclipse javaw.exe process is now using ~25% of total CPU utilization following the execution of our sample program. Step #2 – Launch Process Explorer Threads view The next step is to display the Threads view of the javaw.exe process. Simply right click on the javaw.exe process and select Properties. The Threads view will be opened as per below snapshot: - The first column is the Thread Id (decimal format) - The second column is the CPU utilization % used by each Thread - The third column is also another counter indicating if Thread is running on the CPU In our example, we can see our primary culprit is Thread Id #5996 using ~ 25% of CPU. Step #3 – Generate a JVM Thread Dump At this point, Process Explorer will no longer be useful. The goal was to pinpoint one or multiple Java Threads consuming most of the Java process CPU utilization which is what we achieved. In order to go the next level in your analysis you will need to capture a JVM Thread Dump. This will allow you to correlate the Thread Id with the Thread Stack Trace so you can pinpoint that type of processing is consuming such high CPU. JVM Thread Dump generation can be done in a few manners. If you are using JRockit VM you can simply use the jrcmd tool as per below example: Once you have the Thread Dump data, simply search for the Thread Id and locate the Thread Stack Trace that you are interested in. For our example, the Thread “Main Thread” which was fired from Eclipse got exposed as the primary culprit which is exactly what we wanted to demonstrate. "Main Thread" id=1 idx=0x4 tid=5996 prio=5 alive, native_blocked at org/ph/javaee/tool/cpu/HighCPUSimulator.main (HighCPUSimulator.java:31) at jrockit/vm/RNI.c2java(IIIII)V(Native Method) -- end of trace Step #4 – Analyze the culprit Thread(s) Stack Trace and determine root cause At this point you should have everything that you need to move forward with the root cause analysis. You will need to review each Thread Stack Trace and determine what type of problem you are dealing with. That final step is typically where you will spend most of your time and problem can be simple such as infinite looping or complex such as garbage collection related problems. In our example, the Thread Dump did reveal the high CPU originates from our sample Java program around line 31. As expected, it did reveal the looping condition that we engineered on purpose for this tutorial. for (int i = 0; i < NB_ITERATIONS; i++) { // Perform some String manipulations to slowdown and expose looping process... String data = DATA_PREFIX + i; } I hope this tutorial has helped you understand how you can analyze and help pinpoint root cause of Java CPU problems on Windows OS. Please stay tuned for more updates, the next article will provide you with a Java CPU troubleshooting guide including how to tackle that last analysis step along with common problem patterns.