ふわっと JVM のヒープ領域監視について考える

ども、かっぱです。

はじめに

• Java アプリケーションを運用する上では避けて通れないであろうヒープ領域の監視についてフワッと考えてみた
• JVM には幾つか領域があるがヒープ領域に焦点を当てる

---

参考

• http://www.whitemark.co.jp/tec/java/javaHeap.html
• http://www.whitemark.co.jp/tec/java/javagc.html
• http://d.hatena.ne.jp/ogin_s57/20120623/1340463194
• http://d.hatena.ne.jp/ogin_s57/20120709/1341836704
• https://docs.oracle.com/javase/jp/1.5.0/guide/management/agent.html
• http://chonaso.hatenablog.com/entry/20140507/1399395305
• http://www.slideboom.com/presentations/800440/20130727-%E6%B8%8B%E8%B0%B7Java-%232-Java%E3%82%A2%E3%83%97%E3%83%AA%E3%82%B5%E3%83%BC%E3%83%90-%E3%81%A8%E3%82%8A%E3%81%82%E3%81%88%E3%81%9A%E3%81%AE%E7%9B%A3%E8%A6%96
• http://www.syboos.jp/java/doc/full-gc-in-java-and-howto.html

上記の全ての記事がとても参考になった（というかむしろそのまま内容を拝借した感じになっている...）投稿者、作者の皆様に感謝。

---

JVM の構成

構成

以下のようなイメージ。

ヒープ領域

• Java が利用出来るメモリ領域

非ヒープ領域

• Permanent 領域

New 領域

• Eden : 最初にインスタンス化したオブジェクトが格納される
• From : Scavenge GC によってオブジェクトが格納される
• To : Scavenge GC によってオブジェクトが格納される

Old 領域

• New 領域の From と To のやりとり頻度が多い（Defaul 32 回）オブジェクトで利用される
• 空き領域が少なくなると Full GC によってオブジェクトは破棄される

Parament 領域

• アプリケーションのクラス、メソッドが格納される
• 大量のクラスや JSP を大量に利用する場合には領域を大きく確保しておく必要がある
• Old 領域同様に空き領域が少なくなると Full GC により空き領域を確保する

---

GC

ガーベージコレクション

以下のようなイメージ。

New 領域における Scavenge GC について

• Eden 領域が一杯になると Scavenge GC が実行されオブジェクトは To 領域へ移動して Eden 領域の空き容量を確保
• 再び Eden 領域が一杯になり Scavenge GC が実行されるとオブジェクトは To 領域へ移動、To 領域のオブジェクトは From 領域に移動
• From と To でオブジェクトの行き来が発生するが、この行き来が 32 回を超える*1と Old 領域にオブジェクトは移動する（MaxTenuringThreshold）
• 比較的短時間で終了する

Old 領域における Full GC について

• 主に Old 領域と Perament 領域を対象とした GC となる（New 領域でも発生する）
• Scavenge GC 及び Old 領域、Perament 領域を対象とする GC の為に処理時間が長い
• Full GC 実行中はシステム停止となってしまう...

---

監視項目（どこを見ておくべきなのか（何を主に見ておくべきなのか））

個人的な見解

• 各領域（New / Old / Parament）の使用率
• 各 GC の回数（特に Full GC）
• New の Eden 領域
• JVM に関係ないけどファイルのオープン数（Open Files Limits）
• メモリリーク =「Full GC が発生しても Old領域 の空き容量が回復しない状態」

---

（以下、引続き書く）

各種ツール（監視ツール、解析ツール）

jstat

jstat は JVM のパフォーマンス統計監視ツールで CentOS の場合には openjdk-devel をインストールする必要がある。

sudo yum install java-1.7.0-openjdk-devel.x86_64

例えば jps を使って Elasticsearch で利用している JVM のプロセス ID を確認して jstat で状態を確認するには以下のように実行する。

# sudo -u elasticsearch jps
2713 Jps
2363 Elasticsearch
# sudo -u elasticsearch jstat -gc 2365
2365 not found
# sudo -u elasticsearch jstat -gc 2363
 S0C    S1C    S0U    S1U      EC       EU        OC         OU       PC     PU    YGC     YGCT    FGC    FGCT     GCT
8512.0 8512.0 8512.0  0.0   68160.0  58472.1   176960.0   13304.9   38912.0 38885.4      2    0.059   0      0.000    0.059

地味にハマったのが root ユーザーの状態で jps を実行すると以下のように Elasticsearch のプロセスを見つける事が出来ない。

# jps
2780 Jps
2363 -- process information unavailable

jps コマンドや jstat コマンドはデフォルトで /tmp/hsperfdata_${ユーザー名} 以下に出力される ${PID} ファイル名が付いたファイルを参照するが、Elasticsearch の場合には以下のような状態になっている。

