Perf4Jを使ったパフォーマンス解析とモニタリング

作者 Alex Devine , 翻訳者 編集部 投稿日 2009年5月26日

セクション

デベロップメント,

設計/アーキテクチャ

トピック

パフォーマンス&スケーラビリティ ,

Java

タグ

性能評価

原文(投稿日：2009/4/23)へのリンク

「アプリケーションの高速性やスケーラビリティに間違いのないことをステージング環境で時間をかけて確認したのに、その後プロダクションに入った途端に、どういうわけかパフォーマンスが急降下する」 -- これはまさに多数の開発者に馴染み深いマーフィーの法則です。さらに都合の悪いケースになると、通常は速いのに、上司や、動作について苦情を言う重要な顧客から見た場合に限って、いつもノロノロした動作になります。こうした断続的なパフォーマンスボトルネックを追跡するには、詳細なロギングと解析が必要不可欠です。

しかし、サービス指向アーキテクチャと広範囲に分散したアプリケーションで成り立っている現状では、パフォーマンスボトルネックの原因となっているコンポーネントの発見は非常に難しいことがあります。典型的なWeb 2.0スタイルのアプリケーションで比較的よく見られるシナリオについて、サーバーに何が起こるかを考えてみましょう。

1. 着信Webリクエストが、応答の生成を担当するコンポーネントにディスパッチされる。
2. そのリクエストをLDAPサーバーで認証しなければならない場合もあり得る。
3. コントローラコンポーネントがデータベースに対してクエリする。
4. コントローラコンポーネントはサードパーティのWebサービスも呼び出す。
5. コントローラコンポーネントは検索した全データをビジネスオブジェクト群としてまとめ、表示する。
6. ビジネスオブジェクトはレンダリングされ、ユーザーのブラウザに応答が送られる。
7. ブラウザ上で動作しているAJAXコードが、追加のリクエストをサーバーに送り返す。

「なぜ私のWebページは遅いのか？」という質問に答えるには、多数のコンポーネントと実行プランを調査する必要があり、さらに、プロダクション内の全アプリケーションコンポーネントから詳細なパフォーマンスデータが必要になります。

Perf4Jは、サーバーサイドでJavaのコードタイミング・ステートメントを追加したり、結果のロギングや解析、モニタリングをしたりする、オープンソースのツールセットです。log4jやjava.util.loggingといったロギングフレームワークに精通している開発者にとっては、Perf4Jの説明に類似性が役立ちます。

Perf4JのSystem.currentTimeMillis()に対する関係は、log4jのSystem.out.println()に対する関係と同じである。

これがPerf4Jの理解にどう関係があるのでしょうか。Java向けの優れたロギングフレームワークが広く利用可能になる前の古き悪しき時代、私たち開発者の大部分がロギングステートメントを追加した方法を考えてみてください。System.out.println()を「手軽なデバッガ」 -- ロギング情報を出力するための間に合わせの方法として使いました。すぐに、これでは不十分と分かりました。ロギングステートメントを専用のログファイル（異なる複数のファイルの可能性もあり）に向かわせ、おそらくそうしたログファイルを毎日ロールさせたかったのです。異なるレベルの重要性を異なるロギングステートメントに割り当てる能力や、コードをまったく変更することなく、特定の環境で特定のログステートメントのみを書いたり、異なる環境でログステートメントのフォーマットを変更したりするオプションを求めていました。そのため、log4jが提供する豊富な機能群が生まれるきっかけとなったのは、ロギングステートメント向けに「より優れた」System.out.println()が欲しいという願望でした。

同様に、Javaの新入り開発者がコードにパフォーマンスロギングを追加する必要性を見つけると、頻繁に以下のような処理をします。

long start = System.currentTimeMillis();
// execute the block of code to be timed
log.info("ms for block n was: " + (System.currentTimeMillis() - start));

