同時アクセス数が増えるとコネクションが切断されてしまう。

Question

###同時アクセス数が増えるとコネクションが切断されてしまう。

Spring MVCで作成しているWEBシステムで、
同時アクセスができていることの確認はできているのですが、
同時アクセス数が増えると、コネクションが切断されてしまいます。

そこで、コネクションプールの設定を行う為に
データソースマッピング設定に以下の設定を記載しましたが、
設定が反映されませんでした。

        <bean id="dataSource" class="org.apache.tomcat.jdbc.pool.DataSource">
        <property name="driverClassName" value="org.postgresql.Driver"/>
        <property name="url" value="jdbc:postgresql://xxxxxxxxxxxxxx"/>
        <property name="username" value="xxxx" />
        <property name="password" value="xxxx" />
        <property name="validationQuery" value="SELECT 1" />
        <property name="testOnBorrow" value="true" />
        <property name="testWhileIdle" value="true" />
        <property name="timeBetweenEvictionRunsMillis" value="60000" />
        <property name="initialSize" value="100" />
        <property name="maxActive" value="100" />
        <property name="maxIdle" value="100" />
        <property name="minIdle" value="10" />

以下にpom.xmlを抜粋します

		<dependency>
			<groupId>org.springframework</groupId>
			<artifactId>spring-core</artifactId>
			<version>${spring.version}</version>
		</dependency>

		<dependency>
			<groupId>org.springframework</groupId>
			<artifactId>spring-web</artifactId>
			<version>${spring.version}</version>
		</dependency>

		<dependency>
			<groupId>org.springframework</groupId>
			<artifactId>spring-webmvc</artifactId>
			<version>${spring.version}</version>
		</dependency>
		<dependency>
		    <groupId>org.springframework</groupId>
		    <artifactId>spring-jdbc</artifactId>
		    <version>4.3.8.RELEASE</version>
		</dependency>
		<dependency>
		    <groupId>org.postgresql</groupId>
		    <artifactId>postgresql</artifactId>
		    <version>9.4-1200-jdbc41</version>
		</dependency>
		<dependency>
		    <groupId>org.springframework</groupId>
		    <artifactId>spring-jdbc</artifactId>
		    <version>4.3.8.RELEASE</version>
		</dependency>
		<dependency>
		    <groupId>org.apache.tomcat</groupId>
		    <artifactId>tomcat-jdbc</artifactId>
		    <version>8.5.23</version>
		</dependency>

###コネクション接続時に発生したエラーメッセージ

[ERROR] DBException!
000.0.0.0jp.co.xxx.exception.DBException: java.sql.SQLException: PooledConnection has already been closed.
jp.co.xxxx.exception.DBException: jp.co.xxxx.exception.DBException: java.sql.SQLException: PooledConnection has already been closed.

何かアドバイスをいただけるとうれしいです。
よろしくお願い致します。

###追記
ご質問ありがとうございます。
返答が遅くなり、申し訳ございません。

A)PostgreSQL側で、max_connectionsの設定は？
⇒"100"になっております。

B)PostgreSQL側で、全てのSQLをログ出力できるようにして、validationQuery" value="SELECT 1 " が発行されているかどうか
⇒確認しましたところ、validationQuery" value="SELECT 1 "の発行はされておりました。

C) OS側のtcp timeoutが短すぎることはないか？
⇒他アプリケーション動作時は、問題なく動作するため、
tcp timeoutの設定は問題ないと思っております。

また、今回の同時アクセス検証につきましては、
10秒間に100アクセスが可能かの検証を行っており
現状、100アクセス中の数件のコネクションが切断されてしまう状態です。

###追記(使用データソース変更(2017/11/16))
データソースを
org.apache.commons.dbcp.BasicDataSourceに変更したところ、
性能が多少改善致しましたので追記致します。
（以前、[dbcp2]を試した時は、性能の改善が見られなかったのですが…)

【以下、データソースマッピング設定】

	<bean id="dataSource" class="org.apache.commons.dbcp.BasicDataSource">
		<property name="driverClassName" value="org.postgresql.Driver"/>
		<property name="url" value="jdbc:postgresql://xxxxxxxxxxxxxx" />
		<property name="username" value="xxxxx"/>
		<property name="password" value="xxxxx"/>
		<property name="initialSize" value="300"/>
		<property name="testOnBorrow" value="true"/>
		<property name="maxActive" value="300"/>
		<property name="maxIdle" value="300" />
	</bean>

上記データソースに変更後、
10秒間に100アクセスは、問題なく動作するようになりました。
ご協力ありがとうございます。

しかし、
・負荷を上げると、以前と同エラーが発生してしまう。
(※5秒間に400アクセスの検証で稀にエラーが発生)

・10秒間に100アクセスの検証をループして実施すると、
エラーが発生してしまう。
(※10秒間に100アクセスを2分間ループさせると、
1％未満の確立でエラーが発生)

・不具合原因の特定ができていない。

という状況の為、引き続き調査を行っていきたいと思っております。

