kagamihogeの日記

kagamihogeの日記です。

JEP 358: Helpful NullPointerExceptionsをテキトーに訳した

http://openjdk.java.net/jeps/358

JEP 358: Helpful NullPointerExceptions

Authors  Goetz Lindenmaier, Ralf Schmelter
Owner   Goetz Lindenmaier
Type    Feature
Scope   JDK
Status  Candidate
Component   hotspot / runtime
Discussion  hotspot dash runtime dash dev at openjdk dot java dot net, core dash libs dash dev at openjdk dot java dot net
Effort  S
Duration    S
Reviewed by Alex Buckley, Coleen Phillimore
Created 2019/03/15 10:27
Updated 2019/07/29 09:04
Issue   8220715

Summary

JVMが生成するNullPointerExceptionsユーザビリティを、null変数を正確に記述することで、改善します。

Goals

  • 開発者とサポートスタッフに対しプログラムの予期せぬ終了に関する有用な情報の提供。
  • コードと実行時例外の関連付けによりプログラムの理解しやすさ向上。
  • 新規開発者が陥りがちなNullPointerExceptionsに対する混乱と困惑の緩和。

Non-Goals

  • 不幸な発生元だけ追跡し、null参照を行った大元の追跡までは行わない。
  • 複数NullPointerExceptionsのスローや、ある時点の異なる箇所で複数NullPointerExceptionsをスローは目的外*1

Motivation

Java開発者はNullPointerExceptions (NPEs)を必ず目にします。NPEsはプログラム内のどこでも発生しうるため、これを捕捉してリカバリするのはあまり現実的ではありません。このため、開発者は例外発生時にNPEの発生箇所を探すのにJVM頼みになります。たとえば、NPEが以下のコードで発生するとして、

a.i = 99;

JVMは、メソッド・ファイル名・NPE発生行、を出力します。

Exception in thread "main" java.lang.NullPointerException
    at Prog.main(Prog.java:5)

大抵はバグレポートに含まれる上記メッセージを見て、開発者はa.i = 99;を探し、ここがnullであろうと推測します。しかし、より複雑なコード場合、デバッガ無しで変数がnullだと判断するのは困難です。NPEが以下のコードで発生するとして、

a.b.c.i = 99;

ファイル名と行番号が、変数がnullな場所を指すとは限りません。abcか、どれかは分かりません。

同様な問題は配列アクセスと代入でも発生します。NPEが以下のコードで発生するとして、

a[i][j][k] = 99;

ファイル名と行番号が、配列の要素がnullな場所を指すとは限りません。a[i]a[i][j]か、どれかは分かりません。

単一行が複数のアクセスパスを持ち、それぞれにNPEの可能性がある場合があります。NPEが以下のコードで発生するとして、

a.i = b.j;

ファイル名と行番号は、問題のあるアクセスパスを指しません。abか、どれかは分かりません。

最後の例として、メソッド呼び出しがNPEの場合があります。NPEが以下のコードで発生するとして、

x().y().i = 99;

ファイル名と行番号は、nullを返したメソッドを指しません。x()y()、どれかは分かりません。

JVMが正確な場所を指せない点は各種技術で軽減できます。たとえば、NPEが発生したアクセスパスを中間変数で分割します。(var便利です。)これによりJVMメッセージ内のnull変数が正確になりますが、そのためにコードを書き換えるのは望ましくないです。どちらにしても、NPEの大半は本番環境で発生し、NPEを追跡するサポートエンジニアはそのコードを書いた開発者と別なのが普通です。

仮に、JVMがNPE発生箇所情報を提供して発生元の特定を、別途ツールやコードを洗わなくとも可能になれば、Javaのエコシステム全体で有益と考えられます。SAP商用JVMは2006年以来これを提供しており、開発者とサポートエンジニアから高い評価を得ています。

Description

JVMはプログラム内でnull参照の間接参照を試みた時点でNullPointerException (NPE)をスローします。バイトコード命令を分析してJVMnull変数を検出し、NPEでnull詳細メッセージ(null-detail message)と(ソースコードの)変数を記述します。null詳細メッセージはJVMメッセージに表示され、メソッド・ファイル名・行番号も出します。

