凌晨两点数据库主从延迟告警，我用 binlog + pt-query-digest 在十分钟内还原了事故链

iceveil

361人浏览 · 2026-04-28 15:06:36

iceveil · 2026-04-28 15:06:36 发布

凌晨两点数据库主从延迟告警，我用 binlog + pt-query-digest 在十分钟内还原了事故链

凌晨两点十七分，手机震醒我的不是闹钟，是 PagerDuty。主从延迟 38 秒，还在涨。我第一反应不是慌张，是兴奋——终于来了个能写进简历的故障。

01 告警来了，但延迟曲线不太对劲

平时主从延迟也就毫秒级，今晚突然飙到 38 秒，而且斜率很陡。这说明不是网络抖动，是某条 SQL 在从库上执行卡住了。

我打开监控面板，确认了两件事：

主库 QPS 没暴涨，排除写入洪峰
从库的 Slave_SQL_Running_State 显示 “Reading event from the relay log”，但 Seconds_Behind_Master 持续增加

经验告诉我，问题大概率是一条大事务或者慢查询，在从库单线程回放时拖住了。

02 先抓 binlog，定位"嫌疑 SQL"

主从复制延迟的本质，是从库 SQL 线程回放速度慢于主库写入速度。要找到元凶，先看主库这段时间写了什么。

我登录主库，用 mysqlbinlog 导出异常时间段的 binlog：

# 找到当前正在写的 binlog 文件
mysql -e "SHOW MASTER STATUS;"

# 导出最近 10 分钟的 binlog（假设当前是 mysql-bin.000123）
mysqlbinlog --start-datetime="2026-04-28 02:07:00" \
  --stop-datetime="2026-04-28 02:17:00" \
  --base64-output=DECODE-ROWS -v \
  /var/lib/mysql/mysql-bin.000123 > /tmp/binlog_02_07_02_17.sql

--base64-output=DECODE-ROWS -v 是关键参数，能把 Row 格式的 binlog 解码成人类可读的 SQL。如果不加，你看到的是一堆 Base64 乱码。

导出的文件有 180MB。我粗略扫了一眼，发现某个表出现了大量 UPDATE 操作，而且 WHERE 条件里没有走索引的迹象。

03 pt-query-digest 出场，10 秒锁定慢查询

binlog 能告诉你"发生了什么"，但 pt-query-digest 能告诉你"什么最慢"。这是 Percona Toolkit 里的神器，我每台 DB 服务器都装了。

我直接把刚才的 binlog 丢给它分析：

pt-query-digest --type=binlog /tmp/binlog_02_07_02_17.sql > /tmp/slow_report.txt

10 秒后，报告出来了。我直接拉到 Profile 段落：

# Rank Query ID           Response time  Calls  R/Call  V/M   Item
# ==== ================== ============== ====== ======= ===== ==========
#    1 0x9F3E...          287.3450s     1      287.35  0.00 UPDATE `user_logs` SET `status`=1 WHERE `created_at` < '2026-04-28 00:00:00'
#    2 0xA1B2...          12.0045s      150    0.0800  0.02 SELECT ...

第一条查询独占 287 秒响应时间，只执行了 1 次。就是它。

04 还原事故链：一条"清理脚本"引发的血案

我顺着 Query ID 往下看 pt-query-digest 的详细分析：

表：user_logs，5000 万行
操作：UPDATE user_logs SET status=1 WHERE created_at < '2026-04-28 00:00:00'
问题：created_at 字段没有索引

这条 SQL 是凌晨 2:00 的定时任务跑的，本意是清理过期日志。但在从库回放时，它要做全表扫描，5000 万行逐行更新，SQL 线程被它独占，后面的 binlog 事件全堵住了。

主库执行这条 SQL 用了 3 分钟（因为有更好的 IO 和缓存），从库硬件差一些，硬生生抽了将近 5 分钟。这就是延迟从 38 秒开始飙升的原因。

05 紧急止血：让从库先追上

找到根因后，我先做了一件反直觉的事：在从库上跳过大事务。

-- 在从库执行
STOP SLAVE;
SET GLOBAL SQL_SLAVE_SKIP_COUNTER = 1;
START SLAVE;

SQL_SLAVE_SKIP_COUNTER = 1 跳过了当前卡住的 GTID 事件，从库 SQL 线程立刻恢复，延迟开始下降。两分钟后，主从同步归零。

但这只是止血。那条 UPDATE 已经部分执行，数据一致性需要修复。

06 根治：给慢查询加索引，改写清理逻辑

第二天白天，我做了三件事：

第一，补索引。

ALTER TABLE user_logs ADD INDEX idx_created_at (created_at);

加了索引后，同样的 WHERE 条件走范围扫描，执行时间从 287 秒降到 0.8 秒。

第二，改写清理脚本。

原来的脚本是一刀切：

UPDATE user_logs SET status=1 WHERE created_at < DATE_SUB(NOW(), INTERVAL 7 DAY);

我改成了批量小事务，每次只处理 1000 行：

# cleanup_script.py
import pymysql

def archive_old_logs():
    conn = pymysql.connect(host='master', database='app')
    cursor = conn.cursor()
    
    while True:
        cursor.execute("""
            UPDATE user_logs 
            SET status=1 
            WHERE created_at < DATE_SUB(NOW(), INTERVAL 7 DAY) 
            AND status = 0
            LIMIT 1000
        """)
        conn.commit()
        if cursor.rowcount == 0:
            break
        time.sleep(0.5)  # 给复制留口气
    
    cursor.close()
    conn.close()

LIMIT 1000 + sleep(0.5) 是关键。小事务在从库回放快，不会堵塞复制链路。

第三，加监控。

我在 Prometheus 里加了一条告警规则：

- alert: MySQL_Slave_Lag_Sudden_Jump
  expr: rate(mysql_slave_lag_seconds[5m]) > 2
  for: 2m
  labels:
    severity: warning
  annotations:
    summary: "MySQL 主从延迟快速上升"