こんにちは!SI部の満石です。

以前、仕事でJRockit Flight Recorder(現在OracleJDKに付属しているJava Flight Recorderの元になったもの)を使ったことがあり、最近出てきたHeapStatsにも興味があって使ってみたのでご紹介します。

HeapStatsとは

NTT OSSセンタが開発したOSS(Open Source Software)であり、HeapStatsの日本語Wikiには以下のとおりに書かれています。

HeapStats とは、JavaVM のヒープやGC状況を監視する軽量なツールで、エラーの兆候を検知してSNMPのようなリアルタイムなアラートを発します。生成するログはかなり小さいもので、GUIツールで解析することができます。HeapStatsは、次の二つのプログラムで構成されます:

  • エージェント(agent) – JavaVMの情報を収集するJVMTIエージェントプログラムです。
  • アナライザ(analyzer) – 上記の情報を解析する Javaアプリケーションプログラムです。

また、「Javaアプリケーションの開発から運用までの頼れる助っ人HeapStats」(NTT技術ジャーナル online)[PDF]という記事に詳細や事例が書かれていました。こちらも合わせて御覧ください。

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

エージェントが動作可能な環境はOSはLinuxのみで、JavaはOpenJDK6またはOracleJDK6以降となっています。インストール方法の詳細はHeapStatsのコミッタの方のブログにHeapStatsの紹介スライドとともに説明があったのでそちらも参照してください。今回エージェントをインストールした環境は以下のとおりです。

  • OS: CentOS 6.5 64bit (Windows 8.1上のVirtualBoxで稼働)
  • Java: Java SE 7 Update 55 (Oracle HotSpot VM)

エージェントのバージョンは最新の1.1.1、OSはCentOS 6.5 64bitを使用するため以下のファイルをダウンロードしました。

http://icedtea.wildebeest.org/download/heapstats/heapstats-1.1.1/bin/agent/el6/x86_64/heapstats_agent-1.1.1-1.el6.x86_64.rpm

root権限で以下のコマンドでインストールしました。

# rpm -ivh heapstats_agent-1.1.1-1.el6.x86_64.rpm

エージェントで監視するアプリケーションを実行

エージェントで監視を行うには監視対象のアプリケーションを実行する際の起動オプションに「-agentlib:heapstats」を指定します。上記のNTT技術ジャーナル onlineの記事に「Java実行環境のパフォーマンスを測定する標準的なベンチマ ー クSPECjvm2008を用いてHeapStatsの使用有無でスコア比較したところ、オーバーヘッドは4.51%にまで抑えられていました」とあるとおり、低オーバーヘッドなので本番環境でも安心して常時エージェントを使用可能です。今回はOutOfMemoryErrorが発生するまでの様子をエージェントに記録させたいので、以下のプログラムを作成しました。最初はゆっくりヒープサイズを増やすためにループの中でThread.sleep()を使ったのですが、Thread.sleep()自体のオーバーヘッドのおかげで指定した時間以上に処理が止まってしまい一向にヒープサイズが増えなかったため、以下のような実装となりました。10分程度で512MBのヒープ領域を使い果たしてOutOfMemoryErrorが発生するように調整しています。

OOMESample.java


package com.example;

import java.util.ArrayList;
import java.util.List;

public class OOMESample {

    public static void main(String[] args) {
        List<Hoge> list = new ArrayList<>();
        long i = 0;
        while (true) {
            // ゆっくりヒープサイズが増加するように調整
            if (i++ % 2000 == 0) list.add(new Hoge());
        }
    }
}

Hoge.java


package com.example;

public class Hoge {

}

実行コマンドはこちら。

$ java -Xmx512m -agentlib:heapstats com.example.OOMESample

HeapStatsのログファイルは、カレントディレクトリに「heapstats_log.csv」、「heapstats_snapshot.dat」、「heapstats_analyze140523134114.zip」の3ファイルが作成されました。「heapstats_log.csv」は統計データ、「heapstats_snapshot.dat」はJavaヒープスナップショットでこの2ファイルはエージェントが監視対象のアプリケーション状況を記録し続けるログファイル、「heapstats_analyze140523134114.zip」は障害発生時のみ作成される障害解析関連アーカイブファイルで、ファイル名の数値は年(2桁)月日時分秒となっています。

ログの出力先等、エージェントの設定を変更するには /etc/heapstats/heapstats.conf (RPMパッケージからインストールした場合)を編集します。エージェントの設定内容の詳細については、HeapStats日本語Wikiのこのページを参照してください。

アナライザのインストール

アナライザはJavaがOpenJDK6またはOracleJDK6以降であれば使用可能です。今回アナライザをインストールした環境は以下のとおりです。

  • OS: Windows 8.1
  • Java: Java SE 7 Update 51 (Oracle HotSpot VM)

HeapStats 1.1.1のアナライザは以下のファイルをダウンロードしました。

http://icedtea.wildebeest.org/download/heapstats/heapstats-1.1.1/bin/analyzer/heapstats-analyzer-1.1.1.zip