ところが、こうした開発者はその後、平均偏差、最小偏差、最大偏差、標準偏差や、決められた期間におけるトランザクション／秒などといった、まとまった性能統計のような情報が欲しいことに気付きます。こうした数値のグラフをリアルタイムで入手できたら、実行中のサーバーの問題を検知可能ですし、JMXを通じてパフォーマンスのメトリクスを公開すれば、パフォーマンス低下の際に警告するモニターを設定できます。さらには、log4jのような広く使われているロギングフレームワークと自らのタイミングステートメントがうまく連携するようにしたいのです。

Perf4Jの目標は、こうした機能を簡単に統合できる（そして簡単に拡張可能な）オープンソースのパッケージとして提供することです。Perf4JはHomeaway.comで開発されましたが、Homeaway.comのインフラは広く分散した性質を持っており、その上、このWebサイトには高可用性、高パフォーマンスという必要条件もあるので、徹底的なパフォーマンス解析が必要となります。Perf4Jの重要機能には以下が含まれます。

• 簡潔なタイミングステートメント向けの単純なストップウォッチ・メカニズム。
• 生のログファイルから総合的な統計とパフォーマンスグラフを生成するためのコマンドラインツール。
• 実行中アプリケーションにおいて統計とグラフを生成するカスタムのlog4jアペンダ。java.util.loggingとlogbackについては、次回以降のリリースでのサポートを予定。
• パフォーマンス統計値をJMX属性として公開し、統計値が指定のしきい値を超えた場合に通知を送付する機能。
• AspectJやSpring AOPなどのAOPフレームワークと連動した場合にも支障のない、タイミングステートメントを可能にする@Profiledアノテーションならびにカスタムアスペクトの一式。

これからお見せする例では、ほとんど労力を使わずに、いかにしてこうした機能を利用できるかにスポットライトを当てます。コードベースにPerf4Jを統合する方法の詳細については、Perf4J Developer's Guide（Perf4J開発者ガイド）をご覧になるようお勧めします。

StopWatchを使ったコードブロックの時間計測

org.perf4j.LoggingStopWatchクラスは、コードへのタイミングステートメントの追加と、出力ストリームやログファイルへのステートメントのプリントに使用されます。

StopWatch stopWatch = new LoggingStopWatch();
//... execute code here to be timed
stopWatch.stop("example1", "custom message text");	

stop()メソッドへの呼び出しは、実行時間を記録し、ログメッセージをプリントします。デフォルトでは、ベースのLoggingStopWatchクラスはSystem.errストリームに出力をプリントします。しかしほとんどの場合、Log4JStopWatchやCommonsLogStopWatch、Slf4JStopWatchといった人気のあるJavaロギングフレームワークもしくはロギングファサードに一体化するLoggingStopWatchサブクラスを使った方がよいでしょう。ストップウォッチの出力サンプルをいくつか以下に挙げました。

start[1233364397765] time[499] tag[example1] message[custom message text]
start[1233364398264] time[556] tag[example1] message[custom message text]
start[1233364398820] time[698] tag[example1] message[custom message text]

Log Parserを使って統計とグラフを作成

デフォルトのストップウォッチ出力が、System.currentTimeMillis()の直接呼び出しを大きく改善したことにはなりませんが、本当のメリットはこの出力を解析して総合的な統計とグラフを作成できることから生まれます。LogParserは、タグとタイムスライスで出力をグループ化し、詳細な統計情報を生成し、オプションとして、Google Chart APIを用いて時系列グラフを生成します。デフォルトのテキストフォーマット（csvフォーマットもサポート）を使ったサンプル出力は以下のとおりです。

Performance Statistics   20:32:00 - 20:32:30
Tag                                                  Avg(ms)         Min         Max     Std Dev       Count
codeBlock1                                             249.4           2         487       151.3          37
codeBlock2.failure                                     782.9         612         975       130.8          17
codeBlock2.success                                     260.7           6         500       159.5          20

Performance Statistics   20:32:30 - 20:33:00
Tag                                                  Avg(ms)         Min         Max     Std Dev       Count
codeBlock1                                             244.0           7         494       150.6          41
codeBlock2.failure                                     747.9         531         943       125.3          21
codeBlock2.success                                     224.1          26         398       106.8          21

