Rebounder Tech Blog

運用している当事者が書く、本番システムの記録。

audit_logのadvisory lockとUPDATE順序が作る新しいデッドロック窓

公開 読了時間 約10分執筆: Rebounder 開発チーム(当該システムの運用当事者)

※本記事にはアフィリエイトリンクを含む場合があります。内容は広告の有無に影響されません。

結論

audit_logのBEFORE INSERTトリガがhash chain直列化のためpg_advisory_xact_lockをcommitまで保持しているところへ、ads UPDATEの直後に監査INSERTを挟む構成を重ねると、advisory lock取得後に別トランザクションの行ロックを待つ循環ができ40P01デッドロックが起きる。

結論

改ざん検知用hash chainを1本に直列化するadvisory lockは、トランザクションのcommitまで保持される。 audit_logのBEFORE INSERTトリガ(migration 0003)は、並行INSERTの競合を避けるためpg_advisory_xact_lock(hashtext('audit_log')::bigint)を取得し、そのトランザクションが終わるまで離さない設計になっている。一方、portal配信の反映処理(applyPartnerDelivery)は、配信対象から外れた・戻った広告の監査記録を「ads UPDATE → 監査INSERT(advisory lock取得)→ 次のplacementのads UPDATE」という順で、placementごとに複数回挟み込んでいた。この処理が、運営画面の広告一時停止操作(これも「ads UPDATE → 監査INSERT」という同型の処理)と並行して走り、互いが先に更新した行を後から要求し合う順序になると、advisory lockを取得した側が相手の行ロックを待ち、相手はadvisory lockの解放を待つという循環ができ、PostgreSQLが40P01(deadlock detected)を検出して一方を強制終了させていた。直し方は、監査INSERTの呼び出しを対象の行UPDATEがすべて終わった後ろへ1本に集約すること。

症状

portal(学校向け営業支援システム)から送られてくる広告配信の反映は、partner-delivery.tsのapplyPartnerDeliveryが担う。配信対象の学校集合が変わると、対象から外れた広告行は物理削除ではなくads.retired_atを立てて残し(過去の表示実測をAPIから引けなくするK1事故の再発防止のため、2026-09-14に物理DELETEから変更済み)、対象に戻った広告行はretired_atをnullに戻す。この「外れた(retire)」「戻った(revive)」という変化は、1件ごとにaudit_logへ監査行として記録される。

// partner-delivery.ts(e0a9d22b時点、修正前)
for (const [placementId, adIds] of deliveredAdIdsByPlacement) {
  const revived = await tx
    .update(ads)
    .set({ retiredAt: null, updatedAt: new Date(), updatedBy: null })
    .where(and(inArray(ads.id, adIds), isNotNull(ads.retiredAt)))
    .returning({ id: ads.id, schoolId: ads.schoolId });
  await writeScopeAudit(tx, revived, {
    portalPlacementId: placementId,
    change: "revive",
    retiredAt: null,
  });
}
// ...4. retire も同型で、placementごとに UPDATE の直後へ writeScopeAudit を呼ぶ

配信対象のplacementが複数あると、このUPDATE→監査INSERTのペアが1トランザクション内で複数回連続する。単独で流れている間は問題にならないが、運営画面から広告の一時停止・再開を操作すると、そちらも同じadsテーブルへのUPDATEと監査INSERTのペアを実行する。

// operator-ads-actions.ts(e0a9d22b時点、修正前)
await tx
  .update(ads)
  .set({ isPaused: paused, updatedBy: actorRef, updatedAt: new Date() })
  .where(and(eq(ads.id, adId), isNotNull(ads.advertiserId)));
await writeAudit(tx, {
  actor: user,
  schoolId: target.schoolId,
  recordId: adId,
  operation: "update",
  diff: { before: { isPaused: target.isPaused }, after: { isPaused: paused } },
});

