テスト 248 件全パスなのに本番は 110 秒固まった ── リファクタですり抜けた N+1 障害の話

Last updated at 2026-04-21Posted at 2026-04-19

はじめに

個人開発で運用している電気料金シミュレーター（enegent.jp）で、3層構造への計算エンジンリファクタリングを完了し、248 件のテストが全てグリーンな状態で本番デプロイした。

ゴールデンテスト（本番推薦 API 相当の 5 シナリオ同値比較）も PASS、verify_spot_mode の出力も before/after で 1 byte 違わず一致。完璧なリファクタのつもりだった。

デプロイから数十分後、ユーザーから報告：

22:28 現在、シミュレーターが計算中のまま止まる

本番 API の応答時間を測ると 110 秒。ブラウザ側の fetch がタイムアウトして「計算中」のまま hang していた。

テストは全部通っていたのに、本番は落ちた。何が起きていたのか。

結論を先に

原因は N+1 DB クエリ爆発。1 試算で plan_system_fees テーブルに 10,000+ 回アクセスしていた
リファクタで追加したコード由来ではなく、元々存在していた設計バグがコールドスタート時だけ顕在化した
ローカルでは Supabase への RTT が小さく見えず、本番 Cloud Run のコールドスタート + 大量クエリで一気に破綻した
テストは正しさ（値の同値）しか見ておらず、「計算コストの爆発」は見ていなかった

以下、発生から対処までを時系列で書く。

事件の構造

リファクタの内容（背景）

計算エンジンを 3 層構造に分離するリファクタを実施した：

UsagePattern (年間使用量)
    ↓ expand_usage_pattern
MonthlyUsage[12] (数量層)
    ×
UnitPriceSet (単価層)  ← plan × month × area × ampere → 単価の完全セット
    ↓ calculate_monthly_bill_from_unit_prices
CostBreakdown (計算層出力)

既存 calculate_monthly_bill は内部で market_linked_params を import し、plan_type で if/elif 分岐していた。これを「単価層が全プランを UnitPriceSet に正規化 → 計算層は if/elif なし」の構造に変えた。既存 API のシグネチャは完全互換（内部は v3 層に委譲する shim）。

デプロイ前のテスト状況

py -m pytest: 268 passed, 0 failed
tests/test_golden_recommendation.py: 5 シナリオ全 PASS（本番推薦 API 相当の値を同値比較）
scripts/verify_spot_mode.py --jepx=20.62: before/after 出力完全一致

値の正確性は 100% 保証されていた。

本番デプロイ直後の症状

ユーザー報告を受けて本番を叩くと：

$ curl -sSL --max-time 60 "https://.../api/simulate?area=tepco&ampere=40A&monthly_yen=15000"
curl: (28) Operation timed out after 60013 milliseconds

60 秒でもタイムアウト。90 秒、120 秒、最終的に応答は返るが 110 秒 かかっていた。

Cloud Run ログを見る

$ gcloud run services logs read enegent-bot --region asia-northeast1 --limit 100
2026-04-19 13:32:15 INFO:httpx:HTTP Request: GET .../plan_system_fees?...&retailer_name=eq.ニチガスでんき&fee_type=eq.fixed_flat
2026-04-19 13:32:15 INFO:httpx:HTTP Request: GET .../plan_system_fees?...&retailer_name=eq.ニチガスでんき&fee_type=eq.usage_per_kwh
2026-04-19 13:32:15 INFO:httpx:HTTP Request: GET .../plan_system_fees?...&retailer_name=eq.ニチガスでんき&fee_type=eq.fixed_flat
2026-04-19 13:32:15 INFO:httpx:HTTP Request: GET .../plan_system_fees?...&retailer_name=eq.ニチガスでんき&fee_type=eq.usage_per_kwh
（同じクエリが延々と続く）

同一の (retailer_name, fee_type) への GET が 1 秒に 10 回以上発生している。30 秒間の実ログでは 300+ 回。

犯人は `calculate_monthly_bill` の呼び出し構造

