谷本 心 in せろ部屋

はてなダイアリーから引っ越してきました

100万件ぐらいのレコードを扱ったらOOMEが出た話。

Java Spring

要約

技術的な話だけ教えて、という方のために先に結論だけ書いておきますと、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ファイルを読み込みました。
↓こんな感じでヒープを占めるオブジェクトの傾向が分かります。

f:id:cero-t:20200812214730p:plain
JMCでヒープダンプを開くとこういう情報が分かる

一番上にある byte[][] がヒープの7割も占めていて明らかに怪しいので、ダブルクリックして詳細を見ます。
↓こんな感じでどこから参照されているかが分かります。

f:id:cero-t:20200812214806p:plain
オブジェクトの親子関係も追跡できる

どうやら 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のトランザクションサポートの課題も見つかって良かったね！

という感じで、原因の追及と対応に丸一日かかりましたが、良い経験になりました。