Identifying which Java Thread is consuming most CPU

I didn’t come up with this. I was shown how to do this by an esteemed college at work.

Introduction

Most (if not all) productive systems doing anything important will use more than 1 java thread. And when something goes crazy and your cpu usage is on 100%, it is hard to identify which thread(s) is/are causing this. Or so I thought. Until someone smarter than me showed me how it can be done. And here I will show you how to do it and you too can amaze your family and friends with your geek skillz.

A Test Application

In order to test this, we need a test application. So I will give you one. It consists of 3 classes:
A HeavyThread class that does something CPU intensive (computing MD5 hashes), a LightThread class that does something not-so-cpu-intensive (counting and sleeping). And a final class to start 1 cpu intensive and several light threads. Here is code for these classes:

import java.security.MessageDigest;
import java.security.NoSuchAlgorithmException;
import java.util.UUID;

/**
 * thread that does some heavy lifting
 *
 * @author srasul
 *
 */
public class HeavyThread implements Runnable {

	private long length;

	public HeavyThread(long length) {
		this.length = length;
		new Thread(this).start();
	}

	@Override
	public void run() {
		while (true) {
			String data = "";

			// make some shit up
			for (int i = 0; i < length; i++) {
				data += UUID.randomUUID().toString();
			}

			MessageDigest digest;
			try {
				digest = MessageDigest.getInstance("MD5");
			} catch (NoSuchAlgorithmException e) {
				throw new RuntimeException(e);
			}

			// hash that shit
			digest.update(data.getBytes());
		}
	}
}

import java.util.Random;

/**
 * thread that does little work. just count & sleep
 *
 * @author srasul
 *
 */
public class LightThread implements Runnable {

	public LightThread() {
		new Thread(this).start();
	}

	@Override
	public void run() {
		Long l = 0l;
		while(true) {
			l++;
			try {
				Thread.sleep(new Random().nextInt(10));
			} catch (InterruptedException e) {
				e.printStackTrace();
			}
			if(l == Long.MAX_VALUE) {
				l = 0l;
			}
		}
	}
}


/**
 * start it all
 *
 * @author srasul
 *
 */
public class StartThreads {

	public static void main(String[] args) {
		// lets start 1 heavy ...
		new HeavyThread(1000);

		// ... and 3 light threads
		new LightThread();
		new LightThread();
		new LightThread();
	}
}

And Finally...

Assuming that you have never seen this code, and all you have a PID of a runaway java process that is running these classes and is consuming 100% CPU.

First lets start the StartThreads class.

$ ls
HeavyThread.java  LightThread.java  StartThreads.java
$ javac *
$ java StartThreads &

At this stage a java process is running should be taking up 100 cpu. In my top i see:

In top press Shift-H which turns on Threads. The man page for top says:

       -H : Threads toggle
            Starts top with the last remembered 'H' state reversed.  When
            this  toggle is On, all individual threads will be displayed.
            Otherwise, top displays a  summation  of  all  threads  in  a
            process.

And now in my top with Threads display turned ON i see:

And I have a java process with PID 28294. Lets get the stack dump of this process using jstack:

$ jstack 28924
2010-11-18 13:05:41
Full thread dump Java HotSpot(TM) 64-Bit Server VM (17.0-b16 mixed mode):

