チューニングを実施する前にやるべきこととは？：WebSphereサーバ・チューニング入門（1）（2/3 ページ）

» 2007年03月14日 00時00分公開

[上野憲一郎，日本アイ・ビー・エム]

「要求メトリック」でレスポンスタイムを分析

　まず、WASが提供する1つめのツールの紹介として、レスポンスタイムに注目してパフォーマンス・ボトルネックを発見する方法を検討します。

　Webアプリケーションにおいて、クライアント（多くの場合は、Webブラウザ）がリクエストメッセージを送信してから応答メッセージを受け取るまでにかかるエンド・トゥ・エンドのレスポンスタイムを分析し、経由するコンポーネントごとにかかる時間を見極めることにより、レスポンスタイムという視点からどのコンポーネントをチューニングするかを判別するという手法を支援するために、「要求メトリック（Request Metrics）」と呼ばれるツールが提供されています。

図1 要求メトリックによるトランザクションの分析

　「要求メトリック」は、各リクエスト（トランザクション）に対するパフォーマンス情報を記録し、該当リクエストがWASの主要コンポーネントで費やした時間を取得できます。

　また、それらの情報をARM（Application Response Measurement）エージェントに送信もできます。要求メトリックにより取得したログを解析することにより、トランザクションがどのコンポーネントにおいて、どれほどの時間を費やしているかを把握できます。要求メトリックは、以下のコンポーネントに設定できます。

Webサーバ・ポートの使用時のみ使用可能なWebサーバ・プラグイン
サーブレットおよびWebサービス要求として装備されているプロキシ・サーバ
サーブレットおよびサーブレット・フィルターを含むWebコンテナ
EJBコンテナ
JDBC呼び出し
J2EEコネクター・アーキテクチャ（JCA）
サーバ・サイドとクライアント・サイドの両方のWebサービス
JMSエンジン
サービス統合バス（SIB）
ポートレット要求を含むポートレット・コンテナ（Portlet）
非同期Bean（AsyncBeans）

　例えば、あるサーブレットのレスポンスタイムが130ミリ秒であった場合、EJBおよびJDBCを併せて38ミリ秒が費やされ、92ミリ秒がサーブレットの処理自体に費やされたというように分析できます。

　要求メトリックは、フィルタリング機能を提供しており、特定のトランザクションに対して、要求メトリックのトレースを制限することも可能です。フィルタとしては、以下の5つが提供されています。

ソースIP
URI
EJB
JMS
Webサービス

要求メトリックの設定の仕方

　以下に、要求メトリックの設定例および出力ログのサンプルを載せます。

図2 要求メトリックの設定（クリックすると画像が拡大します）

　管理コンソール上で、「モニターおよびチューニング」→「要求メトリック」をクリックし、要求メトリックの設定画面にて、「要求メトリック・コレクション用のサーバの準備」のチェックボックスをチェックします。

　「計測対象コンポーネント」で対象とするコンポーネントを指定します。コンポーネントには、「なし」「すべて」「カスタム」を選択でき、さらに「カスタム」を選ぶことにより、詳細なコンポーネントの指定ができます。

　「トレース・レベル」では、どの程度のトレースを取得するかを指定します。トレース・レベルには、「なし」「ホップ」「パフォーマンス・デバッグ」「デバッグ」の1つを指定できます。「デバッグ」を指定すると、要求メトリックで取得可能なすべての情報を取得できます。

　「要求メトリックの宛先」で、「標準ログ」チェックボックスをチェックすることにより標準出力に記録するか、あるいは「アプリケーション応答測定（ARM）エージェント」を指定して、ARMエージェントを呼び出せます。

要求メトリックの実行結果の詳しい見方

　例として以下に、「計測対象コンポーネント」に「すべて」を選択し、「トレース・レベル」に「デバッグ」を選択し、「要求メトリックの宛先」に「標準ログ」を指定した場合の出力結果を見ていきましょう。

　出力結果を見る前に、今回使用したアプリケーションの動きを説明します。最初に呼び出される「PingServlet2Session2Entity」は、「/ejb/TradeEJB」に対するJNDIルックアップを実施し、「org.apache.geronimo.samples.daytrader.ejb.TradeBean.getQuote」というSession Beanを呼び出します。そして、「TradeBean EJB」は、Entity Beanである「org.apache.geronimo.samples.daytrader.ejb.QuoteBean.findByPrimaryKey」を呼び出し、それにより、続く4つのJDBC処理を呼び出します。その後、同じくEntity Beanである「org.apache.geronimo.samples.daytrader.ejb.QuoteBean.getDataBean」が呼び出され、続いて3つのJDBC処理を呼び出します。

