Working With Thread Logic : A Thread Dump Analysis Tool

Thread Dump analysis is key tool for analyzing the Performance issues and troubleshooting many Issues. Currently available tools like samurai says about the state of the Thread , they does not give detailed view of what a thread is doing.

In most cases , they dont mention what was happening inside a Thread , whether they are critical or normal. Are there any optimization's that can be performed on these.

ThreadLogic is a Tool which provides options for performing the above.Thread Logic Comes in a form of Jar File.We need to manually run the file using “java -jar threadLogic.jar”

Once the GUI is open , we can select a Thread Dump file to open. Once you open a file the starting screen will be like

We can see all the Threads , threads which are waiting for Monitors, sleeping threads , locking threads e.t.c.

Once we click on the Dump No.1 , we can see a Information about the Thread Dump and also about the Threads information below like

The main important one is the “Advisory level”.Once a thread dump is parsed and threads details are populated, each of the thread is then analyzed against matching advisories and tagged appropriately.

If you click on the “Advisory map” link you can see

Which gives you various level of information.

Each of the advisory has a health level indicating severity of the issue found, pattern, name, keyword and related advice.

If you click on the Threads with an health (consider Fatal ) , we can see information regarding the thread like

Thread Logic also gives an advice on how to handle that. The Advisory gets trigged based on either call execution patterns that are found inside the thread stack of by other conditions inside the Thread Dump

The health levels (in descending of severity) are FATAL (meant for Deadlocks, STUCK, Finalizer blocked etc), WARNING, WATCH (worth watching), NORMAL and IGNORE.

Thread Groups

The threads are associated with thread groups based on the functionality or thread names. We can see thread Groups like

As we can see this is a Weblogic Thread dump , there is a group which says “WLS Thread Groups” with 40 threads. Clicking on the Groups gives you more insight like

One can see the thread groups are divided into two buckets - WLS and non-WLS related threads. The JVM threads, LDAP and other unknown custom threads go under the non-WLS bucket while all the WLS, Muxer, ADF, Coherence, Oracle, SOA, JMS, Oracle Adapter threads are all under the WLS bucket.

Using Thread Logic We can get more Information on how Threads Especially In Weblogic Work.

Happy learning :-)

Read More

org.jboss.virtual.plugins.context.zip.zipentrycontext Issue in Jboss 5.0.0.GA

The application team was complaining that they are seeing a lot of Out Of Memory When they try to deploy the application more than 3 times.

Now we Got the Heap Dump and checked the instances that were causing the heap To Full.

I found out that "org.jboss.virtual.plugins.context.zip.zipentrycontext" are being loaded and

causing the memory to fill.

As The references of "org.jboss.virtual.plugins.context.zip.zipentrycontext" are being loaded

highly and are taking more space in heap.

The reason for this is the VFS ( Virtaul File System) In Jboss. This Uses the temp location in JBoss to cache copies of Deployment Units as to speed up the performance of the

application Server.This also causes

the "org.jboss.virtual.plugins.context.zip.zipentrycontext" to load in to memory.

Besides that the default configuration for the VFS Cache repeatedly creates the Context

Objects and once it times out and these objects are ready for Finalization the GC could not

finalize these objects completely causing the heap To Grow faster

The Element that effects this was to prevent the caching of all deployment units and

cleaning up the Context objects are in

/config/jboss/ewp/5.0/domains/<Server>/conf/bootstrap/vfs.xml ( One of the Core File

For Changing the Virtual File Settings)

We need to change the Element realCache from IterableTimedVFSCache to

TimedVFSCache.

<property name="realCache">

<bean class="org.jboss.virtual.plugins.cache.TimedVFSCache"/>

<!-- <bean class="org.jboss.virtual.plugins.cache.IterableTimedVFSCache"/> -->

</property>

Once the Changes are done these Classes will not be loaded heavily .This is solved in Jboss 5.1.0

Happy learning :-)

Read More

Linux Core and Java JMAP

When Generating heap dumps jmap blocks, and with large heaps  this can take a very long time. In these cases it is often much faster to get a core and then run jmap to extract a heap dump from the core. It is typically best to create the heap dump on the same box where the core was created to avoid environment differences.

So what is Core Dump?

When a program terminated abnormally, the status of the program at the point of termination should be saved some where for further analysis.This status is recorded in the form of a Core Dump File.

