0
0

Delete article

Deleted articles cannot be recovered.

Draft of this article would be also deleted.

Are you sure you want to delete this article?

@yousan(Yousan Yousan)

Supabase Edge Functions の 546 エラーで画像生成ポーリングが17時間詰まった話 — ネイティブメモリ枯渇によるリトライ地獄

0
Last updated at Posted at 2026-04-22

はじめに

Supabase Edge Functions で HTTP 546 (WORKER_RESOURCE_LIMIT) が発生し、絵本生成機能のポーリング処理が17時間にわたって詰まり続け ました。しかも調査するまで誰も気づいていませんでした(サービス全体が落ちていたわけではなく、非同期ポーリングだけが静かに失敗し続けていたため)。

この記事は、その障害の全記録と、同じ罠を踏まないための監視設計の話です。

先にお伝えしておくと、調査当初は「Wall Clock(isolate 寿命 400秒)を使い切ったから」だと推測していました。Supabase Edge Functions の 546 でググるとそれらしい話がたくさん出てきます。が、実際に function_logs を最後まで確認したところ、原因は 100% メモリ枯渇で、Wall Clock は一切関係なかった ことが判明しました。推測ではなくログで確定させる大事さを痛感したインシデントなので、書き残しておきます。

546 の 一般的な仕組み・ローカル再現方法 については先に書いた Supabase Edge Functions の HTTP 546 の正体を edge-runtime コンテナから掘り出して、ローカルで再現する にまとめてあります。本記事は 具体的な17時間インシデントの調査ログと監視設計 にフォーカスするので、546 自体が初耳の方はそちらを先にどうぞ。

TL;DR

  • pg_cron から 30秒ごとに叩いていた Edge Function が、17時間にわたって 毎分2回 546 を返し続けていた
  • 原因は ネイティブメモリ枯渇 (256MB 上限)。V8 heap は 12〜14MB で安定していたにも関わらず、ネイティブ側で超過していた
  • Wall Clock 枯渇は 0件、Memory limit exceeded 2,041件、CPU Time exceeded 12件 という集計結果
  • pg_cron は net.http_post(pg_net 拡張)を fire-and-forget で叩くので、546 が返っていても cron.job_run_details では 全て succeeded 扱い
  • フロントエンド / バックエンドの Sentry もほぼ検知できず、Supabase Analytics の function_logs にしか痕跡が残っていなかった
  • 処理途中で isolate が kill されるため、DB の status が更新されず同じジョブを拾い続け、リトライ地獄 になった

アーキテクチャ

絵本作成 SaaS で、AI 画像生成を Gemini Batch API に投げています。構成はこんな感じです。

┌─────────────┐   ①ジョブ投入    ┌──────────────────┐
│ Frontend    │ ───────────→  │ submit-image-job │
└─────────────┘               │ (Edge Function)  │
                              └────────┬─────────┘
                                       │ Batch 投入
                                       ▼
                              ┌──────────────────┐
                              │ Gemini Batch API │
                              └────────┬─────────┘
                                       │ 数分〜数十分で完了
                                       ▼
  ┌──────────────┐ ③30秒ごと  ┌──────────────────┐
  │  pg_cron     │ ────────→ │ poll-image-jobs  │
  │ (Postgres)   │           │ (Edge Function)  │
  └──────────────┘           └────────┬─────────┘
                                      │ 画像取得 → Storage 保存
                                      ▼
                              ┌──────────────────┐
                              │ Storage + DB     │
                              └──────────────────┘

要点は pg_cron が 30秒ごとに Edge Function を叩いて、Batch ジョブの結果を取り込む という非同期ポーリング型です。「画像生成完了したら Storage に配置し、image_jobs.status を completed に更新する」という Edge Function 側の責務が重要です。

症状

朝ユーザーから「絵本作成画面でいつまで経っても処理中のままです」と連絡がありました。確認すると確かに image_jobs.status = 'running' のまま 17時間経っていました。

フロントエンドの Sentry(GlitchTip のセルフホスト)を見ると、546 エラーが 数件だけ 記録されていました。「断続的に失敗したけど、それで 17時間も止まるもの?」というくらいの軽微な見た目です。

しかし実際に Supabase Analytics の function_logs を確認すると、様子は全然違いました。

調査 1: Supabase Analytics で全貌を把握

