JVMアプリケーションのCPUボトルネックをasync-profilerで調べてみる

こんにちは、事業開発部の齋藤です。 ここ最近ずっと負荷試験をやっていました。

今日はJVMのアプリケーションのプロファイルを取ることが出来る、「async-profiler」を使ってみたので そのツールの紹介記事です。

はじめに

今回使ってみよう、というきっかけになったのは 負荷試験実行中にやけにCPU負荷が高い、ということで プロファイラを試してみるか、という話になりました。

このasync-profilerを選んだ理由は 単に知っている中で一番楽に使えそう、というので選びました。 また、Javaのプロファイラはいくつか商用製品もあるみたいなのですが 今回はちょっと調べてみたい、ということでasync-profilerを選びました。

今回の記事ではprofilerを掛けて 「Flame Graph」というグラフを見るところまでをやってみます。

詳しくは以下の流れでやっていきます。

• インストール
• プロファイラを掛ける
• Flame Graphを見る

Flame Graphについては以下のサイトを参考にしながら 見ていきました。

• Flame Graph
• GolangでFlame Graphを描く

インストール

Profileは今回はMacで行うので ダウンロードしてくるのはMac向けのアーカイブです。 Linux向けのアーカイブも提供されているので Linux上でのProfileを行いたい方は GitHubのリポジトリにあるREADMEを確認してください。

$ curl -L https://github.com/jvm-profiling-tools/async-profiler/releases/download/v1.4/async-profiler-1.4-macos-x64.tar.gz -O
$ tar xvf async-profiler-1.4-macos-x64.tar.gz

Usageが表示されるので必要になったら見てください。

$ ./profiler.sh
Usage: ./profiler.sh [action] [options] <pid>
Actions:
  start             start profiling and return immediately
  stop              stop profiling
  status            print profiling status
  list              list profiling events supported by the target JVM
  collect           collect profile for the specified period of time
                    and then stop (default action)
Options:
  -e event          profiling event: cpu|alloc|lock|cache-misses etc.
  -d duration       run profiling for <duration> seconds
  -f filename       dump output to <filename>
  -i interval       sampling interval in nanoseconds
  -j jstackdepth    maximum Java stack depth
  -b bufsize        frame buffer size
  -t                profile different threads separately
  -s                simple class names instead of FQN
  -o fmt[,fmt...]   output format: summary|traces|flat|collapsed|svg|tree|jfr

  --title string    SVG title
  --width px        SVG width
  --height px       SVG frame height
  --minwidth px     skip frames smaller than px
  --reverse         generate stack-reversed FlameGraph / Call tree

  -v, --version     display version string

<pid> is a numeric process ID of the target JVM
      or 'jps' keyword to find running JVM automatically

Example: ./profiler.sh -d 30 -f profile.svg 3456
         ./profiler.sh start -i 999000 jps
         ./profiler.sh stop -o summary,flat jps

プロファイルを取ってみる

今回は単純に60秒間プロファイルを取ってみましょう。

$ jps
# プロファイルを掛けたいJVMのPIDを調べる
$ ./profiler.sh -d 120 -f `pwd`/flamegraph.svg <PID>
# 120秒ぐらい待つ

これだけでFlame Graphを取ることが可能です。

取ったFlame GraphはChromeなどのブラウザで開くと良いです。 内部にスクリプトが埋め込まれており、ズームイン、ズームアウトすることが可能です。

今回負荷調べる時にどうやってプロファイルを取ったかについて

今回はいくつかの方針を立ててプロファイルを取っていきました。

• ローカルで実行出来る範囲でプロファイルを取る
• JVMおよびフレームワークの起動が完全に終わった後にプロファイルを取る
• watch -n1 scenario.sh といった形で負荷を掛けるシナリオなどを用意して、JVMの状態を見たい状況にする
• JITコンパイルやクラスローディングの話が絡んでくるので軽くJVMを暖気してからプロファイルを取る

上記方針でプロファイルを掛けました。

Flame Graphについては冒頭でも上げましたが 以下のリンク先の内容を参考に見ていきました。

• Flame Graph
• GolangでFlame Graphを描く

今回取ったプロファイラでの結果を元に以下のようなFlame Graphを取ることができました。

スクリーンショットは断片的なものですが、見たところ、spring-data-mirageのメソッド内部でCPUを使っているように見えます。 ZIPへのIOをしているようなので、IOを減らす意味でも、この部分を減らせないか実装コードを確認しました。 インスタンス作成時に１回だけ実行する形に出来そうなので、以下の修正のPRを送りました。

• https://github.com/dai0304/spring-data-mirage/pull/19

まとめ

今回の記事では、async-profilerを使って アプリケーションにプロファイラを掛けてみました。 今回の利用用途は非常に限定的ですが簡単にプロファイルを取ることが出来ました。 また、今回取ったプロファイルから、Flame Graphを見てライブラリを直すことが出来ました。 その結果、CPU利用率が抑えられ、WebアプリケーションからRDBにもっと負荷が掛かるようになりました！

皆さんも、CPUボトルネックを調べるために使ってみてはいかがでしょうか。 ボトルネックを修正出来ると楽しいですよ！

Docker コンテナ上でのプロファイルも取ってみたいところですが linux perf eventsを制限していてプロファイルが取れませんでした。 Docker コンテナ側の修正が必要になりそうです。

今度試す時はDockerコンテナ上動くJVMアプリケーションに対してプロファイルを掛けてみたいところです。

今回の記事はこれで終わりです。

TIPS: PID楽に調べたい。

以下のコマンドで JVMのPIDを調べるのが楽でした。

ソートしておくと １回１回表記が変らなくて良いです。

$ watch -n1 jps | sort -k1,1 -n