LoginSignup
2
1

More than 5 years have passed since last update.

@h-r-k-matsumoto

OpenJDK11 Java Flight Recorder + Google Kubernetes Engineで実行分析

Last updated at Posted at 2018-08-13

はじめに

OSSとなったJava Mission Control 7.0.0 Early-Accessを触ってみる：導入編 の続きです。
前回は、JMC、JFRが動作することを確認しましたが、障害はいつ発生するか分からないので、Flight Recorderとして、ちゃんと記録し続けてくれないと、困ってしまうわけです。
試しに、

  • OOM発生時の分析：OOM発生時に、どの部分でメモリを消費しているか分析できるか
  • Profilerによる遅い箇所の分析：特定処理のボトルネックを確認することができるか

を、確認することができるかを見てみようと思います。

下記設定で動かしてみます。

  • アプリケーション起動時から記録し続ける
  • 最大2時間記録、もしくは100MBまでファイルに記録し続ける
  • 開始30秒後から記録を開始する。
  • 記録するファイルは、ファイルに出力し、永続化する。

JFR関連は、google検索から飛んでくる方が多いので英語で頑張って書こうと思いましたが・・・挫折しました。

結果

  • OOM分析はできそう
  • profilerとしての機能は・・・jvisualvm程の機能はなさそうでした。
    ※jvisualvmはアプリケーションに負荷をかけてしまうので、それを考えると、production環境でも利用可能なprofilerとして役立つのかもしれません。
  • jvisualvmではできない別の分析は色々できそう。(イベント情報、GC発生状況からの分析)

profilerの機能はもうちょっと深く勉強して行こうと思います。
多分、
　http://www.oracle.co.jp/jdt2015/pdf/4-5.pdf
のP59～71に書いてあるような分析も・・・できるはず。

環境

アプリケーションの設定

アプリケーションは、
https://github.com/h-r-k-matsumoto/k8s-jmc-sample.git
にあります。jibを使ってdocker imageのbuild,pushを行っています。

Flight Recorder周りの設定で説明すると・・・

configmapでflight recorederのテンプレートを登録する

これは後述する docker image openjdk:11-jdk にjfrのtemplateが無い の問題より、別途configmapで読み込ませています。

010_configmap.yaml
kind: ConfigMap
metadata:
  name: spring-boot-config
apiVersion: v1
data:
  profile.jfc: |-
    ～テンプレート情報～

Java起動引数に、-XX:StartFlightRecording を追加する。

jvmFlagで -XX:StartFlightRecording オプションを追加します。settingsとしてconfigmapで読み込ませたファイルを指定します。

pom.xml
<jvmFlag>-XX:StartFlightRecording=name=sample,filename=/spring-boot/jfr/sample.jfr,delay=30s,maxage=2h,maxsize=10m,dumponexit=true,settings=/spring-boot/config/profile.jfc</jvmFlag>

アプリケーションのビルド、デプロイ

gcp-project-idは、利用する google container registryのproject idを指定します。
020_statefulset.ymlのimage({chane-it-me}の部分) は適宜書き換えてください。

> mvn -Dgcp.project.name=gcp-project-id compile jib:build

> kubectl apply -f kubernetes
configmap "spring-boot-config" configured
statefulset.apps "k8s-jmc-sample" configured
service "k8s-jmc-sample" configured
>

JMCの接続

WindowsマシンからJMCで接続します。フライト・レコーダーが開始されている事が分かります。
image.png

JFRでの実行分析

OOM発生時の分析

アプリケーションで強制的にOOMを発生させます。どこでメモリを消費してしまっているか確認できるかを見てみます。

$ curl http://10.60.1.28:30001/oom/trigger
{"timestamp":"2018-08-13T13:35:30.768+0000","status":500,"error":"Internal Server Error","message":"Java heap space","path":"/oom/trigger"}
$

