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 Ausführung einer Anforderung länger dauert, als in der Konfiguration vorgesehen, wird eine Warnnachricht in die Nachrichtenprotokolldatei geschrieben. Einzelheiten zu der Anforderung und zu den Ereignissen, aus denen sich die Anforderung zusammensetzt, werden erfasst.
Das folgende Beispiel zeigt die Protokollnachricht für eine Anforderung, die den Schwellenwert für langsame Anforderung überschritten hat. Der Standardwert ist 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>
<DURATION AND OPERATIONS Table>
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 einer 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: Request AAA7WlpP7l7_AAAAAAAAAAA
Sie wurde zuvor als blockiert erkannt und 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.
[17.0.0.3 und höher]Wenn interruptHungRequests in der Timing-Konfiguration der Anforderung auf true gesetzt wurde, wird versucht, die blockierte Anforderung zu unterbrechen, nachdem der erste Threadspeicherauszug ausgeführt wurde. Wenn der Server eine IBM JRE verwendet, werden die Klassen im Paket com.ibm.jvm, wie z. B. InterruptibleIOContext und InterruptibleLockContext verwendet, um die Anforderung zu unterbrechen. Es können möglicherweise auch andere Methoden verwendet werden, um die Anforderung zu unterbrechen, je nachdem, welche Features im Server konfiguriert sind und welchen Code die Anwendung ausführt, wenn die blockierte Anforderung erkannt wird. In den meisten Fällen resultiert eine Unterbrechnung in einer deklarierten Ausnahmebedingung, die für den Anwendungscode ausgelöst wird, der ausgeführt wurde, als die blockierte Anforderung erkannt wurde. Die Anwendung kann anschließend die Ausnahme verarbeiten und dem aufrufenden Programm einen entsprechenden Fehler zurückgeben.
Anmerkung: Wenn mehrere blockierte Anforderungen gleichzeitig erkannt werden, wartet jede Anforderung, bis der erste Threadspeicherauszug für die erste blockierte Anforderung erstellt wurde, bevor versucht wird, diese Anforderung zu unterbrechen.
[17.0.0.3 und höher]

Schwellenwerte für langsame und blockierte Anforderungen konfigurieren

Die Schwellenwerte für die langsamen und blockierten Anforderungen werden konfiguriert, indem Sie slowRequestThreshold und hungRequestThreshold über die <requestTiming/>-Konfiguration in der Datei server.xml festlegen. Diese Einstellung legt einen einzigen Schwellenwert für langsame und blockierte Anforderungen für alle Anforderungen fest, die zeitgesteuert sind.

Sie können auch unterschiedliche Schwellenwerte für langsame und blockierte Anforderungen für unterschiedliche Anforderungstypen festlegen. Eine integrierte <servletTiming/>- oder <jdbcTiming/>-Konfiguration in der Datei server.xml überschreibt den konfigurierten Schwellenwert für langsame und blockierte Anforderungen, der über die <requestTiming/>-Konfiguration definiert wurde. Eine <servletTiming/>-Konfiguration kann den Schwellenwert für langsame und blockierte Anforderungen nach Anwendungsnamen, Servletnamen oder beides angeben. Eine <jdbcTiming/>-Konfiguration kann den Schwellenwert für langsame und blockierte Anforderungen nach Datenquellennamen, SQL-Zeichenfolge oder beides angeben. In beiden Fällen werden die Namen aus den Kontextinformationen für die Anforderung entnommen, wie sie über das Feature eventLogging-1.0 berichtet werden.

Das Ereignisprotokoll enthält die Typ- und Kontextinformationen für jede Anforderung, die vom Server verarbeitet wurde. Sie können mit den Typ- und Kontextinformationen eine <servletTiming/>- oder <jdbcTiming/>-Konfiguration in der Datei server.xml für die Anforderungen erstellen, für die unterschiedliche Schwellenwerte erforderlich sind.

Weitere Informationen darüber, welche Kontextinformationen für jede Anforderung bereitgestellt werden, finden Sie in der Produktdokumentation unter Ereignisprotokollierung. Eine <servletTiming/>- oder <jdbcTiming/>-Konfiguration kann nur für die Zeitsteuerung einer Anforderung auf Stammebene verwendet werden. Wenn beispielsweise eine Servletanforderung eine JDBC-Abfrage absetzt, kann die JDBC-Abfrage nicht zeitgesteuert werden, weil es sich bei der Servletanforderung um eine Anforderung auf Stammebene handelt.

Sehen Sie sich die folgende <requestTiming/>-Konfiguration mit integrierter <servletTiming/>-Konfiguration für ein bestimmtes Servlet und eine bestimmte Webanwendung an:
<requestTiming slowRequestThreshold="10s" hungRequestThreshold="10m">
  <servletTiming servletName="Arm10Servlet" hungRequestThreshold=”20s”/>
  <servletTiming appName="SecurityExchangeApp” hungRequestThreshold=”2h”/>
</requestTiming>

Symbol das den Typ des Artikels anzeigt. Referenzartikel

Dateiname: rwlp_requesttiming.html