trabaja sirve que para jre jdk funciona con como java optimization jvm real-time low-latency

java - sirve - que es jvm y jre



¿Por qué la JVM muestra más latencia para el mismo bloque de código después de una pausa de giro ocupada? (2)

TL; DR

http://www.brendangregg.com/activebenchmarking.html

benchmarking informal: usted compara a A, pero en realidad mide B y concluye que ha medido C.

Problema N1. La primera medición después de la pausa cambia.

Parece que te enfrentas al reemplazo en la pila . Cuando se produce OSR, la máquina virtual está en pausa y el marco de pila para la función de destino se reemplaza por un marco equivalente.

El caso raíz es una microbenchmark incorrecta: no fue calentada adecuadamente. Simplemente inserte la siguiente línea en su punto de referencia antes de while loop para corregirlo:

System.out.println("WARMUP = " + busyPause(5000000000L));

Cómo comprobar esto: simplemente ejecute su punto de referencia con -XX:+UnlockDiagnosticVMOptions -XX:+PrintCompilation -XX:+TraceNMethodInstalls . Modifiqué tu código, ahora imprime el intervalo en la salida del sistema antes de cada llamada:

interval = 1 interval = 1 interval = 5000000000 689 145 4 JvmPauseLatency::busyPause (19 bytes) made not entrant 689 146 3 JvmPauseLatency::busyPause (19 bytes) Installing method (3) JvmPauseLatency.busyPause(J)J 698 147 % 4 JvmPauseLatency::busyPause @ 6 (19 bytes) Installing osr method (4) JvmPauseLatency.busyPause(J)J @ 6 702 148 4 JvmPauseLatency::busyPause (19 bytes) 705 146 3 JvmPauseLatency::busyPause (19 bytes) made not entrant Installing method (4) JvmPauseLatency.busyPause(J)J interval = 5000000000 interval = 5000000000 interval = 5000000000 interval = 5000000000

Por lo general, OSR se produce en el nivel 4, por lo que para deshabilitarlo puede usar las siguientes opciones:

  • -XX:-TieredCompilation deshabilita la compilación escalonada
  • -XX:-TieredCompilation -XX:TieredStopAtLevel=3 deshabilita la compilación por niveles hasta el nivel 4
  • -XX:+TieredCompilation -XX:TieredStopAtLevel=4 -XX:-UseOnStackReplacement deshabilitar OSR

Problema N2. Cómo medir.

Comencemos por el artículo https://shipilev.net/blog/2014/nanotrusting-nanotime . En pocas palabras:

  • JIT solo puede compilar el método: en tu prueba tienes un ciclo, por lo que solo OSR está disponible para tu prueba
  • Está intentando medir algo pequeño, tal vez más pequeño que nanoTime() llamada (consulte ¿Cuál es el costo de la escritura volátil? )
  • nivel de microarquitectura: las memorias caché, los puestos de almacenamiento de CPU son importantes; por ejemplo, la omisión de TLB o la predicción errónea de las ramas demoran más que el tiempo de ejecución de la prueba

Entonces, para evitar todos estos escollos, puede usar un benchmark basado en JMH como este:

import org.openjdk.jmh.annotations.*; import org.openjdk.jmh.infra.Blackhole; import org.openjdk.jmh.runner.Runner; import org.openjdk.jmh.runner.RunnerException; import org.openjdk.jmh.runner.options.Options; import org.openjdk.jmh.runner.options.OptionsBuilder; import org.openjdk.jmh.runner.options.VerboseMode; import java.util.Random; import java.util.concurrent.TimeUnit; @State(Scope.Benchmark) @OutputTimeUnit(TimeUnit.NANOSECONDS) @Warmup(iterations = 2, time = 1, timeUnit = TimeUnit.SECONDS) @Measurement(iterations = 2, time = 3, timeUnit = TimeUnit.SECONDS) @Fork(value = 2) public class LatencyTest { public static final long LONG_PAUSE = 5000L; public static final long SHORT_PAUSE = 1L; public Random rand; @Setup public void initI() { rand = new Random(0xDEAD_BEEF); } private long busyPause(long pauseInNanos) { Blackhole.consumeCPU(pauseInNanos); return pauseInNanos; } @Benchmark @BenchmarkMode({Mode.AverageTime}) public long latencyBusyPauseShort() { return busyPause(SHORT_PAUSE); } @Benchmark @BenchmarkMode({Mode.AverageTime}) public long latencyBusyPauseLong() { return busyPause(LONG_PAUSE); } @Benchmark @BenchmarkMode({Mode.AverageTime}) public long latencyFunc() { return doCalculation(1); } @Benchmark @BenchmarkMode({Mode.AverageTime}) public long measureShort() { long x = busyPause(SHORT_PAUSE); return doCalculation(x); } @Benchmark @BenchmarkMode({Mode.AverageTime}) public long measureLong() { long x = busyPause(LONG_PAUSE); return doCalculation(x); } private long doCalculation(long x) { long calculation = 0; calculation += x / (rand.nextInt(5) + 1); calculation -= calculation / (rand.nextInt(5) + 1); calculation -= x / (rand.nextInt(6) + 1); calculation += calculation / (rand.nextInt(6) + 1); return calculation; } public static void main(String[] args) throws RunnerException { Options options = new OptionsBuilder() .include(LatencyTest.class.getName()) .verbosity(VerboseMode.NORMAL) .build(); new Runner(options).run(); } }

