Référentiel Liberty[8.5.5.6 ou ultérieure]

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 configuré pour les demandes lentes (par défaut, 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 DURATION 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 DURATION 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. La colonne Operation affiche le type d'événement EVENT TYPE et les informations de contexte CONTEXT INFO (facultatives) de cette opération. Pour en savoir plus sur les types d'événements et les informations de contexte, consultez Consignation 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. Lorsqu'une demande suspendue est détectée, une série de trois vidages de l'unité d'exécution est initiée (javacores), à 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.
[AVERTISSEMENT ] TRAS0114W : La demande AAA7WlpP7l7_AAAAAAAAAAA s'est exécutée sur l'unité d'exécution 00000021 pendant au moins 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 fini par être exécutée alors qu'elle était suspendue à l'origine, un message similaire à l'exemple suivant est consigné : TRAS0115W : La demande AAA7WlpP7l7_AAAAAAAAAAA, qui a été préalablement détectée comme suspendue, s'est terminée au bout de 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.

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

Dispositions pour les centres de documentation | Commentaires


Icône d'horodatage Dernière mise à jour: Wednesday, 2 September 2015
http://www14.software.ibm.com/webapp/wsbroker/redirect?version=phil&product=was-libcore-mp&topic=rwlp_requesttiming
Nom du fichier : rwlp_requesttiming.html