作者： Hacker_loCdZ5zu 原文来源：https://tidb.net/blog/f0e3e836

一、pump 日志错误信息疑问

在 pump 排查问题的时候（6.1.5 版本），偶然发现一条错误日志， [ERROR] [server.go:635]drainer’s checkpoint is older than pump gc ts, some binlogs are purged，draine=drainerip:port,gc ts=2023-07-10 06:05,drainer checkpoint=2023-07-09 11:05（为了便于表达，直接将相应的 ts 转为了相应的时间） 第一眼看到这条日志的时候，正如日志所描述的以为 drainer 要从 pump 读取的数据已经被 pump 给 gc 了，但是详细看了下这条日志的上下文及结合代码的逻辑, 发现 drainer 要从 pump 读取的数据 其实没有被 pump gc 了，那为什么会显示出这样的日志呢？

二、日志初步检查

从日志来看，是在说 drainer 要从 pump 里面读取 07-09 11:05 之后的数据 (下文简称 drainer request ts)，但是 gc ts 是 07-10 06:05，看起来 drainer request ts 小于 gc ts，drainer 要从 pump 获取[07-09 11:05,07-10 06:05]这个区间的数据已经被 pump gc 给进行 purge 了，但是事实真的这样嘛？我翻了下 pump 上下文的日志，通过 grep -in ‘request gc ts’ pump.log 可以看到最近一次 pump 的 gc 时间（pump 每小时 gc 一次)，通过最近一次 pump 的 gc 的日志记录，可以看到 pump 当前的最大 gc ts 时间（当前时间 -pump 配置的 gc 参数）为 07-09 10:05 ，也就是说 07-09 10:05 之前的数据被 pump 给 gc 了，但是 drainer request ts 是 2023-07-09 11:05，并不需要读取 pump 07-09 10:05 之前的数据，那么日志显示的 drainer’s checkpoint is older than pump gc ts, some binlogs are purged…..，这条日志就打印的有问题了，并且这个日志还是 ERROR 级别，本着好奇的态度去翻了下 pump 相关的代码

三、代码逻辑

日志里面显示关于这部分逻辑的代码在 pump/server.go:635 行 detectDrainerCheckPoints 方法里面，下面是相关代码

if drainer.MaxCommitTS < gcTS {    log.Error("drainer's checkpoint is older than pump gc ts, some binlogs are purged",       zap.String("drainer", drainer.NodeID),       zap.Int64("gc ts", gcTS),       zap.Int64("drainer checkpoint", drainer.MaxCommitTS),    )    // will add test when binlog have failpoint    detectedDrainerBinlogPurged.WithLabelValues(drainer.NodeID).Inc()}

这个代码的逻辑还是比较简单的，如果 drainer.MaxCommitTS < gcTS，就会打印错误日志 ”drainer’s checkpoint is older than pump gc ts, some binlogs are purged”….，drainer.MaxCommitTS 这个变量的值其实就是 drainer 同步 pump 数据到哪个 tso 了 (就是 drainer savepoint 里面的 commitTS)，那么关键是 gcTS 变量是怎么求出来的，gcTSs 是该方法的传入的参数，而 detectDrainerCheckPoints 方法 被 pump/server.go:546 行被调用

gcTS := s.storage.GetGCTS()alertGCMS := earlyAlertGC.Nanoseconds() / 1000 / 1000alertGCTS := gcTS + int64(storage.EncodeTSO(alertGCMS))
log.Info("use gc ts to detect drainer checkpoint", zap.Int64("gc ts", gcTS))// detect whether the binlog before drainer's checkpoint had been purgeds.detectDrainerCheckPoints(s.ctx, alertGCTS)

通过上面代码可以看到 gcTS 是通过 alertGCTS 这个参数变量传递进来的，alertGCTS 的取值 =gcTS +alertGCMS，gcTS 的值是通过 s.storage.GetGCTS() 该方法的来的，该方法返回的 gcTS 其实就是 pump 最近一次 gc 的 gc tso（当前时间 -pump 配置的 gc 参数，也就是说 pump 已经把这个时间点以前的数据给 gc 了），这就是在日志里面看到的 request gc ts 的时间是 07-09 10:05

[INFO] [server.go:592] [“send gc request to storage”] [“request gc ts”=07-09 10:05]

那么 alertGCMS 的值是多少呢？其实 alertGCMS 在代码里面写死了

earlyAlertGC                    = 20 * time.Hour//pump/server.go:56

那也就是说在 detectDrainerCheckPoints 方法里面判断 drainer 请求的数据是否被 pump 给 gc 的时候，是和 gcTS 这个变量做比较，但是这个 gcTS 是实际的 gcTS +20h，所以才会有上述的日志报错说 drainer 请求的 pump 日志被 purged,

了。

四、总结

代码看到这里，其实我们知道这个报错的根本的原因就找到了，但是为什么要把 gcTS+20h 才去做判断呢？对于这一点，笔者提出猜想，这可能是一个历史遗留问题，可能是想让提醒用户 drainer 归档 binlog 太慢了，需要读取的 pump 数据有被 gc 的风险，一般出现这个错误日志的时候,drainer 那边归档 binlog 的速度其实是比较慢的，在这种情况下，才会出现这个告警，但是具体为什么这么设计可能只有开发同学才知道了，在这里我们就不做过多的研究了，但是这条日志笔者还是认为不应该是 ERROR 级别，并且输出信息也应该改进下，不然容易导致用户的误解。