OutOfMemoryError の調べ方

OutOfMemoryError (以下 OOME)が起こったときにお手上げ状態にならないためにも、 Java のメモリ管理の仕組みとか、 OOME が起こったときの調査方法とかを調べる。

環境

OS

Windows 7

Java

> java -version
java version "1.8.0_74"
Java(TM) SE Runtime Environment (build 1.8.0_74-b02)
Java HotSpot(TM) 64-Bit Server VM (build 25.74-b02, mixed mode)

Java 8 で、 Oracle の JVM を前提とした話です。

Java のメモリ管理

これを知っておかないと、 OOME が起こっても、メモリ内で何が起こっていて、どこを調査すべきで、どのように対処したらいいのかが判断できない。
なので、まずは、そもそも Java がどうやってメモリを管理しているのかを知る。

しかし、実際調べてみたら予想通りというかなんというか、量が多くなってしまった。
なので、個々の用語の説明は末尾の 用語集 に押し込めたので、ここではざっくりとした概要だけ記載する。

メモリの構造

超ざっくりとした、メモリ構造を表した図。

おおきく、ヒープ（Heap）領域とネイティブ（Native）領域の２つの領域がある。

ヒープは Java プログラムが使う領域で、プログラム上で生成したオブジェクトは、このヒープ領域に配置される。
一方、ネイティブ領域は JVM が動くのに必要なメモリやスレッドのスタックを管理するのに使用される。

ガベージコレクション

ガベージコレクション（以下 GC）とは、ヒープ領域に存在する使われていないオブジェクトを見つけ出し、自動で削除してくれる仕組みを言う。

一口に GC と言っても、

• Minor GC
• Major GC
• Full GC
• Scavenge GC
• Copy GC
• Mark & Sweep GC
• Serial GC
• Parallel GC
• Concurrent GC

とかいっぱいあって、初見だとわけがわからなくなる。

この辺の違いを理解していないと、いざメモリの状態や発生した GC の情報とかを見ても、意味が分からなく途方に暮れてしまう。
なので、これらの違いについても知っておいたほうが良いと思う。

個々の意味は 用語集 にまとめたので、そちらを参照のこと。

OOME の種類

OOME は様々な要因で発生する。

• ヒープ領域が足りなくなった。
• Permanent 領域が足りなくなった（Java 7 まで）
• Full GC が高頻度で実行された。
• スレッドを大量に作りすぎてネイティブメモリが足りなくなった。
• etc...

今回は、なんだかんだで開発してて一番遭遇する頻度が多いと（勝手に）思っている、ヒープが足りないケースに絞って調査方法と対処方法を勉強する。

※今後、単に OOME と書いた場合、それはヒープ不足を由来とする OOME のことを指します。

OOME が発生する要因

おおまかに言うと、以下のいずれかになる。

1. 単純にメモリが足りていない。
2. プログラムに問題があり、メモリの解放忘れや不要なオブジェクトの大量生成などが発生している。

前者なら、単純にヒープ領域を増やせばいい。
（厳密には、無駄にオブジェクトを保持していて改良の余地があるかもしれないが、今回はそこまでは考えない）

後者の場合は、問題箇所を特定してプログラムを改修しなければ、どんなにヒープサイズを増やしても意味が無い（場合によっては解決するかもしれないけど、根本解決にはならない）。

発生した OOME がどちらを原因としてるかを調べるためには、アプリケーションのメモリの状態を調査しなければならない。

問題の切り分け方

問題なさそうなヒープ

• ヒープの使用量が同じ高さの波状になっている。
• アプリケーションは、動いている限り少しずつだがヒープを消費していく。
• しかし、ある程度するとマイナーガベージコレクションが発動する。
  • すると、使っていないオブジェクトは削除されるので、その分の領域が確保されることになる。
• グラフが山になるのは、このマイナーガベージコレクションを繰り返しているため。
• GC 後のメモリ領域が一定ということは、不要なオブジェクトはちゃんと毎回解放できていることを表している。

単純にサイズが足りなさそう

• 起動時のオプションでヒープサイズを増やした結果、↑の問題なさそうなヒープの形に落ち着いた場合、単純にヒープサイズが足りていなかったという可能性がある。
• ただし、「無駄にオブジェクトを生成していた」という可能性もあるので、少なくとも OOME が発生した場所は特定しておいたほうがいいと思う。

メモリリークっぽいヒープ

• ヒープの使用量が右肩上がりになっている。
• 何回か GC が発動しているが、そのたびに最低値が上昇していっている。
  • 上昇した分だけ、開放されていないオブジェクトが存在しているということを表している。
• こうなると、どこかに解放漏れのオブジェクトがあることを疑った方がいい。

バカでかいオブジェクトを作った

• OOME が発生するまではヒープサイズは安定していたのに、いきなり爆発的にヒープサイズが大きくなって落ちたような状態。
• バカでかいオブジェクトをいきなり生成（ファイルを読み込んでメモリ上に全て展開したとか）したせいで、メモリが足りなくなり落ちるというケース。
• この場合は、 OOME が発生した瞬間のヒープダンプを取得しておいて、原因箇所を特定し、必要に応じてロジックを修正する。
  • メモリリークしないのであれば、ヒープサイズを増やして対応というのもあるかもしれない。

調査に利用できるツール類の使い方

逆引き

ヒープ使用量の変化を確認する

• jconsole
• GC ログと GC Viwer
• jstat
• HeapStats
• jvisualvm

OOME の発生場所特定する

• ヒープダンプの取得
  • jcmd
  • jmap
  • OOME が発生したときにヒープダンプを取得する
• HeapStats
• jvisualvm
• Eclipse Memory Analyzer

jcmd

JDK7 からに付属しているツール。コマンドラインから実行する。
JDK7 以降なら、基本はこのコマンドを使う。

JVM を指定してメモリ消費量の多いもの順にクラスをリストアップしたりできる。

基本構文

> jcmd <pid | main class> <command> [options]

例

> jcmd 1234 GC.heap_dump heap.hprof

