Incident — Deadlock Production

Deadlock production: đọc graph trong log để tìm thứ tự lock, và vì sao retry chỉ là giảm triệu chứng

Một incident deadlock production hiếm khi là "một transaction chết". Nó là pattern lặp: pg_stat_database.deadlocks tăng đều mỗi phút, error tracker ngập SQLSTATE 40P01, retry layer ăn hết capacity connection pool, latency P99 nhảy vì mỗi request phải đợi deadlock_timeout một lần trước khi được retry. Root cause gần như luôn là hai code path chạm cùng tập row (hoặc row + FK cha) theo thứ tự khác nhau — và team đã "xử" bằng cách bọc mọi transaction trong một wrapper retry_on_deadlock. Retry hấp thụ được lỗi tức thời (user không thấy 500), nhưng nó không xoá cycle — cùng workload, cùng thứ tự lock sai, deadlock counter cứ leo, và một ngày traffic spike đủ cao thì retry storm biến Postgres thành máy chạy wait-for graph algorithm thay vì chạy query. Bài này tập trung vào cách xử một incident deadlock đã ở production: đọc deadlock graph trong log để reconstruct thứ tự lock, phân biệt "sửa được ở app" với "phải sửa ở schema/workflow", và vì sao retry-only là anti-pattern cần escalate.

Cơ chế hoạt động

Postgres không log deadlock đầy đủ mặc định. Khi cycle bị phát hiện, backend thua cuộc luôn ném ERROR: deadlock detected với SQLSTATE 40P01 và một block DETAIL mô tả graph — đây là artifact duy nhất để reconstruct incident sau khi transaction đã rollback. Format cố định qua các version Postgres hiện đại:

ERROR:  deadlock detected
DETAIL:  Process 12345 waits for ShareLock on transaction 9876; blocked by process 12399.
         Process 12399 waits for ShareLock on transaction 9877; blocked by process 12345.
         Process 12345: UPDATE orders SET total = total + $1 WHERE id = $2
         Process 12399: UPDATE order_items SET qty = qty + $1 WHERE order_id = $2
HINT:  See server log for query details.
CONTEXT: while updating tuple (5,12) in relation "orders"
STATEMENT: UPDATE order_items SET qty = qty + $1 WHERE order_id = $2

Đọc block này như một graph có hướng: mỗi dòng Process X waits for ... blocked by Y là một cạnh X → Y. Cycle 2-node có 2 dòng, cycle 3-node có 3 dòng. Query cuối mỗi Process là query đang chạy tại thời điểm bị chặn — không phải query đã lấy lock trước đó. Đây là bẫy đọc log số 1: Process 12345: UPDATE orders ... nghĩa là "process 12345 đang cố chạy UPDATE orders và bị block", không nghĩa là "process 12345 đang giữ lock trên orders". Muốn biết process 12345 đã lấy lock gì trước đó phải scroll lên phía trên trong log để tìm các statement earlier của cùng pid (nhờ %p trong log_line_prefix) hoặc từ APM trace cùng transaction.

Với log_lock_waits = on, mỗi backend còn in ra dòng LOG: process X still waiting for LockMode on ... sau khi vượt deadlock_timeout. Kèm log_line_prefix = '%m [%p] %a %u@%d ' để có timestamp, pid, application_name, user, database — đủ để join deadlock event với service/endpoint. Không có ba GUC này bật trước khi incident xảy ra, log deadlock gần như vô dụng cho post-mortem — chỉ biết "có xảy ra", không biết ai lock gì.

Vấn đề gặp trong production

Failure mode 1: retry-only wrapper giấu lỗi thay vì sửa. Pattern lặp: team gặp 40P01 sporadic → thêm middleware/decorator @retry_on_deadlock(max=5) → error tracker im, incident đóng. Vài tuần sau, pg_stat_database.deadlocks đã tăng vài chục lần/phút, chưa ai để ý vì không còn 5xx nào phơi lên user. Rồi một đợt promo traffic tăng nhiều lần, hàng loạt request đồng thời đâm vào cùng row hot (order id, seat id, inventory id), retry đua nhau tạo cycle mới:

