How To Analyze Thread Dumps: IBM VM

This article is part 4 of our Thread Dump analysis series which will provide you with an overview of what is a JVM Thread Dump for the IBM VM and the different Threads and data points that you will find. As you will see and learn, the IBM VM Thread Dump format is different but provides even more out-of-the-box troubleshooting data.

At this point, you should know how Threads interact with the Java EE container and what a Thread Dump is. Before we go any further in the deep dive analysis patterns, you also need to understand the IBM VM Thread Dump format since this is the typical Thread Dump data to expect when using IBM WAS on IBM VM.

IBM VM Thread Dump breakdown overview

In order for you to better understand, find below a diagram showing you a visual breakdown of an IBM 1.6 VM Thread Dump and its common data points found:

As you can, there are extra runtime data that you will not find from a HotSpot VM Thread Dump. Please keep in mind that you may not need to review all these data points but you still need to understand what data is available depending of your problem case.

The rest of the article will cover each Thread Dump portion in more detail.

# Thread Dump generation event

The first portion provides you with detail on how this Thread Dump was generated. IBM Thread Dump can be generated as a result of a “signal 3” or “user” e.g. kill -3 <Java pid> or automatically as a result of severe JVM conditions such as an OutOfMemoryError.

The next section provides you with some detail on the current hardware and OS that this IBM VM is running from:

0SECTION       GPINFO subcomponent dump routine
NULL           ================================
2XHOSLEVEL     OS Level         : AIX 5.3
2XHCPUS        Processors -
3XHCPUARCH       Architecture   : ppc64
3XHNUMCPUS       How Many       : 6
3XHNUMASUP       NUMA is either not supported or has been disabled by user

# JRE detail and Java start-up arguments

This section is very useful as it provides you with a full view on your JRE major version and patch level along with all JVM start-up arguments.

0SECTION       ENVINFO subcomponent dump routine
NULL           =================================
1CIJAVAVERSION JRE 1.6.0 IBM J9 2.4 AIX ppc64-64 build jvmap6460sr9-20101124_69295
1CIVMVERSION   VM build 20101124_069295
1CIJITVERSION  JIT enabled, AOT enabled - r9_20101028_17488ifx2
1CIGCVERSION   GC - 20101027_AA
1CIRUNNINGAS   Running as a standalone JVM
…………………………………………………………………………………………

# User and environment variables

This section provides you with a listing of current user and environment variables such as File Descriptor limit.

1CIUSERLIMITS  User Limits (in bytes except for NOFILE and NPROC)
NULL           ------------------------------------------------------------------------
NULL           type                            soft limit           hard limit
2CIUSERLIMIT   RLIMIT_AS                        unlimited            unlimited
2CIUSERLIMIT   RLIMIT_CORE                     1073741312            unlimited
2CIUSERLIMIT   RLIMIT_CPU                       unlimited            unlimited
2CIUSERLIMIT   RLIMIT_DATA                      unlimited            unlimited
2CIUSERLIMIT   RLIMIT_FSIZE                     unlimited            unlimited
2CIUSERLIMIT   RLIMIT_NOFILE                         4096                 4096
2CIUSERLIMIT   RLIMIT_RSS                        33554432            unlimited
2CIUSERLIMIT   RLIMIT_STACK                      33554432           4294967296

# Java Heap detail and GC history

Similar to HotSpot VM 1.6+, IBM VM Thread Dump also contains information on the Java Heap capacity and utilization along with memory segments allocated for each memory space of the Java process.

Please keep in mind that deeper Java Heap analysis will require you to analyze the Heap Dump binary snapshot as per below tutorial.

http://javaeesupportpatterns.blogspot.com/2011/02/ibm-sdk-heap-dump-httpsession-footprint.htm

Finally, a history of the garbage collection process is also present.

0SECTION       MEMINFO subcomponent dump routine
NULL           =================================
1STHEAPFREE    Bytes of Heap Space Free: 51104BC8
1STHEAPALLOC   Bytes of Heap Space Allocated: 80000000
1STSEGTYPE     Internal Memory
…………………………………………………………………………………………
1STSEGTYPE     Object Memory
…………………………………………………………………………………………
1STSEGTYPE     Class Memory
…………………………………………………………………………………………
1STSEGTYPE     JIT Code Cache
…………………………………………………………………………………………
1STSEGTYPE     JIT Data Cache
…………………………………………………………………………………………
STGCHTYPE     GC History 
3STHSTTYPE     00:52:07:523048405 GMT j9mm.51 -   SystemGC end: newspace=466136480/483183616 oldspace=899251600/1610612736 loa=80530432/80530432
3STHSTTYPE     00:52:07:523046694 GMT j9mm.139 -   Reference count end: weak=40149 soft=87504 phantom=33 threshold=17 maxThreshold=32
3STHSTTYPE     00:52:07:522164027 GMT j9mm.91 -   GlobalGC end: workstackoverflow=0 overflowcount=0 weakrefs=40149 soft=87504 threshold=17 phantom=33 finalizers=4947 newspace=466136480/483183616 oldspace=899251600/1610612736 loa=80530432/80530432
3STHSTTYPE     00:52:07:522152764 GMT j9mm.90 -   GlobalGC collect complete