注:JVMは例外型と例外メッセージを同一行に出すため行が長くなることがあります。webブラウザでの表示を考慮して、本JEPでは例外型の後に改行を入れたnull詳細メッセージにしています。

たとえば、代入ステートメントa.i = 99;のNPEは以下のメッセージを生成します。

Exception in thread "main" java.lang.NullPointerException: 
        Cannot assign field 'i' because 'a' is null.
    at Prog.main(Prog.java:5)

より複雑なステートメントa.b.c.i = 99;がNPEをスローの場合、メッセージはステートメントを分割して大元を指します。このときnullとなった完全なアクセスパスを示します。

Exception in thread "main" java.lang.NullPointerException: 
        Cannot read field 'c' because 'a.b' is null.
    at Prog.main(Prog.java:5)

nullのフィールド名だけよりも完全なアクセスパスの方がユーザユレンドリで、開発者が複雑なコードを読む際の助けになります。特にコード行に複数同一名がある場合に役立ちます。

同様に配列アクセスと代入ステートメントa[i][j][k] = 99;がNPEをスローする場合、

Exception in thread "main" java.lang.NullPointerException:
        Cannot load from object array because 'a[i][j]' is null.
    at Prog.main(Prog.java:5)

またa.i = b.j;がNPEをスローする場合も同様に、

Exception in thread "main" java.lang.NullPointerException:
        Cannot read field 'j' because 'b' is null.
    at Prog.main(Prog.java:5)

いずれのサンプルにおいても、ソースコードnull式を指すのに行番号つきのnull詳細メッセージは有用です。理想的には、実際のソースコードを示したいですが、ソースコードバイトコード命令との関係を考慮すると難しいです(下記参照)。また、null詳細メッセージではnull要素となる配列インデックスを示すことは出来ません、たとえばa[i][j]nullとなる場合のijの実行時における値など。これは配列インデックスはメソッドのオペランドスタックにあり、NPEスロー時に失われるためです。

JVMが直接生成及びスローするNPEのみnull詳細メッセージになります。JVM上のプログラムが明示的に生成またはスローの両方をするNPEはバイトコード分析の対象ではなくnull詳細メッセージ生成は以下に記述します。また、null詳細メッセージはhidden methodsで起きたNPEについては対象外です。hidden methodsはJVMが生成して呼び出す特殊用途低レベルメソッド(special-purpose low-level methods)で、文字列結合の最適化のためなどに使われます。hidden methodsはNPEのソースを指すためのファイル名や行番号が無いため、null詳細メッセージには適しません。

Computing the null-detail message

a.b.c.i = 99;のようなソースコードコンパイルすると複数のバイトコード命令になります。NPEスロー時、JVMはどのメソッドに原因があるバイトコード命令なのかを正確に把握しており、null詳細メッセージの算出にはその情報を使用します。このメッセージは2つの部分から成ります。

  • 前半部分 -- Cannot read field 'c' -- NPEの結果(consequence)。バイトコード命令がオペランドスタックからnullをポップしたのでそのアクションを実行できなかった事を示す。
  • 後半部分 -- because 'a.b' is null -- NPEの原因(reason)。オペランドスタックにnull参照をプッシュしたソースコード箇所を再構築する。

null詳細メッセージの前半部分は、以下Table 1;に示すように、nullをポップしたバイトコード命令から生成します。

bytecode 1st part
aload "Cannot load from <element type> array"
arraylength "Cannot read the array length"
astore "Cannot store to <element type> array"
athrow "Cannot throw exception"
getfield "Cannot read field '<field name>'"
invokeinterface, invokespecial, invokevirtual "Cannot invoke '<method>'"
monitorenter "Cannot enter synchronized block"
monitorexit "Cannot exit synchronized block"
putfield "Cannot assign field '<field name>'"
Any other bytecode No NPE possible, no message

<method><class name>.<method name>(<parameter types>)にブレークダウンします。

