Liberty Repository[8.5.5.6 이상]

느리거나 정지된 요청 발견

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 TYPECONTEXT 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초 후 완료되었습니다.
참고: 요청이 정지된 것으로 발견되면 연속된 세 개의 스레드 덤프가 시작됩니다. 세 번의 스레드 덤프가 완료되면 추가 스레드 덤프는 새 요청이 정지된 것으로 발견되는 경우에만 작성됩니다.

주제의 유형을 표시하는 아이콘 참조 주제

Information Center 이용 약관 | 피드백


시간소인 아이콘 마지막 업데이트 날짜: Wednesday, 2 September 2015
http://www14.software.ibm.com/webapp/wsbroker/redirect?version=phil&product=was-libcore-mp&topic=rwlp_requesttiming
파일 이름: rwlp_requesttiming.html