느리거나 정지된 요청 발견

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 열은 요청의 해당 조작에 소요된 시간을 표시합니다. 더하기 부호(+)는 아직 실행 중인 요청 내의 이벤트를 표시합니다. 다음 행은 +가 없는 지속 기간을 표시합니다. 이는 지정된 지속 기간 내에 해당 조작이 완료되었음을 나타냅니다. Operation은 해당 조작의 EVENT TYPECONTEXT INFO(선택사항)를 표시합니다. 이벤트 유형 및 컨텍스트 정보에 대한 자세한 정보는 이벤트 로깅의 내용을 참조하십시오.

메시지를 분석하면 이 요청이 느린 이유를 파악할 수 있습니다. 그러나 이 요청이 이 시점에 정지했는지 아니면 느리게 실행되고 있는지는 판별하기 어려울 수 있습니다. 따라서 지정된 <slowRequestThreshold>의 간격으로 느린 요청에 대해 세 개의 메시지가 로깅됨을 볼 수 있습니다. 세 개의 서로 다른 스택 추적 및 요청 데이터를 사용하면 이 문제에 대해 좀 더 자세한 정보를 알 수 있습니다. 세 번째 경고 후에는 요청의 지속 시간이 정지 요청 발견 임계값을 초과하지 않는 한 추가 경고가 로깅되지 않습니다.

정지 요청 발견

요청이 기본 hungRequestThreshold 또는 구성된 임계값을 초과하면 메시지 로그 파일에 경고 메시지가 요청에 대한 세부사항과 함께 기록됩니다. 요청의 세부사항 및 요청을 구성하는 이벤트가 캡처됩니다. 정지 요청 발견의 경우에는 연속된 세 개의 스레드 덤프(javacore)가 1분 간격으로 작성됩니다. 다음 로그 메시지 샘플은 정지 요청 발견 임계값을 초과한 요청에 대한 로그 메시지를 보여줍니다. 기본 지속 시간 값은 10분입니다. 다음 예제에 구성되어 있는 값은 4분입니다.
[WARNING ] TRAS0114W: Request 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: Request AAA7WlpP7l7_AAAAAAAAAAA
이전에 정지된 것으로 발견되고 479999.681초 이후에 완료되었습니다.
참고: 요청이 정지된 것으로 발견되면 연속된 세 개의 스레드 덤프가 시작됩니다. 세 번의 스레드 덤프가 완료되면 추가 스레드 덤프는 새 요청이 정지된 것으로 발견되는 경우에만 작성됩니다.
[17.0.0.3 and later]요청 타이밍 구성에서 interruptHungRequeststrue로 설정된 경우 첫 번째 스레드 덤프가 완료된 후 정지 요청을 인터럽트하려고 시도합니다. 서버가 IBM JRE를 사용 중일 때 InterruptibleIOContext 및 InterruptibleLockContext와 같은 com.ibm.jvm 패키지의 클래스를 사용하여 요청을 인터럽트합니다. 다른 메소드는 서버에서 구성되는 기능과 정지 요청이 발견될 때 애플리케이션이 실행하는 코드에 따라 요청을 인터럽트하는 데 사용될 수 있습니다. 대부분의 경우 인터럽트의 결과는 정지 요청이 발견되었을 때 제어 상태에 있던 애플리케이션 코드로 처리되는 선언된 예외입니다. 그런 다음 애플리케이션은 예외를 처리하고 호출자에게 적절한 오류를 리턴할 수 있습니다.
참고: 여러 정지 요청이 동시에 발견되는 경우 각 요청은 첫 번째 정지 요청에 대한 첫 번째 스레드 덤프가 완료될 때까지 기다렸다가 해당 요청을 인터럽트하려고 시도합니다.
[17.0.0.3 and later]

느리고 정지한 요청 임계값 구성

server.xml 파일의 <requestTiming/> 구성에서 slowRequestThresholdhungRequestThreshold를 설정하여 느리고 정지한 요청 임계값을 구성합니다. 이 설정은 시간 제한이 있는 모든 요청에 대해 느리고 정지한 단일 요청 임계값을 설정합니다.

또한 다른 유형의 요청에 대해 느리고 정지한 요청 임계값을 서로 다르게 설정할 수 있습니다. server.xml 파일의 임베디드 <servletTiming/> 또는 <jdbcTiming/> 구성은 <requestTiming/>에 정의되어 구성된 느리고 정지한 요청 임계값을 대체합니다. <servletTiming/> 구성은 애플리케이션 이름, 서블릿 이름 또는 둘 모두에 의해 느리고 정지한 요청 임계값을 설정할 수 있습니다. <jdbcTiming/> 구성은 데이터 소스 이름, SQL 문자열 또는 둘 모두에 의해 느리고 정지한 요청 임계값을 설정할 수 있습니다. 두 경우 모두 eventLogging-1.0 기능에 의해 보고된 대로 요청의 컨텍스트 정보에서 이름을 가져옵니다.

이벤트 로그에는 서버가 처리한 각 요청에 대한 유형 및 컨텍스트 정보가 포함되어 있습니다. 유형 및 컨텍스트 정보를 사용하여 다른 임계값이 필요한 요청에 대해 server.xml 파일의 <servletTiming/> 또는 <jdbcTiming/> 구성을 작성할 수 있습니다.

각 요청에 대해 제공되는 컨텍스트 정보에 대한 자세한 정보는 제품 문서에서 이벤트 로깅의 내용을 참조하십시오. <servletTiming/> 또는 <jdbcTiming/> 구성은 루트 레벨 요청 시간을 제한하는 데에만 사용할 수 있습니다. 예를 들어, 서블릿 요청이 JDBC 조회를 작성하는 경우 서블릿 요청이 루트 레벨 요청이기 때문에 JDBC 조회 시간을 제한할 수 없습니다.

하나의 특정 서블릿 및 하나의 특정 웹 애플리케이션에 대해 <servletTiming/> 구성이 임베드된 다음 <requestTiming/> 구성을 참조하십시오.
<requestTiming slowRequestThreshold="10s" hungRequestThreshold="10m">
  <servletTiming servletName="Arm10Servlet" hungRequestThreshold=”20s”/>
  <servletTiming appName="SecurityExchangeApp” hungRequestThreshold=”2h”/>
</requestTiming>

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

파일 이름: rwlp_requesttiming.html