"Attach Listener" daemon prio=10 tid=0x0000000040ecb000 nid=0x7150 waiting on condition [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"DestroyJavaVM" prio=10 tid=0x00007f9a98027800 nid=0x70fd waiting on condition [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"Thread-3" prio=10 tid=0x00007f9a98025800 nid=0x710d waiting on condition [0x00007f9a9d543000]
   java.lang.Thread.State: TIMED_WAITING (sleeping)
	at java.lang.Thread.sleep(Native Method)
	at LightThread.run(LightThread.java:21)
	at java.lang.Thread.run(Thread.java:619)

"Thread-2" prio=10 tid=0x00007f9a98023800 nid=0x710c waiting on condition [0x00007f9a9d644000]
   java.lang.Thread.State: TIMED_WAITING (sleeping)
	at java.lang.Thread.sleep(Native Method)
	at LightThread.run(LightThread.java:21)
	at java.lang.Thread.run(Thread.java:619)

"Thread-1" prio=10 tid=0x00007f9a98021800 nid=0x710b waiting on condition [0x00007f9a9d745000]
   java.lang.Thread.State: TIMED_WAITING (sleeping)
	at java.lang.Thread.sleep(Native Method)
	at LightThread.run(LightThread.java:21)
	at java.lang.Thread.run(Thread.java:619)

"Thread-0" prio=10 tid=0x00007f9a98020000 nid=0x710a runnable [0x00007f9a9d846000]
   java.lang.Thread.State: RUNNABLE
	at sun.security.provider.DigestBase.engineReset(DigestBase.java:139)
	at sun.security.provider.DigestBase.engineUpdate(DigestBase.java:104)
	at java.security.MessageDigest$Delegate.engineUpdate(MessageDigest.java:538)
	at java.security.MessageDigest.update(MessageDigest.java:293)
	at sun.security.provider.SecureRandom.engineNextBytes(SecureRandom.java:197)
	- locked <0x00007f9aa457e400> (a sun.security.provider.SecureRandom)
	at sun.security.provider.NativePRNG$RandomIO.implNextBytes(NativePRNG.java:257)
	- locked <0x00007f9aa457e708> (a java.lang.Object)
	at sun.security.provider.NativePRNG$RandomIO.access$200(NativePRNG.java:108)
	at sun.security.provider.NativePRNG.engineNextBytes(NativePRNG.java:97)
	at java.security.SecureRandom.nextBytes(SecureRandom.java:433)
	- locked <0x00007f9aa4582fc8> (a java.security.SecureRandom)
	at java.util.UUID.randomUUID(UUID.java:162)
	at HeavyThread.run(HeavyThread.java:27)
	at java.lang.Thread.run(Thread.java:619)

"Low Memory Detector" daemon prio=10 tid=0x00007f9a98006800 nid=0x7108 runnable [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"CompilerThread1" daemon prio=10 tid=0x00007f9a98004000 nid=0x7107 waiting on condition [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"CompilerThread0" daemon prio=10 tid=0x00007f9a98001000 nid=0x7106 waiting on condition [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"Signal Dispatcher" daemon prio=10 tid=0x0000000040de4000 nid=0x7105 runnable [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"Finalizer" daemon prio=10 tid=0x0000000040dc4800 nid=0x7104 in Object.wait() [0x00007f9a97ffe000]
   java.lang.Thread.State: WAITING (on object monitor)
	at java.lang.Object.wait(Native Method)
	- waiting on <0x00007f9aa45506b0> (a java.lang.ref.ReferenceQueue$Lock)
	at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:118)
	- locked <0x00007f9aa45506b0> (a java.lang.ref.ReferenceQueue$Lock)
	at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:134)
	at java.lang.ref.Finalizer$FinalizerThread.run(Finalizer.java:159)

"Reference Handler" daemon prio=10 tid=0x0000000040dbd000 nid=0x7103 in Object.wait() [0x00007f9a9de92000]
   java.lang.Thread.State: WAITING (on object monitor)
	at java.lang.Object.wait(Native Method)
	- waiting on <0x00007f9aa4550318> (a java.lang.ref.Reference$Lock)
	at java.lang.Object.wait(Object.java:485)
	at java.lang.ref.Reference$ReferenceHandler.run(Reference.java:116)
	- locked <0x00007f9aa4550318> (a java.lang.ref.Reference$Lock)

"VM Thread" prio=10 tid=0x0000000040db8800 nid=0x7102 runnable 

"GC task thread#0 (ParallelGC)" prio=10 tid=0x0000000040d6e800 nid=0x70fe runnable 

"GC task thread#1 (ParallelGC)" prio=10 tid=0x0000000040d70800 nid=0x70ff runnable 

"GC task thread#2 (ParallelGC)" prio=10 tid=0x0000000040d72000 nid=0x7100 runnable 

"GC task thread#3 (ParallelGC)" prio=10 tid=0x0000000040d74000 nid=0x7101 runnable 

"VM Periodic Task Thread" prio=10 tid=0x00007f9a98011800 nid=0x7109 waiting on condition 

JNI global references: 910

From my top I see that the PID of the top thread is: 28938. And 28938 in HEX is 0x710A. Notice that in the stack dump, each thread has an nid which is in HEX. And it just so happens that 0x710A is the id of the thread:

"Thread-0" prio=10 tid=0x00007f9a98020000 nid=0x710a runnable [0x00007f9a9d846000]
   java.lang.Thread.State: RUNNABLE
	at sun.security.provider.DigestBase.engineReset(DigestBase.java:139)
	at sun.security.provider.DigestBase.engineUpdate(DigestBase.java:104)
	at java.security.MessageDigest$Delegate.engineUpdate(MessageDigest.java:538)
	at java.security.MessageDigest.update(MessageDigest.java:293)
	at sun.security.provider.SecureRandom.engineNextBytes(SecureRandom.java:197)
	- locked <0x00007f9aa457e400> (a sun.security.provider.SecureRandom)
	at sun.security.provider.NativePRNG$RandomIO.implNextBytes(NativePRNG.java:257)
	- locked <0x00007f9aa457e708> (a java.lang.Object)
	at sun.security.provider.NativePRNG$RandomIO.access$200(NativePRNG.java:108)
	at sun.security.provider.NativePRNG.engineNextBytes(NativePRNG.java:97)
	at java.security.SecureRandom.nextBytes(SecureRandom.java:433)
	- locked <0x00007f9aa4582fc8> (a java.security.SecureRandom)
	at java.util.UUID.randomUUID(UUID.java:162)
	at HeavyThread.run(HeavyThread.java:27)
	at java.lang.Thread.run(Thread.java:619)

And so you can confirm that the Thread which is running the HeavyThread class is consuming most cpu.

In read world situations, it will probably be a bunch of threads that consume some portion of CPU and these threads put together will lead to the java process using 100% CPU.

Summary

* run top
* press Shift-H to enable Threads View
* get PID of the thread with highest CPU
* convert PID to HEX
* get stack dump of java process
* in stack dump look for thread with the matching HEX PID.

This entry was posted on Thursday, November 18th, 2010 and is filed under Java. You can follow any responses to this entry through RSS 2.0. You can leave a response, or trackback from your own site.

#1 by Marc-Oliver Ihm on November 19th, 2010

Quote

This is great !
Especially the part about top was new to me. So now I can finally make the connection between CPU-usage und Thread-dumps.

regards, Marc

BTW: As a user of jrockit I have it even easier: jrockit desplays the pids in decimal and not in hex, so I do not need to convert …

#2 by Ittay on January 4th, 2011

Or, you can use topthreads for jconsole: http://lsd.luminis.nl/top-threads-plugin-for-jconsole/

#3 by srasul on January 4th, 2011

jconole needs a jmx socket & connection to the java process. And also a gui. When you dont have these then the top has all the info

#4 by Ashish on August 9th, 2011

This is cool !

I used to this in a slightly different way.

ps -L

This shall print all the Threads. See the Thread that has consumed max time from the column. Convert Thread ID to Hex and finding it in Thread dump is same.

Your tip is even simpler

#5 by Tobias on August 10th, 2011

Great thanks for the ‘top’ part and code examples (;

#6 by Adelar on August 11th, 2011

Very usefull article. Thanks.

#7 by beyonddc on August 11th, 2011

Not a bad idea. May I suggest hprof? it’s a Heap/CPU profiling tool that bundles with with JAVA. It has been available since JAVA 1.5. You should take a look at http://java.sun.com/developer/technicalArticles/Programming/HPROF.html

I have very good luck using it to identify resource hungry JAVA threads.

#8 by srasul on August 11th, 2011

Thanks for that tip. This would work well in development/testing. But once an application is running, say in a production environment, top rules!

#9 by Lolosiger on August 25th, 2011

#10 by Hooliwoli on August 26th, 2011

#11 by Egugieva on August 27th, 2011

#12 by origami_ns on November 3rd, 2011

Very nice post. Thanks for that.

What is the issue if VM thread is consuming 100%, all other thread are quiet.

“VM Thread” prio=10 tid=0x00007f30b804e000 nid=0x360d runnable

#13 by Claudio Miranda on February 15th, 2012

Hi, nice article. I you (and readers) know about top_threads.sh script I created to automate the task to identifying the top java threads.
It identify the OS top threads and print the thread stack trace (from jstack).
http://claudius-alphaworks.googlecode.com/svn/trunk/shell_bin/top_threads.sh

Nomad Labs Code

srasul's snippets of code and thought