本文主要讨论的还是5.7,8.0没有实际测试,这里简单记录。
最近在处理一个主从问题的时候,发现一个比较奇怪的现象,这个主从是级联的也就是A->B->C库,B库问题处理后先启动了B库追数据,然后修复C库启动追延迟,这个时候观察到的B库和C库的延迟分别为20000多秒和900多秒,显然这个差距是非常大的,而级联又是平时用得很多的一种方式。 这里实际上C库的延迟应该比B库更大,那么级联从库中C库的延迟计算到底是怎么样的呢?
这里我们简单探讨一下,未考虑清楚的地方还请见谅,下面我们也用A B C来代表主库、从库1、从库2。
一般来讲我们在讨论延迟的时候,延迟的计算公式大概如下,当然准确来说是单SQL线程(非MTS)下计算延迟的公式。
其中在主库row格式的binlog其query event中exec time的时间基本为0,因此B库在计算延迟的时候基本可以在公式中简化掉。
而在级联从库C中,其binlog来自B库,那么在B库中的binlog如何记录的就成了关键,那么其有2个关键就是:
(1) 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 依旧来自主库。
(2) 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点:
当然整个逻辑还是说的是时钟同步的情况下。
这里很容易观察到这种现象,只需要稍微做一下延迟就可以了。 主库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的延迟计算也会受到影响。