>kubectl logs -f k8s-jmc-sample-0
2018-08-13 13:35:30.528  INFO 1 --- [io-30001-exec-7] c.e.h.s.controller.OOMController         : dummy memory size = 33554432
2018-08-13 13:35:30.756 ERROR 1 --- [io-30001-exec-7] o.a.c.c.C.[.[.[/].[dispatcherServlet]    : Servlet.service() for servlet [dispatcherServlet] in context with path [] threw exception [Handler dispatch failed; nested exception is java.lang.OutOfMemoryError: Java heap space] with root cause

java.lang.OutOfMemoryError: Java heap space
        at java.base/java.util.Arrays.copyOf(Arrays.java:3745) ~[na:na]
        at java.base/java.io.ByteArrayOutputStream.grow(ByteArrayOutputStream.java:120) ~[na:na]
        at java.base/java.io.ByteArrayOutputStream.ensureCapacity(ByteArrayOutputStream.java:95) ~[na:na]
        at java.base/java.io.ByteArrayOutputStream.write(ByteArrayOutputStream.java:156) ~[na:na]
        at com.example.hrkm.springbootsample.controller.OOMController.trigger(OOMController.java:27) ~[classes/:na]
        at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[na:na]
        at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) ~[na:na]
        at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[na:na]
        at java.base/java.lang.reflect.Method.invoke(Method.java:566) ~[na:na]

JMCで、対象時刻の記録を見てみます。
image.png

byte[]情報が、最終ヒープサイズとして、19.8MiB、Array Elementsが1.06 x 10^6 と大量消費されているのが分かります。
また、スタックトレースから、OOMController#triggerであることが分かりますね。ちゃんと分析できそうです。
image.png

Profilerによる遅い箇所の分析

計測用のWeb APIを実行します。適当にgitリポジトリをcloneしてファイル名で探索するものです。
ソースは、
https://github.com/h-r-k-matsumoto/k8s-jmc-sample/blob/master/src/main/java/com/example/hrkm/springbootsample/controller/ProfileController.java
です。適当に10回くらい実行します。
このAPIのボトルネックとなるとなる箇所を確認できるか見てみます。

$ curl http://10.60.1.28:30001/profile/trigger
["src/main/java/com/example/hrkm/springbootsample/repository/FooRepository.java","src/main/java/com/example/hrkm/springbootsample/Application.java","src/main/java/com/example/hrkm/springbootsample/service/FooService.java","src/main/java/com/example/hrkm/springbootsample/controller/OOMController.java","src/main/java/com/example/hrkm/springbootsample/controller/ProfileControl
$

メソッドプロファイリング

・・・なるほど。私にはまだ使いこなせないという事が分かりました。
image.png

Java アプリケーション

求めていたものと違う・・・。
image.png

期待していたこと

jvisualvmのように、特定のメソッドの呼び出しにおいて、どの処理に時間がかかっているか見たかったのですが・・・できませんでした。

jvisualvmだと、下記のようにProfileController#triggerの中で、FooRepository#initRepositryが処理の大半を費やしているのが分かります。Flight Recorderはprofilerとしてそこまで追跡はできないのか、もしくはもう少し細かく記録する内容を設定しないとダメなのかもしれません。

image.png

ハマったこと、未解決のこと

docker image openjdk:11-jdk にjfrのtemplateが無い

sha256:f684efd78557b35f19e91b84cc3070e852b2344bac22ed4f3d3470c604babc66 の imageを使っていましたが・・・。

起動オプションを下記のようにデフォルト記録テンプレートを使おうとすると、containerが起動しません。

<jvmFlag>-XX:StartFlightRecording=filename=/sprng-boot/jfr/sample.jfr,delay=30s,maxage=2h,maxsize=5g,disk=true</jvmFlag>

下記のように設定が見つからないよーと怒られちゃいます。
んー。Windowsの私のマシンのjdkには含まれているので、dockerのimageがまだ古いのかもしれません。

$ kubectl get pod
NAME               READY     STATUS             RESTARTS   AGE
k8s-jmc-sample-0   0/1       CrashLoopBackOff   14         50m
$ kubectl logs  k8s-jmc-sample-0
Could not parse setting default
Error occurred during initialization of VM
Failure when starting JFR on_vm_start
$

回避方法

configmapで私のマシンにあった jdk_home/lib/jfr/profile.jfc を追加しました。
そして起動オプションに　settings=/spring-boot/config/profile.jfc を追加しました。

参考：https://github.com/h-r-k-matsumoto/k8s-jmc-sample/blob/master/kubernetes/010_configmap.yaml#L35

ファイル出力のタイミングの制御

Threads write events, lock-free, to thread-local buffers. Once a thread-local buffer fills up, it is promoted to a global in-memory circular buffer system which maintains the most recent event data. Depending on configuration, the oldest data is either discarded or written to disk allowing the history to be continuously saved. Binary files on disk have the extension .jfr and are maintained and controlled using a retention policy.

恐らくメモリ中に滞在できなくなったら、ディスクに書き込まれるみたいだけれども・・・どれくらいで出力されるのかがわかりませんでした。。。
java起動時に、

Use jcmd 1 JFR.dump name=sample to copy recording data to file.

と出力され、たしかにこれを実行することでファイルにダンプされるのは分かりましたが、定期的な出力方法は不明でした。

プロセス終了時のダンプファイル出力場所の制御

dumponexit=true とした場合、 tmpディレクトリに出力されます。
・・・tmp以外に出力される方法は不明です。tmpを永続先としてマウントさせちゃうか、 java.io.tmpdir のシステムプロパティ変えればよいのかもしれないですが、tmpを永続する・・・というのは何か気持ち悪いですね・・・。

Java Mission Control 7.0.0の使い方がいまいちわからない。

まだ、EAだからでしょうね。ドキュメントがまったく見当たりません。
もう少し立てば・・・ドキュメントも増えると期待しています。

参考

2
1
0

Register as a new user and use Qiita more conveniently

  1. You get articles that match your needs
  2. You can efficiently read back useful information
  3. You can use dark theme
What you can do with signing up
Sign upLogin
2
1