# Sai: retry hấp thụ triệu chứng, không sửa nguyên nhân
@retry(on=DeadlockDetected, max_attempts=5, backoff=0.01)
def reserve_seat(user_id, event_id, seat_id):
    with conn.transaction():
        # Không lock theo thứ tự cố định — thứ tự lock phụ thuộc user_id/seat_id runtime
        conn.execute("UPDATE users SET credits = credits - 1 WHERE id = %s", (user_id,))
        conn.execute("UPDATE seats  SET holder  = %s     WHERE id = %s", (user_id, seat_id))

Hai request đảo user/seat có thể tạo cycle nếu FK từ seats.holder tới users.id gây implicit FOR KEY SHARE (xem failure mode 3). Retry với backoff 10ms tái tạo cycle gần như tức thì; deadlock_timeout (mặc định 1s) cộng dồn mỗi vòng retry — request vài ms thành vài giây. Fix thật là chuẩn hoá thứ tự truy cập tài nguyên: sort id hoặc pin theo entity chính:

# Đúng: chuẩn hoá thứ tự lock trước khi update
def reserve_seat(user_id, event_id, seat_id):
    with conn.transaction():
        # Lock cả hai row theo thứ tự deterministic (ví dụ: seats trước, users sau) —
        # mọi code path đụng cùng cặp bảng đều tuân cùng thứ tự này.
        conn.execute("SELECT 1 FROM seats WHERE id = %s FOR UPDATE", (seat_id,))
        conn.execute("SELECT 1 FROM users WHERE id = %s FOR UPDATE", (user_id,))
        conn.execute("UPDATE users SET credits = credits - 1 WHERE id = %s", (user_id,))
        conn.execute("UPDATE seats SET holder  = %s     WHERE id = %s", (user_id, seat_id))

Retry vẫn giữ nhưng chỉ để hấp thụ deadlock class không khử được (multi-table workflow phức tạp, FK race), phải có exponential backoff và cap. Rule cứng cho code review: không merge một retry-on-deadlock wrapper nếu chưa có ticket điều tra thứ tự lock.

Failure mode 2: bulk UPDATE/DELETE không deterministic order. Executor Postgres không cam kết thứ tự row trong một UPDATE ... WHERE region = 'VN' — plan có thể là seq scan, index scan, bitmap heap scan tuỳ statistics. Hai job cron chạy song song trên cùng tập row với plan khác nhau lock các row theo thứ tự khác nhau, deadlock random dưới load:

-- Sai: hai bulk update không đảm bảo cùng row order
UPDATE accounts SET fee = fee + 1 WHERE region = 'VN';   -- job A
UPDATE accounts SET fee = fee + 2 WHERE region = 'VN';   -- job B, song song

Fix: ép order bằng CTE FOR UPDATE:

WITH locked AS (
  SELECT id FROM accounts WHERE region = 'VN' ORDER BY id FOR UPDATE
)
UPDATE accounts SET fee = fee + 1 WHERE id IN (SELECT id FROM locked);

Class deadlock này thường xuất hiện sau khi thêm partial index hoặc statistics thay đổi làm planner đổi plan — pattern lock sai vẫn ở đó từ ngày đầu, chỉ chưa "vỡ" vì plan cũ tình cờ deterministic.

Failure mode 3: foreign key implicit lock. INSERT hoặc UPDATE row con làm Postgres tự lấy FOR KEY SHARE trên row cha (chống cha bị xoá/đổi PK trong lúc con reference). Class này tinh vi vì code "không hề lock cha rõ ràng":

-- Transaction A
INSERT INTO order_items(order_id, sku, qty) VALUES (1001, 'X', 2);
-- Postgres âm thầm lấy FOR KEY SHARE trên orders.id = 1001
UPDATE orders SET total = total + 20 WHERE id = 1001;
-- Nâng lock cha lên KEY UPDATE

-- Transaction B chạy đảo thứ tự
UPDATE orders SET total = total + 20 WHERE id = 1001;
-- KEY UPDATE trên orders.id = 1001
INSERT INTO order_items(order_id, sku, qty) VALUES (1001, 'Y', 3);
-- Đợi A nhả FOR KEY SHARE → A giờ đợi B nhả KEY UPDATE → cycle