Supabase ダッシュボードの Logs Explorer、あるいは Management API 経由で function_edge_logs / function_logs に直接クエリを投げると、Edge Function の全実行履歴が取れます。

以下のクエリで 17時間分の実行ステータスを集計しました。

SUPABASE_ACCESS_TOKEN=$(grep -oP 'access_token = \K.*' ~/.config/supabase/credentials.toml)
PROJECT_REF="fhdvqfjutrpcbsarptqp"

SQL="select TIMESTAMP_TRUNC(function_edge_logs.timestamp, HOUR) as hour,
            response.status_code,
            count(*) as cnt
     from function_edge_logs
     cross join unnest(metadata) as m
     cross join unnest(m.response) as response
     cross join unnest(m.request) as request
     where request.pathname like '%poll-image-jobs%'
     group by hour, response.status_code
     order by hour"

curl -s -G "https://api.supabase.com/v1/projects/$PROJECT_REF/analytics/endpoints/logs.all" \
  -H "Authorization: Bearer $SUPABASE_ACCESS_TOKEN" \
  --data-urlencode "sql=$SQL" \
  --data-urlencode "iso_timestamp_start=2026-04-21T00:00:00.000Z" \
  --data-urlencode "iso_timestamp_end=2026-04-22T23:59:59.000Z"

重要: iso_timestamp_start / iso_timestamp_end を省略すると直近数件しか返らず、障害は見えません。この落とし穴で最初は「そんなにエラー出てない」と誤認しました。

結果はこうなっていました。

時間帯 200 546
15:00 8 0
15:30 5 12
16:00〜翌 08:00 0 毎時 120
08:30 4 2
09:00 以降 60 0

フロント側の Sentry には数件しか来ていなかったのに、実態は 約 2,000件の 546 が連続していた、という悲しい事実です。

調査 2: function_logs でイベントを分類

次に同じ期間で function_logs の event_message を集計しました。

Supabase Analytics には function_edge_logs(HTTP エッジレイヤのリクエスト/レスポンスログ)と function_logs(ランタイム内部のイベントログ)の 2 種類があります。HTTP ステータスでの集計は前者、「どのリソース上限で死んだか」の集計は後者を使います。

「どのリソース上限で kill されたか」を特定するためです。

select event_message, count(*) as cnt
from function_logs
where timestamp between '2026-04-21T06:00:00Z' and '2026-04-22T00:00:00Z'
group by event_message
order by cnt desc

結果:

event_message 件数
booted (time: 70〜98ms) 2,082
shutdown 2,067
Memory limit exceeded 2,041
CPU Time exceeded 12
Wall clock time exceeded 0

ここが調査の転換点でした。

  • Wall Clock は 0件。「Edge Functions の 546 = isolate 寿命 400秒 枯渇」説は今回当たらない
  • Memory limit が 2,041件。これがほぼ全て
  • booted が 2,082件ある → isolate は毎回新規生成されていた。deployment 単位のリソース枯渇ではない

「1 boot につき 1回 Memory limit を踏んで死ぬ」パターンが 17時間続いていたという結論です。

調査 3: V8 heap はむしろ全然使っていなかった

ここから「なぜメモリが尽きたのか」の調査に入ります。まず疑ったのは V8 heap (JavaScript オブジェクトが載る領域)。Edge Function 内で Deno.memoryUsage() で記録していました。

const mem = Deno.memoryUsage();
console.log(`[memory] heap=${(mem.heapUsed / 1024 / 1024).toFixed(1)}/` +
            `${(mem.heapTotal / 1024 / 1024).toFixed(1)}MB ` +
            `duration=${duration}ms`);

障害直前のログ:

15:43:33 [memory] heap=12.4/14.7MB  duration=2,821ms
15:44:32 [memory] heap=12.4/14.7MB  duration=2,230ms
15:45:41 >>> Memory limit exceeded (546 返却)

V8 heap は常に 11〜14MB で安定 していました。Supabase の上限 256MB から見ると誤差レベル。ところが 546 は返る。矛盾しているように見えます。

原因: V8 heap 以外のネイティブメモリ

