刚下的单，转头就查不到：读写分离、主从延迟与那个 500 万行的 DELETE

读写分离上线的第三天，客服转来一张截图：用户付款成功页，点“查看订单”，页面上写着“订单不存在”。用户再刷新一下，订单又出现了。用户说“你们系统是不是在跟我玩捉迷藏”，客服说“我也想知道”。

这个故事的老套之处在于——每个做读写分离的团队几乎都会遇到一次。老套的另一面是：它的排查路径非常清晰，值得整理成流程。下面是我们那次的完整过程，含一个“大事务把从库拖了 12 分钟”的加戏。

一、现象：写成功了，读不到，过几秒又有了

先把现象拆成三个可验证的事实：

1. 写请求（下单）落主库，返回成功；
2. 紧接着的读请求（查订单）被路由到从库，没查到；
3. 过几秒或几十秒之后，从库上能查到——数据没丢，是晚到。

数据“晚到”，最先怀疑的就是主从复制延迟。别猜，量一下。在从库上：

mysql> SHOW REPLICA STATUS\G          -- 8.0.22 之前用 SHOW SLAVE STATUS\G
*************************** 1. row ***************************
             Replica_IO_State: Waiting for source to send event
                  Source_Host: 10.0.2.11
                  Source_Port: 3306
              Source_Log_File: mysql-bin.004871
          Read_Source_Log_Pos: 812345678
               Relay_Log_File: relay-bin.009122
                Relay_Log_Pos: 611234567
        Relay_Source_Log_File: mysql-bin.004871
           Replica_IO_Running: Yes
          Replica_SQL_Running: Yes
          Exec_Source_Log_Pos: 611234350
        Seconds_Behind_Source: 743
                   Last_Error:
       Replica_SQL_Running_State: Waiting for dependent transaction to commit  (示例)

（8.0.22 之前字段叫 Slave_IO_Running、Slave_SQL_Running、Seconds_Behind_Master、Master_Log_File 等，含义一样，看你的版本。）

关键信息：

• Replica_IO_Running: Yes 与 Replica_SQL_Running: Yes：两条线程都在正常运行，不是复制断了；
• Read_Source_Log_Pos: 812345678 vs Exec_Source_Log_Pos: 611234350：I/O 线程已经把主库 binlog 读到 8.12 亿位置，但 SQL 线程只执行到 6.11 亿位置，二者之间差了两亿字节（约 200MB）的日志还没回放。IO 线程收得动，SQL 线程回放跟不上——这是最常见的延迟形态；
• Seconds_Behind_Source: 743：落后 743 秒，12 分多钟。

关于 Seconds_Behind_Source，官方文档有几条别忘了的说明：它是“从库当前时间 − 正在回放的事件在主库上的时间戳”；空闲时为 0；网络很慢时，SQL 线程追上了 IO 线程也可能显示 0，而实际上 IO 线程落后于主库；依赖主从时钟差保持恒定；线程没运行时是 NULL；多线程回放时它基于 Exec_Source_Log_Pos，那只是“低水位”。所以它只是参考值。要更准确的延迟，可以用 pt-heartbeat（主库定期写心跳表，从库读它并与当前时间做差）。

二、排查路线图

先看这次故障是怎么发生的，再讲怎么定位：

路线图：确认延迟 → 判断是 IO 线程慢还是 SQL 线程慢 → 找出 SQL 线程正在回放什么 → 对症下药。

三、动手：一步步找出“谁拖慢了从库”

第 1 步：IO 线程还是 SQL 线程？

比较 Read_Source_Log_Pos（IO 读到哪）与主库当前 SHOW MASTER STATUS（8.4 起改为 SHOW BINARY LOG STATUS）的 Position：

-- 主库
mysql> SHOW MASTER STATUS;
+------------------+-----------+--------------+------------------+---------------------------+
| File             | Position  | Binlog_Do_DB | Binlog_Ignore_DB | Executed_Gtid_Set         |
+------------------+-----------+--------------+------------------+---------------------------+
| mysql-bin.004871 | 812346120 |              |                  | 3e11fa47-...:1-88123456   |
+------------------+-----------+--------------+------------------+---------------------------+

