Thanks for the input. I need to finish off a previous bug fix, but once
I've done that I'll look into this one, unless someone else picks it up
first.
Meanwhile, I'd like to get as many clues as possible. I don't suppose
you can reproduce it, or extract a test case, but any information about
the type of workload and other conditions might be useful.
Patricia
Christopher Dolan 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
