This particular blocked thread dependency graph should not occur with the RIVER-254 fix, because ConnectionManager.OutboundMux.checkIdle no longer synchronizes on the OutboundMux instance. Also note that the fix for RIVER-229/242 changed the ConnectionManager.Reaper code a bit.
But you would still probably see thread "UMMDTableNotifs-thread-1" waiting for thread "UMMDTableNotifs-thread-2" to unblock, however, because they both want a connection to the same endpoint, so the former is waiting on the latter's success (to share the connection) or failure (to try connecting again) in doing so. So I think that the most important question is why "UMMDTableNotifs-thread-2" is blocking. It's waiting for the server side to respond with its header for the initial connection handshake (the underlying TCP connection has been successfully established). There should really be a configurable timeout for this wait (which occurs in com.sun.jini.jeri.internal.mux.Mux.start)-- I can't remember if there is already a bug filed for that. -- Peter On Mon, Jan 17, 2011 at 12:16 PM, Christopher Dolan <[email protected]> wrote: > We've captured a stacktrace from the field where it looks like the Jeri > ConnectionManager has locked up trying to start a new Mux connection. > I'm wondering 1) if anyone else has seen something like this (is this > the same as RIVER-254?); 2) if my analysis looks correct; and 3) if > anyone sees a possible solution. > > The excerpt below comes from jstacktrace on River 2.1.0. My analysis is > that: > > * UMMDTableNotifs-thread-1 is blocked waiting for the ConnectionManager > * ConnectionManager is blocked waiting for the outbound connection > * UMMDTableNotifs-thread-2 is trying to establish the outbound > connection and is waiting on the network. Notably the code where this > thread is waiting says in Mux.start(): > > while (!muxDown && !clientConnectionReady) { > try { > muxLock.wait(); // REMIND: timeout? > } catch (InterruptedException e) { > setDown("interrupt waiting for connection > header", e); > } > } > > * the mux reader is blocked reading from the network socket. (this > uses StreamConnectionIO instead of SocketChannelConnectionIO) > > > This appears to be similar to > https://issues.apache.org/jira/browse/RIVER-254 but some of the details > are different, so I'm not sure if it's the same bug. > > > Open lock chains > ================ > Chain 1: > "UMMDTableNotifs-thread-1" id=1270 idx=0x650 tid=340 waiting for > net/jini/jeri/connection/ConnectionManager@0x00000001D4E0A7D8 held by: > "(JSK) > ConnectionManager[net.jini.jeri.tcp.TcpEndpoint$ConnectionEndpointImpl@3 > a9c1504].Reaper" id=168278 idx=0x6a4 tid=4152 waiting for > net/jini/jeri/connection/ConnectionManager$OutboundMux@0x00000002041468A > 0 held by: > "UMMDTableNotifs-thread-2" id=1271 idx=0x658 tid=3276 (waiting on > notification) > > > "(JSK) > ConnectionManager[net.jini.jeri.tcp.TcpEndpoint$ConnectionEndpointImpl@3 > a9c1504].Reaper" id=168278 idx=0x6a4 tid=4152 prio=5 alive, in native, > blocked, daemon > -- Blocked trying to get lock: > net/jini/jeri/connection/ConnectionManager$OutboundMux@0x00000002041468A > 0[thin lock] > at jrockit/vm/Threads.sleep(I)V(Native Method) > at jrockit/vm/Locks.waitForThinRelease(Locks.java:1209)[optimized] > at > jrockit/vm/Locks.monitorEnterSecondStageHard(Locks.java:1342)[optimized] > at > jrockit/vm/Locks.monitorEnterSecondStage(Locks.java:1259)[optimized] > at jrockit/vm/Locks.monitorEnter(Locks.java:2439)[optimized] > at > net/jini/jeri/connection/ConnectionManager$OutboundMux.checkIdle(Connect > ionManager.java:377) > at > net/jini/jeri/connection/ConnectionManager.checkIdle(ConnectionManager.j > ava:256) > ^-- Holding lock: > net/jini/jeri/connection/ConnectionManager@0x00000001D4E0A7D8[recursive] > at > net/jini/jeri/connection/ConnectionManager$Reaper.run(ConnectionManager. > java:572) > ^-- Holding lock: > net/jini/jeri/connection/ConnectionManager@0x00000001D4E0A7D8[thin lock] > at > com/sun/jini/thread/ThreadPool$Worker.run(ThreadPool.java:136)[optimized > ] > at java/lang/Thread.run(Thread.java:619)[optimized] > at jrockit/vm/RNI.c2java(JJJJJ)V(Native Method) > -- end of trace > > > "UMMDTableNotifs-thread-1" id=1270 idx=0x650 tid=340 prio=5 alive, in > native, blocked, daemon > -- Blocked trying to get lock: > net/jini/jeri/connection/ConnectionManager@0x00000001D4E0A7D8[thin lock] > at jrockit/vm/Threads.sleep(I)V(Native Method) > at jrockit/vm/Locks.waitForThinRelease(Locks.java:1209)[optimized] > at > jrockit/vm/Locks.monitorEnterSecondStageHard(Locks.java:1342)[optimized] > at > jrockit/vm/Locks.monitorEnterSecondStage(Locks.java:1259)[optimized] > at > net/jini/jeri/connection/ConnectionManager.connectPending(ConnectionMana > ger.java:176)[inlined] > at > net/jini/jeri/connection/ConnectionManager$ReqIterator.next(ConnectionMa > nager.java:629)[optimized] > ^-- Holding lock: > net/jini/jeri/connection/ConnectionManager$ReqIterator@0x000000020CBA800 > 0[biased lock] > at > net/jini/jeri/BasicObjectEndpoint$1.next(BasicObjectEndpoint.java:371) > at > net/jini/jeri/BasicInvocationHandler.invokeRemoteMethodOnce(BasicInvocat > ionHandler.java:708)[optimized] > at > net/jini/jeri/BasicInvocationHandler.invokeRemoteMethod(BasicInvocationH > andler.java:659)[optimized] > at > net/jini/jeri/BasicInvocationHandler.invoke(BasicInvocationHandler.java: > 528) > at $Proxy203.notify(Lnet/jini/core/event/RemoteEvent;)V(Unknown > Source) > at > com/avid/ummd/table/UMMDTableEventListener.notify(Lcom/avid/ummd/event/U > MMDRemoteEvent;)V(Unknown Source) > at > com/avid/ummd/table/UMMDTableAdaptersManager$UMMDTableAdapterListener.no > tify(Lcom/avid/ummd/event/UMMDRemoteEvent;)V(Unknown Source) > at > com/avid/ummd/table/UMMDTableEventListenersManager$ListenerSendTask.run( > )V(Unknown Source) > at > java/util/concurrent/ThreadPoolExecutor$Worker.runTask(ThreadPoolExecuto > r.java:885)[optimized] > at > java/util/concurrent/ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.ja > va:907) > at java/lang/Thread.run(Thread.java:619) > at jrockit/vm/RNI.c2java(JJJJJ)V(Native Method) > -- end of trace > > > "UMMDTableNotifs-thread-2" id=1271 idx=0x658 tid=3276 prio=5 alive, in > native, waiting, daemon > -- Waiting for notification on: > java/lang/Object@0x0000000204146898[fat lock] > at > jrockit/vm/Threads.waitForNotifySignal(JLjava/lang/Object;)Z(Native > Method) > at jrockit/vm/Locks.wait(Locks.java:2229)[inlined] > at java/lang/Object.wait(Object.java:485)[optimized] > at com/sun/jini/jeri/internal/mux/Mux.start(Mux.java:207) > ^-- Lock released while waiting: > java/lang/Object@0x0000000204146898[fat lock] > at > net/jini/jeri/connection/ConnectionManager$OutboundMux.newRequest(Connec > tionManager.java:356)[inlined] > at > net/jini/jeri/connection/ConnectionManager$ReqIterator.next(ConnectionMa > nager.java:631)[optimized] > ^-- Holding lock: > net/jini/jeri/connection/ConnectionManager$OutboundMux@0x00000002041468A > 0[thin lock] > ^-- Holding lock: > net/jini/jeri/connection/ConnectionManager$ReqIterator@0x0000000204147BF > 8[biased lock] > at > net/jini/jeri/BasicObjectEndpoint$1.next(BasicObjectEndpoint.java:371) > at > net/jini/jeri/BasicInvocationHandler.invokeRemoteMethodOnce(BasicInvocat > ionHandler.java:708)[optimized] > at > net/jini/jeri/BasicInvocationHandler.invokeRemoteMethod(BasicInvocationH > andler.java:659)[optimized] > at > net/jini/jeri/BasicInvocationHandler.invoke(BasicInvocationHandler.java: > 528) > at $Proxy203.notify(Lnet/jini/core/event/RemoteEvent;)V(Unknown > Source) > at > com/avid/ummd/table/UMMDTableEventListener.notify(Lcom/avid/ummd/event/U > MMDRemoteEvent;)V(Unknown Source) > at > com/avid/ummd/table/UMMDTableAdaptersManager$UMMDTableAdapterListener.no > tify(Lcom/avid/ummd/event/UMMDRemoteEvent;)V(Unknown Source) > at > com/avid/ummd/table/UMMDTableEventListenersManager$ListenerSendTask.run( > )V(Unknown Source) > at > java/util/concurrent/ThreadPoolExecutor$Worker.runTask(ThreadPoolExecuto > r.java:885)[optimized] > at > java/util/concurrent/ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.ja > va:907) > at java/lang/Thread.run(Thread.java:619) > at jrockit/vm/RNI.c2java(JJJJJ)V(Native Method) > -- end of trace > > "(JSK) mux reader" id=175467 idx=0x470 tid=4700 prio=5 alive, in native, > daemon > at > jrockit/net/SocketNativeIO.readBytesPinned(Ljava/io/FileDescriptor;[BIII > )I(Native Method) > at jrockit/net/SocketNativeIO.socketRead(SocketNativeIO.java:46) > at > java/net/SocketInputStream.socketRead0(Ljava/io/FileDescriptor;[BIII)I(S > ocketInputStream.java) > at java/net/SocketInputStream.read(SocketInputStream.java:129) > at > com/sun/jini/jeri/internal/mux/StreamConnectionIO$1.read(StreamConnectio > nIO.java:356)[optimized] > at > com/sun/jini/jeri/internal/mux/StreamConnectionIO$Reader.run(StreamConne > ctionIO.java:263)[optimized] > at > com/sun/jini/thread/ThreadPool$Worker.run(ThreadPool.java:136)[optimized > ] > at java/lang/Thread.run(Thread.java:619)[optimized] > at jrockit/vm/RNI.c2java(JJJJJ)V(Native Method) > -- end of trace > >
