起こったこと
Spring BootでJPAを使ったデータベースアクセスを行っているアプリケーションで、 データベースアクセス後（特定の条件時のみデータベースアクセスが行われていた…）に遅いAPI呼び出しを行った結果コネクションプール不足となった。
原因にたどり着くまでめっちゃデバッグしたりログ仕込んだりして大変だったので(3時間ぐらいかかった)、ちっちゃいアプリ作って検証や対応方法などを考えてみる。
検証用アプリ
コントローラ
ざっくりとアプリケーションの内容は下のような感じ。 JPAでデータベースアクセスを行ったあとに遅い処理を行っている。検証用なのでAPI呼び出しの代わりにスリープ処理を入れてます。
@RestController @RequestMapping("/sample") class SampleController(private val sampleRepository: SampleRepository) { @GetMapping fun sample() { // DBアクセス sampleRepository.findAll() // 遅いAPIの代わりにスリープ TimeUnit.SECONDS.sleep(5) } }
設定ファイル
再現しやすくするために、プール数とタイムアウト時間を調整しています。
spring.datasource.hikari.maximum-pool-size=2 spring.datasource.hikari.connection-timeout=1000
再現結果
同時に複数リクエストを投げると以下のようなエラーが発生します。タイムアウト時間まで待ってみたけど、使えるコネクション見つからなかったよってやつですね。
java.sql.SQLTransientConnectionException: HikariPool-1 - Connection is not available, request timed out after 1000ms.
原因
spring.jpa.open-in-viewという設定がデフォルトでtrueになっていて、Viewの構築時(Restの場合のjsonの構築時)まで、データベース接続が維持されていたため。
この設定値、デフォルトがtrueになっていて、明示的に指定しないと起動時にワーニングログが出力されていたけど気づかなかった…
データベースアクセス終わったタイミングでコネクション開放されると思ってたから、なかなかここにたどり着けなかった…（まだまだ知らないことがおおいなー）
試しに、コントローラの最後でアクティブなコネクション数を出してみると、スリープ後もコネクションがプールに戻っていないことが確認できる。
@RestController @RequestMapping("/sample") class SampleController(private val sampleRepository: SampleRepository, private val dataSource: HikariDataSource) { @GetMapping fun sample() { val hikariPoolMXBean = dataSource.hikariPoolMXBean println("start: ${hikariPoolMXBean.activeConnections}") // DBアクセス sampleRepository.findAll() // 遅いAPIの代わりにスリープ TimeUnit.SECONDS.sleep(5) println("end: ${hikariPoolMXBean.activeConnections}") } }
実行ログを確認すると、こんな感じにコントローラ終了時には返却されていないコネクションが残っていることがわかる。
対応
spring.jpa.open-in-viewを無効化してみる
application.propertiesを下のように変更し、open-in-viewを無効化して、コネクションが開放されるかを確認してみる。
spring.jpa.open-in-view=false
実行ログを確認すると、先程の結果とは異なりデータベース接続がコントローラ終了時まで維持されなくなったことがわかる。
これで、コネクション不足の問題は解決できるが、すでに動いているアプリケーションのこの設定値を変更した場合、間違いなくlazyなプロパティにviewが依存しているため動かなくなっちゃいますね…
該当リクエストのデータベースアクセスでJPAを使うのを諦める
例えば、下のような感じにJdbcTemplateを使うようにすることで、他の処理には影響を与えずコネクションプール不足問題を解決できるようになる。
@RestController @RequestMapping("/sample") class SampleController(private val jdbcTemplate: JdbcTemplate, private val dataSource: HikariDataSource) { @GetMapping fun sample() { val hikariPoolMXBean = dataSource.hikariPoolMXBean println("start: ${hikariPoolMXBean.activeConnections}") // DBアクセス val list = jdbcTemplate.queryForList("select * from sample") println("list = ${list}") // 遅いAPIの代わりにスリープ TimeUnit.SECONDS.sleep(5) println("end: ${hikariPoolMXBean.activeConnections}") } }
