How to interpret a Java thread dump?

Timo Ernst picture Timo Ernst · Oct 4, 2011 · Viewed 8.1k times · Source

I got a Java web-application here running on Tomcat6 with Ubuntu (server edition). After 1-3 days, the application becomes very slow, so I created a threaddump after a fresh restart of tomcat and another one when the application starts to become slow:

Threaddump after fresh restart:

Threaddump after 3 days (application is slow now):

From the dumps I posted, I can see that there are a lot of threads which do not seem to terminate for some reason. Unfortunately, I cannot tell which ones (class names?) and why. Using top on the console showed that the value for "VIRT" went up from ~800 (after fresh restart) to more than 4000 (after 3 days).

How can I interpret these dumps better? I already tried to load them into TDA but that didn't work (TDA doesn't seem to recognize them as dumps).

Maybe someone already sees in the dumps what's going on?

Answer

Mike Dunlavey picture Mike Dunlavey · Oct 4, 2011

In the jstack text file, I see numerous threads hanging in BCI (Byte-Code Interpreter), probably interpreting your code. It does not seem to indicate where in your code it is interpreting.

It does say you have a deadlock condition.

In the .out file, I looked for what looks like application code. I see it hanging at

  • EventProcessingThreadImpl.run:479 (2 threads)

  • GC.java:100 (1 thread) in GC waiting for something to be released so that GC can proceed.

  • Many threads parked in an unsafe condition, holding for a synchronizer, trying to read a job queue, in ThreadPoolExecutor.java:907

  • I also see what looks like a lot of boilerplate - threads waiting to be given work to do, threads runnable, waiting for mail, etc.

Is this of any help?

Added:

OK, I searched for your code and found it on three threads, shown here, and beneath each one I've given a tentative explanation.

(Also, note this link about using jstack to find deadlocks.)

----------------- 20607 -----------------
__pthread_cond_wait + 0xcc
_ZN13ObjectMonitor4waitElbP6Thread + 0x60a
_ZN18ObjectSynchronizer4waitE6HandlelP6Thread + 0x53
JVM_MonitorWait + 0x1e7
<Unknown compiled code>
* java.lang.Object.wait() bci:2 line:485 (Interpreted frame)
* org.zkoss.zk.ui.impl.EventProcessingThreadImpl.doSuspend0(java.lang.Object) bci:143 line:219 (Interpreted frame)
* org.zkoss.zk.ui.impl.EventProcessingThreadImpl.doSuspend(java.lang.Object) bci:7 line:185 (Interpreted frame)
* org.zkoss.zk.ui.impl.UiEngineImpl.wait(java.lang.Object) bci:198 line:1471 (Interpreted frame)
* org.zkoss.zk.ui.Executions.wait(java.lang.Object) bci:4 line:702 (Interpreted frame)
* org.zkoss.zul.Window.enterModal() bci:22 line:619 (Interpreted frame)
* org.zkoss.zul.Window.doModal() bci:67 line:551 (Interpreted frame)
* org.zkoss.zul.Messagebox.show(java.lang.String, java.lang.String, int, java.lang.String, int,     org.zkoss.zk.ui.event.EventListener) bci:343 line:274 (Interpreted frame)
* org.zkoss.zul.Messagebox.show(java.lang.String, java.lang.String, int, java.lang.String) bci:6 line:128 (Interpreted frame)
* com.smampi.web.view.client.ClientController$5.onEvent(org.zkoss.zk.ui.event.Event) bci:8 line:417 (Interpreted frame)
* org.zkoss.zk.ui.impl.EventProcessor.process0(org.zkoss.zk.ui.ext.Scope) bci:384 line:192 (Compiled frame)
????????

