Détection des demandes lentes ou suspendues

La fonction requestTiming-1.0 fournit des informations de diagnostic lorsque la durée d'une demande dépasse le seuil configuré.

La fonction de minutage des demandes peut contrôler la durée de chaque demande entrant dans le système. Vous pouvez configurer la fonction de manière à contrôler les demandes lentes et suspendues.

Détection de demandes lentes

Lorsque l'exécution d'une demande dépasse la durée configurée, un message d'avertissement est écrit dans le fichier journal des messages. Les détails sur les demandes et les événements formant la demande sont capturés.
L'exemple suivant montre le message de journal d'une demande ayant dépassé le seuil de détection des demandes lentes. La valeur par défaut est de 10 secondes :
[12/1/14 11:58:09:629 IST] 0000001d com.ibm.ws.request.timing.SlowRequestTimer                   W TRAS0112W : La demande AABjnS+lIn0_AAAAAAAAAAb s'est exécutée sur l'unité d'exécution 00000021 pendant au moins 10003.571ms. 
La trace de pile suivante montre ce qu'exécute cette unité d'exécution.

 	 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:%')
La demande continue d'être surveillée et un autre avertissement est consigné si la demande s'exécute au delà de 10 nouvelles secondes. Les messages des journaux ont le format suivant :
TRAS0112W: La demande <(ID DEMANDE)> s'est exécutée sur l'unité d'exécution <ID_UNITE_EXECUTION> pendant au moins <DUREE>. La trace de pile suivante montre ce qu'exécute cette unité d'exécution.
<TRACE DE PILE>
<Tableau DUREE et OPERATIONS>
ID DEMANDE
Ce même ID peut être utilisé pour rechercher les messages de journal et de trace correspondant à la demande. En particulier, si vous utilisez la journalisation binaire, vous pouvez rechercher les entrées de journal et de trace avec la même extension requestID en utilisant la commande de journal binaire.
TRACE DE PILE
Indique la méthode en cours d'exécution. Dans l'exemple précédent, vous pouvez voir une trace de pile de la demande en cours après la ligne TRAS0112W.
Tableau DUREE et OPERATIONS
Après la trace de pile se trouve le format tabulaire de la demande qui indique la durée et l'opération (également appelée événement). La colonne Duration indique la durée occupée par l'opération correspondante de la demande. Le signe plus (+) signale les événements de la demande qui sont toujours en cours d'exécution. La ligne suivante montre la durée sans +, ce qui indique que l'opération correspondante a été achevée dans les temps indiqués. L'opération affiche EVENT TYPE et CONTEXT INFO (facultatif) pour cette opération. Pour en savoir plus sur les types d'événements et les informations de contexte, consultez Journalisation des événements.

En analysant les messages, vous pouvez déterminer la raison pour laquelle la demande est lente. Cependant, il peut être difficile de déterminer si la demande est suspendue à ce moment donné ou si elle continue de s'exécuter lentement. C'est pourquoi trois messages sont consignés pour les demandes lentes à l'intervalle spécifié par <slowRequestThreshold>. Les trois enregistrements différents relatifs à la trace de pile et à la requête vous permettrons de mieux cerner le problème. Après le troisième avertissement, aucun autre avertissement n'est consigné au sujet de la demande, à moins que la durée de la demande ne dépasse le seuil de détection des demandes suspendues.

Détection des demandes suspendues

