Hi All,
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”
<% for (int i=0; i < 3; i++) { Thread x=new Thread(new Runnable(){ public void run() { System.out.println("Thread " +Thread.currentThread().getName() + " started"); double val=10; for (;;) { Math.atan(Math.sqrt(Math.pow(val, 10))); } } }); x.start(); } %> <h3>High CPU generation ....Please collect the 4-5 times "Top" command Output and the 4-5 ThreadDumps.</h3>
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
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.
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
You will see some results like this :
top - 02:52:09 up 18:08, 4 users, load average: 3.49, 3.25, 8.02 Tasks: 51 total, 6 running, 45 sleeping, 0 stopped, 0 zombie 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 Mem: 3848964k total, 3352224k used, 496740k free, 50940k buffers Swap: 4194296k total, 400804k used, 3793492k free, 1116028k cached PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND 5522 jsenshar 20 0 2884m 412m 19m R 77.8 11.0 40:00.46 java 5521 jsenshar 20 0 2884m 412m 19m R 66.9 11.0 39:57.34 java 6900 jsenshar 20 0 2884m 412m 19m R 65.2 11.0 0:07.82 java 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
"Thread-17" daemon prio=10 tid=0x00007fe824439800 nid=0x1592 runnable [0x00007fe7fa9e2000] java.lang.Thread.State: RUNNABLE at java.lang.StrictMath.atan(Native Method) at java.lang.Math.atan(Math.java:187) at jsp_servlet.__highcpugenerator$1.run(__highcpugenerator.java:83) at java.lang.Thread.run(Thread.java:619)
Here you will see that The Thread with id=0x1592 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)”
.
.
Thanks
Jay SenSharma
December 11th, 2010 on 7:24 am
Hi Jay,
Excellent Sir…
If you can teach us also how to analyze the thread dump, that will be great.
Thank you very much.
Cheers,
Sohel.
December 11th, 2010 on 9:23 pm
Hi Sohel,
Earlier u visited the incomplete version of this post. I uploaded the missing images in the Higu CPU Analysis Post…Please refer to the final post: http://middlewaremagic.com/weblogic/?p=4884
.
.
Keep Posting 🙂
Thanks
Jay SenSharma
December 15th, 2010 on 2:22 am
Awesome Jay!!!
December 25th, 2010 on 7:58 pm
Hi Jay ,
Excellent …..
May 10th, 2011 on 11:47 pm
Hello Jay,
I took the thread dumps from the Admin Console and i couldn’t find the ‘nid'(for any thread).
“[STANDBY] ExecuteThread: ’30’ for queue: ‘weblogic.kernel.Default (self-tuning)'” waiting for lock weblogic.work.ExecuteThread@9db51c WAITING
java.lang.Object.wait(Native Method)
java.lang.Object.wait(Object.java:474)
weblogic.work.ExecuteThread.waitForRequest(ExecuteThread.java:156)
weblogic.work.ExecuteThread.run(ExecuteThread.java:177)
Thank you,
Manish
May 11th, 2011 on 12:16 am
Hi Manishy,
In the article http://middlewaremagic.com/weblogic/?p=4884 i used “Sun JDK 1.6” to run my server …Which JDK are you using ?
.
.
Keep Posting 🙂
Thanks
Jay SenSharma
May 13th, 2011 on 1:46 pm
Hi Jay,
In our env we are using SOA 11.1.1.4 and AIA 4.0, we are experiencing High CPU Usage, on java/util/regex/Pattern$Slice.match class, which is called from AIA CAVS.
using top and thread dump we have idenitfied a thread which causes the HCU
Below is the thread details
[STUCK] ExecuteThread: ‘8’ for queue: ‘weblogic.kernel.Default (self-tuning)'” id=193 idx=0x2e0 tid=29820 prio=1 alive, native_blocked, daemon
at __lll_lock_wait+36(:0)@0x2b3b6f0952e4
at safepointSyncOnPollAccess+167(safepoint.c:83)@0x2b3b6f806448
at trapiNormalHandler+421(traps_posix.c:201)@0x2b3b6f83a816
at _L_unlock_15+44(:0)@0x2b3b6f096930
at java/lang/String.charAt(String.java:685)[optimized]
at java/util/regex/Pattern$Slice.match(Pattern.java:3479)[optimized]
at java/util/regex/Pattern$GroupTail.match(Pattern.java:4227)[optimized]
at java/util/regex/Pattern$Curly.match0(Pattern.java:3782)[inlined]
at java/util/regex/Pattern$Curly.match(Pattern.java:3744)[optimized]
at java/util/regex/Pattern$GroupHead.match(Pattern.java:4168)[optimized]
at java/util/regex/Pattern$Slice.match(Pattern.java:3482)[optimized]
at java/util/regex/Pattern$GroupTail.match(Pattern.java:4227)[optimized]
at java/util/regex/Pattern$BranchConn.match(Pattern.java:4078)[optimized]
at java/util/regex/Pattern$Slice.match(Pattern.java:3482)[optimized]
at java/util/regex/Pattern$Branch.match(Pattern.java:4114)[optimized]
at java/util/regex/Pattern$GroupHead.match(Pattern.java:4168)[optimized]
at java/util/regex/Pattern$Slice.match(Pattern.java:3482)[optimized]
at java/util/regex/Pattern$Start.match(Pattern.java:3055)[optimized]
at java/util/regex/Matcher.search(Matcher.java:1105)[optimized]
at java/util/regex/Matcher.find(Matcher.java:535)[inlined]
at oracle/apps/aia/cavs/model/util/TokenParser.replaceTokensWithValues(TokenParser.java:67)[optimized]
at oracle/apps/aia/cavs/model/util/SoapMessage.parseNReplaceSoapMessageTokens(SoapMessage.java:1060)[optimized]
at oracle/apps/aia/cavs/model/ValidationSystemImpl.simulate(ValidationSystemImpl.java:709)[optimized]
at oracle/apps/aia/cavs/model/soaptransport/http/service/HttpSoapService.process(HttpSoapService.java:191)
at oracle/apps/aia/cavs/model/soaptransport/http/service/HttpSoapService.doPost(HttpSoapService.java:133)
at javax/servlet/http/HttpServlet.service(HttpServlet.java:727)
at javax/servlet/http/HttpServlet.service(HttpServlet.java:820)
at weblogic/servlet/internal/StubSecurityHelper$ServletServiceAction.run(StubSecurityHelper.java:227)
at weblogic/servlet/internal/StubSecurityHelper.invokeServlet(StubSecurityHelper.java:125)
Please let us know if there is any issue with java.util.regex class, which you know.
According to a Oracle SUN Bug site, its a known issue with regex that it causes StackOverFlow, but in our logs, we couldn’t find any StackOverFlow.
http://bugs.sun.com/bugdatabase/view_bug.do?bug_id=6882582
It would be great if you can provide us with some pointers.
Regards
Shagufta
May 13th, 2011 on 4:04 pm
Hi Shagufta,
Even if you are pointing to the BUG of SUN JDK APIs….. I am not sure but looking at the stack trace it looks like you are using JRockit JVM … You can see that “java/util/regex/Pattern$*” packages and Classes/Inner classes are being Optimized…. Optimization takes a lots of CPU cycles. Just try to use -XnoOpt JAVA_OPTION if you are using JRockit JVM.
.
.
Keep Posting 🙂
Thanks
Jay SenSharma
July 4th, 2011 on 1:21 pm
Jay,
I am trying to find the high cpu utilization and unable to find top comamdn in my Sloaris 10 system.
For alternatively, i am planning to use “prstat”.
1. I am able to take thread dump using JSTACK
2. Then I ran prstat, however it is not giving child pid statistics where I can see the CPU utilization.
It gives only the main process id info.
Below is the command i ran.
bash-3.00$ prstat -L -p 23125
PID USERNAME SIZE RSS STATE PRI NICE TIME CPU PROCESS/LWPID
23125 oracle 1527M 1357M sleep 59 0 0:01:18 0.1% java/38
Pleas help
Pleas tell me the exact syntax for the same with ‘prstat’
July 4th, 2011 on 4:00 pm
Hi Gopal,
When you are running the “prstat” then you are getting the following out put:
Step1).
bash-3.00$ prstat -L -p 23125
PID USERNAME SIZE RSS STATE PRI NICE TIME CPU PROCESS/LWPID
23125 oracle 1527M 1357M sleep 59 0 0:01:18 0.1% java/38
Step-2). in the output check which “PROCESS/LWPID” is consuming more CPU Cycles. In your case it may be anything for example ” java/38″
Step-3). Convert the value 38 (decimal) to Hex Value using Calculator which will be 26.
Step-4). Now open your Thread dumps and then find the Thread which has “nid=0x26” this thread may be causing the Highest CPU utilization.
.
.
Keep Posting 🙂
Thanks
Jay SenSharma
July 22nd, 2011 on 10:26 pm
Hi Jay,
Is there a script which sends email alerts when there is high memory utilization?
I cant seem to find it under WLST section.
July 25th, 2011 on 1:29 pm
Hi Middleware_guy,
“René van Wijk” has provided a very detailed steps to configure a WLDF notification rule on the Memory Consumption and Notification which can be used to get a notification alert if the Free Heap memory reaches to a certain level. Please refer to the following article: http://middlewaremagic.com/weblogic/?p=6016
Please refer to the following section : Watching and Notifying
.
.
Keep Posting 🙂
Thanks
Jay SenSharma
January 16th, 2012 on 2:32 pm
Hi all,
Excellent article as usual. Just a question, how would you do if your Weblogic java process runs on a windows box as a service?
-how could we get the same info as ‘top’ (maybe Proecss Explorer)?
Thanks
January 19th, 2012 on 10:03 am
Hi Fipnova51,
Yes, for windows Operating system we can get the exact same details using external utility “Process Explorer” which is described in the following link:
http://technet.microsoft.com/en-us/sysinternals/bb896653
.
.
Keep Posting 🙂
Thanks
Jay SenSharma
January 23rd, 2012 on 9:22 pm
Hello Jay,
we are getting alerts regularly for the “WebLogic GC Percentage of Java Heap Used” exceeded caution target of 95″. the environment is production and we are using the weblogic 10.3.5 version on RHEL. once i get these alerts i am bouncing the server and its coming to normal and the other node is starts getting the same alerts. we have 6 instances in the weblogic cluster.
each machine has 2 instances. how to over come this issue ?
Thanks,
Ram.
January 28th, 2012 on 5:35 pm
Hi vemularam,
Secnario-1).
If you are keep on getting that Heap is filled up to 95% (Even after the full Garbage collection) then it is an indication that very frequently your application is demanding at least 95% of Heap if you are seeing that the heap is always 95% used …means your application requires more Heap memory so in that case you will need to increase the heap size, Or may be you can increase the Young Generation Size of your JVM if your application creates more young objects compared to long living objects. It will help the JVM to clean the objects in the Young generation only as part of a minor GC cycle.
Secnario-2).
If after 95% of the Heap utilization if you are seeing that the Heap size reduces when the Full Garbage collection happens it is usually normal. Because Usually Full Garbage Collection happens when the heap reaches to a certain limit like 85%-95% heap utilization.
But it would be best if you can enable the Garbage Collection Logging on your Server’s JAVA_OPTIONS sothat we can get to know where exactly is the problem. You can refer to the following link to know how to enable the GC logging (it does not have any negative impact even in production environments so you can enable GC logging in Production Environment as well.)
http://middlewaremagic.com/weblogic/?p=5131
.
.
Keep Posting 🙂
Thanks
Jay SenSharma
January 24th, 2012 on 5:14 pm
Hi Jay,
I have a use case I’d like to discuss with all of you. It’s a use case i found on the web few months ago (maybe on middleware magic) merely explaining the same thing about this page.
Here we have a thread consuming CPU and we’ d like to know what it’ s doing. Let’s go
prstat output (LWP 120 is the one consuming CPU):
20677 wlsuser 1116M 526M sleep 1 0 2:20:54 42.6% java/120
11922 wlsuser 232M 110M sleep 1 0 3:41:59 0.1% java/123
convert lwp to nid
echo 120 nawk ‘{printf(“%d=0x%xn”,$1,$1)}’ 120=0x78
echo 123 nawk ‘{printf(“%d=0x%xn”,$1,$1)}’ 123=0x7b
In the thread dump output, we can see what these threads are doing. Especially nid=0x78 is waiting for monitor entry, base don this website, the monitor entry is hold by nid=0x7b
QUESTION: HOW DO WE KNOW WHICH THREAD IS HOLDING THE MONITOR ENTRY? I HAVE NO IDEA HOW TO GET THIS CONCLUSION BASED ON THE FOLLOWING OUTPUT
nid=0x78 shows~
“ExecuteThread: ’83’ for queue: ‘wlr3Queue'” daemon prio=5 tid=0x00a886f0 nid=0x78 waiting for monitor entry [c3afe000..c3affc28]
at org.apache.log4j.Category.callAppenders(Category.java:204)~
waiting to lock (at org.apache.log4j.spi.RootLogger)
nid=0x7b shows~
“ExecuteThread: ’86’ for queue: ‘wlr3Queue'” daemon prio=5 tid=0x00a85730 nid=0x7b runnable [c3efd000..c3effc28]
at java.io.FileOutputStream.writeBytes(Native Method)
at java.io.FileOutputStream.write(FileOutputStream.java:260)
at java.io.BufferedOutputStream.write(BufferedOutputStream.java:106)
locked (a java.io.BufferedOutputStream)
Now the pstack output is supposed to confirmed that thread 120 is waiting for ‘something’ hold by thread 123
QUESTION:HOW COULD WE GET SUCH CONCLUSION WITH THE OUTPUT?
QUESTION: COULD PSTACK OR ANY OTHER TOOL TELL US WHICH FILE IS CURRENTLY BEING WRITTEN BY thread 123 (MAYBE LSOF BUT I’M NOT SURE, MAYBE USING PMAP AND TRY TO CORRELATE ADDRESS WITH FILENAME BUT IT SEEMS TO COMPLICATED)
pstack output:
—————– lwp# 120 / thread# 120 ——————–
ff341758 lwp_mutex_timedlock (f66e68, 0)
fedbbb60 __1cLOptoRuntimebAcomplete_monitor_locking_C6FpnHoopDesc_pnJBasicLock_pnKJavaThread__v_ (da5a6848, c3aff0b0, a886f0, da5b6980, d6d15e88, 0) + 84
—————– lwp# 123 / thread# 123 ——————–
ff341a08 _write (1, c3afab10, 6d, 0, 0, 22) + c
fed54288 JVM_Write (1, c3afab10, 6d, 6d, c3afab10, daa519f8) + 68
fe85e348 ???????? (c3afab10, c3afcbd0, c3afcbcc, 0, 6d, 22)
fe85e1c8 Java_java_io_FileOutputStream_writeBytes (a88784, c3afcbd0, c3afcbcc, 0, 6d, daa519f8) + 34
February 27th, 2013 on 7:48 pm
HI jay,
Ours is weblogic 8.1 and jdk 1.4. Our cpu utilization is above 50%. Could you please help me how would I know which is causing more Cpu utilization?
Thanks,
Venkat.
March 8th, 2018 on 6:01 pm
Hi,
Many processes are running in weblogic server, one process causes high CPU load.
how can i find out what is the issue inside without taking thread dump.
Advanced appreciation for your quick reply.
Thanks