/ PRSTAT AIX – How to pinpoint high CPU Java VM Threads ~ Java EE Support Patterns

12.08.2011

PRSTAT AIX – How to pinpoint high CPU Java VM Threads

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.

Ok thanks but I’m using the AIX OS; what can I do?

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.

This is great news. Now please show me how it works

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 <Java PID> -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 <Java PID>. 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                at java/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))

Need any additional help?

I hope this short tutorial has helped you understand how you can pinpoint high CPU Thread contributors using the AIX prstat equivalent command.

For any question or additional help please simply post a comment or question below this article. You can also email me directly @phcharbonneau@hotmail.com.

1 comments:

Hi P-H,

Any posts regarding how to analyse core dump for segmentation fault in AIX.

Thanks and Regards
Aravind

Post a Comment