皆様お忙しいとは思いますが、
引き続きお力添えいただければ幸いです。

Comments

[kuniku]

A)PostgreSQL側で、max_connections の設定は？

B)PostgreSQL側で、全てのSQLをログ出力できるようにして、validationQuery" value="SELECT 1 " が発行されているかどうか

C) OS側のtcp timeoutが短すぎることはないか？

Answer 1

validationQueryの SELECT 1 が発行されていることから
Spring側でgetConnectionしたときに、そのDBとのコネクションは正常と判断されていますね

その正常の後に、コネクションが切断されている可能性があります。

Spring側（tomcat dbcp）の

 initialSize=100
 maxActive=100
 maxIdle=100

と
PostgreSQLでの

 max_connections =100（デフォルト値）

で、アプリ側とDB側の値が同値になっています。

ここからは推測も含みますが、

PostgreSQLのドキュメント（バージョン9.4想定）
https://www.postgresql.jp/document/9.4/html/runtime-config-connection.html

PostgreSQLのスーパユーザによる接続のために予約されている接続"開口部（スロット）"の数
superuser_reserved_connections =3（デフォルト）
何時の時点にあっても、有効な接続数は、少なくともmax_connectionsから
superuser_reserved_connectionsを差し引いた数であって

なので、PostgreSQLのmax_connections=100がPostgreSQLのスーパユーザの接続数を含むため、
100-3=97 が外側（アプリケーションなど）からの最大接続可能数になるのではないかと推測。

Spring側を97以下にするか、PostgreSQL側を103以上にする必要があるのでは？
また、運用でのSQL実行やDBの正常確認もあること考慮すると、10くらいは余裕をもっておく方が良いかと思います。

Comments

[h2-19]

ご回答ありがとうございます。

Spring側（tomcat dbcp）をinitialSize=300、maxActive=300、maxIdle=300、
PostgreSQLの設定を max_connections =300 に設定し、
同じく10秒間に100アクセスが可能かの検証を行いましたが、
設定変更前後で、大きな差が見られませんでした。

他に、修正方法があれば指摘してもらえると幸いです。

[kuniku]

Spring側（tomcat dbcp）をmaxActive=300ならば、PostgreSQLの設定を max_connections =300 + superuser_reserved_connections =303？ にする必要があるのでは？

[h2-19]

度々のご回答ありがとうございます。

早速、Spring側（tomcat dbcp）をmaxActive=300、
PostgreSQLの設定をmax_connections =310で検証致しましたが、
設定変更前後で、大きな差が見られませんでした。

[kuniku]

D)
pom で、 tomcat-jdbc 8.5.23 を利用していることから、

http://tomcat.apache.org/tomcat-8.5-doc/jdbc-pool.html#Common_Attributes

maxWait Default value is 30000 (30 seconds)

の値が有効そうな気がするのですが、30秒程度待機してる事象は発生していますか？
（30秒程度、待機していないとすると、コネクションの取得待ちは発生していない）

もしくは、
maxWait=60000
などの値にしてみる

E)
tomcat8.5として、commons-dbcp2（org.apache.commons.dbcp2.BasicDataSource）の方を使ってみる

http://terasolunaorg.github.io/guideline/5.3.1.RELEASE/ja/ArchitectureInDetail/DataAccessDetail/DataAccessCommon.html
の「6.1.2.1.2. Bean定義したDataSouceを使用する場合の設定」
と
http://commons.apache.org/proper/commons-dbcp/configuration.html
を参考に、maxActiveが maxTotal などに変わります。maxWaitがmaxWaitMillis 等

[kuniku]

追記

F) PostgreSQLに対して、Spring MVCで作成しているWEBシステム　 以外からのDB接続はありませんか？ 運用上の何らかのSQLが常に実行されている 等

G) WEBシステムからは、レプリケーションされる側（スレーブ側、ホットスタンバイ側）に対して、SQL実行していますか？（参照としてSQLを実行）

[h2-19]

D）maxWaitの値を操作し、検証を行いましたが、
　コネクションの取得待ちは発生していない状況でした。

E) 参考サイトまで、記載していただきありがとうございます。
こちらも、実施いたしましたが、性能に差が出ませんでした。

F）現在検証中のシステム以外からのDB接続はございません。

G）今回はDBに対してのレプリケーションは行っておらず、
　DB一台の構成となっております。

度々、お時間をいただきありがとうございます。

[kuniku]

何らか、どこかにバグがあるのか？　とも思えますね。

・元にもどってしまいますが、
Spring側（tomcat dbcp）をmaxActive=100 にして、PostgreSQLの設定を max_connections =300 で、かなりの余裕をもった設定で試行してみる

・PostgreSQLのログで何らか警告なり発生していないか確認してみる。

・PostgreSQL側で、DB接続のsessionをモニタリングしてみる。
https://www.postgresql.jp/document/9.4/html/monitoring-stats.html#PG-STAT-ACTIVITY-VIEW

