数据库｜Binlog故障处理之drainer周期性罢工

秒速五厘米 2024-02-19 10:50 19阅读 0赞

**目录**

一、背景

二、故障现象

三、分析过程

四、解决方案

五、思考

六、总结

--------------------

### **一、背景** ###

最近，用户反馈我们的生产环境TiDB集群的drainer频繁发生故障。故障表现为服务崩溃无法启动，或者数据在运行过程中丢失，给我们的业务带来了很大的困扰。这个集群运行的是离线分析业务，数据量达到20T，使用的是v4版本的drainer，并且有多个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 数量：

![3fc7028b28a9f78874780c4d67465078.png][]

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

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

![f8ff03837361aef0e0f36777542c4cc7.png][]

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

![5564239f1d26a210ea730559fa5cf42d.png][]

日志显示，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: 1gib

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

![754c4cc6bc758055f3b69bf028bde0e6.png][]

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

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

![10f51c24eecc799069f04c23af51ca1a.png][]

从上面这个曲线联想最近两次的故障，貌似问题一下子清楚了：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同步恢复正常。

![68979aea1c5e8416634d9749468c5c8c.png][]

![b4ae775cdd2b8a1209d7db5f8a9b3eaa.png][]

![7a306863923c212dd109366dde2c134d.png][]

经过几天的观察，我们发现pump的磁盘使用率稳定在一半左右，评估不会再出现类似问题，因此我们可以安心休息，不必再担心出现之前的故障。

幸运的是，下游的kafka对丢数据不敏感，可以随时从当前时间重新同步，这为我们节省了很多时间和精力，否则我们可能会面临更大的挑战。

### **五、思考** ###

必须说，为了恢复binlog不得不重启TiDB server真的让人感到非常不舒服。在生产环境中，重启并不是一件轻易就能执行的操作。幸运的是，后来我发现还有一个API可以用于恢复binlog。下次再遇到类似的问题，我会尝试使用这个API来解决。

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

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

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

![a6df72143fb85ea90fd144da68da6dec.png][]

根据我的使用经验，设置ignore-error后，发生critical error的可能性非常高。binlog同步似乎非常脆弱，稍有不合适就会停止工作。每次都需要进行全备份、恢复和重启TiDB server，这对于动辄几十T的集群来说绝对是灾难。不仅耗费时间，而且这么大数据量出错的概率也很高，想想都让人感到恐惧。

### **六、总结** ###

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

另外，我们需要注意pump gc的影响。pump gc不会考虑drainer是否正常消费。因此，在设置gc时，我们需要为drainer故障处理预留一些时间。

最后，我们应该加强对监控指标的研究，以便在排查问题时能够少走弯路。

作者 ：**何傲** | 高级后端开发工程师

***公众号搜索神州数码云基地，后台回复数据库，加入数据库技术交流群。***

[3fc7028b28a9f78874780c4d67465078.png]: https://image.dandelioncloud.cn/pgy_files/images/2024/02/19/2b5492f8101442798721cc7c452a6fea.png
[f8ff03837361aef0e0f36777542c4cc7.png]: https://image.dandelioncloud.cn/pgy_files/images/2024/02/19/356f58272a0f484d9406d97ada779e1c.png
[5564239f1d26a210ea730559fa5cf42d.png]: https://image.dandelioncloud.cn/pgy_files/images/2024/02/19/0835a4898487475f99bc93fddcccdad3.png
[754c4cc6bc758055f3b69bf028bde0e6.png]: https://image.dandelioncloud.cn/pgy_files/images/2024/02/19/a9f6646d78c54e3a8e71cdff9994c0e7.png
[10f51c24eecc799069f04c23af51ca1a.png]: https://image.dandelioncloud.cn/pgy_files/images/2024/02/19/8a27d91025dc4cef8f609f4a4b601a9d.png
[68979aea1c5e8416634d9749468c5c8c.png]: https://image.dandelioncloud.cn/pgy_files/images/2024/02/19/7455228a74b24b87a8d3dd041c2f2301.png
[b4ae775cdd2b8a1209d7db5f8a9b3eaa.png]: https://image.dandelioncloud.cn/pgy_files/images/2024/02/19/e0c834f4eb0745228a4e767d64e8e526.png
[7a306863923c212dd109366dde2c134d.png]: https://image.dandelioncloud.cn/pgy_files/images/2024/02/19/b3c748b2f2064c449686102dfe3178c4.png
[a6df72143fb85ea90fd144da68da6dec.png]: https://image.dandelioncloud.cn/pgy_files/images/2024/02/19/90452fa35f6048618ee80cf977888603.png