The core dump file contains details of where the abnormal termination happened, process stack, symbol table etc.

How can I make sure the core dump will be saved?

Each process has a limit for how big this core can be. If the limit is exceeded no core dump will be saved. By default this limit is 0 , that means no core will be dumped by default.

We need to use the “ulimit” command in linux to find the core file limitations. The “Ulimit” command sets various limits for the current process.

Check the core file size limitations

[root@vx111a ~]# ulimit -a | grep core
core file size          (blocks, -c) 0

Since “0” nothing can be saved.

[root@vx111a ~]# ulimit -c unlimited

Change the limitation to unlimited

[root@vx111a ~]# ulimit -a | grep core
core file size          (blocks, -c) unlimited

Once we change the limitation, we generate a core dump using the “gdb” command available in linux.

GDB command is to allow you to see what is going on inside another program while it executes or what another program was doing at the moment it crashed.

So I started a Java Class called “TestOome” like

[root@vx111a ~]# /usr/jdk1.6.0_14/bin/java -Xms1500m -Xmx1500m TestOome &

[1] 4588

Now iam going to attach the gdb to the process 4588 like

[root@vx111a ~]# gdb --pid=4588

GNU gdb (GDB) Red Hat Enterprise Linux (7.0.1-32.el5)

Copyright (C) 2009 Free Software Foundation, Inc.

License GPLv3+: GNU GPL version 3 or later <http://gnu.org/licenses/gpl.html>

This is free software: you are free to change and redistribute it.

There is NO WARRANTY, to the extent permitted by law.  Type "show copying"

and "show warranty" for details.

This GDB was configured as "i386-redhat-linux-gnu".

For bug reporting instructions, please see:

<http://www.gnu.org/software/gdb/bugs/>.

Attaching to process 4588

Reading symbols from /usr/jdk1.6.0_14/bin/java...(no debugging symbols found)...done.

Reading symbols from /lib/libpthread.so.0...(no debugging symbols found)...done.

[Thread debugging using libthread_db enabled]

[New Thread 0x51953b90 (LWP 4599)]

[New Thread 0x519a4b90 (LWP 4598)]

[New Thread 0x51a25b90 (LWP 4597)]

[New Thread 0x51aa6b90 (LWP 4596)]

[New Thread 0x51af7b90 (LWP 4595)]

[New Thread 0x51d48b90 (LWP 4594)]

[New Thread 0x51d99b90 (LWP 4593)]

[New Thread 0x51e1ab90 (LWP 4592)]

[New Thread 0x52064b90 (LWP 4591)]

[New Thread 0x520e5b90 (LWP 4590)]

[New Thread 0xb7419b90 (LWP 4589)]

Loaded symbols for /lib/libpthread.so.0

Reading symbols from /usr/jdk1.6.0_14/bin/../jre/lib/i386/jli/libjli.so...(no debugging symbols found)...done.

Loaded symbols for /usr/jdk1.6.0_14/bin/../jre/lib/i386/jli/libjli.so

Reading symbols from /lib/libdl.so.2...(no debugging symbols found)...done.

Loaded symbols for /lib/libdl.so.2

Reading symbols from /lib/libc.so.6...(no debugging symbols found)...done.

Loaded symbols for /lib/libc.so.6

Reading symbols from /lib/ld-linux.so.2...(no debugging symbols found)...done.

Loaded symbols for /lib/ld-linux.so.2

Reading symbols from /usr/jdk1.6.0_14/jre/lib/i386/server/libjvm.so...(no debugging symbols found)...done.

Loaded symbols for /usr/jdk1.6.0_14/jre/lib/i386/server/libjvm.so

Reading symbols from /lib/libm.so.6...(no debugging symbols found)...done.

Loaded symbols for /lib/libm.so.6

Reading symbols from /lib/librt.so.1...(no debugging symbols found)...done.

Loaded symbols for /lib/librt.so.1

Reading symbols from /usr/jdk1.6.0_14/jre/lib/i386/libverify.so...(no debugging symbols found)...done.

Loaded symbols for /usr/jdk1.6.0_14/jre/lib/i386/libverify.so

Reading symbols from /usr/jdk1.6.0_14/jre/lib/i386/libjava.so...(no debugging symbols found)...done.

Loaded symbols for /usr/jdk1.6.0_14/jre/lib/i386/libjava.so