null詳細メッセージの後半部分は前半に比べると複雑です。オペランドスタックでnull参照となったアクセスパスを特定しますが、複合的なアクセスパスは複数のバイトコード命令を持ちます。メソッドの命令シーケンスだけでは、それより前の命令がnull参照をプッシュしたかが明確ではありません。よって、シンプルなデータフロー解析をすべてのメソッド命令で実行します。この処理は命令をオペランドスタックスロットにプッシュし、スロットをポップする命令にその情報を伝播させます。(この分析は命令数に線形比例します。)分析後、ソースコードのアクセスパスを構成する命令をステップバック可能になります。メッセージの後半部分はステップバイステップで組み立て、ステップごとのバイトコード命令はTable 2の通りです。

bytecode2nd part
aconst_null"'null'"
aaloadcompute the 2nd part for the instruction which pushed the array reference, then append "[", then compute the 2nd part for the instruction that pushed the index, then append "]"
iconst_*, bipush, sipushthe constant value
getfieldcompute the 2nd part for the instruction which pushed the reference that is accessed by this getfield, then append ".<field name>"
getstatic"<class name>.<field name>"
invokeinterface, invokevirtual, invokespecial, invokestatic If in the first step, "the return value of '<method>'", else "'<method>'"
iload*, aload*For local variable 0, "this". For other local variables and parameters, the variable name if a local variable table is available, otherwise "<parameter i >" or "<local i >".
Any other bytecodeNot applicable to the second part.

アクセスパスは任意数のバイトコード命令で構成します。null詳細メッセージはそのすべてをカバーする必要はありません。出力を簡潔にするために命令のステップバック数を制限します。もしステップの最大値に達する場合、"..."などのプレースホルダーは省略します。レアケースでは、命令のステップバックが不可能なため、null詳細メッセージは前半部分のみになります("Cannot ..."は有るが"because ..."は無し)。

null詳細メッセージ -- Cannot read field 'c' because 'a.b' is null. -- は、JVMThrowable::getMessageを呼ぶときそのメッセージの一部として、オンデマンドに生成します。通例では、例外に入れるメッセージは例外オブジェクトの生成時)に作りますが、メッセージ生成処理は高価で常に必要とは限りません、たとえば大量のNPEをキャッチしてプログラムが無視するなど。生成処理で必要なのは、NPEを引き起こしたメソッドのバイトコード命令と、nullをポップした命令インデックスです。幸運にも、Throwable実装は例外元に関するそうした情報を持っています。

本機能は新規のbooleanコマンドラインオプション-XX:{+|-}ShowCodeDetailsInExceptionMessagesで制御します。オプションは当初はデフォルト'false'でメッセージは表示しません。デフォルトで詳細な例外メッセージを有効化するのは後々のリリースで行う予定です。

Example of computing the null-detail message

以下のコードを基に例を示します。

a().b[i][j] = 99;

このコードは以下のバイトコードになります。

5: invokestatic  #7    // Method a:()LA;
   8: getfield      #13   // Field A.b, an array
  11: iload_1             // Load local variable i, an array index
  12: aaload              // Load b[i], another array
  13: iload_2             // Load local variable j, another array index
  14: bipush        99
  16: iastore             // Store to b[i][j]

いまa().b[i]nullとします。これがb[i][j]への代入時のNPEの原因になります。JVM16: iastoreを実行するとNPEをスローします。この原因は12: aaloadオペランドスタックにnullをプッシュしたためです。null詳細メッセージの生成は以下になります。

Cannot store to int array because 'Test.a().b[i]' is null.

この生成処理は、バイトコードindex 16と、バイトコード命令を持つメソッドから開始します。index 16の命令はiastoreなので、メッセージの前半部分はTable 1を参照して"Cannot store to int array"になります。

メッセージの後半部分については、不幸にもnullをプッシュしたiastore命令にステップバックします。データフロー解析が配列にロードする12: aaloadが原因と判断します。Table 2を参照し、配列へのロードがnull参照の原因なので、オペランドスタックに配列参照をプッシュする命令8: getfieldにステップバックします。再度Table 2を参照し、getfieldがアクセスパスの一部なので、getfieldで参照をプッシュする命令5: invokestaticにステップバックします。以上によりメッセージの後半部分は以下のように組み上げます。

  • For 5: invokestatic, emit "Test.a()"
  • For 8: getfield, emit ".b"
  • For 12: aaload, emit '[" and stepback to the instruction that pushed the index, 11: iload_1. Emit "i", the name of local variable #1, then "]".

