/ Thread Dump analysis ~ Java EE Support Patterns

Thread Dump analysis

This page provides a consolidated of all articles and tutorials related to JVM Thread Dump analysis. 



Thread Dump analysis is a very important skill to master for any individual involved in Java EE production support and I highly recommend that you read all of these articles below.




Thread Dump analysis training plan

Java Deadlock


Training Videos

34 comments:

Hi,

Really good work. Very much appreciated.

This will helps me and other too.

Keep this good work.

Regards,
Peter Jerald

Thanks Peter,

I will release more thread dump related posts shortly, including problem pattern analysis.

Regards,
P-H

Very very nice and Very much Explanatory ...if you get chane please provide vedios...

Thanks
Narasimha

Thank you.

I will create more thread dump analysis shortly.

Regards,
P-H

very help full .. please keep up the good work

Thanks and Regards
Naveen Burman

very helpful .....thanks you...pierre

Thanks, I'm currently working on a Thread dump analysis tips and ticks article to be released in the next 1-2 weeks.

Thanks.
P-H

Hey Pierre,
Can you briefly look at this thread dump?
"AD Thread Pool-CSS9" waiting for lock java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject@7097bbb8 WAITING

sun.misc.Unsafe.park(Native Method)

java.util.concurrent.locks.LockSupport.park(LockSupport.java:156)

java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:1987)

java.util.concurrent.DelayQueue.take(DelayQueue.java:160)

com.singularity.ee.util.de.c(de.java:523)

com.singularity.ee.util.de.take(de.java:516)

com.singularity.ee.util.ge.a(ge.java:487)

com.singularity.ee.util.sb.run(sb.java:691)

java.lang.Thread.run(Thread.java:662)

"Thread-45" waiting for lock com.comergent.dcm.cron.RunQueue@a908faf TIMED_WAITING

java.lang.Object.wait(Native Method)

com.comergent.dcm.cron.RunQueue.dequeue(RunQueue.java:231)

com.comergent.dcm.cron.RunQueue$RunRunnable.run(RunQueue.java:140)

"[STANDBY] ExecuteThread: '14' for queue: 'weblogic.kernel.Default (self-tuning)'" waiting for lock weblogic.work.ExecuteThread@18c92f94 WAITING

java.lang.Object.wait(Native Method)

java.lang.Object.wait(Object.java:485)

weblogic.work.ExecuteThread.waitForRequest(ExecuteThread.java:162)

weblogic.work.ExecuteThread.run(ExecuteThread.java:183)

"AD Thread Pool-CSS8" waiting for lock java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject@7097bbb8 WAITING

sun.misc.Unsafe.park(Native Method)

java.util.concurrent.locks.LockSupport.park(LockSupport.java:156)

java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:1987)

java.util.concurrent.DelayQueue.take(DelayQueue.java:160)

com.singularity.ee.util.de.c(de.java:523)

com.singularity.ee.util.de.take(de.java:516)

com.singularity.ee.util.ge.a(ge.java:487)

com.singularity.ee.util.sb.run(sb.java:691)

java.lang.Thread.run(Thread.java:662)

"[ACTIVE] ExecuteThread: '13' for queue: 'weblogic.kernel.Default (self-tuning)'" waiting for lock weblogic.work.ExecuteThread@58469848 WAITING

java.lang.Object.wait(Native Method)

java.lang.Object.wait(Object.java:485)

weblogic.work.ExecuteThread.waitForRequest(ExecuteThread.java:162)

weblogic.work.ExecuteThread.run(ExecuteThread.java:183)

"[ACTIVE] ExecuteThread: '12' for queue: 'weblogic.kernel.Default (self-tuning)'" waiting for lock weblogic.work.ExecuteThread@6655a179 WAITING

java.lang.Object.wait(Native Method)

java.lang.Object.wait(Object.java:485)

weblogic.work.ExecuteThread.waitForRequest(ExecuteThread.java:162)

weblogic.work.ExecuteThread.run(ExecuteThread.java:183)
Guy

Hi Guy,

Not much going on this thread dump, were you facing any particular slowdown condition?

NOTE: this is a partial thread dump, i would recommend that you review each and every thread of WebLogic e.g. ExecuteThread: 'XYZ'

Please re-post further details, if any, from the WebLogic threads.

Regards,
P-H

hi, your articles were very nice and informative. I m new to analysis of thread dump and need you help with some trouble shooting. In our load environment we are seeing very low TPS and when we get the thread dumps
I noticed there are lot of thread in below state (like 900 odd threads). Does this mean anything or its
just an idle thread waiting for work to be assigned