　以下が、SystemOut.logに記録された要求メトリックの出力結果です。

[07/03/11 20:30:36:562 JST] 00000021 ServletWrappe I   SRVE0242I: [DayTrader 1.2] [/daytrader] [PingServlet2Session2Entity]: 初期化が正常に行われました。
[07/03/11 20:30:36:703 JST] 00000021 PmiRmArmWrapp I   PMRM0003I:  parent:ver=1,ip=127.0.0.1,time=1173612005640,pid=4968,reqid=46,event=1 - current:ver=1,ip=127.0.0.1,time=1173612005640,pid=4968,reqid=47,event=1 type=JNDI detail=ejb/TradeEJB elapsed=0
[07/03/11 20:30:36:718 JST] 00000021 PmiRmArmWrapp I   PMRM0003I:  parent:ver=1,ip=127.0.0.1,time=1173612005640,pid=4968,reqid=49,event=1 - current:ver=1,ip=127.0.0.1,time=1173612005640,pid=4968,reqid=50,event=1 type=JDBC detail=javax.resource.spi.ManagedConnectionFactory.matchManagedConnections(Set, Subject, ConnectionRequestInfo) elapsed=0
[07/03/11 20:30:36:734 JST] 00000021 PmiRmArmWrapp I   PMRM0003I:  parent:ver=1,ip=127.0.0.1,time=1173612005640,pid=4968,reqid=49,event=1 - current:ver=1,ip=127.0.0.1,time=1173612005640,pid=4968,reqid=51,event=1 type=JDBC detail=javax.resource.spi.ManagedConnection.getConnection(Subject, ConnectionRequestInfo) elapsed=0
[07/03/11 20:30:36:750 JST] 00000021 PmiRmArmWrapp I   PMRM0003I:  parent:ver=1,ip=127.0.0.1,time=1173612005640,pid=4968,reqid=49,event=1 - current:ver=1,ip=127.0.0.1,time=1173612005640,pid=4968,reqid=52,event=1 type=JDBC detail=javax.resource.spi.XAResource.start(Xid, int) elapsed=16
[07/03/11 20:30:36:765 JST] 00000021 PmiRmArmWrapp I   PMRM0003I:  parent:ver=1,ip=127.0.0.1,time=1173612005640,pid=4968,reqid=49,event=1 - current:ver=1,ip=127.0.0.1,time=1173612005640,pid=4968,reqid=53,event=1 type=JDBC detail=java.sql.PreparedStatement.executeQuery() elapsed=15
[07/03/11 20:30:36:781 JST] 00000021 PmiRmArmWrapp I   PMRM0003I:  parent:ver=1,ip=127.0.0.1,time=1173612005640,pid=4968,reqid=48,event=1 - current:ver=1,ip=127.0.0.1,time=1173612005640,pid=4968,reqid=49,event=1 type=EJB detail=org.apache.geronimo.samples.daytrader.ejb.QuoteBean.findByPrimaryKey elapsed=63
[07/03/11 20:30:36:812 JST] 00000021 PmiRmArmWrapp I   PMRM0003I:  parent:ver=1,ip=127.0.0.1,time=1173612005640,pid=4968,reqid=48,event=1 - current:ver=1,ip=127.0.0.1,time=1173612005640,pid=4968,reqid=54,event=1 type=EJB detail=org.apache.geronimo.samples.daytrader.ejb.QuoteBean.getDataBean elapsed=0
[07/03/11 20:30:36:812 JST] 00000021 PmiRmArmWrapp I   PMRM0003I:  parent:ver=1,ip=127.0.0.1,time=1173612005640,pid=4968,reqid=48,event=1 - current:ver=1,ip=127.0.0.1,time=1173612005640,pid=4968,reqid=55,event=1 type=JDBC detail=javax.resource.spi.XAResource.end(Xid, int) elapsed=0
[07/03/11 20:30:36:828 JST] 00000021 PmiRmArmWrapp I   PMRM0003I:  parent:ver=1,ip=127.0.0.1,time=1173612005640,pid=4968,reqid=48,event=1 - current:ver=1,ip=127.0.0.1,time=1173612005640,pid=4968,reqid=56,event=1 type=JDBC detail=javax.resource.spi.XAResource.commit(Xid, boolean) elapsed=0
[07/03/11 20:30:36:843 JST] 00000021 PmiRmArmWrapp I   PMRM0003I:  parent:ver=1,ip=127.0.0.1,time=1173612005640,pid=4968,reqid=48,event=1 - current:ver=1,ip=127.0.0.1,time=1173612005640,pid=4968,reqid=57,event=1 type=JDBC detail=javax.resource.spi.ManagedConnection.cleanup() elapsed=0
[07/03/11 20:30:36:859 JST] 00000021 PmiRmArmWrapp I   PMRM0003I:  parent:ver=1,ip=127.0.0.1,time=1173612005640,pid=4968,reqid=46,event=1 - current:ver=1,ip=127.0.0.1,time=1173612005640,pid=4968,reqid=48,event=1 type=EJB detail=org.apache.geronimo.samples.daytrader.ejb.TradeBean.getQuote elapsed=141
[07/03/11 20:30:36:890 JST] 00000021 PmiRmArmWrapp I   PMRM0003I:  parent:ver=1,ip=127.0.0.1,time=1173612005640,pid=4968,reqid=46,event=1 - current:ver=1,ip=127.0.0.1,time=1173612005640,pid=4968,reqid=58,event=1 type=EJB detail=org.apache.geronimo.samples.daytrader.ejb.TradeBean.remove elapsed=0
[07/03/11 20:30:36:906 JST] 00000021 PmiRmArmWrapp I   PMRM0003I:  parent:ver=1,ip=127.0.0.1,time=1173612005640,pid=4968,reqid=46,event=1 - current:ver=1,ip=127.0.0.1,time=1173612005640,pid=4968,reqid=46,event=1 type=URI detail=/daytrader/servlet/PingServlet2Session2Entity elapsed=328