ここではindex jをプッシュする13: iload_2や99をプッシュする14: bipushは出てきませんが、これらはNPEの原因とは無関係なためです。

null詳細メッセージの他のサンプルについてはmessages when class files contain a local variable tablemessages when class files do not contain a local variable tableに多数あります。

Alternatives

The presence of the null-detail message

JVMでは、stdout書き込み・トレーシング・ロギング機能、など各種方法でnull詳細情報を出力可能です。しかし、例外はJVMで問題を報告する標準的な方法で、現状でもNPEは例外発生箇所プラス行番号とスタックトレースを出しています。この情報だけでは原因特定には不十分で、NPEに情報追加が自然な解決策です。

null詳細メッセージはデフォルトオフでコマンドラインオプション-XX:+ShowCodeDetailsInExceptionMessagesで有効化します。NPEを引き起こすバイトコードのうち特定のものだけを指定する方法はありません。以下理由により、あらゆる状況下でnull詳細メッセージが望ましいわけではありません。

  1. Performance. スタックトレース生成のオーバーヘッドが追加になります。しかし、例外発生時に実行するstack walkingと同程度です。アプリケーションが頻繁に例外をスローしてメッセージを表示するならパフォーマンスに影響を与えますが、それはすでに避けるべきオーバーヘッドが発生しています。
  2. Security. null詳細メッセージは他の手段では入手の難しいソースコード情報を取得します。これをさせないようにメッセージをオフに出来ますが、例外メッセージは問題解決のための原因に関する情報の出力を想定しています。情報の露出が許容出来ない場合、アプリケーションでメッセージを表示しないのが良いですが、この場合例外はキャッチすると破棄されます。これはJVMの設定で処理すべきではありません。
  3. Compatibility. これまでJVMはNPEにメッセージを含めていなかったので、メッセージ有りにすると、強引にスタックトレースをパースするツールで問題を起こす可能性があります。しかし、Javaプログラムはメッセージを含むNPEをスロー可能だったので、ツールはJVMのNPEのメッセージに適応出来ると思われます。関連リスクとしては、ツールがnull詳細メッセージのフォーマットに依存する可能性があります。

デフォルトでnull詳細メッセージを有効化するのは将来のリリースを考えています。

The computation of the null-detail message

オンデマンドのnull詳細メッセージ生成はより複雑な状況下ではメッセージの可用性に影響があります。

  1. RMI経由リモートコード実行時、リモートコードがスローする例外はシリアライズ処理を介して呼び出し元に届きます。例外オブジェクトのシリアライズは内部的なデータ構造を保存しないので、リモートコードがスローしてNPEをシリアライズする場合、最終的なデシリアライズ処理が生成するNPEではnull詳細メッセージをオンデマンドで生成できません。
  2. JVMTIを使用するJavaエージェントがメソッドを再定義するなどの場合、プログラム実行中にメソッドのバイトコード命令が変更されて、その間はオリジナルの命令が保持されますが、GCで破棄出来ます。オリジナルの命令がnull詳細メッセージの生成には必要なので、この場合にはオンデマンドでのnull詳細メッセージ生成は行われなくなります。

NullPointerExceptionクラスの修正を最小化するためにシリアライズをサポートしない事にしました。シリアライズにおけるnull詳細メッセージの永続化が望ましい場合、writeReplaceをそのクラスに実装します。もしくは、例外オブジェクト生成時にnull詳細メッセージを生成し、シリアライズとメソッド再定義の両方でそのnull詳細メッセージを永続化します。

The format of the null-detail message

null詳細メッセージは前半・後半に分けられます。前半部分は実行出来なかったアクション(NPEの結果(consequence))で、後半部分はそのアクション以前でオペランドスタックにnull参照をプッシュした式(NPEの原因(reason))です。しかし、ソースコードnull式を指すのにメッセージの一部だけが必要な場合は冗長なテキストとなる場合があります。例として、以下2ケースではメッセージを省略する方が有用かもしれません。

  1. 配列アクセス失敗時 -- Cannot load from object array because 'a[i][j]' isnull. -- 後半部分'a[i][j]' is nullだけでソースコード中のa[i][j][k] = 99;nullと特定できます。
  2. メソッド呼び出し失敗時 -- Cannot invoke 'NullPointerExceptionTest.callWithTypes(String[][], int[][][], float, long, short, boolean, byte, double, char)' because... -- メソッドの宣言型とパラメータが長々として見にくくなる場合があり、開発者がnull箇所を特定する妨げになるので省略可能です。

