Typemock: その過去・現在・未来
Eli Lopian氏率いるTypemock社の過去・現在・未来について、インタビュー形式にて記します。
Articles
Javaトラブルシューティングメルマガ総集編 2008/06～07
作者 エスエムジー株式会社 投稿日 2008年8月5日 午前8時39分
エスエムジーでは、Java全般を対象にしたトラブルシューティングサービス「JaTS」を提供しています。ご好評頂いているJaTSにて蓄積したトラブル事例とその解決ノウハウの一部を今年６月から「Javaトラブルシューティングメールマガジン」(JTSMM)として配信しています。この記事では過去２ヶ月のJTSMMの記事の総集編として、追加情報を含めたトラブル事例のダイジェスト情報を提供いたします。
６月～７月にかけて、JTSMMでは以下のトラブルを扱いました。
- メモリを使用していないのにFull GCに非常に時間がかかります
- Jakarta Commons HttpClientをマルチスレッド環境で利用時に、想定よりもパフォーマンスが向上しません
- 長期稼動しているJavaプロセスでjstatが動かなくなります
- プログラムがメモリリークしているかの判定ができません
￣￣￣￣￣￣￣￣￣￣￣￣￣￣￣￣￣￣￣￣￣￣￣￣￣￣￣￣￣￣￣￣￣￣￣￣
■「メモリを使用していないのにFull GCに非常に時間がかかります。」 【JTSMM vol.001】
＿＿＿＿＿＿＿＿＿＿＿＿＿＿＿＿＿＿＿＿＿＿＿＿＿＿＿＿＿＿＿＿＿＿＿＿
[問題]
ヒープ領域のメモリは殆ど使用していないにも関わらず、Full GCの完了に非常に時間がかかる場合があるという問題に遭遇しています。またファイル処理・DB処理をしていないにも関わらず、Full GC時にディスクへのアクセスが発生しています。
[解説]
これはヒープ領域を大量に確保しているJavaプロセスが長時間実行される場合に発生する問題です。
大量に確保しているヒープ領域のうち、一定時間利用されていない部分が実メモリからディスクに書き出される場合があります。一方、JavaのFull GCではJavaのヒープ領域の全スキャンを行います。
その結果、ヒープ領域の一部がディスクに書き出された状態でFull GCが発生すると、ディスクに書き出されたヒープをスキャンするためにディスクから実メモリへの読み込みが発生します。
一般にディスクアクセスでは実メモリへのアクセスに比べて非常に時間がかかるため、非常に長い時間のかかる処理に変わってしまいます。
vol.001はOSのメモリ管理とJavaのGCの仕組みが組み合わさって発生する問題でした。
Windowsでは、タスクマネージャのコミットチャージの合計が物理メモリの合計よりも大きな状態の場合に、この現象が発生しやすくなります。
Linuxでは、ps auxwで得られるプロセス情報のうち、VSZが大きくRSSが極端に小さな場合に、この現象が発生しやすくなります。下記は、見やすく整形した出力結果です。
（クリックすると拡大します）
￣￣￣￣￣￣￣￣￣￣￣￣￣￣￣￣￣￣￣￣￣￣￣￣￣￣￣￣￣￣￣￣￣￣￣￣
■「HttpClientをマルチスレッド環境で利用時に、想定よりもパフォーマンスが向上しません。」 【JTSMM vol.002】
＿＿＿＿＿＿＿＿＿＿＿＿＿＿＿＿＿＿＿＿＿＿＿＿＿＿＿＿＿＿＿＿＿＿＿＿
[問題]
Jakarta Commons HttpClient (以下、HttpClient)を、Webや雑誌などに掲載されているチュートリアル記事に記述されている方法で利用しています。 HttpClientは、コネクションプーリングによって処理も高速化されているはずですが、マルチスレッド環境で動作させても、パフォーマンスが想定よりも向上しません。
[解説]
HttpClientをマルチスレッドで効率よく利用するには、実は、一般に知られている実装方法とはことなる実装に切り替える必要があります。 Webや雑誌などのチュートリアル記事などで広く紹介されているHttpClientの利用方法は、シングルスレッド環境を想定した利用方法になっています。
Jakarta Commons HttpClientは、簡単に利用できる高性能なHTTPのクライアントライブラリとして広く利用されています。vol.002で掲載した問題は、このライブラリが提供している機能を把握しない使用方法では、本来のパフォーマンスを発揮できないというものでした。
vol.002で紹介した以外にも、HttpClientには様々な注意点があります。そのうちの一つで勘違いし易いのが「シングルスレッドにおけるコネクションプーリングの動作」です。
HttpClientのシングルスレッド版では、１ホストに対してのみコネクションプーリングを行います。このため、複数のホストに対しての接続を繰り返すプログラムにおいては、シングルスレッドのアプリケーションでもマルチスレッド版を利用した方が高速になる場合があります。
￣￣￣￣￣￣￣￣￣￣￣￣￣￣￣￣￣￣￣￣￣￣￣￣￣￣￣￣￣￣￣￣￣￣￣￣
■ 「長期稼動しているJavaプロセスでjstatが動かなくなります。」 【JTSMM vol.003】
＿＿＿＿＿＿＿＿＿＿＿＿＿＿＿＿＿＿＿＿＿＿＿＿＿＿＿＿＿＿＿＿＿＿＿＿
[問題]
Linuxで稼働中のJavaプロセスの情報を確認するため定期的にjstatを実行しています。長期間稼動中にjstatが"(pid) not found"と表示し、実行に失敗するようになりました。jpsも該当のPIDを一覧化してくれません。
[解説]
jstatやjpsは、Javaプロセスが立ち上げ時に作成するhsperfdataというファイルを参照して、Javaプロセスの存在や、Javaプロセスの情報を取得します。
このhsperfdataファイルは、"(テンポラリ領域)/hsperfdata_(ユーザ名)"以下に保存されます。
テンポラリ領域は、Javaを実行するプラットフォームごとに次のように決められています。
・Windows : TMP、TEMP、USERPROFILEの順に、存在する環境変数で示されたパス
・Linux : /tmp
・Solaris : /tmp
しかし、Linuxの一部ディストリビューションでは、/tmpディレクトリのディスク使用量を抑えるために、一定条件を満たすファイルを自動的に削除するように設定されています。そのため、hsperfdataファイルがこの削除条件に該当してしまった場合、自動的に削除されます。結果、jstatや jpsはhsperfdataファイルを参照できず、Javaプロセスを認識できなくなります。
jstat/jpsなど、JDK5.0から追加されたコマンドは"/tmp/hsperfdata_[UID]"にファイルを参照して、現在起動中のプロセス情報を取得します。このため、このファイルが削除されてしまうとjstat/jpsはJavaプロセスを認識できなくなってしまいます。
￣￣￣￣￣￣￣￣￣￣￣￣￣￣￣￣￣￣￣￣￣￣￣￣￣￣￣￣￣￣￣￣￣￣￣￣
■「プログラムがメモリリークしているかの判定ができません。」 【JTSMM vol.004】
＿＿＿＿＿＿＿＿＿＿＿＿＿＿＿＿＿＿＿＿＿＿＿＿＿＿＿＿＿＿＿＿＿＿＿＿
[問題]
プログラムを動かすと、徐々にメモリ使用量が増加していきます。
プログラムが正しい動作をしているのか、それともメモリリークしているのかどうか判断がつきません。
[解説]
1週間・1ヶ月と長時間実行するプログラムで発生した場合に、最も問題になるのは、メモリリークです。メモリリークが発生するプログラムを長時間実行させると、メモリを使い尽くしてしまいます。メモリを使い尽くしたプログラムは、次のようにOutOfMemoryErrorを発生して、強制終了してしまいます。
++++++++++++++++++++++++++++++++++++++++++++++++++++++++++
Exception java.lang.OutOfMemoryError: requested 124 bytes for AAA
++++++++++++++++++++++++++++++++++++++++++++++++++++++++++
実運用と同じような長時間実行する試験は頻繁に出来ないため、プログラムを短い時間動かすだけで、メモリリークかどうかを分析する必要があります。
メールマガジンでは、メモリリーク検出方法の概要を説明しました。ここでは、具体例として、Jakarta Commons DBCPを利用したプログラムで発生したメモリリークの検出事例をご紹介します。プログラムのソースコードはこちらです。
このプログラムは、長時間動作するとメモリ使用量が次第に増加することが分かっています。
まず最初にjstatコマンドを使って、Javaヒープの使用量の推移を確認します。 OUの値が増加していることから、Javaヒープが増加していることが分かりますので、Javaヒープでのメモリリークに的を絞って調査を行います。
（クリックすると拡大します）
次にJavaヒープ内の使用状況を調査するために、JavaVMのオプションに"-XX:+PrintClassHistogram"を追加してプログラムを実行します。起動したJavaプロセスにSIGQUITシグナルを送信することで、Javaのヒープ使用状況がコンソールに表示されます。以下は、その結果です。
num #instances #bytes class name -------------------------------------- 1: 9390 3648912 [I 2: 14742 18415843: 1553 1466032 oracle.jdbc.driver.T4CPreparedStatement ・・・ 11: 1553 273328 oracle.jdbc.driver.OracleSql 12: 1553 260904 oracle.jdbc.driver.T4CNumberAccessor 13: 10664 255936 java.lang.String 14: 3249 227224 [S 15: 3861 214864 [Ljava.lang.Object; 16: 1195 114720 java.lang.Class 17: 1553 99392 org.apache.commons.dbcp.PoolablePreparedStatement 18: 1556 88520 [[I 19: 243 58080 20: 1563 50016 org.apache.commons.dbcp.PoolingConnection$PStmtKey
PoolablePreparedStatement関連のインスタンス数が上昇していることから、DBCPのPrepared Statement機能にメモリリークの原因があると考えられます。この後は、ソースコードを調査し、インスタンス数が上昇しているオブジェクトを大量生成している箇所を特定します。
このように、メモリリークの発見と原因調査は、複数のコマンドを使いこなし、ソースコードを解析する必要がある難しいものです。そこで、当社のパッケージ製品であるENdoSnipeでは、メモリリーク検出機能を提供し、従来の方法に比べて格段と容易に行うことを可能にしています。
ENdoSnipeを適用すると、下図のようにメモリリークの発生をグラフィカルに表示することができます。
（クリックすると拡大します）
ENdoSnipeの製品ページでは、同じくDBCPの事例を用いて、メモリリーク検出機能の説明をしています。詳細は、「ENdoSnipeの利用事例～メモリリーク～」をご参照ください。
また、ENdoSnipeでは、実際に実行されたメソッドの呼び出し関係をクラス図として表示することができます。クラス図には、各メソッドの最大応答時間や平均応答時間が表示されます。応答時間が閾値を超えた場合には、メソッドを赤く点滅表示し、ユーザに問題発見を通知します。
参考として、vol.002で取り上げたHttpClientを利用したサンプルにENdoSnipeを適用し、実行時のクラス図を表示した結果を以下に示します。平均応答時間に大きな差が出ていることが分かります。
（クリックすると拡大します）
ENdoSnipeは、他にも、システムを診断しパフォーマンスに影響を与える各種問題を検出する機能など、障害解析/障害解決に役立つ様々な機能を備えています。詳細は、ENdoSnipeの製品ページをご覧下さい。
以上、７月までのJTSMMのダイジェストをお送りしました。
Javaトラブルシューティングメールマガジンは、２週間を目処に不定期で無料配信しております。メールマガジンの無料配信登録は、こちらから行うことができます。メールマガジンでは、これからもJavaのトラブル解決に役立つ情報をお届けして参ります。次回は、その他のメモリリーク解決事例をお届けする予定です。
ダイジェストにつきましては、次回は9月末を予定しております。ご期待下さい。
No comments
返信