TiDB GC 之监控及日志解读

作者:李坤、高振娇

背景

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 阶段:

    [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]
    
  • 下述日志表示,当前的 GC 还在进行过程中,但是已经到达下一次 GC 开始的时间(tikv_gc_run_interval 默认 10 分钟)。此时,上一轮 GC 还处在前两个阶段,故新开始的这轮 GC 会跳过:

    [2020/06/24 07:36:29.404 +08:00] [INFO] [gc_worker.go:246] ["[gc worker] there's already a gc job running, skipped"] ["leaderTick on"=5cb7b8557d40027]
    
  • 跳过新一轮的 GC 后,继续本次 GC 剩下的阶段 Delete Ranges,以及 Do GC:

    [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]
    
1赞