• pid または main class は必須だが、特に指定できるプロセスが無いのであれば 0 を指定できる。
• 0 を指定すると、現在実行されている全ての Java プロセスが対象になる。
• 厳密には、実行されている JVM のバージョンごとに指定できるコマンドが異なる可能性があるので、プロセスごとに pid を指定してヘルプや実行できるコマンド一覧を確認したほうが確実。

使用できるコマンドを一覧で確認する

> jcmd 0 help
4136:
The following commands are available:
JFR.stop
JFR.start
JFR.dump
JFR.check
VM.native_memory
VM.check_commercial_features
VM.unlock_commercial_features
ManagementAgent.stop
ManagementAgent.start_local
ManagementAgent.start
GC.rotate_log
Thread.print
GC.class_stats
GC.class_histogram
GC.heap_dump
GC.run_finalization
GC.run
VM.uptime
VM.flags
VM.system_properties
VM.command_line
VM.version
help

For more information about a specific command use 'help <command>'.

コマンドのヘルプを確認する

> jcmd 0 help GC.heap_dump
4136:
GC.heap_dump
Generate a HPROF format dump of the Java heap.

Impact: High: Depends on Java heap size and content. Request a full GC unless the '-all' option is specified.

Permission: java.lang.management.ManagementPermission(monitor)

Syntax : GC.heap_dump [options] <filename>

Arguments:
        filename :  Name of the dump file (STRING, no default value)

Options: (options must be specified using the <key> or <key>=<value> syntax)
        -all : [optional] Dump all objects, including unreachable objects (BOOLEAN, false)

現在実行されている Java プロセスを表示する

> jcmd -l
4136
12748 sun.tools.jcmd.JCmd -l

• jps の代わりにこちらもつかえる。

システムプロパティを全て出力する

> jcmd 12636 VM.system_properties
12636:
#Mon Mar 07 23:51:16 JST 2016
java.vendor=Oracle Corporation
sun.java.launcher=SUN_STANDARD
（以下略）

VM のフラグを全て出力する

> jcmd 12636 VM.flags
12636:
-XX:CICompilerCount=4 -XX:InitialHeapSize=268435456 -XX:MaxHeapSize=536870912 -XX:MaxNewSize=178782208 -XX:MinHeapDeltaBytes=524288 -XX:NewSize=89128960 -XX:OldSize=179306496 -XX:+PrintGC -XX:+UseCompressedClassPointers -XX:+UseCompressedOops -XX:+UseFastUnorderedTimeStamps -XX:-UseLargePagesIndividualAllocation -XX:+UseParallelGC

クラス・ヒストグラムを出力する

> jcmd 12636 GC.class_histogram > class_histogram.txt

class_histogram.txt

12636:

 num     #instances         #bytes  class name
