Q&A
HikariConnectionPoolの設定ならびにデータベース側の製品、バージョン、接続タイムアウトに関する設定など、わかる範囲で追記していただくと回答が得られるかもしれません。
Spring BootでWEBアプリケーションを作成しています。
DBとのコネクションプールにHikariCPを用いているのですが、
日中正常に動いていても翌朝使用しようとするとDBに繋がらず、
jconsoleからHikariCPの状態を見るとtotal connectionsが0になっていることがあります。
夜間でDBサーバが再起動しているのですが、これが関係あるのでしょうか？
毎日この現象が起こるわけではなく、たまに起こる状況です。
本番環境でDEBUGログが出せないため、現在テスト環境でHikariのDEBUGログを
出してみようとしています。
ありがとうございます。
データベースはOracle 12c、接続時にはodbc8でthinドライバにて接続しています。
HikariCPの設定は以下の通りです。
spring.datasource.hikari.auto-commit=true
spring.datasource.hikari.connection-timeout=600000
spring.datasource.hikari.max-lifetime=1800000
spring.datasource.hikari.maximum-pool-size=50
spring.datasource.hikari.minimum-idle=50
spring.datasource.hikari.leak-detection-threshold=600000
spring.datasource.hikari.pool-name=XXXX
spring.datasource.hikari.register-Mbeans=true
※hikari-pool-nameはマスキングしています。
本日、また本番環境で枯渇する現象が発生していたため、
テスト環境を使用してみましたところ、テスト環境は問題なくTotal connectionが50になっていました。
本番もテスト環境も同じDBへ接続しています。
本日本番環境でhikariのDEBUGログを出力してみたところ、通常
2020-10-06 06:27:50.103 DEBUG 1368 --- [ESmateCP connection closer] com.zaxxer.hikari.pool.PoolBase : ESmateCP - Closing connection oracle.jdbc.driver.T4CConnection@64acee38: (connection has passed maxLifetime)
2020-10-06 06:27:50.181 DEBUG 1368 --- [ESmateCP connection adder] com.zaxxer.hikari.pool.HikariPool : ESmateCP - Added connection oracle.jdbc.driver.T4CConnection@51e94131
2020-10-06 06:27:50.181 DEBUG 1368 --- [ESmateCP connection adder] com.zaxxer.hikari.pool.HikariPool : ESmateCP - After adding stats (total=49, active=0, idle=49, waiting=0)
のように、maxlifetimeに達したコネクションがCloseされた後にAddで新しいコネクションを作り直しているのですが、ある時を境に
2020-10-06 06:28:07.823 DEBUG 1368 --- [ESmateCP connection closer] com.zaxxer.hikari.pool.PoolBase : ESmateCP - Closing connection oracle.jdbc.driver.T4CConnection@3512f12a: (connection has passed maxLifetime)
2020-10-06 06:28:09.042 DEBUG 1368 --- [ESmateCP connection closer] com.zaxxer.hikari.pool.PoolBase : ESmateCP - Closing connection oracle.jdbc.driver.T4CConnection@4614d76: (connection has passed maxLifetime)
2020-10-06 06:28:17.683 DEBUG 1368 --- [ESmateCP connection closer] com.zaxxer.hikari.pool.PoolBase : ESmateCP - Closing connection oracle.jdbc.driver.T4CConnection@60e8ac92: (connection has passed maxLifetime)
2020-10-06 06:28:23.433 DEBUG 1368 --- [ESmateCP housekeeper] com.zaxxer.hikari.pool.HikariPool : ESmateCP - Pool stats (total=37, active=0, idle=37, waiting=0)
と、Closeのログしか出ておらず、そこからどんどんtotal connectionsが減少していくようです。
その少し後に以下のようなStackTraceが出ていましたが、通常稼働時もたまに出ているのであまり関係ないのかなと思っています。
java.sql.SQLRecoverableException: IOエラー: Socket read timed out
at oracle.jdbc.driver.T4CConnection.logoff(T4CConnection.java:1002) ~[ojdbc8-19.3.0.0.jar!/:19.3.0.0.0]
at oracle.jdbc.driver.PhysicalConnection.close(PhysicalConnection.java:2268) ~[ojdbc8-19.3.0.0.jar!/:19.3.0.0.0]
at com.zaxxer.hikari.pool.PoolBase.quietlyCloseConnection(PoolBase.java:139) ~[HikariCP-3.4.2.jar!/:na]
at com.zaxxer.hikari.pool.HikariPool.lambda$closeConnection$1(HikariPool.java:447) [HikariCP-3.4.2.jar!/:na]
at java.util.concurrent.ThreadPoolExecutor.runWorker(Unknown Source) ~[na:1.8.0_261]
at java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source) ~[na:1.8.0_261]
at java.lang.Thread.run(Unknown Source) ~[na:1.8.0_261]
Caused by: oracle.net.nt.TimeoutInterruptHandler$IOReadTimeoutException: Socket read timed out
at oracle.net.nt.TimeoutSocketChannel.handleInterrupt(TimeoutSocketChannel.java:254) ~[ojdbc8-19.3.0.0.jar!/:19.3.0.0.0]
at oracle.net.nt.TimeoutSocketChannel.read(TimeoutSocketChannel.java:180) ~[ojdbc8-19.3.0.0.jar!/:19.3.0.0.0]
at oracle.net.ns.NSProtocolNIO.doSocketRead(NSProtocolNIO.java:555) ~[ojdbc8-19.3.0.0.jar!/:19.3.0.0.0]
at oracle.net.ns.NIOPacket.readHeader(NIOPacket.java:258) ~[ojdbc8-19.3.0.0.jar!/:19.3.0.0.0]
at oracle.net.ns.NIOPacket.readPacketFromSocketChannel(NIOPacket.java:190) ~[ojdbc8-19.3.0.0.jar!/:19.3.0.0.0]
at oracle.net.ns.NIOPacket.readFromSocketChannel(NIOPacket.java:132) ~[ojdbc8-19.3.0.0.jar!/:19.3.0.0.0]
at oracle.net.ns.NIOPacket.readFromSocketChannel(NIOPacket.java:105) ~[ojdbc8-19.3.0.0.jar!/:19.3.0.0.0]
at oracle.net.ns.NIONSDataChannel.readDataFromSocketChannel(NIONSDataChannel.java:91) ~[ojdbc8-19.3.0.0.jar!/:19.3.0.0.0]
at oracle.jdbc.driver.T4CMAREngineNIO.prepareForUnmarshall(T4CMAREngineNIO.java:764) ~[ojdbc8-19.3.0.0.jar!/:19.3.0.0.0]
at oracle.jdbc.driver.T4CMAREngineNIO.unmarshalUB1(T4CMAREngineNIO.java:429) ~[ojdbc8-19.3.0.0.jar!/:19.3.0.0.0]
at oracle.jdbc.driver.T4CTTIfun.receive(T4CTTIfun.java:407) ~[ojdbc8-19.3.0.0.jar!/:19.3.0.0.0]
at oracle.jdbc.driver.T4CTTIfun.doRPC(T4CTTIfun.java:268) ~[ojdbc8-19.3.0.0.jar!/:19.3.0.0.0]
at oracle.jdbc.driver.T4C7Ocommoncall.doOLOGOFF(T4C7Ocommoncall.java:64) ~[ojdbc8-19.3.0.0.jar!/:19.3.0.0.0]
at oracle.jdbc.driver.T4CConnection.logoff(T4CConnection.java:991) ~[ojdbc8-19.3.0.0.jar!/:19.3.0.0.0]
... 6 common frames omitted
アプリケーションのHikariデバッグログとOracle側のlistener.logを見てみました。
上記のログとは時間が違いますが、ちょうど現象が起こった箇所を見ると
【アプリケーションのログ】
2020-10-07 20:43:05.790 DEBUG 7520 --- [ESmateCP connection closer] com.zaxxer.hikari.pool.PoolBase : ESmateCP - Closing connection oracle.jdbc.driver.T4CConnection@7ee123e6: (connection has passed maxLifetime)
2020-10-07 20:43:06.274 DEBUG 7520 --- [ESmateCP connection adder] com.zaxxer.hikari.pool.HikariPool : ESmateCP - Added connection oracle.jdbc.driver.T4CConnection@3f614ae9
2020-10-07 20:43:14.274 DEBUG 7520 --- [ESmateCP connection closer] com.zaxxer.hikari.pool.PoolBase : ESmateCP - Closing connection oracle.jdbc.driver.T4CConnection@128bb839: (connection has passed maxLifetime)
2020-10-07 20:43:14.884 DEBUG 7520 --- [ESmateCP connection adder] com.zaxxer.hikari.pool.HikariPool : ESmateCP - Added connection oracle.jdbc.driver.T4CConnection@73a0b3ff
2020-10-07 20:43:23.946 DEBUG 7520 --- [ESmateCP connection closer] com.zaxxer.hikari.pool.PoolBase : ESmateCP - Closing connection oracle.jdbc.driver.T4CConnection@6ac66acb: (connection has passed maxLifetime)
2020-10-07 20:43:29.587 DEBUG 7520 --- [ESmateCP connection closer] com.zaxxer.hikari.pool.PoolBase : ESmateCP - Closing connection oracle.jdbc.driver.T4CConnection@2c334d57: (connection has passed maxLifetime)
2020-10-07 20:43:30.368 DEBUG 7520 --- [ESmateCP connection closer] com.zaxxer.hikari.pool.PoolBase : ESmateCP - Closing connection oracle.jdbc.driver.T4CConnection@5451c5ab: (connection has passed maxLifetime)
2020-10-07 20:43:31.306 DEBUG 7520 --- [ESmateCP housekeeper] com.zaxxer.hikari.pool.HikariPool : ESmateCP - Pool stats (total=47, active=9, idle=38, waiting=0)
2020-10-07 20:43:31.431 DEBUG 7520 --- [ESmateCP connection closer] com.zaxxer.hikari.pool.PoolBase : ESmateCP - Closing connection oracle.jdbc.driver.T4CConnection@2a060656: (connection has passed maxLifetime)
2020-10-07 20:43:33.353 DEBUG 7520 --- [ESmateCP connection closer] com.zaxxer.hikari.pool.PoolBase : ESmateCP - Closing connection oracle.jdbc.driver.T4CConnection@3f7e32f6: (connection has passed maxLifetime)
2020-10-07 20:43:35.306 DEBUG 7520 --- [ESmateCP connection closer] com.zaxxer.hikari.pool.PoolBase : ESmateCP - Closing connection oracle.jdbc.driver.T4CConnection@2e80321b: (connection has passed maxLifetime)
2020-10-07 20:43:42.727 DEBUG 7520 --- [ESmateCP connection closer] com.zaxxer.hikari.pool.PoolBase : ESmateCP - Closing connection oracle.jdbc.driver.T4CConnection@7b5d4f: (connection has passed maxLifetime)
2020-10-07 20:43:46.946 DEBUG 7520 --- [ESmateCP connection closer] com.zaxxer.hikari.pool.PoolBase : ESmateCP - Closing connection oracle.jdbc.driver.T4CConnection@5267b8f4: (connection has passed maxLifetime)
2020-10-07 20:43:50.526 DEBUG 7520 --- [ESmateCP connection closer] com.zaxxer.hikari.pool.PoolBase : ESmateCP - Closing connection oracle.jdbc.driver.T4CConnection@6a581e9e: (connection has passed maxLifetime)
2020-10-07 20:44:01.307 DEBUG 7520 --- [ESmateCP housekeeper] com.zaxxer.hikari.pool.HikariPool : ESmateCP - Pool stats (total=41, active=9, idle=32, waiting=0)
【listener.log】
07-10月-2020 20:43:06 * (CONNECT_DATA=(SID=BO)(CID=(PROGRAM=JDBC Thin Client)(HOST=__jdbc__)(USER=opc))) * (ADDRESS=(PROTOCOL=tcp)(HOST=10.40.1.101)(PORT=58828)) * establish * BO * 0
07-10月-2020 20:43:14 * (CONNECT_DATA=(SID=BO)(CID=(PROGRAM=JDBC Thin Client)(HOST=__jdbc__)(USER=opc))) * (ADDRESS=(PROTOCOL=tcp)(HOST=10.40.1.101)(PORT=58830)) * establish * BO * 0
07-10月-2020 20:43:24 * (CONNECT_DATA=(SID=BO)(CID=(PROGRAM=JDBC Thin Client)(HOST=__jdbc__)(USER=opc))) * (ADDRESS=(PROTOCOL=tcp)(HOST=10.40.1.101)(PORT=58832)) * establish * BO * 0
07-10月-2020 20:43:25 * service_update * bo * 0
07-10月-2020 20:43:28 * service_update * bo * 0
07-10月-2020 20:43:31 * service_update * bo * 0
07-10月-2020 20:43:34 * service_update * bo * 0
07-10月-2020 20:43:37 * service_update * bo * 0
というように、20:43:06、20:43:14のコネクションは双方記録されておりますが、20:43:24はOracle側は接続を正常として返していますが、アプリケーション側でコネクションを受け取っていません。
ここから一切コネクションの再作成を行わなくなりプールが枯渇しているようです。
詳細にありがとうございます。見当違いかもしれませんが、Oracle側の接続タイムアウト値とHikariCPのmax-lifetimeのミスマッチで発生する可能性はあります。
ありがとうございます。
とりあえず、
spring.datasource.hikari.max-lifetime=3600000
spring.datasource.hikari.maximum-pool-size=50
spring.datasource.hikari.minimum-idle=20
と変更し、hikari cleanupが動くようにしたところ、
今のところTotal connectionが枯渇することはなくなりました。
しばらくこれで運用してみます。
@s806099dさま
今のところ大丈夫そうですね、承知しました。ご連絡ありがとうございました。
しばらくは稼働してそうだったのですが、本日また枯渇が発生しておりました。
ログを確認すると、
(IOエラー: Invalid Operation, NOT Connected). Possibly consider using a shorter maxLifetime value.
というログが接続数分（20行）出力されておりました。
何かわかる方はいらっしゃいますでしょうか。
あなたの回答
tips
プレビュー