# ls -l tmp/hsperfdata_elasticsearch/
total 32
-rw------- 1 elasticsearch elasticsearch 32768 Mar 28 17:23 2363

ということで elasticsearch ユーザーで実行することで jps や jstat で Elasticsearch のプロセスを見つけることが出来て状態を確認することも出来たところで...前後してしまったが jstat の出力オプションについて以下のようにドキュメントより転載。

オプション	表示内容
class	クラスローダーの動作に関する統計データ
compiler	HotSpot Just-in-Time コンパイラの動作に関する統計データ
gc	ガベージコレクトされたヒープの動作に関する統計データ
gccapacity	世代ごとの容量と対応する領域に関する統計データ
gccause	ガベージコレクション統計データの概要 (-gcutil と同じ) と、直前および現在 (適用可能な場合) のガベージコレクションイベントの原因
gcnew	New 世代の動作に関する統計データ
gcnewcapacity	New 世代のサイズと対応する領域に関する統計データ
gcold	Old 世代および Permanent 世代の動作に関する統計データ
gcoldcapacity	Old 世代のサイズに関する統計データ
gcpermcapacity	Permanent 世代のサイズに関する統計データ
gcutil	ガベージコレクション統計データの概要
printcompilation	HotSpot コンパイル方法の統計データ

出力オプションに関してはプラットフォーム毎に異なるので各プラットフォームで利用可能な出力オプションを確認するには -options を実行して確認する。例えば、x86_64 な CentOS 6.x 上で確認すると以下のように出力される。

# jstat -options
-class
-compiler
-gc
-gccapacity
-gccause
-gcnew
-gcnewcapacity
-gcold
-gcoldcapacity
-gcpermcapacity
-gcutil
-printcompilation

Elasticsearch が稼働している環境で各出力オプションを試してみる。

# sudo -u elasticsearch jps
1145 Elasticsearch
1570 Jps

# sudo -u elasticsearch jstat -class 1145
Loaded  Bytes  Unloaded  Bytes     Time
  6687 12891.6        0     0.0       4.30

# sudo -u elasticsearch jstat -compiler 1145
Compiled Failed Invalid   Time   FailedType FailedMethod
     672      0       0     3.80          0

# sudo -u elasticsearch jstat -gc 1145
 S0C    S1C    S0U    S1U      EC       EU        OC         OU       PC     PU    YGC     YGCT    FGC    FGCT     GCT
8704.0 8704.0  0.0   4026.3 69952.0  20325.1   174784.0   29543.6   35264.0 35087.9      7    0.129   0      0.000    0.129

# sudo -u elasticsearch jstat -gccapacity 1145
 NGCMN    NGCMX     NGC     S0C   S1C       EC      OGCMN      OGCMX       OGC         OC      PGCMN    PGCMX     PGC       PC     YGC    FGC
 87360.0 340736.0  87360.0 8704.0 8704.0  69952.0   174784.0   707840.0   174784.0   174784.0  21248.0 169984.0  35264.0  35264.0      7     0

# sudo -u elasticsearch jstat -gccause 1145
  S0     S1     E      O      P     YGC     YGCT    FGC    FGCT     GCT    LGCC                 GCC
  0.00  46.26  30.21  16.90  99.50      7    0.129     0    0.000    0.129 Allocation Failure   No GC

# sudo -u elasticsearch jstat -gcnew 1145
 S0C    S1C    S0U    S1U   TT MTT  DSS      EC       EU     YGC     YGCT
8704.0 8704.0    0.0 4026.3  6   6 4352.0  69952.0  22320.2      7    0.129

# sudo -u elasticsearch jstat -gcnewcapacity 1145
  NGCMN      NGCMX       NGC      S0CMX     S0C     S1CMX     S1C       ECMX        EC      YGC   FGC
   87360.0   340736.0    87360.0  34048.0   8704.0  34048.0   8704.0   272640.0    69952.0     7     0

# sudo -u elasticsearch jstat -gcold 1145
   PC       PU        OC          OU       YGC    FGC    FGCT     GCT
 35264.0  35088.4    174784.0     29543.6      7     0    0.000    0.129

# sudo -u elasticsearch jstat -gcoldcapacity 1145
   OGCMN       OGCMX        OGC         OC       YGC   FGC    FGCT     GCT
   174784.0    707840.0    174784.0    174784.0     7     0    0.000    0.129

# sudo -u elasticsearch jstat -gcpermcapacity 1145
  PGCMN      PGCMX       PGC         PC      YGC   FGC    FGCT     GCT
   21248.0   169984.0    35264.0    35264.0     7     0    0.000    0.129

# sudo -u elasticsearch jstat -gcutil 1145
  S0     S1     E      O      P     YGC     YGCT    FGC    FGCT     GCT
  0.00  46.26  39.41  16.90  99.50      7    0.129     0    0.000    0.129

