TiDB binlog 故障处理之 drainer 周期性罢工

原文来源：https://tidb.net/blog/0d94d2d7

背景

前段时间用户反馈某生产环境 TiDB 集群 drainer 频繁发生故障，要么服务崩溃无法启动，要么数据跑着跑着就丢失了，很是折磨人。该集群跑的是离线分析业务，数据量 20T ，v4 版本，有多个 drainer 往下游同步数据，目标端包括 kafka、file、tidb 多种形态。

两天前刚恢复过一次，这会又故障重现，不得不来一次根因排查。

故障现象

接业务端反馈，某下游 kafka 几个小时没收到 TiDB 数据了，但是 pump 和 drainer 节点状态都显示正常，同样在几天前也收到类似的反馈，当时是因为 binlog 发生未知异常导致 TiDB server 停止写入，需要通过以下 API 验证 binlog 状态：

curl http://{tidb-server ip}:{status_port}/info/all

该 API 会返回所有 TiDB server 的元信息，其中就包括每个实例 binlog 的写入状态（binlog_status 字段），如果 TiDB server 设置了ignore-error，那么在 binlog 故障时通常是 skipping，正常情况下是 on。

经确认 7 个 TiDB server 的 binlog_status 均为 skipping 状态，和此前是一样的问题。

处理方法比较简单，重启 TiDB server 即可，但是避免后续重复出现需要搞清楚原因后再重启。

分析过程

数据不同步了相信大家都会第一时间怀疑是 drainer 的问题， 最常见的原因就是大事务导致 drainer 崩溃 panic，但是登录到 drainer 所在的机器上分析日志，并没有发现异常现象，日志显示 savepoint 正常写入，checkpoint 正常推进，实例状态 up，说明并不是 drainer 的问题。

根据 binlog skip 状态，转头去分析 TiDB server 监控，在 TiDB->Server->Skip Binlog Count面板可以看到被跳过的 binlog 数量：

从监控看到，在 8 月 18 号下午 6 点左右 Skip Count 突然从高位掉到 0，正是因为上一次重启 TiDB server 修复了故障。往后到 21 号早上左右，Skip Count 又开始出现，那么就要重点分析这个时间点的日志。

进一步分析监控，发现 Skip Count 上升趋势和 Critical Error 相吻合，说明在 21 号早上 07:06 左右开始出现大量的 binlog 写入异常，接下来根据这个时间点去排查 pump 的日志。

根据精确的时间点，很快就在 pump 日志中定位到了 panic 的位置，在 panic 之后日志发现了一个非常有用的信息：

日志显示，binlog 确实停止写入了，同时指出停止写入的原因是磁盘空间不够，这里有个关键信息StopWriteAtAvailableSpace，也就是说 pump 所在的磁盘可用空间小于这个参数时就会停止写入。我们用edit-config看一下 pump 的配置参数：

  pump:    gc: 2    heartbeat-interval: 2    security:      ssl-ca: ""      ssl-cert: ""      ssl-key: ""    storage:      stop-write-at-available-space: 1 gib

发现日志和配置参数可以对应上，确实是磁盘不够了。反手就是一个df -h看看什么情况：

意外的是，上图显示 pump 的数据盘只用了 1%，还有大把的空间没被使用，貌似和日志报错原因不符。

到这里我忽略了一个重要的时间因素，就是介入排查的时候离 pump 故障已经过去了 3 天（从前面第一章监控图可以看到），而 pump gc 时间设置的是 2 天，那么意味着在排查的时候 pump 之前记录的 binlog 已经被 gc 掉了，至于这些 binlog 有没有被 drainer 正常消费还不得而知。好在 Grafana 监控里面有一个面板记录了 pump storage 的变化情况，路径是：Binlog->pump->Storage Size。

从上面这个曲线联想最近两次的故障，貌似问题一下子清楚了：18 号下午 6 点左右重启 TiDB Server 恢复 binlog 写入，pump 可用空间开始变少，到 21 号早上 7 点左右几乎被使用完毕，触发StopWriteAtAvailableSpace异常，binlog 停止写入变成 skipping 状态，但与此同时 pump gc 还在工作，且没有新的 binlog 进来，两天后存量数据被 gc 完毕在 23 号早上 7 点左右恢复到空盘水平，持续到现在。

半途接手的集群，各种背景信息也不是很了解，经常奇奇怪怪问题一查就是查半天，这就是 oncall 人的日常。。😭

解决方案

到这里问题已经很明确了，是磁盘空间不够导致的，那么只有两条路摆在面前：要么开源、要么节流。

经过和用户沟通，加盘是不可能加的，直接就把 pump gc 缩短到 1 天。不过缩短 gc 也是存在风险的，如果哪次 drainer 故障超过 1 天那就要丢数据了。最终在 24 号下午 6 点左右把 gc 调整和 TiDB server 重启刚好一起做了，binlog 同步恢复正常。

观察几天后发现，pump 磁盘使用率稳定在一半左右，评估不会再出现类似问题，可以睡个安稳觉了。

好在下游 kafka 对丢数据不敏感，可以接受随时从当前时间重新同步，省了好多事，要不然得崩溃。

吐槽时间

不得不说要重启 TiDB server 才能恢复 binlog 真的太难受了，生产环境不是想重启就能重启的，好在后面发现了还有个 API 能恢复 binlog，下次碰到了试一下。

curl http://{tidb-server ip}:{status_port}/binlog/recover

文档隐蔽工作做的太好了，这些走后门的方法不知道 TiDB 还隐藏了多少。🤣

再就是在文档上看到的 binlog 主从故障恢复方法，真是瑟瑟发抖，谁用谁 996。↓↓↓

根据使用经验来看，设置了ignore-error后发生 critical error的可能性非常高，binlog 同步真的是太脆了，一言不合就罢工。每次都要全备 + 恢复 + 重启 TiDB server，对于动辄几十 T 的集群那绝对是灾难，时间成本不说，这么大数据量出错的概率也高，想想都后背发凉。

被折磨的人应该不少。

总结

从这个案例中我总结到，在参数设置上要留有一些 buffer，给后续出问题时有缓冲时间来处理。比如在本案中可以把stop-write-at-available-space设大一点，在出现磁盘空间不足时可以快速把值调小，这样 binlog 还能恢复继续同步，也能留出时间去做磁盘扩容，或者制定其他方案。

另外一点要注意 pump gc 的影响，它不会管 drainer 有没有正常消费，gc 设置上也要给 drainer 故障处理留出一些时间。

最后，没事多研究下监控指标，在排查问题时能少走很多弯路。

不好意思，标题让 drainer 背锅了。🤪

作者介绍：hey-hoho，来自神州数码钛合金战队，是一支致力于为企业提供分布式数据库 TiDB 整体解决方案的专业技术团队。团队成员拥有丰富的数据库从业背景，全部拥有 TiDB 高级资格证书，并活跃于 TiDB 开源社区，是官方认证合作伙伴。目前已为 10+ 客户提供了专业的 TiDB 交付服务，涵盖金融、证券、物流、电力、政府、零售等重点行业。