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

## 概要

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

```xml
<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に設定する必要があります。