Si la demande dépasse la valeur par défaut définie pour hungRequestThreshold ou la valeur de seuil configurée, un message d'avertissement est écrit dans le fichier journal des messages, avec les détails de la demande. Les détails sur les demandes et sur les événements formant la demande sont capturés. Pour une détection de demande suspendue, une série de trois vidages de l'unité d'exécution (javacores) est initiée, à une minute d'intervalle. L'exemple suivant montre les messages de journal d'une requête ayant dépassé le seuil de détection des demandes suspendues. La durée par défaut est de 10 minutes. La valeur configurée dans l'exemple suivant est de 4 minutes.
[WARNING ] TRAS0114W: Request AAA7WlpP7l7_AAAAAAAAAAA was running on thread 00000021 for at least 240001.015ms. Le tableau suivant affiche les événements qui se sont exécutés lors de cette demande.
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
Si une demande s'achève après avoir été détectée comme suspendue initialement, un message similaire à l'exemple suivant est consigné :
TRAS0115W: Request AAA7WlpP7l7_AAAAAAAAAAA
It was previously detected to be hung and completed after 479999.681 s.
Remarque : Lorsqu'une demande est détectée comme étant suspendue, une série de trois vidages de l'unité d'exécution est initiée. Une fois les trois vidages de l'unité d'exécution achevés, d'autres vidages sont créés uniquement si de nouvelles demandes sont détectées comme étant suspendues.
[17.0.0.3 and later]Si interruptHungRequests est défini sur true dans la configuration du calcul du temps de la demande, un tentative est faite d'interrompre la demande suspendue une fois que le premier vidage de l'unité d'exécution est achevé. Lorsque le serveur utilise un JRE IBM, les classes incluses dans le package com.ibm.jvm, comme InterruptibleIOContext et InterruptibleLockContext, sont utilisées pour interrompre la demande. D'autres méthodes peuvent être utilisées pour interrompre la demande suivant les fonction configurées dans le serveur et suivant le code exécuté par l'application lorsque la demande suspendue est détectée. Dans la plupart des cas, le résultat d'une interruption est une exception déclarée qui est envoyée au code de l'application en charge lorsque la demande suspendue a été détectée. L'application peut ensuite traiter l'exception et renvoyer une erreur appropriée à l'appelant.
Remarque : Si plusieurs demandes suspendues sont détectées en même temps, chaque demande attend que le premier vidage d'unité d'exécution de la première demande suspendue s'achève avant de tenter une interruption de cette demande.
[17.0.0.3 and later]

Configuration des seuils de demandes lentes et suspendues

Les seuils des demandes lentes et suspendues sont configurés en définissant slowRequestThreshold et hungRequestThreshold dans la configuration <requestTiming/> dans le fichier server.xml. Ce réglage définit un seuil de demande lente et suspendu unique pour toutes les demandes temporisées.

Vous pouvez également définir différents seuils de demandes lentes et suspendues pour les différents types de demandes. Une configuration <servletTiming/> ou <jdbcTiming/> imbriquée dans le fichier server.xml remplace le seuil de demande lente et suspendue configuré défini dans <requestTiming/>. une configuration <servletTiming/> peut définir le seuil de demande lente et suspendue par nom d'application, par nom de servlet, ou les deux. Une configuration <jdbcTiming/> peut définir le seuil de demande lente et suspendue par nom de source de données, par chaîne sql, ou les deux. Dans les deux cas, les noms sont tirés des informations contextuelles de la demande, conformément au rapport de la fonction eventLogging-1.0.

Le journal des événements contient des informations sur le type et le contexte de chaque demande traitée par le serveur. Avec les informations sur le type et le contexte, vous pouvez créer une configuration <servletTiming/> ou <jdbcTiming/> dans le fichier server.xml pour les demandes qui nécessitent des valeurs de seuil différentes.

Pour en savoir plus sur les informations contextuelles fournies pour chaque demande, voir Journalisation des événements dans la documentation du produit. Une configuration <servletTiming/> ou <jdbcTiming/> peut uniquement être utilisée pour temporiser une demande au niveau de la racine. Par exemple, si une demande de servlet effectue une requête JDBC, la requête JDBC ne peut pas être temporisée car la demande de servlet est la demande de niveau racine.

Voir la configuration suivante <requestTiming/> avec configuration <servletTiming/> intégrée pour un servlet spécifique et une application Web spécifique :
<requestTiming slowRequestThreshold="10s" hungRequestThreshold="10m">
  <servletTiming servletName="Arm10Servlet" hungRequestThreshold=”20s”/>
  <servletTiming appName="SecurityExchangeApp” hungRequestThreshold=”2h”/>
</requestTiming>

Icône indiquant le type de rubrique Rubrique de référence

Nom du fichier : rwlp_requesttiming.html