# calculator.py 内部
def annual_cost_range(cache, plan, usage):
    # 12 ヶ月 × 3 種のレンジ (median / low / high) で合計 36 回
    for month in range(12):
        for range_type in [median, low, high]:
            calculate_monthly_bill(plan, ..., fy_key, month)

def calculate_monthly_bill(plan, kwh, ampere, fuel_per_kwh, fy_key, month):
    # ここで DB アクセス
    if plan.retailer_name:
        from market_linked_params import get_system_fee_fixed, get_system_fee_usage
        basic += get_system_fee_fixed(plan.retailer_name, ampere)  # DB クエリ 1-2 回
        usage += get_system_fee_usage(plan.retailer_name, kwh)     # DB クエリ 1 回

# market_linked_params.py
def _fetch_system_fee_from_db(retailer_name: str, fee_type: str) -> float | None:
    sb = get_supabase()
    res = sb.table("plan_system_fees").select("amount").eq("retailer_name", retailer_name)...
    # 毎回 Supabase に問い合わせる

掛け算：

147 プラン × 12 ヶ月 × 3 レンジ = 5,292 回 の calculate_monthly_bill 呼び出し
各回 2-3 回の DB クエリ → 約 15,000 回の DB 往復
Cloud Run コールドスタート時の各往復 ~10ms → 合計 150 秒

これが「110 秒応答」の正体。

対処（プロセス内辞書キャッシュ）

_fetch_system_fee_from_db を、初回呼び出し時に全件 1 クエリで取得 → プロセス内辞書に展開 する形に書き換える：

_SYSTEM_FEE_CACHE: dict[tuple[str, str], float | None] = {}
_SYSTEM_FEE_CACHE_LOADED: bool = False


def _preload_system_fees() -> None:
    global _SYSTEM_FEE_CACHE_LOADED
    if _SYSTEM_FEE_CACHE_LOADED:
        return
    try:
        sb = get_supabase()
        res = (sb.table("plan_system_fees")
            .select("retailer_name, fee_type, amount")
            .is_("valid_to", "null")
            .execute())
        for r in res.data or []:
            _SYSTEM_FEE_CACHE[(r["retailer_name"], r["fee_type"])] = float(r["amount"])
    except Exception:
        pass
    _SYSTEM_FEE_CACHE_LOADED = True


def _fetch_system_fee_from_db(retailer_name: str, fee_type: str) -> float | None:
    if not _SYSTEM_FEE_CACHE_LOADED:
        _preload_system_fees()
    return _SYSTEM_FEE_CACHE.get((retailer_name, fee_type))

変更点は 10 行程度。効果：

本番 /api/simulate: 110 秒 → 2.7 秒（約 40 倍高速化）
ローカル test_golden_recommendation.py: 420 秒 → 18 秒（約 23 倍高速化）
計算値は完全同値（verify_deploy_regression.py 5 シナリオ PASS）

なぜテストは捕まえられなかったのか

1. テストが「値の正しさ」しか見ていなかった

既存のテストスイートは以下を検証していた：

test_calculator.py / test_calculator_v2.py: 月額計算の出力値
test_golden_recommendation.py: 推薦 API のスナップショット比較
verify_spot_mode.py: before/after の JSON 出力 diff

全て 「値が正しいか」 のみ。「計算にどれだけかかるか」は 1 つも見ていなかった。リファクタで値は変わらなかったので全て通った。

2. ローカルでは問題が見えなかった

ローカル環境は Supabase への RTT が ~50ms で、15,000 回のクエリでも 12 分程度。テスト実行時間で気付けたはずだが：

ゴールデンテストは「もともと 7 分かかる」と割り切られていた（Cloud Run コールドスタート対策のため）
その中で 420 秒と 240 秒の区別がつかず、「こんなもんか」と流れていた

「常識的に遅すぎる」と気付くべき閾値を設定していなかった。

3. Cloud Run コールドスタート時の挙動は別物

本番では：

Cloud Run コンテナ起動直後は HTTP/2 コネクション確立に時間がかかる
大量の並行 httpx リクエストでイベントループが詰まる
結果、1 往復が ~10ms でも累積 150 秒、場合によってはタイムアウト

