読者です 読者をやめる 読者になる 読者になる

ぺーぺーSEのブログ

備忘録・メモ用サイト。

JavaVMのメモリ管理に関するまとめ(Javaヒープ、GC、ダンプ等)

本ブログはJava8(特にMetaspace)に対応していない。

下記にJava8以降に対応した記事を記載する(予定)。

blog.pepese.com


JavaVMのメモリ領域について

JavaVMが管理するメモリ領域について

階層1 階層2 階層3 説明
Javaヒープ JavaVM上で起動するJavaプログラムのリソースを管理する領域。New領域とOld領域で構成される。
 l" New領域 新規オブジェクトと閾値(-XX:MaxTenuringThreshold)未満のオブジェクトが配置される。(Young領域とも呼ばれる)
 l  l" Eden領域 新規のオブジェクトが配置される。
 l  l" From領域 CopyGC(ScavengeGC、マイナーGC)が実行された際に、使用中のオブジェクトはここへコピーされる。(S0やS1とも呼ばれる)
 l  lー To領域 CopyGC(ScavengeGC、マイナーGC)が実行された際に、使用中のオブジェクトはここへコピーされる。(S0やS1とも呼ばれる)
 l" Old領域 New領域で閾値(-XX:MaxTenuringThreshold)を超えたオブジェクトが配置される。(Tenured領域とも呼ばれる)
Permanent領域 クラスやメソッドの情報が格納される領域であり、アプリケーション起動後はほとんど増減しない。
Cヒープ ネイティブ領域。JavaVM自身のリソースを管理する領域。NativeMethod、Javaスレッド自身、(8k以上の)バッファ領域として利用される。
スレッドスタック スレッド毎に保持するスタックの領域。

※「New領域」=「Eden領域」+「From領域」+「To領域」
※From、To領域をあわせてSurvivor領域と呼ぶ。
★Java8からPerm領域が廃止され、MetaSpaceとなっていることに注意!
MetaSpaceについては下記。
http://d.hatena.ne.jp/tanakakns/20141024/1414132381



OutOfMemoryErrorが発生するタイミング

  • New領域が溢れた場合
    • New領域のオブジェクトはある程度の期間存在し続けるとOld領域へ移動される。しかし、移動する条件に達する前のオブジェクトで溢れる場合がある。
      • ※JavaVMはNew領域が溢れそうな際ある程度New領域を広げる処理を行っているようだが、それでも溢れた場合はOutOfMemoryErrorとなる。
  • Old領域が溢れた場合
    • 参照されつづけるオブジェクトが大量に存在する場合に溢れる。
  • Cヒープが溢れた場合

JavaVMのメモリ領域に関するVM引数

オプション 説明
-Xms ヒープ全体の初期値
-Xmx ヒープ全体の最大値
-XX:NewSize New領域の初期値(-Xmnと同じ)
-XX:MaxNewSize New領域の最大値
-XX:PermSize Permanent領域の初期値
-XX:MaxPermSize Permanent領域の最大値
-Xss スレッドスタックの領域(デフォルト512k)

※OSによっては1つのJavaプロセスに割り当てられるヒープに制限がある場合があるので注意が必要
http://docs.oracle.com/cd/E19528-01/820-1613/6nd986vcr/index.html#abeii

ヒープの使用状況を確認する方法

ヒープダンプの統計情報を取得する方法

  • -XX:+HeapDumpOnCtrlBreakを設定しておき、kill -3 [pid]を実行 (Java 1.5の場合)
  • -verbose:gc(-Xloggc:[path_to_file])、-XX:+PrintClassHistogramを設定しておき、kill -3 [pid]を実行
  • jmap -heap:format=b [pid](Java 1.5の場合)
    • 「heap:format=b」はバイナリで出力するという意味
  • jmap -dump:format=b,file=[filePath] [pid] (Java 1.6の場合)
    • 実行できなかった場合は「jmap -F -dump:format=b,file=filename [pid]」で実行してみる
  • jcmd [pid] GC.heap_dump [filePath](Java 7u4以降、Java8まで確認)
  • -XX:+HeapDumpOnOutOfMemoryErrorを設定しておき、OutOfMemoryErrorが発生