Reading symbols from /lib/libnsl.so.1...(no debugging symbols found)...done.

Loaded symbols for /lib/libnsl.so.1

Reading symbols from /usr/jdk1.6.0_14/jre/lib/i386/native_threads/libhpi.so...(no debugging symbols found)...done.

Loaded symbols for /usr/jdk1.6.0_14/jre/lib/i386/native_threads/libhpi.so

Reading symbols from /lib/libnss_files.so.2...(no debugging symbols found)...done.

Loaded symbols for /lib/libnss_files.so.2

Reading symbols from /usr/jdk1.6.0_14/jre/lib/i386/libzip.so...(no debugging symbols found)...done.

Loaded symbols for /usr/jdk1.6.0_14/jre/lib/i386/libzip.so

0xb7f72402 in __kernel_vsyscall ()

(gdb) gcore

Saved corefile core.4588

(gdb) detach

Detaching from program: /usr/jdk1.6.0_14/bin/java, process 4588

(gdb) quit

The last 3 commands are basically important ,

Gcore : generated the Core file

Detach : detaches the gdb from process ID 4588

Quit : quit

Now we can see that the core file Is generated like

[root@vx111a ~]# file core.4588

core.4588: ELF 32-bit LSB core file Intel 80386, version 1 (SYSV), SVR4-style, from 'java'

There is another way to generate the Core file using

[root@vx111a ~]# kill -SIGABRT 4705

Now we need to create a heap dump from this core file usimg “jmap” like

jmap -heap:format=b JAVA_HOME/bin/java COREFILE > heap.hprof 2>&1

Now we can perform many other function on this core file like

To get Thread Dumps information

[root@vx111a ~]# /usr/jdk1.6.0_14/bin/jstack  /usr/jdk1.6.0_14/bin/java core.4588

Attaching to core core.4588 from executable /usr/jdk1.6.0_14/bin/java, please wait...

Debugger attached successfully.

Server compiler detected.

JVM version is 14.0-b16

Deadlock Detection:

No deadlocks found.

Thread 4595: (state = BLOCKED)

Thread 4594: (state = BLOCKED)

 - java.lang.Object.wait(long) @bci=0 (Interpreted frame)

 - java.lang.ref.ReferenceQueue.remove(long) @bci=44, line=118 (Interpreted frame)

 - java.lang.ref.ReferenceQueue.remove() @bci=2, line=134 (Interpreted frame)

 - java.lang.ref.Finalizer$FinalizerThread.run() @bci=3, line=159 (Interpreted frame)

Thread 4593: (state = BLOCKED)

 - java.lang.Object.wait(long) @bci=0 (Interpreted frame)

 - java.lang.Object.wait() @bci=2, line=485 (Interpreted frame)

 - java.lang.ref.Reference$ReferenceHandler.run() @bci=46, line=116 (Interpreted frame)

Thread 4589: (state = BLOCKED)

 - java.util.Arrays.copyOf(java.lang.Object[], int, java.lang.Class) @bci=8, line=2760 (Interpreted frame)

 - java.util.Arrays.copyOf(java.lang.Object[], int) @bci=6, line=2734 (Interpreted frame)

 - java.util.ArrayList.ensureCapacity(int) @bci=51, line=167 (Compiled frame)

 - java.util.ArrayList.add(java.lang.Object) @bci=7, line=351 (Compiled frame)

 - TestOome.main(java.lang.String[]) @bci=23, line=15 (Compiled frame)

To get the Heap Details ,jmap examnes a core file and prints out the shared object memory maps or heap details

[root@vx111a ~]# /usr/jdk1.6.0_14/bin/jmap  /usr/jdk1.6.0_14/bin/java core.4588

Attaching to core core.4588 from executable /usr/jdk1.6.0_14/bin/java, please wait...

Debugger attached successfully.

Server compiler detected.

JVM version is 14.0-b16

0x08048000      46K     /usr/jdk1.6.0_14/bin/java

0x00887000      134K    /lib/libpthread.so.0

0xb7f58000      37K     /usr/jdk1.6.0_14/bin/../jre/lib/i386/jli/libjli.so

0x00880000      20K     /lib/libdl.so.2

0x006fa000      1654K   /lib/libc.so.6

0x006db000      126K    /lib/ld-linux.so.2

0xb741a000      8965K   /usr/jdk1.6.0_14/jre/lib/i386/server/libjvm.so

