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

任何请求的持续时间超过所配置阈值时,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 秒后已完成。
注: 请求被检测为挂起时,系统会启动一系列(三个)线程转储。完成三个线程转储后,仅当新请求被检测为挂起时,系统才会创建其他线程转储。
[17.0.0.3 and later]如果在请求计时配置中将 interruptHungRequests 设置为 true,那么在首次线程转储完成后,系统会尝试中断挂起的请求。当服务器正在使用 IBM JRE 时,com.ibm.jvm 包中的类(例如 InterruptibleIOContext 和 InterruptibleLockContext)用于中断请求。可能会使用其他方法来中断请求,这取决于服务器中配置的功能部件,以及在检测到挂起的请求时应用程序正在执行的代码。在大多数情况下,中断结果是所声明的异常,该异常向检测到挂起的请求时受控制的应用程序代码抛出。随后,应用程序可以处理该异常,并向调用者返回相应的错误。
注: 如果同时检测到多个挂起的请求,每个请求都会等到针对第一个挂起的请求的第一个线程转储完成后,再尝试中断该请求。
[17.0.0.3 and later]

配置运行缓慢请求阈值和挂起请求阈值

可以通过在 server.xml 文件的 <requestTiming/> 配置中设置 slowRequestThresholdhungRequestThreshold 来配置运行缓慢请求阈值和挂起请求阈值。此设置针对所有计时的请求设置单个运行缓慢请求阈值和挂起请求阈值。

您也可以为不同类型的请求设置不同的运行缓慢请求阈值和挂起请求阈值。server.xml 文件中的嵌入式 <servletTiming/><jdbcTiming/> 配置会覆盖 <requestTiming/> 中定义的已配置运行缓慢请求阈值和挂起请求阈值。<servletTiming/> 配置可通过应用程序名称和/或 Servlet 名称来设置运行缓慢请求阈值和挂起请求阈值。<jdbcTiming/> 配置可通过数据源名称和/或 SQL 字符串来设置运行缓慢请求阈值和挂起请求阈值。在这两种情况下,名称都取自请求的上下文信息,如 eventLogging-1.0 功能部件所报告的那样。

事件日志包含服务器已处理的每个请求的类型和上下文信息。借助类型和上下文信息,您可以在 server.xml 文件中为需要不同阈值的请求创建 <servletTiming/><jdbcTiming/> 配置。

有关为每个请求提供的上下文信息的更多信息,请参阅产品文档中的事件日志记录<servletTiming/><jdbcTiming/> 配置只能用于对根级别请求进行计时。例如,如果 Servlet 请求进行 JDBC 查询,那么无法对该 JDBC 请求进行计时,因为 Servlet 请求是根级别请求。

请参阅以下 <requestTiming/> 配置,该配置中嵌入了一个特定 Servlet 和一个特定 Web 应用程序的 <servletTiming/> 配置:
<requestTiming slowRequestThreshold="10s" hungRequestThreshold="10m">
  <servletTiming servletName="Arm10Servlet" hungRequestThreshold=”20s”/>
  <servletTiming appName="SecurityExchangeApp” hungRequestThreshold=”2h”/>
</requestTiming>

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

文件名:rwlp_requesttiming.html