# sudo -u elasticsearch jstat -printcompilation 1145
Compiled  Size  Type Method
     679    191    1 java/util/EnumSet noneOf

各出力オプション毎の項目についてはドキュメントを参照するとして　-gc オプションを実行した際の各項目は下記の通り。（ドキュメントより抜粋）

列名	意味	備考
S0C	Survivor 領域 0 の現在の容量 (KB)	From のことだと思う
S1C	Survivor 領域 1 の現在の容量 (KB)	To のことだと思う
S0U	Survivor 領域 0 の使用率 (KB)	From のことだと思う
S1U	Survivor 領域 1 の使用率 (KB)	To のことだと思う
EC	Eden 領域の現在の容量 (KB)
EU	Eden 領域の使用率 (KB)
OC	Old 領域の現在の容量 (KB)
OU	Old 領域の使用率 (KB)
PC	Permanent 領域の現在の容量 (KB)
PU	Permanent 領域の使用率 (KB)
YGC	若い世代の GC イベント数
YGCT	若い世代のガベージコレクション時間
FGC	フル GC イベント数
FGCT	フルガベージコレクション時間
GCT	ガベージコレクション総時間

JMX と Jolokia

JMX とは...

Java Management Extensions (JMX) は、Java アプリケーションをモニタおよび管理するための仕様です。JMX を使用すると、汎用管理システムでアプリケーションをモニタし、注意が必要なときに通知を生成し、アプリケーションの状態を変更して問題を解決できます。JMX は SNMP および他の管理規格と同様に公開された仕様であり、一般的に用いられるモニタ用製品を扱うベンダの多くでサポートされています。

上記のように言及されている。

JMX は JConsole 等のツールを利用して JVM をモニタリングすることになるが、Jolokia というツールを利用することで JConsole 等のツールを特別に用意することなく HTTP 経由でアクセス出来るツールがあるのでそちらを利用することで簡単に JMX を利用することが出来るようになる。

例えば、Elasticsearch に Jolokia を組み込む場合には以下のように簡単に組み込むことが出来る。

$ sudo mkdir /opt/jolokia
$ cd /opt/jolokia
$ sudo wget http://search.maven.org/remotecontent?filepath=org/jolokia/jolokia-jvm/1.3.1/jolokia-jvm-1.3.1-agent.jar
$ sudo mv remotecontent\?filepath\=org%2Fjolokia%2Fjolokia-jvm%2F1.3.1%2Fjolokia-jvm-1.3.1-agent.jar jolokia-jvm-1.3.1-agent.jar

以下のように etc/sysconfig/elasticsearch を修正する。

$ diff -u /etc/sysconfig/elasticsearch.bk /etc/sysconfig/elasticsearch
--- /etc/sysconfig/elasticsearch.bk     2015-07-15 22:12:24.762736013 +0900
+++ /etc/sysconfig/elasticsearch        2015-07-15 22:14:02.365038454 +0900
@@ -34,7 +34,7 @@
 #ES_DIRECT_SIZE=
 
 # Additional Java OPTS
-#ES_JAVA_OPTS=
+ES_JAVA_OPTS="$JVM_OPTS -javaagent:/opt/jolokia/jolokia-jvm-1.3.1-agent.jar=port=8778,host=127.0.0.1"
 
 # Configure restart on package upgrade (true, every other setting will lead to not restarting)
 #ES_RESTART_ON_UPGRADE=true

修正したら Elasticsearch のプロセスを再起動する。

$ sudo /etc/init.d/elasticsearch restart
Stopping elasticsearch:                                    [  OK  ]
Starting elasticsearch:                                    [  OK  ]

以下のように出力される。

> No access restrictor found, access to all MBean is allowed
Jolokia: Agent started with URL http://127.0.0.1:8778/jolokia/

curl を利用してヒープの使用量を確認する。

$ curl -s http://127.0.0.1:8778/jolokia/read/java.lang:type=Memory/HeapMemoryUsage/ | python -m json.tool
{
    "request": {
        "attribute": "HeapMemoryUsage", 
        "mbean": "java.lang:type=Memory", 
        "type": "read"
    }, 
    "status": 200, 
    "timestamp": 1436966090, 
    "value": {
        "committed": 259719168, 
        "init": 268435456, 
        "max": 1065025536, 
        "used": 37271360
    }
}

上記のように値は JSON で返却されるので色々と幸せになれる。尚、Jolokia を利用することで監視以外にも GC の実行等も行うことが出来る。詳細については以下の記事を参考にさせて頂いている。

JolokiaでMBeanにアクセスする | Ore no homepage

---

ということで...

駆け足で JVM の構成からヒープ領域の監視方法等についてメモってみた。JVM って何？ってところからだったので正直勉強不足。引き続き、Java や JVM の運用については精進していきたい。

*1:「最大 32 回となり 32 回未満でも Old 領域にプロモートすることがある」とのコメントを頂きました