1

在我们的代码中,我们在双方(服务器和客户端)上都使用了 Apache Mina。客户端是一个 java 小程序。服务器托管在单独的机器上,多个小程序连接到它并在它们之间交换数据。我们今天遇到了一个奇怪的问题,即服务器不接受(或响应)来自客户端的新连接,而旧会话工作正常(数据交换正确)。这很奇怪,因为服务器几个月以来一直在运行(并且工作正常)。这个 bug 很难跟踪,因为当 applet 尝试创建会话(甚至没有 sessionOpened() 的开始)时,服务器端没有记录任何内容,并且没有异常。似乎服务器处于部分无响应状态。我们也试图重现它,但没有成功。

在服务器端,这是我们初始化 mina 的方式:

acceptor.setHandler(handler);
acceptor.getSessionConfig().setReadBufferSize(2048);
acceptor.getSessionConfig().setIdleTime(IdleStatus.BOTH_IDLE, tcpServerIdleTime);
acceptor.bind(new InetSocketAddress(m_tcpPort));

这是数据写入客户端的方式:

cardReadersession.getConfig().setUseReadOperation(true);
final WriteFuture writeFuture = cardReadersession.write(message);
writeFuture.awaitUninterruptibly();
    if (writeFuture.getException() != null)
    {
        cardReadersession.getConfig().setUseReadOperation(false);
        return null;
    }

final ReadFuture readFuture = cardReadersession.read();
readFuture.awaitUninterruptibly();

if (readFuture.getException() != null) 
    {
        cardReadersession.getConfig().setUseReadOperation(false);
        return null;
}

  messageResponse = (MessageResponse ) readFuture.getMessage();
  // stop blocking inbound messages
  cardReadersession.getConfig().setUseReadOperation(false);

这是客户端连接到服务器的方式:

ConnectFuture future = connector.connect(new InetSocketAddress(hostName, portNumber));
future.awaitUninterruptibly();
session = future.getSession();
session.getCloseFuture().awaitUninterruptibly();

那时的线程转储

Full thread dump Java HotSpot(TM) 64-Bit Server VM (1.5.0_18-b02 mixed mode):

"NioProcessor-8" prio=1 tid=0x0000000050ed2250 nid=0x7a88 runnable [0x0000000042e04000..0x0000000042e04a90]
    at sun.nio.ch.PollArrayWrapper.poll0(Native Method)
    at sun.nio.ch.PollArrayWrapper.poll(PollArrayWrapper.java:100)
    at sun.nio.ch.PollSelectorImpl.doSelect(PollSelectorImpl.java:56)
    at sun.nio.ch.SelectorImpl.lockAndDoSelect(SelectorImpl.java:69)
    - locked <0x00002aac600f4b28> (a sun.nio.ch.Util$1)
    - locked <0x00002aac600f4b10> (a java.util.Collections$UnmodifiableSet)
    - locked <0x00002aac600f49f0> (a sun.nio.ch.PollSelectorImpl)
    at sun.nio.ch.SelectorImpl.select(SelectorImpl.java:80)
    at org.apache.mina.transport.socket.nio.NioProcessor.select(NioProcessor.java:70)
    at org.apache.mina.core.polling.AbstractPollingIoProcessor$Processor.run(AbstractPollingIoProcessor.java:1067)
    at org.apache.mina.util.NamePreservingRunnable.run(NamePreservingRunnable.java:64)
    at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:650)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:675)
    at java.lang.Thread.run(Thread.java:595)

"NioProcessor-10" prio=1 tid=0x0000000050ed3e40 nid=0x538a runnable [0x0000000041447000..0x0000000041447b10]
    at sun.nio.ch.PollArrayWrapper.poll0(Native Method)
    at sun.nio.ch.PollArrayWrapper.poll(PollArrayWrapper.java:100)
    at sun.nio.ch.PollSelectorImpl.doSelect(PollSelectorImpl.java:56)
    at sun.nio.ch.SelectorImpl.lockAndDoSelect(SelectorImpl.java:69)
    - locked <0x00002aac600e0b30> (a sun.nio.ch.Util$1)
    - locked <0x00002aac600e0b18> (a java.util.Collections$UnmodifiableSet)
    - locked <0x00002aac600e02a8> (a sun.nio.ch.PollSelectorImpl)
    at sun.nio.ch.SelectorImpl.select(SelectorImpl.java:80)
    at org.apache.mina.transport.socket.nio.NioProcessor.select(NioProcessor.java:70)
    at org.apache.mina.core.polling.AbstractPollingIoProcessor$Processor.run(AbstractPollingIoProcessor.java:1067)
    at org.apache.mina.util.NamePreservingRunnable.run(NamePreservingRunnable.java:64)
    at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:650)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:675)
    at java.lang.Thread.run(Thread.java:595)

