Understanding Thread Dumps in Mulesoft

A thread dump is a snapshot of all the active threads in a running Java Virtual Machine (JVM) or similar environments at a particular moment in time. It captures the state of each thread, including what it is doing, whether it is blocked, waiting, or running, and provides a detailed view of the call stack for each thread.

Thread dumps are useful in situations where your Mule application is experiencing performance issues, such as high CPU usage, deadlocks, or unresponsive behavior.

For each thread in the thread dump we’ll find the following info:

Thread ID: A unique identifier for each thread.
Thread Name: The name of the thread, often assigned by the developer or the system.
Thread State: The current state of the thread, such as:

RUNNABLE: The thread is currently executing or ready to execute.
BLOCKED: The thread is waiting for a monitor lock to enter a synchronized block or method.
WAITING: The thread is waiting indefinitely for another thread to perform a particular action.
TIMED_WAITING: The thread is waiting for another thread to perform an action for up to a specified waiting time.
TERMINATED: The thread has completed execution.

Stack Trace: For each thread, the dump includes a stack trace similar to a regular stack trace, showing the method calls that the thread is executing or waiting on.
Lock Information: If a thread is blocked or waiting, the dump may include information about the lock it is trying to acquire and the thread currently holding that lock.

When to use Thread Dumps

Debugging Performance Issues: Thread dumps are particularly useful for diagnosing performance problems, such as deadlocks, where multiple threads are blocked waiting on each other, or identifying which threads are consuming the most CPU. We would use the info in the Thread dump to:

Identify Bottlenecks: We would look for threads that are in a BLOCKED or WAITING state to identify potential deadlocks or resource contention issues
Check CPU Usage: If certain threads are in a RUNNABLE state and consuming excessive CPU, investigate the code or flow components involved.
Analyze Resource Usage: See how threads are utilizing resources like database connections, HTTP calls, or external APIs.
Find Long-Running Threads: Identify any threads that have been running for an unusually long time, which might indicate a stuck process or an inefficient operation.

Analyzing System Behavior: By capturing thread dumps at different times, you can analyze how the application behaves under load or identify bottlenecks.
Monitor Trends: Regularly monitor thread dumps in production to spot trends before they escalate into major issues.
Production Monitoring: Thread dumps can be triggered and analyzed during production to investigate issues without stopping the application
Working with Support: In some cases, the Mulesoft support team will ask you to get a thread dump and send it for further analysis. For that you’d probably need to reproduce the issue and capture the thread dump at different intervals to compare and understand the progression of the issue

Example

Let’s see an example

"Flow-Worker-5" #50 prio=5 os_prio=0 tid=0x00007f8468429000 nid=0x4b2 waiting for monitor entry [0x00007f8449ff8000]
   java.lang.Thread.State: BLOCKED (on object monitor)
    at org.mule.runtime.core.internal.processor.AsyncRequestReplyObjectStore.tryAcquireLock(AsyncRequestReplyObjectStore.java:116)
    - waiting to lock <0x000000076c8a1ef0> (a java.util.concurrent.locks.ReentrantLock$NonfairSync)
    at org.mule.runtime.core.internal.processor.AsyncRequestReplyObjectStore.store(AsyncRequestReplyObjectStore.java:66)
    at org.mule.runtime.core.internal.processor.AsyncRequestReplyProcessor.lambda$create$1(AsyncRequestReplyProcessor.java:87)
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)
    at java.lang.Thread.run(Thread.java:834)

"MuleSoftScheduler_Worker-3" #68 prio=5 os_prio=0 tid=0x00007f8468457000 nid=0x4b7 waiting on condition [0x00007f84497f5000]
   java.lang.Thread.State: TIMED_WAITING (parking)
    at sun.misc.Unsafe.park(Native Method)
    - parking to wait for <0x000000076c8a5fd0> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
    at java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:338)
    at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.awaitNanos(AbstractQueuedSynchronizer.java:2061)
    at java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(ScheduledThreadPoolExecutor.java:1177)
    at java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(ScheduledThreadPoolExecutor.java:899)
    at java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1054)
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1114)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)
    at java.lang.Thread.run(Thread.java:834)

