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

逃离我推掉我的手 2024-02-21 08:51 14阅读 0赞

**目录**

一、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相关的代码。

### **三、代码逻辑** ###

日志里面显示关于这部分逻辑的代码在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，并可能会让用户产生误解。因此，建议更改日志级别和输出信息，以避免这些问题。

***公众号搜索神州数码云基地，后台回复数据库，加入数据库技术交流群。***