El subproceso Java que ejecuta la operación restante en un bucle bloquea todos los demás subprocesos

El siguiente fragmento de código ejecuta dos subprocesos, uno es un temporizador simple que registra cada segundo, el segundo es un bucle infinito que ejecuta una operación restante:

public class TestBlockingThread {
    private static final Logger LOGGER = LoggerFactory.getLogger(TestBlockingThread.class);

    public static final void main(String[] args) throws InterruptedException {
        Runnable task = () -> {
            int i = 0;
            while (true) {
                i++;
                if (i != 0) {
                    boolean b = 1 % i == 0;
                }
            }
        };

        new Thread(new LogTimer()).start();
        Thread.sleep(2000);
        new Thread(task).start();
    }

    public static class LogTimer implements Runnable {
        @Override
        public void run() {
            while (true) {
                long start = System.currentTimeMillis();
                try {
                    Thread.sleep(1000);
                } catch (InterruptedException e) {
                    // do nothing
                }
                LOGGER.info("timeElapsed={}", System.currentTimeMillis() - start);
            }
        }
    }
}

Esto da el siguiente resultado:

[Thread-0] INFO  c.m.c.concurrent.TestBlockingThread - timeElapsed=1004
[Thread-0] INFO  c.m.c.concurrent.TestBlockingThread - timeElapsed=1003
[Thread-0] INFO  c.m.c.concurrent.TestBlockingThread - timeElapsed=13331
[Thread-0] INFO  c.m.c.concurrent.TestBlockingThread - timeElapsed=1006
[Thread-0] INFO  c.m.c.concurrent.TestBlockingThread - timeElapsed=1003
[Thread-0] INFO  c.m.c.concurrent.TestBlockingThread - timeElapsed=1004
[Thread-0] INFO  c.m.c.concurrent.TestBlockingThread - timeElapsed=1004

No entiendo por qué la tarea infinita bloquea todos los otros hilos durante 13,3 segundos. Traté de cambiar las prioridades del hilo y otras configuraciones, nada funcionó.

Si tiene alguna sugerencia para solucionar esto (incluida la modificación de la configuración de cambio de contexto del sistema operativo), hágamelo saber.

Después de todas las explicaciones aquí (gracias a Peter Lawrey ) descubrimos que la fuente principal de esta pausa es que el punto seguro dentro del bucle se alcanza con bastante poca frecuencia, por lo que lleva mucho tiempo detener todos los hilos para el reemplazo del código compilado JIT.

Pero decidí profundizar y descubrir por qué raramente se alcanza el punto seguro. Me pareció un poco confuso por qué el salto hacia atrás del whilebucle no es "seguro" en este caso.

Entonces convoco -XX:+PrintAssemblyen toda su gloria para ayudar

-XX:+UnlockDiagnosticVMOptions \
-XX:+TraceClassLoading \
-XX:+DebugNonSafepoints \
-XX:+PrintCompilation \
-XX:+PrintGCDetails \
-XX:+PrintStubCode \
-XX:+PrintAssembly \
-XX:PrintAssemblyOptions=-Mintel

Después de un poco de investigación, descubrí que después de una tercera recopilación del C2compilador lambda , descarté completamente las encuestas de punto seguro dentro del bucle.

ACTUALIZAR

Durante la etapa de perfil, la variable inunca se vio igual a 0. Es por eso que C2optimizó especulativamente esta rama, de modo que el bucle se transformó en algo así como

for (int i = OSR_value; i != 0; i++) {
    if (1 % i == 0) {
        uncommon_trap();
    }
}
uncommon_trap();

¡Tenga en cuenta que el bucle infinito original se reformó en un bucle finito regular con un contador! Debido a la optimización JIT para eliminar las encuestas de punto seguro en bucles contados finitos, tampoco hubo encuesta de punto seguro en este bucle.

Después de un tiempo, iregresó 0y la trampa poco común fue tomada. El método se desoptimizó y se siguió ejecutando en el intérprete. Durante la C2compilación con un nuevo conocimiento reconoció el bucle infinito y abandonó la compilación. El resto del método procedió en el intérprete con los puntos de seguridad adecuados.

Hay una gran publicación de blog que debe leerse "Safepoints: significado, efectos secundarios y gastos generales" por Nitsan Wakart que cubre los puntos seguros y este tema en particular.

Se sabe que la eliminación de puntos seguros en bucles contados muy largos es un problema. El error JDK-5014723(gracias a Vladimir Ivanov ) soluciona este problema.

La solución alternativa está disponible hasta que finalmente se solucione el error.

