Prismaのpgbouncer=trueがSupabaseでクエリを4往復させていた（ポストモーテム）
要約
この記事は、SupabaseでPrismaを使用する際にpgbouncer=true設定が原因で発生した深刻なパフォーマンス問題について詳述しています。この設定により、各データベースクエリが4回のネットワーク往復を必要とし、応答時間が大幅に増加しました。著者は当初ネットワーク遅延を疑っていましたが、最終的にPrismaがトランザクションモードで各クエリを複数のステートメントにラップすることが原因であると特定し、設定変更によって問題を解決しました。
全文翻訳
Every database query cost us four round-trips for six months
9月14日の夜、私が運営するマサイマラのロッジ、Mara Hilltopにゲストが予約を試みた際、日付を選択して「Continue」を押すたびにページがクラッシュしました。その夜、私たちはクラッシュを修正し、3月から抱えていた別のデータベース設定ミスを発見しました。これは、私たちが構築・運営しているホテルソフトウェアKaribuKitに存在していました。一つの設定を修正しただけで、予約ページの裏側にある空室確認の時間が8.06秒から1.88秒に短縮されました。私たちは、そのミスのコストをローンチの4日後に測定し、正しく計算していましたが、地理的な要因のせいにしました。
クラッシュと遅延は無関係であることが判明しました。クラッシュは短い話であり、遅延は書き留める価値のある話です。
The crash
［画像: The guest's WhatsApp messages: a Chrome error page in Spanish, "No se puede abrir esta página", then "after pressing continue I have this message (sorry it's in Spanish)" at 7:13 PM, and the lodge replying "Getting it checked right now" at 7:14 PM］ 午後7時13分。彼はスクリーンショットがスペイン語であることを謝罪しました。
Chromeの「ページを開けませんでした」という画面は、iOSが同じページでブラウザのコンテンツプロセスを2回連続でキルした場合に表示されるもので、携帯電話ではほとんどの場合メモリ不足を意味します。私たちの予約ページは、すべての部屋写真の元のカメラファイルをロードしており、空室情報が表示されると同時にプリローダーが全ギャラリーを読み込んでいました。ページが取得する同じ36個のファイルをダウンロードして測定したところ、転送サイズは47MB、デコード後は3.9GBでした。最大のファイル、ラグジュアリーテントのインテリアの一つは、8171 x 5957ピクセルで、それだけで186MBになります。ラップトップならメモリに余裕がありますが、私のラップトップでは再現できませんでした。しかし、iPhoneにはそれがなく、彼の元のスクリーンショットのタブバッジは81を示していました。
不快なのは、修正策がすでに存在していたことです。AnthropicのコマンドラインコーディングエージェントであるClaude Codeが、8月26日に別のページで同じクラッシュが発生した後、それを修正していました。それは、Next.jsの画像オプティマイザーを通してリサイズされたコピーを提供し、プリローダーを削除するというものでした。それは19日間オープンなプルリクエストのまま放置されていました。なぜなら、私のメモには「PR to dev」と書かれており、私はそれを完了したと解釈していたからです。その夜にマージされ、ページは36個の生のファイルフェッチからゼロになりました。彼は深夜3時3分にそのことに関するメッセージを送ってきました。彼が予約を完了したかどうかは、まだわかりません。
The number that didn't fit
修正されたページを確認している際に、その裏側にある空室リクエスト、つまりAPIがゲストの日付に対してどの部屋が空いているかを尋ねる呼び出しの時間を計測しました。APIサーバー自体から、ネットワークを介さずにlocalhostで計測したところ、その夜は9.9秒、過去3日間のログのメディアンでは8.1秒でした。これは、午前3時でも午後5時でも同様でした。
ヘルスチェックの方が良い手がかりでした。「/health」はPostgresに対して一つのSELECT 1を実行し、Redisにpingを打ちます。localhostからの計測では、私が測定した夜は240ミリ秒、その前の3日間のメディアンでは285ミリ秒でした。取るに足らないクエリであれば、データベースへのネットワーク往復は1回で済むはずです。私たちのAPIは、ヘルシンキにあるHetznerのサーバーがダブリンのSupabaseと通信しており、その往復（ボックスからのTCP接続で測定）は47ミリ秒です。240ミリ秒は、その4倍に余りがある時間です。その時点では、その4倍の理由がわかりませんでした。
Six months of looking one layer away
私たちは3月27日にローンチしました。3月31日、アプリが遅かったためパフォーマンス仕様書を作成し、その最初の作業として、すべてのレスポンスにServer-TimingヘッダーとX-DB-Queriesカウントを追加しました。仕様書と当日のベースラインは、まだリポジトリに残っています。仕様書には「localhost /health で257ms TTFB」と記録されており、「mixed health-check cost」の下に分類されています。ベースラインは、フォリオエンドポイントが10クエリに対して2,667msのデータベース時間を記録し、その後、「Remaining bottleneck」の下で割り算をしています。
DB round trip: ~267ms per query (2667ms / 10 queries). This is the Hetzner Finland → Supabase Ireland network latency. Every Prisma query pays this cost.
計算は正しかったのですが、文章が間違っていました。誰もレイテンシを測定していませんでした。推奨事項は、インフラストラクチャを「約267msから約5ms」に移動させることでした。それは機能したでしょう。なぜなら、5ミリ秒の往復が4回なら安価であり、私たちは4回あることを決して知らなかったからです。
その後に続いたのは、間違ったレイヤーでの良い作業でした。リザベーションページをロードあたりのリクエスト数を68から数個に減らし、ユーザー検索をキャッシュし、gzipを有効にし、5月に遅延して戻ってきたアイドルタブのためにキープアライブを追加し、6月に認証リフレッシュを4回パッチし、8月にAPIをCloudflareの後ろに置きました。それらのすべてが役立ちましたが、単一クエリのコストに触れるものはありませんでした。「ネットワークが遅い」というのが、4日目からの受け入れられた説明であり、新しい症状はすべてそれに適合しました。
What it actually was
［画像: Sequence diagram. Before: the API in Helsinki sends BEGIN, DEALLOCATE ALL, the SELECT, and COMMIT to Supavisor in Dublin, four 47 ms round-trips, about 188 ms of wire per query, /health measured at 240 ms. After: one SELECT, one 47 ms round-trip, /health measured at 85 ms.］ Prisma 5.22とpgbouncer=trueをトランザクションプーラーに対して使用した場合、各クエリは47msのリンクを4回横断していました。セッションモードでは1回です。
SupabaseはPostgresの前にSupavisorというプーラーを配置しており、2つのモードがあります。トランザクションモードは各トランザクションに接続を割り当て、プリペアドステートメントをサポートしないため、私たちのORMであるPrismaは、それと連携するために pgbouncer=true フラグが必要です。そのフラグにより、Prismaは各クエリをダイアグラムの4つのステートメントでラップし、それぞれがリンクを横断します。ヘルスチェックがコストとしていた240ミリ秒のうち188ミリ秒がこれに費やされ、残りはプーラー自体のブックキーピングとクエリ自体でした。同じラックにあるプーラーでは、ラップのコストは数ミリ秒です。ヘルシンキとダブリン間の47ミリ秒の距離では、空室確認パスでのクエリあたりの測定コストは、アプリケーションが行うすべてのクエリで210ミリ秒から260ミリ秒の間でした。
データベースは3月からスコアを付けていました。pg_stat_statementsは、約400万回の実際のクエリに対して、BEGINが4,053,716回、DEALLOCATE ALLが4,053,574回、COMMITが4,053,080回呼び出されていることを示していました。400万回のすべてのDEALLOCATE ALL呼び出しの合計サーバーサイド時間は9.6秒でした。データベースは何もしていませんでした。時間はすべてワイヤー（ネットワーク転送）にかかっていました。空室確認エンドポイントは38個の質問を連続して行います。ほとんどが部屋タイプごと（部屋は空いているか、料金はいくらか、この日付に対するオーバーライドはあるか）であり、1クォーター秒あたり10秒になります。
セッションモードは、バックエンドをクライアント接続にピン留めし、プリペアドステートメントをサポートし、フラグを必要としません。その唯一のコストは、開いている各接続がプールスロットを保持するため、プールを意図的にサイズ設定する必要があることです。Supabase自身のPrismaガイドは、長期間実行されるサーバーをセッションモードで配置しています。トランザクションモードのレシピとフラグは、リクエストごとに接続を開くサーバーレス関数向けです。KaribuKitは、PM2下で数週間存続するNodeプロセスです。私たちはローンチ週にサーバーレスのレシピをコピーし、二度と見直しませんでした。その一部は、サーバー上の.envファイルにのみ存在していたためです。
The fix, and how we knew it worked
一行の変更でした。DATABASE_URLをポート6543（pgbouncer=true付き）からポート5432（connection_limit=5付き）に変更しました。まずステージングで、次に本番環境でナイロビ時間23:40に適用しました。ロールバックは1分で完了します。空室確認はメディアンで8.06秒から1.88秒に、フォリオは1.43秒から0.39秒に、カレンダーは0.58秒から0.18秒に、/healthは285ミリ秒から85ミリ秒に、そして今日のボードは0.85秒から0.49秒に改善されました。ほとんどの画面で3〜4倍速くなり、予約ページは4.3倍、今日のボードは1.7倍速くなりました。
速度だけでは証明になりません。なぜなら、半適用された変更（2つのプロセスのうち1つだけ再起動、2つの設定ファイルのうち1つだけ編集）も速くなるからです。私を納得させたのは、メカニズム自体のカウンターでした。2分間隔で取得したpg_stat_statementsの2つのサンプルと、その間の既知のリクエストにより、DEALLOCATE ALLの呼び出し回数が変化せず、空室確認リクエストあたりの38ステートメントがゼロになったことが確認できました。ss -tnpコマンドは、APIとワーカーのソケットすべてがダブリンのポート5432に接続されており、6543には接続されていないことを示しました。また、12個の同時接続が5個のプールに対してタイムアウトなしで処理されました。
Who found it
私ではありません。Claude Codeにゲストのスクリーンショットを渡し、問題が私たち側にあるのか、それとも彼の電話にあるのか尋ねました。彼は20分で回答し、デプロイを確認している間に、10秒の壁に気づき、さらに調査を進めました。時間ごとのログ、47ミリ秒のTCP測定、pg_stat_statementsクエリ、計算などです。サーバー上で実行されていた2回目のセッションは、私が書いた設定変更手順を実行することを拒否しました。なぜなら、手順内のプロセス名が間違っており、あるコマンドシーケンスでは、すべてのチェックがグリーンと報告しているにもかかわらず、本番環境がステージングデータベースを指してしまう可能性があったからです。4回の改訂を経て、ようやく実行できました。
私が最も心地よく思わない部分は、3月のベースラインを作成するのに役立ったのと同じ種類のツールが、2,667を10で割り、その答えをアイルランドまでの距離と呼び、大陸の移動を提案したことです。エージェントの分析における計算は通常正しいです。その結果に付随する文章は、測定された何かがそれを裏付けるまで推測であり、私は両方を同じ信頼度で読みました。
What I now believe
- ペイロード、宿泊日数、または負荷によってスケールしないコストは、スローワークではなく、コールごとのオーバーヘッドです。空室確認は、1泊でも7泊でも10秒かかりました。
- 同じ症状に対する3回目のパッチは、再びパッチを当てるのではなく、最初から再測定する合図です。
- サーバー設定にのみ存在する、負荷がかかる要素は、その形状をリポジトリに、理由とともに書き込むか、次のパスワードローテーションで元に戻されます。
リモートデータベースを持つあらゆるスタックでのチェック方法：
- APIホスト上で、ヘルスチェックの時間を計測します:
curl -s -o /dev/null -w '%{time_starttransfer} ' http://localhost:PORT/health。ここで、ヘルスチェックは取るに足らないクエリを1回実行します。 - そのホストからデータベースエンドポイントまでのTCP往復を測定します。
- 最初の数値が2番目の数値の約2倍より大きい場合は、ドライバーがクエリごとに何を行っているかを調べます。
私たちの場合は、最初の週から240ミリ秒対47ミリ秒でした。次に行うことは、空室確認ハンドラーの38個の質問を並列化することです。これにより、1秒未満になるはずです。もしあなたのlocalhostヘルスチェックが、数十ミリ秒のpingに対して数百ミリ秒を読み取る場合、それはドライバーを確認する理由にはなりますが、同じ原因であることの証明にはなりません。いずれにせよ、あなたがどのレシピをコピーしたか教えていただけると嬉しいです: nj@simbastack.com。
— NJ
私はSimbaStackを運営しており、AIエージェントとそのシステムを構築しています。また、この記事で言及されているホテルソフトウェアKaribuKitも運営しています。エージェントを本番環境に展開するお手伝いが必要な場合は、構築しているものを同じアドレスまでお知らせください。