正解は「Supabase の 256MB 制限は V8 heap ではなく isolate プロセス全体のメモリ」ということでした。Supabase Edge Functions は Deno ベースの supabase/edge-runtime 上で動いており、isolate のランタイム的には以下が全部乗ります(参考: Deno.memoryUsage() の rss/heap/external 解説)。

  • V8 heap (JS オブジェクト、配列など)
  • ArrayBuffer / Uint8Array などの ArrayBufferView が指すバックストア
  • TextDecoder / JSON.parse の中間バッファ
  • Blob / ReadableStream の内部バッファ
  • fetch の受信バッファ、TLS の暗号バッファ
  • Deno ランタイム自体のネイティブコードが確保するメモリ

今回の poll-image-jobs は何をやっていたかというと:

  1. Gemini Batch API から 12枚の画像の base64 レスポンス を受け取る (1枚あたり数 MB)
  2. base64 をデコードして Uint8Array にする
  3. Supabase Storage に PUT で送る

この 12枚を Promise.all で並列処理 していたので、ピークで以下が全部乗る状況でした。

  • 生レスポンスの文字列 (base64 なので 4/3 倍に膨らむ): 約 50〜80MB
  • デコード後の Uint8Array: 約 30〜60MB
  • Storage アップロード用の Blob/Body: 約 30〜60MB
  • JSON.parse の中間バッファ: 数 MB〜十数 MB

Deno.memoryUsage().heap には一切現れない領域で 256MB を超えていた、というのが答えです。「heap 見てるから大丈夫」と思っていたのが完全な誤解でした。

なぜ 17時間リトライし続けたのか

ここからが地獄編です。Memory limit exceeded で isolate が kill されると、処理は 途中で停止 します。具体的には:

  1. 新しい isolate が立ち上がる (75〜100ms)
  2. supabase.from("image_jobs").select() で status='running' のジョブを拾う
  3. streamBatchJob で Gemini から12枚の画像を取得開始
  4. base64 デコード → Storage アップロードで 256MB 超過
  5. isolate が kill される
  6. DB の image_jobs.status は更新されない (コミット前に死ぬため)
  7. 次の pg_cron (30秒後) が同じジョブを拾う → 1. に戻る

無限ループです。pg_cron の cron 頻度が 30秒なので、 1時間で 120回、17時間で約 2,000回。冒頭の function_logs の件数とピッタリ一致します。

動かぬ証拠: ai_call_logs の pending 残骸

プロジェクトでは AI API 呼び出しのたびに ai_call_logs テーブルに記録しています。この記録処理 writeAiCallLogs は Edge Function の 処理の最後 に呼ばれる構造でした。

// poll-image-jobs/index.ts (抜粋)
try {
  await streamBatchJob(job);
  await uploadAllImages(images);
  await updateJobStatus(job.id, 'completed');
  await writeAiCallLogs({ ...metrics, status: 'completed' });  // ← 最後に呼ばれる
} catch (e) {
  await writeAiCallLogs({ ...metrics, status: 'failed' });
}

メモリ枯渇で死ぬと try/catch のどちらも実行されない ので、ai_call_logs.status が pending のまま残ります。調査時に pending の件数を集計してみると:

SELECT status, count(*) FROM ai_call_logs
WHERE function_name IN ('submit-image-job', 'poll-image-jobs')
GROUP BY status;

 status  | count
---------+-------
 pending |   123
 success |  8420
 failed  |    45

123件の pending が「処理途中で死んだ AI 呼び出しの具体的な数」 として残っていました。普段こんなのはゼロのはずなので、これで完全に裏が取れました。

監視の盲点 (ここが本当に重要)

今回の障害で一番怖かったのが、既存の監視体制でほとんど検知できなかった ことです。具体的に何が盲点だったかを挙げます。

盲点 1: pg_cron の cron.job_run_details は全て succeeded

pg_cron 経由で Edge Function を叩く定番の書き方はこうです。

