Perfil Liberty: Detección de solicitudes lentas y colgadas
La característica requestTiming-1.0 proporciona información de diagnóstico cuando la duración de alguna solicitud supera el umbral configurado.
Detección de solicitud lenta
Cuando se ha ejecutado una solicitud durante más tiempo del configurado, se graba un mensaje de aviso en el archivo de registro de mensajes. Se capturan los detalles sobre la solicitud y los sucesos que configuran la solicitud.[12/1/14 11:58:09:629 IST] 0000001d com.ibm.ws.request.timing.SlowRequestTimer W TRAS0112W: La solicitud AABjnS+lIn0_AAAAAAAAAAb se ha ejecutado en la hebra 00000021 durante al menos 10003.571ms. En el siguiente seguimiento de la pila se muestra que esta hebra se está ejecutando actualmente.
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: Se ha ejecutado la solicitud < (ID de solicitud)> en la hebra <THREADID> durante al menos <DURATION>. En el siguiente seguimiento de la pila se muestra que esta hebra se está ejecutando actualmente.
<STACK TRACE>
<DURATION AND OPERATIONS Table>
- REQUEST ID
- Este mismo ID se puede utilizar para buscar mensajes de registro y de rastreo correspondientes a la solicitud. En particular, si utiliza el registro binario, puede buscar entradas de registro y de rastreo con la misma extensión requestID utilizando el mandato de registro binario.
- STACK TRACE
- Indica el método que se está ejecutando. En el ejemplo anterior, puede ver un rastreo de pila de la solicitud actual después de la línea TRAS0112W.
- DURATION AND OPERATIONS Table
- Después del seguimiento de la pila, puede encontrar el formato tabular de la solicitud que muestra la duración y la operación (también conocida como suceso). La columna Duración indica la hora que se toma mediante la correspondiente operación de la solicitud. El signo más (+) indica sucesos dentro de la solicitud que todavía se están ejecutando. En la línea siguiente se muestra la duración sin +, que indica que se ha completado la operación correspondiente en la duración especificada. Operación muestra EVENT TYPE y CONTEXT INFO (que es opcional) para esa operación. Para obtener más información sobre los tipos de sucesos e información de contexto, consulte Liberty: Registro de sucesos.
Al analizar los mensajes, puede averiguar el motivo por el cual la solicitud es lenta. Sin embargo, puede ser difícil determinar si la solicitud se ha atascado en ese punto o todavía está ejecutándose lentamente. Por lo tanto, puede ver tres mensajes que se registran para cualquier solicitud lenta en el intervalo de <slowRequestThreshold> especificado. Mediante la utilización de tres datos distintos de rastreo de pila y solicitud, se obtiene un mejor enfoque del problema. Tras el tercer aviso, ya no se registran más avisos sobre la solicitud a menos que la duración de la solicitud traspase el umbral de detección de solicitud de bloqueo.
Detección de solicitud de bloqueo
Si la solicitud supera el valor predeterminado de hungRequestThreshold o el valor de umbral configurado, se graba un mensaje de aviso en el archivo de registro de mensajes junto con los detalles sobre la solicitud. Se capturan los detalles sobre la solicitud y los sucesos que configuran la solicitud. En el caso de una detección de solicitud de bloqueo, se toma una serie de tres vuelcos de hebra (javacores), con 1 minuto de retraso entre ellos. El siguiente ejemplo de mensaje de registro muestra los mensajes de registro para una solicitud que ha traspasado el umbral de detección de la solicitud de bloqueo. El valor de la duración predeterminada es de 10 min. El valor que se configura en el ejemplo siguiente es de 4 min.Duración Operación
240001.754ms + websphere.servlet.service | TestWebApp | TestServlet?sleepTime=480000
0.095ms websphere.session.setAttribute | mCzBMyzMvAEnjMJJx9zQYIw | userID
0.007ms websphere.session.setAttribute | mCzBMyzMvAEnjMJJx9zQYIw | visitCount