TiDB 出现 PD server timeout%!(EXTRA string=start timestamp may fall behind safe point) 错误

🪐 TiDB 技术问题 部署&运维管理
1

【TiDB 版本】： v3.0.12

【问题描述】：

我们的环境有 8 台 TiDB, 最近压力测试偶尔会随机有 TiDB 出现错误讯息 “TiDB 出现 PD server timeout%!(EXTRA string=start timestamp may fall behind safe point) 错误”

出现错误时, 其它七台 TiDB 正常, 所以推断不是 PD 端的问题

导致该错误出现的条件与原因目前还不太确定, 该错误出现后大概持续几个小时又会恢復正常

针对出问题的地方, 我们有查看了一下相关的原始码, 發现是以下这段逻辑似乎有问题

理论上 runSafePointChecker 这隻 goroutine 应该要每 gcSafePointUpdateInterval (10 秒钟) 去执行一次 loadSafePoint

func (s *tikvStore) runSafePointChecker() {
    d := gcSafePointUpdateInterval
    for {
        select {
        case spCachedTime := <-time.After(d):
            cachedSafePoint, err := loadSafePoint(s.GetSafePointKV(), GcSavedSafePoint)
            if err == nil {
                metrics.TiKVLoadSafepointCounter.WithLabelValues("ok").Inc()
                s.UpdateSPCache(cachedSafePoint, spCachedTime)
                d = gcSafePointUpdateInterval
            } else {
                metrics.TiKVLoadSafepointCounter.WithLabelValues("fail").Inc()
                logutil.Logger(context.Background()).Error("fail to load safepoint from pd", zap.Error(err))
                d = gcSafePointQuickRepeatInterval
            }
        case <-s.Closed():
            return
        }
    }

透过 pprof 的 goroutine 查看, 该 goroutine 是停在 select

stuck-in-select

正常情况下, 至少每 10 秒应该会去执行一次 loadSafePoint, 不管成功或失败, 都会去更新 metrics.TiKVLoadSafepointCounter
但该 goroutine 卡住时, 从下图可以看到 metrics.TiKVLoadSafepointCounter 停止增加 (04:05)

prometheus

透过 pprof 的 trace 收集 30 秒的纪录, 可以看到 runSafePointChecker 的 goroutine 在这 30 秒似乎没有触發

trace-bad

下图是正常 TiDB 的 trace 截图, 可以看到 runSafePointChecker 的 goroutine

trace-ok

查看 runtime.timerproc, 异常的 TiDB 有些 goroutine 的 bar 是灰色的 (unknown)

bar-bad

但如果是正常的 TiDB, runtime.timerproc 应该是紫色的, 大部分的时间应该是处于 Blocking syscall 的状态

bar-ok

从上面的资讯推论起来, 应该是 runtime.timerproc 有点异常, 导致 time.After(d) 没被触發.

目前查看了一下, 比较类似的问题应该是 https://github.com/golang/go/issues/14561

这个问题在 golang 1.14 有改善 https://github.com/golang/go/issues/24543

【我的疑问】:

  1. 不知道老师们是否有遇过类似的问题? 是否有什麽解决的方法
  2. 如果没有遇过的话, TiDB 有计画要升级到 golang 1.14 吗? 预计的时间大概是什麽时候
2

稍等，我们先查看一下，会尽快反馈，多谢

1 个赞
3

你好，我是 PingCAP 的研发同学，感谢你详细的分析，感觉思路很清晰。

看了下 https://github.com/golang/go/issues/24543 和 https://github.com/golang/go/issues/14561, 这俩的问题应该是 golang 是非抢占式的调度（在编译时期在函数调用前插入汇编代码跳转到抢占逻辑），如果有小的死循环，就会让 goroutine 切换(抢占)失败。

这里的问题我感觉应该是 runSafePointChecker 所在的这个 goroutine，一直拿不到线程资源去执行它，这个可能和 golang 调度算法有关，不过总的来说应该是公平的，正常情况不太可能出现 30s 调度不上。

因此怀疑可能是当时有什么情况导致了 golang 调度异常，比如 goroutine 非常多，CPU 被打满等，导致 runSafePointChecker 在 30s 的时间上都没被选上。

@AkioLove 麻烦你那边

  1. 观察下出问题时的 CPU 使用情况和 goroutine 数量
  2. 上传出问题时一段时间完整的 profile trace 数据，我们这里也看一下各个 goroutine 的调度情况
1 个赞
4

您好,

我把 trace file 的 link 透過郵件寄給你了, 再麻煩您收信一下

5

我这边收到了，我再看下。

1 个赞