遅い要求およびハング要求の検出
requestTiming-1.0 フィーチャーは、要求の所要時間が構成されているしきい値を超えた場合に診断情報を提供します。
遅い要求の検出
構成された時間よりも長く実行されている要求があると、メッセージ・ログ・ファイルに警告メッセージが書き込まれます。要求、および要求を構成したイベントに関する詳細が取り込まれます。[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:%')
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 分です。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 秒後に完了しました。![[17.0.0.3 and later]](../ng_v17003plus.gif)
![[17.0.0.3 and later]](../ng_v17003plus.gif)
遅い要求およびハング要求のしきい値の構成
遅い要求およびハング要求のしきい値は、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 slowRequestThreshold="10s" hungRequestThreshold="10m">
<servletTiming servletName="Arm10Servlet" hungRequestThreshold=”20s”/>
<servletTiming appName="SecurityExchangeApp” hungRequestThreshold=”2h”/>
</requestTiming>