gihyo.jpサイトのロゴ

halookで始めるHadoop/HBaseトラブルシューティング

第9回ENdoSnipeを使ったトラブルシューティング

2013-09-09

前回までの連載で、ENdoSnipeの概要からセットアップ方法までを紹介してきました。今回はENdoSnipeを利用して、実際の問題検出から原因分析ができるまでのトラブルシュートの流れを紹介します。

問題解析の流れ

ENdoSnipeを用いて問題解析を行うフローは、以下のようになります。

0．ENdoSnipeの適用

ENdoSnipeのセットアップを行い、アプリケーション（サーバ）を起動します。詳細な手順は、前回の記事を参考にしてください。

1．問題の再現

アプリケーション上で、問題を発生させる操作を行います。たとえばWebアプリケーションであれば、ブラウザでの操作を行います。

2．Dashboardを利用した状況確認

FirefoxでENdoSnipeのDashboardにアクセスして、各種グラフで状況を確認したり、PerformanceDoctorの画面にて検出した問題の一覧を確認します。

3．ArrowVisionで発生箇所の特定

PerformanceDoctorの画面より問題の詳細ログをダウンロードします。ArrowVisionを利用して、この問題発生箇所を特定します。

これが問題解析の際の基本フローとなります。今回紹介する問題解析では、実際にこのフローに則って解析を進めます。

セットアップ

問題の解析に入る前に、セットアップを行いましょう。前回と同じく、以下の3台構成を想定して説明します。

  1. アプリケーションサーバ兼データベースサーバ
  2. ダッシュボードサーバ
  3. クライアントPC
図　マシン構成図
図　マシン構成図

1．アプリケーションサーバのセットアップ

サンプルアプリケーションを動作させるためのアプリケーションサーバに、JDK6.0、Tomcat7.0、PostgreSQL 9.2をインストールします。問題を含んだサンプルアプリケーションのwarファイルをgithubに置いていますので、実際に手を動かしながら試してみたいという方はダウンロードしてください。

また、サンプルアプリケーションの初期設定手順は、以下のURLに記載しています。

また、Tomcat7.0に対してJavelinを設定する必要がありますが、手順は前回の記事で紹介したため割愛します。

2．ダッシュボードサーバのセットアップ

情報収集・表示のためのダッシュボードサーバに、JDK6.0、Tomcat7.0、PostgreSQL 9.2をインストールします。このサーバ上でDataCollectorとDashboardを設定する必要があります。手順は前回の記事で紹介したため割愛します。

3．クライアントPCのセットアップ

クライアントPCにFirefoxをインストールします。また、検出した問題の詳細を確認するためにArrowVisionというEclipseプラグインを利用します。このArrowVisionもENdoSnipeの公式サイトよりダウンロードすることが可能です。

arrowvision.zipを解凍し、その中にあるjarファイルを全てEclipseのdropinsフォルダにコピーすれば、セットアップ完了です。なお、ArrowVisionの機能の一部は、ENdoSnipeの次期バージョンに組み込まれる予定をしており、そのバージョン以降を使う場合はArrowVisionのセットアップは必要ありません。

トラブルシューティングの実践

セットアップが完了したので、実際の問題の解析に進みましょう。今回扱う問題は、以下の3つです。

  1. ヒープメモリのメモリリーク
  2. SQLの性能問題
  3. ライブラリの誤った使い方

問題1：ヒープメモリのメモリリーク

Javaアプリケーションではヒープ領域と呼ばれるメモリ領域で、生成したオブジェクトの情報などを管理します。このヒープ領域では、定められたタイミングでGC（ガベージコレクション）が実行されることにより、不要なオブジェクトの情報が削除されます。しかしアプリケーションの作り方が悪かったり、利用しているライブラリの不具合などによって、ヒープ領域に不要なオブジェクトが残り続けてしまう、メモリリークと呼ばれる現象が発生します。このメモリリークが続くことで、ヒープ領域は圧迫されて最終的にはOutOfMemoryErrorが発生して、アプリケーションが止まってしまいます。

ヒープメモリやGCに関する説明は「Javaはどのように動くのか～図解でわかるJVMの仕組み」が詳しいです。

それでは、サンプルアプリケーションを利用してヒープメモリのメモリリークを発生させ、ENdoSnipeを利用して解析してみましょう。「⁠問題解析の流れ」で説明した通りの手順で進めます。

