Liberty : Détection de requête lente ou bloquée
La fonction requestTiming-1.0 fournit des informations de diagnostic lorsque la durée d'une demande dépasse le seuil configuré.
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.[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:%')
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>
- 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 Liberty : Journalisation d'é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.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