遅い要求およびハング要求の検出

requestTiming-1.0 フィーチャーは、要求の所要時間が構成されているしきい値を超えた場合に診断情報を提供します。

Request Timing フィーチャーは、システムに着信しているすべての要求の所要時間を追跡できます。遅い要求およびハング要求がないかを監視するようにこのフィーチャーを構成できます。

遅い要求の検出

要求が構成された時間より長く実行されている場合、警告メッセージが、メッセージ・ログ・ファイルに書き込まれます。要求、および要求を構成したイベントに関する詳細が取り込まれます。
以下の例では、遅い要求のしきい値 (デフォルトは 10 秒) を超過した要求に対するログ・メッセージを示します。
[12/1/14 11:58:09:629 IST] 0000001d com.ibm.ws.request.timing.SlowRequestTimer                   W TRAS0112W: Request AABjnS+lIn0_AAAAAAAAAAb has been running on thread 00000021 for at least 10003.571ms. The following stack trace shows what this thread is currently running.

 	 at java.util.HashMap.getEntry(HashMap.java:516)
	 at java.util.HashMap.get(HashMap.java:504)
	 at org.apache.derby.iapi.store.access.BackingStoreHashtable.get(Unknown Source)
	 at org.apache.derby.impl.sql.execute.HashScanResultSet.getNextRowCore(Unknown Source)
	 at org.apache.derby.impl.sql.execute.NestedLoopJoinResultSet.getNextRowCore(Unknown Source)
	 at org.apache.derby.impl.sql.execute.ProjectRestrictResultSet.getNextRowCore(Unknown Source)
	 at org.apache.derby.impl.sql.execute.DMLWriteResultSet.getNextRowCore(Unknown Source)
	 at org.apache.derby.impl.sql.execute.DeleteResultSet.setup(Unknown Source)
	 at org.apache.derby.impl.sql.execute.DeleteResultSet.open(Unknown Source)
	 at org.apache.derby.impl.sql.GenericPreparedStatement.executeStmt(Unknown Source)
	 at org.apache.derby.impl.sql.GenericPreparedStatement.execute(Unknown Source)
	 at org.apache.derby.impl.jdbc.EmbedStatement.executeStatement(Unknown Source)
	 at org.apache.derby.impl.jdbc.EmbedPreparedStatement.executeStatement(Unknown Source)
	 at org.apache.derby.impl.jdbc.EmbedPreparedStatement.executeUpdate(Unknown Source)
	 at com.ibm.ws.rsadapter.jdbc.WSJdbcPreparedStatement.executeUpdate(WSJdbcPreparedStatement.java:626)
	 at com.ibm.websphere.samples.trade.direct.TradeDirect.resetTrade(TradeDirect.java:1832)
	 at com.ibm.websphere.samples.trade.web.TradeConfigServlet.doResetTrade(TradeConfigServlet.java:65)
	 at com.ibm.websphere.samples.trade.web.TradeConfigServlet.service(TradeConfigServlet.java:348)
	 at javax.servlet.http.HttpServlet.service(HttpServlet.java:668)
	 at com.ibm.ws.webcontainer.servlet.ServletWrapper.service(ServletWrapper.java:1275)
	 ....
	 at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1121)
	 at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:614)
	 at java.lang.Thread.run(Thread.java:769)
 
Duration    Operation
10007.571ms + websphere.servlet.service | TradeWeb | TradeConfigServlet?action=resetTrade
    3.923ms       websphere.datasource.psExecuteUpdate | jdbc/TradeDataSource | delete from holdingejb where holdingejb.account_accountid is null
    0.853ms       websphere.datasource.psExecuteUpdate | jdbc/TradeDataSource | delete from accountprofileejb where userid like 'ru:%'
 5271.341ms +     websphere.datasource.psExecuteUpdate | jdbc/TradeDataSource | delete from orderejb where account_accountid in (select accountid from accountejb a where a.profile_useri like 'ru:%')
