Tomcatでリクエストの処理遅延の検知する

概要

Tomcat (6.0.36、7.0.14以降)では、処理に時間がかかっているリクエストを検知することができます。server.xmlのHost要素内に、次のようにStuckThreadDetectionValveを定義すると、

<Valve className="org.apache.catalina.valves.StuckThreadDetectionValve" threshold="300" />

処理に5分(300秒)を超える時間がかかっているリクエストを検知し、次のようなログを出力します。

05-Nov-2015 20:26:09.857 WARNING [ContainerBackgroundProcessor[StandardEngine[Catalina]]] org.apache.catalina.valves.StuckThreadDetectionValve.notifyStuckThreadDetected Thread "http-nio-18080-exec-7" (id=30) has been active for 7,627 milliseconds (since 15/11/05 20:26) to serve the same request for http://openam09.example.co.jp:18080/sample/sample.jsp and may be stuck (configured threshold for this StuckThreadDetectionValve is 5 seconds). There is/are 1 thread(s) in total that are monitored by this Valve and may be stuck.
 java.lang.Throwable
        at java.lang.Thread.sleep(Native Method)
        at org.apache.jsp.sample_jsp._jspService(sample_jsp.java:110)
        at org.apache.jasper.runtime.HttpJspBase.service(HttpJspBase.java:70)
        at javax.servlet.http.HttpServlet.service(HttpServlet.java:729)
        at org.apache.jasper.servlet.JspServletWrapper.service(JspServletWrapper.java:438)
        at org.apache.jasper.servlet.JspServlet.serviceJspFile(JspServlet.java:396)
        at org.apache.jasper.servlet.JspServlet.service(JspServlet.java:340)
        at javax.servlet.http.HttpServlet.service(HttpServlet.java:729)
        at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:291)
        at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206)
        at org.apache.tomcat.websocket.server.WsFilter.doFilter(WsFilter.java:52)
        at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:239)
        at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206)
        at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:217)
        at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:106)
        at org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:502)
        at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:142)
        at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:79)
        at org.apache.catalina.valves.AbstractAccessLogValve.invoke(AbstractAccessLogValve.java:616)
        at org.apache.catalina.valves.StuckThreadDetectionValve.invoke(StuckThreadDetectionValve.java:208)
        at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:88)
        at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:518)
        at org.apache.coyote.http11.AbstractHttp11Processor.process(AbstractHttp11Processor.java:1091)
        at org.apache.coyote.AbstractProtocol$AbstractConnectionHandler.process(AbstractProtocol.java:673)
        at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1500)
        at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.run(NioEndpoint.java:1456)
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
        at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61)
        at java.lang.Thread.run(Thread.java:744)

05-Nov-2015 20:26:19.861 WARNING [ContainerBackgroundProcessor[StandardEngine[Catalina]]] org.apache.catalina.valves.StuckThreadDetectionValve.notifyStuckThreadCompleted Thread "http-nio-18080-exec-7" (id=30) was previously reported to be stuck but has completed. It was active for approximately 10,002 milliseconds.

注意事項

ただし、上記説明は厳密には正しくありません。5分を超えても、ログが出力されない場合もあります。処理遅延の検知はバックグラウンドプロセスが行っており、最大でバックグラウンドプロセスの実行間隔分(backgroundProcessorDelay)の誤差が生じるためです。

backgroundProcessorDelayはデフォルトで10秒であるため、実際には300～310(300+10)秒の間で遅延を検知することになります。例えば、303秒で処理が終了し、307秒で遅延検知が動作したのであれば、その遅延処理はログが出力されないことになります。

backgroundProcessorDelayは0やマイナス値にはできないので、誤差なく処理遅延を検知することはできないようです。処理に5分(300秒)を超える時間がかかっている全てのリクエストを検知したいということであれば、backgroundProcessorDelayの数値(10)を引いた290をthresholdに設定する必要があります。