Tomcat がハングした

こんにちは。サイオステクノロジー OSS サポート担当何敏欽です。

Apache と Tomcat を連携し、Tomcat から JDBC を使用してデータベース MySQL にアクセスするシステムがあります。Apache サーバを 1台、Tomcat と MySQL は同一サーバを 1台の合計 2台構成で、突然ハング (無応答状態) してしまい、アクセス不可になってしまいました。原因は追究していきたいと思います。

[事象確認]→コネクションのクローズ漏れ

では、設定やログを確認していきます。

■tomcat 側

context.xml の設定は下記の通りです。「removeAbandoned」が true (有効) になっていることに注目して欲しいです。removeAbandoned はデータベースコネクションのクローズ漏れ等でコネクションプールに返していないコネクションを破棄する機能です。その他のパラメータの意味は 各種パラメータの意味などについて で説明します。

<Resource name="jdbc/app" auth="Container"
        type="javax.sql.DataSource"
        driverClassName="com.mysql.jdbc.Driver"
        url="jdbc:mysql://localhost:3306/hoge?useSSL=false"
        username="root"
        password="password"
        maxActive="20" maxIdle="20" initialSize="0" maxWait="-1"
        removeAbandoned="true"
        removeAbandonedTimeout="30"
        logAbandoned="true" /&gt

catalina.out に com.sios.yorozu.app.GetConnection クラスの service() メソッドで取得したデータベースコネクションがクローズされていないことが記録されました。このログを見れば、本事象の発生原因は大体見当がつきますね。

DBCP object created 2018-06-28 13:31:05 by the following code was never closed:
java.lang.Exception
at org.apache.commons.dbcp.AbandonedTrace.setStackTrace(AbandonedTrace.java:157)
at org.apache.commons.dbcp.AbandonedObjectPool.borrowObject(AbandonedObjectPool.java:76)
at org.apache.commons.dbcp.PoolingDataSource.getConnection(PoolingDataSource.java:97)
at org.apache.commons.dbcp.BasicDataSource.getConnection(BasicDataSource.java:543)
at com.sios.yorozu.app.GetConnection.service(GetConnection.java:49)
at javax.servlet.https.HttpServlet.service(HttpServlet.java:723)
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:290)

■Apache側

access_log にステータスコード「503」が出力されました。

10.1.A.AAA - - [28/Jun/2018:13:31:18 +0900] "GET /app/getConnection HTTP/1.1" 503 400 "https://10.1.B.BBB/app/getConnection" "Mozilla/5.0 (X11; U; Linux x86_64; ja; rv:1.9.2.24) Gecko/20111104 Red Hat/3.6.24-3.el6_1 Firefox/3.6.24"
10.1.A.AAA - - [28/Jun/2018:13:39:07 +0900] "GET /app/getConnection HTTP/1.1" 503 400 "https://10.1.B.BBB/app/getConnection" "Mozilla/5.0 (X11; U; Linux x86_64; ja; rv:1.9.2.24) Gecko/20111104 Red Hat/3.6.24-3.el6_1 Firefox/3.6.24"

error_log に以下のメッセージが出力されました。

[Thu Jun 28 13:32:18 2018] [error] (70007)The timeout specified has expired: ajp_ilink_receive() can't receive header
[Thu Jun 28 13:32:18 2018] [error] ajp_read_header: ajp_ilink_receive failed
[Thu Jun 28 13:32:18 2018] [error] (70007)The timeout specified has expired: proxy: read response failed from 10.1.A.AAA:8009 (10.1.A.AAA)

もうわかっていると思いますが、無応答状態になった原因はアプリケーション内でデータベースコネクションのクローズ漏れがあるためです。

データベースコネクションをクローズしていないとコネクションプールに戻らないため、maxActive 値である 20 コネクションを越えてデータベースコネクションを取得しようとすると、コネクションプールがコネクションの要求に応えきれず、「maxWait=”-1″」(待ち続ける) の設定どおり待つ、応答なしの状態になります。

一方、Apache 側では Tomcat からの応答がなく、タイムアウトしたと判定してエラーログに記録し、クライアントには 503 エラーを返しました。

ですので、対策はログに記録されているデータベースコネクションのクローズ漏れ箇所を確認・修正になりますね。

maxWait パラメータの動作確認

問題は解決しましたが、もう一つ疑問が残ります。maxWait を -1 と設定した際、ブラウザは応答がなく、「Service Temporarily Unavailable」が表示されましたが、もし maxWait を 30 に設定したら、待機中のコネクションがタイムアウトして、そのタイムアウトしたコネクションの情報等はログに出力されるかを確認してみたいと思います。