Performance Statistics   20:33:00 - 20:33:30
Tag                                                  Avg(ms)         Min         Max     Std Dev       Count
codeBlock1                                             289.3          10         464       141.1          22
codeBlock2.failure                                     781.1         599         947       135.1           8
codeBlock2.success                                     316.2         115         490       112.6          13

平均実行時間とトランザクション／秒のグラフは、Google Chart Serverに対するURLとして生成されます。

LogParserはデフォルトで標準入力から読み込むので、動作中のサーバーからLogParserへログファイルをパイプすることにより、生成された出力をリアルタイムで入手できます。

tail -f performance.log | java -jar perf4j-0.9.8.1.jar	

Log4Jと直接統合

Perf4Jの拡張機能の多くは、log4jのカスタムアペンダ群を介して利用可能になります。これにより開発者は、多数のJava開発者に馴染み深いロギングフレームワークを介して、解析・モニタリング機能を漸次追加できるようになります（そしてPerf4Jの将来のバージョンでは、カスタムのlogbackアペンダとjava.util.loggingハンドラが提供されます）。そうした価値ある機能性により、Perf4JはJMX MBeans上でパフォーマンスデータを属性として公開し、許容されるしきい値をパフォーマンスが下回った際には、JMXに通知を送付できるようにします。Javaアプリケーションの管理とモニタリングではJMXが標準インターフェースとなったので、Perf4J MBeanの公開により、サードパーティ製のモニタリングアプリケーションが提供する様々な機能へと、選択の道が開かれます。たとえば、Homeawayでは、IT部門はシステムモニタリングをNagiosとCactiに標準化しています。両ツールともMBeansをデータソースとしてクエリすることをサポートしています。

以下のlog4j.xmlサンプルファイルを見れば、JMX向けにPerf4Jアペンダを有効にする方法がわかります。

<?xml version="1.0" encoding="UTF-8"  ?>
	<!DOCTYPE log4j:configuration SYSTEM "log4j.dtd">


	<log4j:configuration debug="false"  xmlns:log4j="http://jakarta.apache.org/log4j/">


	    <!-- Perf4J appenders -->
	    <!--
	      This AsyncCoalescingStatisticsAppender groups  StopWatch log messages
	      into GroupedTimingStatistics messages which it  sends on the
	      file appender and perf4jJmxAppender defined  below
	    -->
	    <appender name="CoalescingStatistics"
	               class="org.perf4j.log4j.AsyncCoalescingStatisticsAppender">
	        <!--
	          The TimeSlice option  means timing logs are aggregated every 10 secs.
	        -->
	        <param name="TimeSlice"  value="10000"/>
	        <appender-ref  ref="fileAppender"/>
	        <appender-ref  ref="perf4jJmxAppender"/>
	    </appender>


	    <!--
	      This file appender is used to output aggregated  performance statistics
	      in a format identical to that produced by the LogParser.
	    -->
	    <appender name="fileAppender"  class="org.apache.log4j.FileAppender">
	        <param name="File"  value="perfStats.log"/>
	        <layout  class="org.apache.log4j.PatternLayout">
	            <param  name="ConversionPattern" value="%m%n"/>
	        </layout>
	    </appender>


	    <!--
	      This JMX appender creates an MBean and publishes  it to the platform MBean
 server by
	      default.
	    -->
	    <appender name="perf4jJmxAppender"