※上記の方法で詳細なヒープ情報を取得可能であるが、出力には時間がかかり、また負荷も大きいので注意が必要。

ヒープダンプ解析ツール

  • VisualVM
    • JDKにデフォルトで付いているのでお手軽。「jvisualvm」と打ってみる。
    • アプリケーションのスナップショット(*.apps,*.*)、スレッドダンプ(*.tdump)、ヒープダンプ(*.hprof,*.*)、プロファイルのスナップショット(*.nps,*.npss)を読み込むことができる
  • Eclipse Memory Analyzer(mat)
  • HeapAnalyzer
  • HAT (Heap Analysis Tool)
    • JDKにデフォルトで付いている。「jhat」と打ってみる。

Cヒープの解析

「java.lang.OutOfMemoryError: unable to create new native thread」やスタックトレースの先頭が「Native Method」の場合、Cヒープの領域が枯渇したことが考えられる。
Cヒープはネイティブ領域とも呼ばれ、JVMがJNI等で他のAPI(OSのAPI等)の実行時に使用される。
Cヒープの領域は32bitマシンであれば概ね「2G - Javaヒープ」、64bitマシンであれば概ね「1プロセスが使用できるメモリ量(OSのパラメータ設定) - Javaヒープ」と考えられる。
Cヒープが枯渇した場合の解析は、Linuxであればpmapコマンド(プロセス毎のメモリ使用状況を表示)を使用するとよい。

# pmap -d [PID]

[PID]:   /usr/java/jdk1.x.x_xx/bin/java APP
Address           Kbytes Mode  Offset           Device    Mapping
0000000000400000       4 r-x-- 0000000000000000 0ca:00041 java
0000000000600000       4 rw--- 0000000000000000 0ca:00041 java
00000000022bd000     760 rw--- 0000000000000000 000:00000   [ anon ]
000000009a400000 1667072 rw--- 0000000000000000 000:00000   [ anon ]
00007f3c9a3a4000      12 ----- 0000000000000000 000:00000   [ anon ]
00007f3c9a3a7000    1016 rw--- 0000000000000000 000:00000   [ anon ]
00007f3c9a5a6000      12 ----- 0000000000000000 000:00000   [ anon ]
...
00007fffe3733000      84 rw--- 0000000000000000 000:00000   [ stack ]
00007fffe37ff000       4 r-x-- 0000000000000000 000:00000   [ anon ]
ffffffffff600000       4 r-x-- 0000000000000000 000:00000   [ anon ]
mapped: 6272192K    writeable/private: 2193164K    shared: 2620K
  • Address
    • 仮想メモリ上のアドレス
  • Kbytes
    • 仮想メモリ上のサイズ
  • Mode
    • メモリ属性
  • Offset
    • ファイルのオフセット
  • Device
    • デバイス名 (major:minor)
  • Mapping
    • file backing the map, or '[ anon ]' for allocated memory, or '[ stack ]' for the program stack

※「オフセット」とは・・・基準となるある点からの相対的な位置のこと
※ファイルシステム内のどの名前付きオブジェクトまたはファイルにも関連しないメモリは [ anon ] となる