Tenga en cuenta que he cambiado la implementación del bucle ocupado a Blackhole # consumeCPU () para evitar los efectos relacionados con el sistema operativo. Entonces mis resultados son:

Benchmark Mode Cnt Score Error Units LatencyTest.latencyBusyPauseLong avgt 4 15992.216 ± 106.538 ns/op LatencyTest.latencyBusyPauseShort avgt 4 6.450 ± 0.163 ns/op LatencyTest.latencyFunc avgt 4 97.321 ± 0.984 ns/op LatencyTest.measureLong avgt 4 16103.228 ± 102.338 ns/op LatencyTest.measureShort avgt 4 100.454 ± 0.041 ns/op

Tenga en cuenta que los resultados son casi aditivos, es decir, latencyFunc + latencyBusyPauseShort = measureShort

Problema N3. La discrepancia es grande.

¿Qué pasa con tu prueba? No calienta correctamente la JVM, es decir, usa un parámetro para calentar y otro para probar. ¿Porque es esto importante? JVM utiliza optimizaciones guiadas por perfil, por ejemplo, cuenta la frecuencia con que se ha tomado una rama y genera el código "mejor" (sin ramificación) para el perfil en particular. Entonces, estamos intentando calentar a JVM, nuestro punto de referencia con el parámetro 1, JVM genera un "código óptimo" donde la bifurcación en el ciclo while nunca se ha tomado. Aquí hay un evento del registro de compilación de JIT ( -XX:+UnlockDiagnosticVMOptions -XX:+LogCompilation ):

<branch prob="0.0408393" not_taken="40960" taken="1744" cnt="42704" target_bci="42"/>

Después del cambio de propiedad, JIT usa una trampa poco común para procesar su código que no es óptimo. Creé un punto de referencia basado en el original con cambios menores:

  • busyPause reemplazado por consumptionCPU desde JMH para tener benchmark java puro sin interacciones con el sistema (en realidad, nano time usa la función userland vdso clock_gettime y no podemos perfilar este código)
  • todos los cálculos son eliminados

_

