Caída de rendimiento impredecible de Java 8 stream sin ninguna razón obvia
Estoy usando Java 8 streams para iterar sobre una lista con sublistas. El tamaño de la lista externa varía entre 100 y 1000 (diferentes ejecuciones de prueba) y el tamaño de la lista interna siempre es 5.
Hay 2 ejecuciones de referencia que muestran desviaciones de rendimiento inesperadas.
package benchmark;
import org.openjdk.jmh.annotations.*;
import org.openjdk.jmh.infra.Blackhole;
import java.io.IOException;
import java.util.concurrent.ThreadLocalRandom;
import java.util.*;
import java.util.function.*;
import java.util.stream.*;
@Threads(32)
@Warmup(iterations = 25)
@Measurement(iterations = 5)
@State(Scope.Benchmark)
@Fork(1)
@BenchmarkMode(Mode.Throughput)
public class StreamBenchmark {
@Param({"700", "600", "500", "400", "300", "200", "100"})
int outerListSizeParam;
final static int INNER_LIST_SIZE = 5;
List<List<Integer>> list;
Random rand() {
return ThreadLocalRandom.current();
}
final BinaryOperator<Integer> reducer = (val1, val2) -> val1 + val2;
final Supplier<List<Integer>> supplier = () -> IntStream
.range(0, INNER_LIST_SIZE)
.mapToObj(ptr -> rand().nextInt(100))
.collect(Collectors.toList());
@Setup
public void init() throws IOException {
list = IntStream
.range(0, outerListSizeParam)
.mapToObj(i -> supplier.get())
.collect(Collectors.toList());
}
@Benchmark
public void loop(Blackhole bh) throws Exception {
List<List<Integer>> res = new ArrayList<>();
for (List<Integer> innerList : list) {
if (innerList.stream().reduce(reducer).orElse(0) == rand().nextInt(2000)) {
res.add(innerList);
}
}
bh.consume(res);
}
@Benchmark
public void stream(Blackhole bh) throws Exception {
List<List<Integer>> res = list
.stream()
.filter(innerList -> innerList.stream().reduce(reducer).orElse(0) == rand().nextInt(2000))
.collect(Collectors.toList());
bh.consume(res);
}
}
Ejecutar 1
Benchmark (outerListSizeParam) Mode Cnt Score Error Units
StreamBenchmark.loop 700 thrpt 5 22488.601 ? 1128.543 ops/s
StreamBenchmark.loop 600 thrpt 5 26010.430 ? 1161.854 ops/s
StreamBenchmark.loop 500 thrpt 5 361837.395 ? 12777.016 ops/s
StreamBenchmark.loop 400 thrpt 5 451774.457 ? 22517.801 ops/s
StreamBenchmark.loop 300 thrpt 5 744677.723 ? 23456.913 ops/s
StreamBenchmark.loop 200 thrpt 5 1102075.707 ? 38678.994 ops/s
StreamBenchmark.loop 100 thrpt 5 2334981.090 ? 100973.551 ops/s
StreamBenchmark.stream 700 thrpt 5 22320.346 ? 496.432 ops/s
StreamBenchmark.stream 600 thrpt 5 26091.609 ? 1044.868 ops/s
StreamBenchmark.stream 500 thrpt 5 31961.096 ? 497.854 ops/s
StreamBenchmark.stream 400 thrpt 5 377701.859 ? 11115.990 ops/s
StreamBenchmark.stream 300 thrpt 5 53887.652 ? 1228.245 ops/s
StreamBenchmark.stream 200 thrpt 5 78754.294 ? 2173.316 ops/s
StreamBenchmark.stream 100 thrpt 5 1564899.788 ? 47369.698 ops/s
Ejecutar 2
Benchmark (outerListSizeParam) Mode Cnt Score Error Units
StreamBenchmark.loop 1000 thrpt 10 16179.702 ? 260.134 ops/s
StreamBenchmark.loop 700 thrpt 10 22924.319 ? 329.134 ops/s
StreamBenchmark.loop 600 thrpt 10 26871.267 ? 416.464 ops/s
StreamBenchmark.loop 500 thrpt 10 353043.221 ? 6628.980 ops/s
StreamBenchmark.loop 300 thrpt 10 772234.261 ? 10075.536 ops/s
StreamBenchmark.loop 100 thrpt 10 2357125.442 ? 30824.834 ops/s
StreamBenchmark.stream 1000 thrpt 10 15526.423 ? 147.454 ops/s
StreamBenchmark.stream 700 thrpt 10 22347.898 ? 117.360 ops/s
StreamBenchmark.stream 600 thrpt 10 26172.790 ? 229.745 ops/s
StreamBenchmark.stream 500 thrpt 10 31643.518 ? 428.680 ops/s
StreamBenchmark.stream 300 thrpt 10 536037.041 ? 6176.192 ops/s
StreamBenchmark.stream 100 thrpt 10 153619.054 ? 1450.839 ops/s
Tengo dos preguntas:
- ¿Por qué hay una diferencia de rendimiento consistente y significativa entre loop+500 y loop+600 para ambos? ¿pruebas?
- ¿Por qué en Run1 stream+400 y Run2 stream+300 hay una desviación de rendimiento significativa pero inconsistente?
Parece que el JIT a veces toma decisiones de optimización subóptimas, causando una gran caída en el rendimiento.
La máquina de prueba tiene 128 GB de RAM y 32 núcleos de CPU:
java version "1.8.0_45"
Java(TM) SE Runtime Environment (build 1.8.0_45-b14)
Java HotSpot(TM) 64-Bit Server VM (build 25.45-b02, mixed mode)
Architecture: x86_64
CPU op-mode(s): 32-bit, 64-bit
Byte Order: Little Endian
CPU(s): 32
On-line CPU(s) list: 0-31
Thread(s) per core: 2
Core(s) per socket: 8
Socket(s): 2
NUMA node(s): 2
Vendor ID: GenuineIntel
CPU family: 6
Model: 62
Model name: Intel(R) Xeon(R) CPU E5-2650 v2 @ 2.60GHz
Stepping: 4
CPU MHz: 1201.078
CPU max MHz: 3400.0000
CPU min MHz: 1200.0000
BogoMIPS: 5201.67
Virtualization: VT-x
L1d cache: 32K
L1i cache: 32K
L2 cache: 256K
L3 cache: 20480K
NUMA node0 CPU(s): 0-7,16-23
NUMA node1 CPU(s): 8-15,24-31
P.d. Se agregó benchmark sin flujo. Estas pruebas (loop + stream + pureLoop) me hacen pensar que el uso de streams y lambdas requeriría mucha micro optimización esfuerzos y no garantiza un rendimiento consistente de todos modos.
@Benchmark
public void pureLoop(Blackhole bh) throws Exception {
List<List<Integer>> res = new ArrayList<>();
for (List<Integer> innerList : list) {
int sum = 0;
for (Integer i : innerList) {
sum += i;
}
if (sum == rand().nextInt(2000))
res.add(innerList);
}
bh.consume(res);
}
Ejecutar 3 (bucles puros)
Benchmark (outerListSizeParam) Mode Cnt Score Error Units
StreamBenchmark.loop 1000 thrpt 5 15848.277 ? 445.624 ops/s
StreamBenchmark.loop 700 thrpt 5 22330.289 ? 484.554 ops/s
StreamBenchmark.loop 600 thrpt 5 26353.565 ? 631.421 ops/s
StreamBenchmark.loop 500 thrpt 5 358144.956 ? 8273.981 ops/s
StreamBenchmark.loop 400 thrpt 5 591471.382 ? 17725.212 ops/s
StreamBenchmark.loop 300 thrpt 5 785458.022 ? 23775.650 ops/s
StreamBenchmark.loop 200 thrpt 5 1192328.880 ? 40006.056 ops/s
StreamBenchmark.loop 100 thrpt 5 2330555.766 ? 73143.081 ops/s
StreamBenchmark.pureLoop 1000 thrpt 5 1024629.128 ? 4387.106 ops/s
StreamBenchmark.pureLoop 700 thrpt 5 1495365.029 ? 31659.941 ops/s
StreamBenchmark.pureLoop 600 thrpt 5 1787432.825 ? 16611.868 ops/s
StreamBenchmark.pureLoop 500 thrpt 5 2087093.023 ? 20143.165 ops/s
StreamBenchmark.pureLoop 400 thrpt 5 2662946.999 ? 33326.079 ops/s
StreamBenchmark.pureLoop 300 thrpt 5 3657830.227 ? 55020.775 ops/s
StreamBenchmark.pureLoop 200 thrpt 5 5365706.786 ? 64404.783 ops/s
StreamBenchmark.pureLoop 100 thrpt 5 10477430.730 ? 187641.413 ops/s
StreamBenchmark.stream 1000 thrpt 5 15576.304 ? 250.620 ops/s
StreamBenchmark.stream 700 thrpt 5 22286.965 ? 1153.734 ops/s
StreamBenchmark.stream 600 thrpt 5 26109.258 ? 296.382 ops/s
StreamBenchmark.stream 500 thrpt 5 31343.986 ? 1270.210 ops/s
StreamBenchmark.stream 400 thrpt 5 39696.775 ? 1812.355 ops/s
StreamBenchmark.stream 300 thrpt 5 536932.353 ? 41249.909 ops/s
StreamBenchmark.stream 200 thrpt 5 77797.301 ? 976.641 ops/s
StreamBenchmark.stream 100 thrpt 5 155387.348 ? 3182.841 ops/s
Solución : según lo recomendado por apangin deshabilitar la compilación por niveles hizo que los resultados de JIT fueran estables.
java -XX:-TieredCompilation -jar test-jmh.jar
Benchmark (outerListSizeParam) Mode Cnt Score Error Units
StreamBenchmark.loop 1000 thrpt 5 160410.288 ? 4426.320 ops/s
StreamBenchmark.loop 700 thrpt 5 230524.018 ? 4426.740 ops/s
StreamBenchmark.loop 600 thrpt 5 266266.663 ? 9078.827 ops/s
StreamBenchmark.loop 500 thrpt 5 324182.307 ? 8452.368 ops/s
StreamBenchmark.loop 400 thrpt 5 400793.677 ? 12526.475 ops/s
StreamBenchmark.loop 300 thrpt 5 534618.231 ? 25616.352 ops/s
StreamBenchmark.loop 200 thrpt 5 803314.614 ? 33108.005 ops/s
StreamBenchmark.loop 100 thrpt 5 1827400.764 ? 13868.253 ops/s
StreamBenchmark.pureLoop 1000 thrpt 5 1126873.129 ? 33307.600 ops/s
StreamBenchmark.pureLoop 700 thrpt 5 1560200.150 ? 150146.319 ops/s
StreamBenchmark.pureLoop 600 thrpt 5 1848113.823 ? 16195.103 ops/s
StreamBenchmark.pureLoop 500 thrpt 5 2250201.116 ? 130995.240 ops/s
StreamBenchmark.pureLoop 400 thrpt 5 2839212.063 ? 142008.523 ops/s
StreamBenchmark.pureLoop 300 thrpt 5 3807436.825 ? 140612.798 ops/s
StreamBenchmark.pureLoop 200 thrpt 5 5724311.256 ? 77031.417 ops/s
StreamBenchmark.pureLoop 100 thrpt 5 11718427.224 ? 101424.952 ops/s
StreamBenchmark.stream 1000 thrpt 5 16186.121 ? 249.806 ops/s
StreamBenchmark.stream 700 thrpt 5 22071.884 ? 703.729 ops/s
StreamBenchmark.stream 600 thrpt 5 25546.378 ? 472.804 ops/s
StreamBenchmark.stream 500 thrpt 5 32271.659 ? 437.048 ops/s
StreamBenchmark.stream 400 thrpt 5 39755.841 ? 506.207 ops/s
StreamBenchmark.stream 300 thrpt 5 52309.706 ? 1271.206 ops/s
StreamBenchmark.stream 200 thrpt 5 79277.532 ? 2040.740 ops/s
StreamBenchmark.stream 100 thrpt 5 161244.347 ? 3882.619 ops/s
1 answers
Este efecto es causado por Tipo de contaminación del Perfil. Permítanme explicar en un punto de referencia simplificado:
@State(Scope.Benchmark)
public class Streams {
@Param({"500", "520"})
int iterations;
@Setup
public void init() {
for (int i = 0; i < iterations; i++) {
Stream.empty().reduce((x, y) -> x);
}
}
@Benchmark
public long loop() {
return Stream.empty().count();
}
}
Aunque el parámetro iteration aquí cambia muy ligeramente y no afecta al bucle principal de referencia, los resultados exponen una degradación del rendimiento 2.5 x muy sorprendente:
Benchmark (iterations) Mode Cnt Score Error Units
Streams.loop 500 thrpt 5 29491,039 ± 240,953 ops/ms
Streams.loop 520 thrpt 5 11867,860 ± 344,779 ops/ms
Ahora vamos a ejecutar JMH con la opción -prof perfasm para ver las regiones de código más calientes:
Caso rápido (iteraciones = 500):
....[Hottest Methods (after inlining)]..................................
48,66% bench.generated.Streams_loop::loop_thrpt_jmhStub
23,14% <unknown>
2,99% java.util.stream.Sink$ChainedReference::<init>
1,98% org.openjdk.jmh.infra.Blackhole::consume
1,68% java.util.Objects::requireNonNull
0,65% java.util.stream.AbstractPipeline::evaluate
Caso lento (iteraciones = 520):
....[Hottest Methods (after inlining)]..................................
40,09% java.util.stream.ReduceOps$ReduceOp::evaluateSequential
22,02% <unknown>
17,61% bench.generated.Streams_loop::loop_thrpt_jmhStub
1,25% org.openjdk.jmh.infra.Blackhole::consume
0,74% java.util.stream.AbstractPipeline::evaluate
Parece que el caso lento pasa la mayor parte del tiempo en el método ReduceOp.evaluateSequential que no está inlineado. Además, si estudiamos el código de ensamblado para este método encontraremos que la operación más larga es checkcast.
Usted sabe cómo funciona el compilador de HotSpot: antes de que comience el JIT, se ejecuta un método en el intérprete durante algún tiempo para recopilar los datos de perfil , por ejemplo, qué métodos se llaman, qué clases se ven, qué ramas se toman, etc. Con compilación escalonada el perfil también se recoge en código compilado C1. El perfil se utiliza para generar código C2-optimizied. Sin embargo, si la aplicación cambia el patrón de ejecución en el medio, el código generado puede no ser óptimo para el comportamiento modificado.
Usemos -XX:+PrintMethodData (disponible en debug JVM) para comparar los perfiles de ejecución:
----- Fast case -----
java.util.stream.ReduceOps$ReduceOp::evaluateSequential(Ljava/util/stream/PipelineHelper;Ljava/util/Spliterator;)Ljava/lang/Object;
interpreter_invocation_count: 13382
invocation_counter: 13382
backedge_counter: 0
mdo size: 552 bytes
0 aload_1
1 fast_aload_0
2 invokevirtual 3 <java/util/stream/ReduceOps$ReduceOp.makeSink()Ljava/util/stream/ReduceOps$AccumulatingSink;>
0 bci: 2 VirtualCallData count(0) entries(1)
'java/util/stream/ReduceOps$8'(12870 1.00)
5 aload_2
6 invokevirtual 4 <java/util/stream/PipelineHelper.wrapAndCopyInto(Ljava/util/stream/Sink;Ljava/util/Spliterator;)Ljava/util/stream/Sink;>
48 bci: 6 VirtualCallData count(0) entries(1)
'java/util/stream/ReferencePipeline$5'(12870 1.00)
9 checkcast 5 <java/util/stream/ReduceOps$AccumulatingSink>
96 bci: 9 ReceiverTypeData count(0) entries(1)
'java/util/stream/ReduceOps$8ReducingSink'(12870 1.00)
12 invokeinterface 6 <java/util/stream/ReduceOps$AccumulatingSink.get()Ljava/lang/Object;>
144 bci: 12 VirtualCallData count(0) entries(1)
'java/util/stream/ReduceOps$8ReducingSink'(12870 1.00)
17 areturn
----- Slow case -----
java.util.stream.ReduceOps$ReduceOp::evaluateSequential(Ljava/util/stream/PipelineHelper;Ljava/util/Spliterator;)Ljava/lang/Object;
interpreter_invocation_count: 54751
invocation_counter: 54751
backedge_counter: 0
mdo size: 552 bytes
0 aload_1
1 fast_aload_0
2 invokevirtual 3 <java/util/stream/ReduceOps$ReduceOp.makeSink()Ljava/util/stream/ReduceOps$AccumulatingSink;>
0 bci: 2 VirtualCallData count(0) entries(2)
'java/util/stream/ReduceOps$2'(16 0.00)
'java/util/stream/ReduceOps$8'(54223 1.00)
5 aload_2
6 invokevirtual 4 <java/util/stream/PipelineHelper.wrapAndCopyInto(Ljava/util/stream/Sink;Ljava/util/Spliterator;)Ljava/util/stream/Sink;>
48 bci: 6 VirtualCallData count(0) entries(2)
'java/util/stream/ReferencePipeline$Head'(16 0.00)
'java/util/stream/ReferencePipeline$5'(54223 1.00)
9 checkcast 5 <java/util/stream/ReduceOps$AccumulatingSink>
96 bci: 9 ReceiverTypeData count(0) entries(2)
'java/util/stream/ReduceOps$2ReducingSink'(16 0.00)
'java/util/stream/ReduceOps$8ReducingSink'(54228 1.00)
12 invokeinterface 6 <java/util/stream/ReduceOps$AccumulatingSink.get()Ljava/lang/Object;>
144 bci: 12 VirtualCallData count(0) entries(2)
'java/util/stream/ReduceOps$2ReducingSink'(16 0.00)
'java/util/stream/ReduceOps$8ReducingSink'(54228 1.00)
17 areturn
Verá, el bucle de inicialización se ejecutó demasiado largo que sus estadísticas aparecieron en el perfil de ejecución: todos los métodos virtuales tienen dos implementaciones y checkcast también tiene dos entradas diferentes. En el caso rápido, el perfil no está contaminado: todos los sitios son monomorfos, y JIT puede insertarlos y optimizarlos fácilmente.
Lo mismo es cierto para su punto de referencia original: las operaciones de flujo más largas en el método init() contaminaron el perfil. Si juegas con el perfil y las opciones de compilación por niveles, los resultados pueden ser bastante diferentes. Por ejemplo, intente
-XX:-ProfileInterpreter-XX:Tier3InvocationThreshold=1000-XX:-TieredCompilation
Finalmente, este problema no es exclusivo. Ya hay varios errores JVM relacionados con regresiones de rendimiento debido a la contaminación del perfil: JDK-8015416, JDK-8015417, JDK-8059879 ... Espero que esto se mejore en Java 9.
Warning: date(): Invalid date.timezone value 'Europe/Kyiv', we selected the timezone 'UTC' for now. in /var/www/agent_stack/data/www/ajaxhispano.com/template/agent.layouts/content.php on line 61
2015-06-09 06:49:27