Trong log, dấu vết là ShareLock on transaction NNN (không phải row-level explicit lock) và query cuối là hoặc INSERT hoặc UPDATE orders — hai statement nhìn "không liên quan gì đến khoá cha". Fix: trong workflow đụng cả cha và con, lock cha rõ ràng trước (SELECT ... FROM orders WHERE id = $1 FOR NO KEY UPDATE) trước khi INSERT con. Hoặc gộp workflow thành một SQL function/CTE để Postgres tự sắp xếp.

Failure mode 4: DDL migration chạy giữa peak. ALTER TABLE ... ADD COLUMN ... cần ACCESS EXCLUSIVE trên bảng — block mọi lock khác. Nếu bảng đang có DML in-flight, DDL vào queue chờ; DML mới đến phía sau DDL cũng bị chặn (Postgres lock queue là FIFO). Kèm tương tác với FK lock trên bảng phụ thuộc, có thể tạo cycle qua nhiều bảng. Class này hay xuất hiện trong migration chạy live không có lock_timeout. Fix: mọi migration DDL bắt đầu bằng SET lock_timeout = '2s'; SET statement_timeout = '5s'; để fail nhanh thay vì kẹt hàng đợi; schedule migration ngoài peak; dùng CREATE INDEX CONCURRENTLY hoặc pattern tương đương cho các thao tác cần lock nhẹ.

Cách debug và monitor

Triệu chứng deadlock production khác lock contention thường: contention làm latency tăng đều tỉ lệ với load, không có error code; deadlock ném 40P01 rời rạc, mỗi lần đúng một transaction rollback, và pattern lặp lại. Khi được page vì deadlock incident:

Bước 1 — xác nhận đang xảy ra hay đã qua. Query counter:

SELECT datname, deadlocks, stats_reset
FROM pg_stat_database
WHERE datname NOT IN ('template0','template1');

So delta với snapshot 5 phút trước (Grafana hoặc metric store). Delta > 0 và đang tăng = active. Delta ổn định = incident đã kết thúc, giờ là điều tra post-mortem.

Bước 2 — nhặt vài mẫu deadlock graph gần nhất từ log. Grep tuỳ log pipeline:

# Nếu log ra stderr container:
docker logs pg 2>&1 | grep -A 12 'deadlock detected' | tail -80

# Log file trên VM/host:
grep -A 12 'deadlock detected' /var/log/postgresql/postgresql-*.log | tail -80

Mỗi block deadlock có DETAIL: liệt kê các cạnh của cycle, STATEMENT: là query của victim, CONTEXT: while updating tuple ... chỉ ra bảng/tuple bị chặn cuối cùng. Nếu log_lock_waits = on, phía trước còn có LOG: process X still waiting for ... after ... ms cho cả hai process — dùng dòng này để biết lock mode và lock object trước khi cycle hình thành.

Bước 3 — reconstruct thứ tự lock. Với mỗi process trong graph, grep tất cả statement cùng pid trong window vài giây trước deadlock:

grep '\[12345\]' /var/log/postgresql/postgresql-*.log | tail -50
grep '\[12399\]' /var/log/postgresql/postgresql-*.log | tail -50

Ghép thành timeline: process 12345 đã UPDATE seats trước, rồi bị treo tại UPDATE users; process 12399 đã UPDATE users trước rồi treo tại UPDATE seats → thứ tự lock ngược nhau. Đây là output cần đưa vào post-mortem, không phải chỉ dòng ERROR: deadlock detected.

Bước 4 — quan sát cycle live (nếu vẫn đang xảy ra). Tạm tăng deadlock_timeout để có thời gian query trước khi Postgres cắt:

SET deadlock_timeout = '10s';  -- session-level, không ảnh hưởng backend khác

Rồi ở session monitor:

SELECT a.pid, a.application_name, a.wait_event_type, a.wait_event,
       pg_blocking_pids(a.pid) AS blocked_by,
       now() - a.xact_start    AS xact_age,
       left(a.query, 200)      AS query