リスト1 要求メトリックの出力結果（もとファイルはこちら）

　要求メトリックの出力のフォーマットは以下のとおりです。

PMRM0003I:

parent:ver=n

　　　,ip=n.n.n.n

　　　,time=nnnnnnnnnn

　　　,pid=nnnn

　　　,reqid=nnnnnn

　　　,event=nnnn

current:ver=n

　　　,ip=n.n.n.n

　　　,time=nnnnnnnnnn

　　　,pid=nnnn

　　　,reqid=nnnnnn

　　　,event=nnnn

　　　,type=TTT

　　　,detail=some_detail_information

　　　,elapsed=nnnn

リスト2　要求メトリックの出力のフォーマット

　「parent」は、該当コンポーネントから見て1つリクエスターに近いコンポーネントへの要求の情報であり、「current」は、「type=」で指定されている該当コンポーネントへの要求の情報です。「type=」で指定されたコンポーネントが、このオペレーションで呼び出されたすべてのサブオペレーションを含む、オペレーションの経過時間が「elapsed=」で示されます。経過時間はミリ秒単位です。

　上記フォーマットに照らし合わせて、先ほどの出力結果をまとめると、「/daytrader/servlet/PingServlet2Session2Entity」に対するHTTPリクエストのレスポンスタイムは328ミリ秒で、その中には下記が含まれます。

「PingServlet2Session2Entity」サーブレットの処理
「/ejb/TradeEJB」のJNDIルックアップ：0ミリ秒
「org.apache.geronimo.samples.daytrader.ejb.TradeBean.getQuote」EJBの処理：141ミリ秒
「org.apache.geronimo.samples.daytrader.ejb.QuoteBean.findByPrimaryKey」EJBの処理：63ミリ秒
「javax.resource.spi.ManagedConnectionFactory.matchManagedConnections(Set, Subject, ConnectionRequestInfo)」JDBCの処理：0ミリ秒
「javax.resource.spi.ManagedConnection.getConnection(Subject, ConnectionRequestInfo)」JDBCの処理：0ミリ秒
「javax.resource.spi.XAResource.start(Xid, int)」JDBCの処理：16ミリ秒
「java.sql.PreparedStatement.executeQuery()」JDBCの処理：15ミリ秒
「org.apache.geronimo.samples.daytrader.ejb.QuoteBean.getDataBean」EJBの処理：0ミリ秒
「javax.resource.spi.XAResource.end(Xid, int)」JDBCの処理：0ミリ秒
「javax.resource.spi.XAResource.commit(Xid, boolean)」JDBCの処理：0ミリ秒
「javax.resource.spi.ManagedConnection.cleanup()」JDBCの処理：0ミリ秒
「org.apache.geronimo.samples.daytrader.ejb.TradeBean.remove」EJBの処理：0ミリ秒