Javaのheapログ(タイムスタンプ付)取得方法

Jmeterで負荷試験を実施した時にJmeterサーバ側のリソースがボトルネックになっては
いないか?という問い合わせを受ける事があります。
OSのリソース状態はWindowsであればカウンタログ、Linuxであればsarなどから簡単に取得できるのですが、
今回はJavaのheapの使用状況をタイムスタンプ付きで確認する方法をご紹介します。

Javaのメモリ領域を監視できるコマンド【jstat, jps】
jps
jstat
という2つのコマンドを使用すると現在のJavaのヒープメモリの領域の使用状況がわかります

まずはjpsコマンドで現在JVM上で稼働しているプロセス情報を取得します
jpsで返却される番号は VMIDと呼ばれるものになります

C:Program FilesJavajdk1.7.0_07bin>jps.exe

それをjstatコマンドに食わせることでそのVMIDのプロセスのメモリ状況を閲覧することができます。
(下の例では、7888がVMIDになります。)

C:Program FilesJavajdk1.7.0_07bin>jstat.exe -gcutil -t 7888 1000

jstatのコマンドはメモリ使用量の概要を表しています
また、一番後ろの1000は一秒おきにストリーム表示してくれるパラメータです
タイムスタンプ列を出力の最初の列として表示します。タイムスタンプは、ターゲットJVMの起動時からの経過時間です。

しかし、起動時からの経過時間では無く、リアルタイムのタイムスタンプが欲しいところです。
これを実現するには gawkを使います。

jstat.exe -gcutil -t 7888 1000 | awk “{print strftime(“%y/%m/%d %H:%M:%S”), $0}” > heaplog_20150822.txt

こうする事で heaplog_20150822.txtにタイムスタンプ付きでログが記録されていきます。

15/08/22 16:08:02 Timestamp S0 S1 E O M CCS YGC YGCT FGC FGCT GCT
15/08/22 16:08:02 23012.3 99.94 0.00 56.09 67.89 98.13 96.20 62 3.247 19 3.251 6.498
15/08/22 16:08:03 23013.3 99.94 0.00 56.09 67.89 98.13 96.20 62 3.247 19 3.251 6.498
15/08/22 16:08:04 23014.3 99.94 0.00 56.09 67.89 98.13 96.20 62 3.247 19 3.251 6.498
15/08/22 16:08:05 23015.3 99.94 0.00 56.09 67.89 98.13 96.20 62 3.247 19 3.251 6.498
15/08/22 16:08:06 23016.3 99.94 0.00 56.09 67.89 98.13 96.20 62 3.247 19 3.251 6.498
15/08/22 16:08:07 23017.3 99.94 0.00 56.09 67.89 98.13 96.20 62 3.247 19 3.251 6.498
15/08/22 16:08:08 23018.3 99.94 0.00 56.09 67.89 98.13 96.20 62 3.247 19 3.251 6.498

読み方は下記の通りです。

ガベージ・コレクション統計データのサマリー

S0: Survivor領域0の使用率(現在の容量に対するパーセンテージ)。

S1: Survivor領域1の使用率(現在の容量に対するパーセンテージ)。

E: Eden領域の使用率(現在の容量に対するパーセンテージ)。

O: Old領域の使用率(現在の容量に対するパーセンテージ)。

M: メタスペースの使用率(現在の容量に対するパーセンテージ)。

YGC: Young世代のGCイベントの数。

YGCT: Young世代のガベージ・コレクション時間。

FGC: フルGCイベントの数。

FGCT: フル・ガベージ・コレクションの時間。

GCT: ガベージ・コレクションの総時間。

Comments are closed.