FROM pg_stat_activity a
WHERE a.backend_type = 'client backend'
  AND a.wait_event_type = 'Lock'
ORDER BY xact_age DESC;

pg_blocking_pids(a.pid) trả về mảng các pid đang chặn a.pid. Cycle 2-node = pid X có blocked_by = {Y} và pid Y có blocked_by = {X}.

Monitoring dài hạn. Alert trên pg_stat_database_deadlocks (metric name qua postgres_exporter cho Prometheus, hoặc equivalent trong Datadog, pganalyze, AWS Performance Insights — tất cả đều wrap counter gốc). Rule thực tế: alert khi rate over 5m > 0 trên database production, treat như incident chứ không như noise — vì chuẩn hoá thứ tự lock là việc làm được, không có deadlock nào "chấp nhận được" trong steady state.

Rule phòng ngừa. log_lock_waits = on và log_line_prefix giàu context luôn bật; deadlock_timeout giữ mặc định (giảm ép Postgres chạy graph algo thường xuyên → tốn CPU, tăng làm transaction kẹt lâu); DDL migration set lock_timeout ngắn; mọi retry-on-deadlock wrapper phải có cap + exponential backoff + alert khi retry rate vượt ngưỡng — không có wrapper "vô hạn".

Tradeoff

Retry-only vs sửa root cause là tradeoff thời gian trước mắt vs nợ kỹ thuật cộng dồn. Retry-only triển khai được trong một PR, hấp thụ ngay lỗi user-visible, không cần đọc lock semantics — nhưng nó ẩn metric (nếu deadlock được swallow trước khi log ra APM), kéo dài P99 mỗi lần cycle xảy ra (cộng thêm khoảng deadlock_timeout), và dưới traffic spike có thể tạo retry storm đè CPU database vào wait-for graph algorithm. Chuẩn hoá thứ tự lock đòi hỏi hiểu toàn bộ code path đụng cùng tập tài nguyên (thường xuyên hơn dev tưởng, vì FK implicit lock kéo theo cả các bảng "không được nhắc"), tốn thời gian audit và test — nhưng sau khi làm, deadlock counter về ~0 và không cần retry giấu lỗi.

Ngưỡng dùng retry (có giới hạn) hợp lý là class deadlock không khử được ở app: multi-table workflow phức tạp, race giữa DDL và DML trong migration window, contention trên hot row không thể serialize triệt để. Ngưỡng phải sửa logic là class deterministic: transfer(a, b) lock theo argument order, bulk update không ORDER BY, INSERT con + UPDATE cha xen kẽ. Nếu deadlock rate không giảm sau khi chỉnh retry parameters, đó là dấu hiệu chắc chắn thuộc class thứ hai.

Quy tắc thực tế: chuẩn hoá thứ tự lock ở application để deadlock không xảy ra là default; retry (có cap + exponential backoff) chỉ để hấp thụ phần dư; alert trên pg_stat_database.deadlocks > 0 để biết còn class chưa fix; không dùng retry vô hạn hoặc retry-not-logged để giấu incident khỏi metric.

Câu hỏi phỏng vấn

Deadlock production xử lý thế nào — nhận log, tìm cycle, sửa, phòng?

Bước 1, xác nhận đang active hay đã qua: query pg_stat_database.deadlocks so với baseline vài phút trước. Delta > 0 và đang tăng = active. Bước 2, nhặt vài mẫu deadlock graph gần nhất từ log Postgres — grep deadlock detected kèm 10-12 dòng phía sau để lấy block DETAIL: Process X waits for ... blocked by Y. Process Y waits for ... blocked by X. cùng STATEMENT và CONTEXT. Mỗi dòng waits for ... blocked by là một cạnh của graph có hướng; cycle 2-node có 2 dòng, 3-node có 3 dòng. Bẫy đọc log: query in ra cạnh mỗi Process là query đang bị chặn, không phải query đã giữ lock — muốn biết lock giữ trước đó phải grep các statement cùng pid trong log (nhờ %p trong log_line_prefix) hoặc từ APM trace cùng transaction. Bước 3, reconstruct thứ tự lock: nếu process A đã UPDATE seats rồi treo tại UPDATE users, process B đã UPDATE users rồi treo tại UPDATE seats — thứ tự lock ngược nhau, class deterministic, fix bằng chuẩn hoá thứ tự lock ở application (sort id, pin theo entity chính, lock cha trước con rõ ràng). Bước 4, phòng ngừa dài hạn: bật log_lock_waits = on, log_line_prefix giàu context; alert pg_stat_database.deadlocks rate > 0 treat như incident; mọi retry-on-deadlock wrapper có cap + exponential backoff, không vô hạn.

