Java Thread blockiert

Ich habe ein Problem mit meiner Java-Umgebung. Ich betreibe Solr 1.3 (Suchmaschine) seit mehr als einem Jahr und plötzlich bekam ich eine Menge Ärger damit. Mein gesamter Thread-Pool (250) wurde ein- oder zweimal am Tag zufällig blockiert. Ich habe keine Änderungen an meiner Solr-Anwendung oder an meinem Tomcat-Server vorgenommen.Java Thread blockiert

Ich benutze Tomcat 5.5.25 und Solr 1.3. Ich bekam ein Thread-Dump, wenn das System völlig überlastet ist:

igot wie 240-Thread wie dieser:

"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)

Wir können sehen, dass dieser Thread blockiert und wartet auf: < 0x00007fe37e72b340>

der Faden, der die < 0x00007fe37e72b340> tatsächlich besitzen ist diese:

"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)

und dies ist der letzte Teil meines dre ad dump:

"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

Ich weiß, das ist kein Thread-Deadlock prob ist, da ein Thread eigentlich mit der ganzen ressource wollen, dass jeder andere Thread runnning.

Wer hat eine Idee von was kann dieses Problem verursachen?

Quelle

2010-08-20 Alexandre Boudreault

Ich habe selber nie java.util.logging, so dass ich weiß nicht, ob mein Vorschlag nützlich, aber netherless:
versuchen andere Instanz java.util.logging.Logger, zu verwenden, um nicht alle 240 Threads auf demselben Monitor blockiert werden
(it wird helfen, wenn verschiedene Instanzen von Logger verschiedene Instanzen von java.util.logging.ConsoleHandler verwenden).

Quelle

2010-08-20 14:26:51

Es scheint, dass der Thread, der "0x00007fe37e72b340" besitzt, auf der IO-Ebene blockiert ist. Vielleicht ein Datenträger (Raid?) Problem?

Kannst du einen Thread Dump machen 5 Minuten später die sehen, ob der gleiche Thread noch blockiert ist?

Quelle

2010-08-20 14:27:12

Vielen Dank für die Tipps, versuchen Sie, Thread-Aktivität während des nächsten Absturzes in ein paar Stunden zu überwachen;) –

Alle Ihre Threads protokollieren Dinge. Sie müssen alle von Zeit zu Zeit auf die Festplatte schreiben. Jedes Mal, wenn einer Ihrer 240 Threads auf eine Protokollierungszeile trifft, treten Probleme beim Zugriff auf die Festplatte auf.

Es verblüfft mich, dass der Thread mit der Sperre im Zustand RUNNABLE ist.

ich denke, es könnte für einige externe Ressource warten freigegeben werden (Beispiel wie Plattenzugriff für)

Sind Sie wenig Speicherplatz laufen? Haben Sie kürzlich etwas in Ihrem Speichersystem geändert?

Quelle

2010-08-20 14:29:56 BenoitParis

Ich denke, das ist der richtige Track. Ich würde externe Faktoren betrachten. Wenn Sie nicht in eine herkömmliche Datei, sondern in eine Named Pipe schreiben, stellen Sie sicher, dass jemand das andere Ende der Pipe in ausreichendem Tempo liest. Wenn der Puffer voll ist, blocken Sie einfach. –

Der Speicherplatz ist gut und wir haben nichts am System geändert. Wir haben versucht, das System auf einen anderen Server umzustellen, und wir haben das gleiche Problem. –

Ich glaube nicht, dass dies ein Problem mit Thread Sicherheit ist. Es wäre viel früher gebrochen. 240 Threads ist kein Problem für die JVM. 240 Threads bearbeiten eine einzelne Datei könnte. Ein hässlicher Fix wäre, die Menge der protokollierten Nachrichten zu reduzieren. Versuchen Sie, die Sache mit getLoggerNames(), getLogger() und setLevel() von http://download-llnw.oracle.com/javase/1.4.2/docs/api/java/util/logging/LogManager.html zu optimieren und http://download-llnw.oracle.com/javase/1.4.2/docs/api/java/util/logging/Logger.html – BenoitParis

Spülen nach jedem Protokolleintrag wird teuer, wenn Sie sehr ausführliche Protokolle haben.

Eine Qualitätsverbesserung wäre, die Protokollierung zu bereinigen, wahrscheinlich basierend auf Auditing.

Als schnelle Lösung, überschreiben Sie StreamHandler.flush oder OutputStream.flush, um dies nicht sofort zu tun. Nur gelegentlich spülen. Beachten Sie jedoch, dass Sie möglicherweise Protokollierungsdaten unmittelbar vor einem Absturz verlieren könnten, wenn Sie dies tun.

Quelle

2010-08-20 14:35:08

Wenn Sie unter Windows laufen und die Java-Anwendung eine Konsole startet, achten Sie darauf, nicht in die DOS-Box zu klicken. Window's crappy markiere und kopiere "feature" blockiere die Ausgabe in den ConsoleHandler. So wird jeder Logger, der versucht auf den Bildschirm zu schreiben, blockieren. Das Schreiben in die Konsole erfolgt in einem systemeigenen Aufruf, und der Java-Thread wird scheinbar im Status RUNNING sein, obwohl er tatsächlich blockiert ist. Es ist einfach nicht möglich, diesen blockierten Status an die Anwendung zurückzugeben (weil Sie nativ sind) Raum).

Wenn die Anwendung blockiert ist (Sie haben in der DOS-Box geklickt), drücken Sie Esc, um fortzufahren.

Quelle

2012-06-20 13:21:20

Gemäß Ihrem Protokoll betrifft das Problem die Verwendung von java.util.logging.ConsoleHandler.

Versuchen Sie zuerst, den Konsolen-Handler zu deaktivieren, indem Sie ihn aus der Liste 'Handler' und '.handlers' in '$ {TOMCAT_HOME} /conf/logging.properties' entfernen. Überprüfen Sie, ob das Problem weiterhin auftritt.

Wenn das hilft, dann ist es definitiv ein Problem mit der Ausgabe des ConsoleHandler. Überprüfen Sie, ob es Probleme mit der Datei "catalina.out" gibt. Dies ist die Datei, in die Tomcat seine Konsolenausgabe umleitet.

Quelle

2013-12-11 20:05:19 dstibbe

Antwort

Verwandte Themen