背景

前段时间用户反馈某生产环境 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 数量:

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

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

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

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

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

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

日志显示,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看看什么情况:

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

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

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

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

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

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

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

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

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

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

吐槽时间

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

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

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

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

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

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

被折磨的人应该不少。

总结

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

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

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

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

11-17 00:09