class="org.perf4j.log4j.JmxAttributeStatisticsAppender">
	        <!-- The tag names whose  statistics should be exposed as MBean attributes. -->
	        <param name="TagNamesToExpose"  value="firstBlock,secondBlock"/>
	        <!--
	          The  NotificationThresholds param configures the sending of JMX notifications
	          when statistic values  exceed specified thresholds. This config states that
	          the firstBlock max value  should be between 0 and 800ms, and the secondBlock max
	          value should be less  than 1500 ms. You can also set thresholds on the Min,
	          Mean, StdDev, Count and  TPS statistics - e.g. firstBlockMean(<600).
	        -->
	        <param name="NotificationThresholds"  value="firstBlockMax(0-800),secondBlockMax(<1500)"/>
	    </appender>


	    <!-- Loggers -->
	    <!-- The Perf4J logger. -->
	    <logger name="org.perf4j.TimingLogger"  additivity="false">
	        <level  value="INFO"/>
	        <appender-ref  ref="CoalescingStatistics"/>
	    </logger>


	    <!--
	      The root logger sends all log statements EXCEPT  those sent to the perf4j
	      logger to System.out.
	    -->
	    <root>
	        <level  value="INFO"/>
	        <appender  name="console" class="org.apache.log4j.ConsoleAppender">
	            <layout  class="org.apache.log4j.SimpleLayout"/>
	        </appender>
	    </root>
	</log4j:configuration>

Perf4JはJMXアペンダのほかにも、Perf4Jのグラフ化サーブレットを利用するWebフロントエンドを介して公開可能なパフォーマンスグラフを生成する、グラフ化アペンダも提供します。カスタムのcsvレイアウトにより、Excelや他のスプレッドシートプログラムに簡単にインポートできます。

@Profiledアノテーションを使った実行に支障のないパフォーマンスロギング

コードにパフォーマンスロギングのステートメント（ならびに、ロギングステートメント一般）を追加した場合のデメリットの１つに、コードの「全情報と有用情報」比（SN比）が低下し、特定のコードブロックのクリティカルなビジネスロジックの追跡がいっそう難しくなってしまうことがあります。この軽減に役立つように、Perf4Jは@Profiledアノテーションを提供しますが、実行時間をログすべきメソッドにこのアノテーションを追加することにより、そのメソッド本体にはStopWatchコードを入れないですみます。

@Profiled(tag = "dynamicTag_{$0}")
public void profiledExample(String tagSuffix) {
    ... business logic only here
}
	

@Profiledアノテーションの追加がすめば、AspectJやSpring AOPといったアスペクト指向のプログラミングフレームワークを使って、Perf4Jのカスタムタイミング・アスペクトを有効化できます。このアスペクトは、StopWatchインスタンスの作成と停止を行うバイトコードを使って、メソッド呼び出しを取り囲みます。AspectJのロード時ウィービング機能を使って、ランタイムの特定クラスについてタイミング・アスペクトを選択的に有効化することさえ可能です。ですから、ロードタイム・ウィービングを使うことにより、プロファイリングを作動させていないメソッドに対して、オーバーヘッドが発生することは絶対にありません。

単純な例：Webベースの素数ジェネレータ

この例では、Perf4Jライブラリがもつ機能の大部分を説明する、実際のアプリケーションの作成ステップを最初から最後までお見せします。自分でこのアプリケーションを実行するには、perf4jPrimes.warファイルをダウンロードし、サーブレットコンテナで実行します。warファイルには、アプリケーションを作成するために使われたソースコードも入っているので、ご注意ください。

単純にする目的で、この例にはメインコードファイルが2つしか入っていません。生成された素数を表示し、ユーザー指定のパラメータの受け入れに使用するprimes.jspファイルと、実際の生成コード（その大部分はjava.math.BigIntegerクラスにデレゲートされます）が入っているPrimeNumberGeneratorクラスです。コードブロックの時間計測にPerf4Jを使用する場所が3つあります。

1. Log4JStopWatchがコードで作成され、primes.jspファイル内のページ全体の生成時間を計測する。
2. PrimeNumberGenerator.generatePrime()メソッドにはProfiledアノテーションがついている。
3. PrimeNumberGenerator.randomFromRandomDotOrg()メソッドにもProfiledアノテーションがついている。

WEB-INF/classes/log4j.xmlファイルを見れば、Perf4Jの以下の機能が有効化されたことがわかるでしょう。