"EventHandler-thread-352" prio=10 tid=0x00007fb5c8012800 nid=0x5e35 waiting on condition [0x00007fb2069af000]
java.lang.Thread.State: TIMED_WAITING (parking)
at sun.misc.Unsafe.park(Native Method)
- parking to wait for <0x0000000648995a58> (a java.util.concurrent.SynchronousQueue$TransferStack)
at java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:198)
at java.util.concurrent.SynchronousQueue$TransferStack.awaitFulfill(SynchronousQueue.java:424)
at java.util.concurrent.SynchronousQueue$TransferStack.transfer(SynchronousQueue.java:323)
at java.util.concurrent.SynchronousQueue.poll(SynchronousQueue.java:874)
at java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:945)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:907)
at java.lang.Thread.run(Thread.java:662)

You are amazing, please keep up the good work.

hi ,can you look at this thread dump and suggest where is the problem... we are facing a slowness.
"RMI TCP Accept-0" daemon prio=6 tid=0x0000000000562d40 nid=0x934 runnable [0x000000000b6ef000..0x000000000b6ef9e0]
at java.net.PlainSocketImpl.socketAccept(Native Method)
at java.net.PlainSocketImpl.accept(PlainSocketImpl.java:384)
- locked <0x000000008548e400> (a java.net.SocksSocketImpl)
at java.net.ServerSocket.implAccept(ServerSocket.java:450)
at java.net.ServerSocket.accept(ServerSocket.java:421)
at sun.management.jmxremote.LocalRMIServerSocketFactory$1.accept(LocalRM
IServerSocketFactory.java:31)
at sun.rmi.transport.tcp.TCPTransport.run(TCPTransport.java:340)
at java.lang.Thread.run(Thread.java:595)
"RMI TCP Accept-10500" daemon prio=6 tid=0x0000000000562a90 nid=0x17e4 runnable
[0x000000000b5ef000..0x000000000b5efa60]
at java.net.PlainSocketImpl.socketAccept(Native Method)
at java.net.PlainSocketImpl.accept(PlainSocketImpl.java:384)
- locked <0x000000008548e2b8> (a java.net.SocksSocketImpl)
at java.net.ServerSocket.implAccept(ServerSocket.java:450)
at java.net.ServerSocket.accept(ServerSocket.java:421)
at sun.rmi.transport.tcp.TCPTransport.run(TCPTransport.java:340)
at java.lang.Thread.run(Thread.java:595)

"RMI TCP Accept-0" daemon prio=6 tid=0x00000000005627e0 nid=0x9a4 runnable [0x00
0000000b4ef000..0x000000000b4efae0]
at java.net.PlainSocketImpl.socketAccept(Native Method)
at java.net.PlainSocketImpl.accept(PlainSocketImpl.java:384)
- locked <0x000000008548e7f0> (a java.net.SocksSocketImpl)
at java.net.ServerSocket.implAccept(ServerSocket.java:450)
at java.net.ServerSocket.accept(ServerSocket.java:421)
at sun.rmi.transport.tcp.TCPTransport.run(TCPTransport.java:340)
at java.lang.Thread.run(Thread.java:595)

"Timer-0" daemon prio=6 tid=0x0000000000562530 nid=0x13d8 in Object.wait() [0x00
0000000b36f000..0x000000000b36fb60]
at java.lang.Object.wait(Native Method)
- waiting on <0x000000008548d658> (a java.util.TaskQueue)
at java.util.TimerThread.mainLoop(Timer.java:509)
- locked <0x000000008548d658> (a java.util.TaskQueue)
at java.util.TimerThread.run(Timer.java:462)
"Low Memory Detector" daemon prio=6 tid=0x0000000000562280 nid=0xc88 runnable [0
x0000000000000000..0x0000000000000000]
"CompilerThread1" daemon prio=10 tid=0x0000000008f51810 nid=0x1724 waiting on co
ndition [0x0000000000000000..0x000000000986e9f0]
"CompilerThread0" daemon prio=10 tid=0x0000000008f51540 nid=0xafc waiting on con
dition [0x0000000000000000..0x000000000976ea40]
"AdapterThread" daemon prio=10 tid=0x0000000008f51270 nid=0x1100 waiting on cond
ition [0x0000000000000000..0x0000000000000000]
"Signal Dispatcher" daemon prio=10 tid=0x0000000000561fd0 nid=0x1048 waiting on
condition [0x0000000000000000..0x0000000000000000]
"Finalizer" daemon prio=8 tid=0x0000000000561d20 nid=0x770 in Object.wait() [0x0
00000000946f000..0x000000000946fa60]
at java.lang.Object.wait(Native Method)
- waiting on <0x00000000854dd720> (a java.lang.ref.ReferenceQueue$Lock)
at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:120)
- locked <0x00000000854dd720> (a java.lang.ref.ReferenceQueue$Lock)
at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:136)
at java.lang.ref.Finalizer$FinalizerThread.run(Finalizer.java:159)