アナライザの実行にはJGraphX、JFreeChart、JCommonが必要なのでこれらもダウンロードします。

JGraphXは https://github.com/jgraph/jgraphx/tags から執筆時点の最新バージョンである v2.8.0.0をダウンロードしました。

JFreeChartは http://sourceforge.net/projects/jfreechart/files/ から執筆時点の最新バージョンである 1.0.17をダウンロードしました。

JCommonはJFreeChartに同梱されています。

アナライザのzipファイルを解凍したらその中にあるlibフォルダに、jgraphx.jar、jfreechart-1.0.17.jar、jcommon-1.0.22.jarを格納しました。

アナライザの使い方

アナライザの起動

アナライザの起動は、heapstats.jar をダブルクリックするだけです。

起動するとメニューが英語ですが、heapstats.propertiesの language=en を language=ja に変更して起動することでメニューを日本語に変更することが出来ます。その他のheapstats.propertiesの設定内容についてはHeapStats日本語Wikiのこのページを参照してください。

以下、メニューの言語は日本語で起動したことを前提として解説します。また、各表示項目についてはアナライザのzipファイルに入っている「howtouse_ja.txt」に日本語で詳細が書かれているのでそちらを参照してください。

起動すると以下の画面が表示されます。「収集ログ」と「スナップショット」の2つのタブがあるのがわかります。

analyzer1

「収集ログ」タブ

まず収集ログを「ファイル選択」ボタンを押下して、統計データファイルの「heapstats_log.csv」を読み込みます。読み込むと「期間選択」の欄に記録された全期間を指定可能な値が設定されます。「収集ログ」タブの中にはさらに「リソース情報表示」タブと、「収集ログ詳細表示」タブがあります。

「リソース情報表示」タブ

そのまま「OK」ボタンを押下すると、「リソース情報表示」タブには「Java CPU使用率」、「システム CPU使用率」、「Java メモリ使用量」、「スレッド」の4つのグラフと「プロセスサマリー」の表が表示されます。グラフの右端が白くなっているのは、最古の障害解析関連アーカイブファイルが存在する時間が選択状態となるためです。また、今回はwhile文でひたすらループしているため、2コアの仮想CPUの片方のコアが100%になっているのがよくわかりますね。

analyzer2

また、「期間選択」の欄をクリックすると選択可能な時間がリスト表示されるので、これを利用して表示したい期間を絞り込むことが出来ます。

analyzer3

グラフの表示領域については右クリックでズームインやズームアウトを選択できる他、縦方向にドラッグすることでその縦の範囲に拡大することも出来ます。以下は「Javaメモリ使用量」のRSSのグラフだけを拡大してみた例です。

analyzer4

「Java CPU率」と「システム CPU使用率」の両方がグラフで見ることができるため、CPU使用率が高い場合にその原因はJavaなのかJava以外なのか、その現象はいつから、またはいつ発生しているかが一目瞭然です。「Javaメモリ使用量」についてはスナップショットタブで詳細が見れるのでこの画面で他のグラフとの関連性を確認するくらいでしょうか。「スレッド」については異常にthreadsの値(※Javaアプリケーションの動作中スレッドの数)が増加していないか、monitorの値(※Java内部でモニタ競合が発生した回数)が継続的に高い値になっていないか等を確認することになると思います。いずれにせよ、日中や夜間、週末などシチュエーション別の平常時の値を日頃から確認しておき、異常かどうかを判断できるようになっておくことが大切です。

「収集ログ詳細表示」タブ

このタブは障害解析関連アーカイブファイル(※今回は「heapstats_analyze140523134114.zip」)が統計データファイル(※今回は「heapstats_log.csv」)と同じ場所にある場合に限り、情報が表示されます。今回は障害解析関連アーカイブファイルがあるので以下のように表示されました。

analyzer5

表の「…」ボタンを押下すると、右側のテキストエリアに詳細を表示します。以下は「VmArgs」の「…」ボタンを押下してみた例です。

analyzer6

障害発生時に後からこのような情報を収集する手間が省けるのは嬉しいですね。また、「howtouse_ja.txt」によるとログトリガーがデッドロック検知の場合に「ThreadDump」の項目が追加され、スレッドダンプの情報を表示可能になるようです。

「スナップショット」タブ

「収集ログ」タブと同様に「ファイル選択」ボタンを押下して、エージェントが記録したログファイルの「heapstats_snapshot.dat」を読み込みます。読み込むと「期間選択」の欄に記録された全期間を指定可能な値が設定されます。そのまま「OK」ボタンを押下すると、グラフや表が生成されます。「スナップショット」タブの中にはさらに「統計情報表示」タブ、「差分表示」タブ、「スナップショット表示」タブ、「参照情報表示」タブの4つのタブがあります。

「統計情報表示」タブ