# pmap -x [PID]
[PID]:   /usr/java/jdk1.x.x_xx/bin/java APP
Address           Kbytes     RSS   Dirty Mode   Mapping
0000000000400000       4       4       0 r-x--  java
0000000000600000       4       4       4 rw---  java
000000000203c000     868     740     740 rw---    [ anon ]
000000009a400000 1667072 1396736 1396736 rw---    [ anon ]
00007fb3f9051000      12       0       0 -----    [ anon ]
00007fb3f9054000    1016     108     108 rw---    [ anon ]
00007fb3f9152000      12       0       0 -----    [ anon ]
...
00007fb51bcfc000       4       4       4 rw---  ld-2.12.so
00007fb51bcfd000       4       4       4 rw---    [ anon ]
00007fff53896000      84      32      32 rw---    [ stack ]
00007fff539ff000       4       4       0 r-x--    [ anon ]
ffffffffff600000       4       0       0 r-x--    [ anon ]
----------------  ------  ------  ------
total kB         6328584 1658056 1646376
  • RSS
    • 常駐サイズ(resident set size in kilobytes)
  • Dirty
    • dirty pages (both shared and private) in kilobytes

OutOfMemoryErrorが発生した際に情報を取得できるように下記の設定を加える。

  • 「-XX:OnOutOfMemoryError」
    • (例)-XX:OnOutOfMemoryError="/bin/kill -ABRT %p"
  • 「-XX:OnError」
    • (例)-XX:OnError="pmap -d %p"

以上の情報を元に以下のパターンになるか確認してみる。

1.スレッドの増加

スレッドはスタック領域としてCヒープを消費する。

32bit OS/64bit OS スレッド当たりのスタック領域サイズ
32bit OS 512 Kbytes
64bit OS 1 Mbytes

スレッドは、アプリケーションから明示的に作成する場合だけでなく、Java APIから暗黙的に作成する場合もある。
スレッドダンプを取得したり、pmapの結果から1スレッドサイズのメモリが過剰に確保されていないか確認する。

2.大容量のI/O

ファイル入出力や通信関連のAPIは、最終的にはネイティブなシステムコールで実現されている。
入出力対象データは、いったんCヒープにコピーされた後、システムコールに渡される。
コピー先のバッファは、8Kbytes未満の場合は当該スレッドのスタック上に取られることになるが、それを超える場合は、Cヒープに一時的に確保される。
I/Oが完了すれば、その領域は解放される。

3.圧縮ライブラリで使用する領域

java.util.zipパッケージのDeflaterクラスやInflaterクラスでは、コンストラクタの処理でCヒープ領域を確保する。
確保されたCヒープ領域は、オブジェクトがGCされてfinalize()が実行されるか、end()メソッドを明示的に実行するまでは解放されない。

4.バッファオブジェクトで使用する領域

java.nio.ByteBufferクラスのallocateDirectメソッドや、java.nio.channels.FileChannelクラスのmapメソッドによりBufferオブジェクトを生成する場合、引数で指定したサイズの領域をmmapシステムコールにより確保する。

