開発、テストから運用まで、あらゆるフェーズでシステムのトラブル解決に役立つJava SE 7の「Java Flight Recorder」──Oracle DBA & Developer Day 2013レポート

Oracle Java & Developers編集部
2013-12-11 17:10:00
  • このエントリーをはてなブックマークに追加

見つけづらい「マルチスレッド処理におけるロック競合」も目視で簡単に発見

 続いてはマルチスレッドでの動作確認を行う。これは日次の集計データを月の前半と後半で2つに分け、2つのスレッドでの処理が正常に行われるかどうかを確認するというものだ。しかし、実際にテストしてみたところ、シングル・スレッドの場合と処理時間がまったく変わらない。これは不自然である。

 そこで、再びJava Flight Recorderで記録した稼働情報をJava Mission Controlに読み込み、処理状況をイベント・グラフで確認してみる。すると、「pool-1-thread-1」と「pool-1-thread-2」の2つのスレッドにおいて、交互にJava Monitor Blockedイベントが発生していることが判明する。

 このイベントの詳細を見ると、Synchronizedメソッドでブロックしたそれぞれのスレッドにおいて、「Logic」というインスタンスのロックを取り合うという競合が発生していることがわかった。つまり、2つのスレッドで1つのLogicインスタンスのロックを取り合っているため、一方のスレッドがロックを取得している間、もう一方のスレッドがロック取得待ちの状態に陥り、結果的にシングル・スレッドの場合と同様の処理時間がかかってしまっていたというわけだ。そこで、スレッド数分のインスタンスを用意し、それぞれが自分のLogicインスタンスを使って処理を行うようにすることで、この問題を解決した。

 伊藤氏は、実際の現場では、このようなマルチスレッドに起因する問題が発生しても見過ごされる可能性があると指摘する。

 「今回はシングル・スレッドで動作確認を行った後にテストしたため、マルチスレッドでの処理が不自然に遅いことが判明しました。マルチスレッドだけをテストした場合はロック競合に気づかず、処理速度についてもこの程度だと誤って判断してしまう可能性があります。

 しかし、Java Flight RecorderとJava Mission Controlを使えば、スレッドごとの処理状況をビジュアルに確認できるので、各スレッドの処理内容や異常も容易に見つけることができます。運用フェーズに移行する前の段階で、こうしたバグを目視で簡単に発見できるという点は大きなメリットでしょう」(伊藤氏)

JVMの動きも一目で把握。チューニング・ミスも即座に判明/解決

 アプリケーションの確認と修正が終わったら、最後にこれまでのノウハウも生かして机上チューニングを実施し、JVMのオプションを設定する。そのうえで実行してみたところ、35秒で処理が完了した。この処理時間は妥当だろうか?

 処理時間が適切かどうかを判断する方法としては、ガベージ・コレクション(GC)の回数や、それに要した時間を確認することが考えられる。実際にこのアプリケーションで計測したところ、GCに要した時間は合計で約24秒であった。処理時間のおよそ3分の2がGCに使われている計算になるが、これはいくら何でも時間がかかりすぎだ。

 そこで、Java Flight Recorderで記録したJVMの稼働情報をJava Mission Controlで詳しく見ていくと、ヒープ全体のGCが1170回も実行され、GC後のヒープ使用量は2.15MBであることがわかった。このアプリケーションはヒープ・サイズが15.5MB、若い世代のオブジェクトが格納されるEden領域には13MBを割り当てている。

 だがGCが実行されると、ほとんどのオブジェクトは中長期寿命のオブジェクトが格納されるSurvivor領域とTenured領域に移される。Eden領域に13MBを割り当てているということは、Survivor領域とTenured領域には2MBしか割り当てがないということになる。その領域をGC後のオブジェクトが占有するため、GCが頻発しているわけだ。

 中長期寿命のオブジェクトが多く作られてしまう原因は、対象がバッチ処理であるのにもかかわらず、OLTP向けの手法で机上チューニングを行っていたことにある。処理時間の短いOLTPでは、寿命の短いオブジェクトが多いため、短命なオブジェクトを格納するEden領域のサイズを大きくとったほうが有利となる。しかし、処理時間が長くなるバッチでは、寿命の長いオブジェクトが多くなる傾向があり、Survivor領域やTenured領域を大きくしたほうが有利となるのだ。

 実際に、このケースではヒープ全体のサイズは変更せず、Survivor領域とTenured領域のサイズを大きくすることで、GCに要する合計時間を2.4秒にまで抑え、全体の処理時間も13秒へと大幅に短縮することができた。

 このような調整はプロファイリング・ツールなどによって各種のログを記録/分析することでも行えるが、システムにかかる負荷や手間の問題から、必要なログを常にすべて記録しているケースはまれだろう。だが、Java Flight Recorderであれば、JVMを含むシステムの稼働情報を低負荷で記録することができる。そこで、常にJava Flight Recorderで稼働情報を記録しておき、気になる挙動があればJava Mission Controlを使って総合的に分析するといったアプローチをとることで、「何が起きているのかわからない」といった状況でも、問題の原因を子細に究明できるようになるのだ。

 なお、Java Flight RecorderとJava Mission Controlは、長期保守サービスを含むJava SEの有料ライセンス「Java SE Advanced」、およびJava SE Advancedのサービス内容にリアルタイムJVMのJRockit Real Timeを付加した有料ライセンス「Java SE Suite」を購入したユーザーが利用できる機能だが、製品評価のために試用することも可能だ。関心を持たれた方は、ぜひ最新版のJava SE 7と併せてお試しいただきたい。

このサイトでは、利用状況の把握や広告配信などのために、Cookieなどを使用してアクセスデータを取得・利用しています。 これ以降ページを遷移した場合、Cookieなどの設定や使用に同意したことになります。
Cookieなどの設定や使用の詳細、オプトアウトについては詳細をご覧ください。
[ 閉じる ]