主库 812346120，从库 IO 线程读到 812345678，几乎追平。所以是 SQL 线程慢（回放慢），不是网络问题。如果 Read_Source_Log_Pos 明显落后主库，才去查网络带宽、net_read_timeout、主库 dump 线程。

第 2 步：SQL 线程在回放什么？

在从库上看 processlist：

mysql> SHOW PROCESSLIST;
+-----+-------------+-----------+------+---------+------+----------------------------------+------------------+
| Id  | User        | Host      | db   | Command | Time | State                            | Info             |
+-----+-------------+-----------+------+---------+------+----------------------------------+------------------+
|   5 | system user |           | NULL | Connect | 9120 | Waiting for source to send event | NULL             |
|   6 | system user |           | NULL | Query   |  731 | Applying batch of row changes (delete) | NULL       |
...
2 rows in set (0.00 sec)

system user 就是复制线程。Time 731、State 为 Applying batch of row changes (delete)：SQL 线程在同一个事务里回放 delete 已经 731 秒。通常这就是大事务的特征：一个事务的 binlog 必须完整回放完才能提交。追到主库 binlog 里看看那是什么：

$ mysqlbinlog --base64-output=decode-rows -vv --start-position=611234350 --stop-position=611300000 \
    /var/lib/mysql/mysql-bin.004871 | head -40
# at 611234350
#260929 20:31:02 server id 1  end_log_pos 611234425 CRC32 0x8f1a2b3c   GTID  last_committed=1502  sequence_number=1503  rbr_only=yes
SET @@SESSION.GTID_NEXT= '3e11fa47-...:88121012'/*!*/;
# at 611234425
#260929 20:31:02 server id 1  end_log_pos 611234498  Query  thread_id=902881  exec_time=738  error_code=0
BEGIN
# at 611234498
#260929 20:31:02 server id 1  end_log_pos 611235012  Table_map: `order_db`.`t_order_log` mapped to number 412
# at 611235012
#260929 20:31:02 server id 1  end_log_pos 611299999  Delete_rows: table id 412
### DELETE FROM `order_db`.`t_order_log`
### WHERE
###   @1=1
###   @2='2026-01-01 00:00:00'
...

两个非常关键的字段：exec_time=738（这个事务在主库上就执行了 738 秒），以及它对 t_order_log 的大批量 Delete_rows（row 格式下每一行被删除都会被记录，事件量巨大）。真相是：有人在主库上跑了一次清理历史日志的任务：DELETE FROM t_order_log WHERE create_time < '2026-01-01'，一次删了 500 多万行，一个事务，跑了 12 分钟。主库跑了 12 分钟，binlog 里是一个事务，从库拿到之后也只能按照这一个事务，用一个线程，再跑 12 分钟，期间该事务之后的所有提交都要排队。

顺带一提：主库上执行时间很长的更新，从库延迟基本就是同样的时间。这不是从库配置差，而是复制的原子单位是事务。

第 3 步：performance_schema 看回放线程状态（并行复制时）

mysql> SELECT WORKER_ID, THREAD_ID, SERVICE_STATE, LAST_APPLIED_TRANSACTION,
    ->        APPLYING_TRANSACTION, APPLYING_TRANSACTION_ORIGINAL_COMMIT_TIMESTAMP
    -> FROM performance_schema.replication_applier_status_by_worker;

这张表按 worker 一行，能看到每个回放线程正在应用哪个事务、这个事务在主库什么时候提交的。官方文档也指出：它还有事务重试相关信息，用来判断重试（死锁、锁等待超时）是否在制造延迟。如果只有一个 worker 在忙，其它闲着，说明并行度没发挥出来（比如主库并发度低、或者被大事务串行化）。

第 4 步：确认从库自己有没有被“打扰”

$ iostat -x 1 3
Device  r/s   w/s  rkB/s   wkB/s  await  %util
nvme0n1 812   1544  ...            2.31   87.4
$ top -bn1 | head -12    # 看 mysqld 的 CPU、%wa

从库如果同时承担大查询（报表、导出），磁盘 IO 被占满，SQL 线程回放也会变慢。这也是“把大报表查询放到专门的分析从库”的原因。

四、根因：复制是“流水线”，最怕一个特别慢的“包裹”

