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

今日はJVMのアプリケーションのプロファイルを取ることが出来る、「async-profiler」を使って Javaで動くアプリケーションのボトルネックを探してみました。今回のプロファイル結果からライブラリに修正も送ってみました。皆さんもasync-profilerを使ってアプリケーションのボトルネックを調べてみてはいかがでしょうか。

#Java

齋藤将也

2018.09.13

この記事は公開されてから1年以上経過しています。情報が古い可能性がありますので、ご注意ください。

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

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

はじめに

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

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

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

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

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

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を取ることができました。

スクリーンショットは断片的なものですが、見たところ、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アプリケーションに対してプロファイルを掛けてみたいところです。

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