※公式トラブルシュート(http://www.oracle.com/technetwork/java/javase/tsg-vm-149989.pdf

プロファイラ

オブジェクトの生成、GC等、JVMの挙動をトレースする。アプリケーションを動作させつつ、増加していくオブジェクトを探したり、スタックトレースを確認したり等の調査が可能。
パフォーマンスが悪化するため、運用環境では通常使用できない。
メモリリークやメモリの大量消費の調査の場合、まず問題の再現方法を突き止めた上で、開発/検証環境でプロファイラを使用して、再現方法を実施して、増加したオブジェクトを解析する。
・NetBeans Profiler

その他VM引数

オプション 説明
-d32 32 ビット環境でプログラムを実行(デフォルト)
-d64 64 ビット環境でプログラムを実行
-client HotSpot VMのクライアントモードを有効化
-server HotSpot VMのサーバーモードを有効化
-XX:+UseCompressedOops Java オブジェクトヒープのサイズが32ギガバイト未満の場合に、64 ビットJREのパフォーマンスを向上させる(★)

※-d64を使用すると -server オプションが暗黙的に有効になり、-clientオプションは無視される。
※HotSpot VMは-clientと-serverオプションによりクライアント用VMとサーバ用VMを使い分けることができる。
※HotSpotはクライアント版、サーバ版と呼ばれる二つの互換版からなる。クライアント版は必要不可欠なクラスやメソッドのみを素速くロードしコンパイルするようチューニングする。サーバ版は、よりゆっくりロードを行うが、より高性能な高度に最適化されたJITコンパイル結果を産出することに、より尽力する。
★64ビットなアドレス空間だと、論理的には16エクサバイトのメモリ空間を扱えるくらい広大。Javaの場合は無駄にオブジェクトポインタ用に使用する管理領域のメモリ使用量が32ビットのそれに比べてとても増えてしまう。なのでオブジェクトポインタだけを32ビットにして、その分、指定可能な最大のjavaヒープサイズを32ギガバイトに抑えて、オブジェクトポインタのメモリフットプリントを削減して効率的にメモリを使用する。


GCについて

GCが発生するタイミング

  • ヒープメモリ中に新規オブジェクトを作成するために必要な空き領域が足りなくなったとき
  • プログラム中でSystem.gc()が実行されたとき
    • 「-XX:+DisableExplicitGC」を指定することにより、無効化することができる
  • JVMで実行する処理がなくなってアイドル状態になったとき
  • 下記オプションで設定された定期的なGC

GCの動き

① Eden領域が一杯になるとCopyGC(ScavengeGC、マイナーGC)が実行される。このとき、まだ使用中のオブジェクトはEden領域からTo領域へ移動され、使用されていないオブジェクトは削除される。
② Eden領域が一杯になるとCopyGC(ScavengeGC、マイナーGC)が実行され、今度はEden・To領域で使用中のオブジェクトはFrom領域へコピーされ、使用されていないオブジェクトは削除される。
③ Eden領域が一杯になるとCopyGC(ScavengeGC、マイナーGC)が実行され、今度はEden・From領域で使用中のオブジェクトはTo領域へコピーされ、使用されていないオブジェクトは削除される。
④ ②③が繰り返される。この間、CopyGC(ScavengeGC、マイナーGC)によってFrom⇔To間でコピーされたオブジェクトはコピー回数がカウントされ、閾値を超えるとOld領域へコピーされる。
⑤ コピー回数の閾値は「-XX:MaxTenuringThreshold」で設定する。
※Survivor(From、To)領域があふれてもOld領域にオブジェクトが移動する。

Javaはどのように動くのか0図解でわかるJVMの仕組み
http://gihyo.jp/dev/serial/01/jvm-arc

GCに関するVM引数

オプション 説明
-XX:SurvivorRatio=[n] Eden領域のサイズをFromまたはTo領域のサイズで割った値(FromとTo領域は同じサイズ)
-XX:MaxTenuringThreshold New領域において、オブジェクトがマイナーGCを何回超えて生き残ると、Old領域に移動するかのしきい値の最大値(実際のしきい値は、1からMaxTenuringThreshold(015)の範囲で動的に決定される)
-XX:TargetSurvivorRatio Survivor領域がいっぱいと判断される使用率
-XX:+DisableExplicitGC プログラム中で強制的にFull GCを起こすSystem.gc()を処理を無効化する
-Dsun.rmi.dgc.server.gcInterval 定期Full GCの設定(JDK6デフォルト3600000(1時間))
-Dsun.rmi.dgc.client.gcInterval 定期Full GCの設定(JDK6デフォルト3600000(1時間))

かつてこのページでは「-XX:MaxTenuringThreshold」は「32程度に設定」と書いていたが、いつぞやから最大値が「15」となっており、これより大きい値を指定するとJavaプロセスが起動しなくなることに注意!。(1.8.0_31にて確認)

GCログに関するVM引数

オプション 説明
-verbose:gc GCログ出力を有効化(標準出力)。
-Xloggc:[file_path] GCログをファイルへ出力。
(例)-Xloggc:C:\gc.log、-Xloggc:/tmp/gc.log
(例)「-Xloggc:/var/log/gc.`date '+%Y-%m-%d'`.log」とすると日付付きになる
-XX:+PrintGCTimeStamps GCログにタイムスタンプ(Java起動時からの経過時間)を出力
-XX:+PrintGCDateStamps GCログのタイムスタンプを時刻で出力
(例)2012-02-21T23:24:35.564+09000
-XX:+PrintGCDetails GCログを詳細に出力(New領域とJavaヒープそれぞれがどれだけ減ったか出力される)
-XX:+PrintClassHistogram SIGQUITシグナル受信時にヒープ統計情報を出力(出力時に強制的にFull GCが発生)。
-verbose:gcと併用必須。なお、SIGQUITシグナルを送信するには、kill -3 [pid]を実行すればよい
-XX:+HeapDumpOnOutOfMemoryError OutOfMemoryError発生時にヒープダンプを出力
-XX:+UseGCLogFileRotation GCログのローテンションを有効化。「-XX:NumberOfGCLogFiles=n -XX:GCLogFileSize=size」も指定。
-XX:+PrintGCApplicationStoppedTime GCに使用した時間を出力する。StopTheWorldの時間もわかる。

※シグナル(signal)とは、UNIX系オペレーティングシステムにおいてプロセス間で非同期イベントの発生を伝える機構。
※SIGQUITは終了のシグナル。通常、端末からの終了キー(CTRL + \)で発生する。

GCログのグラフ化

GCの種類

Java7までのCGの種類と設定方法は以下。

オプション 説明
-XX:+UseSerialGC New領域、Old領域ともに、GCを単一スレッドで実行。
-XX:+UseParallelGC New領域では、GCを複数スレッドで実行。Old領域が不足したら、Full GCを単一スレッドで実行。
-XX:+UseParallelGC -XX:+UseParallelOldGC New領域では、GCを複数スレッドで実行。Old領域が不足したら、Full GCを複数スレッドで実行。
-XX:+UseConcMarkSweepGC New領域は-XX:+UseParallelGCと同様の処理。Old領域でCMS GCを実行。コンカレントGC。CMS GCでもメモリが不足する場合は、Full GCを実行。
-XX:+UseConcMarkSweepGC -XX:+CMSIncrementalMode -XX:+UseConcMarkSweepGCをインクリメンタル・モードで実行。
-XX:+UseG1GC Java 7新機能のG1 GCを実行。Javaヒープを細かく細分化し、New領域やOld領域などを割り当てる方式。

通常のエンタープライズシステムであればコンカレントGCで十分。
しかし、Javaヒープが数十GBともなるとG1GCの検討が必要。
G1CGではヒープ領域の設定がここまでの説明と異なるため注意が必要。(未調査)

コンカレントGC

J2SE 1.4から使用できるGC方式で、FullGCをアプリケーションスレッドと並列に実行できる。

オプション 説明
-XX:+UseConcMarkSweepGC コンカレントGCの有効化。
-XX:+CMSParallelRemarkEnabled Full GCのRemarkフェイズをマルチスレッドで実行。整合性の調査を複数スレッドで並行に実施する。
-XX:+UseParNewGC マイナーGCをマルチスレッドで実行 。
-XX:+CMSClassUnloadingEnabled コンカレントGCによるクラスのアンロードを有効にする。
-XX:+CMSPermGenSweepingEnabled なにこれわからん
-XX:+CMSIncrementalMode インクリメンタルGCを有効にする。インクリメンタルGCとは、GC処理を中断可能にして、タイムスライス(CPU 時分割)でアプリケーションと平行して処理できるようにしたもの。
-XX:+CMSIncrementalPacing なにこれわからん
-XX:CMSIncrementalDutyCycleMin なにこれわからん
-XX:CMSInitiatingOccupancyFraction=[n] コンカレントGCを開始する場合のOld領域のオブジェクトの割当の割合を指定。70程度で必ず指定したほうがよい。


スレッドダンプについて

ヒープ、GCチューニングの観点ではないが、アプリケーションの応答がとまってしまったらとりあえず取得するのがよい。
スレッドのデッドロックが発生していないか、大量の待ち行列が発生していないか等がわかる。

スレッドダンプの取得方法

  • kill -3 [pid]で標準出力に出力される。
    • Tomcatをデフォルトで使用している場合は、標準出力・標準エラー出力はCatalina.outへリダイレクトされているため、Catalina.outへ出力される。
  • kill -3 [pid]を使用できない場合は、「jstack」や「jcmd」を使用する。
    • jstack [pid]
    • jcmd [pid] [filename](Java 7u4以降)
  • 環境によってオプションを追加
    • 「-XX:+UnlockDiagnosticVMOptions -XX:LogVMOutput -XX:LogFile=[file]」

スレッドダンプの解析

スレッドダンプは下記のように出力される。

Full thread dump Java HotSpot(TM) 64-Bit Server VM (20.6-b01 mixed mode):

"pool-3-thread-13" prio=10 tid=0x00007f9828173800 nid=0x3be3 waiting on condition [0x00007f978e5e4000]
   java.lang.Thread.State: WAITING (parking)
	at sun.misc.Unsafe.park(Native Method)
	- parking to wait for  <0x00000000d809f248> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
	at java.util.concurrent.locks.LockSupport.park(LockSupport.java:156)
	at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:1987)
	at java.util.concurrent.LinkedBlockingDeque.takeFirst(LinkedBlockingDeque.java:440)
	at java.util.concurrent.LinkedBlockingDeque.take(LinkedBlockingDeque.java:629)
	at java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:947)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:907)
	at java.lang.Thread.run(Thread.java:662)