continuation of thread dump


"Reference Handler" daemon prio=10 tid=0x0000000000561a70 nid=0x958 in Object.wa
it() [0x000000000936f000..0x000000000936fae0]
at java.lang.Object.wait(Native Method)
- waiting on <0x00000000853f0500> (a java.lang.ref.Reference$Lock)
at java.lang.Object.wait(Object.java:474)
at java.lang.ref.Reference$ReferenceHandler.run(Reference.java:116)
- locked <0x00000000853f0500> (a java.lang.ref.Reference$Lock)

"VM Thread" prio=10 tid=0x000000000032d470 nid=0x1128 runnable

"GC task thread#0 (ParallelGC)" prio=6 tid=0x0000000000322f90 nid=0x10fc runnabl
e

"GC task thread#1 (ParallelGC)" prio=6 tid=0x0000000000323210 nid=0x11e0 runnabl
e

"GC task thread#2 (ParallelGC)" prio=6 tid=0x0000000000323490 nid=0xd0c runnable


"GC task thread#3 (ParallelGC)" prio=6 tid=0x0000000000323710 nid=0xcb4 runnable


"GC task thread#4 (ParallelGC)" prio=6 tid=0x0000000000323990 nid=0xfe8 runnable


"GC task thread#5 (ParallelGC)" prio=6 tid=0x0000000000323c10 nid=0xb10 runnable


"GC task thread#6 (ParallelGC)" prio=6 tid=0x0000000000323e90 nid=0x1428 runnabl
e

"GC task thread#7 (ParallelGC)" prio=6 tid=0x0000000000324110 nid=0xdf0 runnable


"GC task thread#8 (ParallelGC)" prio=6 tid=0x0000000000324390 nid=0xdd0 runnable


"GC task thread#9 (ParallelGC)" prio=6 tid=0x0000000000324610 nid=0x14f8 runnabl
e

"GC task thread#10 (ParallelGC)" prio=6 tid=0x0000000000324890 nid=0xd80 runnabl
e

"GC task thread#11 (ParallelGC)" prio=6 tid=0x0000000000324b10 nid=0x2bc runnabl
e

"GC task thread#12 (ParallelGC)" prio=6 tid=0x00000000005ffbf0 nid=0xde4 runnabl
e

"GC task thread#13 (ParallelGC)" prio=6 tid=0x00000000005ffe70 nid=0x228 runnabl
e

"GC task thread#14 (ParallelGC)" prio=6 tid=0x00000000006000f0 nid=0x1004 runnab
le

"GC task thread#15 (ParallelGC)" prio=6 tid=0x0000000000600370 nid=0x5cc runnabl
e

"GC task thread#16 (ParallelGC)" prio=6 tid=0x00000000006005f0 nid=0x15e8 runnab
le

"GC task thread#17 (ParallelGC)" prio=6 tid=0x0000000000600870 nid=0x12d0 runnab
le

"GC task thread#18 (ParallelGC)" prio=6 tid=0x0000000000600af0 nid=0xf5c runnabl
e

"GC task thread#19 (ParallelGC)" prio=6 tid=0x0000000000600d70 nid=0x1360 runnab
le

"GC task thread#20 (ParallelGC)" prio=6 tid=0x0000000000600ff0 nid=0x1538 runnab
le

"GC task thread#21 (ParallelGC)" prio=6 tid=0x0000000000601270 nid=0xd1c runnabl
e

"GC task thread#22 (ParallelGC)" prio=6 tid=0x00000000006014f0 nid=0x3c0 runnabl
e

"GC task thread#23 (ParallelGC)" prio=6 tid=0x0000000000601770 nid=0x14c0 runnab
le

"VM Periodic Task Thread" prio=10 tid=0x000000000032d7d0 nid=0x6b4 waiting on co
ndition

Hi,

No problem in the Thread Dump data that you are showing. You will need to concentrate from the dump on threads processing actual application requests.

Thanks.
P-H

ITS REALLY NICE
CRYSTAL CLEAR TO LEARN FOR BEGINNERS.

Thanks you very much Pierre Hugues - It really helped me get by basics right again! - Nice detailed Post.

"webcontainer 201 " is blocking my 25 threads and when i checked for it below is what i get