"NioProcessor-15" prio=1 tid=0x00000000503f18a0 nid=0x30ab runnable [0x0000000042a00000..0x0000000042a00c10]
    at sun.nio.ch.PollArrayWrapper.poll0(Native Method)
    at sun.nio.ch.PollArrayWrapper.poll(PollArrayWrapper.java:100)
    at sun.nio.ch.PollSelectorImpl.doSelect(PollSelectorImpl.java:56)
    at sun.nio.ch.SelectorImpl.lockAndDoSelect(SelectorImpl.java:69)
    - locked <0x00002aac600abf88> (a sun.nio.ch.Util$1)
    - locked <0x00002aac600abf70> (a java.util.Collections$UnmodifiableSet)
    - locked <0x00002aac600abe68> (a sun.nio.ch.PollSelectorImpl)
    at sun.nio.ch.SelectorImpl.select(SelectorImpl.java:80)
    at org.apache.mina.transport.socket.nio.NioProcessor.select(NioProcessor.java:70)
    at org.apache.mina.core.polling.AbstractPollingIoProcessor$Processor.run(AbstractPollingIoProcessor.java:1067)
    at org.apache.mina.util.NamePreservingRunnable.run(NamePreservingRunnable.java:64)
    at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:650)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:675)
    at java.lang.Thread.run(Thread.java:595)

"NioProcessor-14" prio=1 tid=0x0000000050654d60 nid=0x307e runnable [0x0000000042b01000..0x0000000042b01c90]
    at sun.nio.ch.PollArrayWrapper.poll0(Native Method)
    at sun.nio.ch.PollArrayWrapper.poll(PollArrayWrapper.java:100)
    at sun.nio.ch.PollSelectorImpl.doSelect(PollSelectorImpl.java:56)
    at sun.nio.ch.SelectorImpl.lockAndDoSelect(SelectorImpl.java:69)
    - locked <0x00002aac600acc78> (a sun.nio.ch.Util$1)
    - locked <0x00002aac600acc60> (a java.util.Collections$UnmodifiableSet)
    - locked <0x00002aac600acb40> (a sun.nio.ch.PollSelectorImpl)
    at sun.nio.ch.SelectorImpl.select(SelectorImpl.java:80)
    at org.apache.mina.transport.socket.nio.NioProcessor.select(NioProcessor.java:70)
    at org.apache.mina.core.polling.AbstractPollingIoProcessor$Processor.run(AbstractPollingIoProcessor.java:1067)
    at org.apache.mina.util.NamePreservingRunnable.run(NamePreservingRunnable.java:64)
    at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:650)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:675)
    at java.lang.Thread.run(Thread.java:595)

"NioProcessor-13" prio=1 tid=0x0000000050724420 nid=0x2f9c runnable [0x00000000428ff000..0x00000000428ffe10]
    at sun.nio.ch.PollArrayWrapper.poll0(Native Method)
    at sun.nio.ch.PollArrayWrapper.poll(PollArrayWrapper.java:100)
    at sun.nio.ch.PollSelectorImpl.doSelect(PollSelectorImpl.java:56)
    at sun.nio.ch.SelectorImpl.lockAndDoSelect(SelectorImpl.java:69)
    - locked <0x00002aac60086310> (a sun.nio.ch.Util$1)
    - locked <0x00002aac600862f8> (a java.util.Collections$UnmodifiableSet)
    - locked <0x00002aac600860e0> (a sun.nio.ch.PollSelectorImpl)
    at sun.nio.ch.SelectorImpl.select(SelectorImpl.java:80)
    at org.apache.mina.transport.socket.nio.NioProcessor.select(NioProcessor.java:70)
    at org.apache.mina.core.polling.AbstractPollingIoProcessor$Processor.run(AbstractPollingIoProcessor.java:1067)
    at org.apache.mina.util.NamePreservingRunnable.run(NamePreservingRunnable.java:64)
    at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:650)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:675)
    at java.lang.Thread.run(Thread.java:595)