0x00855000      211K    /lib/libm.so.6

0x008b7000      47K     /lib/librt.so.1

0xb7f65000      55K     /usr/jdk1.6.0_14/jre/lib/i386/libverify.so

0xb73a4000      184K    /usr/jdk1.6.0_14/jre/lib/i386/libjava.so

0x00924000      107K    /lib/libnsl.so.1

0xb739d000      37K     /usr/jdk1.6.0_14/jre/lib/i386/native_threads/libhpi.so

0xb7381000      49K     /lib/libnss_files.so.2

0xb7370000      74K     /usr/jdk1.6.0_14/jre/lib/i386/libzip.so

Happy learning J

Read More

Java Dumps

As a Production Support Guy ,I many times faced the out of Memory(OOM) Issues. Most of times I take a Thread dump, Heap Dump before doing any thing to the server. I analyze the dumps to find out the possible problems that caused the out of Memory.

So what are these Dumps?

Thread Dump, a Thread Dump is a log containing information about currently running threads inside the JVM

Heap Dump, a Heap Dump is a log which contains the memory structure of the JVM with all the classes and objects inside the JVM and their memory usage

Core Dump, A Core Dump is recorded state of the working memory of a program at the specific time. This is generated generally when a program has been terminated abnormally.

Generating these dumps is always necessary for analyzing the issues.

Heap Dump

As is said A JVM heap dump is basically a “snapshot” of the Java heap memory at a given time. It is quite different than a JVM thread dump which is a snapshot of the threads.

Generating a Heap Dump can be done by using the “jmap” command available in the java software.

jmap -dump:format=b,file=heap.hprof JAVA_PID

For Oracle Jrocket we can use

jrcmd <JAVA_PID> hprofdump filename=abc.hprof

So Consider generating a heap Dump Files for the Process ID 22979.

Dev:vx1379:djbs002-jas $ jmap -dump:file=my_stack.bin 22979

Dumping heap to /config/jboss/ews/1.0/domains/jas/my_stack.bin ...

Heap dump file created

It’s easy to get an OutOfMememory exception when opening the java heap. The dump file can be very memory consuming if you application was in the moment it was taken. If you experience the problem you should give to the JVM as much memory as you can:

Most of the times the heap dumps are generated with the .hprof extension.

What is HProf?

HProf is a tool built into JDK for profiling the CPU and heap usage within a JVM. A Java process crash may produce an hprof file containing a heap dump of the process at the time of the failure.

So Once the Heap Dump is generated we need to analyze the file. Java provides a tool called “jhat” which helps in heap analysis.

Now in order to work with jhat to analysis the heap file we use,

jhat -J-mx2000m my_stack.bin

When we run this command we see,

Dev:vx1232:jbs002-jas $ jhat -J-mx2000m my_stack.bin

Reading from my_stack.bin...

Dump file created Sun May 12 23:56:01 CDT 2013

Snapshot read, resolving...

Resolving 1548901 objects...

Chasing references, expect 309 dots .....................................................................................................................................................................................................................................................................................................................

Eliminating duplicate references .....................................................................................................................................................................................................................................................................................................................

Snapshot resolved.

Started HTTP server on port 7000

Server is ready.

This says that the jhat Server is started. We can access the Server using

http://vx1232:7000/

Now we can point another port as

jhat -port 7010 -J-Xmx1G my_stack.bin

Now the Jhat web console is open, we can see “Object Query Language” Link at the End.

A SQL-like query language to query Java heap. OQL allows to filter/select information wanted from Java heap. OQL is based on JavaScript expression language.

A few queries would be

