CLOVER🍀

That was when it all began.

Tomcat 7から追加された、StuckThreadDetectionValveを使う

Java Scala Tomcat

こちらの記事にすごーくしれっと載っているのですが
http://www.atmarkit.co.jp/fjava/rensai4/tomcat7_03/03.html
Tomcat 7から、StuckThreadDetectionValveというValveが追加されています。

これを使うと、リクエストに時間がかかっている処理を検知することができます。自分の仕事でも、半年くらい前に使ってみたのですが割と便利だったりするので、メモっておきましょう。

まずは、ムダに処理時間がかかる、ダミーのサーブレットを用意します。
build.sbt

name := "tomcat-stuck-thread"

version := "0.0.1"

scalaVersion := "2.9.2"

seq(webSettings :_*)

libraryDependencies ++= Seq(
  "javax.servlet" % "javax.servlet-api" % "3.0.1" % "provided",
  "org.mortbay.jetty" % "jetty" % "6.1.22" % "container"
)

artifactName in packageWar := {
  (scalaVersion: ScalaVersion, module: ModuleID, artifact: Artifact) =>
    artifact.name + "." + artifact.extension
}

project/plugins.sbt

libraryDependencies <+= sbtVersion(v => v match {
  case "0.11.0" => "com.github.siasia" %% "xsbt-web-plugin" % "0.11.0-0.2.8"
  case "0.11.1" => "com.github.siasia" %% "xsbt-web-plugin" % "0.11.1-0.2.10"
  case "0.11.2" => "com.github.siasia" %% "xsbt-web-plugin" % "0.11.2-0.2.11"
  case "0.11.3" => "com.github.siasia" %% "xsbt-web-plugin" % "0.11.3-0.2.11.1"
  case x if (x.startsWith("0.12")) => "com.github.siasia" %% "xsbt-web-plugin" % "0.12.0-0.2.11.1"
})

src/main/scala/SleepServlet.scala

package sample

import java.io.IOException

import javax.servlet.ServletException
import javax.servlet.annotation.WebServlet
import javax.servlet.http.{HttpServlet, HttpServletRequest, HttpServletResponse}

@WebServlet(name = "sleepServlet", urlPatterns = Array("/sleep"))
class SleepServlet extends HttpServlet {
  val sleepTime: Long = 10 * 1000L

  @throws(classOf[IOException])
  @throws(classOf[ServletException])
  override protected def doGet(request: HttpServletRequest,
                               response: HttpServletResponse): Unit = {
    printf("Sleeping... [%d]msec%n", sleepTime)
    Thread.sleep(sleepTime)

    val message =
      <html>
        <head>
          <title>Sleep Servlet</title>
        </head>
        <body>
          <p>{"Sleeping... [%d]msec".format(sleepTime)}</p>
        </body>
      </html>

    response.getWriter.write(message.toString)
  }
}

ムダに、Scala＋sbt＋Servlet 3.0。

まあ、10秒ほどスリープして、HTMLを返すサーブレットです。これでWARを作って、Tomcatにデプロイ。

では、Tomcatのserver.xmlにStuckThreadDetectionValveを追加してみます。

      <Host name="localhost"  appBase="webapps"
            unpackWARs="true" autoDeploy="true">

　〜省略〜

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

 〜省略〜

threshold属性は、時間がかかっている処理を検知する際のしきい値を”秒”で指定します。

詳細は、こちら。
http://tomcat.apache.org/tomcat-7.0-doc/config/valve.html#Stuck_Thread_Detection_Valve

この設定でTomcatを起動して問題のサーブレットにアクセスすると、catalina.outに以下のようなログが出力されます。

10 14, 2012 9:13:49 午後 org.apache.catalina.valves.StuckThreadDetectionValve notifyStuckThreadDetected
WARNING: Thread "http-bio-8080-exec-1" (id=16) has been active for 9,639 milliseconds (since 12/10/14 21:13) to serve the same request for http://localhost:8080/tomcat-stuck-thread/sleep 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 sample.SleepServlet.doGet(SleepServlet.scala:18)
	at javax.servlet.http.HttpServlet.service(HttpServlet.java:621)
	at javax.servlet.http.HttpServlet.service(HttpServlet.java:722)
	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:305)
	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:210)
	at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:222)
	at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:123)
	at org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:472)
	at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:168)
	at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:99)
	at org.apache.catalina.valves.StuckThreadDetectionValve.invoke(StuckThreadDetectionValve.java:193)
	at org.apache.catalina.valves.AccessLogValve.invoke(AccessLogValve.java:929)
	at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:118)
	at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:407)
	at org.apache.coyote.http11.AbstractHttp11Processor.process(AbstractHttp11Processor.java:1002)
	at org.apache.coyote.AbstractProtocol$AbstractConnectionHandler.process(AbstractProtocol.java:585)
	at org.apache.tomcat.util.net.JIoEndpoint$SocketProcessor.run(JIoEndpoint.java:310)
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1110)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:603)
	at java.lang.Thread.run(Thread.java:722)

10 14, 2012 9:13:59 午後 org.apache.catalina.valves.StuckThreadDetectionValve notifyStuckThreadCompleted
WARNING: Thread "http-bio-8080-exec-1" (id=16) was previously reported to be stuck but has completed. It was active for approximately 10,425 millisecond

ここを見ると、しきい値5秒に設定して、それに引っかかったことが書かれていますね。

WARNING: Thread "http-bio-8080-exec-1" (id=16) has been active for 9,639 milliseconds (since 12/10/14 21:13) to serve the same request for http://localhost:8080/tomcat-stuck-thread/sleep 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.

パフォーマンス系のトラブルシュート時は、けっこう便利かも？