扫码阅读
手机扫码阅读

数据库|Pump日志出现错误,你的数据被清空了吗?

70 2024-03-14

本期摘要

大家在日常使用TiDB时经常会进行故障排查,笔者在使用TiDB(6.1.5版本)时遇到了一个令人困惑的错误日志。日志表明,Pump的垃圾回收时间戳(gcTs)与Drainer的检查点时间戳存在时间差,Drainer可能无法从Pump读取到期望的数据。由于好奇,笔者深入研究了一下这一段代码,发现了一些有趣的东西。

本篇文章为大家分享一下笔者对于这个问题的探索和总结。

作者

匿名 | 数据库运维工程师

神州数码云基地钛合金团队的一位神秘的DBA~

01

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读取的数据并未被清除

那么,为什么会显示这样的错误日志呢?

02

日志初步检查

从日志中可以看到,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相关的代码。

03

代码逻辑

日志里面显示关于这部分逻辑的代码在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的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日志被清楚。

04

总结

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

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

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

原文链接: http://mp.weixin.qq.com/s?__biz=Mzg5MzUyOTgwMQ==&mid=2247525939&idx=1&sn=770c86cce80ec65def76b0f1950f6f89&chksm=c02f5d95f758d48348c97db521eef63176da8bc5ba24fb828654aa7c0b5c0930e829894bf2ea#rd