Handling and Resolving Performance Issues in Java Multithreaded Applications I: Using Thread Dumps
In Java, performance issues can be identified and resolved using built-in JVM commands which can be used to extract useful information from the JVM and correlate it to pinpoint and address the problem. While there are advanced monitoring tools like Dynatrace available, this article focuses on freely available methods and tools to diagnose performance issues in multithreaded Java applications using thread dumps.
Capturing multiple thread dumps allows us to observe the thread state and stack trace changes over time. For instance, if your application processes a single transaction in 2 seconds, but occasionally takes up to 10 seconds, you’ll need to capture multiple threads during the issue’s occurrence, covering the entire duration of a problematic transaction. Use the script provided below to capture thread dumps at given intervals:
Using the script, capture 15 thread dumps at 1-second intervals, covering a 15-second period to observe the thread stack trace behavior. Familiarity with your application code and the threads/thread pools handling transactions is essential to identify potential issues.
To analyze thread dumps, it’s crucial to understand the thread life cycle and its states. Refer to the thread life cycle diagram for a better understanding.
For example, let’s examine a performance issue in the WSO2 API Manager. The main thread pool, named PassThroughMessageProcessor, handles HTTP requests/responses and executes business logic. If we observe any performance issues related to WSO2 API Manager’s HTTP/HTTPS transports, we should first focus on the PassThroughMessageProcessor threads and their behavior over time.
After capturing thread dumps, focus on the thread state of the threads under scrutiny. If multiple threads are in a BLOCKED state and remain unchanged over time, you may have found the issue.
PassThroughMessageProcessor-577" #7782 prio=5 os_prio=0 tid=0x0000000001a77800 nid=0x380d16 waiting for monitor entry [0x00007f481ff89000]
java.lang.Thread.State: BLOCKED (on object monitor)
at org.apache.log4j.Category.callAppenders(Category.java:204)
- waiting to lock <0x00000005c1b996f8> (a org.apache.log4j.Logger)
at org.apache.log4j.Category.forcedLog(Category.java:384)
at org.apache.log4j.Category.log(Category.java:810)
at org.apache.commons.logging.impl.Log4JLogger.info(Log4JLogger.java:176)
at org.apache.synapse.mediators.MediatorLog.auditLog(MediatorLog.java:119)
at org.apache.synapse.mediators.builtin.LogMediator.mediate(LogMediator.java:102)
at org.apache.synapse.mediators.AbstractListMediator.mediate(AbstractListMediator.java:109)
at org.apache.synapse.mediators.filters.FilterMediator.mediate(FilterMediator.java:250)
at org.apache.synapse.mediators.base.SequenceMediator.mediate(SequenceMediator.java:249)
at org.apache.synapse.core.axis2.Axis2SynapseEnvironment.mediateFromContinuationStateStack(Axis2SynapseEnvironment.java:802)
at org.apache.synapse.core.axis2.Axis2SynapseEnvironment.injectMessage(Axis2SynapseEnvironment.java:303)
at org.apache.synapse.core.axis2.SynapseCallbackReceiver.handleMessage(SynapseCallbackReceiver.java:608)
at org.apache.synapse.core.axis2.SynapseCallbackReceiver.receive(SynapseCallbackReceiver.java:205)
at org.apache.axis2.engine.AxisEngine.receive(AxisEngine.java:180)
at org.apache.synapse.transport.passthru.ClientWorker.run(ClientWorker.java:265)
at org.apache.axis2.transport.base.threads.NativeWorkerPool$1.run(NativeWorkerPool.java:172)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
at java.lang.Thread.run(Thread.java:748)also, you need to focus on the thread which has a runnable state as well. ?Sometimes treads are getting stuck in a RUNNABLE state which could be the culprit of the issue. As you can see in the below thread, jms-Worker-5806 thread is in a runnable state at the java-level socketRead, and if the thread state is not getting changed over time. That menas the thread has been stuck over time. By looking at the thread stack, we could say that it has connected to a database and stuck while in a socket read.
"jms-Worker-5806" #6233 prio=5 os_prio=0 tid=0x00007f4a84131000 nid=0x10f452 runnable [0x00007f485b8f8000]
java.lang.Thread.State: RUNNABLE
at java.net.SocketInputStream.socketRead0(Native Method)
at java.net.SocketInputStream.socketRead(SocketInputStream.java:116)
at java.net.SocketInputStream.read(SocketInputStream.java:171)
at java.net.SocketInputStream.read(SocketInputStream.java:141)
at com.ibm.db2.jcc.am.k7.be(k7.java:832)
at com.ibm.db2.jcc.am.k7.executeUpdate(k7.java:806)
- locked <0x00000005e9dcd0c0> (a com.ibm.db2.jcc.t4.b)
at sun.reflect.GeneratedMethodAccessor54.invoke(Unknown Source)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:498)
at org.apache.tomcat.jdbc.pool.StatementFacade$StatementProxy.invoke(StatementFacade.java:114)
at com.sun.proxy.$Proxy43.executeUpdate(Unknown Source)
at org.apache.synapse.mediators.db.DBReportMediator.processStatement(DBReportMediator.java:75)
at org.apache.synapse.mediators.db.AbstractDBMediator.mediate(AbstractDBMediator.java:233)
at org.apache.synapse.mediators.AbstractListMediator.mediate(AbstractListMediator.java:109)
at org.apache.synapse.mediators.AbstractListMediator.mediate(AbstractListMediator.java:71)
at org.apache.synapse.mediators.base.SequenceMediator.mediate(SequenceMediator.java:158)
at org.apache.synapse.core.axis2.ProxyServiceMessageReceiver.receive(ProxyServiceMessageReceiver.java:225)
at org.apache.axis2.engine.AxisEngine.receive(AxisEngine.java:180)
at org.apache.axis2.transport.base.AbstractTransportListener.handleIncomingMessage(AbstractTransportListener.java:328)
at org.apache.axis2.transport.jms.JMSMessageReceiver.processThoughEngine(JMSMessageReceiver.java:214)
at org.apache.axis2.transport.jms.JMSMessageReceiver.onMessage(JMSMessageReceiver.java:124)
at org.apache.axis2.transport.jms.ServiceTaskManager$MessageListenerTask.handleMessage(ServiceTaskManager.java:645)
at org.apache.axis2.transport.jms.ServiceTaskManager$MessageListenerTask.run(ServiceTaskManager.java:526)
at org.apache.axis2.transport.base.threads.NativeWorkerPool$1.run(NativeWorkerPool.java:172)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
at java.lang.Thread.run(Thread.java:748)Moreover, focus on threads in WAITING or TIMED_WAITING states. In a multithreaded environment, resource access may be restricted, requiring Java synchronization or other locking mechanisms. If a thread gets stuck inside a synchronized block, all other threads needing access to the restricted resource must wait. In this situation, other threads remain in BLOCKED, WAITING or TIMED_WAITING states.
For example, the SynapseWorker-35 thread stack trace shows that it’s waiting for a log4j operation while holding a lock on a com.ibm.mq.jms.MQQueueSession object. Meanwhile, the SynapseWorker-509 thread is blocked, waiting to lock the same object.
"SynapseWorker-35" #448 prio=5 os_prio=0 tid=0x00007f09f8017000 nid=0x4295 waiting on condition [0x00007f08e1729000]
java.lang.Thread.State: WAITING (parking)
at sun.misc.Unsafe.park(Native Method)
- parking to wait for <0x00000006e865b7b0> (a java.util.concurrent.locks.ReentrantLock$FairSync)
at java.util.concurrent.locks.LockSupport.park(LockSupport.java:175)
at java.util.concurrent.locks.AbstractQueuedSynchronizer.parkAndCheckInterrupt(AbstractQueuedSynchronizer.java:836)
at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquireQueued(AbstractQueuedSynchronizer.java:870)
at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquire(AbstractQueuedSynchronizer.java:1199)
at java.util.concurrent.locks.ReentrantLock$FairSync.lock(ReentrantLock.java:224)
at java.util.concurrent.locks.ReentrantLock.lock(ReentrantLock.java:285)
at org.apache.log4j.Logger.info(Logger.java:608)
at org.apache.synapse.mediators.AbstractListMediator.mediate(AbstractListMediator.java:100)
at org.apache.synapse.mediators.AbstractListMediator.mediate(AbstractListMediator.java:62)
at org.apache.synapse.mediators.base.SequenceMediator.mediate(SequenceMediator.java:158)
at org.apache.synapse.mediators.base.SequenceMediator.mediate(SequenceMediator.java:214)
at org.apache.synapse.mediators.AbstractListMediator.mediate(AbstractListMediator.java:100)
at org.apache.synapse.mediators.filters.FilterMediator.mediate(FilterMediator.java:250)
at org.apache.synapse.mediators.base.SequenceMediator.mediate(SequenceMediator.java:267)
at org.apache.synapse.core.axis2.Axis2SynapseEnvironment.mediateFromContinuationStateStack(Axis2SynapseEnvironment.java:774)
at org.apache.synapse.core.axis2.Axis2SynapseEnvironment.injectMessage(Axis2SynapseEnvironment.java:281)
at org.apache.synapse.core.axis2.SynapseCallbackReceiver.handleMessage(SynapseCallbackReceiver.java:553)
at org.apache.synapse.core.axis2.SynapseCallbackReceiver.receive(SynapseCallbackReceiver.java:195)
at org.apache.axis2.engine.AxisEngine.receive(AxisEngine.java:180)
at org.apache.axis2.transport.base.AbstractTransportSender.handleIncomingMessage(AbstractTransportSender.java:148)
at org.apache.axis2.transport.jms.JMSSender.processSyncResponse(JMSSender.java:741)
at org.apache.axis2.transport.jms.JMSSender.proceedMessageFlow(JMSSender.java:536)
at org.apache.axis2.transport.jms.JMSSender.waitForResponseFromDefinedDestination(JMSSender.java:502)
at org.apache.axis2.transport.jms.JMSSender.sendOverJMS(JMSSender.java:420)
at org.apache.axis2.transport.jms.JMSSender.sendMessage(JMSSender.java:219)
- locked <0x00000006ee882260> (a com.ibm.mq.jms.MQQueueSession)
at org.apache.axis2.transport.base.AbstractTransportSender.invoke(AbstractTransportSender.java:112)
at org.apache.axis2.engine.AxisEngine.send(AxisEngine.java:442)
at org.apache.synapse.core.axis2.DynamicAxisOperation$DynamicOperationClient.send(DynamicAxisOperation.java:185)
at org.apache.synapse.core.axis2.DynamicAxisOperation$DynamicOperationClient.executeImpl(DynamicAxisOperation.java:167)"SynapseWorker-509" #50885 prio=5 os_prio=0 tid=0x00007f0914098800 nid=0x6ccf waiting for monitor entry [0x00007f086f3f2000]
java.lang.Thread.State: BLOCKED (on object monitor)
at org.apache.axis2.transport.jms.JMSSender.sendMessage(JMSSender.java:217)
- waiting to lock <0x00000006ee882260> (a com.ibm.mq.jms.MQQueueSession)
at org.apache.axis2.transport.base.AbstractTransportSender.invoke(AbstractTransportSender.java:112)
at org.apache.axis2.engine.AxisEngine.send(AxisEngine.java:442)
at org.apache.synapse.core.axis2.DynamicAxisOperation$DynamicOperationClient.send(DynamicAxisOperation.java:185)
at org.apache.synapse.core.axis2.DynamicAxisOperation$DynamicOperationClient.executeImpl(DynamicAxisOperation.java:167)
at org.apache.axis2.client.OperationClient.execute(OperationClient.java:149)Note that some threads may be waiting in the thread pool without performing any tasks; these can be ignored when analyzing thread dumps.
"PassThroughMessageProcessor-597" #7813 prio=5 os_prio=0 tid=0x00007f49f025d800 nid=0x380e3c waiting on condition [0x00007f481ec77000]
java.lang.Thread.State: WAITING (parking)
at sun.misc.Unsafe.park(Native Method)
- parking to wait for <0x00000005c46ed2a0> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
at java.util.concurrent.locks.LockSupport.park(LockSupport.java:175)
at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2039)
at java.util.concurrent.LinkedBlockingQueue.take(LinkedBlockingQueue.java:442)
at java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1074)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1134)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
at java.lang.Thread.run(Thread.java:748)
Locked ownable synchronizers:
- NoneAnalyzing thread dumps one by one can be time-consuming. However, the IBM Thread and Monitor Dump Analyzer for Java (TMDA) can help streamline this process:
https://www.ibm.com/support/pages/ibm-thread-and-monitor-dump-analyzer-java-tmda
Using TMDA, you can open multiple thread dumps and compare their thread states and behavior over time.
This article should provide a solid understanding of thread dump analysis and its application in resolving performance issues in multithreaded Java applications. Stay tuned for a future blog post on using JFR dumps to achieve similar results.
