JFRをBigQuery/Metabaseのオレオレダッシュボードで可視化する

この記事は Java Advent Calendar 2019の9日目です。前日はSphereさんの「Visual Studio CodeでParaya MicroのWebアプリケーションを作る準備をする: すふぃあの記憶」でした。

はじめに

JDK Flight Recorderを皆さん使っていますか？ JDK 9からAPIが整備されJDK 11からOpenJDKに寄贈されたので商用ライセンスを持っていなくても本番で自由に使えるようになりました。

常時プロファイルをonにして障害時にすぐに情報を取得できるブラックボックス分析はとても便利です。OpenJDK系ディス鳥の標準機能なので、まだ利用されてない方はぜひ使って見てください。

JFRはあまり詳しくないという方は、更新があまりできてないですが個人的にJFRの情報をまとめてるサイトも書き始めたので良ければご参考ください。

koduki.github.io

閑話休題。JFRはJDK Mission ControlないしはVisual VMで見るのが基本なのですが、対象のJFRファイル以外の情報と統合したくてデータを抽出したいことも良くあります。

事後の分析を複数環境に対してやりたいときやPVとの相関を見たいとき。そんな時は仕方ないのでExcelにコピペして集計したりしました。

これを解決しようとすると、以前は非公式APIを使うとかあまり便利な方法が無かったのですが、JDK9以降はAPIが標準化されて便利になったのでそのやり方を紹介したいと思います。なお、基本的にはCode Oneで喋ったのと同じ内容となります。

JFRを取得する

JFRを取得しないと始まらないのでJFRの取得をします。

WebアプリケーションだろうがバッチだろうがJFRの取得はJVMオプションを指定するだけで簡単に出来ます。

今回はQuarkusで作ったRESTベースのWebアプリです。

java -XX:StartFlightRecording=settings=profile,disk=true,filename=/var/log/myapp/myapp.jfr \
-XX:FlightRecorderOptions=repository=/var/log/myapp/reposistory / \
-jar myapp-runner.jar

-XXオプションを-jarの後に書いた場合は正常に動かないので注意してください。

ポイントはrepositoryオプションを使ってリポジトリを指定することです。filenameで指定するJFRファイルはプロセスの終了時かJFR.dumpコマンドの実行時にしか出力されません。

それだと、不便なことも多いので循環バッファの一部をディスクに出力するようにrepositoryオプションを指定すると特にWebアプリケーションでは便利です。

以前は必要だったUnlockCommercialFeaturesやFlightRecorderオプションは不要です。また、JDK 8の頃とはJFRに必要なJVMオプションがJDK8から少し異なっています。例えば、以下のような差分があります。

JDK 8:

-XX:+UnlockCommercialFeatures
-XX:+FlightRecorder
-XX:FlightRecorderOptions=defaultrecording=true,
dumponexit=true, dumponexitpath=/var/log/myapp/myapp.jfr

JDK 11:

-XX:StartFlightRecording=dumponexit=true,
filename=/var/log/myapp/myapp.jfr

JDK9のオプションがJava Flight Recorder Command Referenceで確認できるので見直しておくのが良いと思います。

起動したWebアプリケーションに負荷を掛けてみます。すると以下のようなディレクトリ構成でJFRファイルが出力されます。

$ tree /var/log/myapp/ 
/var/log/myapp/
├── myapp.jfr
└── reposistory
    └── 2019_12_01_23_43_51_89649
        ├── 2019_12_01_23_43_51.jfr
        ├── 2019_12_01_23_53_42.jfr
        └── 2019_12_01_23_53_42.part

myapp.jfrは基本的にはプロセスが終了するまで空なので、スローレスポンスの分析のために中間の状態を取得したい場合はrepository配下のファイルを取得することになります。障害時にはプロセスが終了するのでmyapp.jfrを取得することになるでしょう。

今回はプロセスを落とさずにJFRを取得したかったのでリポジトリから2019_12_01_23_43_51.jfrを取得しています。

とりあえずJMCで開いてみるとこんな感じです。

JFRをJSONに展開する

続いて、JFRファイルを取り扱いやすい形式に変換しましょう。

JFRファイルはバイナリです。これはこれで便利なのですが、他のツールと連携する場合には不便です。なのでテキストベースの形式に変換します。

