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

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 was 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
これは、ハングしていると以前に検出され、479999.681 秒後に完了しました。
注: 要求がハングしていることが検出されると、一連の 3 つのスレッド・ダンプが開始されます。3 つのスレッド・ダンプが完了した後には、新規要求がハングしているものと検出された場合にのみ、さらにスレッド・ダンプが作成されます。
[17.0.0.3 and later]要求タイミング構成で interruptHungRequeststrue に設定されている場合、最初のスレッド・ダンプが完了した後で、ハングした要求の中断が試行されます。サーバーが IBM JRE を使用している場合、要求を中断するために com.ibm.jvm パッケージ内のクラス (InterruptibleIOContext や InterruptibleLockContext など) が使用されます。サーバーに構成されているフィーチャーと、ハング要求検出時にアプリケーションが実行しているコードに応じて、要求を中断するためにその他のメソッドが使用されることもあります。ほとんどの場合、中断の結果として、宣言済みの例外が、ハング要求検出時に制御下にあったアプリケーション・コードにスローされます。その後、アプリケーションはその例外を処理して、適切なエラーを呼び出し元に返すことができます。
注: 複数のハング要求が同時に検出された場合、各要求は、最初のハング要求に対する最初のスレッド・ダンプが完了するのを待ってから、その要求の中断を試みます。
[17.0.0.3 and later]

遅い要求およびハング要求のしきい値の構成

遅い要求およびハング要求のしきい値は、server.xml ファイル内の <requestTiming/> 構成内で slowRequestThreshold および hungRequestThreshold を設定することによって構成されます。この設定は、タイミング設定のあるすべての要求に対して、遅い要求およびハング要求のしきい値を 1 つ設定します。

異なるタイプの要求に対して、遅い要求およびハング要求のしきい値として異なる値を設定することもできます。server.xml ファイル内の組み込み <servletTiming/> または <jdbcTiming/> 構成は、<requestTiming/> 内に定義された、遅い要求およびハング要求のしきい値の構成をオーバーライドします。<servletTiming/> 構成では、アプリケーション名、サーブレット名、またはその両方によって、遅い要求およびハング要求のしきい値を設定できます。<jdbcTiming/> 構成では、データ・ソース名、SQL ストリング、またはその両方によって、遅い要求およびハング要求のしきい値を設定できます。どちらの場合も、eventLogging-1.0 フィーチャーによって報告されるように、それらの名前は要求のコンテキスト情報から取られます。

イベント・ログには、サーバーによって処理された各要求のタイプおよびコンテキスト情報が含まれます。タイプおよびコンテキスト情報を使用して、異なるしきい値を必要とする要求のために、server.xml ファイル内に <servletTiming/> または <jdbcTiming/> 構成を作成できます。

各要求に対して提供されるコンテキスト情報について詳しくは、製品資料の『イベント・ロギング』を参照してください。<servletTiming/> または <jdbcTiming/> 構成は、ルート・レベルの要求のタイミングを設定するためにのみ使用できます。 例えば、サーブレット要求が JDBC 照会を行う場合、サーブレット要求がルート・レベルの要求であるため、JDBC 照会にはタイミングを設定することはできません。

次の <requestTiming/> 構成には、1 つの特定のサーブレットおよび 1 つの特定の Web アプリケーションに対する組み込み <servletTiming/> 構成があります。
<requestTiming slowRequestThreshold="10s" hungRequestThreshold="10m">
  <servletTiming servletName="Arm10Servlet" hungRequestThreshold=”20s”/>
  <servletTiming appName="SecurityExchangeApp” hungRequestThreshold=”2h”/>
</requestTiming>

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

ファイル名: rwlp_requesttiming.html