UIL2 ReadTask / WriteTask thread leak on 4.0.5 GA

[gogoasa]

Hello,

I see the thread leak problem described in http://jira.jboss.org/jira/browse/JBAS-4525 was backported for the 4.0.3 branch in http://jira.jboss.org/jira/browse/ASPATCH-300.

I am using 4.0.5GA, and still the thread leak behaviour manifests itself. Inspecting the jvm with JConsole, i can see lots of UIL2.SocketManager.ReadTask /WriteTask pairs that accumulate. When the number of started threads reaches a couple of millions, I get OutOfMemoryError. Could anybody confirm that the patch made it to 4.0.5.GA too and not only to 4.0.3sp1. ? Any other advice?

For illustration, here is the stacktrace of a blocked ReadTask :

Name: UIL2.SocketManager.ReadTask#1 client=172.20.20.160:8093
State: RUNNABLE
Total blocked: 0 Total waited: 0

Stack trace:
java.net.SocketInputStream.socketRead0(Native Method)
java.net.SocketInputStream.read(SocketInputStream.java:129)
java.io.BufferedInputStream.fill(BufferedInputStream.java:218)
java.io.BufferedInputStream.read(BufferedInputStream.java:235)
org.jboss.util.stream.NotifyingBufferedInputStream.read(NotifyingBufferedInputStream.java:79)
java.io.ObjectInputStream$PeekInputStream.peek(ObjectInputStream.java:2196)
java.io.ObjectInputStream$BlockDataInputStream.readBlockHeader(ObjectInputStream.java:2376)
java.io.ObjectInputStream$BlockDataInputStream.refill(ObjectInputStream.java:2443)
java.io.ObjectInputStream$BlockDataInputStream.read(ObjectInputStream.java:2515)
java.io.ObjectInputStream$BlockDataInputStream.readByte(ObjectInputStream.java:2664)
java.io.ObjectInputStream.readByte(ObjectInputStream.java:875)
org.jboss.mq.il.uil2.SocketManager$ReadTask.run(SocketManager.java:316)
java.lang.Thread.run(Thread.java:595)

and of a blocked WriteTask :

Name: UIL2.SocketManager.WriteTask#3 client=172.20.20.160:3486
State: WAITING on java.lang.Object@67692e
Total blocked: 0 Total waited: 69

Stack trace:
java.lang.Object.wait(Native Method)
java.lang.Object.wait(Object.java:474)
EDU.oswego.cs.dl.util.concurrent.LinkedQueue.take(LinkedQueue.java:122)
org.jboss.mq.il.uil2.SocketManager$WriteTask.run(SocketManager.java:518)
java.lang.Thread.run(Thread.java:595)

Thank you,
Adrian.

[gogoasa]

Ok, I confirm it myself : ASPATCH300 didn't make it in the 4.0.5GA. But, if you look at the svn rep, you can see that it has been eventually merged :

The history of SocketManager.java in 4.0.5:
http://viewvc.jboss.org/cgi-bin/viewvc.cgi/jbossas/tags/JBoss_4_0_5_GA_CP11/messaging/src/main/org/jboss/mq/il/uil2/SocketManager.java?view=log

the 4.0.5.GA_CP11 release contains the fix. So, people having the same problem, svn checkout that release and build it.



Some further URLs concerning this issue:

The backport JIRA issue:
http://jira.jboss.org/jira/browse/ASPATCH-300?page=com.atlassian.jira.plugin.ext.subversion:subversion-commits-tabpanel

The diff showing what changed :
http://viewvc.jboss.org/cgi-bin/viewvc.cgi/jbossas/branches/JBoss_4_0_3_SP1_CP/messaging/src/main/org/jboss/mq/il/uil2/SocketManager.java/?revision=66324&r1=66324&r2=66323

The patched file in 4.0.3SP1 :
http://viewvc.jboss.org/cgi-bin/viewvc.cgi/jbossas/branches/JBoss_4_0_3_SP1_CP/messaging/src/main/org/jboss/mq/il/uil2/SocketManager.java?revision=67114&view=markup