portal配信の反映と運営の一時停止操作が重なったとき、まれに一方のトランザクションが40P01: deadlock detectedで中断される、という報告がReviewer指摘(PR #1385)で上がった。

原因

audit_logのBEFORE INSERTトリガは、hash chainを1本の連番として保つために、テーブル全体に対する固定キーのadvisory lockを使っている。

-- 0003_audit_trigger.sql(69-107行、変更なし)
-- chain を直列化(audit_log のテーブル単位 advisory lock)
PERFORM pg_advisory_xact_lock(hashtext('audit_log')::bigint);

pg_advisory_xact_lockはトランザクションスコープのロックで、COMMITまたはROLLBACKまで自動的には解放されない。つまりaudit_logへ1行INSERTした時点で、そのトランザクションは「commitするまでこの固定キーのロックを握り続ける」状態になる。

ここに、修正前のapplyPartnerDeliveryとsetOperatorAdPausedActionが共有していた「ads UPDATE → 監査INSERT」という順序が重なる。2つのトランザクションT1・T2が次のように進んだ場合を考える。

  • T1(portal配信、placement A→Bの順で処理): ads行AをUPDATE(行Aのロック取得)→ 監査INSERT(advisory lock取得)→ ads行BをUPDATE(行Bのロックを要求、T2が保持中なら待つ)
  • T2(運営の一時停止、行Bを対象): ads行BをUPDATE(行Bのロック取得)→ 監査INSERT(advisory lockを要求、T1が保持中なら待つ)

T1はadvisory lockを取得済みのまま行Bのロックを待ち、T2は行Bのロックを取得済みのままadvisory lockを待つ。どちらも相手が先に進まない限り解放できるものを持っておらず、PostgreSQLのデッドロック検出器がこの循環を見つけて片方を40P01で中断する。

この構造の特徴は、advisory lockのキーが'audit_log'というテーブル全体で1本の固定値であることにある。行単位のロックであれば異なる行を触る限り衝突しないが、advisory lockは対象行に関係なく同じキーを取り合うため、「UPDATEの直後に監査INSERTを挟む」という書き方をしているコードが2箇所以上あれば、それぞれが別の行を触っていても、UPDATEとINSERTの順序が互い違いになった瞬間に上記の循環が成立してしまう。

直し方

修正(PR #1385 M1)は、applyPartnerDelivery側の監査書き込みを、対象のplacementすべてのUPDATEが終わるまでバッファし、最後に1回だけ発行する形に変えた。

// partner-delivery.ts(a49eba4b時点、修正後)
// 3.5 / 4 の監査はここに溜め、すべての ads UPDATE が終わってからまとめて書く
const scopeChanges: ScopeChange[] = [];

for (const [placementId, adIds] of deliveredAdIdsByPlacement) {
  const toRevive = await tx
    .select({ id: ads.id, schoolId: ads.schoolId, retiredAt: ads.retiredAt })
    .from(ads)
    .where(and(inArray(ads.id, adIds), isNotNull(ads.retiredAt)));
  if (toRevive.length === 0) continue;
  await tx.update(ads).set({ retiredAt: null, updatedAt: new Date(), updatedBy: null })
    .where(inArray(ads.id, toRevive.map((r) => r.id)));
  for (const r of toRevive) {
    scopeChanges.push({ adId: r.id, schoolId: r.schoolId, portalPlacementId: placementId, change: "revive", before: r.retiredAt, after: null });
  }
}
// ...4. retire も同様に UPDATE だけ行い、scopeChanges へ push するだけに留める

// 5. 監査をまとめて書く(advisory lock を最後に 1 度だけ取る)
await writeScopeAudits(tx, scopeChanges);

ポイントは、writeScopeAudits(旧writeScopeAudit)の呼び出しが、このトランザクションの中で最後に1回だけになったことにある。トランザクションがadvisory lockを取得する時点で、すでに自分が必要とする行ロックはすべて確保し終えている。したがって「advisory lockを持ったまま、まだ取れていない行ロックを待つ」という状態がこの関数の中には構造的に存在しなくなり、前述のT1↔T2の循環が成立しなくなる。

// partner-delivery.ts(a49eba4b時点、writeScopeAuditsのdocコメント)
// ⚠ すべての ads UPDATE が終わってから、最後にまとめて呼ぶこと。
// audit_log の BEFORE INSERT トリガ(migration 0003)は chain 直列化のため
// pg_advisory_xact_lock(hashtext('audit_log')) を取り、commit まで保持する。
// 「ads を UPDATE → 監査 INSERT → 別の ads を UPDATE」と交互に並べると、
// advisory lock を取った後にさらに行ロックを要求する順序になり、
// portal 配送の 2 入口が並行したときにデッドロックしうる(ローカル PG16 で再現)。
// 書き込みを末尾へ寄せれば、advisory lock 取得後に行ロックを待つ tx が
// 存在しなくなり循環が作れない。

このコミットの記録では、2 placementを含むportal配信の反映処理と運営の一時停止操作を並行させるprobeで、修正前は40P01を確実に再現し、修正後は同じprobeを3回×360操作回して0件になったとされている。なお、setOperatorAdPausedAction側は今回のPRでは直されておらず、「UPDATE直後に監査INSERT」という形自体は残っている。今回解消したのはapplyPartnerDelivery側がplacementをまたいでこの形を複数回連続させていた部分で、単発のUPDATE→INSERTだけでは、advisory lock取得後にそのトランザクションが別の行ロックを新たに要求する箇所が無いため、同じ循環は作れない。

再発防止

このバグが成立する条件は、「audit_logへのINSERT(テーブル全体で1本のadvisory lockを要求する)」と「対象行のUPDATE(行ロックを要求する)」が1トランザクション内で2回以上交互に現れることだった。writeScopeAuditsのdocコメントは、この条件を次に同じ関数を触る人に向けて明文化しており、修正の要点は「監査書き込みは、そのトランザクションが行う全UPDATEの後ろに1本化する」という順序の制約として関数のdocに残されている。audit_logへ書く処理を新しく追加する側(本件のようにadsを複数回UPDATEしながら監査を挟む設計)は、advisory lockがテーブル単位の固定キーである以上、対象行に関わらず他の書き込み経路と衝突し得ることを前提に、監査INSERTをトランザクションの末尾へ寄せる設計を踏襲する必要がある。

よくある質問

Q1なぜ監査ログへの書き込みがデッドロックの原因になるのですか?

audit_logのBEFORE INSERTトリガ(migration 0003)が改ざん検知用hash chainを1本に直列化するため、pg_advisory_xact_lockをトランザクションのcommitまで保持する設計になっている。adsのUPDATE直後にこの監査INSERTを挟む処理が複数回あると、advisory lock取得後に別トランザクションが握るads行のロックを待つ状況が作れてしまう。

Q2advisory lockの粒度を細かくすれば直せたのではないですか?

本件の直し方はlockの粒度を変えることではない。監査INSERTを呼ぶ位置を、対象の行UPDATEがすべて終わった後ろへ1回だけ移すこと。advisory lockを取る時点でそのトランザクションはこれ以上行ロックを要求しないため、advisory lockを保持したまま他トランザクションの行ロックを待つ経路自体が作れなくなる。

Q3このデッドロックはどんな操作が重なったときに再現しましたか?

修正コミットの記録によれば、2 placementを含むportal配信の反映処理と、運営画面での広告の一時停止操作を並行させるprobeで、UPDATE→監査INSERT→別UPDATEという順序が交差し40P01(deadlock detected)を再現したとある。修正後は同じprobeを3回×360操作で0件としている。

確認した環境

  • PostgreSQL 16(修正コミットのコードコメントに「ローカル PG16 で再現」と記載)
  • postgres(porsager/postgres)^3.4.5 / drizzle-orm ^0.45.2(packages/db/package.json)
  • 2026-09-14 修正(PR #1385 Reviewer指摘M1)

この記事の根拠

  • SQLファイル 69〜107行目コミット e3d5791
  • TypeScriptファイル 263〜292行目コミット e0a9d22
  • TypeScriptファイル 508〜564行目コミット e0a9d22
  • TypeScriptファイル 264〜274行目コミット e0a9d22
  • TypeScriptファイル 264〜282行目コミット a49eba4
  • TypeScriptファイル 511〜608行目コミット a49eba4
  • TypeScriptファイル 309〜390行目コミット a49eba4

本文の主張は、上の記録に書かれていることだけです。運用しているリポジトリは非公開のため リンクは張れませんが、どのファイルの何行目を、どのコミット時点で見て書いたかは 記事ごとに残しています。推測で書いた箇所はありません。