また、Linuxで「ps -L aux」を実行すると下記が得られる。

USER       PID   LWP %CPU NLWP %MEM    VSZ   RSS TTY      STAT START   TIME COMMAND
tomcat    7424  7424  0.0   97 39.1 8168216 2790396 ?     Sl   Sep16   0:00 /usr/java/jdk1.6.0_xx/bin/java -Djava...
tomcat    7424  7430  0.0   97 39.1 8168216 2790396 ?     Sl   Sep16   0:00 /usr/java/jdk1.6.0_xx/bin/java -Djava...

「ps -L aux」で取得したLWPはスレッド番号を意味し、これを16進数に変換すると、スレッドダンプのnidと等しくなる。
この結果により、どのスレッドでCPUやメモリリソースをどれだけ使用しかいるか追跡できる。
参考
http://d.hatena.ne.jp/nashuaki/20110415/1302872031

スレッドダンプの解析ツール

VM引数のまとめ

まとめると以下くらいの感じでよいのでは。
Webアプリ(32bit/Java8未満)を想定。

-d32
-server
-Xms1024m
-Xmx1024m
-XX:NewSize=384m
-XX:MaxNewSize=384m
-XX:PermSize=128m
-XX:MaxPermSize=128m
-XX:+DisableExplicitGC
-XX:+UseConcMarkSweepGC
-XX:+CMSParallelRemarkEnabled
-XX:CMSInitiatingOccupancyFraction=70
-XX:+UseParNewGC
-XX:SurvivorRatio=8
-XX:MaxTenuringThreshold=15
-XX:TargetSurvivorRatio=80
-Xloggc:/[ログ出力先]/gc.`date '+%Y-%m-%d'`.log
-XX:+PrintGCDetails
-XX:+PrintGCTimeStamps
-XX:+PrintGCDateStamps
-XX:+PrintClassHistogram
-XX:+HeapDumpOnOutOfMemoryError
-XX:HeapDumpPath=/[ヒープダンプ出力先]/java.hprof

