Detección de solicitud lenta y de bloqueo

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 una solicitud se ejecuta durante más tiempo del que se ha configurado, se escribe 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.
El ejemplo siguiente muestra el registro de mensajes para una solicitud que ha cruzado el umbral de solicitud lenta. El valor predeterminado es 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. La siguiente línea muestra la duración sin +, que indica que la operación correspondiente se ha completado en la duración especificada. La operación muestra EVENT TYPE y CONTEXT INFO (opcional) para dicha operación. Para obtener más información sobre los tipos de sucesos e información de contexto, consulte 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. Para una detección de solicitud de bloqueo, se toma una serie de tres vuelcos de hebra (javacores) con un retardo de 1-minuto 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: Request AAA7WlpP7l7_AAAAAAAAAAA se estaba ejecutando 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 ha completado después de que se haya detectado como bloqueada inicialmente, se registra un mensaje similar al ejemplo siguiente:
TRAS0115W: Request AAA7WlpP7l7_AAAAAAAAAAA
Se había detectado anteriormente como bloqueada y completada después de 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.
[17.0.0.3 and later]Si interruptHungRequests está establecido en true en la configuración de temporización de solicitud, se realiza un intento para interrumpir la solicitud de bloqueo después de que se haya completado el primer volcado de hebra. Cuando el servidor está utilizando un IBM JRE, las clases en el paquete com.ibm.jvm, como InterruptibleIOContext y InterruptibleLockContext, se utilizan para interrumpir la solicitud. Se podrían utilizar otros métodos para interrumpir la solicitud en función de las características que están configuradas en el servidor, y del código que está ejecutando la aplicación cuando se detecta la solicitud de bloqueo. En la mayoría de los casos, el resultado de una interrupción es una excepción declarada que se lanza al código de aplicación que estaba en control cuando se detectó la solicitud de bloqueo. La aplicación puede manejar la excepción y devolver un error apropiado al interlocutor.
Nota: Si se detectan varias solicitudes de bloqueo simultáneamente, cada solicitud espera hasta que se completa el primer volcado de hebra para el primer bloqueo, antes de intentar interrumpir dicha solicitud.
[17.0.0.3 and later]

Configuración de los umbrales de solicitud lenta y de bloqueo

Los umbrales de solicitud lenta y de bloqueo se configuran estableciendo slowRequestThreshold y hungRequestThreshold en la configuración de <requestTiming/> en el archivo server.xml. Este valor establecer un único umbral de solicitud lenta y de bloqueo para todas las solicitudes que han agotado el tiempo de espera.

También puede establecer distintos umbrales de solicitud lenta y de bloqueo para tipos de solicitudes diferentes. Una configuración incorporada de <servletTiming/> o <jdbcTiming/> en el archivo server.xml altera temporalmente el umbral de solicitud lenta y de bloqueo configurado que está definido en <requestTiming/>. Una configuración de <servletTiming/> puede establecer el umbral de solicitud lenta y de bloqueo por nombre de aplicación, nombre de servlet o ambos. Una configuración de <jdbcTiming/> puede establecer el umbral de solicitud lenta y de bloqueo por nombre de origen de datos, serie sql o ambos. En ambos casos, los nombres se toman de la información de contexto para la solicitud, tal como lo notifica la característica eventLogging-1.0.

El registro de sucesos contiene la información de tipo y contexto para cada solicitud procesada por el servidor. Con la información de tipo y contexto, puede crear una configuración de <servletTiming/> o <jdbcTiming/> en el archivo server.xml para las solicitudes que requieren distintos valores de umbrales.

Si desea más información sobre qué información de contexto se proporciona para cada solicitud, consulte Registro de sucesos en la documentación del producto. Una configuración de <servletTiming/> o <jdbcTiming/> solo se puede utilizar para medir el tiempo de una solicitud de nivel raíz. Por ejemplo, si la solicitud de servlet realiza una consulta JDBC, la consulta JDBC no puede agotar el tiempo de espera porque la solicitud de servlet es la solicitud de nivel raíz.

Consulte la configuración siguiente de <requestTiming/> con la configuración incorporada de <servletTiming/> para un servlet específico y una aplicación web específica:
<requestTiming slowRequestThreshold="10s" hungRequestThreshold="10m">
  <servletTiming servletName="Arm10Servlet" hungRequestThreshold=”20s”/>
  <servletTiming appName="SecurityExchangeApp” hungRequestThreshold=”2h”/>
</requestTiming>

Icono que indica el tipo de tema Tema de referencia

Nombre de archivo: rwlp_requesttiming.html