/ Java Thread CPU analysis on Windows ~ 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.

15 comments:

Nice tips, thanks. I think that the process would be pretty inaccurate in case of more complicated CPU utilization issues. But of course a very good starting point this article is. Looking for more articles on this topic...

Thanks anonymous. I will release shorty a Java high CPU troubleshooting guide along with common causes of high CPU of Java EE paltforms.

Thanks.
P-H

nice post !
i generaly use the same tips with windows you can also build a poor man profiler base on on the typeperf command who can give you perfmon access at command line
regards
Cordialement;)
Marc

Should not the TID be converted to HEX before looking at the thread dumps?

Hi anonymous,

I'm glad you ask the question.

It depends of the OS and JVM vendor. In the above combination e.g. Windows + JRockit, the JRockit Thread Dump TID is already converted in decimal format which is why you can correlate it out-of-the-box.

Sun HotSpot & IBM VM on UNIX will require you to convert the decimal to HEXA since native Thread Dump threads TID is in HEXA format.

Regards,
P-H

Hello P-H,

Thank you very much for this useful post! I got a question regarding your example:
In my case, i have a web application deployed under tomcat there i have a lot of thread, do you know how i could know which thread is using a high CPU?

As in my case, my thread dump will not contain only one thread, but much and all will be related to the same java process.


Thanks for ideas,

Abdoul

Hi Abdoul and thanks for your comments,

That CPU analysis approach should be the same for your Tomcat server. You just need to generate a Thread Dump from your primary Tomcat Java process and combine with Windows Process Explorer tool to correlation/identify the high CPU contributors.

You should be able to do a "dry run" so you can be ready to capture detail when you have real activity on your Tomcat server.

Can you please provide detail how you generated Thread Dump from your Tomcat server environment?

If you are using the Oracle(Sun) HotSpot JVM, then you can simply use jstack to generate Thread Dump from the master Java process of your Tomcat server.

Thanks.
P-H

Thank you P-H for your feedback,

I used jstack and jvisualvm GUI to generate two thread dump. In that thread i have a list of thread started by my war app deployed. For example, my tomcat java process is xxxx as in my thread dump file i will have a lot of thread with the same tid ( i guess), how will i know which thread is causing issue.

I could send an example of thread dump on your personnal email and we could discuss. In fact i am a software tester and i have an interest on performance test.

Thanks again,

Abdoul

Hi Abdoul,

Yes please send me the Thread Dump snapshot to my Java EE consulting address: phcharbonneau@hotmail.com

Regards,
P-H

Thanks, it's done.

Regards,
Abdoul

Thanks a lot for this nice and informative post.

In Production, the CPU shot up drastically in one of the application servers. Using the above post, we were able to figure out the thread that was consuming the CPU. It was in the email validation which was using java pattern matching. However, we wanted to kill the thread so that the system comes back to normal. The only way that we knew was to call the stop method, however it has been deprecated and there is a lot of comments that it shouldn't be used.

So, is there any option other than restarting the app server in such scenario?

Thanks
Muku

Hi Muku,

Glad that you were able to pinpoint the culprit Thread. Unfortunatly, the current Java specifications do not offer any safe way to kill a thread on the fly given risk associated with this.

The best solution at this point is to prevent the problem to happen at the first place and fast root cause/discovery (like you did).

For now, a full JVM restart is required to fix/kill this Thread. Then please work on fixing the code to prevent this Java pattern matching code to use that much CPU at the first place.

Regards,
P-H

Hi P-H,

Thanks for the very helpful article. When I run Process Explorer Threads View sorted by highest CPU, I see one thread TID using highest CPU at 15% for one second, and then drops off to 0%. And then another thread TID uses 10% and then drops off to 0%.

How can I take a snapshot of Threads View every second for 30 seconds?

Vous voulez en arriver a quoi ? Votre programme s'execute dans le "main" thread java, alloue par Windows. Comme votre programme est mono threade et loop dans ce thread vous vous attendiez quand meme pas a avoir 0.1% d'utilisation CPU ? Non, vous avez simplement ce que vous avez programme rien d'autre. Ce serait en C++ ou tout autre language, vous auriez le meme resultat. Alors dire "java the culprit" heu oui. Faites du multithread si vous voulez utiliser moins de resources ou faite dormir votre main thread, Windows etant peremptif il va vaquer a d'autres choses durant ce temps. Sinon ben votre programme fait ce que vous lui demander de faire. Si le but de l'article etait de montrer les outils a mettre en oeuvre pour debugger des problemes de performances en Java, il faudrait commencer a utiliser jvisualvm livre avec le jdk.

Hi Johny,

That is correct. The goal of the article was to demonstrate how to breakdown the CPU per Thread using Windows OS, which is a different technique than UNIX base OS.

We created this simple Java program to voluntarily generates excessive CPU so we can correlate the CPU % with the captured JVM thread dump.

A similar but different goal can be achieved via JVisualVM through the CPU sampler but the purpose of using Process Explorer is to give you the exact fact figures e.g. CPU % per Java thread, especially when dealing with multiple concurrent threads within a Java EE container.

Thanks.
P-H

Post a Comment