2017年6月16日金曜日

[Tomcat]StuckThreadDetectionValveを使って遅延した処理の情報をログに出力する

StuckThreadDetectionValveを使うことで、処理遅延が発生したスレッドを検知することができる。

使い方は下の通り

設定を追加する

conf/server.xmlにStuckThreadDetectionValveを使用するように設定をする。

thresholdを使って、どれぐらい遅延したら検知するかを設定する。
デフォルトは600秒となっている。下のように60と設定すると60秒となる。

  


ログの結果

単純に一定時間スリープするServletで試すと下のようなログが出力される。

16-Jun-2017 21:14:37.445 警告 [ContainerBackgroundProcessor[StandardEngine[Catalina]]] org.apache.catalina.valves.StuckThreadDetectionValve.notifyStuckThreadDetected Thread [http-nio-8080-exec-6] (id=[29]) has been active for [62,731] milliseconds (since [17/06/16 21:13]) to serve the same request for [http://localhost:8080/hoge] and may be stuck (configured threshold for this StuckThreadDetectionValve is [60] 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 java.lang.Thread.sleep(Thread.java:340)
at java.util.concurrent.TimeUnit.sleep(TimeUnit.java:386)
at hoge.HogeServlet.doGet(HogeServlet.kt:11)
at javax.servlet.http.HttpServlet.service(HttpServlet.java:635)
at javax.servlet.http.HttpServlet.service(HttpServlet.java:742)
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:231)

その後処理が完了すると、下のようなログも出力される

16-Jun-2017 21:15:37.465 警告 [ContainerBackgroundProcessor[StandardEngine[Catalina]]] org.apache.catalina.valves.StuckThreadDetectionValve.notifyStuckThreadCompleted Thread [http-nio-8080-exec-6] (id=[29]) was previously reported to be stuck but has completed. It was active for approximately [120,031] milliseconds.

これで、処理遅延などが発生した場合に自動的にスレッドダンプが取得できる。
障害時にスレッドダンプとってません問題も回避できそうな気もする。