1. 個々のストップウォッチログはすべて、標準出力に書き込まれることになる（サーブレットコンテナが標準出力をディスク上のファイルにパイプすることもあるので、注意）。必要なら、この出力に対してLogParserを直接使える。
2. AsyncCoalescingStatisticsAppenderが作成されて、ストップウォッチログを集め、そのログをダウンストリームの複数のGraphingStatisticsAppenderと1つのJmxAttributeStatisticsAppenderに送付する。
3. GraphingStatisticsAppenderを2つ作成完了。1つは平均実行時間を出力し、もう1つはトランザクション／秒を出力する。

WebサーバーでこのWebアプリケーションをいったん起動すれば、http://servername/<rootcontextlocation>/primes.jspの素数生成ページにアクセス可能になり、そのページではWebサーバーの設定によってrootContextLocationが決定されます（簡単なアクセスで、http://servername/<rootcontextlocation>/PrimeNumberGenerator.javaでもPrimeNumberGeneratorソースコードを見ることができます）。primes.jspページでは、素数を生成する方法を決定する様々なパラメータをお見せします。パラメータを変更し、「Generate Prime Number」（素数を生成）ボタンをクリックすれば、数の生成に要する時間にパラメータがいかに影響しているかがわかります。数をたくさん生成した後は、Perf4Jの出力を以下の3ヵ所で見られるはずです。

1. 生ログの出力は標準出力へ送られる。
2. グラフ化サーブレットはhttp://servername/<rootcontextlocation>/perf4jGraphsで有効化されている。このサーブレットをヒットすれば、平均実行時間とトランザクション／秒を示したグラフが見られるはずである。
3. JMXモニタリングも有効化されている。Java SDK付属のjconsoleアプリケーションを使ってPerf4J MBeanの値が見られる。-Dcom.sun.management.jmxremoteのJavaコマンドライン・オプションを使ってWebサーバーを起動する必要がある。その後、サーバーを実行しているのと同じマシン上でjconsoleを起動すれば、「MBeans」タブの下に「org.perf4j.StatisticsExposingMBean.Perf4J」のデータ値が見られるはずである。

この時点では、@ProfiledアノテーションをサポートするTimingAspectsをまだ1つも有効化していないので、表示される唯一のストップウォッチ出力は「fullPageGeneration」タグ向けになります。TimingAspectsを有効化するには、AspectJのロード時ウィービングを利用できます。有効化するには、次のようなAspectJのウィービングエージェント・コマンドライン・パラメータを使って、Webサーバーを起動する必要があります。

-javaagent:/path/to/aspectjweaver-1.6.1.jar

以下のアドレスで、このjarをダウンロードできます。http://mirrors.ibiblio.org/pub/mirrors/maven2/org/aspectj/aspectjweaver/1.6.1/aspectjweaver-1.6.1.jar

エージェントが有効化されると、「generatePrime」と「randomFromRandomDotOrg」のタグ名にストップウォッチ出力が表示されるはずです。

落とし穴とベストプラクティス

アプリケーションをモニタリングする多数の試みにおいて、パフォーマンスや安定性、セマンティックの正確性など、そのモニタリングの目的にかかわらず、意図されたメリットを最適にもたらすことに失敗しています。その原因は、集めた情報が膨大すぎて、データの洪水の中を進むのが難しくなってしまうか、必須の情報が最も必要とされるポイントで十分に情報収集されていないかのどちらかです。そして、あらゆるモニタリングでいくらかのオーバーヘッドが発生しますが、パフォーマンスモニタリングについては、追加の間接費に特に敏感であるべきです。以下に挙げた秘けつは、意図しない影響を最小に抑えながら、Perf4Jを最大限活用するのに役立つでしょう。