import java.util.Arrays; public class JvmPauseLatency { private static final int WARMUP = 2000 ; private static final int EXTRA = 10; private static final long PAUSE = 70000L; // in nanos private static volatile long consumedCPU = System.nanoTime(); //org.openjdk.jmh.infra.Blackhole.consumeCPU() private static void consumeCPU(long tokens) { long t = consumedCPU; for (long i = tokens; i > 0; i--) { t += (t * 0x5DEECE66DL + 0xBL + i) & (0xFFFFFFFFFFFFL); } if (t == 42) { consumedCPU += t; } } public void run(long warmPause) { long[] results = new long[WARMUP + EXTRA]; int count = 0; long interval = warmPause; while(count < results.length) { consumeCPU(interval); long latency = System.nanoTime(); latency = System.nanoTime() - latency; results[count++] = latency; if (count == WARMUP) { interval = PAUSE; } } System.out.println("Results:" + Arrays.toString(Arrays.copyOfRange(results, results.length - EXTRA * 2, results.length))); } public static void main(String[] args) { int totalCount = 0; while (totalCount < 100) { new JvmPauseLatency().run(0); totalCount ++; } } }

Y los resultados son

Results:[62, 66, 63, 64, 62, 62, 60, 58, 65, 61, 127, 245, 140, 85, 88, 114, 76, 199, 310, 196] Results:[61, 63, 65, 64, 62, 65, 82, 63, 67, 70, 104, 176, 368, 297, 272, 183, 248, 217, 267, 181] Results:[62, 65, 60, 59, 54, 64, 63, 71, 48, 59, 202, 74, 400, 247, 215, 184, 380, 258, 266, 323]

Para arreglar este punto de referencia simplemente reemplace el new JvmPauseLatency().run(0) con el new JvmPauseLatency().run(PAUSE); y aquí están los resultados:

Results:[46, 45, 44, 45, 48, 46, 43, 72, 50, 47, 46, 44, 54, 45, 43, 43, 43, 48, 46, 43] Results:[44, 44, 45, 45, 43, 46, 46, 44, 44, 44, 43, 49, 45, 44, 43, 49, 45, 46, 45, 44]

Si desea cambiar "pausa" dinámicamente, debe calentar la JVM de forma dinámica, es decir,

while(count < results.length) { consumeCPU(interval); long latency = System.nanoTime(); latency = System.nanoTime() - latency; results[count++] = latency; if (count >= WARMUP) { interval = PAUSE; } else { interval = rnd.nextBoolean() ? PAUSE : 0; } }

Problema N4. ¿Qué hay del intérprete -Xint?

En el caso de un intérprete basado en conmutadores, tenemos muchos problemas y el principal son las instrucciones indirectas de derivación. He hecho 3 experimentos:

  1. calentamiento aleatorio
  2. Calentamiento constante con 0 pausa
  3. toda la prueba usa pausa 0 incluyendo

Cada experimento se inició con el siguiente comando sudo perf stat -e cycles,instructions,cache-references,cache-misses,bus-cycles,branch-misses java -Xint JvmPauseLatency y los resultados son:

Performance counter stats for ''java -Xint JvmPauseLatency'': 272,822,274,275 cycles 723,420,125,590 instructions # 2.65 insn per cycle 26,994,494 cache-references 8,575,746 cache-misses # 31.769 % of all cache refs 2,060,138,555 bus-cycles 2,930,155 branch-misses 86.808481183 seconds time elapsed Performance counter stats for ''java -Xint JvmPauseLatency'': 2,812,949,238 cycles 7,267,497,946 instructions # 2.58 insn per cycle 6,936,666 cache-references 1,107,318 cache-misses # 15.963 % of all cache refs 21,410,797 bus-cycles 791,441 branch-misses 0.907758181 seconds time elapsed Performance counter stats for ''java -Xint JvmPauseLatency'': 126,157,793 cycles 158,845,300 instructions # 1.26 insn per cycle 6,650,471 cache-references 909,593 cache-misses # 13.677 % of all cache refs 1,635,548 bus-cycles 775,564 branch-misses 0.073511817 seconds time elapsed

En caso de falta de latencia de rama, la huella crece de forma no lineal debido a la gran huella de memoria.

El siguiente código muestra el problema inequívocamente , que es:

El mismo bloque de código se vuelve más lento después de una pausa de giro ocupada.

Tenga en cuenta que, por supuesto, no estoy usando Thread.sleep . También tenga en cuenta que no hay condicionales que conduzcan a una desoptimización de HotSpot / JIT ya que estoy cambiando la pausa usando una operación matemática, no un IF .

  • Hay un bloque de operaciones matemáticas que quiero cronometrar.
  • Primero, hago que el bloque pause 1 nanosegundo antes de comenzar mi medición. Lo hago 20,000 veces.
  • Luego cambio la pausa de 1 nanosegundo a 5 segundos y procedo a medir la latencia como de costumbre. Lo hago 15 veces.
  • Luego imprimo las últimas 30 mediciones, para que pueda ver 15 mediciones con la pausa de 1 nanosegundo y 15 mediciones con la pausa de 5 segundos.

Como puede ver a continuación, la discrepancia es grande , especialmente en la primera medición después del cambio de pausa. ¿¡Porqué es eso!?

$ java -server -cp . JvmPauseLatency Sat Apr 29 10:34:28 EDT 2017 => Please wait 75 seconds for the results... Sat Apr 29 10:35:43 EDT 2017 => Calculation: 4.0042328611017236E11 Results: 215 214 215 214 215 214 217 215 216 214 216 213 215 214 215 2343 <----- FIRST MEASUREMENT AFTER PAUSE CHANGE 795 727 942 778 765 856 762 801 708 692 765 776 780 754

El código:

import java.util.Arrays; import java.util.Date; import java.util.Random; public class JvmPauseLatency { private static final int WARMUP = 20000; private static final int EXTRA = 15; private static final long PAUSE = 5 * 1000000000L; // in nanos private final Random rand = new Random(); private int count; private double calculation; private final long[] results = new long[WARMUP + EXTRA]; private long interval = 1; // in nanos private long busyPause(long pauseInNanos) { final long start = System.nanoTime(); long until = Long.MAX_VALUE; while(System.nanoTime() < until) { until = start + pauseInNanos; } return until; } public void run() { long testDuration = ((WARMUP * 1) + (EXTRA * PAUSE)) / 1000000000L; System.out.println(new Date() +" => Please wait " + testDuration + " seconds for the results..."); while(count < results.length) { double x = busyPause(interval); long latency = System.nanoTime(); calculation += x / (rand.nextInt(5) + 1); calculation -= calculation / (rand.nextInt(5) + 1); calculation -= x / (rand.nextInt(6) + 1); calculation += calculation / (rand.nextInt(6) + 1); latency = System.nanoTime() - latency; results[count++] = latency; interval = (count / WARMUP * (PAUSE - 1)) + 1; // it will change to PAUSE when it reaches WARMUP } // now print the last (EXTRA * 2) results so you can compare before and after the pause change (from 1 to PAUSE) System.out.println(new Date() + " => Calculation: " + calculation); System.out.println("Results:"); long[] array = Arrays.copyOfRange(results, results.length - EXTRA * 2, results.length); for(long t: array) System.out.println(t); } public static void main(String[] args) { new JvmPauseLatency().run(); } }

Probablemente no pueda confiar en la precisión de ningún temporizador para la precisión que parezca querer, https://docs.oracle.com/javase/8/docs/api/java/lang/System.html#nanoTime-- afirma que

Este método proporciona una precisión de nanosegundos, pero no necesariamente una resolución en nanosegundos (es decir, con qué frecuencia cambia el valor): no se hacen garantías, excepto que la resolución es al menos tan buena como la de CurrentTimeMillis ().