Webアプリ(64bit/Java8)を想定。

-d64
-server
-XX:+UseCompressedOops
-Xms1024m
-Xmx1024m
-XX:NewSize=384m
-XX:MaxNewSize=384m
-XX:MaxMetaspaceSize=128m
-XX:CompressedClassSpaceSize=128m
-XX:+DisableExplicitGC
-XX:+UseConcMarkSweepGC
-XX:+CMSParallelRemarkEnabled
-XX:CMSInitiatingOccupancyFraction=70
-XX:+UseParNewGC
-XX:SurvivorRatio=8
-XX:MaxTenuringThreshold=15
-XX:TargetSurvivorRatio=80
-Xloggc:/[ログ出力先]/gc.`date '+%Y-%m-%d'`.log
-XX:+PrintGCDetails
-XX:+PrintGCTimeStamps
-XX:+PrintGCDateStamps
-XX:+PrintClassHistogram
-XX:+HeapDumpOnOutOfMemoryError
-XX:HeapDumpPath=/[ヒープダンプ出力先]/java.hprof

スループットを向上させるチューニング(ページ末公式参照)

-d64 -server -XX:+AggressiveOpts -XX:+UseLargePages -Xmn10g  -Xms26g -Xmx26g

レスポンス時間を短縮するチューニング(ページ末公式参照)

