winds.from.oz 技術メモ

Java トラブルシューティング

Posted:

トラブル解決フロー

問題発生　→　基本データ分析　→GCログ解析

  • GCが頻発している　→　Heapチューニング　→　GCログ解析
    • GCが頻発している　→　オブジェクトのプロファイリング
      • オブジェクトに問題あり　→　ソース修正
      • オブジェクトに問題なし　→　OS,ミドルウェアの設定値再確認
    • GCが頻発していない　→　解決！！
  • GCが頻発していない　→　CPUの使用率確認
    • CPUがボトルネックである　→　メソッドのプロファイリング（特定の処理の重いメソッドが何度も呼ばれていないか？）
      • メソッドに問題あり　→　ソース修正
      • メソッドに問題なし　→　OS,ミドルウェアの設定値再確認
    • CPUがボトルネックではない　→　スレッドダンプ解析
      • スレッドダンプ問題あり　→　プールオブジェクト解析
      • *プールオブジェクト問題あり　→　OS,ミドルウェアの設定値再確認
      • *プールオブジェクト問題なし　→　ソース修正
      • スレッドダンプ問題なし　→　メソッドのプロファイリング（特定の処理の重いメソッドが何度も呼ばれていないか？）
      • *メソッドに問題あり　→　ソース修正
      • *メソッドに問題なし　→　OS,ミドルウェアの設定値再確認

１．Javaヒープ領域がOutOfMemoryとなる場合

【応急処置】

-Xms、-Xmxを指定し、OutOfMemoryErrorが発生しないようにヒープを広げる。

【原因調査】

GCログを取得し、ヒープでのメモリリークが発生していないか確認する。

GCログを侍やGCViewer、Excel等でグラフ化して確認する。

グラフがFull GCを跨って、右肩上がりになっている場合は、メモリリークが発生している可能性が高い。

リーク箇所を発見するには、ヒープ統計情報やヒープダンプを数回取得して比較して、Full GCを経ても増加し続けているオブジェクトを探す。

怪しいオブジェクトが見つかれば、NetBeans Profiler等を使用して、オブジェクトの使用箇所を探し、オブジェクト参照を追跡する。

２．ヒープチューニング方法

【方針】

Full GC実行時間を最小にするために、OutOfMemoryErrorが発生しないサイズでなるべく小さいサイズを-Xms、-Xmxに指定する。

Full GC発生頻度を抑えるために、-XX:NewSize、-XX:MaxNewSize、-XX:SurvivorRatio、-XX:MaxTenuringThreshold、-XX:TargetSurvivorRatioを調整して、なるべくNew領域でのマイナーGCでメモリを解放させて、Old領域へ移動される頻度、サイズを減らすようにする。

【設定】

||オプション||説明 ||-XX:NewSize、-XX:MaxNewSize|| -Xmxサイズの1/4 - 1/3程度 ||-XX:SurvivorRatio||2-8程度 ||-XX:MaxTenuringThreshold||32程度 ||-XX:TargetSurvivorRatio||80-90程度

※アプリケーションサーバのように500Mバイトから1Gバイト近くのメモリサイズを使用する場合、Copy GCは0.01秒から0.7秒程度と１秒に満たない間に終了するのに対し、同じ条件でFull GCが発生した場合１秒から数10秒とされている。

３．マイナーGCが1秒を超える場合

New領域が大きすぎる可能性があるので、-XX:NewSize、-XX:MaxNewSizeを減らす。

CPUが複数ある(マルチコアを含む)場合は、-XX:+UseParallelGC オプションでパラレルGCを有効にする。

-XX:+UseParallelGC マイナーGCをマルチスレッドで実行

