/ April 2012 ~ Java EE Support Patterns

4.25.2012

Java Thread CPU analysis on Windows

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.

Tutorials are also available from some other OS as per below:
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.

4.09.2012

JRockit jrcmd tutorial

This article will provide you an overview and tutorial on how you can perform an initial analysis and problem isolation of a JRockit Java Heap problem using the jrcmd tool. A deeper analysis and tutorial using JRockit Mission Control and Heap Dump analysis (JRockit version R28+ only) will be covered in future articles.

For a quick overview of the JRockit Java Heap Space, please consult the article below:

JRCMD tool overview

jrcmd is a free tool that is available out-of-the-box in the JRockit binaries. It allows you generate and collect crucial data from your runtime JRockit VM such as:

-        Java process memory space breakdown (Java Heap vs Native memory spaces)
-        Java Heap diagnostic (histogram)
-        Java loaded classes
-        On-demand JRockit Heap Dump generation (version R28+ only)
-        Thread Dump generation
-        More…

For this article, we created a simple Java program leaking internally. We will use this program to demonstrate how you can leverage jrcmd to perform your initial analysis.

Sample Java memory leak program

This simple Java program is simply adding String data to a static HashMap and slowly leaking to the point of the JVM running out of Java Heap memory. This program will allow you to visualize a slowly growing Java Heap leak via JRockit jrcmd. Please note that a Java Heap size of 128 MB (-Xms128m –Xmx128m) was used for this example.

/**
 * JavaHeapLeakSimulator
 * @author Pierre-Hugues Charbonneau
 * http://javaeesupportpatterns.blogspot.com
 */
public class JavaHeapLeakSimulator {

        private final static int NB_ITERATIONS = 500000000;

        // ~1 KB data footprint
        private final static String LEAKING_DATA_PREFIX = "datadatadatadatadatadatadatadatadatadatadatadatadatadatadatadatadatadatadatadatadatadatadatadatadatadatadatadatadatadatadatadatadatadatadatadatadatadatadatadatadatadatadatadatadatadatadatadatadatadatadatadatadatadatadatadatadatadatadatadatadatadatadatadatadatadatadatadatadatadatadatadatadatadatadatadatadatadatadatadatadatadatadatadatadatadatadatadatadatadatadatadatadatadatadatadatadatadatadatadatadatadatadatadatadatadatadatadatadatadatadatadatadatadatadatadatadatadatadata";

        // Map used to stored our leaking String instances
        private static Map<String, String> leakingMap;

        static {
               leakingMap = new HashMap<String, String>();
        }

        /**
         * @param args
         */
        public static void main(String[] args) {

               System.out.println("Java Heap Leak Simulator 1.0");
               System.out.println("Author: Pierre-Hugues Charbonneau");
               System.out.println("http://javaeesupportpatterns.blogspot.com/");

               try {

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

                              String data = LEAKING_DATA_PREFIX + i;
                             
                              // Add data to our leaking Map data structure...
                              leakingMap.put(data, data);
                             
                              // Slowdown the Java program so we can monitor the leak before the OutOfMemoryError condition
                              Thread.sleep(1);
                       }

               } catch (Throwable any) {
                       if (any instanceof java.lang.OutOfMemoryError) {
                              System.out.println("OutOfMemoryError triggered! "
                                             + any.getMessage() + " [" + any + "]");

                       } else {
                              System.out.println("Unexpected Exception! " + any.getMessage()
                                             + " [" + any + "]");
                       }
               }

               System.out.println("JavaHeapLeakSimulator done!");
        }
}


JRCMD - initial execution

JRCMD can be executed from the local server hosting the JVM that you want to monitor or remotely via JRockit Mission Control. The executable is located within the JRockit JDK that you are using:

<JRockit_JDK_HOME>/bin/jrcmd

The default jrcmd execution will return the list of active JRockit Java process Id that you can monitor:

C:\Apps\Weblogic1035\jrockit_160_24_D1.1.2-4\bin>jrcmd
5360 org.ph.javaee.tool.oom.JavaHeapLeakSimulator
5952
6852 jrockit.tools.jrcmd.JrCmd

JRCMD - Java Heap monitoring

The next step is to start monitoring the Java Heap memory usage and histogram. A Java Heap histogram is a snapshot of the biggest pools of Java Class instances. This allow you to pinpoint the leaking data type. Ple

You can either chose between print_object_summary (quick summary) or heap_diagnostics (complete breakdown).

C:\Apps\Weblogic1035\jrockit_160_24_D1.1.2-4\bin>jrcmd 5360 heap_diagnostics

Invoked from diagnosticcommand
======== BEGIN OF HEAPDIAGNOSTIC =========================

Total memory in system: 8465022976 bytes
Available physical memory in system: 5279170560 bytes
-Xmx (maximal heap size) is 134217728 bytes
Heapsize: 134217728 bytes
Free heap-memory: 123592704 bytes


