How to analyze Thread Dump – Part 4: 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.

** UPDATE: Thread Dump analysis tutorial videos now available here.

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.

0SECTION       TITLE subcomponent dump routine

NULL           ===============================

1TISIGINFO     Dump Event "user" (00004000) received

1TIDATETIME    Date:                 2012/03/12 at 20:52:13

1TIFILENAME    Javacore filename:    /apps/wl11g/domains/app/javacore.20120312.205205.1949928.0004.txt

1TIREQFLAGS    Request Flags: 0x81 (exclusive+preempt)

1TIPREPSTATE   Prep State: 0x4 (exclusive_vm_access)

0SECTION       TITLE subcomponent dump routine

NULL           ===============================

1TISIGINFO     OUTOFMEMORY received

1TIDATETIME    Date:                 2012/06/01 at 09:52:12

1TIFILENAME    Javacore filename:    /usr/WebSphere/AppServer/javacore311328.1338524532.txt

# HW and OS environment detail

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.html

Finally, an 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

0SECTION       CLASSES subcomponent dump routine

NULL           =================================

1CLTEXTCLLOS        Classloader summaries

1CLTEXTCLLSS               12345678: 1=primordial,2=extension,3=shareable,4=middleware,5=system,6=trusted,7=application,8=delegating

2CLTEXTCLLOADER            p---st-- Loader *System*(0x0700000000878898)

3CLNMBRLOADEDLIB           Number of loaded libraries 6

3CLNMBRLOADEDCL                  Number of loaded classes 3721

2CLTEXTCLLOADER            -x--st-- Loader sun/misc/Launcher$ExtClassLoader(0x0700000000AE8F40), Parent *none*(0x0000000000000000)

3CLNMBRLOADEDLIB           Number of loaded libraries 0

3CLNMBRLOADEDCL                  Number of loaded classes 91

2CLTEXTCLLOADER            -----ta- Loader sun/misc/Launcher$AppClassLoader(0x07000000008786D0), Parent sun/misc/Launcher$ExtClassLoader(0x0700000000AE8F40)

3CLNMBRLOADEDLIB           Number of loaded libraries 3

3CLNMBRLOADEDCL                  Number of loaded classes 15178

……………………………………………………………………………………………

I hope this article has helped to understand the basic view of an IBM VM Thread Dump. The next article (part 5) will provide you with a tutorial on how to analyze a JVM Thread Dump via a step by step tutorial and technique I have used over the last 10 years.

The part 5 of the series is now available.

Please feel free to post any comment and question.

Read More

IBM JVM tuning – gencon GC policy

This article will provide you detail on an important Java Heap space tuning consideration when migrating from a Java VM such as HotSpot or JRockit to the IBM JVM. This tuning recommendation is based on a recent troubleshooting and tuning mandate I performed for one of my IT clients.

IBM JVM overview

As you probably saw from my other articles, the IBM JVM is different than the HotSpot JVM in some aspects as it does not have a PermGen memory space for example. From a garbage collection perspective, it does provide you with advanced algorithms that can take advantage of a multi physical cores machine; similar to the HotSpot JVM.

From a troubleshooting perspective, IBM provides you with many tools; including out-of-the-box Thread Dump and Heap Dump generation capabilities from its JVM implementation.

The IBM JVM Thread Dump for example is particularly powerful as it provides you extra data on your JVM such as the active JVM environment variables, GC policies, loaded classes in each active class-loader etc. We will explore this in more detail on the part 4 of our Thread Dump Training plan.

IBM VM – default GC behaviour

Now back to our primary topic, it is very important that you understand the default behaviour of the IBM JVM garbage collector (version 1.5 & 1.6). By default, the Java Heap space is created using tenured memory only e.g. it does not create a separate YoungGen (nursery) space. This means that any memory allocation goes to the tenured space (short lived and long lived objects) which later gets collected by the default collector (via a Full GC).

** Please note that the IBM VM default GC policy has now been changed to gencon for JDK 1.7

Find below a verbose GC snapshot showing you the default GC memory breakdown with explanations:

<af type="tenured" id="5" timestamp="Mar 01 13:40:30 2012" intervalms="0.000">

  <minimum requested_bytes="48" />

  <time exclusiveaccessms="0.106" meanexclusiveaccessms="0.106" threads="0" lastthreadtid="0x000000011A846B00" />

  <tenured freebytes="20131840" totalbytes="2013265920" percent="0" >

    <soa freebytes="0" totalbytes="1993134080" percent="0" />

    <loa freebytes="20131840" totalbytes="20131840" percent="100" />

  </tenured>

  <gc type="global" id="8" totalid="2492" intervalms="2017588.587">

    <finalization objectsqueued="199" />

    <timesms mark="808.286" sweep="9.341" compact="0.000" total="818.292" />

    <tenured freebytes="1362331024" totalbytes="2013265920" percent="67" >

      <soa freebytes="1344212368" totalbytes="1995147264" percent="67" />

      <loa freebytes="18118656" totalbytes="18118656" percent="100" />

    </tenured>

  </gc>

  <tenured freebytes="1362330976" totalbytes="2013265920" percent="67" >

    <soa freebytes="1344212320" totalbytes="1995147264" percent="67" />

    <loa freebytes="18118656" totalbytes="18118656" percent="100" />

  </tenured>

  <time totalms="818.750" />

</af>

Ok, default IBM JVM GC policy is different… what is the problem?