1. プロファイルするメソッドやコードブロックを決定する際には、まず大物に焦点を合わせましょう。企業アプリケーションでは、パフォーマンスボトルネックとなると「容疑者の常連」が多数存在します。 -- データベース呼び出し、リモートメソッド呼び出し、ディスクI/O、大きなデータセットに作用する重量級のコンピュータオペレーションです。したがって、プロファイリングの対象を決定する際には、こうした種類のオペレーションに焦点を合わせるべきです。さらに、こうしたオペレーションには一般に何十?何百ミリ秒といった時間がかかるので、Perf4Jでこうしたオペレーションに追加発生するオーバーヘッドは、ネイティブの実行時間と比べて桁違いに小さく、実用目的では無視できます。実際、Perf4Jでコードブロックの時間をこっそり計測するのに、（System.nanoTimeではなく）System.currentTimeMillisを意図的に使う理由の1つがこれです。 -- 企業アプリケーションにおいて、問題を起こす可能性が高い種類のコードブロックの時間計測を行う際は、ナノ秒の粒度を求めるべきではありません。
2. Perf4Jはパフォーマンス解析を別個のスレッドやプロセスにオフロードするように設計されています。AsyncCoalescingStatisticsAppenderを使用する際、実行スレッドがログイベントをメモリ内のキューにプッシュしますが、そのキューは、ダウンストリームのアペンダへログメッセージを送信する別のスレッドによってドレーンされます。したがって、ダウンストリームのアペンダがグラフの作成やMBeanの更新、データベースへの保存といった集中的な作業を大量にこなしたとしても、計測中のコードブロックへの影響は最小であり、ダウンストリームのそうしたアペンダが行う仕事量には無関係なのです。同様に、解析と分析を後で行うことを計画しているファイルに（たとえば、上で説明したようにUNIXのtailコマンドを使って）時間計測のログを書き込む際には、時間計測されているプロセスへの影響は、そのプロセスがログステートメント記述に要する時間にのみ関係しており、ログパーサーが要する時間には関係ありません。
3. パフォーマンス・リグレッションテストのメリットをお忘れなく。ランタイムにおけるパフォーマンスボトルネックの検出に加え、Perf4Jは、コード変更がパフォーマンスに重大な影響（プラスもしくはマイナスの影響のどちらか）を与えているか否かを決定するためのパフォーマンス・リグレッションテストの作成に非常に役立ちます。コードの最初のバージョンでベースラインを作成することにより、新バージョンがパフォーマンスにどう影響することになるかを迅速に見定めることができます。
4. @ProfiledアノテーションとAspectJのロード時ウィービングを活用し、デプロイメント時にどのメソッドを計測すべきか決めましょう。@Profiledアノテーションを使っているなら、メソッド呼び出しの周辺に自由に時間計測を追加でき、その後で、AspectJのaop.xmlコンフィギュレーション・ファイルを使ってデプロイする際に、実際に計測するメソッドを決定します。時間計測をしないことになったメソッドについては、ゼロヒットが用いられます。計測されたメソッドには、コード内でStopWatchesを直接使用する（AspectJでは基本的に、時間計測されているメソッドの周辺にクロージャを作成）のと比べて間接費が多少高くなりますが、少なくとも2ミリ秒を要するメソッドの時間計測を行っている際には、このオーバーヘッドの増加は依然として取るに足らないレベルでしょう。
5. アプリケーションにはJVMの外で実行されるパーツもあることを忘れないでください。たとえば、多数のWeb 2.0アプリケーションのたくさんのパーツが、クライアントのブラウザ上で動作するJavascriptで実装されます。Perf4Jは、AJAXのリモート呼び出しへの返答として実行されるサーバー上のメソッドの計測に使用できますが、Javascriptの実行自体がスローダウンしている場合は、クライアント側に別のデバッギングツールが必要になります。

Perf4Jの将来の方向

Perf4Jの開発は活発に行われており、新しい機能が頻繁に追加されています。たとえば、Perf4Jの将来のバージョンでは、別個のconfigファイルを使ってプロファイルするメソッドを指定できるようになるので、オリジナルのソースコードにアクセスできない場合でさえ、メソッドの実行時間を計測できます。ユーザーのフィードバックとニーズを踏まえて、全機能の優先順位をつけているので、将来の機能の方向付けに役立たたいと思うなら、今すぐPerf4Jを試してみてください。さらによいことに、Perf4JはApache 2ライセンスのもと、完全にオープンソースであり、コードも完全に文書化されているので、希望のままに拡張することができます。

今すぐPerf4Jをダウンロードして、意見をお聞かせください！

• 次へ >