図　問題の再現
図　問題の再現

ブラウザでサンプルアプリケーションのURLにアクセスします。

  • http://(サンプルアプリケーションのサーバ)/demo/
図　サンプルアプリケーション
図　サンプルアプリケーション

このページで、「⁠問題1：メモリリーク」と書かれたリンクを数回クリックします。処理は普通に成功するため、何か問題が起きているようには見えないのですが、JMeterなどを用いて何百、何千回と繰り返しアクセスすると、OutOfMemoryErrorが発生します。

今回のサンプルアプリケーションでは問題を簡単に検出するため、5回以上クリックすれば、たとえOutOfMemoryErrorが発生していなくとも、メモリリークと見なせる問題が起こるように調整しています。

図　問題状況の確認
図　問題状況の確認

問題を発生させたら、次はENdoSnipeのDashboardを用いて状況を確認します。ヒープメモリのメモリリークが発生しているかどうかは、Dashboard上の「PerformanceDoctor」で確認ができます。以下の手順でPerformanceDoctorを開きます。

  1. 左側のツリーのクラスタ名か、サーバ名、エージェント名のいずれかをクリックします。
  2. 右側のウィンドウの「PerformanceDoctor」タブを選択します。
  3. 発生している問題の一覧が表示されます。
図　PerformanceDoctor
図　PerformanceDoctor

この問題一覧の中に、メモリリークの疑いがある旨のメッセージがあります。

図　メモリリーク
図　メモリリーク

ENdoSnipeは、CollectionやMapのサイズを監視して、一定以上のオブジェクト数になるとメモリリークの疑いがあることを検出しています。

図　発生箇所の特定
図　発生箇所の特定

PerformanceDoctorで問題を検出していることを確認できたら、続いて問題の発生箇所を特定します。問題一覧の中にDownloadのリンクがあり、このリンクより問題の詳細ログをダウンロードすることができます。ダウンロードしたログファイルは、ArrowVisionを用いて解析することができます。

  1. ArrowVisionをセットアップ済みのEclipseを起動します。
  2. Window - Open Perspective - Otherより「ArrowVision」を選択して開きます。
  3. メニューのArrowVisionより「ファイルを開く」を選択して、ダウンロードしたファイルを開きます。
図　ArrowVisionメモリリーク
図　ArrowVisionメモリリーク

ArrowVisionでは処理の流れを可視化することができますが、今回は問題解析のみに絞って説明するため、設定や詳細な説明は割愛します。

さて、ArrowVisionで問題の詳細ログを開くと、画面上に問題発生している箇所（黄色い丸のアイコン）が描画されているほか、右側のPerformanceDoctorのタブにも問題の一覧が表示されています。このいずれかをクリックすれば、左下の詳細ビューに詳細情報が表示されます。

詳細情報には、問題が発生した際のスタックトレースが記録されており、このスタックトレースに以下の記述が見つかります。

at jp.co.acroquest.gihyo.demo.service.ProblemService.insert(ProblemService.java:20)

このメソッドで行った処理が問題を引き起こしていることが分かります。この処理がメモリリークを引き起こしているのです。ENdoSnipeは、問題を検出した際にスレッドのダンプを取得して、呼び出し元を特定しているのです。ここまで解析できれば、実際にソースコードを見て検証してみましょう。

private static Map<String, Entity> cache = new HashMap<String, Entity>();
public void insert(Entity entity) {
	cache.put(entity.getId(), entity);
}

このソースコードを見れば、cacheという名前のクラス変数に延々とオブジェクトを追加し続けていることが分かります。これではヒープメモリのメモリリークが発生するのも当然です。キャッシュを作るのであれば、格納する上限数を決めたり、生存時間を決めておくなどの検討が必要です。

このサンプルアプリケーションはとてもシンプルな作りですので、最初からソースコードを見ても、すぐに問題に気づくことができるでしょう。しかし、ENdoSnipeを利用することで、ソースコードを一切見ることなく問題箇所を特定できるという事も分かったと思います。そのため、アプリケーションのソースコードがより複雑であればあるほど、ENdoSnipeによる解析の有効性が高まることが想像できます。

問題2：SQLの性能問題

続いて、SQLの問題を解析してみましょう。一般的なWebアプリケーションではデータベース（RDBMS）に対して、SQLを利用してデータの読み書きを行うことがほとんどです。アプリケーションの性能問題は八割方、このデータアクセスによって引き起こされていると言われることもあります。