MySQL 复制的三个阶段：主库写 binlog → 从库 IO 线程拉取写成 relay log → 从库 SQL 线程回放。

1. 大事务：事务在主库提交时才写入 binlog，所以主库上一个执行 12 分钟的大事务，提交之后才被从库看到，然后从库还要再花一遍时间回放。期间它后面所有事务的回放都排队。这就是这次的“一次删 500 万行”；
2. 单线程回放：早期 MySQL（5.5 及以前）从库只有一个 SQL 线程，主库多个连接并发写、从库一个线程串行回放，主库写入压力一大必然落后。5.6 起支持按库并行，5.7 起引入基于 LOGICAL_CLOCK 的并行；
3. 从库资源不足或被大查询占用；
4. 还有一类：无主键表。row 格式下无主键的表更新/删除，从库每一行都要全表扫描去定位，一个批量 DELETE 可能被放大成天文数字的扫描。这个坑我们踩过，务必给每张表设置主键。

而读写分离的应用层，天然假设“写完马上读能读到”。异步复制下，这个假设不成立，它只保证最终一致。

五、止血与修复

止血

1. 立刻让“刚写完就要读”的接口读主库（路由开关/降级配置，我们放在配置中心里，秒级生效）。这一步就能让用户不再看到“订单不存在”；
2. 大事务：如果还在主库上执行且仍可控，评估中断（KILL，会回滚，回滚也很慢）还是等它结束；已经提交的，只能让从库慢慢追。期间不要重启从库，也不要 STOP SLAVE 后随意 SKIP；
3. 把该从库暂时摘出读流量池，让业务先走其它延迟低的从库或主库。

根治：三层

第一层：别再制造大事务。批量清理必须分批，小批量、带主键条件、每批之间 sleep：

-- 每次 1000 行，循环到影响行数为 0；脚本里每批之间 sleep 0.2~1s，并检查从库延迟
DELETE FROM t_order_log WHERE create_time < '2026-01-01' ORDER BY id LIMIT 1000;
-- 应用层：affected_rows > 0 则继续；顺带监控 Seconds_Behind_Source，超过阈值就暂停

分批不仅缩短了单个事务，也把回放的粒度拆碎，让从库能持续追赶，读延迟平稳。

第二层：开启并行复制。官方文档对回放线程相关变量的说明：replica_parallel_workers（8.0.26 以前叫 slave_parallel_workers）决定回放线程数，值为 0 表示单线程；并行类型 replica_parallel_type（旧名 slave_parallel_type）可取 DATABASE 或 LOGICAL_CLOCK，推荐 LOGICAL_CLOCK（基于主库组提交的逻辑时钟，在同一个组里提交的事务可以并行回放）；replica_preserve_commit_order（旧名 slave_preserve_commit_order）为 ON 时保证从库提交顺序与主库一致，读到的数据状态与主库某个历史时刻一致。各版本的默认值不同（例如 8.0 文档里新变量默认 4 个 worker、LOGICAL_CLOCK），升级前请对照自己版本的手册确认，不要照搬。参考配置：

# 从库 my.cnf（8.0.26+ 命名；旧版本用 slave_ 前缀）
[mysqld]
replica_parallel_workers      = 8            # 按 CPU 核数和写入并发决定，常见 4~16
replica_parallel_type         = LOGICAL_CLOCK
replica_preserve_commit_order = ON
relay_log_recovery            = ON           # 崩溃恢复更安全
# 主库端可让更多事务“看起来可并行”（8.0 常用）
# binlog_transaction_dependency_tracking = WRITESET

-- 运行时切换需要先停 SQL 线程（旧版本 STOP SLAVE SQL_THREAD）
mysql> STOP REPLICA SQL_THREAD;
mysql> SET GLOBAL replica_parallel_workers = 8;
mysql> START REPLICA SQL_THREAD;

需要强调：并行复制对“一个巨型事务”无能为力——一个事务只能被一个 worker 回放。它解决的是“很多小事务在主库并发提交，从库却串行回放”的问题。所以第一层和第二层是互补关系，不是二选一。

第三层：应用层保证“读自己写的”（Read-Your-Writes）。不能指望从库永远不延迟，所以架构上要有兜底。常见方案，从简单到复杂：

