Jboss client hang in QueueConnection.start() - IOException P

[nsayer]

We have a client whose code looks somewhat like this:

do {
qc.start();
makeABunchOfThreadsThatProcess5000Messages();
qc.stop();
} while(shouldWeKeepGoing());

The problem we're seeing is that very intermittently the client will get stuck inside the call to start(). We registered an Exception handler with the connection and once per minute we get notified about an IOException, with "ping timeout" in the message.

Setting aside for the moment what may be causing the ping timeouts, what has me immediately concerned is that the call to start() should be throwing a JMS exception rather than hanging, no?

And as for the timeouts, I read the wiki entry and none of those cases apply (the messages are small, GCs are never taking longer than a second or two on the server).

We're running JBoss 4.0.0. Is this something that, perhaps, is fixed in a newer version?

The first thing we've done is removed the call to stop(); and moved the call to start(); outside the loop. Hopefully the message wait functions that hang off the QueueSession will throw rather than hang. But I'd still like to know what's wrong with start().

[nsayer]

"nsayer" wrote:
We have a client whose code looks somewhat like this:

do {
qc.start();
runABunchOfThreadsThatProcess5000Messages();
qc.stop();
} while(shouldWeKeepGoing());

(note that the method between start() and stop() waits for all the message processing in this batch to finish).

The problem we're seeing is that very intermittently the client will get stuck inside the call to start(). We registered an Exception handler with the connection and once per minute we get notified about an IOException, with "ping timeout" in the message.

Setting aside for the moment what may be causing the ping timeouts, what has me immediately concerned is that the call to start() should be throwing a JMS exception rather than hanging, no?

And as for the timeouts, I read the wiki entry and none of those cases apply (the messages are small, GCs are never taking longer than a second or two on the server).

We're running JBoss 4.0.0. Is this something that, perhaps, is fixed in a newer version?

The first thing we've done is removed the call to stop(); and moved the call to start(); outside the loop. Hopefully the message wait functions that hang off the QueueSession will throw rather than hang. But I'd still like to know what's wrong with start().

[genman]

Get a stack trace of your application and see what it's doing in JBoss land. Also, upgrading and testing wouldn't hurt and might not be too hard to try...

[nsayer]

"genman" wrote:

Get a stack trace of your application and see what it's doing in JBoss land. Also, upgrading and testing wouldn't hurt and might not be too hard to try...

The main thread, which is stuck in start() looks like this:

- java.lang.Object.wait(long) (Compiled frame; information may be imprecise)
- java.lang.Object.wait() @bci=2, line=474 (Compiled frame)
- org.jboss.mq.il.uil2.SocketManager.sendMessage(org.jboss.mq.il.uil2.msgs.BaseMsg) @bci=3, line=192 (Compiled frame)
- org.jboss.mq.il.uil2.UILServerIL.setEnabled(org.jboss.mq.ConnectionToken, boolean) @bci=14, line=162 (Interpreted frame)
- org.jboss.mq.Connection.start() @bci=74, line=705 (Interpreted frame)

Other threads that look JBossish include:

Thread 31165: (state = BLOCKED)
- java.lang.Object.wait(long) (Compiled frame; information may be imprecise)
- java.lang.Object.wait() @bci=2, line=474 (Compiled frame)
- org.jboss.mq.il.uil2.SocketManager.sendMessage(org.jboss.mq.il.uil2.msgs.BaseMsg) @bci=3, line=192 (Compiled frame)
- org.jboss.mq.il.uil2.UILServerIL.acknowledge(org.jboss.mq.ConnectionToken, org.jboss.mq.AcknowledgementRequest) @bci=14, line=226 (Compiled frame)
- org.jboss.mq.Connection.send(org.jboss.mq.AcknowledgementRequest) @bci=66, line=1189 (Interpreted frame)
- org.jboss.mq.Connection.asynchDeliver(org.jboss.mq.ReceiveRequest[]) @bci=151, line=401 (Interpreted frame)
- org.jboss.mq.il.uil2.UILClientILService.handleMsg(org.jboss.mq.il.uil2.msgs.BaseMsg) @bci=103, line=94 (Interpreted frame)
- org.jboss.mq.il.uil2.SocketManager$ReadTask.handleMsg(org.jboss.mq.il.uil2.msgs.BaseMsg) @bci=8, line=356 (Interpreted frame)
- org.jboss.mq.il.uil2.msgs.BaseMsg.run() @bci=5, line=377 (Interpreted frame)
- EDU.oswego.cs.dl.util.concurrent.PooledExecutor$RunWhenBlocked.blockedAction(java.lang.Runnable) @bci=1, line=777 (Interpreted frame)
- EDU.oswego.cs.dl.util.concurrent.PooledExecutor.execute(java.lang.Runnable) @bci=82, line=898 (Interpreted frame)
- org.jboss.mq.il.uil2.SocketManager$ReadTask.run() @bci=272, line=296 (Interpreted frame)
- java.lang.Thread.run() @bci=11, line=595 (Interpreted frame)

