How to interpret a Java thread dump?

Question

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:

• via pkill -3: http://dl.dropbox.com/u/17844821/zeug/pkill-threaddump-fresh.out
• via jstack: http://dl.dropbox.com/u/17844821/zeug/jstack-threaddump-fresh.txt

Threaddump after 3 days (application is slow now):

• via pkill -3: http://dl.dropbox.com/u/17844821/zeug/pkill-threaddump.txt
• via jstack: http://dl.dropbox.com/u/17844821/zeug/jstack-threaddump.txt

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 1

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?

Answer 2

I see plenty of threads trying to establish an SSL context:

"JavaMail-EventQueue" daemon prio=10 tid=0x00007f9f10416000 nid=0x54c6 waiting for monitor entry [0x00007f9e3e92d000]
   java.lang.Thread.State: BLOCKED (on object monitor)
    at sun.security.provider.NativePRNG$RandomIO.implNextBytes(NativePRNG.java:255)
    - waiting to lock  (a java.lang.Object)
    at sun.security.provider.NativePRNG$RandomIO.access$200(NativePRNG.java:108)
    at sun.security.provider.NativePRNG.engineNextBytes(NativePRNG.java:97)
    at java.security.SecureRandom.nextBytes(SecureRandom.java:433)
    - locked  (a java.security.SecureRandom)
    at java.security.SecureRandom.next(SecureRandom.java:455)
    at java.util.Random.nextInt(Random.java:189)
    at com.sun.net.ssl.internal.ssl.SSLContextImpl.engineInit(SSLContextImpl.java:82)
    at javax.net.ssl.SSLContext.init(SSLContext.java:248)
    at com.sun.mail.util.MailSSLSocketFactory.newAdapteeFactory(MailSSLSocketFactory.java:130)
    - locked  (a com.sun.mail.util.MailSSLSocketFactory)
    at com.sun.mail.util.MailSSLSocketFactory.(MailSSLSocketFactory.java:119)
    at com.sun.mail.util.MailSSLSocketFactory.(MailSSLSocketFactory.java:94)
    at com.sun.mail.util.SocketFetcher.startTLS(SocketFetcher.java:413)
    at com.sun.mail.iap.Protocol.startTLS(Protocol.java:377)
    - locked  (a com.sun.mail.imap.protocol.IMAPProtocol)
    at com.sun.mail.imap.protocol.IMAPProtocol.startTLS(IMAPProtocol.java:734)
    at com.sun.mail.imap.IMAPStore.login(IMAPStore.java:676)
    at com.sun.mail.imap.IMAPStore.protocolConnect(IMAPStore.java:643)
    - locked  (a com.sun.mail.imap.IMAPStore)
    at javax.mail.Service.connect(Service.java:295)
    - locked  (a com.sun.mail.imap.IMAPStore)
    at com.smampi.web.model.mail.server.MailServer.connect(MailServer.java:514)
    at com.smampi.web.model.mail.server.MailServer$1.closed(MailServer.java:593)
    at javax.mail.event.ConnectionEvent.dispatch(ConnectionEvent.java:96)
    at javax.mail.EventQueue.run(EventQueue.java:134)
    at java.lang.Thread.run(Thread.java:662)

I've often seen servers become inexplicably slow during SSL setup (either as the server or as the client), when the amount of available entropy to the operating system becomes very low (i.e. the OS can't produce high-quality random numbers any more).

Try displaying the content of /proc/sys/kernel/random/entropy_avail using

cat /proc/sys/kernel/random/entropy_avail

This should tell you how much random data the OS can provide at the moment, it should usually be at least in the hundereds. If it is consistently 0 or very close, then you've got a problem and need to introduce another source of entropy.

Then again it could also be the other way around: the other end of that connection might have problems gathering entropy and might be slow to answer.

Answer 3

You've got lots (thousands?) of Threads in the WAITING state. Read here about the various Thread States: http://download.oracle.com/javase/1,5,0/docs/api/java/lang/Thread.State.html

This is a problem. You'll need to find why your app is creating so many Threads and not destroying them.

You've also lots of Threads called "JavaMail-EventQueue". Find out why the mailing life cycle is not completing. Adding some logging statements to your use of JavaMail, and you'll probably find some action regularly not completing.

Answer 4

My guess is that you accidentially try to talk TLS (encrypted) to a service which does not expect encrypted traffic so you have many threads waiting for a proper response which never come.

Are you certain you use the correct port number for this service?