SELECT cron.schedule(
  'poll-image-jobs',
  '*/30 * * * * *',  -- 6フィールド形式(秒単位)。pg_cron 1.5+ で対応(参考: https://github.com/citusdata/pg_cron )
  $$
  SELECT net.http_post(
    url := 'https://xxx.supabase.co/functions/v1/poll-image-jobs',
    headers := jsonb_build_object('Authorization', 'Bearer ' || current_setting('app.service_role_key'))
  );
  $$
);

注: サブ秒 cron(6 フィールド形式)は pg_cron 1.5 以降で対応しています(Supabase は有効化済み)。古いバージョンの自前環境では 5 フィールド(* * * * *=毎分)までしか動きません。

net.http_post は fire-and-forget です。リクエストを投げるだけで HTTP レスポンスを確認しません。Edge Function が 546 を返そうが 500 を返そうが、pg_cron 的にはジョブは正常に完了したことになります。

SELECT status, count(*) FROM cron.job_run_details
WHERE command LIKE '%poll-image-jobs%'
  AND start_time > '2026-04-21T00:00:00Z'
GROUP BY status;

結果は全て succeeded。このテーブルを見るだけでは異常に気づけません。

盲点 2: フロントエンドの Sentry ではほぼ拾えない

pg_cron からの呼び出しは ブラウザを経由しない ので、ブラウザで動く Sentry / GlitchTip には一切記録されません。たまにユーザーがフロントから直接叩いたケースで少数の 546 が記録されていただけで、これで「数件しか出ていない」と錯覚しました。

盲点 3: バックエンド Sentry (withSentry ラッパー) も機能しない

Edge Function 内部で Sentry に送る実装はこうなっていました。

export const withSentry = (handler) => async (req) => {
  try {
    const res = await handler(req);
    if (res.status >= 500) {
      Sentry.captureMessage(`HTTP ${res.status}`, { level: 'error' });
    }
    return res;
  } catch (e) {
    Sentry.captureException(e);
    throw e;
  }
};

これが効くのは Edge Function のコードが正常に走って 5xx を返した場合 だけです。546 の実体は Supabase 側のスーパーバイザが isolate を強制終了して返すものなので、Edge Function のコード自体が実行を終えられず、Sentry.captureMessage のラインに辿り着けません。バックエンド Sentry もほぼ沈黙でした。

盲点 4: Deno.memoryUsage() では検知できない

前述の通り V8 heap しか見えないので、ネイティブメモリ枯渇は計測できません。ログに heap=12MB と書いてあっても、実際のプロセスメモリは 250MB ということが普通にあります。

盲点 5: function_logs は見に行かないと気付けない

Supabase Analytics のダッシュボードには表示されていたので、意識的に見れば気付けました。ただし:

  • CLI / API で取得する場合は iso_timestamp_start/end の指定が必須。省略すると直近数件しか見えない
  • 定期的に自動でチェックする仕組みがなかった
  • function_logs はアプリ層の異常とは扱いが切り離されていて、アラート経路に乗っていなかった

結果として「Supabase は正常に見えるし、フロント Sentry も静か」という状況で、17時間誰も気づけませんでした。

対策

対策は大きく「コード側」と「監視側」の両面で入れました。

対策 1: バッチサイズを小さくする

一番効いた対策です。12枚を一度に処理せず、3〜4枚ずつに分けました。

// Before: 12枚を Promise.all
const results = await Promise.all(items.map(processItem));

// After: 3枚ずつバッチ処理
const BATCH_SIZE = 3;
const results = [];
for (let i = 0; i < items.length; i += BATCH_SIZE) {
  const batch = items.slice(i, i + BATCH_SIZE);
  const batchResults = await Promise.all(batch.map(processItem));
  results.push(...batchResults);
}

ポイントは Promise.all の引数を 小さい配列に区切る こと。並列数を抑えることでピークメモリが下がります。

対策 2: 1ループごとに参照を切る

base64 文字列のような大きいデータは デコード後に元参照を切る ことでネイティブメモリ側を早く GC 対象にできます。

// Before
const b64 = await response.text();   // 数十 MB
const bytes = base64Decode(b64);
const blob = new Blob([bytes]);
await uploadToStorage(blob);
// → 関数終了まで b64, bytes, blob が全部メモリに残る

// After
{
  const b64 = await response.text();
  const bytes = base64Decode(b64);
  const blob = new Blob([bytes]);
  await uploadToStorage(blob);
}
// ブロックスコープを抜けた時点で参照が切れる

V8 の最適化次第では let のままでも関数途中で回収されることはありますが、タイミング保証がない のが厄介な点です。明示的にブロックで区切っておけば「少なくともブロックを抜けた時点では参照が消えている」という状態が作れるので、メモリ圧が高いときに効くことがあります(ネイティブ側バッファの解放は GC タイミング依存なので万能ではありません)。

対策 3: pg_cron のレスポンスをちゃんと監視する

pg_net は net._http_response テーブルに HTTP レスポンスを記録するので、これを定期チェックする関数を追加しました。

-- 過去1時間の pg_net レスポンスから poll-image-jobs を集計
-- (pg_net 0.14 で動作確認。カラム名・ID の紐付け方はバージョンで差があるので注意)
SELECT
  COUNT(*) FILTER (WHERE status_code = 200) AS success,
  COUNT(*) FILTER (WHERE status_code = 546) AS memory_exceeded,
  COUNT(*) FILTER (WHERE status_code >= 500 AND status_code != 546) AS other_5xx
FROM net._http_response
WHERE created > NOW() - INTERVAL '1 hour'
  AND (content ->> 'url') LIKE '%poll-image-jobs%';

注: pg_net はバージョンによって _http_response のカラム構成や http_request_queue との紐付けカラム名が異なります。http_request_queue を JOIN する場合は手元の pg_net バージョンで必ず \d+ net._http_response を確認してください。上の例は「どのバージョンでも動きやすい、単体テーブル集計」寄りに書いてあります。

一定割合以上が 546 なら Slack 通知するよう CI で定期実行しています。

対策 4: image_jobs.last_polled_at による死活監視

「Edge Function が動いているか」ではなく「DB の状態が進行しているか」を見る方が確実、と結論しました。

-- 30分以上更新されていない running ジョブ = 異常
SELECT id, created_at, last_polled_at
FROM image_jobs
WHERE status = 'running'
  AND last_polled_at < NOW() - INTERVAL '30 minutes';

これが 1件でも出たら人間に通知。実行自体は軽いので pg_cron で 1分おきに流しています。

対策 5: 多層のエラー監視

最終的にエラー検知を 3層 に分けました。

層 内容 検知するもの
1 フロント Sentry UI 側の例外
2 バックエンド Sentry Edge Function 内部の 5xx / キャッチ済み例外
3 Supabase function_logs 定期監査 Supabase 側で isolate が死ぬタイプのエラー

3 が今回抜けていた層です。function_logs を 5分おきに集計して、Memory limit exceeded / Wall clock time exceeded の件数が急増したらアラートを上げるようにしました。

教訓

長くなったのでまとめます。

  1. Supabase Edge Functions のメモリ 256MB 上限は V8 heap ではなく isolate プロセス全体 。Deno.memoryUsage() では見えないネイティブメモリ (ArrayBuffer、Blob、TextDecoder バッファ、fetch 受信バッファ) が乗ることを忘れない
  2. Promise.all で大きいペイロードを並列処理しない。バッチ処理するかストリームで逐次処理する
  3. pg_cron + Edge Function の組み合わせは既存の監視で検知できない。cron.job_run_details は fire-and-forget で HTTP ステータスを見ないし、フロント Sentry には pg_cron 経由の呼び出しが来ないし、Supabase 側で isolate が kill されるとバックエンド Sentry も通らない
  4. 546 の原因は推測ではなくログで確定させる。Wall Clock / Memory / CPU のどれかは function_logs の event_message を見れば一発で分かる。推測だと別の対策をして時間を溶かす
  5. image_jobs のような進行状況テーブルの last_polled_at 死活監視 は最後の砦として便利。Edge Function の生死を外から確認できる

おまけ: よくある Wall Clock 枯渇説は今回当たらなかった

Supabase Edge Functions で 546 の話題を調べると「Wall Clock (isolate 寿命 400秒) を使い切った」という説明が一番多いです。実際そのパターンも存在するはずですが、今回は function_logs の Wall clock time exceeded は 0件 で、完全にメモリ枯渇でした。

function_logs を確認しないまま「Wall Clock だろう」と推測して EdgeRuntime.waitUntil を使ったり非同期化したりする対策を入れると、メモリ問題には効かないので根本解決しません。まずはログを見る、これが今回の一番の教訓かもしれません。

同じ症状を踏んだ誰かの時間短縮に繋がれば幸いです。

参考リンク

0
0
0

Register as a new user and use Qiita more conveniently

  1. You get articles that match your needs
  2. You can efficiently read back useful information
  3. You can use dark theme
What you can do with signing up
Sign upLogin
0
0

Delete article

Deleted articles cannot be recovered.

Draft of this article would be also deleted.

Are you sure you want to delete this article?