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

# はじめに
[OSSとなったJava Mission Control 7.0.0 Early-Accessを触ってみる：導入編] ( https://qiita.com/h-r-k-matsumoto/items/ca1a6d80f3984c975c20) の続きです。
前回は、JMC、JFRが動作することを確認しましたが、障害はいつ発生するか分からないので、Flight Recorderとして、ちゃんと記録し続けてくれないと、困ってしまうわけです。
試しに、

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

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

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

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

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

# 結果

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

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

# 環境

- Google Kubernetes Engine 1.10.5-gke.4
- 動作確認方法は、<br>[OSSとなったJava Mission Control 7.0.0 Early-Accessを触ってみる：導入編] ( https://qiita.com/h-r-k-matsumoto/items/ca1a6d80f3984c975c20)  <br>と一緒です。

# アプリケーションの設定

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

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

## configmapでflight recorederのテンプレートを登録する
これは後述する [docker image `openjdk:11-jdk` にjfrのtemplateが無い](#docker-image-openjdk11-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}の部分) は適宜書き換えてください。

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

```deploy
> 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](https://qiita-image-store.s3.amazonaws.com/0/268550/7b2ad948-5e11-783e-0daf-f9173a210b88.png)

# JFRでの実行分析

## OOM発生時の分析

アプリケーションで強制的に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](https://qiita-image-store.s3.amazonaws.com/0/268550/671d85ee-0199-e6d0-825a-704163192a10.png)

byte[]情報が、最終ヒープサイズとして、19.8MiB、Array Elementsが1.06 x 10^6 と大量消費されているのが分かります。
また、スタックトレースから、OOMController#triggerであることが分かりますね。ちゃんと分析できそうです。
![image.png](https://qiita-image-store.s3.amazonaws.com/0/268550/111f63a1-701f-a0b0-c109-6bd049b86bdd.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](https://qiita-image-store.s3.amazonaws.com/0/268550/a0b44a27-61a1-62cc-4b37-774449f8ef93.png)

### Java アプリケーション

求めていたものと違う・・・。
![image.png](https://qiita-image-store.s3.amazonaws.com/0/268550/5cfc2d05-8dd4-5a60-5ee9-7f724cd5a6d0.png)

### 期待していたこと

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

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

![image.png](https://qiita-image-store.s3.amazonaws.com/0/268550/da41eafe-bca8-3347-290d-ae602ec2a883.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

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

http://openjdk.java.net/jeps/328
> 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だからでしょうね。ドキュメントがまったく見当たりません。
もう少し立てば・・・ドキュメントも増えると期待しています。

# 参考

- jib:https://github.com/GoogleContainerTools/jib
- flight recorder:http://openjdk.java.net/jeps/328
- [OSSとなったJava Mission Control 7.0.0 Early-Accessを触ってみる：導入編] ( https://qiita.com/h-r-k-matsumoto/items/ca1a6d80f3984c975c20 )