Блокировка потока Java - PullRequest
Новая
       2

Блокировка потока Java

5 голосов
/ 20 августа 2010

У меня проблема с моей средой Java. Я использую Solr 1.3 (поисковик) уже более года, и внезапно у меня возникли большие проблемы с ним. Весь мой пул потоков (250) блокировался случайным образом один или два раза в день. Я не сделал никаких изменений в моем приложении solr или на сервере Tomcat.

Я использую Tomcat 5.5.25 и Solr 1.3. Я получил дамп потока, когда система полностью перегружена:

igot, как 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 голосов
/ 20 июня 2012

Если вы работаете под Windows, и java-приложение запускает консоль, будьте осторожны, чтобы не щелкнуть в поле DOS. Дрянная пометка окна и копирование «функциональных» блоков выводятся в ConsoleHandler. Так что любой регистратор, пытающийся записать на экран, заблокируется. Запись в консоль выполняется в собственном вызове, и, таким образом, поток java, по-видимому, находится в состоянии RUNNING, когда на самом деле он заблокирован, просто нет способа передать это заблокированное состояние обратно приложению (потому что вы находитесь в native пространство).

Если приложение заблокировано (вы щелкнули в поле DOS), нажмите escape для продолжения.

5 голосов
/ 20 августа 2010

Все ваши темы регистрируют вещи. Им всем нужно время от времени записывать на диск. Каждый раз, когда один из 240 потоков попадает в строку журнала, возникают проблемы с доступом к диску.

Меня сбивает с толку, что Поток, имеющий блокировку, находится в состоянии RUNNABLE.

Я думаю, что он может ожидать освобождения какого-либо внешнего ресурса (например, доступа к диску)

Недостаточно места на диске? Вы недавно что-то изменили в своей системе хранения?

0 голосов
/ 12 декабря 2013

Согласно вашему журналу, проблема касается использования java.util.logging.ConsoleHandler.

Сначала попробуйте отключить консольный обработчик, удалив его из списка «обработчики» и «.handlers» в «$ {TOMCAT_HOME} /conf/logging.properties». Посмотрите, возникает ли проблема по-прежнему.

Если это поможет, то это определенно проблема с выводом ConsoleHandler. Попробуйте проверить, есть ли проблемы с файлом catalina.out. Это файл, куда tomcat перенаправляет вывод на консоль.

0 голосов
/ 20 августа 2010

Очистка после каждой записи в журнале обходится дорого, если у вас очень подробные журналы.

Качественным исправлением будет очистка журналов, возможно, основанная на аудите.исправить, переопределить StreamHandler.flush или OutputStream.flush, чтобы не делать это немедленно.Промывайте только один раз так часто.Обратите внимание, однако, что вы можете потерять данные регистрации непосредственно перед сбоем, если вы сделаете это.

0 голосов
/ 20 августа 2010

Кажется, что поток, которому принадлежит "0x00007fe37e72b340", заблокирован на уровне ввода-вывода. Может проблема с диском (рейдом?)?

Можете ли вы сделать дамп потока через 5 минут, чтобы увидеть, заблокирован ли тот же поток?

0 голосов
/ 20 августа 2010

Я никогда не использовал java.util.logging, так что я не знаю, полезно ли мое предложение, но без него:
попробуйте использовать другой экземпляр java.util.logging.Logger, чтобы не все 240 потоков были заблокированы на одном мониторе
(это поможет, если разные экземпляры Logger используют разные экземпляры java.util.logging.ConsoleHandler).

...