检测运行缓慢和挂起的请求
任何请求的持续时间超过所配置阈值时,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
- 此相同标识可用于搜索对应该请求的日志和跟踪消息。尤其是您使用二进制日志记录时,您可搜索使用二进制日志命令来搜索具有相同 requestID 扩展的日志和跟踪条目。
- STACK TRACE
- 指示正在运行的方法。在上一样本中,可在 TRAS0112W 行后查看当前请求的堆栈跟踪。
- DURATION AND OPERATIONS 表
- 进行堆栈跟踪后,可查找该请求的表格格式,该表格显示持续时间和操作(又称为事件)。持续时间列指示该请求的对应操作的耗用时间。加号 (+) 指示该请求内的事件仍在运行。下一行显示不带 + 的持续时间,它指示相应的操作已在指定的持续时间内完成。对于该操作,“操作”显示 EVENT TYPE 和 CONTEXT INFO(可选)。有关事件类型和上下文信息的更多信息,请参阅事件日志记录。
通过分析消息,您可确定请求运行缓慢的原因。但是,可能难以确定请求是在该点停住还是仍在缓慢运行。因此,可按指定 <slowRequestThreshold> 的时间间隔来查看针对任何运行缓慢的请求记录的三条消息。通过使用三个不同的堆栈跟踪和请求数据,您可更深入地了解问题。在第三条警告后,系统不会再记录有关该请求的任何警告,除非该请求的持续时间超过挂起请求检测阈值。
检测挂起请求
如果请求超过缺省 hungRequestThreshold 或所配置阈值,那么系统会在消息日志文件中写入警告消息及有关该请求的详细信息。系统会捕获有关该请求及构成该请求的事件的详细信息。检测挂起的请求时,系统会执行一系列(三个)线程转储(java 核心),各个转储之间存在 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: 请求 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 来配置运行缓慢请求阈值和挂起请求阈值。此设置针对所有计时的请求设置单个运行缓慢请求阈值和挂起请求阈值。
您也可以为不同类型的请求设置不同的运行缓慢请求阈值和挂起请求阈值。server.xml 文件中的嵌入式 <servletTiming/> 或 <jdbcTiming/> 配置会覆盖 <requestTiming/> 中定义的已配置运行缓慢请求阈值和挂起请求阈值。<servletTiming/> 配置可通过应用程序名称和/或 Servlet 名称来设置运行缓慢请求阈值和挂起请求阈值。<jdbcTiming/> 配置可通过数据源名称和/或 SQL 字符串来设置运行缓慢请求阈值和挂起请求阈值。在这两种情况下,名称都取自请求的上下文信息,如 eventLogging-1.0 功能部件所报告的那样。
事件日志包含服务器已处理的每个请求的类型和上下文信息。借助类型和上下文信息,您可以在 server.xml 文件中为需要不同阈值的请求创建 <servletTiming/> 或 <jdbcTiming/> 配置。
有关为每个请求提供的上下文信息的更多信息,请参阅产品文档中的事件日志记录。<servletTiming/> 或 <jdbcTiming/> 配置只能用于对根级别请求进行计时。例如,如果 Servlet 请求进行 JDBC 查询,那么无法对该 JDBC 请求进行计时,因为 Servlet 请求是根级别请求。
<requestTiming slowRequestThreshold="10s" hungRequestThreshold="10m">
<servletTiming servletName="Arm10Servlet" hungRequestThreshold=”20s”/>
<servletTiming appName="SecurityExchangeApp” hungRequestThreshold=”2h”/>
</requestTiming>