Thread 20607 is in com.smampi.web.view.client.ClientController$5.onEvent line 128 (I'm guessing). It is displaying a modal message box and waiting for it to be answered.

----------------- 20878 -----------------
__pthread_cond_wait + 0xcc
_ZN13ObjectMonitor4waitElbP6Thread + 0x60a
_ZN18ObjectSynchronizer4waitE6HandlelP6Thread + 0x53
JVM_MonitorWait + 0x1e7
<Unknown compiled code>
* java.lang.Object.wait() bci:2 line:485 (Interpreted frame)
* org.zkoss.zk.ui.impl.EventProcessingThreadImpl.doSuspend0(java.lang.Object) bci:143 line:219 (Interpreted frame)
* org.zkoss.zk.ui.impl.EventProcessingThreadImpl.doSuspend(java.lang.Object) bci:7 line:185 (Interpreted frame)
* org.zkoss.zk.ui.impl.UiEngineImpl.wait(java.lang.Object) bci:198 line:1471 (Interpreted frame)
* org.zkoss.zk.ui.Executions.wait(java.lang.Object) bci:4 line:702 (Interpreted frame)
* org.zkoss.zul.Window.enterModal() bci:22 line:619 (Interpreted frame)
* org.zkoss.zul.Window.doModal() bci:67 line:551 (Interpreted frame)
* org.zkoss.zul.Messagebox.show(java.lang.String, java.lang.String, int, java.lang.String, int, org.zkoss.zk.ui.event.EventListener) bci:343 line:274 (Interpreted frame)
* org.zkoss.zul.Messagebox.show(java.lang.String, java.lang.String, int, java.lang.String) bci:6 line:128 (Interpreted frame)
* com.smampi.web.view.client.ClientController$5.onEvent(org.zkoss.zk.ui.event.Event) bci:8 line:417 (Interpreted frame)
* org.zkoss.zk.ui.impl.EventProcessor.process0(org.zkoss.zk.ui.ext.Scope) bci:384 line:192 (Compiled frame)
????????

Thread 20878 is also displaying a message box, but at line 417 (I'm guessing)

----------------- 22792 -----------------
__pthread_cond_wait + 0xcc
_ZN7Monitor5ILockEP6Thread + 0xb9
_ZN7Monitor4lockEP6Thread + 0xf2
_ZN7Monitor4lockEv + 0x28
_ZN18GenCollectorPolicy17mem_allocate_workEmbPb + 0xca
_ZN16GenCollectedHeap12mem_allocateEmbbPb + 0x38
_ZN13CollectedHeap26common_mem_allocate_noinitEmbP6Thread + 0x9a
_ZN13instanceKlass17allocate_instanceEP6Thread + 0x7d
_ZN18InterpreterRuntime4_newEP10JavaThreadP19constantPoolOopDesci + 0xda
* com.sun.mail.util.SocketFetcher.startTLS(java.net.Socket, java.lang.String, java.util.Properties, java.lang.String) bci:378 line:413 (Interpreted frame)
* com.sun.mail.iap.Protocol.startTLS(java.lang.String) bci:23 line:377 (Interpreted frame)
* com.sun.mail.imap.protocol.IMAPProtocol.startTLS() bci:3 line:734 (Interpreted frame)
* com.sun.mail.imap.IMAPStore.login(com.sun.mail.imap.protocol.IMAPProtocol, java.lang.String, java.lang.String) bci:24 line:676 (Interpreted frame)
* com.sun.mail.imap.IMAPStore.protocolConnect(java.lang.String, int, java.lang.String, java.lang.String) bci:343 line:643 (Interpreted frame)
* javax.mail.Service.connect(java.lang.String, int, java.lang.String, java.lang.String) bci:380 line:295 (Interpreted frame)
* com.smampi.web.model.mail.server.MailServer.connect() bci:427 line:514 (Interpreted frame)
* com.smampi.web.model.mail.server.MailServer$1.closed(javax.mail.event.ConnectionEvent) bci:10 line:593 (Interpreted frame)
* javax.mail.event.ConnectionEvent.dispatch(java.lang.Object) bci:55 line:96 (Interpreted frame)

Thread 22792 is trying to do a mail service connect from com.smampi.web.model.mail.server.MailServer.connect line 514, and that's being called from com.smampi.web.model.mail.server.MailServer$1.closed at line 593. To do that, it looks like it's waiting for another thread to stop garbage collecting so it can allocate memory for a new thread so it can do a "startTLS" (for upgrading a plain text link to an encrypted one) so it can do a mail service connect.

Does that shed any light?