"NioProcessor-12" prio=1 tid=0x00000000505e0b30 nid=0x2f80 runnable [0x0000000041346000..0x0000000041346a90]
    at sun.nio.ch.PollArrayWrapper.poll0(Native Method)
    at sun.nio.ch.PollArrayWrapper.poll(PollArrayWrapper.java:100)
    at sun.nio.ch.PollSelectorImpl.doSelect(PollSelectorImpl.java:56)
    at sun.nio.ch.SelectorImpl.lockAndDoSelect(SelectorImpl.java:69)
    - locked <0x00002aac600a9758> (a sun.nio.ch.Util$1)
    - locked <0x00002aac600a9740> (a java.util.Collections$UnmodifiableSet)
    - locked <0x00002aac60085e60> (a sun.nio.ch.PollSelectorImpl)
    at sun.nio.ch.SelectorImpl.select(SelectorImpl.java:80)
    at org.apache.mina.transport.socket.nio.NioProcessor.select(NioProcessor.java:70)
    at org.apache.mina.core.polling.AbstractPollingIoProcessor$Processor.run(AbstractPollingIoProcessor.java:1067)
    at org.apache.mina.util.NamePreservingRunnable.run(NamePreservingRunnable.java:64)
    at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:650)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:675)
    at java.lang.Thread.run(Thread.java:595)

"NioProcessor-11" prio=1 tid=0x0000000050b67b00 nid=0x2f47 runnable [0x00000000427fe000..0x00000000427feb10]
    at sun.nio.ch.PollArrayWrapper.poll0(Native Method)
    at sun.nio.ch.PollArrayWrapper.poll(PollArrayWrapper.java:100)
    at sun.nio.ch.PollSelectorImpl.doSelect(PollSelectorImpl.java:56)
    at sun.nio.ch.SelectorImpl.lockAndDoSelect(SelectorImpl.java:69)
    - locked <0x00002aac600abbf0> (a sun.nio.ch.Util$1)
    - locked <0x00002aac600abbd8> (a java.util.Collections$UnmodifiableSet)
    - locked <0x00002aac600ab8a0> (a sun.nio.ch.PollSelectorImpl)
    at sun.nio.ch.SelectorImpl.select(SelectorImpl.java:80)
    at org.apache.mina.transport.socket.nio.NioProcessor.select(NioProcessor.java:70)
    at org.apache.mina.core.polling.AbstractPollingIoProcessor$Processor.run(AbstractPollingIoProcessor.java:1067)
    at org.apache.mina.util.NamePreservingRunnable.run(NamePreservingRunnable.java:64)
    at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:650)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:675)
    at java.lang.Thread.run(Thread.java:595)

"NioSocketAcceptor-3" prio=1 tid=0x00002aaab4271a20 nid=0x2f3c waiting on condition [0x00000000425fc000..0x00000000425fcd90]
    at java.lang.Thread.sleep(Native Method)
    at org.apache.mina.core.polling.AbstractPollingIoAcceptor$Acceptor.run(AbstractPollingIoAcceptor.java:432)
    at org.apache.mina.util.NamePreservingRunnable.run(NamePreservingRunnable.java:64)
    at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:650)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:675)
    at java.lang.Thread.run(Thread.java:595)

"NioSocketAcceptor-2" prio=1 tid=0x00002aaab44074c0 nid=0x2f3b waiting on condition [0x00000000424fb000..0x00000000424fbe10]
    at java.lang.Thread.sleep(Native Method)
    at org.apache.mina.core.polling.AbstractPollingIoAcceptor$Acceptor.run(AbstractPollingIoAcceptor.java:432)
    at org.apache.mina.util.NamePreservingRunnable.run(NamePreservingRunnable.java:64)
    at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:650)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:675)
    at java.lang.Thread.run(Thread.java:595)