3LKWAITNOTIFY "WebContainer : 201" (0x0000000052A4DD00)
2LKREGMON &(classLoader->mutex) lock (0x000000000E542F00):
2LKREGMON &(classLoader->mutex) lock (0x000000000E542FA0):


and if i search for it again:
3XMTHREADINFO "WebContainer : 201" J9VMThread:0x0000000052A4DD00, j9thread_t:0x000000000E4503D0, java/lang/Thread:0x0000000180780010, state:CW, prio=5
3XMJAVALTHREAD (java/lang/Thread getId:0xB234, isDaemon:true)
3XMTHREADINFO1 (native thread ID:0x4A60, native priority:0x5, native policy:UNKNOWN)
3XMTHREADINFO3 Java callstack:
4XESTACKTRACE at java/lang/Object.wait(Native Method)
4XESTACKTRACE at java/lang/Object.wait(Object.java:196(Compiled Code))
4XESTACKTRACE at com/ibm/ws/util/BoundedBuffer.waitGet_(BoundedBuffer.java:187(Compiled Code))
4XESTACKTRACE at com/ibm/ws/util/BoundedBuffer.take(BoundedBuffer.java:549(Compiled Code))
4XESTACKTRACE at com/ibm/ws/util/ThreadPool.getTask(ThreadPool.java:904(Compiled Code))
4XESTACKTRACE at com/ibm/ws/util/ThreadPool$Worker.run(ThreadPool.java:1671(Compiled Code))
3XMTHREADINFO3 No native callstack available on this platform

So, we can tell that it is on a wait .

Above is the case with most of my threads and i think the threads are idle and are waiting -

Any comments please.

Hello P-H,
I see a several entries as the one below in my thread dumps. Basically, those are instances where thread-1 is waiting on thread-2 when thread-1 already has a lock on thread-2. Is that a case of deadlock?

"TP-Processor54" daemon prio=10 tid=0x00007fe494073000 nid=0x270d in Object.wait() [0x00007fe465b33000]
java.lang.Thread.State: WAITING (on object monitor)
at java.lang.Object.wait(Native Method)
- waiting on <0x0000000744b84048> (a org.apache.tomcat.util.threads.ThreadPool$ControlRunnable)
at java.lang.Object.wait(Object.java:485)
at org.apache.tomcat.util.threads.ThreadPool$ControlRunnable.run(ThreadPool.java:662)
- locked <0x0000000744b84048> (a org.apache.tomcat.util.threads.ThreadPool$ControlRunnable)
at java.lang.Thread.run(Unknown Source)

Excellent Article...thank you

http://fastthread.io/ tool is a self explanatory tool for analyzing thread dumps

Did you publish Thread Dump Analysis Fundamentals - Part 3?

Hi Pallavi,

Not at this point. The next focus will be on YouTube videos where I will create further training materials on the analysis process.

Thanks.
P-H

Hi Pierre,

How are you..just a small question the video on "Thread dump Analysis for IBM JVM -part1 is really good.Are you releasing More videos on that

Hi Siva,

Yes, I will be releasing more video on Thread Dump Analysis. The next series will focus on the analysis process. I will demonstrate analysis using just the raw data and also using some tools as well.

Both Oracle HotSpot JVM and IBM J9 will be demonstrated along with common problem patterns.

Thanks for watching.

Hi Pierre,

All your training videos of Thread Dump analysis that i have seen are Linux based. Do you have any separate blog for Windows based tutorials?
If not, Could you please help me.How to generate Java Thread Dumps and Apache Tomcat Thread dumps in windows based environment. As my java web application is deployed in windows server at production environment and Apache tomcat8 run as a windows service. We exactly don't know how to generate Thread dumps for my Java web application in windows environment to analyze application issues. Please Help!!

Hi Ganesh,

I don't have a training video using Windows OS at the moment. For you environment, I recommend that you generate a Thread Dump via JDK jstack utility.

1) locate the JDK home folder e.g. not JRE
2) the jstack utility is located under /bin folder
3) execute the following command: jstack

This will generate a thread dump snapshot from your Apache Tomcat 8 Java process running as a service.

Please keep me posted on your progress...thanks!

Hi Pierre and thank you.

I'm learning a lot about thread dump analysis from your tutorials and videos, i also saw your answers on oracle foruns out there.

But i'm still facing some problems trying to see the problem with a thread dump i collected.

Can you help me to point the problem of this dump ?

"[STUCK] ExecuteThread: '18' for queue: 'weblogic.kernel.Default (self-tuning)'" id=139 idx=0x248 tid=34526 prio=1 alive, in native, daemon

