느리고 정지된 요청 발견
requestTiming-1.0 기능은 요청의 지속 시간이 구성된 임계값을 초과하는 경우 진단 정보를 제공합니다.
이 요청 타이밍 기능은 시스템이 수신하는 모든 요청의 지속 시간을 추적할 수 있습니다. 느리거나 정지한 요청을 감시하도록 이 기능을 구성할 수 있습니다.
느린 요청 발견
요청이 구성된 시간보다 느리게 실행되는 경우에는 메시지 로그 파일에 경고 메시지가 기록됩니다. 요청의 세부사항 및 요청을 구성하는 이벤트가 캡처됩니다.다음 샘플은 느린 요청 임계값을 초과한 요청에 대한 로그 메시지를 보여줍니다(기본값은 10초).
[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:%')
이 요청은 계속해서 모니터되며
이 요청이 또 다시 10초를 초과하여 실행 중인 경우에는 추가 경고가 로그됩니다. 이 로그 메시지의 형식은 다음과 같습니다.
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>
- REQUEST ID
- 이 ID는 요청에 대응하는 로그 및 추적 메시지를 검색하는 데 사용할 수 있습니다. 특히, 2진 로깅을 사용하는 경우에는 2진 로그 명령을 사용하여 동일한 requestID 확장이 있는 로그 및 추적 항목을 검색할 수 있습니다.
- STACK TRACE
- 실행 중인 메소드를 표시합니다. 이전 샘플에서는 TRAS0112W 행 뒤에 현재 요청의 스택 추적이 표시되어 있습니다.
- DURATION AND OPERATIONS Table
- 스택 추적 뒤에는 지속 시간 및 조작(이벤트라고도 함)을 보여주는 표 형식의 요청이 있습니다. Duration 열은 요청의 해당 조작에 소요된 시간을 표시합니다. 더하기 부호(+)는 아직 실행 중인 요청 내의 이벤트를 표시합니다. 다음 행에는 +가 없는 지속 시간이 표시되어 있으며, 이는 지정된 지속 시간 내에 해당 조작이 완료되었음을 표시합니다. 조작은 자신의 EVENT TYPE 및 CONTEXT INFO(선택사항)를 표시합니다. 이벤트 유형 및 컨텍스트 정보에 대한 자세한 정보는 이벤트 로깅의 내용을 참조하십시오.
메시지를 분석하면 이 요청이 느린 이유를 파악할 수 있습니다. 그러나 이 요청이 이 시점에 정지했는지 아니면 느리게 실행되고 있는지는 판별하기 어려울 수 있습니다. 따라서 지정된 <slowRequestThreshold> 간격 내에 있는 느린 요청에 대해서는 세 개의 메시지가 로그됩니다. 세 개의 서로 다른 스택 추적 및 요청 데이터를 사용하면 이 문제에 대해 좀 더 자세한 정보를 알 수 있습니다. 세 번째 경고 후에는 요청의 지속 시간이 정지 요청 발견 임계값을 초과하지 않는 한 추가 경고가 로그되지 않습니다.
정지 요청 발견
요청이 기본 hungRequestThreshold 또는 구성된 임계값을 초과하면 메시지 로그 파일에 경고 메시지가 요청에 대한 세부사항과 함께 기록됩니다. 요청의 세부사항 및 요청을 구성하는 이벤트가 캡처됩니다. 정지 요청 발견의 경우에는 연속된 세 개의 스레드 덤프(javacore)가 1분 간격으로 작성됩니다. 다음 로그 메시지 샘플은 정지 요청 발견 임계값을 초과한 요청에 대한 로그 메시지를 보여줍니다. 기본 지속 시간 값은 10분입니다. 다음 예제에 구성되어 있는 값은 4분입니다.[WARNING ] TRAS0114W: 요청 AAA7WlpP7l7_AAAAAAAAAAA가 스레드 00000021에서 240001.015밀리초 이상 실행되고 있었습니다. 다음 표에는 이 요청 중에 실행된 이벤트가 표시되어 있습니다.
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
처음에 정지된 것으로 발견된 요청이 나중에 완료되는 경우에는
다음 예제와 유사한 메시지가 로그됩니다. TRAS0115W: 이전에 정지된 것으로 발견된 요청 AAA7WlpP7l7_AAAAAAAAAAA가 479999.681초 후 완료되었습니다.
참고: 요청이 정지된 것으로 발견되면 연속된 세 개의 스레드 덤프가 시작됩니다. 세 번의 스레드 덤프가 완료되면 추가 스레드 덤프는 새 요청이 정지된 것으로 발견되는 경우에만 작성됩니다.