４．Full GCが1秒を超える場合

  • メモリリークが発生していない場合は、Old領域が大きすぎる可能性があるので、-Xms、-Xmxを減らす。

  • メモリリークが発生しておらず、これ以上減らすとOutOfMemoryErrorが発生するOld領域サイズなのに、Full GC実行時間が1秒を超える場合は、以下の対応案が考えられる。

  • アプリケーションでメモリを使いすぎていないか確認し、使いすぎている場合は修正する。

    • メモリを多く消費する処理を特定するには、運用環境で、jstat -gcutilやjconsoleを使用してヒープの各領域の使用状況を監視し、使用率がドカッとあがったときに実行された処理を、アクセスログから突き止める。(ある程度絞れれば、あとは開発/検証環境で突き止める)あとは、コード解析を行い、修正する。

  • セッションタイムアウト時間の確認。

    • 不必要に長すぎないか確認。

  • コンカレントGCの使用。

    • Full GCをできるだけアプリケーションをとめずに並行実行するコンカレントGCを使用する。以下のJava起動オプションを設定する。
    • ※-Xms -Xmx -XX:NewSize -XX:MaxNewSize、-XX:SurvivorRatio、-XX:MaxTenuringThreshold、-XX:TargetSurvivorRatioは設定されている前提。

||オプション||説明 ||-XX:+UseConcMarkSweepGC||コンカレントGCの有効化。 ||-XX:+CMSParallelRemarkEnabled||Full GCのRemarkフェイズをマルチスレッドで実行。整合性の調査を複数スレッドで並行に実施する。 ||-XX:+UseParNewGC||マイナーGCをマルチスレッドで実行 。

５．アプリケーションの応答が停止(フリーズ)した場合

スレッドダンプを取得する。

  • kill -3 <pid>を使用する。
  • kill -3 <pid>を使用できない場合は、「jstack」を使用する。
  • 「侍」等を使用してダンプファイルを解析する。

６．StackOverflowError と出る場合

StackTraceを確認し、メソッドの不要な再帰呼び出し等が行われていないか確認する。あるいは、以下のJava起動オプションを設定し、スタックサイズを増やしてみる。

  • -Xss
  • -Xoss

GCログの見方

パターン１
【説明】ログを出す設定だけ
【オプション】-verbose:gc
【ログ】

[GC 4405K->844K(15872K), 0.0053825 secs]
[GC 5260K->1314K(15872K), 0.0037365 secs]
[GC 5730K->1681K(15872K), 0.0028928 secs]
[Full GC 2263K->1757K(15872K), 0.0185841 secs]


パターン２
【説明】ログ出力とタイムスタンプ（起動からの経過時間）出力を設定
【オプション】-verbose:gc -XX:+PrintGCTimeStamps
【ログ】

0.217: [GC 4405K->844K(15872K), 0.0054283 secs]
0.320: [GC 5260K->1314K(15872K), 0.0040315 secs]
0.404: [GC 5730K->1681K(15872K), 0.0028648 secs]
0.419: [Full GC 2267K->1757K(15872K), 0.0188291 secs]


パターン３
【説明】ログ出力を詳細に設定
【オプション】-verbose:gc -XX:+PrintGCTimeStamps
【ログ】

