TiDB GC 之监控及日志解读

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

作者：李坤、高振娇

背景

TiDB 的 GC 相关的问题比如 GC 的流程、参数设置、监控以及日志解析，GC 设置多大比较合适，设置过大对集群会产生什么样的影响，GC 卡住了应该从哪里排查等等一系列的问题，是笔者在使用 TiDB 过程中经常遇到的问题。

故笔者将 GC 相关的内容进行了相关的整理，一共分为 3 篇，第一篇为 『GC 原理浅析』，第二篇为『GC 监控及日志解读』，而最后一篇则为『GC 处理案例 & FAQ』。

本文从 GC 监控以及日志两个维度列举了 TiDB GC 相关的内容，希望能够对大家对分析 GC 问题能够有所帮助，表示不严谨或者错误的地方，欢迎大家批评指正 ~~~

监控

在 Grafana 中的 TiDB 和 TiKV-Details 的监控面板中都有 GC 相关的监控，来帮助用户分析 GC 所处的阶段以及 GC 的速度等。

TiDB 监控面板

• GC –> Worker Action OPM

TiDB 的 GC Worker 进行的各种操作的统计。只包括前两阶段，Y 轴是各阶段操作的次数统计，不是以 Region 为单位:

• delete_range ， delete range 阶段活动的次数，调用 UnsafeDestroyRange 接口。

• redo_delete_range，删过的区间 24h 后再删除一次的操作，不用太关注。

• resolve_locks，清锁阶段，无论是否产生真实清锁都会有该 metric（ scan_lock 是该阶段内部调用的 TiKV 接口，所以不会在这里展示）。

• run_job ，会在 GC 第一阶段最开始产生一个尖峰，可以用这个指标确认是否完成整轮 GC。

• GC –> Duration

TiDB 的整轮 GC 的耗时情况。3.0 开始只包括前两阶段的 duration，第三阶段看 TiKV-Details 面板的 TiKV Auto GC Progress。

图中可以理解为 1s 完成这两部分 GC，但是由于这种图内部是用 histogram 算的，分了多个桶，数值越大越不精确，所以不能把它当作精确的耗时，精确的耗时建议从日志中获取。

• GC –> GC Failure OPM

TiDB GC 失败的情况。如果出现这个指标，说明整轮 GC 失败了。

• GC –> Delete Range Failure OPM

UnsafeDestroyRange 操作失败的指标。出现这个指标可能意味着：

• 网络等问题导致偶尔有 UnsafeDestroyRange 请求失败；

• 集群中存在挂掉但是没有下线的 store，UnsafeDestroyRange 请求发到该 store 上就会失败；

• 查询或更新系统表出错（导致整个 GC 过程失败）

• GC –> Too Many Locks Error OPM

如果有 Region 中含有的 Safepoint 之前的残留锁过多，无法在一次请求中处理，则会产生这一指标。单个 Region 含有超过 1024 个 Safepoint 之前的锁会这样处理。Resolve Locks 阶段会对每个 Region 调用 scanlock 请求扫描过期的锁，但是有限制一个请求只能拿 1024 个锁，超过 1024 的话就会产生这一指标，并且会再次发送请求继续扫描，这里只会扫 lock cf。

• GC –> Action Result OPM

TiDB 对 TiKV 发送 gc 请求的结果（分为成功和失败）。在 3.0 后版本分布式 GC 启用的情况下不会产生这一指标。

TiKV-Details 监控面板

• GC –> GC tasks

显示 TiKV 的 GC worker 执行的任务。这些任务分为 GC 任务和 UnsafeDestroyRange 任务。以 Region 为粒度的。具体的指标有：

• total-gc: GC 任务总量。

• skipped-gc: 跳过的 GC 任务数量。TiKV 会根据记录在 RocksDB 中的一些元信息来推断一个 Region 是不是并没有太多需要 GC 的数据，如果是的话则跳过该 Region。

• failed-gc: GC 任务失败的数量。在 leader 迁移、region 不可用之类的情况下会发生。如果这一指标非常低，则无需在意。

• total-unsafe-destroy-range: TiKV 实际执行的 UnsafeDestroyRange 任务数量。

• failed-unsafe-destory-range: UnsafeDestroyRange 失败的数量。一般不会出现。

• gcworker-too-busy: 由于 TiKV 的 GCWorker 队列已满（队列长度为 2），而拒绝掉的请求数量。

• GC –> GC tasks duration

• 上一图 gc task 执行各种任务耗时的统计。

• 通常在秒级别、偶尔出现十几秒的 task 都是正常的。如果持续耗时几十秒甚至到分钟级别就可能有问题。