Thread 31166: (state = BLOCKED)
- java.lang.Object.wait(long) (Compiled frame; information may be imprecise)
- java.lang.Object.wait() @bci=2, line=474 (Compiled frame)
- org.jboss.mq.il.uil2.SocketManager$WriteTask.run() @bci=105, line=479 (Compiled frame)

Thread 18491: (state = BLOCKED)
- java.lang.Object.wait(long) (Compiled frame; information may be imprecise)
- java.lang.Object.wait() @bci=2, line=474 (Compiled frame)
- org.jboss.mq.il.uil2.SocketManager.sendMessage(org.jboss.mq.il.uil2.msgs.BaseMsg) @bci=3, line=192 (Compiled frame)
- org.jboss.mq.il.uil2.UILServerIL.acknowledge(org.jboss.mq.ConnectionToken, org.jboss.mq.AcknowledgementRequest) @bci=14, line=226 (Compiled frame)
- org.jboss.mq.Connection.send(org.jboss.mq.AcknowledgementRequest) @bci=66, line=1189 (Interpreted frame)
- org.jboss.mq.Connection.asynchDeliver(org.jboss.mq.ReceiveRequest[]) @bci=151, line=401 (Interpreted frame)
- org.jboss.mq.il.uil2.UILClientILService.handleMsg(org.jboss.mq.il.uil2.msgs.BaseMsg) @bci=103, line=94 (Interpreted frame)
- org.jboss.mq.il.uil2.SocketManager$ReadTask.handleMsg(org.jboss.mq.il.uil2.msgs.BaseMsg) @bci=8, line=356 (Interpreted frame)
- org.jboss.mq.il.uil2.msgs.BaseMsg.run() @bci=5, line=377 (Interpreted frame)
- EDU.oswego.cs.dl.util.concurrent.PooledExecutor$Worker.run() @bci=35, line=748 (Interpreted frame)
- java.lang.Thread.run() @bci=11, line=595 (Interpreted frame)

Thread 18534: (state = BLOCKED)
- java.lang.Object.wait(long) (Compiled frame; information may be imprecise)
- java.lang.Object.wait() @bci=2, line=474 (Compiled frame)
- org.jboss.mq.il.uil2.SocketManager.sendMessage(org.jboss.mq.il.uil2.msgs.BaseMsg) @bci=3, line=192 (Compiled frame)
- org.jboss.mq.il.uil2.UILServerIL.acknowledge(org.jboss.mq.ConnectionToken, org.jboss.mq.AcknowledgementRequest) @bci=14, line=226 (Compiled frame)
- org.jboss.mq.Connection.send(org.jboss.mq.AcknowledgementRequest) @bci=66, line=1189 (Interpreted frame)
- org.jboss.mq.Connection.asynchDeliver(org.jboss.mq.ReceiveRequest[]) @bci=151, line=401 (Interpreted frame)
- org.jboss.mq.il.uil2.UILClientILService.handleMsg(org.jboss.mq.il.uil2.msgs.BaseMsg) @bci=103, line=94 (Interpreted frame)
- org.jboss.mq.il.uil2.SocketManager$ReadTask.handleMsg(org.jboss.mq.il.uil2.msgs.BaseMsg) @bci=8, line=356 (Interpreted frame)
- org.jboss.mq.il.uil2.msgs.BaseMsg.run() @bci=5, line=377 (Interpreted frame)
- EDU.oswego.cs.dl.util.concurrent.PooledExecutor$Worker.run() @bci=15, line=743 (Interpreted frame)
- java.lang.Thread.run() @bci=11, line=595 (Interpreted frame)


