How to analyze high cpu usage of a Java program?

Many Java daemons are multi threaded. If some program shows high cpu usage, how will you analyze it? I’m showing the tip based on Linux environment.

1) Detect problemetic thread

Usually linux “top” shows total cpu usage of a process. Therefore we need to separate problematic thread. While running top, press “H” or start top with -H option. Then PID column shows thread id.

2) Map the thread with source code

To detect problematic class, make thread dump of the process.

#kill -3 process_id (Do not use thread id, but use process id)

Now, I’m showing a sample.

<High cpu thread class>

package test;

public class BusyThread implements Runnable {
	private int i = 0;
	@Override
	public void run() {
		System.out.println("BusyThread id : " + Thread.currentThread().getId());
		while(true) {
			i += 1;
			if(i == Integer.MAX_VALUE) {
				i = 0;
			}
		}
	}
}

 

<Idle thread class>

package test;

public class IdleThread implements Runnable {
	private Object lockObject = new Object();
	@Override
	public void run() {
		System.out.println("IdleThread id : " + Thread.currentThread().getId());
		synchronized(this.lockObject) {
			try {
				lockObject.wait();	
			}
			catch(InterruptedException e) {
					
			}
		}
	}
}

 

<Test main class>

package test;

public class TestMain {
	public static void main(String [] args) throws Exception{
		Thread busyThread = new Thread(new BusyThread());
		Thread idleThread = new Thread(new IdleThread());
		busyThread.start();
		idleThread.start();
		busyThread.join();
	}
}

 

When I run TestMain.class, top shows high cpu usage. (Process mode)

Process id 13906’s cpu usage is high. Next I change into thread mode. (with “H” option)

This top shows that thread id 13936 is the root cause of the problem. Now I make thread dump with following command.

# kill -3 13906 (Do not type in 13936)

The following is thread dump.

Full thread dump Java HotSpot(TM) 64-Bit Server VM (25.121-b13 mixed mode): “Thread-1” #11 prio=5 os_prio=0 tid=0x00007f1b1c124800 nid=0x3671 in Object.wait() [0x00007f1b08236000] java.lang.Thread.State: WAITING (on object monitor) at java.lang.Object.wait(Native Method) – waiting on <0x000000076d175e58> (a java.lang.Object) at java.lang.Object.wait(Object.java:502) at test.IdleThread.run(IdleThread.java:10) – locked <0x000000076d175e58> (a java.lang.Object) at java.lang.Thread.run(Thread.java:745) “Thread-0” #10 prio=5 os_prio=0 tid=0x00007f1b1c123000 nid=0x3670 runnable [0x00007f1b08337000] java.lang.Thread.State: RUNNABLE at test.BusyThread.run(BusyThread.java:10) at java.lang.Thread.run(Thread.java:745) … “main” #1 prio=5 os_prio=0 tid=0x00007f1b1c009000 nid=0x3657 in Object.wait() [0x00007f1b22e12000] java.lang.Thread.State: WAITING (on object monitor) at java.lang.Object.wait(Native Method) – waiting on <0x000000076d1714e8> (a java.lang.Thread) at java.lang.Thread.join(Thread.java:1249) – locked <0x000000076d1714e8> (a java.lang.Thread) at java.lang.Thread.join(Thread.java:1323) at test.TestMain.main(TestMain.java:9) …

At first, you can not find string “13936”. Java thread dump shows thread id in hexa decimal. 13936’s hexa decimal value is 3670 and you can find the line.

“Thread-0” #10 prio=5 os_prio=0 tid=0x00007f1b1c123000 nid=0x3670 runnable

(nid means native thread id. More detailed explanation)

Now we found the problemetic class (BusyThread.java).

Advertisement