1. Puedes probar a utilizar -XX:+UseCountedLoopSafepoints(que va a causar pena de actuación global y puede conducir a bloqueo de JVM JDK-8161147 ). Después de usar el C2compilador, continúe manteniendo los puntos seguros en los saltos hacia atrás y la pausa original desaparecerá por completo.

2. Puede deshabilitar explícitamente la compilación del método problemático utilizando
   -XX:CompileCommand='exclude,binary/class/Name,methodName'

3. O puede reescribir su código agregando Safepoint manualmente. Por ejemplo, Thread.yield()llamar al final del ciclo o incluso cambiar int ia long i(gracias, Nitsan Wakart ) también reparará la pausa.

En resumen, el bucle que tiene no tiene un punto seguro dentro, excepto cuando i == 0se alcanza. Cuando este método se compila y activa el código que se debe reemplazar, debe llevar todos los subprocesos a un punto seguro, pero esto lleva mucho tiempo, bloqueando no solo el subproceso que ejecuta el código sino todos los subprocesos en la JVM.

Agregué las siguientes opciones de línea de comando.

-XX:+PrintGCApplicationStoppedTime -XX:+PrintGCApplicationConcurrentTime -XX:+PrintCompilation

También modifiqué el código para usar el punto flotante que parece tomar más tiempo.

boolean b = 1.0 / i == 0;

Y lo que veo en la salida es

timeElapsed=100
Application time: 0.9560686 seconds
  41423  280 %     4       TestBlockingThread::lambda$main$0 @ -2 (27 bytes)   made not entrant
Total time for which application threads were stopped: 40.3971116 seconds, Stopping threads took: 40.3967755 seconds
Application time: 0.0000219 seconds
Total time for which application threads were stopped: 0.0005840 seconds, Stopping threads took: 0.0000383 seconds
  41424  281 %     3       TestBlockingThread::lambda$main$0 @ 2 (27 bytes)
timeElapsed=40473
  41425  282 %     4       TestBlockingThread::lambda$main$0 @ 2 (27 bytes)
  41426  281 %     3       TestBlockingThread::lambda$main$0 @ -2 (27 bytes)   made not entrant
timeElapsed=100

