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

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.