Vì sao "chỉ retry" là anti-pattern: retry hấp thụ lỗi user-visible ngay nhưng không xoá cycle — cùng workload cùng thứ tự lock sai vẫn tái tạo deadlock, mỗi vòng cộng deadlock_timeout (mặc định 1s) vào latency, request vài ms biến thành vài giây. Không có backoff, dưới traffic spike các retry đua nhau tạo cycle mới, CPU database burn vào chạy wait-for graph algorithm thay vì query thật. Retry cũng ẩn metric nếu deadlock được swallow trước khi log ra APM — pg_stat_database.deadlocks leo thang mà không ai biết. Điểm ăn điểm là gọi tên SQLSTATE 40P01 cùng counter pg_stat_database.deadlocks và hàm pg_blocking_pids(), giải thích được cách đọc block DETAIL như một graph, phân biệt được class "sửa được ở app" (deterministic lock order) với class "phải giữ retry" (FK implicit lock, DDL race), và nói được vì sao retry-only kéo dài P99 và có thể gây retry storm dưới spike.

Hands-on

Mục tiêu: tái hiện một deadlock production, đọc log graph để reconstruct thứ tự lock, đo counter tăng, thử fix bằng chuẩn hoá thứ tự và so sánh trước/sau.

Dựng container với logging đầy đủ:

docker run -d --name pg-inc \
  -e POSTGRES_PASSWORD=pw -p 5440:5432 \
  postgres:16 \
  -c log_lock_waits=on \
  -c deadlock_timeout=1s \
  -c log_line_prefix='%m [%p] %a %u@%d '
sleep 5
docker exec -i pg-inc psql -U postgres <<'SQL'
CREATE TABLE users (
  id   bigint PRIMARY KEY,
  name text NOT NULL,
  credits int NOT NULL DEFAULT 100
);
CREATE TABLE seats (
  id     bigint PRIMARY KEY,
  event  text NOT NULL,
  holder bigint REFERENCES users(id)
);
INSERT INTO users VALUES (1,'alice'),(2,'bob');
INSERT INTO seats VALUES (10,'concert',NULL),(11,'concert',NULL);
SQL

Bước 1 — tái hiện deadlock 2-node. Mở 2 session:

docker exec -it pg-inc psql "postgresql://postgres:pw@localhost/postgres?application_name=sessA"
docker exec -it pg-inc psql "postgresql://postgres:pw@localhost/postgres?application_name=sessB"

Chạy xen kẽ (thứ tự lock ngược nhau):

-- sessA:
BEGIN;
UPDATE seats SET holder = 1 WHERE id = 10;   -- lock seat 10

-- sessB:
BEGIN;
UPDATE seats SET holder = 2 WHERE id = 11;   -- lock seat 11
UPDATE seats SET holder = 2 WHERE id = 10;   -- treo, đợi sessA

-- sessA (trong khi sessB đang treo):
UPDATE seats SET holder = 1 WHERE id = 11;   -- cycle hình thành

Sau khoảng deadlock_timeout (~1s), một session nhận ERROR: deadlock detected.

Bước 2 — đọc log để phân tích graph.

docker logs pg-inc 2>&1 | grep -B 1 -A 12 'deadlock detected' | tail -40

Xác định: bao nhiêu dòng waits for ... blocked by ... (chính là size của cycle); với mỗi Process, STATEMENT chỉ query đang bị chặn (không phải query đã lấy lock); CONTEXT: while updating tuple (block,offset) in relation "X" chỉ chính xác tuple đang bị chặn cuối.