上記背景はありますが、null詳細メッセージはこうした省略をしません。任意数のバイトコート命令を処理するメッセージ生成なので、常に有用なメッセージを組み立てられるとは限りません。たとえば、配列アクセス失敗時、後半部分を完全には生成出来ない場合があり、これはもし前半部分を省略してメッセージが何も無くなると発生しますが、前半部分だけでソースコードnull参照の特定に十分なこともあります。基本的には、メッセージは一連の命令から組み立てるため、十分な情報を収集してある時点であるパーツを省略するかどうかの決定は、メッセージの有用性を損なうこと無しには、機械的に簡単には下せません。よって、なるべく多様な状況下でメッセージが役に立つようにすべての情報を出力する事にしました。

Risks and Assumptions

JVM仕様に新しいバイトコードが追加された場合null詳細メッセージ生成を拡張するという想定です。

null詳細メッセージにはソースコード由来の変数名を含む場合があります。こうした情報の露出はセキュリティリスクになりえます。とくにclassファイルにデバッグ情報を含む(javac -g)場合、ローカル変数名を出力します。これらはJavaのリフレクションAPI経由で他プログラムで以前は利用出来ませんでした(適切なパーミッションを持つプログラムはClassLoader::getResourceAsStream()を介してclassファイルを参照可能とはいえ)。しかし、ローカル変数名の省略はメッセージの利点を制限するとも言えます。

Testing

本機能のプロトタイプはJDK-8218628で実装しています。この プロトタイプにはメッセージの各部分のユニットテストがあります。SAPの商用JVMという先駆者の実装で2006年以来の実績があり、安定を証明しています。

レグレッション回避のためコードの大部分をテストする必要があります。jThe jtreg tests should be run to detect other tests that handle the message and need to be adapted.

*1:It is not a goal to throw more NullPointerExceptions, or to throw them at a different point in time. が原文。more..なのでこういう意味では無いかもしれない。

アトラス作品ファンのオフ会 新年号に開催する眼鏡祭(2019/07/20)に行ってきた

7/20(土) 新年号に開催する眼鏡祭に行ってきました。

f:id:kagamihoge:20190720143305j:plain

当日の天候は雨こそ降りませんでしたが、涼しい前日と比べていきなり夏らしい湿気のある1日になりました。今回も200人超の参加者となり、ペルソナをはじめとしたアトラス作品ファンの熱気で盛り上がりました。会場はキリストンカフェ東京をワンフロア貸し切っての開催です。当日の様子は#眼鏡祭0720 から追えます。

コスプレOKなアトラス作品ファンの大規模オフ会

眼鏡祭はオフ会です。主宰の言葉を借りれば「唯一のコンテンツは参加者同士のコミュニケーション」です。コスプレをして、お酒を飲んで、盛り上がる、一言で表せばそれだけのイベントです。アルコール提供があるため20歳以上の大人がアニメ・ゲーム・マンガの話題で一日中盛り上がるオタクの社交場が眼鏡祭です。年齢層は、眼鏡祭の由来がP4のキーアイテム「メガネ」のとおり、やや高めで30~35歳付近です。しかし、P5から眼鏡祭に来る方も大勢おり、見た目では年齢層はそこまでの偏りはありません。

眼鏡祭のオフ会としての特徴はコスプレOKな点です。以下は、コスプレ参加者の全体集合写真です。

眼鏡祭では「コスプレ」を「仮装」と呼んでおり*1、もし簡単なものでも用意出来るならコスプレすることを推奨しています。その理由は初対面同士のコミュニケーションにおいてコスプレはとても有用だからです。その作品やキャラに思い入れがあるからこそコスプレをするので、自分もそれが好きであれば話しかける切欠としてこれ以上のものはありません。話しかけるのが難しければそのコスプレを話題に隣の人と会話するもよし、写真を一緒に撮るだけでもよし。眼鏡祭ではコスプレはコミュニ―ションをやりやすくする仕組みの一つです。