[DefNew: 4405K->512K(4928K), 0.0054153 secs] 4405K->844K(15872K), 0.0054474 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
[GC [DefNew: 4928K->512K(4928K), 0.0037293 secs] 5260K->1314K(15872K), 0.0038013 secs] [Times: user=0.00 sys=0.02, real=0.02 secs]
[GC [DefNew: 4928K->374K(4928K), 0.0028912 secs] 5730K->1681K(15872K), 0.0029126 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
[Full GC (System) [Tenured: 1307K->1757K(10944K), 0.0188756 secs] 2264K->1757K(15872K), [Perm : 7419K->7419K(12288K)], 0.0189368 secs] [Times: user=0.01 sys=0.00, real=0.02 secs]

GCログのオプションパターンと見方

（例１）3.125: [GC 3.125: [DefNew: 3328K->384K(3712K), 0.0112500 secs] 8168K->5998K(16000K), 0.0113291 secs]

上記のデータの説明
3.125・・・JVM が起動してから GC が発生した時間
GC・・・GC の種類を表示します。
「GC」 と表示されれば主に New 領域が対象の Scavenge GC。
「FULL GC」と表示されれば New 、Old 、Permanent 領域が対象の FULL GC。
New 領域の情報
DefNew・・・New 領域に対するGCを表す。以下の値はNew 領域が対象。
3328K ・・・GC 前のオブジェクトのサイズ ( New 領域 )
384K ・・・GC 後のオブジェクトのサイズ ( New 領域 )
(3712K) ・・New 領域のヒープサイズ
0.0112500 secs・・・この New 領域の GCにかかった時間
ヒープ全体の情報
8168K ・・・GC 前のオブジェクトのサイズ
5998K ・・・GC 後のオブジェクトのサイズ
(16000K)・・全体のヒープサイズ
0.0113291 secs・・・この GC にかかった時間

（例２）
-210.274: [GC 210.274: [DefNew: 335145K->3122K(339264K), 0.1164251 secs] 389309K->62953K(1038336K), 0.1165947 secs]
-214.007: [Full GC 214.007: [Tenured: 68230K->67535K(699072K), 1.2545997 secs] 167459K->64535K(1038336K), [Perm : 53247K->53247K(53248K)], 1.2547773 secs]

上記のデータの説明
210.274 及び 214.007・・・JVM が起動してから GC が発生した時間
Full GC ・・・GC の種類を表示します。
「GC」 と表示されれば主に New 領域が対象の Scavenge GC です。
「FULL GC」と表示されれば New 、Old 、Permanent 領域が対象の FULL GC です。

この例では、210.274 のデータは GC 、214.007 のデータで Full GC が発生している。
210.274 のデータ ( 1 行目のデータ ) は上述の説明を参考にし、ここでは、214.007 のデータ ( 2 行目のデータ ) について確認する。

Old 領域の情報
Tenured・・・Old 領域に対するGCを表す。以下の値は Old 領域が対象。
68230K ・・・GC 前のオブジェクトのサイズ ( Old 領域 )
67535K ・・・GC 後のオブジェクトのサイズ( Old 領域 )
(699072K)・・Old 領域のヒープサイズ
1.2545997 secs・・・この Old 領域の GCにかかった時間
ヒープ全体の情報
167459K ・・・GC 前のオブジェクトのサイズ
64535K ・・・GC 後のオブジェクトのサイズ
(1038336K)・・全体のヒープサイズ
1.2547773 secs・・・この GC にかかった時間
Permanent 領域の情報
Perm ・・・Permanent 領域に対するGCを表す。以下の値は Permanent 領域が対象。
53247K ・・・GC 前のオブジェクトのサイズ ( Permanent 領域 )
53247K ・・・GC 後のオブジェクトのサイズ( Permanent 領域 )
(53248K) ・・Permanent 領域のサイズ( Permanent 領域 )

トラブルシューティング参考

http://www.acroquest.co.jp/company/press/2012/img/BoF1-04_DL.pdf

参考
http://www.atmarkit.co.jp/fjava/rensai3/devedge03/devedge03_1.html
http://d.hatena.ne.jp/learn/20090218/p1
http://d.hatena.ne.jp/j7400157/20070716/1184595385
http://www.whitemark.co.jp/tec/java/javagc.html
http://www.deftrash.com/blog/archives/2006/10/jstat_01.html
http://www.javainthebox.net/laboratory/JavaSE6/managementtools/mngtools.html
http://www.atmarkit.co.jp/fjava/rensai4/troublehacks01/troublehacks01_3.html
http://www.ibm.com/developerworks/jp/websphere/library/was/was_nglist/5.html
http://www.atmarkit.co.jp/fjava/rensai4/troublehacks02/troublehacks02_1.html
http://www.insuite.jp/blog/archives/50
http://wall-climb.com/2009/10/12/%E3%82%B3%E3%83%B3%E3%82%AB%E3%83%AC%E3%83%B3%E3%83%88gc%E3%81%AE%E6%B3%A8%E6%84%8F%E7%82%B9/
http://www.atmarkit.co.jp/fjava/rensai4/trouble_knowhow04/01.html
http://www.atmarkit.co.jp/fjava/rensai3/javavm01/javavm01_1.html