Явное непредсказуемое падение производительности Java 8 без очевидной причины

Ответ 1

Этот эффект вызван Типом загрязнения профиля. Позвольте мне объяснить упрощенную оценку:

@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();
    }
}

Хотя параметр iteration здесь изменяется очень немного, и он не влияет на основной цикл тестирования, результаты показывают очень удивительное снижение производительности на 2,5 раза:

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

Теперь запустите JMH с параметром -prof perfasm, чтобы увидеть самые горячие области кода:

Быстрый случай (итерации = 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

Медленный случай (итерации = 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

Похоже, что медленный случай тратит больше времени на ReduceOp.evaluateSequential метод, который не встроен. Кроме того, если мы изучим код сборки для этого метода, мы найдем, что самая длинная операция checkcast.

Вы знаете, как работает компилятор HotSpot: перед запуском JIT в интерпретаторе в течение некоторого времени выполняется сбор данных профиля , например. какие методы называются, какие классы видны, какие ветки заняты и т.д. С многоуровневой компиляцией профиль также собирается в C1-компилированном коде. Затем профиль используется для генерации C2-оптимизированного кода. Однако, если приложение меняет шаблон выполнения в середине, сгенерированный код может быть не оптимальным для измененного поведения.

Позвольте использовать -XX:+PrintMethodData (доступный в debug JVM) для сравнения профилей выполнения:

----- 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

Видите ли, цикл инициализации слишком длинен, чтобы его статистика появилась в профиле выполнения: все виртуальные методы имеют две реализации, а в контрольной таблице также есть две разные записи. В быстром случае профиль не загрязнен: все сайты мономорфны, и JIT может легко встраивать и оптимизировать их.

То же самое верно для вашего исходного теста: более длинные потоковые операции в методе init() загрязняют профиль. Если вы играете с профилированными и многоуровневыми параметрами компиляции, результаты могут быть совершенно разными. Например, попробуйте

• -XX:-ProfileInterpreter
• -XX:Tier3InvocationThreshold=1000
• -XX:-TieredCompilation

Наконец, эта проблема не уникальна. Есть уже несколько ошибок JVM, связанных с регрессией производительности из-за загрязнения профиля: JDK-8015416, JDK-8015417, JDK-8059879... Надеюсь, это улучшится в Java 9.