Thread 18538: (state = BLOCKED)
- java.lang.Object.wait(long) (Compiled frame; information may be imprecise)
- java.lang.Object.wait() @bci=2, line=474 (Compiled frame)
- org.jboss.mq.il.uil2.SocketManager.sendMessage(org.jboss.mq.il.uil2.msgs.BaseMsg) @bci=3, line=192 (Compiled frame)
- org.jboss.mq.il.uil2.UILServerIL.acknowledge(org.jboss.mq.ConnectionToken, org.jboss.mq.AcknowledgementRequest) @bci=14, line=226 (Compiled frame)
- org.jboss.mq.Connection.send(org.jboss.mq.AcknowledgementRequest) @bci=66, line=1189 (Interpreted frame)
- org.jboss.mq.Connection.asynchDeliver(org.jboss.mq.ReceiveRequest[]) @bci=151, line=401 (Interpreted frame)
- org.jboss.mq.il.uil2.UILClientILService.handleMsg(org.jboss.mq.il.uil2.msgs.BaseMsg) @bci=103, line=94 (Interpreted frame)
- org.jboss.mq.il.uil2.SocketManager$ReadTask.handleMsg(org.jboss.mq.il.uil2.msgs.BaseMsg) @bci=8, line=356 (Interpreted frame)
- org.jboss.mq.il.uil2.msgs.BaseMsg.run() @bci=5, line=377 (Interpreted frame)
- EDU.oswego.cs.dl.util.concurrent.PooledExecutor$Worker.run() @bci=15, line=743 (Interpreted frame)
- java.lang.Thread.run() @bci=11, line=595 (Interpreted frame)


Thread 18536: (state = BLOCKED)
- java.lang.Object.wait(long) (Compiled frame; information may be imprecise)
- java.lang.Object.wait() @bci=2, line=474 (Compiled frame)
- org.jboss.mq.il.uil2.SocketManager.sendMessage(org.jboss.mq.il.uil2.msgs.BaseMsg) @bci=3, line=192 (Compiled frame)
- org.jboss.mq.il.uil2.UILServerIL.acknowledge(org.jboss.mq.ConnectionToken, org.jboss.mq.AcknowledgementRequest) @bci=14, line=226 (Compiled frame)
- org.jboss.mq.Connection.send(org.jboss.mq.AcknowledgementRequest) @bci=66, line=1189 (Interpreted frame)
- org.jboss.mq.Connection.asynchDeliver(org.jboss.mq.ReceiveRequest[]) @bci=151, line=401 (Interpreted frame)
- org.jboss.mq.il.uil2.UILClientILService.handleMsg(org.jboss.mq.il.uil2.msgs.BaseMsg) @bci=103, line=94 (Interpreted frame)
- org.jboss.mq.il.uil2.SocketManager$ReadTask.handleMsg(org.jboss.mq.il.uil2.msgs.BaseMsg) @bci=8, line=356 (Interpreted frame)
- org.jboss.mq.il.uil2.msgs.BaseMsg.run() @bci=5, line=377 (Interpreted frame)
- EDU.oswego.cs.dl.util.concurrent.PooledExecutor$Worker.run() @bci=15, line=743 (Interpreted frame)
- java.lang.Thread.run() @bci=11, line=595 (Interpreted frame)


Thread 18535: (state = BLOCKED)
- java.lang.Object.wait(long) (Compiled frame; information may be imprecise)
- java.lang.Object.wait() @bci=2, line=474 (Compiled frame)
- org.jboss.mq.il.uil2.SocketManager.sendMessage(org.jboss.mq.il.uil2.msgs.BaseMsg) @bci=3, line=192 (Compiled frame)
- org.jboss.mq.il.uil2.UILServerIL.acknowledge(org.jboss.mq.ConnectionToken, org.jboss.mq.AcknowledgementRequest) @bci=14, line=226 (Compiled frame)
- org.jboss.mq.Connection.send(org.jboss.mq.AcknowledgementRequest) @bci=66, line=1189 (Interpreted frame)
- org.jboss.mq.Connection.asynchDeliver(org.jboss.mq.ReceiveRequest[]) @bci=151, line=401 (Interpreted frame)
- org.jboss.mq.il.uil2.UILClientILService.handleMsg(org.jboss.mq.il.uil2.msgs.BaseMsg) @bci=103, line=94 (Interpreted frame)
- org.jboss.mq.il.uil2.SocketManager$ReadTask.handleMsg(org.jboss.mq.il.uil2.msgs.BaseMsg) @bci=8, line=356 (Interpreted frame)
- org.jboss.mq.il.uil2.msgs.BaseMsg.run() @bci=5, line=377 (Interpreted frame)
- EDU.oswego.cs.dl.util.concurrent.PooledExecutor$Worker.run() @bci=15, line=743 (Interpreted frame)
- java.lang.Thread.run() @bci=11, line=595 (Interpreted frame)


The rest of the threads, I believe, our our application threads unrelated to the problem, so I won't clutter the thread with them.

[genman]

It looks the "wait" are for messages to arrive off the receive queue. Perhaps the server isn't seeing the client response message? Do you know if your client is active.

[nsayer]

"genman" wrote:

It looks the "wait" are for messages to arrive off the receive queue. Perhaps the server isn't seeing the client response message? Do you know if your client is active.

These are client stack traces. The client is hung in the main thread calling start().