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.

La característica de temporización de solicitud puede realizar un seguimiento de la duración de cada solicitud que entra en el sistema. Puede configurar la característica para que vigile las solicitudes lentas y de bloqueo.

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.
En el ejemplo siguiente se muestra el mensaje de registro para una solicitud que ha traspasado el umbral de solicitud lenta (el valor predeterminado es de 10 segundos):
[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:%')
Se sigue supervisando la solicitud y se registro otro aviso si la solicitud se ejecuta durante 10 segundos más. Los mensajes de registro se hallan en el formato siguiente:
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.
[AVISO] TRAS0114W: Se ha ejecutado la solicitud AAA7WlpP7l7_AAAAAAAAAAA en la hebra 00000021 durante al menos 240001.015ms. En la tabla siguiente se muestran los sucesos que se han ejecutado durante esta ejecución.
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
Si una solicitud se completa más tarde, después de haberse detectado como bloqueada inicialmente, se registra un mensaje similar al ejemplo siguiente: TRAS0115W: La solicitud AAA7WlpP7l7_AAAAAAAAAAA, que anteriormente se ha detectado como bloqueada, se ha completado tras 479999.681 s.
Nota: Cuando se detecta que una solicitud está bloqueada, se inicia una serie de tres vuelcos de hebra. Tras finalizar los tres vuelcos de hebra, se crearán más vuelcos de hebra solamente si se detectan nuevas solicitudes bloqueadas.

Icono que indica el tipo de tema Tema de referencia



Icono de indicación de fecha y hora Última actualización: Tuesday, 6 December 2016
http://www14.software.ibm.com/webapp/wsbroker/redirect?version=cord&product=was-nd-mp&topic=rwlp_requesttiming
Nombre de archivo:rwlp_requesttiming.html