logo标签列表

Java线程阻塞

javamultithreadingblocked-threads
6
我有一个关于Java环境的问题。我运行了一个搜索引擎Solr 1.3已经一年多了，但最近突然出现了很多问题。我的250个线程池会在一天中随机地被阻塞一两次。我没有对我的Solr应用程序或Tomcat服务器进行任何更改。
我正在运行Tomcat 5.5.25和Solr 1.3。当系统完全超载时，我得到了一个线程转储：
我有大约240个这样的线程：
"http-8080-Processor1" daemon prio=10 tid=0x0000000000b2e000 nid=0x193 waiting for monitor entry [0x000000004066c000..0x000000004066cb20]
   java.lang.Thread.State: BLOCKED (on object monitor)
    at java.util.logging.StreamHandler.publish(StreamHandler.java:174)
    - waiting to lock <0x00007fe37e72b340> (a java.util.logging.ConsoleHandler)
    at java.util.logging.ConsoleHandler.publish(ConsoleHandler.java:88)
    at java.util.logging.Logger.log(Logger.java:472)
    at java.util.logging.Logger.doLog(Logger.java:494)
    at java.util.logging.Logger.log(Logger.java:517)
    at java.util.logging.Logger.info(Logger.java:1036)
    at org.apache.solr.core.SolrCore.execute(SolrCore.java:1212)
    at org.apache.solr.servlet.SolrDispatchFilter.execute(SolrDispatchFilter.java:303)
    at org.apache.solr.servlet.SolrDispatchFilter.doFilter(SolrDispatchFilter.java:232)
    at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:215)
    at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:188)
    at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:213)
    at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:172)
    at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:127)
    at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:117)
    at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:108)
    at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:151)
    at org.apache.coyote.http11.Http11Processor.process(Http11Processor.java:874)
    at org.apache.coyote.http11.Http11BaseProtocol$Http11ConnectionHandler.processConnection(Http11BaseProtocol.java:665)
    at org.apache.tomcat.util.net.PoolTcpEndpoint.processSocket(PoolTcpEndpoint.java:528)
    at org.apache.tomcat.util.net.LeaderFollowerWorkerThread.runIt(LeaderFollowerWorkerThread.java:81)
    at org.apache.tomcat.util.threads.ThreadPool$ControlRunnable.run(ThreadPool.java:689)
    at java.lang.Thread.run(Thread.java:619)

我们可以看到，这个线程被阻塞并且在等待：<0x00007fe37e72b340> 实际拥有<0x00007fe37e72b340>的线程是：
"http-8080-Processor156" daemon prio=10 tid=0x0000000000df2000 nid=0x1e52 runnable [0x0000000044521000..0x0000000044521c20]
   java.lang.Thread.State: RUNNABLE
    at java.io.FileOutputStream.writeBytes(Native Method)
    at java.io.FileOutputStream.write(FileOutputStream.java:260)
    at java.io.BufferedOutputStream.write(BufferedOutputStream.java:105)
    - locked <0x00007fe37e3abcd8> (a java.io.BufferedOutputStream)
    at java.io.PrintStream.write(PrintStream.java:430)
    - locked <0x00007fe37e3abca0> (a java.io.PrintStream)
    at sun.nio.cs.StreamEncoder.writeBytes(StreamEncoder.java:202)
    at sun.nio.cs.StreamEncoder.implFlushBuffer(StreamEncoder.java:272)
    at sun.nio.cs.StreamEncoder.implFlush(StreamEncoder.java:276)
    at sun.nio.cs.StreamEncoder.flush(StreamEncoder.java:122)
    - locked <0x00007fe37e72cd90> (a java.io.OutputStreamWriter)
    at java.io.OutputStreamWriter.flush(OutputStreamWriter.java:212)
    at java.util.logging.StreamHandler.flush(StreamHandler.java:225)
    - locked <0x00007fe37e72b340> (a java.util.logging.ConsoleHandler)
    at java.util.logging.ConsoleHandler.publish(ConsoleHandler.java:89)
    at java.util.logging.Logger.log(Logger.java:472)
    at java.util.logging.Logger.doLog(Logger.java:494)
    at java.util.logging.Logger.log(Logger.java:517)
    at java.util.logging.Logger.info(Logger.java:1036)
    at org.apache.solr.core.SolrCore.execute(SolrCore.java:1212)
    at org.apache.solr.servlet.SolrDispatchFilter.execute(SolrDispatchFilter.java:303)
    at org.apache.solr.servlet.SolrDispatchFilter.doFilter(SolrDispatchFilter.java:232)
    at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:215)
    at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:188)
    at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:213)
    at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:172)
    at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:127)
    at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:117)
    at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:108)
    at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:151)
    at org.apache.coyote.http11.Http11Processor.process(Http11Processor.java:874)
    at org.apache.coyote.http11.Http11BaseProtocol$Http11ConnectionHandler.processConnection(Http11BaseProtocol.java:665)
    at org.apache.tomcat.util.net.PoolTcpEndpoint.processSocket(PoolTcpEndpoint.java:528)
    at org.apache.tomcat.util.net.LeaderFollowerWorkerThread.runIt(LeaderFollowerWorkerThread.java:81)
    at org.apache.tomcat.util.threads.ThreadPool$ControlRunnable.run(ThreadPool.java:689)
    at java.lang.Thread.run(Thread.java:619)

