太慢和停擺之要求的偵測

只要有要求的持續時間超過所配置的臨界值,requestTiming-1.0 特性可提供診斷資訊。

要求計時特性可以追蹤送入至系統的每一項要求的持續時間。您可以配置此特性,以留意是否有太慢和停擺的要求。

太慢要求的偵測

當要求的執行時間超過配置時間時,會將警告訊息寫入訊息日誌檔中。會擷取要求的詳細資料,以及構成該要求的事件。
下列範例顯示對於超出太慢要求臨界值的要求,所顯示的日誌訊息。預設值是 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 AND OPERATIONS Table
在堆疊追蹤之後,您可以尋找表格格式的要求,其中顯示持續時間和作業(亦稱為事件)。Duration 直欄指出該要求的對應作業所耗費的時間。加號 (+) 指出仍在執行之要求內的事件。下一行顯示沒有 + 的持續時間,這表示對應的作業已在指定期間內完成。作業會顯示 EVENT TYPE 和該作業的 CONTEXT INFO(選用)。如需事件類型和環境定義資訊的相關資訊,請參閱事件記載

您可以分析訊息,藉以瞭解要求太慢的原因。不過,可能難以判斷要求是停留在該點或者仍舊慢慢執行。因此,對於在 <slowRequestThreshold> 指定間隔內任何執行過慢的要求,您可以查看為其所記載的三則訊息。藉由三項不同的堆疊追蹤和要求資料,可讓您更能洞察問題。在第三則警告之後,除非要求的持續時間超過停擺要求偵測臨界值,否則不會記載該要求的其他警告。

停擺要求偵測

如果要求超過預設 hungRequestThreshold 或所配置的臨界值,會將警告訊息寫入訊息日誌檔中,以及提供該要求的詳細資料。會擷取要求的詳細資料,以及構成該要求的事件。在停擺要求的偵測方面,會進行一系列的三次執行緒傾出 (javacores),且每次間隔延遲 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 以及更新版本]如果在要求計時配置中,將 interruptHungRequests 設為 true,在第一次執行緒傾出完成之後,會嘗試中斷停擺的要求。當伺服器使用 IBM JRE 時,會使用 com.ibm.jvm 套件中的類別(例如 InterruptibleIOContext 和 InterruptibleLockContext)來中斷要求。視伺服器中配置的特性,以及在偵測到停擺要求時應用程式正在執行的程式碼而定,可能會使用其他方法來中斷要求。在大部分情況下,中斷的結果會是宣告的異常狀況,此異常狀況會擲出至偵測到停擺要求時所控制的應用程式碼。之後,應用程式可以處理異常狀況,並傳回適當的錯誤給呼叫端。
註: 如果同時偵測到多個停擺要求,每一個要求會等待對第一個停擺的要求完成第一次執行緒傾出之後,再嘗試中斷該要求。
[17.0.0.3 以及更新版本]

配置太慢和停擺要求臨界值

如果要配置太慢和停擺要求臨界值,請在 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