「maxWait=”-1″」を「maxWait=”30″」に変更し、tomcat を再起動させます。maxActive の設定値を越えてコネクションプールのコネクションが不足した状況を作り出して確認しましたところ、ブラウザで下記の例外レポートが表示されましたが、残念ながら、タイムアウトしたコネクションの情報等は出力されていません。

javax.servlet.ServletException: org.apache.commons.dbcp.SQLNestedException: Cannot get a connection, pool exhausted
com.sios.yorozu.app.GetConnection.service(GetConnection.java:53)
javax.servlet.https.HttpServlet.service(HttpServlet.java:723)

原因

org.apache.commons.dbcp.SQLNestedException: Cannot get a connection, pool exhausted
org.apache.commons.dbcp.PoolingDataSource.getConnection(PoolingDataSource.java:105)
org.apache.commons.dbcp.BasicDataSource.getConnection(BasicDataSource.java:543)
com.sios.yorozu.app.GetConnection.service(GetConnection.java:49)
javax.servlet.https.HttpServlet.service(HttpServlet.java:723)

原因

java.util.NoSuchElementException: Timeout waiting for idle object
org.apache.commons.pool.impl.GenericObjectPool.borrowObject(GenericObjectPool.java:825)
org.apache.commons.dbcp.AbandonedObjectPool.borrowObject(AbandonedObjectPool.java:74)
org.apache.commons.dbcp.PoolingDataSource.getConnection(PoolingDataSource.java:97)
org.apache.commons.dbcp.BasicDataSource.getConnection(BasicDataSource.java:543)
com.sios.yorozu.app.GetConnection.service(GetConnection.java:49)
javax.servlet.https.HttpServlet.service(HttpServlet.java:723)

注意 原因のすべてのスタックトレースは、Apache Tomcat/6.0.24のログに記録されています

各種パラメータの意味などについて

■コネクションプールの性能に影響を与えるパラメータについて説明していきます。

• • maxActive:同時にプールから割り当てることのできるアクティブなコネクションの最大数

最小値は 0 で、データベース最大接続数として有効な最小値になります。-1 を設定した場合は無制限であることを意味します。

• • minIdle:プールに保持する最小のコネクション数

最小値は 0 で、負の値が設定されている場合 IllegalArgumentException が返され、エラーとなります。

• • maxIdle:プールに保持しておく最大のコネクション数

最小値は 0 で、アイドル状態のデータベース最大接続数として有効な最小値になります。-1 を設定した場合は無制限であることを意味します。

• • initialSize:プールの起動時に作成されるコネクションの初期サイズ

最小値は 1 で、負の値が設定されている場合、SQLException が返され、エラーとなります。

• • maxWait:利用可能なコネクションが存在しないときに待機する最大時間

-1 を設定した場合は無制限であることを意味します。

■コネクションの追跡機能・クローズ漏れ検知のパラメータについて説明していきます。

• • removeAbandoned:クローズ漏れコネクションの検知を行う場合は true に設定

デフォルト値は false

• • removeAbandonedTimeout:クローズ漏れとみなすまでの時間 (秒)

デフォルト値は 300

• • logAbandoned:クローズ漏れを検知した際に、コネクションをクローズしていないアプリのスタックトレースをログに出力する場合に設定。ただし、コネクションの取得時にスタックトレースを生成する必要があるため、本機能利用時はオーバーヘッドが追加される

デフォルト値は false

では、冒頭で言及した下記 context.xml の設定の意味を見ていきます。

<Resource name="jdbc/app" auth="Container"
        type="javax.sql.DataSource"
        driverClassName="com.mysql.jdbc.Driver"
        url="jdbc:mysql://localhost:3306/hoge?useSSL=false"
        username="root"
        password="password"
        maxActive="20" maxIdle="20" initialSize="0" maxWait="-1"
        removeAbandoned="true"
        removeAbandonedTimeout="30"
        logAbandoned="true" /&gt

こちらの設定では、同時接続で 20 以上を受けた場合、21 番目以降のコネクションは maxWait の設定 “-1” によりデータベースコネクションを取得するまで待ち続けます。また、minIdle が設定されておらず initialSize に 0 が設定されているため、minIdle の値は initialSize と同値となり 0 が適用されます。そのため、アイドル状態のコネクションの上限数としては maxIdle の値の通り 20 ですが、下限値は 0 が適用されます。なお、30 秒以上応答がないアイドル状態のコネクションを破棄する動きをします。

以上でコネクションのクローズ漏れ事象の確認と各種パラメータの意味について説明しました。