----------------------------------------------
   1:         63670        5482832  [C
   2:          5782        1799000  [B
   3:         19643        1728584  java.lang.reflect.Method
   4:         63355        1520520  java.lang.String
   5:         11215        1253456  java.lang.Class
   6:         36380        1164160  java.util.HashMap$Node
   7:         13166        1138904  [Ljava.util.HashMap$Node;
   8:         18932         757280  java.util.LinkedHashMap$Entry
   9:         22985         735520  java.util.concurrent.ConcurrentHashMap$Node
  10:         11475         718880  [Ljava.lang.Object;
（以下略）

• クラスごとにメモリ消費量の多いもの順に一覧を表示する。
  • [C と [B は、たぶん char と byte の配列
• VM への負荷は大きい。

ヒープダンプを取得する

> jcmd 12636 GC.heap_dump heapdmp.hprof

• コマンドの引数に出力先のファイル名を指定する。
• 相対パス指定した場合、対象の VM のカレントフォルダが起点になるので注意（jcmd を実行している場所ではない）。
• VM への負荷は大きい。
• jmap コマンドでも取得できるけど、 jcmd を使う方が推奨らしい。
• デフォルトでは、 Full GC が実行されたうえでダンプが取得される。

GC を実行させずにヒープダンプを取得する

> jcmd 12636 GC.heap_dump -all heapdmp.hprof

• -all オプションをつけると、 GC を実行させずに、そのままのヒープダンプを取得できる。

全てのスレッドのスタックトレースを出力する

> jcmd 12636 Thread.print > ThreadPrint.txt

ThreadPrint.txt

12636:
2016-03-08 00:04:45
Full thread dump Java HotSpot(TM) 64-Bit Server VM (25.74-b02 mixed mode):

"cached5" #125 prio=5 os_prio=0 tid=0x0000000060209000 nid=0x2e7c waiting on condition [0x000000006610e000]
   java.lang.Thread.State: WAITING (parking)
	at sun.misc.Unsafe.park(Native Method)
	- parking to wait for  <0x00000000e0432a40> (a java.util.concurrent.SynchronousQueue$TransferStack)
	at java.util.concurrent.locks.LockSupport.park(LockSupport.java:175)
	at java.util.concurrent.SynchronousQueue$TransferStack.awaitFulfill(SynchronousQueue.java:458)
	at java.util.concurrent.SynchronousQueue$TransferStack.transfer(SynchronousQueue.java:362)
（以下略）

• VM への影響は中程度。

jmap

JDK に付属しているツール。JDK 6 以前の VM からヒープダンプを取ったりしたい場合はこちらを使う。
（Java 7 以上は jcmd を使う）

基本構文

> jmap [option] <pid>

ヒープダンプを取得する

> jmap -dump:format=b,file=my_heap_dump.hprof 5192

• -dump:format=b は固定。
• file=<ファイルパス> で、ダンプファイルの出力先を指定する。

ヒープ領域の情報を出力する

> jmap -heap 5192
Attaching to process ID 5192, please wait...
Debugger attached successfully.
Server compiler detected.
JVM version is 25.74-b02

using thread-local object allocation.
Parallel GC with 8 thread(s)

Heap Configuration:
   MinHeapFreeRatio         = 0
   MaxHeapFreeRatio         = 100
   MaxHeapSize              = 536870912 (512.0MB)
   NewSize                  = 89128960 (85.0MB)
   MaxNewSize               = 178782208 (170.5MB)
   OldSize                  = 179306496 (171.0MB)
   NewRatio                 = 2
   SurvivorRatio            = 8
   MetaspaceSize            = 21807104 (20.796875MB)
   CompressedClassSpaceSize = 1073741824 (1024.0MB)
   MaxMetaspaceSize         = 17592186044415 MB
   G1HeapRegionSize         = 0 (0.0MB)

Heap Usage:
PS Young Generation
Eden Space:
   capacity = 128974848 (123.0MB)
   used     = 18571016 (17.71070098876953MB)
   free     = 110403832 (105.28929901123047MB)
   14.398943893308562% used
From Space:
   capacity = 21495808 (20.5MB)
   used     = 0 (0.0MB)
   free     = 21495808 (20.5MB)
   0.0% used
To Space:
   capacity = 20971520 (20.0MB)
   used     = 0 (0.0MB)
   free     = 20971520 (20.0MB)
   0.0% used
PS Old Generation
   capacity = 241172480 (230.0MB)
   used     = 26622312 (25.389015197753906MB)
   free     = 214550168 (204.6109848022461MB)
   11.038702259893002% used

21472 interned Strings occupying 1915464 bytes.

ヒストグラムを出力する

> jmap -histo 5192 > histogram.txt

histogram.txt

 num     #instances         #bytes  class name
----------------------------------------------
   1:         11178       17514456  [I
   2:         71332        6582488  [C
   3:          6461        2612328  [B
   4:         19673        1731224  java.lang.reflect.Method
   5:         67223        1613352  java.lang.String
   6:         11220        1254040  java.lang.Class
   7:         36592        1170944  java.util.HashMap$Node
   8:         13409        1154280  [Ljava.util.HashMap$Node;
   9:         17503         980168  java.util.concurrent.ConcurrentHashMap$ValueIterator
  10:         13625         841032  [Ljava.lang.Object;
  11:         18958         758320  java.util.LinkedHashMap$Entry
  12:         22981         735392  java.util.concurrent.ConcurrentHashMap$Node
  13:         13674         656352  java.util.HashMap
  14:         10003         560168  java.util.LinkedHashMap
  15:         28543         456688  java.lang.Object
  16:          6327         455544  java.lang.reflect.Field
（以下略）

jstat

JDK に付属しているコマンドツール。
JVM の統計情報をモニターできる。試験的なもので、サポート対象外らしい。

基本

構文（簡易版）

> jstat <startOption> <pid> [interval[s|ms]] [count]

例

> jstat -gc 1776
 S0C    S1C    S0U    S1U      EC       EU        OC         OU       MC     MU    CCSC   CCSU   YGC     YGCT    FGC    FGCT     GCT
19456.0 21504.0 17170.9  0.0   131584.0 52202.1   182784.0   20159.6   49792.0 48738.2 6528.0 6377.2      6    0.079   2      0.118    0.197

• 監視したい内容ごとに startOption を切り替える。
• pid は、対象の JVM のプロセスID。

一定間隔で出力する

> jstat -class 32024 1s
Loaded  Bytes  Unloaded  Bytes     Time
 10613 18500.1        0     0.0       5.03
 10613 18500.1        0     0.0       5.03
 10614 18501.1        0     0.0       5.03
 10614 18501.1        0     0.0       5.03
 10614 18501.1        0     0.0       5.03
 10614 18501.1        0     0.0       5.03
（以下永遠に続く）

• pid の後ろに 1s とか 100ms とか書くと、その間隔で繰り返し情報を出力できる。
• 時間の単位（s or ms）を指定しない場合は、デフォルトでミリ秒扱いになる。

指定回数出力したら終了する

> jstat -class 32024 1s 3
Loaded  Bytes  Unloaded  Bytes     Time
 10614 18501.1        0     0.0       5.03
 10614 18501.1        0     0.0       5.03
 10614 18501.1        0     0.0       5.03

>

• interval の後ろに数値を指定すると、その数だけ出力したら監視を終了させられるようになる。
• デフォルトは無限、つまり永遠に監視を続ける。

指定回数ごとにヘッダーを再表示する

> jstat -class -h5 32024 1s
Loaded  Bytes  Unloaded  Bytes     Time
 10614 18501.1        0     0.0       5.03
 10614 18501.1        0     0.0       5.03
 10614 18501.1        0     0.0       5.03
 10614 18501.1        0     0.0       5.03
 10614 18501.1        0     0.0       5.03
Loaded  Bytes  Unloaded  Bytes     Time
 10614 18501.1        0     0.0       5.03
 10614 18501.1        0     0.0       5.03
 10614 18501.1        0     0.0       5.03
 10614 18501.1        0     0.0       5.03
（省略）

• startOption と pid の間に -h<表示間隔> を指定すると、指定した表示間隔ごとにヘッダーが再表示される。

各 startOption

いくつかの種類があるが、出力内容が重複しているものもあり、どのオプションが何を出力するのかがわかりづらい。
なので、表にまとめた。

表にないオプションについては 公式の help を参照。

自分が確認したい情報を決めて、それを出力するオプションを選択すればいいと思う。

jvisualvm

JVM の状態をリアルタイムに GUI で分析（プロファイリング）するためのツール。
JDK に付属している。

コマンドラインで jvisualvm と入力すれば実行できる（パスが通っていれば）。

左の「アプリケーション」に、現在ローカルで起動している JVM が一覧表示されている。
調査したい JVM をダブルクリックして開くと、その JVM に接続して調査を開始できる。

タブごとに、色々な情報が見れる。

タブ名	内容
概要	対象の JVM の基本的な情報を確認できる。
監視	CPU 利用状況・メモリ使用量・クラスロード数・スレッドの状況をリアルタイムで確認できる。
スレッド	各スレッドの状態をリアルタイムで確認できる。
サンプラ・プロファイラ	CPU 使用率とメモリ使用率の詳細な情報を確認できる。

サンプラとプロファイラの違い

サンプラは、アプリケーションへの影響が小さいが、情報が漏れる可能性がある。
プロファイラは、アプリケーションへの影響が大きいが、情報に漏れがない。

サンプラは、定期的に JVM から情報を取得して結果を出力する。
プロファイラは、監視情報をリアルタイムに送信するように実行されているアプリケーションのバイトコードを書き変える。

サンプラはアプリケーションに対する影響が小さく比較的高速に動作するが、情報を取得した瞬間の情報しか取れない。
情報を取得していない時間に、たまたまホットスポットとなる部分が実行されていたりすると、その分の情報が漏れることになる。

プロファイラはアプリケーションのバイトコードをいじるため影響を与える可能性があり、かつ動作に時間もかかる。
しかし、随時アプリケーションから情報が連携されるのでサンプラと比較して情報に漏れがない。

たぶん、そんな違いがあるっぽい。

Java パフォーマンス の「3.3 プロファイリングツール」に、そのへんの詳細な説明が載っている。

ヒープダンプを取得して内容を確認する

• 「監視」タブを開き、「ヒープ」ダンプボタンをクリックすると、ヒープダンプが取得できる。
• ただし、ここで取得できるダンプは GC 後の情報になるっぽい。
  • GC させずに取得したヒープダンプを見たい場合は、別途 jcmd などで取得したファイルを「ファイル」→「読み込み」で開く。

• クラスごとのメモリ消費量の一覧を確認できる。
• クラスをダブルクリックすると、そのクラスのインスタンスの一覧と参照元を確認できる。

• 左の「インスタンス」に、選択したクラスのインスタンスが一覧表示されている。
• 詳細を確認したいインスタンスを選択すると、右の「フィールド」と「参照」に詳細が表示される。
• 「フィールド」には、そのインスタンスが持つフィールドの情報が、
• 「参照」には、そのインスタンスを参照しているオブジェクトの一覧が表示される。

jconsole

JVM の詳細なメモリ状況をリアルタイムで確認できる GUI ツール。
JDK に付属している。

コマンドラインで jconsole と入力すれば実行できる（パスが通っていれば）。

起動したら、現在ローカルで起動している JVM の一覧が表示される。
接続したいプロセスを選択して、「接続」をクリックする。

• 使い方は、まぁ、見たまんま。
• メモリ使用率、スレッド数、ロードされたクラス数、 CPU 使用率がリアルタイムなグラフで表示される。
• タブを切り替えれば、それぞれの詳細情報を確認できる。

• 「メモリー」タブを開けば、メモリの詳細な情報を確認できる。
• 「チャート」で、表示するメモリ領域の種別を選択できる。
  • 右下の「ヒープ」「非ヒープ」と書いている緑のところでも、表示する領域を選択できる。

Eclipse Memory Analyzer Tool

Eclipse Memory Analyzer Open Source Project

• ヒープダンプの内容を調査するための GUI ツール。
• mat と略されたりする。
• Eclipse のプラグインとしてインストールできる。
• Eclipse 無しで、単独で動かすことも可能。
• 今回は、単独で動かした場合の使い方をメモする。

ヒープダンプを開く

• [File] → [Open Heap Dump]
• 開きたいヒープダンプを選択する。

• OOME の調査の場合は、とりあえず一番上を選べば良い。
  • メモリリークの原因と思われる箇所を分析してレポートを生成してくれる。

Leak Suspects Report

• ヒープダンプを解析した結果、メモリリークが疑われる箇所が円グラフで表示される。
• 下の「Problem Suspect 1」には、 ConcurrentHashMap が全体の 95.03% を占めていると記載されている。
• 「Details」をクリックすると、詳細が表示される。

• 重たいインスタンス（CuncurrentHashMap）を参照している他のインスタンスをツリー構造で表示している。

• 重たいインスタンス（CuncurrentHashMap）の中身をツリー構造で表示している。

• クラス別に、メモリ消費量の多いものを表示している。

とりあえず、一番重いらしい ConcurrentHashMap をクリックして [List Objects] → [with outcoming references] を選択する。

• 指定したインスタンスと、その中身がツリーで表示される。
• 「Shallow Heap」が、そのインスタンス単独でのサイズを表している。
• 「Retained Heap」が、そのインスタンスが持つ他のインスタンスを含めたサイズを表している。
• とりあえず、サイズが大きいヤツを掘っていってみる。

• 最終的に、BigObject とかいうクラスが巨大な byte の三次元配列を持っているところまで辿り着いた。
• このプログラムは、実際は以下のようなコードになっている。

MyResource.java

package sample.oome;

import java.io.Serializable;

import javax.enterprise.context.SessionScoped;
import javax.ws.rs.GET;
import javax.ws.rs.Path;
import javax.ws.rs.QueryParam;

@Path("")
@SessionScoped
public class MyResource implements Serializable {
    private static final long serialVersionUID = 1L;
    
    private BigObject bigObject;
    
    @GET
    public void execute(@QueryParam("size") int size) {
        this.bigObject = new BigObject(size);
        System.out.println("done (" + size + ")");
    }
    
    public static class BigObject {
        public byte[][][] data;
        
        public BigObject(int size) {
            this.data = new byte[1024][1024][size];
        }
    }
}

• セッションスコープのリソースクラスに、巨大なインスタンス（BigObject）を保存するようにしている。
• これが溜まり溜まって OOME になっていた。
• Memory Analyzer を使えば、こんな感じで OOME の原因箇所を調査できる。

GC Viewer

GC ログをグラフで表示するツール。

詳しくはこちら。

HeapStats

• NTT の OSS センタが開発した JVM の状態を監視するツール。
• OSS（GPL v2）。
• 平常時から JVM を監視して情報を収集することで、異常を事前に検知してアラートを上げたり、障害発生時の情報の収集を省力化したりできる。

動作確認したときの環境

• エージェントを動かす環境
  • CentOS 6.3 (VMware)
  • Java 1.8.0_65 (Oracle JDK)
• アナライザを動かす環境
  • Windows 7
  • Java 1.8.0_74

インストール

エージェントのインストール

• こちらにあるリンク から、 rpm ファイルをダウンロードしてくる。
• CentOS 6 は RHEL6 相当なので、 heapstats-2.0.1-0.el6.x86_64.rpm を落とすことにした。
• 今回は Oracle の Java を入れていたが、 OpenJDK の場合は debuginfo とかいうのをインストールしないといけないらしい

# rpm をダウンロード
$ wget http://icedtea.wildebeest.org/download/heapstats/heapstats-2.0.1/bin/agent/el6/x86_64/heapstats-2.0.1-0.el6.x86_64.rpm

# インストール
$ sudo rpm -ivh heapstats-2.0.1-0.el6.x86_64.rpm

# インストールが完了しているか確認
$ java -agentlib:heapstats -version
heapstats INFO: HeapStats 2.0.1
heapstats INFO: Supported processor features: AVX
heapstats INFO: Agent Attach Enable = true
（略）
heapstats INFO: Kill on Error = false
java version "1.8.0_65"
Java(TM) SE Runtime Environment (build 1.8.0_65-b17)
Java HotSpot(TM) 64-Bit Server VM (build 25.65-b01, mixed mode)

起動

# HeapStats のエージェントを差し込んで Java プログラムを起動する
$ java -agentpath:/usr/lib64/heapstats/libheapstats.so （略）
heapstats INFO: HeapStats 2.0.1
heapstats INFO: Supported processor features: AVX
heapstats INFO: Agent Attach Enable = true
heapstats INFO: SnapShot FileName = heapstats_snapshot.dat
heapstats INFO: Heap Log FileName = heapstats_log.csv
heapstats INFO: Archive FileName = heapstats_analyze.zip
（略）

• -agentpath で HeapStats の so ファイルを指定する。
  • 環境変数に設定しておく方法なども存在する（1.3 起動 | HeapStats エージェント）。
• 起動すると、カレントディレクトリに以下のファイルが出力される。
  • heapstats_snapshot.dat
    • Full GC が発生したときなどのスナップショットが保存されるファイル。
  • heapstats_log.csv
    • ヒープや CPU などの簡易な情報を出力したログ。
• ログファイルは、デフォルトでは５分間隔で出力される。
  • OOME が発生した場合や、ユーザーが明示的に出力を指示した場合にも出力される。
• ファイルの名前や場所、その他エージェントに関する様々な挙動は、設定ファイルで任意に変更することができる。
  • 詳しくは HeapStats/jp/エージェント を参照。

アナライザで確認する

• エージェントが収集したログファイルやスナップショットは、アナライザと呼ばれる GUI ツールで確認できる。
• エージェントを落としてきた場所に、アナライザも置いてあるので、それを落としてくる（heapstats-analyzer-2.0.1-bin.zip）。
• 解凍したら、中に heapstats-analyzer.jar が入っているので、ダブルクリックで起動する。

• [Log Data] タブで、ログファイルを確認できる。
  • [Log File] をクリックして開くログファイルを選択する。
  • [Range] で、確認したいログファイルの期間を選択する。
  • [OK] をクリックすると、ログの内容がグラフになって表示される。

• [SnapShot Data] タブで、スナップショットファイルを確認できる。
  • [Log File] の場合と同じ要領でファイルを開く。

• [Histogram] タブや [SnapShot Data]タブで、クラスごとのヒープ占有率などを確認できる。
• また、 [SnapShot Data] タブでオブジェクトを選択した状態で [Reference Tree] を選択すれば、そのオブジェクトを参照するオブジェクトの関連をグラフィカルに辿ることができる。

• 詳しい使い方は 日本語のマニュアル があるので、そちらを参照。

JVM のオプション

GC の情報を出力する

基本

java -verbose:gc （略）

GC (Allocation Failure)
305284K->307692K(450048K), 0.0386887 secs]

GC (Allocation Failure)
366572K->369612K(450048K), 0.0429775 secs]

Full GC (Ergonomics)
369612K->357147K(466432K), 0.1287979 secs]

• 起動時のオプションに -verbose:gc と指定すると、 GC が起こったタイミングで標準出力に GC の情報が出力されるようになる。
• GC とだけ出ているのは、 Full GC 以外の GC が発生したことを表している（Young 領域の GC とか）。
• Full GC と出ているのは、そのものずばり Full GC が発生したことを表している。
• 369612K->357147K は、 GC 前後のメモリ使用量を表している。

ログに出力する

java -Xloggc:./gclog/gc.log （略）

gclog/gc.log

（略）
1.115: [GC (Allocation Failure)  65536K->13595K(251392K), 0.0172892 secs]
1.619: [GC (Metadata GC Threshold)  59048K->17654K(316928K), 0.0186921 secs]
1.638: [Full GC (Metadata GC Threshold)  17654K->14363K(316928K), 0.0809789 secs]
9.061: [GC (Metadata GC Threshold)  119609K->33977K(316928K), 0.0129435 secs]
9.074: [Full GC (Metadata GC Threshold)  33977K->28176K(354304K), 0.0658862 secs]
9.914: [GC (Allocation Failure)  159248K->38718K(376320K), 0.0071812 secs]
14.349: [GC (Allocation Failure)  191806K->44894K(376320K), 0.0180813 secs]
16.044: [GC (Allocation Failure)  197982K->58932K(346624K), 0.0185405 secs]
17.062: [GC (Allocation Failure)  182324K->84387K(361472K), 0.0193260 secs]
（略）

• -Xloggc:<GCログファイルの出力先パス> をオプションに指定することで、 GC のログをファイルに出力できる。
  • 既に同名のファイルが存在する場合、ファイルが上書きされるので注意。
  • 起動時の日時をファイル名に含めておけば、誤って上書きしてしまうことを防げる。
• 先頭の数字は、 JVM が起動されてからの経過時間が出力されている。

時刻を出力する

> java -Xloggc:./gclog/gc.log -XX:+PrintGCDateStamps （略）

gc.log

（略）
2016-03-12T23:33:18.100+0900: 1.043: [GC (Allocation Failure)  65536K->13533K(251392K), 0.0164784 secs]
2016-03-12T23:33:18.637+0900: 1.580: [GC (Metadata GC Threshold)  60735K->17423K(316928K), 0.0091990 secs]
2016-03-12T23:33:18.646+0900: 1.589: [Full GC (Metadata GC Threshold)  17423K->14261K(316928K), 0.0382588 secs]
2016-03-12T23:33:26.067+0900: 9.009: [GC (Metadata GC Threshold)  119162K->33976K(316928K), 0.0249904 secs]
2016-03-12T23:33:26.092+0900: 9.034: [Full GC (Metadata GC Threshold)  33976K->28238K(346624K), 0.0769754 secs]
2016-03-12T23:33:27.057+0900: 10.000: [GC (Allocation Failure)  159310K->38719K(368640K), 0.0075372 secs]
2016-03-12T23:34:17.486+0900: 60.428: [GC (Allocation Failure)  191807K->72288K(368640K), 0.0504215 secs]
2016-03-12T23:34:18.894+0900: 61.836: [GC (Allocation Failure)  225376K->86442K(311296K), 0.0200902 secs]
（略）

• -XX:+PrintGCDateStamps を追加することで、 GC ログにそのときの時刻も出力させることができる。

詳細な GC ログを出力させる

> java -Xloggc:./gclog/gc.log -XX:+PrintGCDetails （略）

gc.log

（略）
1.037: [GC (Allocation Failure) [PSYoungGen: 65536K->10743K(76288K)] 65536K->13596K(251392K), 0.0106704 secs] [Times: user=0.00 sys=0.00, real=0.01 secs] 
1.566: [GC (Metadata GC Threshold) [PSYoungGen: 57946K->10731K(76288K)] 60799K->17543K(251392K), 0.0091160 secs] [Times: user=0.05 sys=0.02, real=0.01 secs] 
1.575: [Full GC (Metadata GC Threshold) [PSYoungGen: 10731K->0K(76288K)] [ParOldGen: 6812K->14259K(175104K)] 17543K->14259K(251392K), [Metaspace: 20821K->20821K(1067008K)], 0.0362780 secs] [Times: user=0.08 sys=0.00, real=0.04 secs] 
8.644: [GC (Allocation Failure) [PSYoungGen: 65536K->10750K(76288K)] 79795K->28913K(251392K), 0.0212910 secs] [Times: user=0.11 sys=0.02, real=0.02 secs] 
8.995: [GC (Metadata GC Threshold) [PSYoungGen: 42809K->10746K(96256K)] 60972K->29332K(271360K), 0.0082032 secs] [Times: user=0.00 sys=0.00, real=0.01 secs] 
9.003: [Full GC (Metadata GC Threshold) [PSYoungGen: 10746K->0K(96256K)] [ParOldGen: 18585K->20171K(192000K)] 29332K->20171K(288256K), [Metaspace: 34754K->34754K(1081344K)], 0.0700618 secs] [Times: user=0.47 sys=0.00, real=0.07 secs] 
9.238: [GC (Allocation Failure) [PSYoungGen: 85504K->1118K(96256K)] 105675K->21289K(288256K), 0.0043759 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
10.587: [GC (Allocation Failure) [PSYoungGen: 86622K->17111K(143872K)] 106793K->37291K(335872K), 0.0245291 secs] [Times: user=0.11 sys=0.00, real=0.02 secs] 
19.645: [GC (Allocation Failure) [PSYoungGen: 141527K->21483K(145920K)] 161707K->49982K(337920K), 0.0182595 secs] [Times: user=0.08 sys=0.00, real=0.02 secs] 
（略）

• -XX:+PrintGCDetails を追加することで、より詳細な情報を出力させられるようになる。
  • 領域ごとのメモリ量の変化などが出力されている

ログファイルをローテーションさせる

> java -Xloggc:./gclog/gc.log -XX:+UseGCLogFileRotation -XX:NumberOfGCLogFiles=5 -XX:GCLogFileSize=10k （略）

ローテーションが１周回った後の状態

gclog> dir
2016/03/12  23:52    <DIR>          .
2016/03/12  23:52    <DIR>          ..
2016/03/12  23:52            10,594 gc.log.0
2016/03/12  23:52             1,302 gc.log.1.current
2016/03/12  23:52            10,458 gc.log.2
2016/03/12  23:52            10,515 gc.log.3
2016/03/12  23:52            10,519 gc.log.4

• GC ログファイルをローテーションさせる場合は、起動時に次のオプションを指定する。
  • -XX:+UseGCLogFileRotation
  • -XX:NumberOfGCLogFiles=<ローテーション数>
  • -XX:GCLogFileSize=<１ファイルの最大サイズ>
• サイズは k や m などでキロバイト・メガバイトを指定できる。
• まず最初に gc.log.0.current が生成される。
• 次にローテーションすると gc.log.1.current が生成され、そちらにログが吐かれるようになる。
  • gc.log.0.current は gc.log.0 という名前にリネームされる。
• 同じようにしてローテーションを繰り返していき、 NumberOfGCLogFiles で指定したファイル数を超えたら再び gc.log.0 にログが出力されるようになる。
• 現在出力しているファイルは、末尾に .current が付く。

GC ログをグラフで確認する

• GC Viewer という GUI のツールを使うことで、 GC ログをグラフで確認することができる。
  • なんか、 -XX:+PrintGCDateStamps を指定していないとログの解析でエラーになる気がする。。。？
• オリジナルの作者による開発は 2008 年の時点で終了しているが、別の人が GitHub 上 で開発を続けている。
• GitHub から実行可能 jar を落としてくることができる。
• ダブルクリックで起動して、 GC ログをドラッグ＆ドロップすれば開くことができる。

• [View] でグラフの表示非表示を切り替えられる。
  • 上図は、ヒープの変化だけを表示している。
• ツールバーにある時計みたいなマーク（拡大率の左）をクリックすると、ログを監視して変更があればリアルタイムで表示を更新できるようになる。
• 普段から GC ログを出力させておいて、ヒープの変化に不自然な様子は無いかを確認するのに利用する。
  • GC が発生したのにヒープのサイズがどんどん増えていっていたら、なんか怪しいという合図。
  • 上図のログでは、 GC の度にヒープサイズがほぼ同じサイズに下がっているので、問題はなさげと判断できる。

OOME が発生したときにヒープダンプを自動で取得する

> java -XX:+HeapDumpOnOutOfMemoryError -XX:HeapDumpPath=./hprof/ （略）

OOMEが発生したときの標準出力

Dumping heap to ./hprof/\java_pid21072.hprof ...
Heap dump file created [454844605 bytes in 0.602 secs]

[2016-03-13T00:38:01.923+0900] [Payara 4.1] [WARNING] [] [javax.enterprise.web] [tid: _ThreadID=17 _ThreadName=http-listener(2)] [timeMillis: 1457797081923] [levelValue: 900] [[StandardWrapperValve[sample.oome.MyApplication]: Servlet.service() for servlet sample.oome.MyApplication threw exception
java.lang.OutOfMemoryError: Java heap space
        at sample.oome.MyResource$BigObject.<init>(MyResource.java:24)
        at sample.oome.MyResource.execute(MyResource.java:16)
（略）

出力されたヒープダンプ

hprof> dir /b
java_pid21072.hprof

• -XX:+HeapDumpOnOutOfMemoryError を設定することで、 OOME が発生したときに自動でヒープダンプを出力させられるようになる。
• -XX:HeapDumpPath=<出力先フォルダ> で、ヒープダンプの出力先を指定できる。
  • ファイル名は java_pid<プロセスID>.hprof という名前になる。
• 同じプロセスでは、一度 OOME でヒープダンプが出力されると、以後 OOME が発生してもヒープダンプを出力しなくなる模様。
  • まぁ、 OOME が出た時点でメモリの状態が保証されないから、一旦アプリケーションは停止させるべきなのだろう。

用語集

ヒープ

• ヒープメモリ。
• Java プログラム上で生成したオブジェクトが配置されるメモリ領域。
• 一般的に「ヒープ」と言うと、プログラムが動くために確保されたメモリ領域のことを指す。
  • ヒープとは｜heap｜ヒープ領域 - 意味/定義 ： IT用語辞典
  • しかし、 JVM での文脈では、単に「ヒープ」と言うと JVM 上で動く Java プログラムのためのメモリ領域のことを指す。
  • JVM が動くときは、 Java プログラムのため以外にも JVM 自身のためのメモリ領域なども確保される。
• JVM のメモリ空間の説明で「C ヒープ」という表現がある場合、その「ヒープ」は一般用語の意味での「ヒープ」のことだと思う。
  • JVM での文脈では、「C ヒープ」はネイティブ領域のことになる。

Permanent 領域

• クラスやメソッドのメタ情報など、静的な情報が格納される。
  • DI コンテナとかがクラスを動的にロードすると、この領域が消費されていき OOME が発生しやすい。
• 非ヒープ領域。
  • ヒープ領域ではないが、ネイティブ領域でもない領域。
• Java 8 で廃止され、代わりに Metaspace と呼ばれる領域が追加された。

Metaspace

• Java 8 から採用された、 Permanent 領域に代わるメモリ領域。
• ネイティブ領域に確保される。

ネイティブ領域

• Native Area とか、単に Native とか。
• JVM が動くためのメモリだったりスレッドのスタックの情報が格納されたりする領域。

Young 領域

• ヒープの一部。
• 生成されてからの時間がまだ短いオブジェクトが配置される領域。
• Young 領域は、さらに Eden 領域と２つの Survivor 領域に分かれる。
• New 領域とも呼ばれる。

Eden 領域

• Young 領域の一部。
• 新規作成されたオブジェクトは、まずこの領域に配置される。

Survivor 領域

• Young 領域の一部。
• Eden 領域がガベージコレクションされるときに、まだ利用されているオブジェクトは Survivor 領域に移動される。
• Young 領域内には２つの Survivor 領域が用意されており、どちらか一方は必ず空になっている。
• 詳しくは Java技術最前線 - 「メモリーを意識してみよう」第2回　GCの仕組みを理解する：ITpro を参照。

Old 領域

• ヒープの一部。
• Survivor 領域の中でも特に長時間生き続けているオブジェクトが退避される場所。
• Tenured 領域とも呼ばれる。

ガベージコレクション

• Garbage Collection
• GC
• ヒープメモリに配置されたオブジェクトのうち、使われていないものを破棄しメモリの空き領域を確保する機能・仕組み。

Stop the World

• ガベージコレクションを実行しているときに発生する、アプリケーションスレッドが完全に停止する現象、またその時間。
• ガベージコレクションではオブジェクトの参照を辿ったり、必要であればコンパクト化したりする。
  • この間に、アプリケーションがメモリを参照したりオブジェクトの関連を書き変えたりすると、正確にガベージコレクションができなくなる。
  • なので、どうしてもアプリケーションスレッドを止めてガベージコレクションが専有する時間が必要になる。
  • これが Stop the World.
• STW と省略されたりすることもある。
• 最初、某吸血鬼の必殺技を元にしたネタと思ってたけど、正式な用語らしい。

コンパクト化

• 断片化したメモリを整理して、まとまった空き領域を確保すること。

マイナーガベージコレクション

• Minor Garbage Collection
• Young 領域（Eden, Survivor）がいっぱいになったときに実行されるガベージコレクション。

Scavenge GC

• 世代別 GC で実行されるガベージコレクションの手法の１つ。
  • 対象メモリ領域のオブジェクトを調べ、使用していないオブジェクトは破棄し、使用しているオブジェクトは別の領域に移動する。
  • 対象メモリ領域が限られており、最後は対象のメモリ領域が空になるのでコンパクト化する必要がなく、高速に動作する。
• マイナーガベージコレクションで使用されている。
• オブジェクトを移動するだけなので、 Copy GC とも呼ばれる。
• Stop the World の時間は短い。

Copy GC

• Scavenge GC のこと。

メジャーガベージコレクション

• Major Garbage Collection
• Old 領域がいっぱいになったときに実行されるガベージコレクション。
  • 厳密には色々複雑な条件があるらしいけど、そのへんは CMS GC おさらい - sugarlife's blog を参照のこと。
• コンパクト化は行わない。

フルガベージコレクション

• Full Garbage Collection
• Full GC
• 全メモリ領域（Permanent も含む）を対象にした大規模なガベージコレクション。
• 断片化のため Old 領域の空き領域が足りないときや、他の GC での回収が間に合わないようなときに実行される。
• コンカレントではない Mark & Sweep を実行して、更にコンパクト化も行う。
• 必然的に Stop the World は長くなる。

Mark & Sweep

• ガベージコレクションの手法の１つ。
• ガベージコレクションを２つのフェーズに分けて実行する。
  • 最初のフェーズでは、使用しているオブジェクトの参照を辿りながらマークを付けていき、使用していないオブジェクトを特定する。
  • 次のフェースでは、使用していないオブジェクトをメモリ上から削除する。
• フルガベージコレクションで使用されている。

シリアル GC

• Serial GC
• ガベージコレクションの実行方法の１つ。
• アプリケーションとガベージコレクションのスレッドが交互に実行される。
• ガベージコレクション用のスレッドは１つだけしか使用されない。
• シングルコアのマシンではデフォルト。

パラレル GC

• Parallel GC
• ガベージコレクションの実行方法の１つ。
• アプリケーションとガベージコレクションのスレッドが交互に実行されるのはシリアル GC と同じ。
• ガベージコレクション用のスレッドが複数使用される点がパラレル。
• マルチコアのマシンではデフォルト。

Concurrent Mark & Sweep GC

• Concurrent GC とか CMS と呼ばれたりもする。
• Mark & Sweep の処理をアプリケーションスレッドと同時並行で行う手法。
  • 完全な同時並行ではなく、最初と途中で Stop the World が発生する。
• Stop the World の時間は短い。
• アプリケーションとガベージコレクトが同時に実行されるので、スループット（単位時間あたりの処理件数）は下がる可能性がある。
  • 代わりに、 Stop the World の時間は短いのでレスポンスタイム（処理結果が返されるまでの時間）は上がる可能性がある。
• メジャーガベージコレクションで使用されている。

G1 GC

• Garbage First GC
• メモリの大容量化に伴い、今までの世代別 GC では無駄が多いということで考え出された GC。
• Java 7 から採用され、 Java 9 でデフォルト化する予定。
• ヒープ領域を「リージョン」と呼ばれる区域で等分割し、世代別に管理する。
  • 分割した領域を Eden, Survivor, Old として使う。
  • まず Eden に配置して、いっぱいになったら Survivor, そして Old に移していく考え方は同じ。

世代別GC

• HotSpot VM で採用されたガベージコレクションの手法。
• ヒープ領域をオブジェクトの生存期間の長さに合わせて Young 領域と Old 領域に分割して、段階的にガベージコレクションを実行する。

HotSpot VM

• JVM で使用されている高速化のための技術、またその技術を採用した JVM のこと。
• HotSpot - すなわち、プログラムの中でも特に実行頻度の高い部分を特定して、その部分を優先的に機械語にコンパイルして実行する手法・仕組み。
  • １回しか実行しないコードを機械語にコンパイルするのは無駄が大きいので、そういう部分はインタプリタで実行して、何回も実行される部分（HotSpot）だけを機械語にコンパイルして高速化しよう、という考え方。
• 「一般的なプログラムは、実行時間の 80% がソースコードの 20 % で実行されている」という法則がもとになっている。

Just In Time Compiler

• JIT コンパイラ
• 中間言語など実行環境に依存しない形式で書かれたプログラムを、実行直前（Just In Time）に実行環境に合わせた機械語にコンパイルして実行する手法・機能。
  • インタプリタは逐次ソースを読みながら実行するので、ちょっと違う。
• 実行環境に依存しない形式でプログラムを配布でき、かつ実行速度は予め機械語で作成されたプログラムと引けを取らないという特徴がある。

参考

全般

• Amazon.co.jp： Javaパフォーマンス: Scott Oaks, アクロクエストテクノロジー株式会社, 寺田 佳央, 牧野 聡: 本

メモリ管理の仕組み

• Java技術最前線 - 「Java SE 6完全攻略」Garbage First GC：ITpro
• Java技術最前線 - 「メモリーを意識してみよう」第2回　GCの仕組みを理解する：ITpro
• Java技術最前線 - 「メモリーを意識してみよう」第4回　進化するメモリー管理：ITpro
• Garbage First Garbage Collection (G1 GC) #jjug_ccc #ccc_cd6
• CMS GC おさらい - sugarlife's blog
• Metaspace を OpenJDK 実装から見てみよう！ | 末永恭正 | SlideShare
• Java 8でPermGenのOutOfMemoryError問題は解決されるのか？
• Java8のHotSpotVMからPermanent領域が消えた理由とその影響 | ギークを目指して
• Java Garbage Collection Basics
• Garbage Collectionについてちょっと調べてみた - wyukawa’s blog
• Javaはどのように動くのか～スライドでわかるJVMの仕組み
• 第9回　［最終回］HotSpot JVMのGCを選択しよう：Javaはどのように動くのか～図解でわかるJVMの仕組み｜gihyo.jp … 技術評論社
• JITコンパイラとは｜実行時コンパイラ｜ジャストインタイムコンパイラ - 意味/定義 ： IT用語辞典
• java memory structure heap permanent native | Google 画像検索

OOME の調査方法など

• Javaトラブルに備えよう #jjug_ccc #ccc_h2
• まじめにJVMチューニング: 第2回 GCログをみる
• 人生楽しまなきゃもったいない！: javaのOutOfMemory時のヒープの分析にチャレンジ（jhat）

ツール類

• jcmdユーティリティ
• jcmd
• jmap - メモリーマップ
• jstat
• jvisualvmを使ったCPUプロファイリング - Javaで画像ビューアを開発してみる日記
• Profiling Vs. Sampling in Java's VisualVM
• java - Difference between sampling and profiling in jVisualvm - Stack Overflow
• HeapStats: Introduction and Technical Preview
• HeapStats/jp - IcedTea