MySQL:级联延迟数据库的延迟问题

本文主要讨论的还是5.7，8.0没有实际测试，这里简单记录。

---

一、问题说明

最近在处理一个主从问题的时候，发现一个比较奇怪的现象，这个主从是级联的也就是A->B->C库，B库问题处理后先启动了B库追数据，然后修复C库启动追延迟，这个时候观察到的B库和C库的延迟分别为20000多秒和900多秒，显然这个差距是非常大的，而级联又是平时用得很多的一种方式。
这里实际上C库的延迟应该比B库更大，那么级联从库中C库的延迟计算到底是怎么样的呢？这里我们简单探讨一下，未考虑清楚的地方还请见谅，下面我们也用A B C来代表主库、从库1、从库2。当然具体的主从原理，这里就不多讨论了，可以参考书籍<<深入理解MySQL主从原理>>。

二、延迟计算和级联从库C

一般来讲我们在讨论延迟的时候，延迟的计算公式大概如下，当然准确来说是单SQL线程（非MTS）下计算延迟的公式。

公式	含义
(long)(time(0) - mi->rli->last_master_timestamp - mi->clock_diff_with_master	从库服务器时间 - （各个Event中header中timestamp的时间 + query event中exec time的时间）- 主从服务器时间差

其中在主库row格式的binlog其query event中exec time的时间基本为0，因此B库在计算延迟的时候基本可以在公式中简化掉。

而在级联从库C中，其binlog来自B库，那么在B库中的binlog如何记录的就成了关键，那么其有2个关键就是：

• Event中header中timestamp的时间：这个时间实际上还是主库的timestamp时间，并不会因为在B库执行过就是B库产生binlog的时间。如下：

    thd->set_time(&(common_header->when));
    thd->set_query(query_arg, q_len_arg);
    thd->set_query_id(next_query_id());
    thd->variables.pseudo_thread_id= thread_id;     // for temp tables

这里在B库应用event的时候，设置了线程的start_time,也就是来自event header，这个实际上就是主库执行命令的时间，因此B库中记录的binlog的event header的timestamp 依旧来自主库。

• query event中exec time的时间：这个时间虽然在主库几乎为0，但是B库在记录的时候为当前时间 - 线程的start_time，而线程的start_time来自主库执行命令的时间，因此这个时间大概就是，B库当前时间-主库A执行命令的时间，基本就是B库的在执行query event时刻的延迟时间，如下：

  ulonglong micro_end_time= my_micro_time();//这里获取当前服务器时间时间
  my_micro_time_to_timeval(micro_end_time, &end_time);

  exec_time= end_time.tv_sec - thd_arg->start_time.tv_sec; //计算exec time

那么级联从库C的延迟实际上就是，

• 从库C当前时间-（主库执行命令的时间+B库的在执行query event时刻的延迟时间）- 主从服务器时间差

好了回到开头的问题，总结为2点。

• 当B库延迟很大的时候显然根据这个公式可以计算出C库的延迟是比较小的，因为B库在执行query event时刻的延迟非常大，那么记录的exec time就很大，到了C库计算延迟的时候就直接扣除了这部分。
• 当B库没什么延迟的时候，C库计算的延迟基本上就是相对于主库的延迟，因为这个时候B库在执行query event时刻的延迟非常小，不会产生太大的误差。

当然整个逻辑还是说的是时钟同步的情况下。

三、观察B库中的exec time

这里很容易观察到这种现象，只需要稍微做一下延迟就可以了。
主库A：

# at 1097
#230518 15:50:04 server id 333900  end_log_pos 1174 CRC32 0xab4d2adc    Query   thread_id=4     exec_time=0     error_code=0
SET TIMESTAMP=1684396204/*!*/;

从库B：

# at 1069
#230518 15:50:04（timestampm是主库的） server id 333900  end_log_pos 1132 CRC32 0x483e49b5    Query   thread_id=4     exec_time=48（这里）    error_code=0
SET TIMESTAMP=1684396204/*!*/;

在测试期间还发现B库，可能 exec_time很大的情况这里简单描述一下，如下，

#230517 15:33:05 server id 1623306  end_log_pos 1558 CRC32 0x2d7d12fc   Query   thread_id=17    exec_time=4283165634（这里）    error_code=0
SET TIMESTAMP=1684308785/*!*/;

显然这个是B库服务器时间落后于A库的时候，出现相减负数的情况，然后转非负整数，得到了一个很大的值。这种情况下C的延迟计算也会受到影响。

MTS 才会有这种现象 为何？

下期我们继续讨论