1. Inicio
  2. Pregunta y respuesta
  3. bloqueo de subproceso Java

bloqueo de subproceso Java

2010-08-20 21 views
5

tengo un problema con mi entorno Java. Estoy ejecutando Solr 1.3 (motor de búsqueda) desde hace más de un año y de repente tengo muchos problemas con él. Todo mi grupo de subprocesos (250) se bloqueó aleatoriamente una o dos veces al día. No hice ningún cambio en mi aplicación solr o en mi servidor tomcat.bloqueo de subproceso Java

Estoy ejecutando Tomcat 5.5.25 y Solr 1.3. Tengo un vertedero de hilo cuando el sistema está totalmente sobrecargado:

Igot como 240 hilo como éste:

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

podemos ver que este hilo se bloquea y esperando en: < 0x00007fe37e72b340>

el hilo que realmente posee el < 0x00007fe37e72b340> es éste:

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

y esta es la última parte de mi thre ad volcado:

"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

Sé que esto no es un callejón sin salida prob hilo desde un hilo es en realidad Runnning con toda la ressource cada otro hilo quiere.

¿Alguien tiene una idea de lo que puede causar este problema?

Fuente

2010-08-20 Alexandre Boudreault

Respuesta

0

nunca he usado java.util.logging, así que no sé si mi sugerencia es útil, pero netherless:
tratar de utilizar diferentes instancia de java.util.logging.Logger, por lo que no todos los hilos 240 serán bloqueados en el mismo monitor
(se ayudará si diferentes instancias de Logger usan instancias diferentes de java.util.logging.ConsoleHandler).

Fuente

2010-08-20 14:26:51

0

Parece que el hilo que posee "0x00007fe37e72b340" está bloqueado en el nivel IO. Tal vez un problema de disco (¿ataque?)

¿Puedes hacer un volcado de hilo 5 minutos después para ver si el mismo hilo todavía está bloqueado?

Fuente

2010-08-20 14:27:12

+0

Gracias por los consejos, intentaré monitorear la actividad del hilo durante el próximo choque en un par de horas;) –

5

Todos sus hilos están registrando cosas. Todos ellos necesitan escribir en el disco de vez en cuando. Cada vez que uno de sus 240 hilos llegue a una línea de registro, habrá problemas de acceso al disco.

Me desconcierta que el hilo que tiene el bloqueo está en estado RUNNABLE.

creo que podría estar esperando un buen ressource externa para ser lanzado (como el acceso al disco, por ejemplo)

¿Está ejecutando poco espacio en disco? ¿Ha cambiado algo recientemente en su sistema de almacenamiento?

Fuente

2010-08-20 14:29:56 BenoitParis

+1

Creo que este es el camino correcto. Me gustaría ver los factores externos. Además, si está escribiendo no en un archivo tradicional sino en una tubería con nombre de Unix, asegúrese de que alguien esté leyendo el otro extremo de la tubería a un ritmo suficiente. Si el buffer se llena, simplemente bloquearás. –

+0

El espacio en disco está bien y no hemos cambiado nada en el sistema. Intentamos cambiar el sistema en otro servidor y obtuvimos el mismo problema. –

+0

No creo que esto sea un problema con la seguridad del subproceso. Hubiera roto mucho antes. 240 subprocesos no es un problema para la JVM. 240 Temas que pueden editar un solo archivo. Un arreglo feo sería reducir la cantidad de mensajes registrados. Intente ajustar la cosa usando getLoggerNames(), getLogger() y setLevel() desde http://download-llnw.oracle.com/javase/1.4.2/docs/api/java/util/logging/LogManager.html y http://download-llnw.oracle.com/javase/1.4.2/docs/api/java/util/logging/Logger.html – BenoitParis

0

El enjuague después de cada registro de registro va a ser costoso si tiene registros muy detallados.

Una solución de calidad sería limpiar el registro, probablemente en función de la auditoría.

Como solución rápida, anule StreamHandler.flush o OutputStream.flush para no hacerlo inmediatamente. Solo enjuague una vez cada cierto tiempo. Sin embargo, tenga en cuenta que podría perder datos de registro inmediatamente antes de un bloqueo si lo hace.

Fuente

2010-08-20 14:35:08

5

Si está ejecutando Windows y la aplicación java inicia una consola, tenga cuidado de no hacer clic en el cuadro de DOS. La "marca" de crappy mark y copy de Windows bloquea la salida al ConsoleHandler. Entonces cualquier bloqueador que intente escribir en la pantalla se bloqueará. Escribir en la consola se realiza en una llamada nativa y, por lo tanto, el hilo de Java aparecerá en estado EN EJECUCIÓN cuando, de hecho, está bloqueado, simplemente no hay manera de devolver ese estado bloqueado a la aplicación (porque usted está en idioma nativo espacio).

Si la aplicación está bloqueada (ha hecho clic en el cuadro de DOS), presione escape para continuar.

Fuente

2012-06-20 13:21:20

0

De acuerdo con su registro, el problema se relaciona con el uso de java.util.logging.ConsoleHandler.

Primero intente deshabilitar el controlador de la consola eliminándolo de la lista 'controladores' y 'manejadores' en '$ {INICIO_TOMACA} /conf/logging.properties'. Vea si el problema todavía ocurre.

Si eso ayuda, entonces definitivamente es un problema con la salida del ConsoleHandler. Intente comprobar si hay problemas relacionados con el archivo 'catalina.out'. Este es el archivo al que tomcat redirige su salida de consola.

Fuente

2013-12-11 20:05:19 dstibbe

Cuestiones relacionadas

 Cuestiones relacionadas