java - log - Volcado de hilo bloqueado Y bloqueado

solaris thread dump

Question

Esto es similar al volcado de hilo Java: BLOQUEADO hilo sin "esperar para bloquear ..." .

Básicamente, estoy viendo un hilo BLOQUEADO pero tiene el bloqueo que está esperando:

"pool-1-thread-60" prio=10 tid=0x00007fbf10017000 nid=0x210 waiting for monitor entry [0x00007fbed64e3000]
   java.lang.Thread.State: BLOCKED (on object monitor)
        at org.apache.log4j.Category.callAppenders(Category.java:204)
        - locked <0x0000000742444ad0> (a org.apache.log4j.Logger)
        at org.apache.log4j.Category.forcedLog(Category.java:391)
        at org.apache.log4j.Category.info(Category.java:666)
        ...

Esperaría ver - waiting to lock <0x0000000742444ad0>... lugar de - locked... La otra pregunta sugiere que la recolección de basura es la causa, pero si ese fuera el caso, ¿no se BLOQUEARÁN todos los hilos? Hay otros hilos que son RUNNABLES. Además, ¿cómo podría probar que ese fue el caso? ¿Por qué sería este el comportamiento observado? No quiero ir ciegamente suponiendo que es el recolector de basura, solo descubrir días después que era otra cosa.

== Información auxiliar ==

Aunque no creo que sea relevante para el tema en cuestión, esta es la sección de código de la que proviene el volcado anterior.

for(Category c = this; c != null; c=c.parent) {
  // Protected against simultaneous call to addAppender, removeAppender,...
  synchronized(c) { //line 204
if(c.aai != null) {
  writes += c.aai.appendLoopOnAppenders(event);
}
if(!c.additive) {
  break;
}
  }
}

Claramente, hay un bloqueo que debe obtenerse en esa línea. SIN EMBARGO, cuando un hilo está realmente bloqueado en este monitor, la salida en el volcado de hilo aparece como (esto viene del mismo volcado):

"pool-1-thread-44" prio=10 tid=0x00007fbef0051000 nid=0x200 waiting for monitor/
 entry [0x00007fbed74f3000]
   java.lang.Thread.State: BLOCKED (on object monitor)
        at org.apache.log4j.Category.callAppenders(Category.java:204)
        - waiting to lock <0x0000000742444ad0> (a org.apache.log4j.Logger)
        at org.apache.log4j.Category.forcedLog(Category.java:391)
        at org.apache.log4j.Category.info(Category.java:666)
        ...

La sección del volcado que me interesa parece diferente ("bloqueado" en lugar de "esperando bloquear"). He depurado muchos deadlocks y he visto muchos volcados de subprocesos. Lo que siempre veo es el "esperando para bloquear". Nunca he visto un hilo que esté "bloqueado" pero todavía "esperando la entrada del monitor" y quiero saber lo que eso significa.

Answer 1

Se adquiere un bloqueo en cada Logger mientras se itera sobre sus apéndices para evitar cambios simultáneos en la colección del appender. Si un subproceso está bloqueado en un appender (por ejemplo, escribir eventos a través de una conexión de red), otros hilos que Logger sesión en esa instancia de Logger deben esperar al bloqueo. Un AsyncAppender se puede usar para almacenar eventos y minimizar la contención, pero a riesgo de perder eventos en el búfer.

Lo extraño no es que veas "bloqueado" en lugar de "esperar para bloquear", sino que no ves "esperando para bloquear" además de "bloqueado". Es decir, parece que el hilo en cuestión es el que ganó la carrera para adquirir el registro en una categoría determinada, y ahora está esperando adquirir un bloqueo adicional en algún otro objeto. El misterio, entonces, es ¿por qué el vertedero no identifica el otro objeto?

Creo que su suposición de que es el Logger en el que ya tiene el bloqueo es incorrecto.

¿Todavía te preguntas cuál es la versión exacta que estás usando?

Answer 2

Este es un error cosmético conocido en HotSpot JVM de Oracle. Como dices, en tu rastro de pila donde ves - locked <0x00007f3e9a0b3830> en realidad debería decir - waiting to lock <0x00007f3e9a0b3830> ya que el hilo aún no ha adquirido el bloqueo relevante.

Mira este error para más detalles.