-d64 -XX:+UseG1GC -Xms26g Xmx26g -XX:MaxGCPauseMillis=500 -XX:+PrintGCTimeStamps


トラブル解決、チューニング方法

トラブル解決フロー

  • 問題発生 → 基本データ分析 →GCログ解析
    • GCが頻発している → Heapチューニング → GCログ解析
      • GCが頻発している → オブジェクトのプロファイリング
        • オブジェクトに問題あり → ソース修正
        • オブジェクトに問題なし → OS,ミドルウェアの設定値再確認
      • GCが頻発していない → 解決!!
    • GCが頻発していない → CPUの使用率確認
      • CPUがボトルネックである → メソッドのプロファイリング(特定の処理の重いメソッドが何度も呼ばれていないか?)
        • メソッドに問題あり → ソース修正
        • メソッドに問題なし → OS,ミドルウェアの設定値再確認
      • CPUがボトルネックではない → スレッドダンプ解析
        • スレッドダンプ問題あり → プールオブジェクト解析
          • プールオブジェクト問題あり → OS,ミドルウェアの設定値再確認
          • プールオブジェクト問題なし → ソース修正
        • スレッドダンプ問題なし → メソッドのプロファイリング(特定の処理の重いメソッドが何度も呼ばれていないか?)
          • メソッドに問題あり → ソース修正
          • メソッドに問題なし → OS,ミドルウェアの設定値再確認
1.Javaヒープ領域がOutOfMemoryとなる場合

【応急処置】
-Xms、-Xmxを指定し、OutOfMemoryErrorが発生しないようにヒープを広げる。
【原因調査】
GCログを取得し、ヒープでのメモリリークが発生していないか確認する。

  1. GCログを侍やGCViewer、Excel等でグラフ化して確認する。
  2. グラフがFull GCを跨って、右肩上がりになっている場合は、メモリリークが発生している可能性が高い。
  3. リーク箇所を発見するには、ヒープ統計情報やヒープダンプを数回取得して比較して、Full GCを経ても増加し続けているオブジェクトを探す。
  4. 怪しいオブジェクトが見つかれば、NetBeans Profiler等を使用して、オブジェクトの使用箇所を探し、オブジェクト参照を追跡する。
2.ヒープチューニング方法

【方針】

  1. Full GC実行時間を最小にするために、OutOfMemoryErrorが発生しないサイズでなるべく小さいサイズを-Xms、-Xmxに指定する。
  2. 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 15
-XX:TargetSurvivorRatio 80-90程度

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

3.マイナーGCが1秒を超える場合

New領域が大きすぎる可能性があるので、-XX:NewSize、-XX:MaxNewSizeを減らす。
CPUが複数ある(マルチコアを含む)場合は、-XX:+UseParallelGC オプションでパラレルGCを有効にする。
-XX:+UseParallelGC マイナーGCをマルチスレッドで実行

