はじめに
Java11をみなさん使ってますか？ このバージョンの一番気に入ってるところはJFR APIがオープン化/標準化されたことです。
なので「JFR APIで作るマイクロベンチマーク」の記事のようにカスタムイベントを作ることも簡単にできます。
さて、みなさんはこんなことを考えたことはありませんか？
「JFR便利なんだけど見たい情報と違う」「バイナリファイルだからKibanaとか既存のツールに連携できない」「etc」
私は思ってました！ もし自分でJMCを使わずにJFRの内容が確認できれば便利なのに、と。
と言うわけで実際にやってみましょう。
JFRで取得できるメソッドのサンプリングを元にメソッドの実行状態を良くあるAPMみたいなHTMLにしてみたいと思います。
なお、今回使ったソースコードは下記にあります。
https://github.com/koduki/jfr-viewer
JFRを読み込んでみる
まずは既存で作成したJFRを読み込んでみます。ここではtest.jfrと言うのが既存で用意したJFRです。
注意点としてはJFR APIで読み込むためにはJava 9以降で記録したJFRである必要があるようです。
APIが変わってるから仕方がないとはいえ、ちょっと面倒なのは事実です。早く本番環境をJava11にしないと！
話を戻して、読み込むのにはRecordingFile#readAllEventsを使います。
他の方法もありますが、このメソッドは戻り値がListなのでStream APIで取り扱うのが楽なのでオススメです。
RecordingFile.readAllEvents(path).stream()
続いてイベント名等でフィルタをしていきます。今回は.ExecutionSampleがそれに当たります。
どのような名前なのかはJMCのEventBrowserを使うと簡単に調べることができます。
Path path = Paths.get("test.jfr");
RecordingFile.readAllEvents(path).stream()
.filter((e) -> e.getEventType().getName().endsWith(".ExecutionSample"))
メソッドをスタックトレースから集計する
下記ではExecutionSampleのイベントからスタックトレースを取得し、それを以下のようなデータ構造に変換しています。
+ メソッド名1
- 取得時間1
- 取得時間2
+ メソッド名2
- 取得時間1
- 取得時間2
- ...
本当はちゃんとメソッドのコール順をグラフにするべきなのですが、今回はサボってスタックトレースの順番を保持して、だいたい親メソッドは上にあると言うそれっぽい感じを作っています。
なので、同じメソッドが違う階層で呼ばれるとおかしくなると言うバグがあるように見えるかもしれませんが仕様です。仕様ったら仕様です！
addMthodsを弄れば取得したいメソッドの種類も変更できます。
今回はJFR APIを弾く方向にしていますが、例えばパッケージ名でチェックして自作のコードだけを検証対象にするとかも可能でしょう。
static Tuple2<LinkedHashMap<String, Set<Instant>>, List<Instant>> readMethod(Path path) throws IOException {
var times = new ArrayList<Instant>();
var methods = new LinkedHashMap<String, Set<Instant>>();
RecordingFile.readAllEvents(path).stream()
.filter((e) -> e.getEventType().getName().endsWith(".ExecutionSample"))
.forEach((event) -> {
RecordedStackTrace stacktrace = event.getStackTrace();
if (stacktrace != null) {
times.add(event.getStartTime());
addMthods(methods, stacktrace, event);
}
});
return $(methods, times);
}
static void addMthods(LinkedHashMap<String, Set<Instant>> methods, RecordedStackTrace stacktrace, RecordedEvent event) {
stacktrace.getFrames().stream()
.filter(x -> x.isJavaFrame())
.filter(x -> !x.getMethod().getType().getName().startsWith("jdk.jfr."))
.collect(Collectors.toCollection(ArrayDeque::new))
.descendingIterator()
.forEachRemaining(x -> {
RecordedMethod method = x.getMethod();
String key = method.getType().getName() + "#" + method.getName();
Set<Instant> span = methods.getOrDefault(key, new HashSet<>());
span.add(event.getStartTime());
methods.put(key, span);
});
}
タイムラインに変換する
さてJFRの解析はできたのでこれをHTMLにしてやればOKですね。
この辺りがからもうJFRは全然関係なくなってきて、このままCSVとかにしていい感じのツールに流すのが最適解だと思いますが、今回は環境作るのもめんどいし試しに書いてみました。
まずはデータ構造を以下のように変換します。
- [メソッド名1, [開始時間, 終了時間]]
- [メソッド名2, [開始時間, 終了時間]]
- [メソッド名3, [開始時間, 終了時間]]
- [メソッド名4, [開始時間, 終了時間]]
なのですが、標準のプロファイルではメソッドサンプルにはメソッドの終了時間は記載されていません。
あくまでスタックトレースの取得時間があるのみです。なので「連続する取得時間に存在するメソッドは実行継続中である」と仮定します。
必ずしもこの定義は正しくないのですが、バッチの遅延分析とかであれば結構使える指標なのではないかと。
以下のようなメソッドで変換します。
static List<Tuple2<String, List<Tuple2<Instant, Instant>>>> parseSpan(LinkedHashMap<String, Set<Instant>> methods, List<Instant> times) {
var span = new ArrayList<Tuple2<String, List<Tuple2<Instant, Instant>>>>();
for (Entry<String, Set<Instant>> m : methods.entrySet()) {
var key = m.getKey();
var value = m.getValue();
var xs = new ArrayList<Tuple2<Instant, Instant>>();
Instant start = null;
Instant last = null;
for (Instant t : times) {
if (value.contains(t)) {
if (start == null) {
start = t;
}
last = t;
} else {
if (last != null) {
xs.add($(start, last));
}
start = null;
last = null;
}
}
span.add($(key, xs));
}
return span;
}
HTMLにレポートする
では先ほどのパースした値をHTMLでタイムラインに表示してみます。
タイムライン化するためにvis.jsを使ってみました。
static void report(List<Tuple2<String, List<Tuple2<Instant, Instant>>>> spans, Path path) throws IOException {
var names = spans.stream().map(xs -> xs._1()).distinct().collect(Collectors.toList());
var htmlNames = names.stream().map(x -> String.format("\"%s\"", x)).collect(Collectors.toList());
var htmlItems = new ArrayList<String>();
int index = 0;
for (int i = 0; i < spans.size(); i++) {
var s = spans.get(i);
String msg = "{ id: %d, group: %d, content: \"\", start: \"%s\", end: \"%s\" }";
for (int j = 0; j < s._2().size(); j++) {
var x = s._2().get(j);
htmlItems.add(String.format(msg, index++, names.indexOf(s._1()), x._1(), x._2()));
}
}
var html = "<!DOCTYPE html>\n"
+ "<html>\n"
+ " <head>\n"
+ " <title>Timeline</title>\n"
+ "\n"
+ " <style type=\"text/css\">\n"
+ " body,\n"
+ " html {\n"
+ " font-family: sans-serif;\n"
+ " }\n"
+ " </style>\n"
+ "\n"
+ " <script src=\"http://visjs.org/dist/vis.js\"></script>\n"
+ " <link\n"
+ " href=\"http://visjs.org/dist/vis-timeline-graph2d.min.css\"\n"
+ " rel=\"stylesheet\"\n"
+ " type=\"text/css\"\n"
+ " />\n"
+ " </head>\n"
+ " <body>\n"
+ " <p>\n"
+ " A Simple Timeline\n"
+ " </p>\n"
+ "\n"
+ " <div id=\"visualization\"></div>\n"
+ "\n"
+ " <script type=\"text/javascript\">\n"
+ " // DOM element where the Timeline will be attached\n"
+ " var container = document.getElementById(\"visualization\");\n"
+ "\n"
+ " // create a data set with groups\n"
+ " var names = [" + String.join(",", htmlNames) + "];\n"
+ " var groups = new vis.DataSet();\n"
+ " for (var g = 0; g < names.length; g++) {\n"
+ " groups.add({ id: g, content: names[g] });\n"
+ " }\n"
+ "\n"
+ " \n"
+ " // Create a DataSet (allows two way data-binding)\n"
+ " var items = new vis.DataSet([" + String.join(",", htmlItems) + "]);\n"
+ "\n"
+ " // Configuration for the Timeline\n"
+ " function customOrder(a, b) {\n"
+ " // order by id\n"
+ " return a.id - b.id;\n"
+ " }\n"
+ "\n"
+ " // Configuration for the Timeline\n"
+ " var options = {\n"
+ " order: customOrder,\n"
+ " editable: true,\n"
+ " margin: { item: 0 }\n"
+ " };\n"
+ "\n"
+ " // Create a Timeline\n"
+ " var timeline = new vis.Timeline(container);\n"
+ " timeline.setOptions(options);\n"
+ " timeline.setGroups(groups);\n"
+ " timeline.setItems(items);\n"
+ " </script>\n"
+ " </body>\n"
+ "</html>";
Files.writeString(path, html);
}
最後に以下のようにメインから実行して完了です。
public static void main(String[] args) throws IOException {
var methods = readMethod(Paths.get("test.jfr"));
report(parseSpan(methods._1(), methods._2()), Paths.get("target/test.html"));
}
生成されたHTMLはこちら。割とそれっぽい感じにはなりましたね！
まとめ
JFR APIを使ってタイムラインレポートを作成してみました。もっとUIを工夫してドリルダウンとかにすれば使い物になるものができる気がします。
あるいは、fluentdやlogstashで随時解析してKibana等にプロファイラの情報を流したり、カスタムAPIを工夫してOpenTracingとかをサポートする事も可能かもしれません。
低負荷プロファイラが内蔵されていて、しかも自由に弄れると言うのはやはり夢が広がります！
なお、サンプルコードはだいぶ雑に書いてしまったので非効率なことをしてる気はかなりするけどそこは気にしない方向でw
あと、ローカル型推論はやっぱ便利ですねー。今回みたいにタプルを使ってるケースには大助かります。
それでは来年もHappy Hacking!