select * from pg_stat_activity where datname = 'データベース名';
を1秒おきに実行してファイルに出力して、エラーの発生タイミングでのセッション数などを確認してみるとか

[h2-19]

pring側（tomcat dbcp）とPostgreSQLの設定の最大コネクション数に
余裕を持たせた状態で検証を実施いたしましたが、性能に差は出ませんでした。

また、検証時(SQL発行時)にPostgreSQL側の
ログの確認、sessionをモニタリングを行いましたが、
特に異常は見られませんでした。

[kuniku]

・例外　「java.sql.SQLException: PooledConnection has already been closed.」が発生するのは、同じ箇所（特定のSQLや特定のロジック処理）で発生するのでしょうか？

・負荷相当の試験をされている時間は、どれくらいの時間やり続けて、どれくらいの割合で例外が発生するのでしょうか？

・何らかのSQLが異様に長く、それがqueryTimeout を起こしたり、DB側とのネットワークが切断されて、そのコネクションがコネクションプールに回収され、validationQueryやtestWhileIdle で例外が発生するのかな？（ネットワーク上のFWで接続状態が一定時間を超えると切断されることはあるのですが、getconnectionされるときにvalidationQueryでコネクションの正常かを判定して接続し直し、そのときコネクションが無効でも例外は発生しないので、そこではないと思っています）

[h2-19]

データソース変更前(org.apache.tomcat.jdbc.pool.DataSource)の状況で、
答えさせていただきます。

・例外　「java.sql.SQLException: PooledConnection has already been closed.」が発生するのは、
　同じ箇所（特定のSQLや特定のロジック処理）で発生するのでしょうか？
　⇒同じ箇所で発生しているようです。

・負荷相当の試験をされている時間は、どれくらいの時間やり続けて、
　どれくらいの割合で例外が発生するのでしょうか？
　⇒10秒間に100アクセスで1％前後のエラーが発生しております。

・何らかのSQLが異様に長く、それがqueryTimeout を起こしたり、
　DB側とのネットワークが切断されて、そのコネクションがコネクションプールに回収され、
　validationQueryやtestWhileIdle で例外が発生するのかな？
　（ネットワーク上のFWで接続状態が一定時間を超えると切断されることはあるのですが、
　getconnectionされるときにvalidationQueryでコネクションの正常かを判定して接続し直し、
　そのときコネクションが無効でも例外は発生しないので、そこではないと思っています）
　⇒検証での実行SQLを精査しましたが、
　　実行SQLには問題がなさそうでした。

Answer 2

https://github.com/apache/tomcat を "PooledConnection has already been closed" で検索する限り、org.apache.tomcat.jdbc.pool.DisposableConnectionFacade の以下の個所しかありませんでした。

try {
            return super.invoke(proxy, method, args);
        } catch (NullPointerException e) {
            if (getNext() == null) {
                if (compare(TOSTRING_VAL, method)) {
                    return "DisposableConnectionFacade[null]";
                }
                throw new SQLException(
                        "PooledConnection has already been closed.");
            }

            throw e;
        } finally {
            if (compare(CLOSE_VAL, method)) {
                setNext(null);
            }
        }

で、super.invoke は、org.apache.tomcat.jdbc.pool.JdbcInterceptor のここ。

@Override
    public Object invoke(Object proxy, Method method, Object[] args) throws Throwable {
        if (getNext()!=null) return getNext().invoke(proxy,method,args);
        else throw new NullPointerException();
    }

Connectionにインターセプタをかまして、closeが呼ばれたらコネクションをクローズせずにプールに戻すといったことをしているのだと思います。で、getNext()では次のインターセプタを取得しているのだと思います。それがnullだったと。ここで、以下の個所に注目しました。

        } finally {
            if (compare(CLOSE_VAL, method)) {
                setNext(null);
            }
        }

closeがよばれたら、次のインターセプタにnullを設定しています。
つまり、close()が既に呼び出されているとこのようなことが起こるのでは？ということです。
実際のデータベース接続の数とかは関係ないように見えます。

同時接続でおかしくなるとのことなので、Connectionをクラス変数にいれていて、別スレッドでcloseしているとかそういったバグがあるのではないかと思います。

Comments

[kuniku]

なるほどです。
connectionをThreadlocal 等に保持して、ServletFilterの最後にclose するようなシステムや、httpリクエストからThread生成などして、別処理を同時に実行（例えばログ出力）などあるかもしれないですね。

[退会済みユーザー]

さすがにトリッキーなことはしないと思っているんですが、Connectionをメンバー変数に持っているクラスが、

1. 保持しているConnectionがnullだったら、getConnection()して保持
2. 保持しているConnectionを使う
3. Connectionをクローズして、保持内容をnullに初期化

などをやっていて、インスタンスがシングルトンだった、とかなら起こりえると思います。
ただ、それならNullPointerExceptionとかも出てもいいと思うんですけどね。

[h2-19]

ご回答ありがとうございます。

データベース接続の設定がおかしいとばかり
考えておりましたが…
一度調査してみます。ありがとうございます。