--------- Detailed Heap Statistics: ---------
90.9% 3948k     5468  +3948k [C
 3.0% 128k     5490   +128k java/lang/String
 2.1% 92k     3941    +92k java/util/HashMap$Entry
 1.2% 50k      461    +50k java/lang/Class
 0.8% 35k       21    +35k [Ljava/util/HashMap$Entry;
 0.6% 24k        7    +24k [B
 0.3% 15k      305    +15k [Ljava/lang/Object;
 0.3% 14k      260    +14k java/net/URL
 0.2% 6k      213     +6k java/util/LinkedHashMap$Entry
 0.1% 4k      211     +4k java/io/ExpiringCache$Entry
 0.1% 2k        4     +2k [Ljrockit/vm/FCECache$FCE;
 0.0% 1k       50     +1k [Ljava/lang/String;
 0.0% 1k       10     +1k java/lang/Thread
 0.0% 1k       61     +1k java/util/Hashtable$Entry
 0.0% 1k        7     +1k [I
 0.0% 0k       19     +0k java/util/HashMap
 0.0% 0k       19     +0k java/lang/ref/WeakReference
 0.0% 0k        7     +0k [Ljava/util/Hashtable$Entry;
 0.0% 0k       19     +0k java/util/Locale
 0.0% 0k       11     +0k java/lang/ref/SoftReference
 0.0% 0k        1     +0k [S
…………………………………………………

- The first column correponds to the Class object type contribution to the Java Heap footprint in %
- The second column correponds to the Class object type memory footprint in K
- The third column correponds to the # of Class instances of a particular type
- The fourth column correponds to the delta - / + memory footprint of a particular type

As you can see from the above snapshot, the biggest data type is [C (char in our case) & java.lang.String. In order to see which data types are leaking, you will need to generate several snapshots. The frequency will depend of the leaking rate. In our example, find below another snapshot taken after 5 minutes:

# After 5 minutes
--------- Detailed Heap Statistics: ---------
93.9% 26169k    28746 +12032k [C
 2.4% 674k    28768   +295k java/lang/String
 2.3% 637k    27219   +295k java/util/HashMap$Entry
 0.9% 259k       21   +128k [Ljava/util/HashMap$Entry;
 0.2% 50k      462     +0k java/lang/Class
 0.1% 24k        7     +0k [B

# After 5 more minutes
--------- Detailed Heap Statistics: ---------
94.5% 46978k    50534 +20809k [C
 2.4% 1184k    50556   +510k java/lang/String
 2.3% 1148k    49007   +510k java/util/HashMap$Entry
 0.5% 259k       21     +0k [Ljava/util/HashMap$Entry;
 0.1% 50k      462     +0k java/lang/Class

The third & fourth column are showing a constant increase. As you can see, the leaking data in our case are [C, java.lang.String and java.util.HashMap$Entry which all increased from ~4 MB to 28 MB, 50 MB and growing…

It is easy to pinpoint the leaking data type(s) with this approach but what about the source (root cause) of the leaking data type(s)? This is where jrcmd is no longer useful. Deeper memory leak analysis will require you to use either JRockit Mission Control or Heap Dump analysis (JRockit R28+ only).

A final point, before you can conclude on a true Java Heap leak, please ensure that jrcmd snapshots are taken after at least one Full GC in between the captures (what you are interested in is OldGen leak e.g. Java objects surviving major GC collections). 

JRCMD Thread Dump generation

Thread Dump analysis is crucial for stuck Thread related problems but can also be useful to troubleshoot certain types of Java Heap problem. For example, it can pinpoint the source of a sudden Java Heap increase by exposing the culprit Thread(s) allocating a large amount of memory on the Java Heap in a short amount of time. Thread Dump can be generated using jrcmd print_threads option.

** Thread Dump captured from our sample Java program after removing the Thread.sleep() and increasing the Java Heap capacity **

C:\Apps\Weblogic1035\jrockit_160_24_D1.1.2-4\bin>jrcmd 5808 print_threads
5808:

===== FULL THREAD DUMP ===============
Mon Apr 09 09:08:08 2012
Oracle JRockit(R) R28.1.3-11-141760-1.6.0_24-20110301-1429-windows-ia32

"Main Thread" id=1 idx=0x4 tid=6076 prio=5 alive, native_blocked
    at jrockit/vm/Allocator.getNewTla(II)V(Native Method)
    at jrockit/vm/Allocator.allocObjectOrArray(Allocator.java:354)[optimized]
    at java/util/Arrays.copyOfRange(Arrays.java:3209)[inlined]
    at java/lang/String.<init>(String.java:215)[inlined]
    at java/lang/StringBuilder.toString(StringBuilder.java:430)[optimized]
    at org/ph/javaee/tool/oom/JavaHeapLeakSimulator.main(JavaHeapLeakSimulator.java:38)
    at jrockit/vm/RNI.c2java(IIIII)V(Native Method)
    -- end of trace
……………………………………….

We can see that our sample Java program is creating a lot of java.lang.String objects from the “Main Thread” executing our JavaHeapLeakSimulator program.

Conclusion

I hope this article has helped you understand you can leverage the JRockit jrcmd tool for quick Java Heap analysis. I’m looking forward for your comments and questions.

Future articles will include a deeper JRockit Java Heap and Heap Dump analysis tutorial.