先にまとめ
jOOQ を大量(数百以上)のテーブルを持つデータベースで使うとき、クラスローディング等で起動後最初のリクエストで時間がかかることがある。
リクエストを受け付ける前に適当な jOOQ クエリを一度流しておくなど、適切にウォームアップしましょう。
問題
jOOQ を ORM として利用してるバックエンドプロジェクトで、以下の様な問題に遭遇しました。
- 起動直後の1発目リクエストが必ず遅い (2秒以上)
- 2発目以降のリクエストは、概ね 500ms 以下で処理できる
- jOOQ を呼び出していないリクエストはそれほど遅くない
- JDBC のコネクションプールは、リクエスト処理前にすでにウォームアップされている (Spring Boot の Readiness Probe を使っている)
条件としては以下の様な環境です。
- Kotlin/JVM で書かれた Spring Boot アプリケーション
- ORM として jOOQ を利用 (JDBC)
- 実環境では Datadog Java Agent をモニタリングに投入している
- jOOQ にコード生成させたデータベースは 100 以上のテーブルが存在する
原因調査
Datadog APM で観測されたトレースでは、アプリケーションがリクエストを受け付けてから、最初の SQL クエリの開始の間で多くの時間が費やされてることが判明しました。
APM のトレースからでは、これ以上何もわかりません。
そこで、Datadog の Continuous Profiler を有効にして CPU がどこで使われているか、フレームグラフを有効にしてみたところ、以下のことが解りました。
- jOOQ を呼び出している Repository クラスのメソッドで 500ms 以上の CPU Time が消費されている
- その呼び出し元は大きく分けて2つの jOOQ メソッド
DefaultDSLContext.select(SelectFieldOrAsterisk[])Tables.<clinit>()
- いずれの場合も、ClassLoader に時間がかかっている
ローカルで再現してみると、大体同じ様な傾向が確認でき、プロファイラーの結果でも同様の問題が観測されました。
一方で、jOOQ を使っている他のプロジェクトで試してみると、それほど時間がかからずに初回のリクエストが処理されます。
Tables.<clinit>
プロファイリングの結果をもっとよくみてみると、Tables.<clinit> は何度もクラスローダーが呼ばれている結果が見えます。
このクラスは、jOOQ のコード生成により作られたクラスで、対象の DB スキーマに含まれる全てのテーブルクラスインスタンスへの参照が static フィールドとして定義されています。
つまり、Tables.USER などで何らかの Tables クラスへの参照が起きると、生成された全ての Table クラスのロードが行われることになります。
今回のプロジェクトはデータベースのテーブルの数が多いので、これが問題でしょうか？
DefaultDSLContext.select
DefaultDSLContext はとても大きなクラスなので、時間がかかっていそう？
解決
Readiness Probe (Startup Probe としても利用している) で、あまり意味のない jOOQ を使ったクエリを叩く様にすることで、問題がほぼ解決しました。2秒以上かかっていたリクエストが、500ms 以下で処理される様になりました。
一方で、Datadog のバイトコード生成が時間を使っている様な点もプロファイリング結果から観測できているので（特に DefaultDSLContext)、そちらが問題だったりするのかもしれません。時間がある時にもう少し調査してみます。
どのクラスのロードにどれぐらい時間がかかっているとか、何かモニタリングできるツールとかないんでしょうか？
Discussion