catalina.outのログ説明について

質問

catalina.outのログ説明について

catalina.outのログで以下のように出力されるのですが、
ログの読み方がよくわかりません・・・。
[GC 428197.352: [DefNew: 393030K->393030K(589824K), 0.0000250 secs]428197.352: [Tenured: 436300K->443579K(786432K), 1.1464740 secs] 829331K->443579
K(1376256K), 1.1465810 secs]

Webで調べたのですが、ログ出力での説明がなかったため、困っております。
ログ出力が説明されているサイト、又は、上記ログの意味がわかる方ご教授いただけないでしょうか。
宜しくお願い致します。

回答No.2

anmochi · ベストアンサー

追加の質問はお礼のメールで見てたけど回答しにくるの忘れてましたごめん。後、新OKWaveってお礼や補足に対する再回答がものすごくしづらいシステムになったのよね（回答画面に質問しか掲載されなくなった）。

> org.postgresql.util.PSQLException: Connection attempt timed out.
> DBはpostgresqlを使用しております。
　う～ん。運用途中で突然これが出てくる（当然Postgres側には問題なしとして）という事は、JDBCのコネクションプール関係が悪さをしている可能性が推測できる。

　GCはあくまでヒープメモリ（ヒープ領域と非ヒープ領域）の整理を行うもので、ヒープ以外にJVMが取得しているリソースについてはプログラム側が責任を持って開放しなければならない。クラス定義やインスタンスはGCがかってにやるけど、ファイルハンドルやソケットハンドルは確実に破棄してあげないとJavaがつかみっぱなしになるという事ですね。

　とりあえず今までの情報からではこの程度の当たり前の事しか返答できませんね。これ以上詳細なログや状況を説明してもらうというのもQAサイトの主旨に反するので、メモリ以外のリソースに当たりをつけてソースをレビューしてみてはどうでしょうか。

回答No.1

anmochi

GCは文字通りGCが発生しましたよ～という意味です。ここが「FULL GC」と書かれていたらFULL GCが発生したという意味になります。はしょって説明するとGCは参照が無くなったインスタンスのお掃除の他にNEW→Survivor→OLDの移動なんかも行われ、FULL GCはPERMANENTからのクラスアンロードなんかも含めて大規模なメモリ掃除が行われます。
　その後ろの数字はJVMが起動されてから今までGCに使われた時間の総合計で、多分ミリ秒。
　DefNewは今回のGC前後のNew領域メモリ使用量と総メモリ量そして掛かった時間。Tenuredは今回のGC前後のOld領域の以下略。時間がミリ秒とすればTomcatを起動してから今までに合計428秒もの時間をGCにとられた事になります。

　今回、GCが発生したにも関わらずNew領域の使用量が変化していません（お掃除が一切行われていない）。そしてOld領域にいたってはメモリ使用量が増えています（これは別に悪い事ではない）。以上のことから、このGCはその1つ前のGCからほとんど時間が経過していないのに発生したと推測できます。これは、Tomcatがとても忙しく稼動しているか（ページビュー／秒が多いあるいは負荷試験を行っている）、サーブレットのプログラムが無意味にインスタンスの生成→消滅を繰り返しているか、その両方か、と言ったところでしょうか。

　ところで、このログはjavaコマンドのオプションで指定しないと出ないはずのため、ご自分でこの指定をしているのではないですか。このログではGC発生しかわからないため、メモリ使用量をリアルタイムで監視したいのであればjconsole（GUIアプリ）やjstat（コンソールアプリ）を使うと良いでしょう。JVMのプロセスIDはjpsコマンドで調べる事ができます。

お礼

ご回答ありがとうございます！
ログ出力の設定ですが、担当者が不在のため、どのような設定しているかわからないのです・・・。

あともう一つだけ教えていただきたいのですが、
最近になって、サイトが落ちることが多々あります・・・。

サイトが落ちる直前には、以下のようなログが多数出る状態です。
[GC 762587.450: [DefNew: 392991K->392991K(589824K), 0.0000250 secs]762587.451:[Tenured: 450952K->459208K(786432K), 1.4179210 secs] 843943K->459208K(1376256K), 1.4180190 secs]
[GC 762589.008: [DefNew: 393102K->393102K(589824K), 0.0000200 secs]762589.008:[Tenured: 459208K->434474K(786432K), 1.4081020 secs] 852311K->434474K(1376256K), 1.4081820 secs]
[GC 762590.554: [DefNew: 392984K->392984K(589824K), 0.0000240 secs]762590.554:[Tenured: 434474K->443384K(786432K), 1.3743890 secs] 827459K->443384K(1376256K), 1.3744860 secs]
[GC 762592.066: [DefNew: 392848K->392848K(589824K), 0.0000200 secs]762592.066:[Tenured: 443384K->458508K(786432K), 1.3555100 secs] 836233K->458508K(1376256K), 1.3555910 secs]

anmochiさん回答によりますと、GCからほとんど時間経過していないのに発生しているということで、
Tomcatが忙しく稼動しているということですよね。
上記のTenuredログが表示されるのは良くないと思っておりました・・・。

普段のGCのログですが、以下のようなログが出力されます。
4549.361: [GC 4549.361: [DefNew: 401597K->5561K(589824K), 0.0096100 secs] 588553K->192517K(1376256K), 0.0096530 secs]
4549.124: [GC 4549.124: [DefNew: 397615K->8455K(589824K), 0.0190430 secs] 584241K->195410K(1376256K), 0.0190840 secs]
4535.930: [GC 4535.930: [DefNew: 398844K->4547K(589824K), 0.0083320 secs] 585468K->191173K(1376256K), 0.0083740 secs]
4535.672: [GC 4535.672: [DefNew: 397329K->5631K(589824K), 0.0114940 secs] 583940K->192255K(1376256K), 0.0115360 secs]

Tenuredが表示されておりませんので、OLD領域には移動せず、メモリ解放が正常に行われていると考えております。

Webでいろいろ調べたのですが、OLD領域のメモリ解放には、FullGcのログが出ていれば、
時間がかかっているが、正常にメモリが解放されたということでよろしいのでしょうか？
FullGCが頻繁に起こらないほうが良いのはわかっておりますが、
サイトが落ちる直前のGCログを見ておりますと、FullGcも出ず、OutOfMemoryErrorも出ずにTenuredのログが数百行発生した後、
↓以下のログが表示され、サイトが閲覧できなくなります。
org.postgresql.util.PSQLException: Connection attempt timed out.

DBはpostgresqlを使用しております。

以上から、解決するにはどのようなことをすれば良いか教えていただけると助かります・・・。
お手数ですが、宜しくお願い致します。