Most of you are probably familiar with the powerful Solaris OS prstat command. This command allows you to generate a snapshot of all running Java VM Threads along with CPU % for each of them.
When combined with Thread Dump analysis, it allows you to pinpoint high CPU problems such as:
· Java Threads involved in infinite or heavy loopin
· Java Threads involved in excessive / nonstop garbage collection (GC Threads)
· Java Threads involved in heavy logging / IO activities
This analysis strategy is extremely important for any individual involved in Java EE middleware and / or application support such as Oracle Weblogic, IBM Websphere, RedHat JBoss etc.
The prstat command is not available on the AIX OS but fortunately there is an equivalent command & strategy that you can use to simulate and generate the same Thread & CPU % breakdown.
Please simply follow the instructions below:
1) Identify the AIX process Id of your Java VM process
2) When high CPU is observed, execute the following command: ps -mp -o THREAD
Example: ps –mp captured of a Weblogic Java process running at 40% CPU utilization
USER PID PPID TID ST CP PRI SC WCHAN F TT BND COMMAND
user 12910772 9896052 - A 40 60 98 * 342001 - - /usr/java6_64/bin/java -Dweblogic.Nam
- - - 6684735 S 0 60 1 f1000f0a10006640 8410400 - - -
- - - 6815801 Z 0 77 1 - c00001 - - -
- - - 6881341 Z 0 110 1 - c00001 - - -
- - - 6946899 S 0 82 1 f1000f0a10006a40 8410400 - - -
- - - 8585337 S 0 82 1 f1000f0a10008340 8410400 - - -
- - - 9502781 S 30 82 1 f1000f0a10009140 8410400 - - -
- - - 10485775 S 0 82 1 f1000f0a1000a040 8410400 - - -
- - - 10813677 S 0 82 1 f1000f0a1000a540 8410400 - - -
- - - 11206843 S 3 82 1 f1000f0a1000ab40 8410400 - - -
- - - 11468831 S 0 82 1 f1000f0a1000af40 8410400 - - -
- - - 11796597 S 0 82 1 f1000f0a1000b440 8410400 - - -
- - - 19070989 S 0 82 1 f1000f0a10012340 8410400 - - -
- - - 25034989 S 2 62 1 f1000a01001d0598 410400 - - -
- - - 25493513 S 0 82 1 f1000f0a10018540 8410400 - - -
- - - 25690227 S 0 86 1 f1000f0a10018840 8410400 - - -
- - - 25755895 S 0 82 1 f1000f0a10018940 8410400 - - -
- - - 26673327 S 2 82 1 f1000f0a10019740 8410400 - - -
- - - 26804377 S 0 60 1 f1000a0100220998 410400 - - -
- - - 27787407 S 0 82 1 - 418400 - - -
- - - 28049461 S 2 82 1 f1000f0a1001ac40 8410400 - - -
- - - 28114963 S 0 82 1 11a835728 c10400 - - -
- - - 29491211 S 0 82 1 f1000f0a1001c240 8410400 - - -
- - - 29884565 S 0 78 1 f1000f0a1001c840 8410400 - - -
3) Immediately after, generate a Java VM Thread Dump by executing kill -3 . This command will generate a AIX / IBM Thread Dump (javacore.xyz format). At this point, you should have both ps –mp data output and a AIX Java VM Thread Dump
4) Now analyse your ps –mp output data identify the Thread Id(s) with the highest CPU contribution and convert the TID decimal format to HEXA format
Example: Thread TID: 9502781 >> 91003D
5) At this point, you are now ready to pinpoint and determine why such Java Thread(s) is / are using so much CPU. The answer is in the JVM Thread Dump. Simply search form the Thread Dump using the Thread TID; HEXA format. The final step is to analyze the affected Thread(s) Stack Trace and determine the root cause e.g. application code problem, middleware problem etc.
Example: In our example, the primary culprit (Thread TID: 0x91003D) was identified in the Thread Dump. As you can see, this Thread is currently involved in an infinite loop condition from a Hashmap. This is a common problem when using non Thread safe Hashmap data structure and combined with high concurrent Threads.
3XMTHREADINFO "[STUCK] ExecuteThread: '97' for queue: 'weblogic.kernel.Default (self-tuning)'" J9VMThread:0x00000001333FFF00, j9thread_t:0x0000000117C00020, java/lang/Thread:0x0700000043184480, state:CW, prio=1
3XMTHREADINFO1 (native thread ID:0x91003D, native priority:0x1, native policy:UNKNOWN)
3XMTHREADINFO3 Java callstack:
4XESTACKTRACE atjava/util/HashMap.findNonNullKeyEntry(HashMap.java:528(Compiled Code))
4XESTACKTRACE at java/util/HashMap.putImpl(HashMap.java:624(Compiled Code))
4XESTACKTRACE at java/util/HashMap.put(HashMap.java:607(Compiled Code))
4XESTACKTRACE at weblogic/socket/utils/RegexpPool.add(RegexpPool.java:20(Compiled Code))
4XESTACKTRACE at weblogic/net/http/HttpClient.resetProperties(HttpClient.java:129(Compiled Code))
4XESTACKTRACE at weblogic/net/http/HttpClient.openServer(HttpClient.java:374(Compiled Code))
4XESTACKTRACE at weblogic/net/http/HttpClient.New(HttpClient.java:252(Compiled Code))
4XESTACKTRACE at weblogic/net/http/HttpURLConnection.connect(HttpURLConnection.java:189(Compiled Code))
4XESTACKTRACE at com/bea/wli/sb/transports/http/HttpOutboundMessageContext.send(HttpOutboundMessageContext.java(Compiled Code))
4XESTACKTRACE at com/bea/wli/sb/transports/http/wls/HttpTransportProvider.sendMessageAsync(HttpTransportProvider.java(Compiled Code))
4XESTACKTRACE at sun/reflect/GeneratedMethodAccessor2587.invoke(Bytecode PC:58(Compiled Code))
4XESTACKTRACE at sun/reflect/DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:37(Compiled Code))
4XESTACKTRACE at java/lang/reflect/Method.invoke(Method.java:589(Compiled Code))
4XESTACKTRACE at com/bea/wli/sb/transports/Util$1.invoke(Util.java(Compiled Code))
4XESTACKTRACE at $Proxy115.sendMessageAsync(Bytecode PC:26(Compiled Code))
4XESTACKTRACE at com/bea/wli/sb/transports/LoadBalanceFailoverListener.sendMessageAsync(LoadBalanceFailoverListener.java:141(Compiled Code))
4XESTACKTRACE at com/bea/wli/sb/transports/LoadBalanceFailoverListener.onError(LoadBalanceFailoverListener.java(Compiled Code))
4XESTACKTRACE at com/bea/wli/sb/transports/http/wls/HttpOutboundMessageContextWls$RetrieveHttpResponseWork.handleResponse(HttpOutboundMessageContextWls.java(Compiled Code))
4XESTACKTRACE at weblogic/net/http/AsyncResponseHandler$MuxableSocketHTTPAsyncResponse$RunnableCallback.run(AsyncResponseHandler.java:531(Compiled Code))
4XESTACKTRACE at weblogic/work/ContextWrap.run(ContextWrap.java:41(Compiled Code))
4XESTACKTRACE at weblogic/work/SelfTuningWorkManagerImpl$WorkAdapterImpl.run(SelfTuningWorkManagerImpl.java:528(Compiled Code))
4XESTACKTRACE at weblogic/work/ExecuteThread.execute(ExecuteThread.java:203(Compiled Code))
4XESTACKTRACE at weblogic/work/ExecuteThread.run(ExecuteThread.java:171(Compiled Code))