Erkennung langsamer und blockierter Anforderungen

Das Feature requestTiming-1.0 stellt Diagnoseinformationen bereit, wenn die Dauer einer Anforderung den konfigurierten Schwellenwert überschreitet.

Das Timing-Feature für Anforderungen kann die Dauer jeder Anforderung überwachen, die im System eingeht. Sie können das Feature so konfigurieren, dass es Ausschau nach langsamen und blockierten Anforderungen hält.

Erkennung langsamer Anforderungen

Wenn die Dauer einer Anforderung den konfigurierten Zeitwert überschreitet, wird eine Warnung in die Nachrichtenprotokolldatei geschrieben. Einzelheiten zu der Anforderung und zu den Ereignissen, aus denen sich die Anforderung zusammensetzt, werden erfasst.
Im folgenden Beispiel sehen Sie die Protokollnachricht für eine Anforderung, die den Schwellenwert für langsame Anforderungen überschritten hat (der Standardwert sind 10 Sekunden):
[12/1/14 11:58:09:629 IST] 0000001d com.ibm.ws.request.timing.SlowRequestTimer                   W TRAS0112W: Die Anforderung AABjnS+lIn0_AAAAAAAAAAb im Thread 00000021 ist seit mindestens 10003,571 ms aktiv. Der folgende Stack-Trace zeigt, was momentan in diesem Thread ausgeführt wird.

 	 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:%')
Die Anforderung wird weiterhin überwacht und es wird eine weitere Warnung protokolliert, wenn die Anforderung mehr als weitere 10 Sekunden ausgeführt wird. Die Protokollnachrichten haben das folgende Format:
TRAS0112W: Die Anforderung < (Anforderungs-ID)> im Thread <THREAD-ID> ist seit mindestens <DAUER> aktiv. Der folgende Stack-Trace zeigt, was momentan in diesem Thread ausgeführt wird.
<STACK-TRACE>
<Tabelle DURATION AND OPERATIONS>
ANFORDERUNGS-ID
Anhand dieser ID kann nach Protokoll- und Tracenachrichten für die Anforderung gesucht werden. Wenn Sie die Binärprotokollierung verwenden, können Sie mithilfe des Befehls für Binärprotokolle nach Protokoll- und Traceeinträgen mit der Erweiterung Anforderung-ID suchen.
STACK-TRACE
Zeigt die ausgeführte Methode an. Im vorherigen Beispiel sehen Sie den Stack-Trace der aktuellen Anforderung hinter der Zeile TRAS0112W.
Tabelle DURATION AND OPERATIONS
Im Anschluss an den Stack-Trace finden Sie das tabellarische Format der Anforderung mit den Angaben zur Dauer und zu den Operationen (auch als Ereignisse bezeichnet). Die Spalte Duration enthält die Dauer der entsprechenden Operation der Anforderung. Das Pluszeichen (+) kennzeichnet Ereignisse in der Anforderung, die immer noch aktiv sind. In der nächsten Zeile wird die Dauer ohne Pluszeichen angezeigt, was bedeutet, dass die entsprechende Operation innerhalb des festgelegten Zeitraums ausgeführt wurde. In der Spalte ""Operation" werden der Ereignistyp und Kontextinformationen (optional) für die jeweilige Operation angezeigt. Weitere Informationen zu den Ereignistypen und Kontextinformationen finden Sie unter Ereignisprotokollierung.

Durch Analyse der Nachrichten können Sie herausfinden, warum die Anforderung langsam ist. Ob die Anforderung an einem bestimmten Punkt feststeckt oder ob sie weiterhin langsam ausgeführt wird, lässt sich jedoch möglicherweise nur schwer feststellen. Deshalb sehen Sie drei Nachrichten, die für jede langsame Anforderung in dem mit <slowRequestThreshold> festgelegten Intervall protokolliert werden. Mithilfe der drei verschiedenen Stack-Trace- und Anforderungsdaten können Sie einen besseren Einblick in das Problem gewinnen. Nach der dritten Warnung werden keine weiteren Warnungen zu der Anforderung protokolliert, sofern die Dauer der Anforderung nicht den Schwellenwert für die Erkennung blockierter Anforderungen überschreitet.

Erkennung blockierter Anforderungen

Wenn die Anforderung den Standardwert bzw. den konfigurierten Schwellenwert für hungRequestThreshold überschreitet, wird eine Warnung zusammen mit den Anforderungsdetails in die Nachrichtenprotokolldatei geschrieben. Einzelheiten zu der Anforderung und zu den Ereignissen, aus denen sich die Anforderung zusammensetzt, werden erfasst. Bei der Erkennung einer blockierten Anforderung wird eine Serie von drei Threadspeicherauszügen (Java-Kernspeicherauszüge) mit einer Verzögerung von jeweils 1 Minute zwischen den Speicherauszügen erstellt. Das folgende Nachrichtenprotokollbeispiel zeigt die Protokollnachrichten für eine Anforderung, die den Schwellenwert für die Erkennung blockierter Anforderungen überschritten hat. Der Wert für die Standarddauer ist 10 Minuten. Der im folgenden Beispiel konfigurierte Wert ist 4 Minuten.
[WARNING ] TRAS0114W: Die Anforderung AAA7WlpP7l7_AAAAAAAAAAA im Thread 00000021 ist seit mindestens 240001,015 ms aktiv. Die folgende Tabelle zeigt die Ergebnisse, die während dieser Anforderung ausgeführt wurden.
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
Wenn eine Anforderung, die zunächst als blockiert erkannt wurde, später doch noch abgeschlossen wird, wird eine Nachricht ähnlich der folgenden protokolliert: TRAS0115W: Die zuvor als blockiert erkannte Anforderung AAA7WlpP7l7_AAAAAAAAAAA wurde nach 479999,681 Sekunden abgeschlossen.
Anmerkung: Bei der Erkennung einer blockierten Anforderung wird eine Serie von drei Threadspeicherauszügen eingeleitet. Nach der Fertigstellung der drei Threadspeicherauszüge werden weitere Threadspeicherauszüge nur erstellt, wenn neue blockierte Anforderungen erkannt werden.

Symbol das den Typ des Artikels anzeigt. Referenzartikel



Symbol für Zeitmarke Letzte Aktualisierung: 01.12.2016
http://www14.software.ibm.com/webapp/wsbroker/redirect?version=cord&product=was-libcore-mp&topic=rwlp_requesttiming
Dateiname: rwlp_requesttiming.html