这是我的线程转储的最后一部分：
"ContainerBackgroundProcessor[StandardEngine[Catalina]]" daemon prio=10 tid=0x00007f6510349800 nid=0xbff waiting on condition [0x0000000041d8d000..0x0000000041d8dd20]
   java.lang.Thread.State: TIMED_WAITING (sleeping)
    at java.lang.Thread.sleep(Native Method)
    at org.apache.catalina.core.ContainerBase$ContainerBackgroundProcessor.run(ContainerBase.java:1548)
    at java.lang.Thread.run(Thread.java:619)

"pool-1-thread-1" prio=10 tid=0x0000000000c26400 nid=0xbfe waiting on condition [0x000000004200e000..0x000000004200eca0]
   java.lang.Thread.State: WAITING (parking)
    at sun.misc.Unsafe.park(Native Method)
    - parking to wait for  <0x00007f651b275510> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
    at java.util.concurrent.locks.LockSupport.park(LockSupport.java:158)
    at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:1925)
    at java.util.concurrent.LinkedBlockingQueue.take(LinkedBlockingQueue.java:358)
    at java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:946)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:906)
    at java.lang.Thread.run(Thread.java:619)

"Low Memory Detector" daemon prio=10 tid=0x00007f6510004400 nid=0xbfa runnable [0x0000000000000000..0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"CompilerThread1" daemon prio=10 tid=0x00007f6510001000 nid=0xbf9 waiting on condition [0x0000000000000000..0x0000000040d5e340]
   java.lang.Thread.State: RUNNABLE

"CompilerThread0" daemon prio=10 tid=0x00000000006bc400 nid=0xbf8 waiting on condition [0x0000000000000000..0x0000000040c5d2d0]
   java.lang.Thread.State: RUNNABLE

"Signal Dispatcher" daemon prio=10 tid=0x00000000006bb000 nid=0xbf7 runnable [0x0000000000000000..0x0000000040b5da30]
   java.lang.Thread.State: RUNNABLE

"Finalizer" daemon prio=10 tid=0x0000000000690c00 nid=0xbf6 in Object.wait() [0x000000004065e000..0x000000004065ed20]
   java.lang.Thread.State: WAITING (on object monitor)
    at java.lang.Object.wait(Native Method)
    - waiting on <0x00007f651aa10258> (a java.lang.ref.ReferenceQueue$Lock)
    at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:116)
    - locked <0x00007f651aa10258> (a java.lang.ref.ReferenceQueue$Lock)
    at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:132)
    at java.lang.ref.Finalizer$FinalizerThread.run(Finalizer.java:159)

"Reference Handler" daemon prio=10 tid=0x000000000068f400 nid=0xbf5 in Object.wait() [0x000000004055d000..0x000000004055dca0]
   java.lang.Thread.State: WAITING (on object monitor)
    at java.lang.Object.wait(Native Method)
    - waiting on <0x00007f651aa10338> (a java.lang.ref.Reference$Lock)
    at java.lang.Object.wait(Object.java:485)
    at java.lang.ref.Reference$ReferenceHandler.run(Reference.java:116)
    - locked <0x00007f651aa10338> (a java.lang.ref.Reference$Lock)

"main" prio=10 tid=0x0000000000622400 nid=0xbeb runnable [0x0000000000000000..0x00007fff69fcbba0]
   java.lang.Thread.State: RUNNABLE

"VM Thread" prio=10 tid=0x000000000068a000 nid=0xbf4 runnable 

"GC task thread#0 (ParallelGC)" prio=10 tid=0x000000000062cc00 nid=0xbec runnable 

"GC task thread#1 (ParallelGC)" prio=10 tid=0x000000000062e000 nid=0xbed runnable 