[gogoasa]

Ok, the problem was that the jBPM installation I used did not close connections after each and every JMS message send it did.

In fact, jBPM JMS subsystem keeps one single Connection and Session for the whole life of the server application.

The JMS specification says that :

A JMS Connection is a client'™s active connection to its JMS provider. It will
typically allocate provider resources outside the Java virtual machine.

Connection objects support concurrent use.

and

A JMS Session is a single-threaded context for producing and consuming
messages. Although it may allocate provider resources outside the Java virtual
machine, it is considered a lightweight JMS object.

If I read between the lines correctly, this should mean that it is acceptable to keep a costly Connection for a long time while it is not really acceptable to keep a "lightweight" Session for a long time.

If I close Sessions but not Connections, the thread blocking still persists. So I modified the code to close both and the thread blocking no longer appears.

Is it normal that if a Connection is hold for a long time, a thread leak, eventually followed by OutOfMemory, occur ?

[gogoasa]

I was wrong, the ReadTask/WriteTask pairs still accumulate, my JConsole was not refreshing the thread list which lead me to think the problem was over.

[gogoasa]

Ok, so here is how I solved the problem.

It is due effectively to the fact that a connection is not closed. I thought I knew all the points in the application that interacted with JMS, I checked and double checked them, still there was a place that did its own JMS sending without closing connections (and using the non XA /ConnectionFactory).

What allowed me to realize where the problem was is that by enabling TRACE on org.jboss.mq, every time a message is sent you have a stacktrace of where that call is coming from. So in my case here PublisherToJmsTopic was the class I had completely forgotten about.

2008-02-15 11:20:51,498 TRACE [JMS SessionPool Worker-1-org.jboss.mq.il.uil2.SocketManager] start called
java.lang.Exception: Start stack trace
 at org.jboss.mq.il.uil2.SocketManager.start(SocketManager.java:112)
 at org.jboss.mq.il.uil2.UILServerIL.createConnection(UILServerIL.java:523)
 at org.jboss.mq.il.uil2.UILServerIL.getSocketMgr(UILServerIL.java:390)
 at org.jboss.mq.il.uil2.UILServerIL.authenticate(UILServerIL.java:277)
 at org.jboss.mq.Connection.authenticate(Connection.java:1067)
 at org.jboss.mq.Connection.<init>(Connection.java:252)
 at org.jboss.mq.Connection.<init>(Connection.java:323)
 at org.jboss.mq.SpyConnection.<init>(SpyConnection.java:116)
 at org.jboss.mq.SpyConnectionFactory.internalCreateConnection(SpyConnectionFactory.java:137)
 at org.jboss.mq.SpyConnectionFactory.createTopicConnection(SpyConnectionFactory.java:118)
 at fr.bnf.entrychain.internalservice.impl.PublisherToJmsTopic.publishEvent(PublisherToJmsTopic.java:31)
 at fr.bnf.entrychain.internalservice.impl.InternalOrchestrationServiceImpl.publishEvent(InternalOrchestrationServiceImpl.java:59)
 at fr.bnf.entrychain.internalservice.impl.InternalOrchestrationServiceBean.publishEvent(InternalOrchestrationServiceBean.java:40)
 at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)

The JDBC pool in JBoss has a nice feature that closes unclosed connections showing the stracktrace of the point that opened the connection. Not that developers should use that as connection closing mechanism but it is helpful for debugging.

[reiterweg]

Hi gogoasa, please can you give a more detailed explanation on how you solve this problem? I'm having the same trouble.

[gogoasa]

There is an incantation you *must* follow when you send/receive your JMS message. If you don't close the connection, the session or whatever, you get this. So make sure in all the points where you use JMS, you properly close things up.

And, as I said, enable TRACE in log4j.xml in order to see where your problem comes from.

[reiterweg]

Thank you so much! The problem was that. I was closing QueueSender and QueueSession but not QueueConnection.