ただし、コスプレが第一目的の方には不向きなイベントです。たとえば、会場はカフェ・レストランなので撮影スタジオやコスプレイベントほどの設備はありません。更衣室兼荷物置き場はフロアの一部を暗幕で仕切りをしただけで、限りあるスペースを譲り合いながらの着替えになり、化粧台も無く暗いのでメイクは苦労します。また、会場の照明は必ずしも十分ではないし、カメラマンに必ず撮影してもらえるとも限りません。

いつも2割は「はじめまして」

前述の通り眼鏡祭は10年以上続いているので常連の割合は高いですが、それでも毎回2割は初参加者です。感覚的には、仮に4~5人に話しかけると1人は「はじめまして」に会う、といったところです。ひとりで参加したとしても自分だけがひとり、という事にはなりません。また、初参加者向けに様々な配慮があります。たとえば、いきなり200人に飛び込ませるのではなく最初は7~8人のテーブルに分かれたり、不安だから知り合い同士同じテーブルになりたいのであれば調整してれます。

とはいえ、実際に初めて来ると……どうなの? という疑問はもっともです。そういうわけで以下はtwitterからの感想ピックアップです。

眼鏡祭を支える有志たち

眼鏡祭の運営は有志スタッフが行っています。会場や飲食を別にすればすべての作業は有志によるものです。200人が1日中動くイベントなので人・物・金・情報はかなりの量です。会場で目にするものだと、会場レイアウト変更の力作業・受付に金銭管理・更衣室の入退室管理・アナウンス・コープリーダーなど。準備作業には紙類や名札、ノベルティ作成もあり。そして裏側でのイベント企画に関する作業は、私はスタッフではないので詳細は分からないですが、かなりのボリュームでしょう。

私も常連のひとりですが、眼鏡祭はいつも少しずつ変化しています。目立つところではアナウンス役やコープリーダーにいつもの人が少なかった印象があります。また、各テーブルの進行や会場レイアウトも毎回試行錯誤の跡が見られます。これは非常に重要なことです。それは、変化の無いコミュニティは消えるからです。オタク同士の交流の場という大きな理念は変えず、しかし時代に合わせて細かい所は変えていく。だからこそ新しい人が絶え間なく訪れるし、数年ぶりに久しぶり、という人も来る。旧来の人も新規の人も一緒くたで混沌としているのに調和がある。そんな眼鏡祭に何かを返したい、という人は有志募集に応じるのも一つの手でしょう。

ここから始めるCOOP作り

200人もの参加者がいるため当日のみで知り合いを増やすのは簡単ではありません。もし可能であれば、眼鏡祭の参加者が開催したり参加しているイベントにも参加するのがオススメです。様々な場所に顔を出したり、より少人数での会で落ち着いたコミュニケーションを取ることで、自分なりのCOOPが作れるでしょう。

次回の眼鏡祭はいつ?

さいごに

今回の眼鏡祭も大変たのしい時間を過ごすことが出来ました。主宰のマソーさんはじめ有志スタッフの皆さん、当日自分の話し相手になってくれた方々、勝手ながらこのレポートでtweetを引用させて頂いた方々、にじさんじミトとカエデTシャツ着たために驚かせてしまった方々、今後ともよろしくお願いいたします。

リンク

*1:ただし、このレポートでは一般的な名称を優先して「コスプレ」と書いています

spring-batchのMapJobRepositoryFactoryBeanでメタテーブルをDBに保存せず大量にstepを実行するとスローダウン

現象

ほぼタイトルで言い切っているけど。spring-batchでメタデータ保存でDBを使わなないようインメモリに格納するMapJobRepositoryFactoryBeanを使う場合が稀に良くある。この状況下で大量のstepを含むjobを実行すると徐々に実行速度が低下していく、という現象に遭遇した。

再現

