一、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相关的代码。
三、代码逻辑
日志里面显示关于这部分逻辑的代码在pump/server.go:635行detectDrainerCheckPoints方法里面，下面是相关代码
ifdrainer.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)从上述代码中可以看到，gcTS是通过alertGCTS参数变量传递进来的。而alertGCTS的值是gcTS与alertGCMS的和。其中，gcTS是通过调用s.storage.GetGCTS()方法获取的。该方法返回的gcTS实际上是pump最近一次垃圾回收的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增加了20小时，所以才会有上述的日志报错说drainer 请求的pump日志被清楚。
四、总结
经过查看代码，我们可以确定这个报错的根本原因已经找到。不过，为什么要在判断时将gcTS加上20小时呢？
对于这个问题，我只能提出一些猜测。这可能是一个历史遗留问题，也可能是为了提醒用户drainer归档binlog的速度太慢，导致需要读取的pump数据有被清除的风险。一般来说，当这个错误日志出现时，drainer归档binlog的速度确实较慢。
不过，具体的原因可能只有开发人员才能确切知道。在此，我们就不做过多研究了。值得注意的是，该错误日志级别为ERROR，并可能会让用户产生误解。因此，建议更改日志级别和输出信息，以避免这些问题。
版权声明:本文由神州数码云基地团队整理撰写，若转载请注明出处。