1. 强制读主：写操作之后的一小段时间里（比如 3~5 秒），同一用户/同一订单的读请求走主库。实现上可以在写成功时往 Redis 写一个 key=uid, ttl=5s 的标记，路由层看到标记就选主库。最简单、最有效，适合订单详情这类强一致读；
2. 关键读永远读主：支付结果查询、下单后立即跳转的详情页，业务上判定为“必须读主”，其余走从库；
3. 延迟感知路由：监控从库延迟，超过阈值（如 1s）自动把它从读池摘除（中间件 / 代理层能力）；
4. 等待从库追平：写完之后拿到主库的 GTID（SELECT @@global.gtid_executed 或会话跟踪），读之前在从库上执行 SELECT WAIT_FOR_EXECUTED_GTID_SET('gtid', 1)（带超时秒数），返回 0 表示已追上，超时则回退到主库。或者用 SOURCE_POS_WAIT（8.0.26 前叫 MASTER_POS_WAIT）按 binlog 位置等待。精确，但实现和成本更高；
5. 业务改造：写成功后由服务端把关键数据直接返回给前端展示，而不是让前端立刻再查一次。

// 读主标记：写后 5 秒内该用户读主库（示意）
public void afterWrite(long uid) {
    redis.opsForValue().set("rw:master:" + uid, "1", Duration.ofSeconds(5));
}
public DataSource route(long uid) {
    return Boolean.TRUE.equals(redis.hasKey("rw:master:" + uid)) ? masterDs : slaveDs;
}

六、顺带：Canal 订阅 binlog 的延迟怎么查？

我们的栈里还有 Canal，把 MySQL 变更同步到 ES/缓存。Canal 的原理（官方 README）是把自己伪装成 MySQL 的从库，向主库发送 dump 协议请求，主库推送 binlog，Canal 解析成对象再交给下游（Kafka / RocketMQ 等）。既然它是“伪从库”，延迟的排查思路和真正的从库是一致的，多了下游这一段：

思路是逐段对位点、找断点：

1. 看主库当前 binlog 位点（SHOW MASTER STATUS）与 Canal 当前消费位点（Canal 的 instance 元数据/管理端可见）的差距，差距大说明 Canal 拉取或解析慢（主库大事务同样会让 Canal 卡住——它同样要等大事务完整读完才能交给下游）；
2. Canal 位点跟得上，就看 MQ 里消费组的堆积（Kafka 看 consumer lag，RocketMQ 看消费进度差）；堆积说明消费者慢；
3. 消费者慢，查消费者写 ES / 刷缓存的耗时（批量写、线程数、重试）；
4. Canal 自身：连接是否断开重连、解析线程的 CPU、堆内存与 GC、batch 大小等。

同一次“500 万行 DELETE”对 Canal 的冲击也很明显：一个事务被解析成几百万条行变更消息，下游 MQ 瞬间被灌满。所以“分批清理”是对主从、Canal、下游 ES 三方都友好的做法。

七、复盘

一句话备忘：写完读不到 → SHOW REPLICA STATUS 看 Seconds_Behind_Source → 对比 Read/Exec 位点分清 IO 与 SQL → processlist/mysqlbinlog 找大事务 → 分批 + 并行复制 + 写后读主兜底。

后来我们把清理任务改成每批 1000 行，从库延迟曲线再也没有出现过那座“12 分钟的珠穆朗玛峰”。客服说用户再也没有反馈过“订单不存在”，我说那是因为订单一直都在，只是它去隔壁绕了一圈，路上稍微多花了点时间。

参考资料

• MySQL 8.0：SHOW REPLICA STATUS——Seconds_Behind_Source 的含义与局限、Read/Exec 位点字段、IO/SQL 线程状态。
• MySQL 8.0：复制从库选项与变量——replica_parallel_workers、replica_parallel_type、replica_preserve_commit_order 的说明与推荐配置。
• MySQL 8.0：复制中的事务重试与超时——事务重试可能引起延迟，以及可用的 performance_schema 观测表。
• Canal 项目主页——伪装成 MySQL 从库、dump 协议订阅 binlog 的原理与组件。