それでは、サンプルアプリケーションを利用してSQLの問題を発生させ、解析しましょう。

図　問題の再現
図　問題の再現

サンプルアプリケーションにブラウザでアクセスして、「⁠問題2：フルスキャン」のリンクをクリックします。PostgreSQLをインストール済みで、接続設定もきちんとされていれば、特に問題なく処理が成功するはずです。先ほどのメモリリークの問題と異なり、この処理は何度繰り返してもまったく問題が発生しません。それでは、何の問題もないと言えるのでしょうか。念のため、ENdoSnipeで確認してみましょう。

図　問題状況の確認
図　問題状況の確認

先の問題解析と同じようにDashboardにブラウザでアクセスして「PerformanceDoctor」のタブを開きます。

図　フルスキャン
図　フルスキャン

いくつかの遅い処理と並んで、SQLのフルスキャンが発生している旨が警告されています。ENdoSnipeは、JDBCドライバ経由で発行しているSQLを監視して、さらにクエリの実行時に実行計画（Explain Plan）の取得と解析まで行うことで、このような問題を検出しています。

図　発生箇所の特定
図　発生箇所の特定

それでは、どの処理で問題が発生しているのか確認してみましょう。PerformanceDoctorの問題一覧から詳細ログをダウンロードして、ArrowVisionに読み込ませます。

図　ArrowVisionフルスキャン
図　ArrowVisionフルスキャン

読み込みを行い、右側のPerformanceDoctorより「テーブルのフルスキャンが発生している可能性があります」という警告メッセージをクリックすると、左下の詳細ビューに実際に発行しているSQLが表示されます。

SELECT
        T1_.ID AS C1_
        ,T1_.EMP_NO AS C2_
        ,T1_.EMP_NAME AS C3_
        (中略)
        ,T1_.VERSION_NO AS C8_
    FROM
        EMP T1_
    WHERE
        (
            dept_id = ?
        )

dept_idによる絞り込みを行っているようですが、これでフルスキャンが発生するということは、dept_idにインデックスが効いていないことがわかります。インデックスを有効にすれば、この問題は解消します。

また参考までに、このSQLを発行している箇所を探してみましょう。スタックトレースを少しさかのぼり、フレームワークやライブラリを呼び出している箇所を探すと、以下の記述が見つかりました。

at jp.co.acroquest.gihyo.demo.service.ProblemService.find(ProblemService.java:29)

実際にProblemServiceクラスの該当箇所のソースコードを見てみましょう。

List<Emp> empList = jdbcManager.from(Emp.class)
	.where("dept_id=?", dept.deptNo).getResultList();

S2JDBCを用いたDBアクセスですが、まさに上に書いた通りのSQLを発行するコードとなっています。このようにして、問題が発生したSQLを発行したアプリケーションのソースコードも特定することができます。

ここで検出したフルスキャンなどは、レコードの件数が増えればそれに比例してSQLの実行回数も増えるのですから、データ件数が大きくなった際にパフォーマンス問題が発生することは容易に想像ができます。逆に、データの件数が少ないうちは大して問題にならないため、単体テストや結合テストでは検出することが難しく、パフォーマンステストや、最悪の場合は運用が始まってから問題が発生することになりがちです。ENdoSnipeを用いてこのような問題を早期に検出して対応することで、アプリケーションの性能を底上げすることが期待できるのです。

問題3：ライブラリの誤った使い方

それでは最後のサンプルとして、ライブラリの使い方を誤るという問題の検出を行ってみましょう。

図　問題の再現
図　問題の再現

サンプルアプリケーションにブラウザでアクセスして、「⁠問題3：フレームワークの使い方」のリンクをクリックします。これもやはり問題なく処理が成功します。しかし先ほどのSQLの例と同じように、一見何の問題がなくても問題の種が潜んでいる場合がありますので、ENdoSnipeで確認してみましょう。

図　問題状況の確認
図　問題状況の確認

Dashboardにブラウザでアクセスして「PerformanceDoctor」のタブを開きます。

図　コンテナ初期化
図　コンテナ初期化

問題一覧の中に「S2コンテナの初期化を複数回行っている可能性があります。」というメッセージを確認できます。これはどういう意味でしょうか？ 問題の詳細を解説する前に、先にソースコードを見てしまいましょう。どこで問題が発生しているのかを確認するため、ArrowVisionを使って問題箇所を特定します。

