<< 2008/11/02 | Home | 2008/11/04 >>

メモリリークトラブルシューティング記 - その2: フリーズの原因は GC

- その1: 自宅サーバがハング

- その2: フリーズの原因はガベージコレクション
JBoss のサーバログ(server/$MY_CONFIG/logs/server.log) を見ても特に顕著なメッセージは見られません。

普段からフリーズしたらとにかくスレッドダンプ!と口を酸っぱくしています。
私自身スレッドダンプを見るのが趣味みたいなものですが、今回はスレッドダンプは必要ありませんでした。

標準出力をみると、原因は明らか。

.
.
.
306122.554: [Full GC 306122.554: [Tenured: 546171K->546171K(546176K), 4.0978385 secs] 607611K->607602K(607616K), [Perm : 60798K->60798K(60928K)], 4.0982228 secs]
306126.672: [Full GC 306126.672: [Tenured: 546171K->545982K(546176K), 6.4798504 secs] 607611K->607421K(607616K), [Perm : 60798K->60797K(60928K)], 6.4801261 secs]
306133.182: [Full GC 306133.182: [Tenured: 546169K->546169K(546176K), 4.2429345 secs] 607609K->607600K(607616K), [Perm : 60798K->60798K(60928K)], 4.2433055 secs]
フリーズの原因は(GC)ガベージコレクションです。
この標準出力に記録されているメッセージは JVM のオプション、"-XX:+PrintGCTimeStamps -XX:+PrintGCDetails" で記録されるもので、GC の状況を報告しています。
一般的な GC アルゴリズムではヒープ領域が一杯になるとアプリケーションのスレッドは一旦停止し、Stop the world と呼ばれる GC 処理に専念する期間に入ります。
そして一回の GC が終了すると上記のようなメッセージが記録されます。
今回注目したいのは GC ログの最後にある時間。これが GC にかかった処理時間 = Stop the world の期間を示します。
この時間が1秒を超えたら危険信号、要チューニングと言って良いでしょう。
今回のログでは4〜7秒ほどの GC が立て続けに発生していることがわかります。
これでは Stop the world だらけでアプリケーションスレッドが全然動けません。

次回は GC が頻発する原因を探ります。

- その3: 侍でヒープ使用量を確認

- その4: リーク箇所を確認する色々な方法

- その5: Memory Analyzer でヒープダンプを解析(最終回)

タグ :

メモリリークトラブルシューティング記 - その1 : 自宅サーバがハング!

- その1: 自宅サーバがハング
現在このweblogをホストしている自宅サーバの構成は以下の通りです。
ハードウェア: iBook G4(1GB / 1TB)
OS: Mac OSX 10.5.5
VM: JDK1.5.0_16
APサーバ: JBoss AS 4.2.x
データベース: MySQL 5.0.x, PostgreSQL 7.4.x

正直 Mac OSX の JVM は安定性に欠けており、bus error で落ちることもしばしば。
bus error のときは単に JBoss を再起動することでしのいできました。
ただ、最近のアップデートで VM の安定性はだいぶ向上した感があります。

替わりに最近なんだかフリーズすることがあります。
2週間くらい安定して稼働していることもあれば起動して2,3日でフリーズすることも。

特にミッションクリティカルなアプリケーションが動いているわけではないので、しばらくは構わず kill / 再起動をしていました。
今回連休中にようやく重い腰を上げてトラブルシュートしましたので過程を記します。

- その2: フリーズの原因は GC

- その3: 侍でヒープ使用量を確認

- その4: リーク箇所を確認する色々な方法

- その5: Memory Analyzer でヒープダンプを解析(最終回)

タグ :