要求はモニターされ続け、要求がさらに 10 秒を超えて実行された場合、さらに警告がログに記録されます。ログ・メッセージは、以下のフォーマットになります。
TRAS0112W: Request <(Request ID)> has been running on thread <THREADID> for at least <DURATION>. The following stack trace shows what this thread is currently running.
<STACK TRACE>
<DURATION AND OPERATIONS Table>
REQUEST ID
この同じ ID を使用して、ログの検索および要求に対応するメッセージのトレースを行うことができます。特に、バイナリー・ロギングを使用している場合、バイナリー・ログ・コマンドを使用して、同じ requestID 拡張でログおよびトレースの項目を検索できます。
STACK TRACE
実行されているメソッドを示します。上記の例では、TRAS0112W 行の後に、現行要求のスタック・トレースが表示されています。
DURATION と OPERATION の表
スタック・トレースの後に、所要時間と操作 (イベントとも呼ばれる) を示す、要求の表形式が表示されます。Duration 列には、要求の対応する操作にかかった時間が示されます。正符号 (+) は、まだ実行されている、要求内のイベントを示します。次の行は、+ のない所要時間を示しています。これは、示されている所要時間で対応する操作が完了したことを示します。Operation は、当該操作の EVENT TYPE および CONTEXT INFO (オプション) を示します。イベント・タイプとコンテキスト情報について詳しくは、『イベント・ロギング』を参照してください。

メッセージを分析することで、要求が遅い理由を確かめることができます。ただし、要求がその時点でスタックしているのか、まだゆっくりと実行されているのかを判断するのは困難な場合があります。そのため、指定されている <slowRequestThreshold> の間隔で、遅い要求に対してログに記録された 3 つのメッセージを確認できます。3 つの異なるスタック・トレースおよび要求データを使用して、問題の理解を深めることができます。3 番目の警告の後に、要求の所要時間がハング要求の検出のしきい値を超過しない限り、それ以上の警告はログに記録されません。

ハング要求の検出

要求がデフォルトの hungRequestThreshold または構成されているしきい値を超えた場合、警告メッセージが、要求に関する詳細とともに、メッセージ・ログ・ファイルに書き込まれます。要求、および要求を構成したイベントに関する詳細が取り込まれます。ハング要求の検出の場合、一連の 3 つのスレッド・ダンプ (javacore) が取られます。各ダンプ間の遅延は 1 分です。以下のログ・メッセージの例では、ハング要求の検出のしきい値を超過した要求に対するログ・メッセージを示します。デフォルトの所要時間値は 10 分です。以下の例で構成されている値は 4 分です。
[WARNING ] TRAS0114W: Request AAA7WlpP7l7_AAAAAAAAAAA has been running on thread 00000021 for at least 240001.015ms. The following table shows the events that have run during this request.
Duration       Operation
240001.754ms + websphere.servlet.service | TestWebApp | TestServlet?sleepTime=480000
     0.095ms       websphere.session.setAttribute | mCzBMyzMvAEnjMJJx9zQYIw | userID
     0.007ms       websphere.session.setAttribute | mCzBMyzMvAEnjMJJx9zQYIw | visitCount
最初はハングしているものとして検出された要求が後で完了した場合、以下の例のようなメッセージがログに記録されます。TRAS0115W: Request AAA7WlpP7l7_AAAAAAAAAAA, which was previously detected to be hung, has completed after 479999.681 s.
注: 要求がハングしていることが検出されると、一連の 3 つのスレッド・ダンプが開始されます。3 つのスレッド・ダンプが完了した後には、新規要求がハングしているものと検出された場合にのみ、さらにスレッド・ダンプが作成されます。

トピックのタイプを示すアイコン 参照トピック



タイム・スタンプ・アイコン 最終更新: Monday, 5 December 2016
http://www14.software.ibm.com/webapp/wsbroker/redirect?version=cord&product=was-libcore-mp&topic=rwlp_requesttiming
ファイル名: rwlp_requesttiming.html