図　発生箇所の特定
図　発生箇所の特定

問題一覧からダウンロードした詳細ログを、ArrowVisionで開きます。

図　ArrowVisionコンテナ初期化
図　ArrowVisionコンテナ初期化

詳細情報のスタックトレースは、以下のようになっています。

javelin.interval.stackTrace = 
	at org.seasar.framework.container.factory.SingletonS2ContainerFactory.init(SingletonS2ContainerFactory.java)
	at jp.co.acroquest.gihyo.demo.service.ProblemService.initContainer(ProblemService.java:37)
	at jp.co.acroquest.gihyo.demo.service.ProblemService$$EnhancedByS2AOP$$3fb088.$$initContainer$$invokeSuperMethod$$(ProblemService$$EnhancedByS2AOP$$3fb088.java)

どうやらProblemServiceクラスのinitContainerメソッドで先ほどの警告が発生していることがわかりました。実際にソースコードを見てみましょう。

SingletonS2ContainerFactory.init();
JdbcManager jdbcManager = SingletonS2Container
	.getComponent(JdbcManager.class);
// jdbcManagerを使ったDBアクセス処理（割愛）

別のクラスを呼び出すために、わざわざSeasar2のコンテナを初期化しています。このような記述は、書籍などのサンプルをそのまま書き写した場合に起こりやすい、開発現場あるあると言える問題です。

フレームワークの誤った使い方はメモリリークの原因になったり、パフォーマンスを低下させるなどの問題を引き起こします。ENdoSnipe 5.0では、Seasar2やSpring、Apache Commonsのいくつかのライブラリなどについて、典型的な誤った使い方を検出する機能を備えています。その他にも検出できる問題のうち特徴的なものを以下にリストアップします。

1．複数スレッドからの並行アクセスチェック

HashMapなど、複数スレッドから同時にアクセスすることで問題が起きるようなオブジェクトに対して、複数スレッドからのアクセスがあれば警告します。

2．Socketのリードタイムアウト未設定チェック

通信処理を行う際に、Socketのタイムアウトを設定しているかどうかを確認します。Socketタイムアウトを設定していなければ、相手サーバから応答がない場合に無限に待ち続けてしまいます。

3．GC発生回数/時間の閾値チェック

GCが過剰に発生していないか、時間が掛かりすぎていないかを検出します。

4．SQL中の結合利用回数の閾値チェック

パフォーマンスを低下させる原因になる、SQLでの過度なJOINを検出します。他にもUNIONやORも使いすぎている場合に警告します。

※リスト全体はENdoSnipeの紹介ページにて確認することができます。

いずれの警告も、アプリケーションの性能問題の原因としてよく見つかるものです。これらの警告は、実際にアプリケーションを動作させ、その動いた結果から問題を検出するENdoSnipeならではの検出項目と言えます。

最後に

3回に渡ってENdoSnipeの概要から実際の使い方まで紹介してきましたが、いかがだったでしょうか。ENdoSnipeは、セットアップに少し時間が掛かるなどまだまだ改善する余地こそありますが、問題を自動的に検出し、ソースコード上での発生箇所まで特定できるというのは、他のトラブルシュートツールにはない、使う価値のある特徴だと思います。

ここまでの紹介を見て魅力的だと思った方は、ぜひ利用してみてください。ENdoSnipeはオープンソースプロダクトですので、無償で利用できるほか、コミッタになって機能改善に参画しても良いでしょう。何ならpullリクエストしていきなりパッチを作ってしまっても構わないでしょう！

最後に、おまけとして開発者から聞いたENdoSnipeの今後のロードマップについて、簡単に紹介します。

ENdoSnipe 5.1（2013年9月頃）

  1. Apache、PHP、Ruby、Python、PostgreSQL、MySQLなどの非Javaアプリケーションへの対応
  2. CPU使用率が高くなった際にスレッドダンプを取得する機能を追加
  3. ArrowVisionの機能（一部）をDashboardに統合

ENdoSnipe 6.0（2014年初前半）

  1. APM（Application Performance Manager）としての機能強化
  2. 有償版のみにあるArrowVision、BottleneckEyeの機能を移植

それでは、今回でENdoSnipeの紹介を終わり、次回からはhalookの紹介に戻ります。次回もお楽しみに！

おすすめ記事

記事・ニュース一覧