"NioSocketAcceptor-1" prio=1 tid=0x00002aaab4273210 nid=0x2f3a runnable [0x00000000423fa000..0x00000000423faa90]
    at sun.nio.ch.PollArrayWrapper.poll0(Native Method)
    at sun.nio.ch.PollArrayWrapper.poll(PollArrayWrapper.java:100)
    at sun.nio.ch.PollSelectorImpl.doSelect(PollSelectorImpl.java:56)
    at sun.nio.ch.SelectorImpl.lockAndDoSelect(SelectorImpl.java:69)
    - locked <0x00002aac600586e0> (a sun.nio.ch.Util$1)
    - locked <0x00002aac600586c8> (a java.util.Collections$UnmodifiableSet)
    - locked <0x00002aac600581f8> (a sun.nio.ch.PollSelectorImpl)
    at sun.nio.ch.SelectorImpl.select(SelectorImpl.java:80)
    at sun.nio.ch.SelectorImpl.select(SelectorImpl.java:84)
    at org.apache.mina.transport.socket.nio.NioSocketAcceptor.select(NioSocketAcceptor.java:285)
    at org.apache.mina.core.polling.AbstractPollingIoAcceptor$Acceptor.run(AbstractPollingIoAcceptor.java:400)
    at org.apache.mina.util.NamePreservingRunnable.run(NamePreservingRunnable.java:64)
    at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:650)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:675)
    at java.lang.Thread.run(Thread.java:595)

"Thread-5" prio=1 tid=0x00002aaab40fec50 nid=0x2f39 waiting on condition [0x000000004188c000..0x000000004188cb10]
    at java.lang.Thread.sleep(Native Method)
    at com.novosys.fts.business.backend.process.downloadauthentication.DownloadAuthenticationServer.run(DownloadAuthenticationServer.java:372)

"Timer-1" prio=1 tid=0x00002aaab4283400 nid=0x2f38 in Object.wait() [0x000000004178b000..0x000000004178bb90]
    at java.lang.Object.wait(Native Method)
    - waiting on <0x00002aac6005c7f8> (a java.util.TaskQueue)
    at java.lang.Object.wait(Object.java:474)
    at java.util.TimerThread.mainLoop(Timer.java:483)
    - locked <0x00002aac6005c7f8> (a java.util.TaskQueue)
    at java.util.TimerThread.run(Timer.java:462)

"com.mchange.v2.async.ThreadPoolAsynchronousRunner$PoolThread-#2" daemon prio=1 tid=0x00002aaab411aed0 nid=0x2f37 waiting on condition [0x0000000040f3e000..0x0000000040f3ec10]
    at java.lang.Thread.sleep(Native Method)
    at com.mchange.v2.resourcepool.BasicResourcePool$AcquireTask.run(BasicResourcePool.java:1805)
    at com.mchange.v2.async.ThreadPoolAsynchronousRunner$PoolThread.run(ThreadPoolAsynchronousRunner.java:547)

"com.mchange.v2.async.ThreadPoolAsynchronousRunner$PoolThread-#1" daemon prio=1 tid=0x00002aaab41048d0 nid=0x2f36 in Object.wait() [0x0000000040e3d000..0x0000000040e3dc90]
    at java.lang.Object.wait(Native Method)
    at com.mchange.v2.async.ThreadPoolAsynchronousRunner$PoolThread.run(ThreadPoolAsynchronousRunner.java:534)
    - locked <0x00002aac5f9a2c48> (a com.mchange.v2.async.ThreadPoolAsynchronousRunner)

"com.mchange.v2.async.ThreadPoolAsynchronousRunner$PoolThread-#0" daemon prio=1 tid=0x00002aaab40cb2d0 nid=0x2f35 waiting on condition [0x0000000040d3c000..0x0000000040d3cd10]
    at java.lang.Thread.sleep(Native Method)
    at com.mchange.v2.resourcepool.BasicResourcePool$AcquireTask.run(BasicResourcePool.java:1805)
    at com.mchange.v2.async.ThreadPoolAsynchronousRunner$PoolThread.run(ThreadPoolAsynchronousRunner.java:547)

