procesamiento - Caída de rendimiento impredecible de Java 8 stream sin una razón obvia

procesamiento de datos con streams de java se 8-parte 2

Question

Estoy usando flujos Java 8 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:

1. ¿Por qué hay una diferencia de rendimiento consistente y significativa entre loop + 500 y loop + 600 para ambas pruebas?
2. ¿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 poco óptimas, lo que provoca una gran caída del 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

PS Punto de referencia agregado sin transmisión. Estas pruebas (loop + stream + pureLoop) me hacen pensar que el uso de streams y lambdas requeriría muchos esfuerzos de micro optimización y de todos modos no garantiza un rendimiento consistente.

@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, la desactivación de la compilación escalonada 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

Answer 1

Este efecto es causado por la contaminación del perfil de tipo . Permítanme explicar sobre 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 de iteration aquí cambia muy levemente y no afecta al bucle de referencia principal, los resultados muestran una degradación de rendimiento 2.5x 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 -prof perfasm JMH con la opción -prof perfasm para ver las regiones de código más populares:

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á en línea. Además, si estudiamos el código ensamblador para este método, veremos que la operación más larga es el checkcast .

Ya sabe cómo funciona el compilador HotSpot: antes de que comience el JIT, se ejecuta un método en el intérprete durante un tiempo para recopilar los datos del perfil , por ejemplo, qué métodos se llaman, qué clases se ven, qué ramas se toman, etc. Con la compilación por niveles, el perfil es también recopilado en código compilado C1. El perfil se usa para generar código optimizado para C2. 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.

-XX:+PrintMethodData (disponible en depuración 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 tiempo como para que sus estadísticas aparecieran 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 monomórficos y JIT puede alinearlos 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 las opciones de compilación de perfil y por niveles, los resultados pueden ser bastante diferentes. Por ejemplo, prueba

1. -XX:-ProfileInterpreter
2. -XX:Tier3InvocationThreshold=1000
3. -XX:-TieredCompilation

Finalmente, este problema no es único. Ya hay varios errores de JVM relacionados con regresiones de rendimiento debido a la contaminación del perfil: JDK-8015416 , JDK-8015417 , JDK-8059879 ... Espero que esto mejore en Java 9.