"GC task thread#2 (ParallelGC)" prio=10 tid=0x000000000062f400 nid=0xbee runnable 

"GC task thread#3 (ParallelGC)" prio=10 tid=0x0000000000630400 nid=0xbef runnable 

"GC task thread#4 (ParallelGC)" prio=10 tid=0x0000000000631800 nid=0xbf0 runnable 

"GC task thread#5 (ParallelGC)" prio=10 tid=0x0000000000632c00 nid=0xbf1 runnable 

"GC task thread#6 (ParallelGC)" prio=10 tid=0x0000000000634000 nid=0xbf2 runnable 

"GC task thread#7 (ParallelGC)" prio=10 tid=0x0000000000635400 nid=0xbf3 runnable 

"VM Periodic Task Thread" prio=10 tid=0x00007f6510006800 nid=0xbfb waiting on condition 

JNI global references: 1201

我知道这不是线程死锁问题，因为一个线程实际上正在运行并拥有其他所有线程想要的所有资源。

有人知道是什么原因导致了这个问题吗？

6个回答
5

您的所有线程都在记录信息。它们都需要不时地写入磁盘。 当240个线程中的一个命中日志行时，就会出现磁盘访问问题。

令我困惑的是持有锁的线程处于RUNNABLE状态。

我认为它可能在等待某些外部资源被释放（例如磁盘访问）。

您的磁盘空间是否不足？您最近是否更改过存储系统中的某些内容？

1
我认为这是正确的方向。我会看看外部因素。此外，如果它不是写入传统文件而是写入Unix命名管道，请确保有人以足够快的速度读取管道的另一端。如果缓冲区填满，你就会被阻塞。 - Mark Peters
磁盘空间正常，系统也没有进行任何更改。我们尝试将系统切换到另一台服务器上，但仍然出现了相同的问题。 - Alexandre Boudreault
我认为这不是线程安全的问题。它早就会崩溃了。 240个线程对于JVM来说不是问题。 但如果240个线程编辑单个文件，可能会有问题。 一个丑陋的解决方法是减少记录的消息数量。 尝试使用http://download-llnw.oracle.com/javase/1.4.2/docs/api/java/util/logging/LogManager.html和http://download-llnw.oracle.com/javase/1.4.2/docs/api/java/util/logging/Logger.html中的getLoggerNames()、getLogger()和setLevel()进行调整。 - BenoitParis
5
如果你在Windows下运行Java应用程序并启动控制台，请小心不要点击DOS框。Windows的糟糕“标记和复制”功能会阻止输出到ConsoleHandler。因此，任何尝试写入屏幕的日志记录器都将被阻止。写入控制台是通过本机调用完成的，因此当Java线程被阻塞时，它看起来是RUNNING状态，实际上是被阻塞了，只是没有办法将这个被阻塞的状态反馈给应用程序（因为你在本机空间中）。如果应用程序被阻塞（你已经点击了DOS框），请按Esc键继续。
0
根据您的日志，问题涉及使用java.util.logging.ConsoleHandler。
首先尝试通过从'${TOMCAT_HOME}/conf/logging.properties'中的'handlers'和'.handlers'列表中删除控制台处理程序来禁用控制台处理程序。查看问题是否仍然存在。
如果有帮助，则肯定存在ConsoleHandler输出的问题。尝试检查是否存在与'catalina.out'文件相关的问题。这是Tomcat重定向其控制台输出的文件。
0
我从未使用过java.util.logging，所以不知道我的建议是否有用，但无论如何：
尝试使用不同的java.util.logging.Logger实例，这样不会有240个线程被阻塞在同一个监视器上
（如果Logger的不同实例使用不同的java.util.logging.ConsoleHandler实例，则会有所帮助）。
0

看起来拥有“0x00007fe37e72b340”的线程在IO层面被阻塞了。可能是磁盘（RAID？）问题？

您能否在5分钟后进行线程转储，以查看是否仍然阻塞同一线程？

谢谢你的建议，我会在接下来几个小时的崩溃中尝试监控线程活动。 - Alexandre Boudreault
0

如果你的日志非常冗长，每个日志记录后都进行刷新会很昂贵。

一个高质量的解决方案是清理日志记录，可能基于审计。

作为一个快速解决方法，可以覆盖StreamHandler.flush或OutputStream.flush以不立即执行刷新。只有在一段时间后才进行刷新。但请注意，如果这样做，你可能会在崩溃前立即丢失日志数据。

网页内容由stack overflow 提供, 点击上面的
可以查看英文原文，
原文链接