"Timer-0" daemon prio=1 tid=0x00002aaab411bd50 nid=0x2f34 in Object.wait() [0x0000000040c3b000..0x0000000040c3bd90]
    at java.lang.Object.wait(Native Method)
    at java.util.TimerThread.mainLoop(Timer.java:509)
    - locked <0x00002aac5f9a3020> (a java.util.TaskQueue)
    at java.util.TimerThread.run(Timer.java:462)

"Low Memory Detector" daemon prio=1 tid=0x00002aaab0003740 nid=0x2f32 runnable [0x0000000000000000..0x0000000000000000]

"CompilerThread1" daemon prio=1 tid=0x00002aaab0001ce0 nid=0x2f31 waiting on condition [0x0000000000000000..0x0000000040937430]

"CompilerThread0" daemon prio=1 tid=0x00002aaab0000940 nid=0x2f30 waiting on condition [0x0000000000000000..0x00000000408364e0]

"AdapterThread" daemon prio=1 tid=0x00000000503c6b90 nid=0x2f2f waiting on condition [0x0000000000000000..0x0000000000000000]

"Signal Dispatcher" daemon prio=1 tid=0x00000000503c58a0 nid=0x2f2e waiting on condition [0x0000000000000000..0x0000000000000000]

"Finalizer" daemon prio=1 tid=0x00000000503b1e20 nid=0x2f2d in Object.wait() [0x00000000422f9000..0x00000000422f9d10]
    at java.lang.Object.wait(Native Method)
    - waiting on <0x00002aac5f8b4528> (a java.lang.ref.ReferenceQueue$Lock)
    at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:120)
    - locked <0x00002aac5f8b4528> (a java.lang.ref.ReferenceQueue$Lock)
    at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:136)
    at java.lang.ref.Finalizer$FinalizerThread.run(Finalizer.java:159)

"Reference Handler" daemon prio=1 tid=0x00000000503b1680 nid=0x2f2c in Object.wait() [0x00000000421f8000..0x00000000421f8d90]
    at java.lang.Object.wait(Native Method)
    at java.lang.Object.wait(Object.java:474)
    at java.lang.ref.Reference$ReferenceHandler.run(Reference.java:116)
    - locked <0x00002aac5f855928> (a java.lang.ref.Reference$Lock)

"main" prio=1 tid=0x00000000502c0b10 nid=0x2f24 runnable [0x00007fff576db000..0x00007fff576dc130]
    at java.net.PlainSocketImpl.socketAccept(Native Method)
    at java.net.PlainSocketImpl.accept(PlainSocketImpl.java:384)
    - locked <0x00002aac602100f8> (a java.net.SocksSocketImpl)
    at java.net.ServerSocket.implAccept(ServerSocket.java:450)
    at java.net.ServerSocket.accept(ServerSocket.java:421)
    at com.novosys.fts.business.backend.process.downloadauthentication.DownloadAuthenticationService.waitForStopSignal(DownloadAuthenticationService.java:356)
    at com.novosys.fts.business.backend.process.downloadauthentication.DownloadAuthenticationService.start(DownloadAuthenticationService.java:319)
    at com.novosys.fts.business.backend.process.downloadauthentication.DownloadAuthenticationService.serviceStart(DownloadAuthenticationService.java:196)
    at com.novosys.fts.business.backend.process.downloadauthentication.DownloadAuthenticationService.main(DownloadAuthenticationService.java:87)

"VM Thread" prio=1 tid=0x00000000503ad190 nid=0x2f2b runnable 

"GC task thread#0 (ParallelGC)" prio=1 tid=0x00000000502de4b0 nid=0x2f27 runnable 

"GC task thread#1 (ParallelGC)" prio=1 tid=0x00000000502df330 nid=0x2f28 runnable 

"GC task thread#2 (ParallelGC)" prio=1 tid=0x00000000502e01b0 nid=0x2f29 runnable 

"GC task thread#3 (ParallelGC)" prio=1 tid=0x00000000502e1030 nid=0x2f2a runnable 

"VM Periodic Task Thread" prio=1 tid=0x00002aaab0006120 nid=0x2f33 waiting on condition 

我可以看到此线程转储中有一些“锁定”线程,但无法真正理解问题所在。我尝试在 Lockeness(一个 Eclipse 插件)中对其进行分析,但发现很难找出问题所在。

关于它为什么发生的任何解释或线索?

4

0 回答 0