jvisualvmを使ったCPUプロファイリング
ここ最近は機能追加の進捗しか書いていなかったので、今回は、技術的なことも少し書いてみたい。ということで、jvisualvmを利用したCPUプロファイリングの方法を紹介しよう。
jvisualvmとは、JDKに標準で付属するプロファイラだ*1。JavaVMのメモリ使用量や、スレッドの動作状況など、基本的な情報をリアルタイムで取得、表示してくれる。さっそく、起動してみる。
jvisualvmの起動
一番初めに、測定対象のJavaプログラムを起動しておこう。起動を確認したら、コマンドラインより、「jvisualvm」と打ち込む。すると、jvisualvmが起動して、次の画面が表示される。
左側には、起動中のJVMの一覧が表示される。ここでは、jvisualvm自身のvm、開発に利用しているIDEであるNetBeans6.1、そして開発中の画像ビューアjgbがあることが分かる。さっそく、開発中の画像ビューアを選択してみる。
CPUプロファイリング開始
さっそく、CPUプロファイリングをしてみよう。今回は、インターネット上のURLからHTMLをダウンロードし、その中にある画像の一覧を表示するという操作をプロファイルする。
プロファイルするためには、「Profiler」タブを選択する。すると、下記の画面が現れる。
もし、次のような警告が現れた場合、測定対象となるJavaプログラムの起動オプションに、「-Xshare:off」を付加しよう。
jvisualvmは、プロファイリングのために動作中のjavaプログラム（バイトコード）にダイナミックに修正を施す。javaのクライアントVMは、VM起動を速めるために、クラスファイル（バイトコード）の共有を行っており、jvisualvmで一つのプログラムに修正を施すと、動作中の他のプログラムにも影響が出る可能性がある。そのため、このような警告が発せられる。起動オプションに「-Xshare:off」を付加すると、クラスファイルの共有を強制的に行わないようにするため、他のプログラムに影響を与えることがなくなる。なお、サーバVMの場合、クラスファイルを共有しないため、このようなことを心配する必要はない。
CPUプロファイリングを行うためには、「CPU」ボタンをクリックする。
その状態で、プロファイルしたい処理を実行する。今回は、URLを指定しての画像一覧表示だ。一覧が表示し終わった段階では、jvisualvmの画面は次のようになっている。
詳しく見てみよう
jvisualvmは、リアルタイムにJVMの状況を取得する。そのため、じっくり解析したいときは、スナップショットを取るほうが良い。でないと、解析中にもどんどんと裏ではプログラムが進行し、いらないデータも表示されてしまう。
スナップショットを取るには、Profiling Results:の下にあるボタン群のうち、左から４番目のボタン、右矢印ボタンをクリックする。
すると、次の画面が表示される。
この画面は、スレッドが消費した時間が表示されている。ここから、「AWT-EventQueue-0」スレッドが約４秒、「BackgroundTaskProcessor」スレッドが同じく約４秒処理をしていることが分かる。
もっと詳しく見てみよう
「AWT-EventQueue-0」では、何の処理に時間が掛かっているか、見てみよう。「AWT-EventQueue-0」のツリーを開くと、メソッドごとの処理時間が表示される。
どうやら、「jgb.view.HistoryWindow$1.valueChanged」メソッドが、全体の87%消費していることが分かる。でも、これだけでは良く分からないので、もっとも掘り下げてみる。
こうしてみると、「org.htmlparser.http.ConnectionManager.openConnection」で約６割の時間が掛かっていることが分かる。Self Timeというのは、他のメソッド呼び出し以外のプログラム実行時間となる*3。
ここは利用しているライブラリのメソッドであるため何の処理かは正確には分からないが、メソッド名からインターネットからHTMLを取得している時間だろうと推測する。こればかりはどうにもならないため、最適化は厳しそうだ。
取得対象の変更
さて、自分が開発したプログラムだけプロファイリングするとか、ある特定の箇所に絞り込んでプロファイリングすると言った場面は頻繁に発生する。プロファイリングを細かく取ろうとすると、プロファイリングのオーバヘッドが相対的に大きくなり、何を測定しているか分からなくなってしまうためだ。そのため実際は、大まかに重たいメソッドを絞り込んで、少しずつドリルダウンしながら絞り込んでいくことが多い。
visualvmは、測定対象のJavaプログラムを再起動することなくプロファイリング対象を変更できる*4。当然、visualvmの再起動も必要ない。
そのためには、いったん「Stop」ボタンでCPUプロファイリングを停止し、「Settings」チェックボックスをONにした状態で、「CPU settings」タブの内容を変更する。
「Start profiling from classes:」という欄には、プロファイリング開始ポイントを指定する。ここで指定されたパッケージ、クラス、メソッドが呼ばれたら、プロファイリングを開始すると言うことだ。今回は、「jgb.**」とした。これは、jgbパッケージ以下全てのクラスに所属するメソッドが起動したら、プロファイリングを開始するという意味だ。
「Profile only classes:」と「Do not profile classes:」とあるが、前者を選択した場合、指定されたパッケージ・クラスのみプロファイル対象とし、後者を選択した場合、指定されたパッケージ・クラス以外をプロファイル対象とすることを意味する。ここでは、画像ビューアの処理のみを測定対象とするため、前者を選択し、「jgb.*」とした。
この設定で、画像ビューアの作りこみ箇所だけをプロファイリング対象とすることになる。
再測定
先ほどの手順で再測定を行うと、次の結果が得られた。
「jgb.image.thumb.SamplingThumbnailStrategy.loadThumbnail」メソッドが36回実行され、合計処理時間が4388msということが分かった。このメソッドは、サムネイル画像を読込・作成する処理である。サムネイル作成に、１画像あたり約120msということが速いかどうかは。。。
まとめ
jvisualvmを利用すると、こんな感じでCPUプロファイリングが簡単にできる。Java6限定となってしまうが、これから新規で開発する場合、わざわざJDK5を選択する理由もないのでぜひ使ってみていただきたい。なお、いくら簡単にできるからと言って、運用中のシステムにアタッチすることは避けたほうが良い。以前、それでひどい目にあった人がいたからだ。。。 あくまで、開発の一環として利用していただきたい。