大量のstepを手軽に再現するため、以下のように無限ループでstepを実行し続ける。つまりJobExecutionDeciderが常に同一値を返し、同一のstepに遷移する。こんな感じ。

 <parent>
        <groupId>org.springframework.boot</groupId>
        <artifactId>spring-boot-starter-parent</artifactId>
        <version>2.1.1.RELEASE</version>
        <relativePath />
    </parent>

    <properties>
        <project.build.sourceEncoding>UTF-8</project.build.sourceEncoding>
        <project.reporting.outputEncoding>UTF-8</project.reporting.outputEncoding>
        <java.version>11</java.version>
    </properties>

    <dependencies>
        <dependency>
            <groupId>org.springframework.boot</groupId>
            <artifactId>spring-boot-starter-batch</artifactId>
        </dependency>
        <dependency>
            <groupId>org.springframework.boot</groupId>
            <artifactId>spring-boot-starter-jdbc</artifactId>
        </dependency>

        <dependency>
            <groupId>com.h2database</groupId>
            <artifactId>h2</artifactId>
        </dependency>

        <dependency>
            <groupId>org.springframework.boot</groupId>
            <artifactId>spring-boot-starter-test</artifactId>
            <scope>test</scope>
        </dependency>
    </dependencies>
package kagamihoge.springbatchslowdown;

import org.springframework.batch.core.Job;
import org.springframework.batch.core.JobExecution;
import org.springframework.batch.core.Step;
import org.springframework.batch.core.StepExecution;
import org.springframework.batch.core.configuration.BatchConfigurationException;
import org.springframework.batch.core.configuration.annotation.DefaultBatchConfigurer;
import org.springframework.batch.core.configuration.annotation.EnableBatchProcessing;
import org.springframework.batch.core.configuration.annotation.JobBuilderFactory;
import org.springframework.batch.core.configuration.annotation.StepBuilderFactory;
import org.springframework.batch.core.explore.JobExplorer;
import org.springframework.batch.core.explore.support.MapJobExplorerFactoryBean;
import org.springframework.batch.core.job.flow.FlowExecutionStatus;
import org.springframework.batch.core.job.flow.JobExecutionDecider;
import org.springframework.batch.core.launch.JobLauncher;
import org.springframework.batch.core.launch.support.RunIdIncrementer;
import org.springframework.batch.core.launch.support.SimpleJobLauncher;
import org.springframework.batch.core.repository.JobRepository;
import org.springframework.batch.core.repository.support.MapJobRepositoryFactoryBean;
import org.springframework.batch.repeat.RepeatStatus;
import org.springframework.beans.factory.annotation.Qualifier;
import org.springframework.context.annotation.Bean;
import org.springframework.context.annotation.Configuration;

@Configuration
@EnableBatchProcessing
public class BatchConfiguration {

    @Bean
    public Job job(JobBuilderFactory jobs, @Qualifier("s1") Step s1, JobExecutionDecider decider) {
        return jobs
                .get("myJob")
                .incrementer(new RunIdIncrementer())
                .start(s1)
                .next(decider)
                  .on("CONTINUE").to(s1)
                 .end()
                .build();
    }

    @Bean(name = "s1")
    public Step step1(StepBuilderFactory steps) {
        return steps.get("step1").tasklet((stepContribution, chunkContext) -> {
            return RepeatStatus.FINISHED;
        }).build();
    }

    @Bean
    public JobExecutionDecider decider() {
        return new JobExecutionDecider() {
            @Override
            public FlowExecutionStatus decide(JobExecution jobExecution, StepExecution stepExecution) {
                return new FlowExecutionStatus("CONTINUE");
            }
        };
    }