Nota: para que el código sea reemplazado, los hilos deben detenerse en un punto seguro. Sin embargo, parece que aquí rara vez se alcanza un punto seguro (posiblemente solo cuando se i == 0cambia la tarea a

Runnable task = () -> {
    for (int i = 1; i != 0 ; i++) {
        boolean b = 1.0 / i == 0;
    }
};

Veo un retraso similar.

timeElapsed=100
Application time: 0.9587419 seconds
  39044  280 %     4       TestBlockingThread::lambda$main$0 @ -2 (28 bytes)   made not entrant
Total time for which application threads were stopped: 38.0227039 seconds, Stopping threads took: 38.0225761 seconds
Application time: 0.0000087 seconds
Total time for which application threads were stopped: 0.0003102 seconds, Stopping threads took: 0.0000105 seconds
timeElapsed=38100
timeElapsed=100

Si agrega código al bucle con cuidado, obtendrá un retraso mayor.

for (int i = 1; i != 0 ; i++) {
    boolean b = 1.0 / i / i == 0;
}

consigue

 Total time for which application threads were stopped: 59.6034546 seconds, Stopping threads took: 59.6030773 seconds

Sin embargo, cambie el código para usar un método nativo que siempre tenga un punto seguro (si no es intrínseco)

for (int i = 1; i != 0 ; i++) {
    boolean b = Math.cos(1.0 / i) == 0;
}

huellas dactilares

Total time for which application threads were stopped: 0.0001444 seconds, Stopping threads took: 0.0000615 seconds

Nota: agregar if (Thread.currentThread().isInterrupted()) { ... }a un bucle agrega un punto seguro.

Nota: Esto sucedió en una máquina de 16 núcleos, por lo que no faltan recursos de CPU.

Encontré la respuesta de por qué . Se llaman puntos de seguridad, y son más conocidos como Stop-The-World que sucede debido a GC.

Vea estos artículos: Registro de pausas para detener el mundo en JVM

Diferentes eventos pueden hacer que la JVM pause todos los hilos de la aplicación. Dichas pausas se llaman pausas Stop-The-World (STW). La causa más común para que se active una pausa STW es la recolección de basura (ejemplo en github), pero diferentes acciones JIT (ejemplo), revocación de bloqueo sesgada (ejemplo), ciertas operaciones JVMTI y muchas más también requieren que se detenga la aplicación.

Los puntos en los que los subprocesos de la aplicación pueden detenerse de forma segura se llaman, sorpresa, puntos seguros . Este término también se usa a menudo para referirse a todas las pausas STW.

Es más o menos común que los registros de GC estén habilitados. Sin embargo, esto no captura información sobre todos los puntos seguros. Para obtenerlo todo, use estas opciones de JVM:

-XX:+PrintGCApplicationStoppedTime -XX:+PrintGCApplicationConcurrentTime

Si se está preguntando si los nombres se refieren explícitamente a GC, no se alarme: al activar estas opciones se registran todos los puntos seguros, no solo las pausas de recolección de basura. Si ejecuta el siguiente ejemplo (fuente en github) con los indicadores especificados anteriormente.

Al leer el Glosario de términos de HotSpot , define esto:

punto seguro

Un punto durante la ejecución del programa en el que se conocen todas las raíces de GC y todos los contenidos de los objetos de montón son consistentes. Desde un punto de vista global, todos los hilos deben bloquearse en un punto seguro antes de que el GC pueda ejecutarse. (Como un caso especial, los subprocesos que ejecutan código JNI pueden continuar ejecutándose, ya que solo usan identificadores. Durante un punto seguro, deben bloquear en lugar de cargar el contenido del identificador). Desde un punto de vista local, un punto seguro es un punto distinguido en un bloque de código donde el hilo en ejecución puede bloquear para el GC. La mayoría de los sitios de llamadas califican como puntos seguros.Hay fuertes invariantes que son válidos en todos los puntos seguros, que pueden ignorarse en los puntos no seguros. Tanto el código Java compilado como el código C / C ++ se optimizarán entre los puntos seguros, pero no tanto en los puntos seguros. El compilador JIT emite un mapa GC en cada punto seguro. El código C / C ++ en la VM utiliza convenciones estilizadas basadas en macros (por ejemplo, TRAPS) para marcar posibles puntos seguros.

Al ejecutar los indicadores mencionados anteriormente, obtengo este resultado:

Application time: 0.9668750 seconds
Total time for which application threads were stopped: 0.0000747 seconds, Stopping threads took: 0.0000291 seconds
timeElapsed=1015
Application time: 1.0148568 seconds
Total time for which application threads were stopped: 0.0000556 seconds, Stopping threads took: 0.0000168 seconds
timeElapsed=1015
timeElapsed=1014
Application time: 2.0453971 seconds
Total time for which application threads were stopped: 10.7951187 seconds, Stopping threads took: 10.7950774 seconds
timeElapsed=11732
Application time: 1.0149263 seconds
Total time for which application threads were stopped: 0.0000644 seconds, Stopping threads took: 0.0000368 seconds
timeElapsed=1015

Observe el tercer evento STW:
Tiempo total detenido: 10.7951187 segundos La
detención de subprocesos tardó: 10.7950774 segundos

JIT en sí prácticamente no tomó tiempo, pero una vez que JVM decidió realizar una compilación JIT, entró en modo STW, sin embargo, dado que el código que se compilará (el bucle infinito) no tiene un sitio de llamada , nunca se llegó a ningún punto seguro.

El STW termina cuando JIT finalmente deja de esperar y concluye que el código está en un bucle infinito.

Después de seguir los hilos de comentarios y algunas pruebas por mi cuenta, creo que la pausa es causada por el compilador JIT. Por qué el compilador de JIT está tardando tanto tiempo está más allá de mi capacidad de depurar.

Sin embargo, dado que solo preguntó cómo prevenir esto, tengo una solución:

Lleva tu bucle infinito a un método donde pueda excluirse del compilador JIT

public class TestBlockingThread {
    private static final Logger LOGGER = Logger.getLogger(TestBlockingThread.class.getName());

    public static final void main(String[] args) throws InterruptedException     {
        Runnable task = () -> {
            infLoop();
        };
        new Thread(new LogTimer()).start();
        Thread.sleep(2000);
        new Thread(task).start();
    }

    private static void infLoop()
    {
        int i = 0;
        while (true) {
            i++;
            if (i != 0) {
                boolean b = 1 % i == 0;
            }
        }
    }

Ejecute su programa con este argumento VM:

-XX: CompileCommand = exclude, PACKAGE.TestBlockingThread :: infLoop (reemplace PACKAGE con la información de su paquete)

Debería recibir un mensaje como este para indicar cuándo se habría compilado el método JIT:
### Excluyendo la compilación: bloqueo estático.TestBlockingThread :: infLoop
puede notar que puse la clase en un paquete llamado bloqueo