Prismaのpgbouncer=trueがSupabaseでクエリを4往復させていた（ポストモーテム）

9月14日の夜、私が経営するマサイマラのロッジ「Mara Hilltop」の予約を試みていたゲストが、日付を選択して「Continue」を押すたびにページがクラッシュするという問題が発生しました。その夜、私たちはクラッシュを修正し、KaribuKit（私たちが開発・運営しているホテルのソフトウェア）で3月から放置されていた別のデータベース設定ミスを発見しました。一つの設定を修正しただけで、予約ページの可用性チェックの時間が8.06秒から1.88秒に短縮されました。私たちはこのミスのコストをローンチの4日後に測定し、計算も正しく行いましたが、地理的な要因のせいにしました。クラッシュと遅延は無関係でした。クラッシュは短い話であり、遅延こそが書き留める価値のある話です。 クラッシュ 19:13。 ゲストはスクリーンショットがスペイン語であることを謝罪しました。Chromeの「ページを開けませんでした」という画面は、iOSで同じページでブラウザのコンテンツプロセスが2回連続で終了した場合に表示されるもので、電話機ではほぼ間違いなくメモリ不足を意味します。私たちの予約ページは、各部屋写真の元のカメラファイルをロードしており、可用性が到着した瞬間にプリローダーが各部屋タイプの全ギャラリーを読み込んでいました。ページが取得する同じ36個のファイルをダウンロードし、そのサイズを測定しました。ネットワーク上では47MB、デコード後は3.9GBでした。最大のファイル、ラグジュアリーテントのインテリアの一つは、8171x5957ピクセルで、それだけで186MBになります。ラップトップにはそれを隠すRAMがありますが、私のラップトップでは再現できなかった理由です。iPhoneにはそれがなく、ゲストの元のスクリーンショットのタブバッジには「81」と表示されていました。 不快なのは、修正策がすでに存在していたことです。AnthropicのコマンドラインコーディングエージェントであるClaude Codeが、8月26日に別のページで同じクラッシュが発生した後、それを書いていました。「リサイズされたコピーをNext.jsの画像オプティマイザー経由で提供し、プリローダーを削除する」というものでした。それは19日間オープンなプルリクエストのまま放置されていました。なぜなら、私のメモには「PR to dev」と書かれており、私はそれを完了したと解釈していたからです。その夜にマージされ、ページは36個の生のフェッチからゼロになりました。ゲストは深夜3分後にその旨のメッセージを送ってきました。彼が予約できたかどうかはまだわかりません。 合わない数字 修正されたページを確認している間に、その背後にある可用性リクエスト、つまりAPIにゲストの日付に対してどの部屋が空いているかを問い合わせる呼び出しの時間を計測しました。APIサーバー自体から、ローカルホストでネットワークを介さずに計測すると、その夜は9.9秒、過去3日間のログの中央値では8.1秒でした。これは、03:00でも17:00でも同様でした。 ヘルスチェックはより良い手がかりでした。 /healthはPostgresに対して1回のSELECT 1を実行し、Redisにpingを打ちますが、ローカルホストから計測したところ、私が計測した夜は240ミリ秒、その前の3日間の中央値では285ミリ秒でした。些細なクエリは、データベースへのネットワーク往復1回で済むはずです。私たちのAPIは、ヘルシンキにあるHetznerのボックスで、ダブリンのSupabaseと通信しています。その往復は、ボックスからのTCP接続で測定すると47ミリ秒です。240ミリ秒は、それの4倍で、お釣りがくるほどです。その時点では、なぜ4回なのかわかりませんでした。 6ヶ月かけて1層離れた場所を探る 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)」。これはHetznerフィンランド → Supabaseアイルランド間のネットワーク遅延です。Prismaの各クエリはこのコストを支払います。計算は正しいが、文脈が間違っていました。誰も遅延を測定していませんでした。推奨事項は、インフラを「約267msから約5ms」に近づけることでした。それは、5ミリ秒の4往復は安価であるという意味で機能したでしょうし、4回あることには決して気づかなかったでしょう。 その後に続いたのは、間違ったレイヤーでの良い仕事でした。予約ページをロードあたりのリクエスト数を68から数個に減らし、ユーザー検索をキャッシュし、gzipを有効にし、5月に遅延していたアイドルタブが戻ってきたときにキープアライブを追加し、6月に認証リフレッシュを4回パッチし、8月にAPIをCloudflareの後ろに置きました。それらのすべてが役立ちましたが、どれも単一クエリのコストには触れていませんでした。「ネットワークが遅い」というのが、4日目からの受け入れられた説明であり、新たな症状はすべてそれに適合しました。 実際には何だったのか Prisma 5.22とトランザクションプーラーに対するpgbouncer=trueを使用すると、各クエリは47msのリンクを4回横断していました。セッションモードは1回で済みます。 SupabaseはPostgresの前にSupavisorというプーラーを配置しており、2つのモードがあります。トランザクションモードは各トランザクションに接続を割り当て、プリペアドステートメントをサポートできないため、Prisma（私たちのORM）はそれと連携するためにpgbouncer=trueフラグが必要です。そのフラグにより、Prismaは各クエリをダイアグラムの4つのステートメントでラップし、それぞれがリンクを横断します。ヘルスチェックがコストをかけていた240ミリ秒のうち188ミリ秒がこれにあたり、残りはプーラー自身の管理とクエリ自体です。同じラックにあるプーラーでは、ラップのコストは数ミリ秒です。ヘルシンキとダブリン間の47ミリ秒を横断すると、可用性パスでのクエリあたりの測定コストは、アプリケーションが行うすべてのクエリで210ミリ秒から260ミリ秒の間になりました。 データベースは3月から記録を付けていました。 pg_stat_statementsは、BEGINが4,053,716回、DEALLOCATE ALLが4,053,574回、COMMITが4,053,080回呼び出されており、実際のクエリは約400万回でした。400万回のDEALLOCATE ALL呼び出しの合計サーバーサイド時間は9.6秒でした。データベースは何もしていませんでした。時間はすべてネットワークでした。 可用性エンドポイントは38個の質問を連続して行います。ほとんどが部屋タイプごと（部屋は空いているか、料金はいくらか、これらの日付に対する上乗せ料金はあるか）であり、1クォーター秒（約0.25秒）あたりで、これは10秒になります。 セッションモードはバックエンドをクライアント接続に固定し、プリペアドステートメントをサポートし、フラグは不要です。唯一のコストは、開かれた各接続がプールスロットを保持するため、プールを意図的にサイズ設定する必要があることです。Supabase自身のPrismaガイドでは、長時間実行サーバーにはセッションモードを使用することを推奨しています。フラグ付きのトランザクションモードのレシピは、リクエストごとに接続を開くサーバーレス関数用です。KaribuKitはPM2下で数週間存続するNodeプロセスです。私たちはローンチ週にサーバーレスのレシピをコピーしましたが、二度と見直しませんでした。それはサーバー上の.envファイルにのみ存在していたことも一因です。 修正方法と、それが機能したとわかった理由 1行だけです。 DATABASE_URLを、pgbouncer=trueのポート6543から、connection_limit=5のポート5432に変更しました。まずステージングで、次にプロダクションでナイロビ時間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をサンプリングしたところ、DEALLOCATE ALLの移動がゼロになり、これは可用性リクエストあたり38ステートメントがゼロになったことを意味します。ss -tnpコマンドは、すべてのAPIおよびワーカーソケットをダブリンのポート5432に接続し、6543には接続しないことを示し、5個のプールに対して12個の同時バーストがタイムアウトなしで保持されました。 誰が見つけたのか 私ではありません。Claude Codeにゲストのスクリーンショットを渡し、問題が私たち側にあるのか、それとも彼の電話にあるのか尋ねました。彼は20分で回答し、デプロイを確認している間に、10秒の壁に気づき、ログを時間ごとに、47msのTCP測定、pg_stat_statementsクエリ、計算を調べ続けました。次に、サーバーで実行されている別のセッションは、設定変更手順を私が書いた通りに実行することを拒否しました。なぜなら、手順内のプロセス名が間違っており、あるコマンドシーケンスがプロダクションをステージングデーモンに向けさせてしまう可能性があったからです。