– その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]
.
.
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 が頻発する原因を探ります。
– その4: リーク箇所を確認する色々な方法
– その5: Memory Analyzer でヒープダンプを解析(最終回)