ローカルマシンと Cloud Run では、DB アクセスパターンの破綻の仕方が違う。N+1 はローカルでは「遅い」だけだが、本番では「落ちる」。

4. 3 層リファクタは「既存バグを温存」していた

リファクタで v3 shim 化した calculate_monthly_bill は、内部で呼んでいる get_system_fee_fixed / get_system_fee_usage のコール回数を変えていなかった。旧版と同じ頻度で DB を叩いていた。

つまり N+1 バグは最初から本番に潜在していた はず。なぜこれまで発覚しなかったのか → min-instances=1 時代は常時ウォームで、コールドスタート問題が隠れていたと推測している（コスト削減で min-instances=0 にした直後、このタイミングで爆発）。

学んだこと

教訓 1: 「関数の呼び出し頻度 × 内部 DB クエリ数」を見積もる習慣

リファクタや新機能追加のレビュー時、以下のチェックリストを足した：

この関数は どれくらいの頻度で呼ばれるか（ループ内? N 回?）
関数内部で DB クエリ（or 外部 API）を発生させていないか
発生させているなら、呼び出し頻度 × クエリ数 ≒ どれくらいの DB 往復になるか

計算結果が数千を超えるなら N+1 パターン確定。preload 型キャッシュに変える。

教訓 2: 応答時間の回帰テストを入れる

「値の回帰テスト」に加えて「応答時間の回帰テスト」を書いた：

def test_annual_cost_range_under_50ms():
    """単一プランの annual_cost_range は warm 時 50ms 以下（N+1 検知）"""
    cache = get_shared_cache(sb)
    cache.preload()  # warm-up
    t0 = time.time()
    annual_cost_range(cache, plan, usage)
    elapsed_ms = (time.time() - t0) * 1000
    assert elapsed_ms < 50, f"annual_cost_range took {elapsed_ms}ms (N+1 suspected)"

数値は環境依存でフラキーになりがちだが、桁違いに遅い ケースは十分捕まえられる。

教訓 3: ロールバック経路を先に用意する

発覚直後、Cloud Run を前の revision に戻してユーザー影響を最小化した：

gcloud run services update-traffic enegent-bot --region=asia-northeast1 \
  --to-revisions=enegent-bot-00088-2d5=100

Cloud Run の revision ベースで 1 コマンドで戻せるのは非常に助かった。ロールバックが確実にできる環境は 「修正しながら本番を復旧する」より「本番を復旧してから落ち着いて修正する」 を選べる余裕を作る。

教訓 4: プロファイリングの習慣をつける

デプロイ後、ローカルで cProfile を実行して改めてボトルネックを確認：

import cProfile, pstats, io

pr = cProfile.Profile()
pr.enable()
run_recommendation(area='tokyo', ampere='40A', monthly_yen=[10000]*3, top_n=10)
pr.disable()

s = io.StringIO()
ps = pstats.Stats(pr, stream=s).sort_stats('cumulative')
ps.print_stats(25)
print(s.getvalue())

出力：

ncalls  tottime  cumtime  filename:lineno(function)
    72    0.000    3.415   api/db.py:140(get_jepx_monthly_avg)
    72    0.000    3.385   httpx/_client.py:879(send)

97.8% が get_jepx_monthly_avg の SSL read。ボトルネックが一目瞭然だった。

おわりに

「テストが全部通った」だけでは本番の健全性は保証されない、という当たり前の事実を改めて学んだ。特にリファクタリングでは：

値の正しさ（回帰テスト）だけでなく
計算コストの変化（パフォーマンス回帰テスト）も
本番環境特有の挙動（コールドスタート、並行性）も

それぞれ別の方法で担保する必要がある。

今回はロールバック後の修正で応答時間を 110 秒 → 2.7 秒まで戻し、計算値は完全同値のまま本番復旧できた。障害時間は約 1 時間、ユーザー影響は最小限で済んだ。

N+1 は経験豊富なエンジニアでも踏み抜く古典的パターンだけど、「ループ内で DB を叩く」構造を見つけたら迷わず preload に変える、という基本を改めて肝に銘じたい。