• GC –> GC speed

GC 删除旧版本的执行速度，单位为 key。

• GC –> ResolveLocks Progress

TiDB 一侧进行 Resolve Locks 的粗略的进度，值为 Region 数量。由于在 TiKV 面板不方便取 Region 总数，因而难以以百分比的形式表示进度。如果 GC 运行过快（比如在一个新建的几乎为空的集群上），该指标可能显示不出来。

• GC –> TiKV Auto GC Progress

TiKV 自行进行分布式 GC 的阶段的粗略进度。显示每台 TiKV 的进度，通过将已扫描的 Region 数量与该 TiKV 节点上 Region 总数相除的方式计算粗略的百分比。如果 GC 运行过快（比如在一个新建的几乎为空的集群上），该指标可能显示不出来。

• GC –> TiKV Auto GC SafePoint

每台 TiKV 当前自行 GC 时所使用的 Safepoint。该 Safepoint 由每台 TiKV 定期从 PD 取得。

日志

在分析 GC Leader 的 GC 相关的日志前，通过 mysql.tidb 来确认当前的 GC Leader 的信息：

select VARIABLE_NAME,VARIABLE_VALUE from mysql.tidb where VARIABLE_NAME in('tikv_gc_leader_uuid','tikv_gc_leader_desc');
+---------------------+-------------------------------------------------------------------------------------------+
| VARIABLE_NAME | VARIABLE_VALUE |
+---------------------+-------------------------------------------------------------------------------------------+
| tikv_gc_leader_uuid | 5d335b8561c000c |
| tikv_gc_leader_desc | host:node5189, pid:20040, start at 2020-09-27 10:39:37.891861155 +0800 CST m=+0.218055497 |
+---------------------+-------------------------------------------------------------------------------------------+

登陆 GC Leader 所在的 TiDB Server 上，并且找到 GC Leader 的 tidb.log，会看到 GC 相关的日志信息：

[2020/09/27 10:39:37.891 +08:00] [INFO] [gc_worker.go:163] ["[gc worker] start"] [uuid=5d335b8561c000c]
[2020/09/28 11:07:38.029 +08:00] [INFO] [gc_worker.go:262] ["[gc worker] starts the whole job"] [uuid=5d335b8561c000c] [safePoint=419761188493852672] [concurrency=3]
[2020/09/28 11:07:38.036 +08:00] [INFO] [gc_worker.go:952] ["[gc worker] start resolve locks"] [uuid=5d335b8561c000c] [safePoint=419761188493852672] [concurrency=3]
[2020/09/28 11:07:38.162 +08:00] [INFO] [gc_worker.go:973] ["[gc worker] finish resolve locks"] [uuid=5d335b8561c000c] [safePoint=419761188493852672] [regions=76]
[2020/09/28 11:08:37.918 +08:00] [INFO] [gc_worker.go:233] ["[gc worker] there's already a gc job running, skipped"] ["leaderTick on"=5d335b8561c000c]
[2020/09/28 11:09:18.187 +08:00] [INFO] [gc_worker.go:622] ["[gc worker] start delete ranges"] [uuid=5d335b8561c000c] [ranges=0]
[2020/09/28 11:09:18.187 +08:00] [INFO] [gc_worker.go:651] ["[gc worker] finish delete ranges"] [uuid=5d335b8561c000c] ["num of ranges"=0] ["cost time"=6.505µs]
[2020/09/28 11:09:18.191 +08:00] [INFO] [gc_worker.go:674] ["[gc worker] start redo-delete ranges"] [uuid=5d335b8561c000c] ["num of ranges"=0]
[2020/09/28 11:09:18.191 +08:00] [INFO] [gc_worker.go:703] ["[gc worker] finish redo-delete ranges"] [uuid=5d335b8561c000c] ["num of ranges"=0] ["cost time"=14.563µs]
[2020/09/28 11:09:18.202 +08:00] [INFO] [gc_worker.go:1436] ["[gc worker] sent safe point to PD"] [uuid=5d335b8561c000c] ["safe point"=419761188493852672]  

上面这段日志中，主要展示了下面的内容：

• 新一轮 GC 开始，并且完成了 Resolve Locks 阶段：

• 下述日志表示，当前的 GC 还在进行过程中，但是已经到达下一次 GC 开始的时间（tikv_gc_run_interval 默认 10 分钟）。此时，上一轮 GC 还处在前两个阶段，故新开始的这轮 GC 会跳过：

• 跳过新一轮的 GC 后，继续本次 GC 剩下的阶段 Delete Ranges，以及 Do GC：