数据库｜Pump日志出现错误，你的数据被清空了吗？

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清除。但是，经过仔细查看日志上下文和代码逻辑，我发现实际上drainer要从pump读取的数据并未被清除。

那么，为什么会显示这样的错误日志呢？

日志初步检查

从日志中可以看到，drainer试图从pump中读取2023年7月9日11:05之后的数据（简称drainer request ts）。然而，gcTS（垃圾回收时间戳）显示的是2023年7月10日06:05，这似乎表明这个时间段内的数据已经被pump进行了清除。

为了验证这个结论，我查看了pump的上下文日志。通过使用“grep -in 'request gc ts' pump.log”命令，我找到了最近一次pump的垃圾回收时间（pump每小时进行一次垃圾回收）。根据该日志记录，我发现pump当前的最大gc ts（当前时间减去pump配置的垃圾回收参数）是2023年7月9日10:05。这意味着2023年7月9日10:05之前的数据已被清除。

然而，drainer的请求时间是2023年7月9日11:05，它并不需要读取2023年7月9日10:05之前的数据。因此，日志中“drainer's checkpoint is older than pump gc ts, some binlogs are purged”这条信息是错误的。更令人惊讶的是，这个日志消息还是以ERROR级别的。

本着好奇的态度，我去研究了pump相关的代码。

代码逻辑

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的checkpoint是否比pump的垃圾回收时间（gcTS）要早。如果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变量是如何计算的。在代码中，gcTS是作为参数传入的，而detectDrainerCheckPoints方法 被pump/server.go:546行被调用。

gcTS := s.storage.GetGCTS()
alertGCMS := earlyAlertGC.Nanoseconds() / 1000 / 1000 alertGCTS := 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 purged s.detectDrainerCheckPoints(s.ctx, alertGCTS)

[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

总结

经过查看代码，我们可以确定这个报错的根本原因已经找到。不过，为什么要在判断时将gcTS加上20小时呢？

对于这个问题，我只能提出一些猜测。这可能是一个历史遗留问题，也可能是为了提醒用户drainer归档binlog的速度太慢，导致需要读取的pump数据有被清除的风险。一般来说，当这个错误日志出现时，drainer归档binlog的速度确实较慢。

不过，具体的原因可能只有开发人员才能确切知道。在此，我们就不做过多研究了。值得注意的是，该错误日志级别为ERROR，并可能会让用户产生误解。因此，建议更改日志级别和输出信息，以避免这些问题。