select i from [Ljava.lang.Object; i where i.length == 10

select all Strings of length 100 or more

show path value of all File objects

select file.path.toString() from java.io.File file

show names of all ClassLoader classes

access static field 'props' of class java.lang.System

select heap.findClass("java.lang.System").statics.props

select heap.findClass("java.lang.System").props

select heap.findClass("java.lang.String").fields.length

find the object whose object id is given

select all classes that have name pattern java.net.*

Happy Learning J

Read More

Muxer Threads

Many Of the Times when there is a Server Crash, We take a Thread dump and analyze the threads running. During that time we see many threads like these

"ExecuteThread: '0' for queue: 'weblogic.socket.Muxer'" id=20 idx=0x68 tid=26709 prio=5 alive, in native, blocked, daemon

    -- Blocked trying to get lock: java/lang/String@0x2b673d373c50[fat lock]

    at jrockit/vm/Threads.waitForUnblockSignal()V(Native Method)

    at jrockit/vm/Locks.fatLockBlockOrSpin(Locks.java:1675)[optimized]

    at jrockit/vm/Locks.lockFat(Locks.java:1776)[optimized]

    at jrockit/vm/Locks.monitorEnterSecondStageHard(Locks.java:1312)[optimized]

    at jrockit/vm/Locks.monitorEnterSecondStage(Locks.java:1259)[optimized]

    at jrockit/vm/Locks.monitorEnter(Locks.java:2439)[optimized]

    at weblogic/socket/EPollSocketMuxer.processSockets(EPollSocketMuxer.java:153)

    at weblogic/socket/SocketReaderRequest.run(SocketReaderRequest.java:29)

    at weblogic/socket/SocketReaderRequest.execute(SocketReaderRequest.java:42)

    at weblogic/kernel/ExecuteThread.execute(ExecuteThread.java:145)

    at weblogic/kernel/ExecuteThread.run(ExecuteThread.java:117)

    at jrockit/vm/RNI.c2java(JJJJJ)V(Native Method)

 These are called “Muxer Threads”. These are the Special Threads in Web logic Server to read incoming request from external entities on the servers. The main usage is to read the incoming request and then pass them to either “execute Thread” or “work Manager”.

Weblogic allocates a percentage of the Thread pool for these pools.The default value is 33% and not more than 50%.

We can assign the value using –Dweblogic.SocketReader=<Value>

Socket Muxer Threads

The Socket Muxer (SM) Threads are threads that manage the existing Server socket connections.

It first checks the sockets and find which socket has an incoming request which needs to be processed ( waiting to be processed).Then It reads data like protocol and then it dispatches the socket that to the run time layer which will process that.

In the run time layer, the SM will identify the Execute Queue that needs to be used for the Socket.

There are 2 types of SM Threads In Weblogic

Native SM & Java SM

Native SM [need to “enable Native I/O” in Weblogic console]: Native SM provides better performance scalability since they use the non blocking thread model. When Native I/O is used the server creates a fixed number of threads especially for reading the incoming socket requests.

Java SM: This uses pure java based threads. These are only available muxer for RMI clients. This is not a suitable one since they blocks on read until there is a data to be read from socket. This can cause bottleneck to the Server.

How can we find which SM is being used?

When we check the Thread Dump,if we see

NTSocketMuxer : Native SM
Weblogic.Socket.Muxer : Java SM

Read More

JRocket vs. SUN JDK

SUN JDK	JRocket
Uses Interpreter Interpreter interprets (executes) one line at a time from the source file. Such as PHP, Perl, other scripting languages The byte code is read and the translated into machine language, but these results are not saved in the memory. So every time even if the same method is run again and again, the JVM has to translate the code into machine language. This means machine code will not be reusable as it is not saved anywhere in the memory. Due to this mechanism the server startup is fast because it will not save the machine code in memory	Uses JIT Compiler Compiler transforms one language into another. For example, C# into IL, Java into byte code, C++ into binary machine code. No execution happens at the compilation stage. Once a method is run, the byte code is translated to machine language and this is saved in the memory. This means if the method is run again, there is no need for translation and the machine code is reused. In this case the server will take a little more time since the machine code needs to be saved inside the memory. but we get a better performance when the application running since the machine instructions are already saved in memory and no need to re compile them again.
JIT is also used by Sun JDK, but that was in the earlier versions.	Also Uses a Hotspot mechanism by which it finds methods that are very often used and optimizes them for better performance. Many Issues are seen during this phase, options are available for disabling these.
SUN JDK has many memory spaces like Eden, Permanent ,Survivor spaces where objects move between them	JRocket has just Young and Old Spaces. No Permanent Spaces. The JRockit Native memory space is storing the Java Classes metadata, Threads and objects such as library files, other JVM and third party native code objects.
SUN JDK has no such facilities	JRocket has self tuning system , in cases such as Out Of Memory due to native TLA due to insufficient TLA which is 2kb in size, it takes case of such things by auto tuning these settings if the application needs
During Crash , SUN JDK generates hr_err.pid file	Generates dump file which contains the reason for the crash
	JRocket has tools to analyze the JVM performance with low over head.

Read More