Liberty 設定檔:偵測過慢和停擺的要求
只要有要求的持續時間超過所配置的臨界值,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(選用)。如需事件類型和環境定義資訊的相關資訊,請參閱Liberty:事件記載。
您可以分析訊息,藉以瞭解要求太慢的原因。不過,可能難以判斷要求是停留在該點或者仍舊慢慢執行。因此,對於在 <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 秒後完成。
註: 當偵測到要求當掉時,會起始一系列的三個執行緒傾出。在三個執行緒傾出完成之後,只有在偵測到新要求當掉時,才會建立進一步的執行緒傾出。