检测运行缓慢和挂起的请求

任何请求的持续时间超过所配置阈值时,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
此相同标识可用于搜索对应该请求的日志和跟踪消息。尤其是您使用二进制日志记录时,您可搜索使用二进制日志命令来搜索具有相同 requestID 扩展的日志和跟踪条目。
STACK TRACE
指示正在运行的方法。在上一样本中,可在 TRAS0112W 行后查看当前请求的堆栈跟踪。
DURATION AND OPERATIONS 表
进行堆栈跟踪后,可查找该请求的表格格式,该表格显示持续时间和操作(又称为事件)。持续时间列指示该请求的对应操作的耗用时间。加号 (+) 指示该请求内的事件仍在运行。下一行显示不带 + 的持续时间,它指示已在指定持续时间内完成的对应操作。对于该操作,“操作”显示 EVENT TYPECONTEXT INFO(这是可选项)。有关事件类型和上下文信息的更多信息,请参阅事件日志记录

通过分析消息,您可确定请求运行缓慢的原因。但是,可能难以确定请求是在该点停住还是仍在缓慢运行。因此,可按指定 <slowRequestThreshold> 的时间间隔来查看针对任何运行缓慢的请求记录的三条消息。通过使用三个不同的堆栈跟踪和请求数据,您可更深入地了解问题。在第三条警告后,系统不会再记录有关该请求的任何警告,除非该请求的持续时间超过挂起请求检测阈值。

检测挂起请求

如果请求超过缺省 hungRequestThreshold 或所配置阈值,那么系统会在消息日志文件中写入警告消息及有关该请求的详细信息。系统会捕获有关该请求及构成该请求的事件的详细信息。检测挂起请求时,系统会执行一系列(三个)线程转储(java 核心),各个转储之间存在 1 分钟延迟。以下日志消息样本显示超过挂起请求检测阈值的请求的日志消息。缺省持续时间值为 10 分钟。以下示例中配置的值为 4 分钟。
[WARNING ] TRAS0114W: 请求 AAA7WlpP7l7_AAAAAAAAAAA 已在线程 00000021 上运行了至少 240001.015ms。下表显示此请求执行期间运行的事件。
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: 先前被检测为挂起的请求 AAA7WlpP7l7_AAAAAAAAAAA 在 479999.681 秒后完成。
注: 请求被检测为挂起时,系统会启动一系列(三个)线程转储。完成三个线程转储后,仅当新请求被检测为挂起时,系统才会创建其他线程转储。

用于指示主题类型的图标 参考主题



时间戳记图标 最近一次更新时间: Monday, 5 December 2016
http://www14.software.ibm.com/webapp/wsbroker/redirect?version=cord&product=was-libcore-mp&topic=rwlp_requesttiming
文件名:rwlp_requesttiming.html