Java 8 ストリームで予期せぬパフォーマンス低下が発生する (明確な理由なし) 質問する

Question

この効果は、タイププロファイル汚染単純化したベンチマークで説明しましょう:

@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

-prof perfasm次に、最もホットなコード領域を確認するオプションを指定して JMH を実行してみましょう。

高速ケース（反復回数 = 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（デバッグ 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

初期化ループの実行時間が長すぎるため、実行プロファイルにその統計情報が表示されています。すべての仮想メソッドには 2 つの実装があり、チェックキャストにも 2 つの異なるエントリがあります。高速なケースでは、プロファイルは汚染されていません。すべてのサイトはモノモーフィックであり、JIT は簡単にインライン化して最適化できます。

元のベンチマークでも同じことが言えます。init()メソッド内の長いストリーム操作がプロファイルを汚染しました。プロファイルと階層型コンパイルオプションを変更すると、結果はまったく異なる可能性があります。たとえば、次のようにします。

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

最後に、この問題は特異なものではありません。プロファイル汚染によるパフォーマンスの低下に関連する JVM のバグはすでに複数存在します。JDK-8015416、JDK-8015417、JDK-8059879... Java 9 でこれが改善されることを期待します。

Answer 1