# Java and JVM object monitor lock and deadlock detail

This Thread Dump portion is very important. Quite often Thread problems involve Threads waiting between each other due to locks on particular Object monitors e.g. Thread B waiting to acquire a lock on Object monitor held by Thread A. Deadlock conditions can also be triggered from time to time; especially for non-Thread safe implementations.

The IBM VM Thread Dump provides a separate section where you can analyze lock(s) held by each Thread including waiting chain(s) e.g. Many Threads waiting to acquire the same Object monitor lock.

0SECTION       LOCKS subcomponent dump routine
NULL           ===============================
NULL          
1LKPOOLINFO    Monitor pool info:
2LKPOOLTOTAL     Current total number of monitors: 1034
NULL          
1LKMONPOOLDUMP Monitor Pool Dump (flat & inflated object-monitors):
2LKMONINUSE      sys_mon_t:0x0000000115B53060 infl_mon_t: 0x0000000115B530A0:
3LKMONOBJECT       java/util/Timer$TimerImpl@0x0700000000C92AA0/0x0700000000C92AB8: <unowned>
3LKNOTIFYQ            Waiting to be notified:
3LKWAITNOTIFY            "Thread-7" (0x0000000114CAB400)
…………………………………………………………………………
## Threads waiting chain
2LKMONINUSE      sys_mon_t:0x000000012462FE00 infl_mon_t: 0x000000012462FE40:
3LKMONOBJECT       com/inc/server/app/Request@0x07000000142ADF30/0x07000000142ADF48: owner "Thread-30" (0x000000012537F300), entry count 1
3LKNOTIFYQ            Waiting to be notified:
3LKWAITNOTIFY            "Thread-26" (0x0000000125221F00)
3LKWAITNOTIFY            "Thread-27" (0x0000000125252000)
3LKWAITNOTIFY            "Thread-28" (0x000000012527B800)
3LKWAITNOTIFY            "Thread-29" (0x00000001252DDA00)
3LKWAITNOTIFY            "Thread-31" (0x0000000125386200)
3LKWAITNOTIFY            "Thread-32" (0x0000000125423600)
3LKWAITNOTIFY            "Thread-33" (0x000000012548C500)
3LKWAITNOTIFY            "Thread-34" (0x00000001255D6000)
3LKWAITNOTIFY            "Thread-35" (0x00000001255F7900)
…………………………………………………………………………

# Java EE middleware, third party & custom application Threads

Similar to the HotSpot VM Thread Dump format, this portion is the core of the Thread Dump and where you will typically spend most of your analysis time. The number of Threads found will depend on your middleware software that you use, third party libraries (that might have its own Threads) and your application (if creating any custom Thread, which is generally not a best practice).

The following Thread in the example below is in BLOCK state which typically means it is waiting to acquire a lock on an Object monitor. You will need to search in the earlier section and determine which Thread is holding the lock so you can pinpoint the root cause.

3XMTHREADINFO      "[STUCK] ExecuteThread: '162' for queue: 'weblogic.kernel.Default (self-tuning)'" J9VMThread:0x000000013ACF0800, j9thread_t:0x000000013AC88B20, java/lang/Thread:0x070000001F945798, state:B, prio=1
3XMTHREADINFO1            (native thread ID:0x1AD0F3, native priority:0x1, native policy:UNKNOWN)
3XMTHREADINFO3           Java callstack:
4XESTACKTRACE                at org/springframework/jms/connection/SingleConnectionFactory.createConnection(SingleConnectionFactory.java:207(Compiled Code))
4XESTACKTRACE                at org/springframework/jms/connection/SingleConnectionFactory.createQueueConnection(SingleConnectionFactory.java:222(Compiled Code))
4XESTACKTRACE                at org/springframework/jms/core/JmsTemplate102.createConnection(JmsTemplate102.java:169(Compiled Code))
4XESTACKTRACE                at org/springframework/jms/core/JmsTemplate.execute(JmsTemplate.java:418(Compiled Code))
4XESTACKTRACE                at org/springframework/jms/core/JmsTemplate.send(JmsTemplate.java:475(Compiled Code))
4XESTACKTRACE                at org/springframework/jms/core/JmsTemplate.send(JmsTemplate.java:467(Compiled Code))
…………………………………………………………………………………………………………

# JVM class loader summary

Finally, the last section of the IBM VM Thread Dump provides you with a detailed class loader summary. This is very crucial data when dealing with Class Loader related issues and leaks. You will find the number and type of loaded Classes for each active Class loader in the running JVM.

I suggest that you review the following case study for a complete tutorial on how to pinpoint root cause for this type of issues when using IBM VM.

http://javaeesupportpatterns.blogspot.com/2011/04/class-loader-memory-leak-debugging.html