JFRはJDK JFR Consume APIを使うことでJavaを使ってJFRを解析出来ます。自分で解析PGを組んでも良いのですが、JFR Toolを使うことでXMLやJSONに変換できるので今回はこちらを使います。

以下のコマンドでJFRファイルをJSONテキストに変換できます。

$ jfr print \
--json  \
--events jdk.GCPhaseParallel,jdk.ExecutionSample,jdk.CPULoad,jdk.GCHeapSummary \
2019_12_01_23_43_51.jfr > 2019_12_01_23_43_51.json

categoriesとeventsはJFRのイベントブラウザから確認できます。こちらの情報を使って内容をフィルタする事ができます。

JSONの中身は以下のようにJFRの値を単純に変換した形となります。

{
  "recording": {
    "events": [{
      "type": "jdk.GCConfiguration", 
      "values": {
        "startTime": "2019-12-01T23:43:51.141988376-08:00", 
        "youngCollector": "G1New", 
        "oldCollector": "G1Old", 
        "parallelGCThreads": 4, 
        "concurrentGCThreads": 1, 
        "usesDynamicGCThreads": true, 
        "isExplicitGCConcurrent": false, 
        "isExplicitGCDisabled": false, 
        "pauseTarget": "PT-2562047788015215H-30M-8S", 
        "gcTimeRatio": 12
      }
    }, {
      "type": "jdk.GCSurvivorConfiguration", 
      "values": {
        "startTime": "2019-12-01T23:43:51.141992948-08:00", 

容量を確認してみましょう。

$ ls -lh 2019_12_01_23_43_51.jfr 2019_12_01_23_43_51.json
-rw-r--r--  1 koduki  staff    18M Dec  1 23:56 2019_12_01_23_43_51.jfr
-rw-r--r--  1 koduki  wheel   25M Dec  2 20:36 2019_12_01_23_43_51.json

元が18MBだった展開すると25MBになっているのが分かります。あくまでフィルタをした状態のサイズで仮にフィルタをしない場合は3.2GBくらいのサイズになり、JFRの保存形式の効率の良さが伺えます。

また、events配列の中身だけあれば良いのとJSONはNDJSON(Newline delimited JSON)形式にする必要があるのでjqコマンドで変換します。

$ cat 2019_12_01_23_43_51.json | jq -c '.recording.events[]' > 2019_12_01_23_43_51_f.json

これでひとまずのJSONへの展開は完了です。

BigQueryに取り込む

では、BigQueryに先ほどのJSONを取り込みましょう。

まず先ほどのJSONをイベント毎のファイルに分割します。

$ echo "jdk.GCPhaseParallel jdk.ExecutionSample jdk.CPULoad jdk.GCHeapSummary" \
|xargs -P4 -n1 sh -c 'grep \"type\":\"$0\" 2019_12_01_23_43_51_f.json \
> logs/${0}.json'

イベント毎フォーマットが異なるので単純にBigQueryにアップロードしようとするとエラーになります。

INSERT文を使うか、別の形式に変換して可変部分をJSON文字列にしてSQLで解析するというELTっぽい手もあるのですが、それはそれで面倒なので今回はシンプルにイベント毎にテーブルを分けてロードすることにします。

続いてGCSにアップロードします。

# Create Bucket
$ gsutil mb gs://jfr-storage/  

# Upload
$ gsutil cp logs/*.json gs://jfr-storage/

# Check
$ gsutil ls -lh gs://jfr-storage/ 
 88.88 KiB  2019-12-03T08:42:43Z  gs://jfr-storage/jdk.CPULoad.json
  7.31 MiB  2019-12-03T08:42:56Z  gs://jfr-storage/jdk.ExecutionSample.json
 104.4 KiB  2019-12-03T08:42:56Z  gs://jfr-storage/jdk.GCHeapSummary.json
  5.37 MiB  2019-12-03T08:43:05Z  gs://jfr-storage/jdk.GCPhaseParallel.json
TOTAL: 4 objects, 13492203 bytes (12.87 MiB)

BigQueryにロードしていきます。

bq load --autodetect --source_format=NEWLINE_DELIMITED_JSON jfr_logs.jdk_CPULoad gs://jfr-storage/jdk.CPULoad.json
bq load --autodetect --source_format=NEWLINE_DELIMITED_JSON jfr_logs.jdk_ExecutionSample gs://jfr-storage/jdk.ExecutionSample.json
bq load --autodetect --source_format=NEWLINE_DELIMITED_JSON jfr_logs.jdk_GCHeapSummary gs://jfr-storage/jdk.GCHeapSummary.json
bq load --autodetect --source_format=NEWLINE_DELIMITED_JSON jfr_logs.jdk_GCPhaseParallel gs://jfr-storage/jdk.GCPhaseParallel.json

テーブルが作成されたのが確認できました。

$ bq ls jfr_logs
        tableId           Type     Labels   Time Partitioning   Clustered Fields  
 --------------------- ---------- -------- ------------------- ------------------ 
  jdk_CPULoad           TABLE                                                     
  jdk_ExecutionSample   TABLE                                                     
  jdk_GCHeapSummary     TABLE                                                     
  jdk_GCPhaseParallel   TABLE

Metabaseで可視化する

さて、ではBigQueryに取り込んだJFRのデータをビジュライズしていきましょう。 今回はMetabaseを使って可視化を行いました。GCPにMetabaseをインストールしてBigQueryと繋ぐ方法は下記の記事に別途まとめてるのでご参考ください。

qiita.com

JFRの解析して、とりあえずこんな感じの簡単なレポートを作ってみました。

SQLは以下の感じで組んでいます。

今回は面倒だったので複数のJFRがテーブルに入ることは無い想定でSQLを組み立てています。実際はその辺を考慮してWHERE句等を書く必要があります。

CPU Load Summary

SELECT 
  values.startTime,  
  values.machineTotal, 
  values.jvmUser 
FROM `{project_id}.jfr_logs.jdk_CPULoad`

GC Summary

SELECT 
  values.name,
  SUM(CAST(REGEXP_REPLACE(values.duration, r"[PTS]", "") AS NUMERIC)) as total_duration, 
  count(1) as count
FROM `{project_id}.jfr_logs.jdk_GCPhaseParallel`
GROUP BY name

Heap Summary

SELECT 
  values.startTime as timestamp, 
  values.heapUsed 
FROM `{project_id}.jfr_logs.jdk_GCHeapSummary`

Methods Call

SELECT method_name, count(1) as count FROM
(
  SELECT 
    CONCAT(
      REGEXP_REPLACE(REGEXP_REPLACE(values.stackTrace.frames[OFFSET(0)].method.descriptor, r";.*|\(L|[\(\)]", ""), "/", "."), 
      ".", 
      values.stackTrace.frames[OFFSET(0)].method.name
    ) as method_name
  FROM `{project_id}..jfr_logs.jdk_ExecutionSample`
  UNION ALL
  SELECT 
    CONCAT(
      REGEXP_REPLACE(REGEXP_REPLACE(values.stackTrace.frames[OFFSET(1)].method.descriptor, r";.*|\(L|[\(\)]", ""), "/", "."), 
      ".", 
      values.stackTrace.frames[OFFSET(1)].method.name
    ) as method_name
  FROM `{project_id}.jfr_logs.jdk_ExecutionSample`
  UNION ALL
  SELECT 
    CONCAT(
      REGEXP_REPLACE(REGEXP_REPLACE(values.stackTrace.frames[OFFSET(2)].method.descriptor, r";.*|\(L|[\(\)]", ""), "/", "."), 
      ".", 
      values.stackTrace.frames[OFFSET(2)].method.name
    ) as method_name
  FROM `{project_id}.jfr_logs.jdk_ExecutionSample`
  UNION ALL
  SELECT 
    CONCAT(
      REGEXP_REPLACE(REGEXP_REPLACE(values.stackTrace.frames[OFFSET(3)].method.descriptor, r";.*|\(L|[\(\)]", ""), "/", "."), 
      ".", 
      values.stackTrace.frames[OFFSET(3)].method.name
    ) as method_name
  FROM `{project_id}.jfr_logs.jdk_ExecutionSample`
)
GROUP BY method_name
ORDER BY count desc
LIMIT 10

簡単なSQLのわりにはそれっぽいレポートが出来てるのは無いでしょうか？

以前はJFRをES + Kibanaでビジュアライズしましたが、BigQuery + Metabaseの方が圧倒的に楽です。

カスタムイベントを追加する

WeblogicならWLDFの情報がJFRに入っていて分析も捗るのですが、それ以外のシステムで値を採ろうと思ったらカスタムイベントを書く必要があります。

以前は、非公式APIを使う必要がありましたがJDK9からはカスタムイベントの仕様も刷新され正式に利用できるようになりました。

ちなみにライブラリがJDK8でも利用される場合は「空実装の互換API」があるようなのでこちらを使えばコンパイルエラーにならないはずです。(#未検証)

とりあえずはWebアプリケーションの基本という事でResponse Timeを取ってみます。

まずはJFRイベントを作成します。

@Category({"Application Profile"})
@Label("HTTP Request")
public class HttpRequestEvent extends Event {

    @Label("Method")
    String method;

    @Label("URL")
    String url;
}

基本的にはEventクラスを継承して、格納したいプロパティをフィールドとして記述するだけです。@Labelや@CategoryでJMC上からの見え方を制御できます。

アノテーションにはその他にも閾値を設定する@Thresholdなどがあります。スロークエリなど特定の条件のみとれば良いときは設定すると負荷やデータサイズも下がって良いと思います。

代表的なアノテーションは以下です。

アノテーション	概要	デフォルト値
@Category	複数のイベントを束ねるカテゴリの作成。複数指定する事で階層化もできる	N/A
@Name	イベントの名前。	イベントクラスのパッケージ名を含むフルクラス名
@Label	プロパティ名	N/A
@Description	イベントの簡易な説明	N/A
@Threshold	JFRに記録するための閾値	0 ns
@StackTrace	イベントにスタックトレースを含むかのフラグ。デフォルトでは含まれる	true
@Enable	イベント記録を有効にするかのフラグ。デフォルトでは有効	true

では、続いてJFRイベントを記録します。

HTTPのレスポンスタイムなのでJAX-RSのメソッドをフックすることになります。今回の対象システムはQuarkusを使ってるのでCDIのインターセプタを使ってAOPを行います。

まずはトリガーとなるアノテーションを作成します。

@Inherited
@InterceptorBinding
@Retention(RetentionPolicy.RUNTIME)
@Target({ElementType.METHOD, ElementType.TYPE})
public @interface WebTrace {
}

続いて、アノテーションをエンドポイントになるJAX-RSのコードに付与します。

@Path("/account")
@WebTrace
public class AccountResource {
.
.
.

最後にCDIのインターセプタを作成します。JFRイベントの記録もここです。

@Interceptor
@Priority(Interceptor.Priority.APPLICATION)
@WebTrace
public class WebTraceIntersepter {
    @Inject
    HttpServletRequest req;

    @AroundInvoke
    public Object invoke(InvocationContext ic) throws Exception {
        var event = new HttpRequestEvent(); // JFRイベントの初期化

        event.begin();  // JFRイベントの記録開始
        var result = ic.proceed();
        event.end();    // JFRイベントの記録完了

        // JFRイベントに任意のパラメータを追加
        event.url = req.getRequestURI();
        event.method = req.getMethod();
        // JFRイベントをコミット
        event.commit();

        return result;
    }
}

JFRイベントは単にnewするだけで良いです。DIとかFactorytとかが必要なのいで簡単ですね。今回の場合はic.proceed()が実際の処理が実行されるタイミングです。その前後でbegin/endする事で実行時間の記録を行います。単位はナノ秒です。

必要なパラメータを詰めたらcommitします。今回はURLとGETなのかPOSTなのかと言う情報も欲しかったので、HttpServletRequestをInjectionして取得しています。JFR関係ないですが1点注意なのはquarkus-undertowを依存に含めないとQuarkusではHttpServletRequestをInjectionできないので注意してください。

JMCのイベントブラウザで以下のように格納されたのが確認できるかと思います。

格納したURLやMethodはもちろんJFR側の機能としてDurationやスタックトレース、あるいは開始と終了のタイムスタンプも取れているので調査が捗りそうですよね？

JFRのカスタムイベントに関しては徳益さんの「使ってみよう！JDK Flight Recorder」か「Java Flight Recorder in JDK 9 – Marcus Hirt」が詳しいです。

カスタムイベントをMetabaseでビジュアライズ

JMCの標準機能だけではグラフにして表示とかはできませんが、JMC Pluginを作れば可能なはずです。ただし、Eclipse力が必要になります。

と言うわけでBigQuery及びMetabaseを使ってビジュアライズしましょう。ちなみに、話の流れ的にMetabaseを使ってますが手元で探索的に作業するだけならgnuplot使うとかJupyter Notebookを使うのも良いと思います。

先ほどと同じ手順でJSONに変換してBigQueryに取り込みます。

$ jfr print --json --events minica.util.profile.HttpRequestEvent myapp.jfr > myapp.json
$ cat myapp.json | jq -c '.recording.events[]' >  myapp_f.json
$ grep '"type":"minica.util.profile.HttpRequestEvent"' myapp_f.json > HttpRequestEvent.json
$ gsutil cp HttpRequestEvent.json gs://jfr-storage/
$ bq load --autodetect \
                 --source_format=NEWLINE_DELIMITED_JSON \
                 jfr_logs.HttpRequestEvent \
                 gs://jfr-storage/HttpRequestEvent.json

Metabaseでグラフにしてみます。

利用したSQLはこちら。

レスポンスサマリ:

SELECT 
  values.startTime as timpestamp,
  CAST(REGEXP_REPLACE(values.duration, r"[PTS]", "") AS NUMERIC) * 1000 duration
FROM `{project_id}.jfr_logs.HttpRequestEvent` 

URL分布:

SELECT 
  REGEXP_REPLACE(values.url, r"[0-9]+", "{key}") as url,
  count(1) as count
FROM `{project_id}.jfr_logs.HttpRequestEvent`
GROUP BY url

TPS:

SELECT PERCENTILE_CONT(count, 0.5) OVER() as tps FROM(
  SELECT sec, count(1) as count  FROM(
    SELECT 
      UNIX_SECONDS(values.startTime) as sec,
      CAST(REGEXP_REPLACE(values.duration, r"[PTS]", "") AS NUMERIC) * 1000 duration
    FROM `{project_id}.jfr_logs.HttpRequestEvent` 
  ) GROUP BY sec
)
LIMIT 1

JMCでカスタムイベントをビジュアライズしようとするとプラグインを書く必要がありGUI力が足らない私としては結構難しかったのですが、Metabase + BigQueryであれば手慣れたSQLでサクッとグラフに出来るのが良いですね。

リアルタイム連携をする

せっかくなのでリアルタイム連携も作っていきましょう。

と言っても、JFR Stream APIはまだ未実装なので下記のような流れでやります。

1. JFRのオプションを変更してリポジトリに小刻みにファイルを吐く
2. JFRをGCPにアップロードする
3. GCSにアップロードされたことCloud Functionsで検知してCloud Runをキックする
4. Cloud RunでCloud SDKコマンドを使ってGCSからBigQueryに連携する

Cloud RunはCloud SDKを使うBashとすることで概ね今までの通りの方法で動くのがポイントです。

JFRのチャンクサイズの変更

まずは、JFRのチャンクサイズを変更します。デフォルトでは12MBとかなり大きいのでアップロード負荷が高いです。なので、1MBまで下げておきます。

java -XX:StartFlightRecording=settings=profile,disk=true,filename=/var/log/myapp/myapp.jfr -XX:FlightRecorderOptions=repository=/var/log/myapp/jfr_logs/,maxchunksize=1M -jar myapp.jar

maxchunksizeを変更する事で比較的小さなファイルがリポジトリにたくさん出来るようになります。

JFRをGCPにアップロードする

続いてJFRのアップロードです。 前回実行時とのファイルリストの差分をチェックして新規があればgs://jfr-storage/にJFRをアップロードします。

REPO=/var/log/myapp/jfr_logs
WORKDIR=/tmp

CURRENT_REPO="$REPO/"$(ls -1 $REPO|sort|head -1)
ls -l $CURRENT_REPO|awk '/jfr/{print $9, $5}'|sort > $WORKDIR/jfr.list
diff ${WORKDIR}/jfr.list ${WORKDIR}/jfr.list.prev |grep jfr|awk '$NF > 0{print $2}' > ${WORKDIR}/jfr.diff
mv $WORKDIR/jfr.list $WORKDIR/jfr.list.prev

cat ${WORKDIR}/jfr.diff|xargs -n1 -P1 -I{} gsutil cp "${CURRENT_REPO}/"{} gs://jfr-storage/

watchコマンドやcronで定期実行すると良いでしょう。

GCSにアップロードされたことCloud Functionsで検知してCloud Runをキックする

Cloud RunはまだHTTP以外のイベントソースを受け取れないのでイベントのフックにはCloud Functionsを使います。スクリプトは下記の通り。

package.json:

{
  "name": "check_gcs4jfr",
  "version": "0.0.1",
  "dependencies": {
    "@google-cloud/storage": "^1.6.0",
    "request": "^2.88.0"
  }
}

index.js:

var request = require("request");

exports.checkGCS4JFR = (event, context) => {
  const gcsEvent = event;
  const url = "https://{Cloud RunのURL}?args=" + gcsEvent.name;

  console.log(`Recive Event: ${gcsEvent.name}`);
  request.get(url, function(err, res, body) {
    if (err) {
      console.log("Error: " + err.message);
      return;
    }
    console.log(body);
  });
};

パススルーしてるだけなのでシンプルですね。以下のコマンドでデプロイします。

$  gcloud functions deploy checkGCS4JFR --runtime nodejs8 --trigger-resource jfr-storage --trigger-event google.storage.object.finalize

Cloud RunでCloud SDKコマンドを使ってGCSからBigQueryに連携する

最後にGCSからBigQueryへのアップロードです。と言っても基本的には先ほど記載したコマンドをそのまま実行するだけです。

HTTPからのリクエストでスクリプトが動かせるようにhttp-wrapperを利用します。 Dockerfileは以下の通り。中で使ってるスクリプトはこちらです。

FROM google/cloud-sdk

RUN apt-get update && apt-get install -y openjdk-13-jdk-headless jq && apt-get clean && rm -rf /var/lib/apt/lists/*
ENV PATH /usr/lib/jvm/java-13-openjdk-amd64/bin/:$PATH

RUN mkdir -p /app
WORKDIR /app

RUN curl https://storage.googleapis.com/shared-artifact/hwrap -o hwrap && chmod a+x ./hwrap
ADD parse.sh ./
ADD transfer_gcs.sh ./
ADD load_bq.sh ./
ADD run.sh ./

CMD ["./hwrap", "-p8080", "./run.sh"]

ではCloud Runにデプロイします。

$ GCP_PRJ_ID=$(gcloud config get-value project)
$ gcloud builds submit --tag gcr.io/${GCP_PRJ_ID}/jfr4bq
$ gcloud beta run deploy --image gcr.io/${GCP_PRJ_ID}/jfr4bq

これで準備はOKです。試してみましょう。

$ watch --interval 60 ./transfer2gcs.sh /var/log/myapp/jfr_logs

BigQueryにJFRの情報が準リアルタイムで連携されるのがわかります。

まとめ

半分くらいJavaではない話を書いた気もしますがいかがだったでしょうか？

リアルタイム分析のところはさておきカスタムイベントとBigQuery/Metabaseでの分析はかなり使いやすいかと思います。 JDK9での仕様の標準化とJDK11でのOpenJDKへの取り込みでこう言った事がやりやすくなったのは非常に良いことかな、と思っています。

MicroprofileのMetricsやOpenTracingなど情報をとる仕組みも標準化してきたので、上手くこの辺りをJFRにも書き込んでWeblogic並みの障害分析環境を標準化出来ないかも今後チャレンジしてみたいです。

それだは、来年もみなさんとJavaにとって良い年でありますように。Happy Hacking!

参考

• Performance Monitoring with Java Flight Recorder on OpenJDK [DEV2406]
• 入門: JDK Flight Recorder(作成中)
• BigQueryとMetabaseで簡単な負荷テストレポートを作ってみた - Qiita
• どんなコマンド/スクリプトもサーバレス化するためのhwrapを書いた - ブログなんだよもん