Analyzing Thread Dump Made Easy

All application these days are multi threaded applications . Analyzing thread dumps in from production can really get tedious. The applications using various frameworks and increased usage of asynchronous programming has made analyzing thread dumps a night mare.

I have been analyzing thread dumps for a  couple of years and that has been my favorite activity so far. Definitely you have to reconcile couple of other evidences to nail down the actual issue. But getting all possible details from the thread dump helps find pin point the issue faster.

This blog is not to explain how to analyse thread dumps. Instead this explains a simple trick to ease out the analysis of thread dumps. 

What is the first issue you see analyzing thread dumps?
1. To decide whether a thread is hanging or processing for a long time. 
2. Which thread is waiting on which thread?

Resolving issue 1 is much easier. Having proper thread state helps resolve that problem. 
For example:

Before:
"Thread 1" #3456 prio=5 os_prio=0 tid=0x4400b9000000 nid=0x1d908
java.lang.Thread.State: RUNNABLE

After:
"Dataload-Thread-564, TaskId:23456, Started At:2018-06-26 18:10:30" #3456 prio=5 os_prio=0 tid=0x4400b9000000 nid=0x1d908
java.lang.Thread.State: RUNNABLE

Seeing above, I know that the thread is doing a dataload job from 2018-06-26 18:10:30

The code change is very simple to add the state information in the name. I have introduced a method in my task processing frame work which will be called before starting any processing.

public void registerTaskStart()
{
        Date date = new Date();
        SimpleDateFormat df = new SimpleDateFormat("yyyy-MM-dd HH:mm:ss");
       String name = getThreadPoolName()+", TaskId="+getTaskId()+", Started At:"+df.format(date); 

      //The below line does the magic.
       Thread.currentThread().setName(name);
}

Now, let us see how to resolve the Issue 2. Take a look at below example. There are 2 threads which are WAITING. Behind the scene the Dataload-Thread-564 is waiting on Dataload-Thread-678. But from the thread dump, there is no such clue.

"Dataload-Thread-564, TaskId:23456, Started At:2018-06-26 18:10:30" #3456 prio=5 os_prio=0 tid=0x4400b9000000 nid=0x1d908
java.lang.Thread.State: WAITING (parking)
at java.util.concurrent.locks.LockSupport.park(LockSupport.java:175)
at java.util.concurrent.FutureTask.awaitDone(FutureTask.java:429)
at java.util.concurrent.FutureTask.get(FutureTask.java:191)
at com.bha.thread.dataload.TransactionLoader.loadFromDatabase(TransactionLoader:403)

"Dataload-Thread-678, TaskId:56789, Started At:2018-06-26 18:10:50" #3456 prio=5 os_prio=0 tid=0x4400b9000000 nid=0x1d908
java.lang.Thread.State: WAITING (parking)
at java.util.concurrent.locks.LockSupport.park(LockSupport.java:175)
at java.util.concurrent.FutureTask.awaitDone(FutureTask.java:429)
at java.util.concurrent.FutureTask.get(FutureTask.java:191)
at com.bha.thread.dataload.AccountTypeLoader.waitForFuture(AccountTypeLoader:213)

Just a simple change in the thread name to add parent task id can help resolve such chain of waiting threads. This also can be achieved by adding the right details in the thread name.

"Dataload-Thread-678, TaskId:23456->56789, Started At:2018-06-26 18:10:50" #3456 prio=5 os_prio=0 tid=0x4400b9000000 nid=0x1d908
java.lang.Thread.State: WAITING (parking)
at java.util.concurrent.locks.LockSupport.park(LockSupport.java:175)
at java.util.concurrent.FutureTask.awaitDone(FutureTask.java:429)
at java.util.concurrent.FutureTask.get(FutureTask.java:191)
at com.bha.thread.dataload.AccountTypeLoader.waitForFuture(AccountTypeLoader:213)






Comments

Post a Comment

Popular posts from this blog

Java Object Size

Image
Do you really know the size of your object? I was curious to see where I was loosing so much memory in my application when I knew the objects size based on the fields within. This provoked me to write a blog on understanding object structure and calculating its size. All throughout the blog, I have used a class called MSMemory. The fields in the class keep changing to explain size for each. Configuration: OS: Windows RAM: 16GB JDK: .8.0_171 64 bit I use jmap to get the heap dump. The command is below (Use jps to get the java process id): jmap -dump:format=b,file=heap.bin <java_process_id> Then i use jhat to analyse the heap dump. The command is below: jhat heap.bin Jhat starts a HTTP server on port 7000 by default. Port number is configurable. 1. Class MSMemory has no fields. Size is for one instance of MSMemory. public class MSMemory {} /*Main class*/ public class MemoryAnalyser { public static void main(String[] args) { MSMemory memory = new MSM...
Read more

Does wait() method have to be called from synchronized method or block?

Does wait() method have to be called from synchronized method or block? Yes, It has to be.  It throws IllegalMonitorStateException otherwsie. I have explained the answer with a vanilla implementation of producer consumer problem. I have used one thread  each.  THe program uses a boolen flag, so the capacity is just one item. In this case let us assume if the wait in producer was called without synchronized block, then there are high chances that the consumer thread can interfere and  producer thread can go to invariable wait. This is called missing communications/signals. To avoid this, we should always call wait(), notify() and notifyAll() inside synchronized block. import java.util.concurrent.locks.ReentrantLock; public class MSProducerConsumer { private volatile boolean flag = false; ReentrantLock lock = new ReentrantLock(); void produce() { try { while(true) { synchronized (this) { try { lock.lock(); while(fl...
Read more