"HTTP Listener" #22 prio=5 os_prio=0 tid=0x00007f846844c000 nid=0x4b0 runnable [0x00007f844a9fa000]
   java.lang.Thread.State: RUNNABLE
    at org.glassfish.grizzly.nio.transport.TCPNIOTransport.read(TCPNIOTransport.java:484)
    at org.glassfish.grizzly.nio.transport.TCPNIOTransportFilter.handleRead(TCPNIOTransportFilter.java:192)
    at org.glassfish.grizzly.filterchain.ExecutorResolver$8.execute(ExecutorResolver.java:95)
    at org.glassfish.grizzly.filterchain.DefaultFilterChain.executeFilter(DefaultFilterChain.java:260)
    at org.glassfish.grizzly.filterchain.DefaultFilterChain.executeChainPart(DefaultFilterChain.java:177)
    at org.glassfish.grizzly.filterchain.DefaultFilterChain.execute(DefaultFilterChain.java:109)
    at org.glassfish.grizzly.filterchain.DefaultFilterChain.process(DefaultFilterChain.java:88)
    at org.glassfish.grizzly.ProcessorExecutor.execute(ProcessorExecutor.java:53)
    at org.glassfish.grizzly.nio.transport.TCPNIOTransport.fireIOEvent(TCPNIOTransport.java:510)
    at org.glassfish.grizzly.strategies.AbstractIOStrategy.fireIOEvent(AbstractIOStrategy.java:82)
    at org.glassfish.grizzly.strategies.WorkerThreadIOStrategy.run0(WorkerThreadIOStrategy.java:118)
    at org.glassfish.grizzly.strategies.WorkerThreadIOStrategy.access$100(WorkerThreadIOStrategy.java:56)
    at org.glassfish.grizzly.strategies.WorkerThreadIOStrategy$WorkerThreadRunnable.run(WorkerThreadIOStrategy.java:142)
    at org.glassfish.grizzly.threadpool.AbstractThreadPool$Worker.doWork(AbstractThreadPool.java:593)
    at org.glassfish.grizzly.threadpool.AbstractThreadPool$Worker.run(AbstractThreadPool.java:573)
    at java.lang.Thread.run(Thread.java:834)

Identifying the Components in the Thread Dump

Thread Name and ID:

"Flow-Worker-5": This thread is likely associated with a worker processing a flow in MuleSoft.
#50: This is the thread’s ID.
prio=5: Indicates the thread's priority.
tid=0x00007f8468429000 and nid=0x4b2: The thread identifier and native thread ID.
waiting for monitor entry: Indicates that the thread is waiting to enter a synchronized block (trying to acquire a lock).

Thread State:

java.lang.Thread.State: BLOCKED (on object monitor): This means the thread is blocked because it’s waiting to acquire a lock that is held by another thread.
at org.mule.runtime.core.internal.processor.AsyncRequestReplyObjectStore.tryAcquireLock(AsyncRequestReplyObjectStore.java:116): The stack trace shows that the thread is trying to acquire a lock to perform a store operation, but it’s currently blocked.

Waiting to Lock:

- waiting to lock <0x000000076c8a1ef0>: The thread is waiting to acquire a lock on a ReentrantLockobject, which is currently held by another thread.

Thread Handling a MuleSoft Scheduler:

"MuleSoftScheduler_Worker-3": This thread is associated with a scheduler in MuleSoft.
TIMED_WAITING (parking): This indicates that the thread is in a timed waiting state, often seen when threads are waiting for a scheduled task to execute.
at java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(ScheduledThreadPoolExecutor.java:1177): The thread is waiting for the next task to be scheduled from the executor's work queue.

Runnable Threads:

"HTTP Listener" #22: This thread is actively processing HTTP requests.
java.lang.Thread.State: RUNNABLE: The thread is currently running and handling I/O operations, as indicated by its interaction with the Grizzly NIO transport.

Call Stack for HTTP Listener:

at org.glassfish.grizzly.nio.transport.TCPNIOTransport.read(TCPNIOTransport.java:484): This shows that the thread is currently involved in reading data over a TCP connection, which is part of the HTTP Listener's processing.
Subsequent lines show the sequence of method calls from the Grizzly framework down to the AbstractThreadPool class, where the thread is executing tasks.

So, in summary, from the info we got in the Thread dump we can conclude that:

"Flow-Worker-5": This thread is blocked because it is waiting to acquire a lock. This could indicate a potential bottleneck or deadlock scenario if the lock is held for too long.
"MuleSoftScheduler_Worker-3": This thread is waiting for the next scheduled task, indicating normal behavior for a scheduled task executor.
"HTTP Listener": This thread is actively processing an HTTP request, showing it is in a RUNNABLE state and is not blocked.

How to get thread dumps in CH1.0

Go to the Logs section of your application
On the right panel you’ll see the workers deployed for that app. Click on the worker(s) you want to get the thread dumps for.
You’ll see three options. The Diagnostics option is the one to download the thread dump. Click on that and a file will be automatically downloaded

How to get thread dumps in CH2.0

In CH2.0 the way to get the thread dumps is slightly different. To do that, we need to go to the Diagnostics section of our mule app, and from there click on the dropdown Run Thread Dump. One of the cool things in CH2.0 is that the platform will keep the thread dumps you run available during 30 days along with the logs of that particular point in time. Pretty cool.

Summary

Thread dumps are invaluable for understanding the internal workings of a multi-threaded application like mule apps at runtime, especially in integration scenarios where multiple systems and apps are interacting simultaneously.

By effectively utilizing stack traces and thread dumps, you can significantly enhance your ability to troubleshoot and optimize your MuleSoft applications.