at jrockit/net/SocketNativeIO.readBytesPinned(Ljava/io/FileDescriptor;[BIII)I(Native Method)
at jrockit/net/SocketNativeIO.socketRead(SocketNativeIO.java:32)[inlined]
at java/net/SocketInputStream.socketRead0(Ljava/io/FileDescriptor;[BIII)I(SocketInputStream.java)[inlined]
at java/net/SocketInputStream.read(SocketInputStream.java:129)[optimized]
at weblogic/socket/JSSEFilterImpl.readFromNetwork(JSSEFilterImpl.java:409)
at weblogic/socket/JSSEFilterImpl.read(JSSEFilterImpl.java:372)

^-- Holding lock: weblogic/socket/JSSEFilterImpl@0x1fc0f2328[biased lock]

at weblogic/socket/JSSESocket$JSSEInputStream.read(JSSESocket.java:60)
at java/io/BufferedInputStream.fill(BufferedInputStream.java:218)[optimized]
at java/io/BufferedInputStream.read1(BufferedInputStream.java:258)[optimized]
at java/io/BufferedInputStream.read(BufferedInputStream.java:317)[optimized]

^-- Holding lock: java/io/BufferedInputStream@0x1fc0f8798[biased lock]

at weblogic/net/http/MessageHeader.isHTTP(MessageHeader.java:226)
at weblogic/net/http/MessageHeader.parseHeader(MessageHeader.java:148)[optimized]
at weblogic/net/http/HttpClient.parseHTTP(HttpClient.java:478)[optimized]
at weblogic/net/http/HttpURLConnection.getInputStream(HttpURLConnection.java:412)[optimized]

^-- Holding lock: weblogic/net/http/SOAPHttpsURLConnection@0x130a09778[biased lock]

at weblogic/net/http/SOAPHttpsURLConnection.getInputStream(SOAPHttpsURLConnection.java:37)
at weblogic/net/http/HttpURLConnection.getHeaderField(HttpURLConnection.java:786)[inlined]
at weblogic/net/http/HttpURLConnection.getResponseCode(HttpURLConnection.java:1050)[optimized]
at com/bea/wli/sb/transports/http/HttpOutboundMessageContext.getResponse(HttpOutboundMessageContext.java:754)[optimized]
at com/bea/wli/sb/transports/http/wls/HttpOutboundMessageContextWls.access$200(HttpOutboundMessageContextWls.java:21)[inlined]
at com/bea/wli/sb/transports/http/wls/HttpOutboundMessageContextWls$RetrieveHttpResponseWork.handleResponse(HttpOutboundMessageContextWls.java:106)[optimized]
at weblogic/net/http/AsyncResponseHandler$MuxableSocketHTTPAsyncResponse$RunnableCallback.run(AsyncResponseHandler.java:551)[optimized]
at weblogic/work/ContextWrap.run(ContextWrap.java:41)[optimized]
at weblogic/work/SelfTuningWorkManagerImpl$WorkAdapterImpl.run(SelfTuningWorkManagerImpl.java:545)[optimized]
at weblogic/work/ExecuteThread.execute(ExecuteThread.java:256)[optimized]
at weblogic/work/ExecuteThread.run(ExecuteThread.java:221)
at jrockit/vm/RNI.c2java(JJJJJ)V(Native Method)
-- end of trace

Hi Bruno,

Based on the stack trace, you are facing STUCK threads with one of your Oracle Service Bus (OSB) business service (HTTPS Web Service call). OSB is firing up child threads (ContextWrap) when executing certain business service outbound calls.

The issue is no response sent back from this external web service and lack of timeout (READ timeout).

Please implement a proper read timeout value e.g. 30/60 seconds for this business service and investigate the source of slowness with this external service provider.

Thanks.

Hi Pierre,

First of all, thank you for answering me.

The read timeout of my business web service was implemented to 300 seconds (5 min) already.

We opened an issue at Oracle and we were informed that there is a bug in OSB 11g where if you're calling an external URI with "Https" and the "Use Chunked Streaming Mode" option is enabled (which usually is, by default) the stuck threads problem may occur.

We changed the property to disabled and the problem is gone !

Thanks again for your analysis.

Best regards.

Bruno

Thanks Bruno for sharing the root cause and OSB 11g bug with the "Chunked Streaming" mode.

I am sure others will benefit from this RCA. Do you have the bug/Doc ID by any chance?

Thanks.

Hi Ph

Very nice info but need help on our case. Can you please help.

I really appreciate you from the bottom of my heart. I never got a chance to learn this because i never got such a experienced learning material. If possible Could you please share details about transaction management in upcoming videos and famous bank account transfer use case. I will never forget such a help in my whole career. Much Appriciate!!!

Post a Comment