4.Full GCが1秒を超える場合

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

  1. アプリケーションでメモリを使いすぎていないか確認し、使いすぎている場合は修正する。
    • メモリを多く消費する処理を特定するには、運用環境で、jstat -gcutilやjconsoleを使用してヒープの各領域の使用状況を監視し、使用率がドカッとあがったときに実行された処理を、アクセスログから突き止める。(ある程度絞れれば、あとは開発/検証環境で突き止める)あとは、コード解析を行い、修正する。
  2. セッションタイムアウト時間の確認。
    • 不必要に長すぎないか確認。
  3. コンカレント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をマルチスレッドで実行 。
5.アプリケーションの応答が停止(フリーズ)した場合

スレッドダンプを取得する。
kill -3 [pid]を使用する。
kill -3 [pid]を使用できない場合は、「jstack」を使用する。
「侍」等を使用してダンプファイルを解析する。

6.StackOverflowError と出る場合

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

GCログの見方

  • パターン1
    • 【説明】ログを出す設定だけ
    • 【オプション】-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]
  • パターン2
    • 【説明】ログ出力とタイムスタンプ(起動からの経過時間)出力を設定
    • 【オプション】-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]
  • パターン3
    • 【説明】ログ出力を詳細に設定
    • 【オプション】-verbose:gc -XX:+PrintGCTimeStamps
    • 【ログ】
[GC [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ログのオプションパターンと見方
  • (例1)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 にかかった時間
  • (例2)
-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 領域 )



Javaアプリトラブルシューティング神サイト

http://www.oracle.com/technetwork/java/javase/index-137495.html

参考

java - Java アプリケーション起動ツール(公式VM引数Doc for Windows)

http://docs.oracle.com/javase/jp/7/technotes/tools/windows/java.html

java - Java アプリケーション起動ツール(公式VM引数Doc for Linux and Solaris)

http://docs.oracle.com/javase/jp/7/technotes/tools/solaris/java.html
Javaのヒープ・メモリ管理の仕組み
http://www.atmarkit.co.jp/fjava/rensai3/devedge03/devedge03_1.html
Javaメモリ、GCチューニングとそれにまつわるトラブル対応手順まとめ
http://d.hatena.ne.jp/learn/20090218/p1
GCをみる
http://d.hatena.ne.jp/j7400157/20070716/1184595385
ガーベジ・コレクション:GC ( Garbage Collection ) についての簡単な説明と調査方法
http://www.whitemark.co.jp/tec/java/javagc.html
管理に使える便利なツール
http://www.javainthebox.net/laboratory/JavaSE6/managementtools/mngtools.html
Webアプリの問題点を「見える化」する7つ道具
http://www.atmarkit.co.jp/ait/articles/0703/22/news138_3.html
WebSphereべからず集: 第5回 「System#gc()を実行している」
http://www.ibm.com/developerworks/jp/websphere/library/was/was_nglist/5.html
“Stop the World”を防ぐコンカレントGCとは?
http://www.atmarkit.co.jp/fjava/rensai4/troublehacks02/troublehacks02_1.html
GCとキャッシュの悩ましい関係
http://www.insuite.jp/blog/archives/50
コンカレントGCの注意点
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/
CMSの見方
https://gist.github.com/relax-more/5142298
調査の難しい「OutOfMemoryError」事例、5選
http://www.atmarkit.co.jp/fjava/rensai4/trouble_knowhow04/01.html
Hotspot VMの基本構造を理解する
http://www.atmarkit.co.jp/fjava/rensai3/javavm01/javavm01_1.html
第4回 チューニングに使えるJava性能監視ツール
http://thinkit.co.jp/story/2011/03/25/2054
Java、メモリリークを追跡して修正する方法
http://news.mynavi.jp/news/2013/05/09/137/index.html
http://news.livedoor.com/article/detail/7659494/
Javaガベージコレクションのエッセンス
http://www.infoq.com/jp/articles/Java_Garbage_Collection_Distilled