    @Bean
    DefaultBatchConfigurer batchConfigurer() {
        return new DefaultBatchConfigurer() {
            private final JobRepository jobRepository;
            private final JobExplorer jobExplorer;
            private final JobLauncher jobLauncher;

            {
                MapJobRepositoryFactoryBean jobRepositoryFactory = new MapJobRepositoryFactoryBean();
                try {
                    this.jobRepository = jobRepositoryFactory.getObject();
                    MapJobExplorerFactoryBean jobExplorerFactory = new MapJobExplorerFactoryBean(jobRepositoryFactory);
                    this.jobExplorer = jobExplorerFactory.getObject();
                    SimpleJobLauncher jobLauncher = new SimpleJobLauncher();
                    jobLauncher.setJobRepository(jobRepository);
                    jobLauncher.afterPropertiesSet();
                    this.jobLauncher = jobLauncher;
                } catch (Exception e) {
                    throw new BatchConfigurationException(e);
                }
            }

            @Override
            public JobRepository getJobRepository() {
                return jobRepository;
            }

            @Override
            public JobExplorer getJobExplorer() {
                return jobExplorer;
            }

            @Override
            public JobLauncher getJobLauncher() {
                return jobLauncher;
            }
        };
    }
}

実行時の様子

以下にjvisualvmのキャプチャを示す。

f:id:kagamihoge:20190706205250j:plain

上記はだいたい5分くらい実行したところだが、ヒープサイズがどんどん膨らんでいく。使用済みヒープも徐々に増えてはいるようだが、どうも急激に増えて減ってを繰り返している、ように見える。

f:id:kagamihoge:20190706205526j:plain

f:id:kagamihoge:20190706205539j:plain

サンプラを見るとbyte[]が多数を占め、CPUを見るとリフレクションが実行時間のうち大半を占めている。

怪しそうなのは、上位にあるStepExecutionObjectとかConcurrentHashMapとか、シリアライズ関連のObjectInputStreamとからへん。なので原因調べるときはその辺から調べていった。

原因

概要

MapJobRepositoryFactoryBeanはjob-executionの格納にMapJobExecutionDaoを使用する。これは内部的にはConcurrentHashMap<Long, JobExecution>()で保存し、また、job-executionに関連付くstep-executionのコレクションを保持している。次に、そのマップ保存時にオリジナルのJobExecutionをコピーするが、その実装がシリアライズandデシリアライズになっている。

詳細

MapJobExecutionDaoは以下のようなプロパティがあり、ここでjobExecution idJobExecutionのマップを持っている。また、JobExecutionはstep-executionを保持するstepExecutionsのコレクションがある。

public class MapJobExecutionDao implements JobExecutionDao {
    private final ConcurrentMap<Long, JobExecution> executionsById = new ConcurrentHashMap<Long, JobExecution>();
@SuppressWarnings("serial")
public class JobExecution extends Entity {
        ....
    private volatile Collection<StepExecution> stepExecutions = Collections.synchronizedSet(new LinkedHashSet<>());

step実行時は以下のMapStepExecutionDaoがstep-executionの追加処理を行う。以下のように、job-exectuion -> step-executionのコレクションに追加する。なのでstepを大量に実行すれば無限にstep-executionが追加されていく。

public class MapStepExecutionDao implements StepExecutionDao {
        ...
    @Override
    public void updateStepExecution(StepExecution stepExecution) {
Map<Long, StepExecution> executions = executionsByJobExecutionId.get(stepExecution.getJobExecutionId());
         ....
         executions.put(stepExecution.getId(), copy);

ヒープサイズが拡大する点についてはこれで一応説明がつく。

次に、スローダウンの原因について。

MapJobExecutionDaoに話は戻るが、マップ保存の際にJobExecutionインスタンスをコピーする。で、コピーは以下のようにシリアライズ -> デシリアライズで実装している。

   private static JobExecution copy(JobExecution original) {
        JobExecution copy = (JobExecution) SerializationUtils.deserialize(SerializationUtils.serialize(original));
        return copy;
    }

前述のようにstep-executionコレクションはどんどんデカくなっていくので、当然、そのマップをシリアライズ -> デシリアライズする処理もどんどん遅くなっていく。この挙動は徐々にスローダウンする事象と一致する。クッソでかいコレクションをシリアライズ -> デシリアライズするのでゴミもクッソでかくなる。使用済みヒープが急激に増えては減ってはを繰り返すのはこの辺にある、と推測される。

対策

インメモリDBにメタデータを保存させる。

f:id:kagamihoge:20190706220204j:plain

H2でやってみたがスローダウンはしなかった。もっと長時間起動し続けたらどうなるか分からんけど、そんなにもstep大量に実行するような状況とは最早別問題であろう。