前回書いた JVMのJITコンパイルのメトリクスをMicrometerで収集する の続きです。

今回は、JVMオプション(-Xlog:jit+compilation=debug)を有効にしてログを出しつつ、mtailを使ってPrometheusで見れるようにしてみます。

ソースはここに置いてます。
k8sクラスタにサンプルアプリ、mtail、Prometheusをまとめてデプロイして動かせるようにしておきました。

https://github.com/matsumana/jvm-jit-compilation-metrics-example


今回使用したJavaのバージョン: AdoptOpenJDK 14.0.2

前回記事のサンプルアプリにmtailを追加したので使用しているJDKは引き続き14ですが、
-Xlog は JEP 158: Unified JVM Logging で追加されたJVMオプションなので
Java9以降であればこのサンプルアプリで使用している mtail設定ファイル が使えます。

Java8以前であれば-XX:+LogCompilationを使うことになりますが、その場合はログファイルのフォーマットが違うためこのmtail設定ファイルは使えないので注意してください。


-Xlog:jit+compilation=debugで出力されるログのフォーマット

-Xlog:jit+compilation=debugを設定すると、JITコンパイルのログが以下のような感じで出力されます。

ログファイルのフォーマットは以下を参考にしてください。

OpenJDKのソースコード:
https://github.com/openjdk/jdk/blob/jdk-15+36/src/hotspot/share/compiler/compileTask.cpp#L232-L302

FYI:
jit+compilationログに情報を追加する案があるっぽい。15にはまだ含まれていないけどログをparseする時は気をつけた方が良さそうです。
https://bugs.openjdk.java.net/browse/JDK-8237002

[133.694s][debug][jit,compilation] 11253   !   3       java.io.RandomAccessFile::read (190 bytes)
[133.695s][debug][jit,compilation] 4697   !   2       java.io.RandomAccessFile::read (190 bytes)   made not entrant
[146.723s][debug][jit,compilation] 11254       3       java.lang.Integer::stringSize (47 bytes)
[148.031s][debug][jit,compilation] 11255       3       java.lang.AbstractStringBuilder::append (55 bytes)

左側の3つのフィールドは、JEP 158: Unified JVM Loggingで出力される uptime, level, tag です。
詳しい内容は以下の資料がわかりやすいです。

Unified JVM Logging:
https://www.slideshare.net/YujiKubota/unified-jvm-logging


mtailで出力しているJITコンパイルのメトリクス

こんな感じのメトリクスが出力されるようにしています。

# HELP mtail_jvm_jit_compilation_total defined at jvm-jit-compilation.mtail:1:9-39
# TYPE mtail_jvm_jit_compilation_total counter
mtail_jvm_jit_compilation_total{filename="/app/jvm-unified-log/jit-compilation.log",package="java.util",prog="jvm-jit-compilation.mtail"} 1921
mtail_jvm_jit_compilation_total{filename="/app/jvm-unified-log/jit-compilation.log",package="java.util.concurrent",prog="jvm-jit-compilation.mtail"} 369
mtail_jvm_jit_compilation_total{filename="/app/jvm-unified-log/jit-compilation.log",package="org.springframework.util",prog="jvm-jit-compilation.mtail"} 554
...


Micometerで収集したメトリクスとの差異

mtailで収集しているメトリクスは(mtail_jvm_jit_compilation_total)と、Micrometerを使って収集しているメトリクス(jvm_jit_compilation_total)は、数も値も一致していません。
これは、-Xlog:jit+compilation=debugのログはJVM起動時から出力されるのに対して、JFR Event Streamingを使って自分で実装したメトリクス収集ロジックが動作し始めるのはSpringアプリとしての動作が始まって以降になるからです。
JFR Event Streamingを使った場合には検知できない（既に終わっている）JITコンパイルも結構ありそうです。


参考資料