High CPU Utilization Finding Cause?

High CPU utilization is a very very common thing for an Application Server Administrator. Almost every week or quarter or may be every day we can see some High CPU utilization by the Application Server. It is very important for an Administrator or System Admin or a Application Server Support Person to find out what is causing the High CPU.

.
High CPU may cause System Crash or Server Crash or Slow Responsiveness of Server. So we need to find out which Thread is actually consuming more CPU cycles this will help us to find out whether the Thread is processing some application code ….there may be a code bug or it may be Application Framework bug as well…etc

.
So here we are going to see a very simple demonstration of generating High CPU and then we will see How to Analyze High CPU utilization. For this purpose we are going to use 2 very basic utilities

.
1). jps: to know How to use JPS utility please refer to : http://middlewaremagic.com/weblogic/?p=2291
2). top: This is an Operating System Utility .. Please refer to “man” (Manual of your OS like Linux/Solaris)
3). jstack: to know how to use jstack please refer to : http://middlewaremagic.com/weblogic/?p=2281

Generating High CPU

Step1). Create a Simple Web Application with the following JSP code:
“HighCpuGenerator.jsp”

01

<%

02	for (int i=0; i < 3; i++)

03

{

04	Thread x=new Thread(new Runnable(){

05

06	public void run()

07

{

08	System.out.println("Thread " +Thread.currentThread().getName() + " started");

09	double val=10;

10

for (;;)

11

{

12	Math.atan(Math.sqrt(Math.pow(val, 10)));

13

}

14

}

15

});

16

17	x.start();

18

}

19

%>

20

21	High CPU generation ....Please collect the 4-5 times "Top" command Output and the 4-5 ThreadDumps.

Step2). Now Deploy your Application which is having this JSP.
Step3). Hit the Application using “http://localhost:7001/HighCpuWebApp/HighCpuGenerator.jsp”

Analyzing High CPU:

Step4). Open a shell prompt and then get the Servers Process ID using “jps” utility which comes with Jdk1.5 and Higher inside the \bin directory.

[jsenshar@jsenshar ~]$ export PATH=/home/jsenshar/MyJdks/jdk1.6.0_21/bin:$PATH
[jsenshar@jsenshar ~]$ jps -v

HighCpu_Collect5ing Process ID using JPS

Step5). Now In the same command prompt run the “JStack” utility to collect some Thread Dumps in a File… Suppose if the Application Servers Process ID is “5398″ which we got in previous step.

[jsenshar@jsenshar ~]$ jstack -l 5398 > ThreadDumps.log

[jsenshar@jsenshar ~]$ jstack -l 5398 >> ThreadDumps.log

[jsenshar@jsenshar ~]$ jstack -l 5398 >> ThreadDumps.log

[jsenshar@jsenshar ~]$ jstack -l 5398 >> ThreadDumps.log

[jsenshar@jsenshar ~]$ jstack -l 5398 >> ThreadDumps.log

HighCpu_ThreadDumps_JStack

Step6). Now In Parallel to collecting the Thread Dumps please collect the “top” commands output as well….like
(NOTE: Make sure that u collect the Thread Dumps and the Top commands results in Parallel whenever u observe any kind of High CPU utilization or Server Slow response)

[jsenshar@jsenshar HighCpu]$ top -H -b -p 5398

HighCPU_Top_Report

You will see some results like this :

01	top - 02:52:09 up 18:08,  4 users,  load average: 3.49, 3.25, 8.02

02	Tasks:  51 total,   6 running,  45 sleeping,   0 stopped,   0 zombie

03	Cpu(s): 96.6%us,  0.7%sy,  0.0%ni,  2.6%id,  0.0%wa,  0.0%hi,  0.1%si,  0.0%st

04	Mem:   3848964k total,  3352224k used,   496740k free,    50940k buffers

05	Swap:  4194296k total,   400804k used,  3793492k free,  1116028k cached

06

07	PID USER      PR  NI  VIRT  RES  SHR S %CPU %MEM    TIME+  COMMAND

08	5522 jsenshar  20   0 2884m 412m  19m R 77.8 11.0  40:00.46 java

09	5521 jsenshar  20   0 2884m 412m  19m R 66.9 11.0  39:57.34 java

10	6900 jsenshar  20   0 2884m 412m  19m R 65.2 11.0   0:07.82 java

11	5520 jsenshar  20   0 2884m 412m  19m R 54.2 11.0  39:57.70 java

Step7). Now U will observe that there are some Thread IDs which are consuming more CPU Cycles like Child Thread PID=5522 is consuming 77.8% of CPU similarly Child Thread PID 5521 is consuming 66.9 % of CPU Cycles. These are very Hign CPU utilization Threads inside the Main Parent Process ID 5398.

Step8). Now convert those PIDs into Hexadecimal values…..Example     the Hex Decimal Value for     5522 will be      1592. So now please open the Thread Dump and then find out the word 1592

Decimal Value of the Thread ID provided by OS

Converted the Decimal Thread ID Value to Hexa Decimal Code

1	"Thread-17" daemon prio=10 tid=0x00007fe824439800 nid=0x1592 runnable [0x00007fe7fa9e2000]

2	java.lang.Thread.State: RUNNABLE

3	at java.lang.StrictMath.atan(Native Method)

4	at java.lang.Math.atan(Math.java:187)

5	at jsp_servlet.__highcpugenerator$1.run(__highcpugenerator.java:83)

6	at java.lang.Thread.run(Thread.java:619)

Here you will see that The Thread with id=0×1592 is actually causing the High CPU …Now u can tell your Developers to check the Stack Trace of this Thread so that they can correct their Application Code or If you see any API Code or Framework code there then you know what u need to do and where the problem is.

Like in above case u can see that  My JSPs code is actually causing High CPU    ”at jsp_servlet.__highcpugenerator$1.run(__highcpugenerator.java:83)”

- See more at: http://middlewaremagic.com/weblogic/?p=4884#sthash.uq0neszh.dpuf