このタブには「統計チャート」、「メタスペースチャート」の2つのグラフと、「サマリー」表が表示されます。今回はゆっくりヒープサイズが増加していきOutOfMemoryErrorが発生するようにしましたが、「統計チャート」にはまさにその様子が表示されています!

analyzer7

「統計チャート」に表示されるヒープの使用量はGC後の値です。少なくともGC後のヒープサイズが最大ヒープサイズの半分を超えないように最大ヒープサイズを設定したほうがいいでしょう。最適なヒープサイズはGCアルゴリズムやアプリケーションの特性によって異なるため、設定変更→測定を繰り返して最適なヒープサイズを探ることになります。また、このグラフが右肩上がりとなっている場合はメモリリークを起こしていることになります。HeapStatsを使ってメモリリークの原因を探る方法については後述します。そして、見えづらいですが黄色の線がGC停止時間です。GC停止時間は許容できる停止時間を超えているものがないか確認してください。

「メタスペースチャート」は最近実装されたもののようで「howtouse_ja.txt」に説明がありません。おそらくJava6、Java7の場合はPermanent領域、Java 8の場合はMetaspace領域の容量と使用量のグラフが表示されているものと思われます。使用量が右肩上がりになっていないか、十分な容量が確保されているかという観点で確認しましょう。

「サマリー」には上記2つのチャートのサマリーが記載されています。GC回数はFull GCとYoung GCの内訳が表示されています。通常はYoung GCの回数の方がFull GCの回数よりもずっと多くなります。そうなっていない、もしくはそうなっていない時間帯がある場合は要注意です。

「差分表示」タブ

このタブには「差分ランクチャート」、「ヒープ使用量チャート」の2つのグラフ、「オブジェクト一覧」表があり、それらに対して表示内容の操作を行う「クラスフィルタ」、「クラス検索」の機能があります。初期表示は以下のように「ヒープ使用量」チャートだけが展開されています。

analyzer8

このタブでは「期間選択」で選択した期間のヒープ使用量の差分と使用量のランキングを表示します。また、「クラスフィルタ」によって除外するクラスやパッケージを指定したり、「クラス検索」で表示対象のクラスを部分一致で絞り込むことが出来ます。あらかじめ「クラスフィルタ」でライブラリやアプリケーションサーバーに含まれるパッケージを除外しておいて、「クラス検索」で増加傾向のクラスを探すという使い方をすることが出来るので便利です。

「スナップショット表示」タブ

このタブには「スナップショット情報」、「オブジェクト一覧」の2つの表と、「ヒープ使用量チャート」円グラフが表示されます。初期表示時は、選択期間内の最古のスナップショットの情報が表示されます。

analyzer9

スナップショットの時間を変更したい場合は、「統計情報表示」タブや「差分表示」タブ内にある各チャートのグラフ部分をクリックするとその部分が選択状態として白くなり、「スナップショット表示」タブの内容はその時間の情報に変わります。スナップショットの時間を最後の時間にしてみます。「差分表示」タブのヒープ使用量チャートで最後の時間をクリックしてみました。

analyzer10

すると、「スナップショット情報」の内容が選択した時間の内容に変わります。また、今回は実行したプログラムがひたすら同じオブジェクトをListにaddし続けるだけなので、円グラフの見た目はほとんど変わっていませんが、インスタンス数やサイズの値が増えています。

analyzer11

「オブジェクト一覧」表を見ると、com.example.Hogeクラスのインスタンスが大量に存在することがわかります。今回はなぜなのかは明らかですが、com.example.Hogeクラスのインスタンスがどのクラスから参照されているのか調べてみることが出来ます。その調査は「参照情報表示」タブで行います。「参照情報表示」タブは初期表示だと何も表示されていませんが、「オブジェクト一覧」で参照情報を表示したいオブジェクトの行をダブルクリックすると、そのオブジェクトが赤色の楕円で表示されます。また、「差分表示」タブの「オブジェクト一覧」でオブジェクトの行をダブルクリックしても同様のことが行えます。

analyzer12

この赤色の楕円をクリックするとそのオブジェクトを参照しているオブジェクトが展開されます。展開されたオブジェクトをクリックするとさらにそのオブジェクトを参照しているオブジェクトが展開されます。

analyzer13

展開していくとArrayListのヒープサイズが巨大であるため、ArrayListがcom.example.Hogeクラスのインスタンスを大量に保持していることがOutOfMemoryErrorの発生原因であることがわかりました。このような方法でHeapStatsを利用してメモリリークの原因を早期に特定することが出来ます。

HeapStatsを使ってみて

以前使ったことのあるJRockit Flight Recorderと比較するとUIの面では大きく見劣りするものの、OSSでこれだけの情報が低オーバーヘッドで常時取得可能なのは大きな魅力だと感じました。費用の面でJava Flight Recorderを導入できないようなプロジェクトではこのHeapStatsの導入をぜひお勧めしたいです。アナライザについてはJava8 + JavaFX8で鋭意開発中のようなので、使い勝手が大きく改善されることを期待しています!