要約
技術的な話だけ教えて、という方のために先に結論だけ書いておきますと、PostgreSQL はクエリを実行した時点で全レコードの情報を一気に読んできてヒープを埋めてしまう場合がある、ということ話です。
たとえば、ResultSet#nextメソッドを使いながら処理を回すようなコードを書いて、少ないヒープでも処理できるようにするのは常套手段だと思いますが、そういうコードを書いていても一気にヒープを消費してしまうことがあるのです。詳しくはこのドキュメントを見てください。
https://jdbc.postgresql.org/documentation/head/query.html#query-with-cursor
ことの発端
ちょっと仕事でJava + jOOQ + PostgreSQL で、DBのデータを集計するようなバッチ処理 を書いてまして、もちろん俺様の書いたコードにバグなんてあるはずがないわけですが、念のために性能試験をしておこうと思い、100万レコードのサンプルデータを投入してバッチのテストを走らせたら、OutOfMemoryErrorが起きたんですよ。
OutOfMemoryError。まさか、俺が?
戸田奈津子 の字幕っぽいセリフが頭をよぎりつつ、何度か試してみてもやはりOutOfMemoryErrorが起きてしまいます。ヒープを2GBとかにすれば実行できますし、レコード数を50万とかに減らせば問題なく動くのですが、そもそも何万レコード扱おうがヒープを大量確保するようなコードなんて書いていないつもりだったので、真面目に問題を確認することにしました。
何がヒープを埋めているって言うんだい?
僕も素人ではないですから、即座に起動引数に -XX:+HeapDumpOnOutOfMemoryError
をつけてテストを再実行し、ヒープダンプを取得しました。えーっと、取得したヒープダンプって何で読むのが良いんでしたっけ(←素人)
Java Mission Controlで読めたはず、と思ってググったら、今は名前が変わってJDK Mission Controlになっていたのですが(←素人)細かいことは気にせず、ダウンロードして実行して、File - Open Fileからヒープダンプのhprofファイルを読み込みました。
↓こんな感じでヒープを占めるオブジェクトの傾向が分かります。
JMCでヒープダンプを開くとこういう情報が分かる
一番上にある byte[][]
がヒープの7割も占めていて明らかに怪しいので、ダブルクリックして詳細を見ます。
↓こんな感じでどこから参照されているかが分かります。
オブジェクトの親子関係も追跡できる
どうやら org.postgresql.core.Tuple.data
から参照されているが分かり、このパッケージ名からやはりDBから読み込んだ100万レコードがヒープを埋めているであろうことがほぼ確定しました。
問題はどこで起きてるんだ!
今度はアプリケーションの方から問題を追跡します。デバッガで少し追ってみると、問題が起きている箇所がすぐに分かりました。
try (Stream<EMP> stream = dslContext.selectFrom(EMP).stream()) {
stream.forEach(e -> {
})
}
dslContextというのはjOOQのDslContextクラスのインスタンス です。この処理で select * from EMP
が実行されて、その結果をStreamとして取得しているわけです。
ただここで // 集計処理
と書いた部分には入っておらず、forEachを呼び出した時点でOutOfMemoryErrorが発生していることが分かりました。
なんてこった、jOOQのstreamメソッドは逐次処理をするんじゃなくて全件まとめて取ってくるヤツなのかい? どんな幼稚な処理を書いたらそうなるんだい? jOOQだからってジョークじゃ済まないよ? と怒りに震えながら、ツイートをしました。
後にこれは完全にとばっちりだったことが分かったのですが、シンガプーラ 使いさん(シンガプーラ って何ですか?)と、jOOQの公式アカウント様からもリプライいただいてしまい、大変恐縮しております。申し訳ありませんでした。
fetchSize()が効かない、だと!?
公式アカウント様が「streamメソッドはLazyローディングだよ。場合によっては fetchSize
メソッドを使うと良いよ」とおっしゃるので、まずそれを試してみました。
try (Stream<EMP> stream = dslContext.selectFrom(EMP).fetchSize(1000 ).stream()) {
stream.forEach(e -> {
})
}
しかし状況は変わりません。fetchSizeを1にしてもOOMEが発生してしまいました。
次にシンガプーラ 使いさんから教えてもらった fetchLazy
メソッドも試してみました。
var cursor = dslContext.selectFrom(BUDGET_REQUEST).fetchSize(1 ).fetchLazy();
while (cursor.hasNext()) {
}
それでも状況は変わりません。
この辺りで、問題はjOOQではなくJDBC ドライバ周りなのではないかと考え始め、jOOQを外して検証することにしました。
生JDBC で問題が再現しちまった!
僕もO/Rマッパーを自作するタイプの人間ですから、生JDBC で処理を書くのもお手の物です。こんなシンプルなコードを書いてみました。
try (Connection conn = dataSource.getConnection();
PreparedStatement stmt = conn.prepareStatement("select * from EMP" );
ResultSet resultSet = stmt.executeQuery()) {
while (resultSet.next()) {
}
}
うんとこしょ、どっこいしょ、それでもOOMEは消えません。これでjOOQは関係なく、PostgreSQL とJDBC ドライバ周りの問題だろうと絞り込めました。
ドキュメント、あったよ!
先に書いたシンプルなコードですらOOMEが発生してしまう状況になってくると、私が何か勘違いしているのかも知れないな、なんて一人称まで謙虚になってきます。何かPostgreSQL では特別なお作法があるのだろうかと思い、「postgresql jdbc lazy loading」でググってみたところ、みんな大好きStack Overflowにたどり着きました。
https://stackoverflow.com/questions/984073/java-jdbc-lazy-loaded-resultset
Another example: here's the documentation for the PostgreSQL behavior. If auto-commit is turned on, then the ResultSet will fetch all the rows at once, but if it's off, then you can use setFetchSize() as expected.
!?!?
ResultSet will fetch all the rows at once
まさに今回起きている現象そのものです。リンクされていたドキュメントを読んでみると、明確に書かれていました。
https://jdbc.postgresql.org/documentation/head/query.html#query-with-cursor
By default the driver collects all the results for the query at once.
はぁ〜!? なんでそんな実装にしとんねん!!!
問題の原因が分かった喜びよりも、この理不尽な実装に対する怒りの方が大きかったです(←理不尽な怒り)
これで解決だな
ドキュメントから、関係ありそうな部分を抜粋しますと。
Cursor based ResultSets cannot be used in all situations. There a number of restrictions which will make the driver silently fall back to fetching the whole ResultSet at once.
The Connection must not be in autocommit mode. The backend closes cursors at the end of transactions, so in autocommit mode the backend will have closed the cursor before anything can be fetched from it.
どうやらautoCommitがtrueになっている場合は、カーソルが使えないようです。そんなわけで Connection#setAutoCommit(false)
したところ、、、jOOQの fetchSize()
メソッドが効くようになって、OOMEが発生しなくなりました!
そもそもなぜautoCommitがtrueになっていたかと言うと、
バッチ本体では setAutoCommit(false) してから処理していたが、テストではロジックの中心部分だけ直接呼び出していた
テストでは面倒だったのでautoCommitをデフォルト値(true)のままにしていた
という、非常に運の悪い状況になっていました。
いやだって、autoCommitのtrue/falseでそんなに挙動が変わるなんて想像もしてなかったんだもん・・・。
さらに、Spring Boot + jOOQ + PostgreSQL で書いていたWebアプリケーションにおいてもautoCommitがtrueのままになっていました。トランザクション が効いている限りはautoCommitがtrueのままになることはあり得ないのですが、実はSpring Boot + jOOQの組み合わせでは、たとえ spring-boot-starter-jooq
を使っていても、そのままでは @Transactional アノテーション が効かない状態になっているのでした。
https://www.baeldung.com/spring-boot-support-for-jooq
いやまさか、Spring Bootとの連携が公式に謳われているようなライブラリで、@Transcational が効かないだなんて想像もしてなかったんだもん・・・。
まとめるぞ!
そんなわけで、今回のまとめです。
PostgreSQL はfetchSizeを指定しないと、ResultSetに検索結果が全て入る
PostgreSQL はautoCommitがtrueだと、fetchSizeを指定しても効果がない
そもそもサボってautoCommitをtrueのままにしてたのが、すべてのきっかけだったわけじゃん
でもそのおかげでSpring BootとjOOQのトランザクション サポートの課題も見つかって良かったね!
という感じで、原因の追及と対応に丸一日かかりましたが、良い経験になりました。