The problem with this default JVM policy is that all Java objects are copied to the tenured space and collected via a global collection (Full GC). For many Java EE applications, the ratio of short lived vs. long lived objects is much higher. This means that your JVM will need to perform quite a lot of major collections to clean up the short lived objects; results: increased frequency of Full GC, increased JVM pause time, increased CPU utilization and performance degradation!

This is exactly what we observed while performing load testing following a migration to JVM HotSpot 1.5 (using incremental & parallel GC) to IBM JVM 1.6 with default GC policy. Heavy GC process was identified as the root cause as per the above explanation.

Solution please!

The good news is that the IBM JVM introduced generational & concurrent GC collector since version 1.5. This GC policy is providing exactly what we want:

-        It does split the Java Heap space between nursery and tenured spaces

-        Nursery (YoungGen) space objects are collected separately via the scavenger GC collector

-        Tenured space objects are collected via the global GC collector

-        The GC collector is concurrent and taking advantage of any multi physical cores machine

Results:

-        Reduced major collection frequency (Full GC)

-        Reduced Full GC elapsed time & pause time

-        Increase JVM throughput

-        Increase performance & capacity of your application

You can enable it by adding this JVM paremeter below:

-Xgcpolicy:gencon

Find below what you can expect in your verbose GC log after enabling this GC policy:

<af type="nursery" id="15" timestamp="Mar 08 05:34:06 2012" intervalms="1289096.227">

  <minimum requested_bytes="40" />

  <time exclusiveaccessms="0.085" meanexclusiveaccessms="0.085" threads="0" lastthreadtid="0x0000000118113900" />

  <refs soft="18043" weak="204057" phantom="27" dynamicSoftReferenceThreshold="32" maxSoftReferenceThreshold="32" />

  <nursery freebytes="0" totalbytes="530716672" percent="0" />

  <tenured freebytes="1887422016" totalbytes="2013265920" percent="93" >

    <soa freebytes="1786758720" totalbytes="1912602624" percent="93" />

    <loa freebytes="100663296" totalbytes="100663296" percent="100" />

  </tenured>

  <gc type="scavenger" id="15" totalid="15" intervalms="1289097.271">

    <flipped objectcount="1486449" bytes="129908000" />

    <tenured objectcount="1176" bytes="184144" />

    <finalization objectsqueued="3082" />

    <scavenger tiltratio="73" />

    <nursery freebytes="364304408" totalbytes="495208448" percent="73" tenureage="10" />

    <tenured freebytes="1886766656" totalbytes="2013265920" percent="93" >

      <soa freebytes="1786103360" totalbytes="1912602624" percent="93" />

      <loa freebytes="100663296" totalbytes="100663296" percent="100" />

    </tenured>

    <time totalms="233.886" />

  </gc>

  <nursery freebytes="364238872" totalbytes="495208448" percent="73" />

  <tenured freebytes="1886766656" totalbytes="2013265920" percent="93" >

    <soa freebytes="1786103360" totalbytes="1912602624" percent="93" />

    <loa freebytes="100663296" totalbytes="100663296" percent="100" />

  </tenured>

  <refs soft="17992" weak="5344" phantom="27" dynamicSoftReferenceThreshold="32" maxSoftReferenceThreshold="32" />

  <time totalms="236.858" />

</af>

Please keep in mind that it is still possible that your application may not benefit from this GC policy (bigger footprint of long lived objects etc.) so my recommendation to you is to always do your due diligence and perform proper capacity planning & load testing of your application before implementing any major tuning recommendations.

Conclusion

I hope this article has helped you understand the default IBM JVM 1.5/1.6 GC policy and how your Java EE application can benefit from this GC policy gencon tuning recommendation.

Please do not hesitate to post a comment or question at the end of this article. I’m also looking forward for your experience with the IBM JVM.

Read More

Java Heap Space – IBM VM

This short article will provide you with a high level overview of the different Java memory spaces for the IBM VM. 

This understanding is quite important given the implementation & naming convention differences between HotSpot & IBM VM.

IBM VM: 2 different memory spaces

The IBM VM memory is split between 2 memory spaces:

-        The Java Heap (nursery and tenured spaces)

-        The Native Heap (C-Heap)

Memory Space	Start-up arguments and tuning	Monitoring strategies	Description
Java Heap	-Xmx (maximum Heap space) -Xms (minimum Heap size) EX: -Xmx1024m -Xms1024m GC policy Ex: -Xgcpolicy:gencon (enable gencon GC policy)	- verbose GC - JMX API - IBM monitoring tools	The IBM Java Heap is typically split between the nursery and tenured space (YoungGen, OldGen). The gencon GC policy (combo of concurrent and generational GC) is typically used for Java EE platforms in order to minimize the GC pause time.
Native Heap  (C-Heap)	Not configurable directly. For a 32-bit VM, the C-Heap capacity = 4 Gig – Java Heap For a 64-bit VM, the C-Heap capacity = Physical server total RAM & virtual memory – Java Heap	- svmon command	The C-Heap is storing class metadata objects including library files, other JVM and third party native code objects.

 Where is the PermGen space?

This is by far the most typical question I get from Java EE support individuals supporting an IBM VM environment for this first time. The answer: there is no PermGen space for the IBM VM. The PermGen space is only applicable to the HotSpot VM. The IBM VM is using the Native Heap for Class metadata related data. Also, as you probably saw from my other article, Oracle / Sun is also starting to remove the PermGen space for the HotSpot VM.

The next article will provide you a tutorial on how to enable and analyze verbose GC for an IBM VM. Please feel free to post any comment or question on the IBM VM.

Read More