跳到主要内容

一次 TiDB 5.1 Write Stall 问题处理

作者介绍:靳献旗,汽车之家 DBA

1.背景

五一放假前,业务方告知要往 TiDB 集群刷 17 亿数据(业务端并发十个线程,以 replace 的方式往单张表中刷数据),计划五一之后项目上线,这个集群上还有少量其它业务已经上线。为了避免刷数据时产生大量告警,我们临时将集群告警关闭了。

四月三十号早上七点多,业务方突然反馈接口超时,我们迅速介入解决了这个问题,本文对本次问题的现象、解决办法做个记录,希望对其他小伙伴有借鉴意义。

2.问题现象

  • 业务端现象 业务接口读写超时。
  • 数据库端现象 show processlist 显示大量读写阻塞,处于 autocommit 状态;TiDB 集群 Duration SQL 999 达到分钟级,QPS 掉底。

3.问题分析

因为提前知道业务方在大量刷数据,又通过 show processlist 看到大量读写阻塞,根据经验,怀疑集群出现了 write stall (如果开启告警的话,可以从告警信息中直接得知是否发生了 write stall),于是顺着这个方向开始排查问题。

  • 集群是否出现 Server is busy server is busy 的出现不一定是 write stall 导致的,但是,一旦集群发生 write stall,则必然会出现 server is busy。

监控位置:TiKV-Details ---> Errors ---> Server is busy

image.png

从上图监控看到,确实出现了 server is busy,原因是 stall ,且显示除了具体 TiKV 实例。

  • 是什么原因引起的 write stall 从上一步分析,我们得知集群出现了 write stall 导致 server is busy 进入了限流模式,究竟是什么原因引起的 write stall 呢?我们继续分析,从下面监控可以得知 write stall 的原因。

监控位置:TiKV-Details ---> RocksDB-kv ---> Write Stall Reason

![image (1).png](https://tidb-blog.oss-cn-beijing.aliyuncs.com/media/image (1)-1651487137979.png)

从上图监控看到,引起 write stall 的原因有两个:

一个是 L1 ~ Ln 层待 Compaction 的 SST 文件的大小过大

一个是 L0 层 SST 文件数量过多

说明:
这里对上图监控中的几个指标做一下简单解释
(1)pending_compaction_bytes_slowdown:L1 ~ Ln 层待 Compaction 的 SST 文件大小达到阀值后集群会减慢写入速度
(2)pending_compaction_bytes_stop:L1 ~ Ln 层待 Compaction 的 SST 文件大小达到阀值后集群会 stall 住新的写入
(3)level0_file_limit_slowdown:L0 层待 Compaction 的 SST 文件个数达到阀值之后集群会减慢写入
说明:
TiDB 4.0 版本 Write Stall Reason 的监控位置和 5.1 不同: TiKV-Details ---> RocksDB-raft ---> Write Stall Reason
  • 是否有大量数据处于 compaction pending 状态 其实从以上两步已经分析出来了 write stall 的原因,这里我们辅助验证下,看下处于 compaction pending 状态的数据量。

监控位置:TiKV-Details ---> RocksDB-kv ---> Compaction pending bytes

![image (2).png](https://tidb-blog.oss-cn-beijing.aliyuncs.com/media/image (2)-1651487150016.png)

从上图监控看到,处于 compaction pending 状态的数据量高达 1.1 T,非常高。

说明:
TiDB 4.0 版本 Compaction pending bytes 的监控位置和 5.1 不同: TiKV-Details ---> RocksDB-raft ---> Compaction pending bytes
  • 分析 TiKV 日志 这一步也是为了辅助分析。

从本节第一步监控图中我们可以得知是哪个 tikv 实例发生了 stall,如果有多个 tikv 发生 stall,我们可以选择其中一个实例查看日志。

截取的部分日志内容如下
[root@p-xx-xx-xx data]#grep 'Stalling writes' /data3/tikv20173/data/rocksdb.info
[2022/04/30 07:16:11.145 +08:00][2][WARN] [db/column_family.cc:805] [default] Stalling writes because we have 23 level-0 files rate 5368709120
[2022/04/30 07:43:27.837 +08:00][2][WARN] [db/column_family.cc:830] [default] Stalling writes because of estimated pending compaction bytes 206825160726 rate 4294967296

简单解释下这两段日志: 当前 L0 层已经有 23 个 SST 文件,阀值是 20,因此集群减缓写入。

当前处于 pending compaction 的数据量达到了 192.62G (206825160726/1024/1024/1024),阀值是 192G,因此集群减缓写入。

特别说明:
TiDB 4.0 write stall 日志文件名和位置
/data3/tikv20173/data/raft/LOG
TiDB 5.1 write stall 日志文件名和位置
/data3/tikv20173/data/rocksdb.info
如果不注意可能会被带偏。
  • 分析磁盘 IO 通过以上几步,我们已经确认了是 write stall 导致的问题,那么究竟是 TiKV 并发刷盘参数太小导致的还是磁盘 IO 性能跟不上导致的呢?接下来我们看下磁盘 IO 的监控进一步判断。

监控位置:Overview ---> System Info ---> IO Util

![image (3).png](https://tidb-blog.oss-cn-beijing.aliyuncs.com/media/image (3)-1651487160906.png)

从上图监控看到,个别 TiKV 服务器的磁盘 IO 已经达到 100%。

到这里,我们已经分析出结论:业务接口超时是因为读写请求阻塞在了 TiDB ,而 TiDB 由于大量刷数据,磁盘 IO 性能跟不上,导致了 TiKV 数据刷盘(L0 往 L1)不及时和各层之间(L1 ~ Ln)待 compaction 的数据量太多,达到了限流阀值,最终导致了 write stall 问题。

4.问题解决

解决问题的过程很简单,让业务方暂停刷数,暂停之后十几分钟集群恢复了正常。

之后,业务将之前的并发十个线程调整为三个线程,观察集群及磁盘 IO 情况,后续增加到了五个线程,集群稳定,数据顺利跑完。

有些时候,当集群发生 write stall 时,我们无法通过通知业务方停止刷数据的方法解决,那么是否有一些应急方案可以缓解 write stall 问题呢?答案是肯定的,详细的应急文档请见专栏里我的另外一篇文章【TiDB 5.1 Write Stalls 应急文档】,里面有 write stall 发生的场景,阀值,缓解方法,详细命令。

5.总结

本文从一次解决 write stall 的问题出发,回顾了问题现象、分析过程、如何解决的整个处理流程,同时标记了在 TiDB 4.0 版本中需要注意的地方,比如 write stall 日志文件名、位置、监控在 4.0 和 5.1 版本中完全不同,避免带偏方向。希望对其他小伙伴有借鉴意义。