2010-08-20 11 views
5

Mam problem z moim środowiskiem java. Używam Solr 1.3 (wyszukiwarki) od ponad roku i nagle mam z tym wiele kłopotów. Cała moja pula wątków (250) została losowo zablokowana raz lub dwa razy dziennie. Nie wprowadziłem żadnych zmian w mojej aplikacji solr lub na serwerze Tomcat.Blokowanie wątków Java

Używam programów tomcat 5.5.25 i Solr 1.3. Mam zrzut wątek, gdy system jest całkowicie przeciążony:

igot jak 240 wątek jak ten:

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

Widzimy, że ten wątek jest zablokowany i czeka na: < 0x00007fe37e72b340>

wątek, który faktycznie właścicielem < 0x00007fe37e72b340> jest to jedno:

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

i jest to ostatnia część mojego thre wysypisko reklamy:

"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 

wiem, że to nie jest prob wątek impas ponieważ jeden wątek jest faktycznie uruchomiona wraz ze wszystkimi ressource każdy inny wątek ma.

Ktoś wpadł na pomysł, co może spowodować ten problem?

Odpowiedz

0

nigdy nie użyłem java.util.logging, więc nie wiem, czy moja sugestia jest przydatna, ale netherless:
spróbować użyć inną instancję java.util.logging.Logger, więc nie wszystkie wątki 240 zostaną zablokowane na tym samym monitorze
(IT pomoże, jeśli różne instancje Logger używają różnych instancji java.util.logging.ConsoleHandler).

0

Wygląda na to, że wątek będący właścicielem "0x00007fe37e72b340" jest zablokowany na poziomie IO. Może problem z dyskiem (raid?)?

czy można zrobić zrzut wątku 5 minut później, czy ten sam wątek jest nadal zablokowany?

+0

Dzięki za porady, złego starają się monitorować aktywność gwintu podczas kolejnej katastrofie w ciągu kilku godzin;) –

5

Wszystkie twoje wątki rejestrują rzeczy. Od czasu do czasu wszyscy muszą pisać na dysku. Za każdym razem, gdy jeden z 240 wątków trafi na linię logowania, wystąpią problemy z dostępem do dysku.

To zbija mnie z tropu, że Wątek mający blokadę znajduje się w stanie RUNNABLE.

myślę, że może czekać na jakiś zewnętrzny ressource zostać zwolniony (jak na przykład dostęp do dysku)

Czy zaczyna brakować miejsca na dysku? Czy ostatnio zmieniłeś coś w swoim systemie przechowywania?

+1

myślę, że to jest właściwy tor. Przyjrzałbym się czynnikom zewnętrznym. Ponadto, jeśli to nie jest pisanie do tradycyjnego pliku, ale do Unix nazwanego potoku, upewnij się, że ktoś czyta drugi koniec rury w wystarczającym tempie. Jeśli bufor się zapełni, po prostu zablokujesz. –

+0

Miejsce na dysku jest w porządku, a my nie zmieniliśmy niczego w systemie. Próbowaliśmy zmienić system na innym serwerze i mieliśmy ten sam problem. –

+0

Nie sądzę, że jest to problem związany z bezpieczeństwem wątków. Zepsułoby się znacznie wcześniej. 240 Wątki nie stanowią problemu dla maszyny JVM. 240 Wątek edytowania pojedynczego pliku może być. Jest brzydki fix byłoby zmniejszyć ilość zarejestrowanych komunikatów. Spróbuj szczypanie rzeczy używając getLoggerNames(), getLogger() i() setLevel z http://download-llnw.oracle.com/javase/1.4.2/docs/api/java/util/logging/LogManager.html i http://download-llnw.oracle.com/javase/1.4.2/docs/api/java/util/logging/Logger.html – BenoitParis

0

Płukanie po każdym zapisie w dzienniku będzie kosztowne, jeśli masz bardzo szczegółowe dzienniki.

Poprawką jakości byłoby oczyszczenie rejestrowania, prawdopodobnie w oparciu o audyt.

Aby szybko to zrobić, należy zastąpić StreamHandler.flush lub OutputStream.flush, aby tego nie robić. Spłukiwać tylko raz tak często. Należy jednak pamiętać, że w takim przypadku potencjalnie można utracić dane rejestrowania bezpośrednio przed awarią.

5

Jeśli korzystasz z systemu Windows, a aplikacja java uruchamia konsolę, należy uważać, aby nie kliknąć w oknie DOS. Okropny znak Window i kopiowanie bloków "feature" do konsoli ConsoleHandler. Więc każdy program próbujący pisać na ekranie będzie blokował. Pisanie do konsoli odbywa się w wywołaniu natywnym, więc wątek java będzie wyglądał w stanie PRAGNIENIA, podczas gdy w rzeczywistości jest zablokowany, to po prostu nie ma możliwości, aby zasilić ten zablokowany status powrotem do aplikacji (ponieważ jesteś w macierzystym języku). przestrzeń).

Jeśli aplikacja jest zablokowana (kliknąłeś w pole DOS), naciśnij przycisk escape, aby kontynuować.

0

Zgodnie z dziennikiem problem dotyczy użycia java.util.logging.ConsoleHandler.

Najpierw spróbuj wyłączyć procedurę obsługi konsoli, usuwając ją z listy "handlery" i ".handlers" w katalogu $ {TOMCAT_HOME} /conf/logging.properties. Sprawdź, czy problem nadal występuje.

Jeśli to pomaga, to zdecydowanie jest problem z wyjściem ConsoleHandler. Spróbuj sprawdzić, czy są jakieś problemy dotyczące pliku "catalina.out". Jest to plik, do którego tomcat przekierowuje wyjście konsoli.