Bước 3 — reconstruct thứ tự lock cho mỗi process. Lấy pid từ block DETAIL (ví dụ 12345 và 12399), grep từng pid:

docker logs pg-inc 2>&1 | grep '\[12345\]' | tail -20
docker logs pg-inc 2>&1 | grep '\[12399\]' | tail -20

Ghép timeline: pid 12345 đã UPDATE ... id = 10 rồi treo tại UPDATE ... id = 11; pid 12399 làm ngược lại → class "deterministic sai thứ tự", fix được ở app.

Bước 4 — kiểm chứng counter tăng.

SELECT datname, deadlocks FROM pg_stat_database WHERE datname='postgres';

Chạy lại Bước 1 vài lần, counter tăng đúng số lần deadlock.

Bước 5 — mô phỏng retry-only anti-pattern. Script hai chiều ngược nhau chạy song song với retry mù, không sửa thứ tự:

cat > /tmp/retry_only.py <<'PY'
import psycopg2, sys, time
conn = psycopg2.connect(
    "postgresql://postgres:pw@localhost:5440/postgres",
    application_name=sys.argv[1],
)
conn.autocommit = False
cur = conn.cursor()
a, b = int(sys.argv[2]), int(sys.argv[3])
holder = int(sys.argv[4])
success, deadlocks = 0, 0
for _ in range(200):
    try:
        cur.execute("UPDATE seats SET holder = %s WHERE id = %s", (holder, a))
        cur.execute("UPDATE seats SET holder = %s WHERE id = %s", (holder, b))
        conn.commit()
        success += 1
    except psycopg2.errors.DeadlockDetected:
        conn.rollback()
        deadlocks += 1
        time.sleep(0.005)   # backoff quá ngắn, không sửa cycle
print(f"{sys.argv[1]}: ok={success} deadlocks={deadlocks}")
PY

python3 /tmp/retry_only.py A 10 11 1 &
python3 /tmp/retry_only.py B 11 10 2 &
wait

docker exec -i pg-inc psql -U postgres -c \
  "SELECT datname, deadlocks FROM pg_stat_database WHERE datname='postgres';"

Counter deadlocks nhảy nhiều lần — chứng minh retry không sửa root cause, chỉ làm Postgres liên tục dò cycle.

Bước 6 — fix bằng chuẩn hoá thứ tự lock. Sửa script để lock theo id tăng dần trước khi update:

cat > /tmp/fixed_order.py <<'PY'
import psycopg2, sys, time
conn = psycopg2.connect(
    "postgresql://postgres:pw@localhost:5440/postgres",
    application_name=sys.argv[1],
)
conn.autocommit = False
cur = conn.cursor()
a, b = int(sys.argv[2]), int(sys.argv[3])
holder = int(sys.argv[4])
lo, hi = sorted((a, b))
success, deadlocks = 0, 0
for attempt in range(200):
    try:
        cur.execute("SELECT id FROM seats WHERE id IN (%s,%s) ORDER BY id FOR UPDATE",
                    (lo, hi))
        cur.execute("UPDATE seats SET holder = %s WHERE id = %s", (holder, a))
        cur.execute("UPDATE seats SET holder = %s WHERE id = %s", (holder, b))
        conn.commit()
        success += 1
    except psycopg2.errors.DeadlockDetected:
        conn.rollback()
        deadlocks += 1
        time.sleep(0.05 * (2 ** min(attempt, 5)))   # exponential backoff, cap
print(f"{sys.argv[1]}: ok={success} deadlocks={deadlocks}")
PY

docker exec -i pg-inc psql -U postgres -c "SELECT pg_stat_reset();"

python3 /tmp/fixed_order.py A 10 11 1 &
python3 /tmp/fixed_order.py B 11 10 2 &
wait

docker exec -i pg-inc psql -U postgres -c \
  "SELECT datname, deadlocks FROM pg_stat_database WHERE datname='postgres';"

Counter về ~0 (chỉ còn deadlock lẻ nếu có FK/hot-row contention khác), retry gần như không kích hoạt.

Dọn dẹp: docker rm -f pg-inc && rm -f /tmp/retry_only.py /tmp/fixed_order.py.