目录
- 问题描述
- 原理简析
- 问题分析
- 拓展一下
- 总结一下
问题描述
用户在主库上执行了一个 alter 操作，持续约一小时。操作完成之后，从库发现存在同步延迟，但是监控图表中的 Seconds_Behind_Master 指标显示为 0，且 binlog 的延迟距离在不断上升。
原理简析
既然是分析延迟时间，那么自然先从延迟的计算方式开始入手。为了方便起见，此处引用官方版本 5.7.31 的源代码进行阅读。找到计算延迟时间的代码：
./sql/rpl_slave.cc
bool show_slave_status_send_data(THD *thd, Master_info *mi,
char* io_gtid_set_buffer,
char* sql_gtid_set_buffer)
......
if ((mi->get_master_log_pos() == mi->rli->get_group_master_log_pos()) &&
(!strcmp(mi->get_master_log_name(), mi->rli->get_group_master_log_name())))
{
if (mi->slave_running == MYSQL_SLAVE_RUN_CONNECT)
protocol->store(0LL);
else
protocol->store_null();
}
else
{
long time_diff= ((long)(time(0) - mi->rli->last_master_timestamp)
- mi->clock_diff_with_master);
protocol->store((longlong)(mi->rli->last_master_timestamp ?
max(0L, time_diff) : 0));
}
......从 time_diff 的计算方式来看，可以发现这个延迟基本上就是一个时间差值，然后再算上主从之间的时间差。不过 if 挺多的，所以借用源代码文件中的注释：
可以知道，Seconds_Behind_Master的计算分为两个部分：
- SQL 线程正常，且回放完所有的 relaylog 时，如果 IO 线程正常，那么直接置 0。
- SQL 线程正常，且回放完所有的 relaylog 时，如果 IO 线程不正常，那么直接置 NULL。
- SQL 线程正常，且没有回放完所有的 relaylog 时，计算延迟时间。
那么在最后计算延迟时间的时候，看看那几个变量代表的意义：
- time(0)：当前的时间戳，timestamp 格式的。
- last_master_timestamp：这个 event 在主库上执行的时刻，timestamp 格式。
- clock_diff_with_master：slave 和 master 的时间差，在 IO 线程启动时获取的。
由此可见，延迟计算的时候，实际上是以 slave 本地的时间来减掉回放的这个 event 在 master 执行的时刻，再补偿两者之间的时间差，最后得到的一个数值。从逻辑上看是没什么问题的，由于 time(0) 和 clock_diff_with_master 在大多数时候是没有什么出问题的机会的，所以这次的问题，应该是出在 last_master_timestamp 上了。
PS：虽说大部分时候没问题，但是 time(0) 取的是本地时间，因此 slave 的本地时间有问题的话，这个最终的值也会出错，不过不在本案例的问题讨论范围之内了。
那么找一下执行 event 的时候，计算last_master_timestamp的逻辑，结合注释可以发现普通复制和并行复制用了不同的计算方式，第一个是普通的复制，计算时间点在执行 event 之前：
./sql/rpl_slave.cc
......
if (ev)
{
enum enum_slave_apply_event_and_update_pos_retval exec_res;
ptr_ev= &ev;
if ((!rli->is_parallel_exec() || rli->last_master_timestamp == 0) &&
!(ev->is_artificial_event() || ev->is_relay_log_event() ||
(ev->common_header->when.tv_sec == 0) ||
ev->get_type_code() == binary_log::FORMAT_DESCRIPTION_EVENT ||
ev->server_id == 0))
{
rli->last_master_timestamp= ev->common_header->when.tv_sec +
(time_t) ev->exec_time;
DBUG_ASSERT(rli->last_master_timestamp >= 0);
}
......last_master_timestamp的值是取了 event 的开始时间并加上执行时间，在 5.7 中有不少 event 是没有执行时间这个数值的，8.0 给很多 event 添加了这个数值，因此也算是升级 8.0 之后带来的好处。
而并行复制的计算方式，参考如下这一段代码：
./sql/rpl\_slave.cc
......
ts= rli->gaq->empty()
? 0
: reinterpret_cast<Slave_job_group*>(rli->gaq->head_queue())->ts;
rli->reset_notified_checkpoint(cnt, ts, need_data_lock, true);
......在 Coordinator 的 commit_positions 这个逻辑中，如果 gaq 队列为空，那么last_master_timestamp直接置 0，否则会选择 gaq 队列的第一个 job 的时间戳。需要补充一点的是，这个计算并不是实时的，而是间歇性的，在计算逻辑前面，有如下的逻辑：
set_timespec_nsec(&curr_clock, 0);
ulonglong diff= diff_timespec(&curr_clock, &rli->last_clock);
if (!force && diff < period)
{
DBUG_RETURN(FALSE);
}即在这个 period 的时间间隔之内，会直接 return，并不会更新这个last_master_timestamp，所以有时候也会发现并行复制会时不时出现 Seconds_Behind_Master 在数值上从 0 到 1 的变化。
而 gaq 队列的操作，估计是类似于入栈退栈的操作，所以留在 gaq 的总是没有执行完的事务，因此时间计算从一般场景的角度来看是没问题。
问题分析
原理简析中简要阐述了整个计算的逻辑，那么回到这个问题本身，腾讯云数据库 MySQL 默认是开启了并行复制的，因此会存在 gaq 队列，而 alter 操作耗时非常的长，不论 alter 操作是否会被放在一组并行事务中执行（大概率，DDL 永远是一个单独的事务组），最终都会出现 gaq 队列持续为空，那么就会把last_master_timestamp置 0，而参考 Seconds_Behind_Master 的计算逻辑，最终的 time_diff 也会被置 0，因此 alter 操作结束前的延迟时间一直会是 0。而当 alter 操作执行完之后，gaq 队列会填充新的 event 和事务，所以会出现延迟之前一直是 0，但是突然跳到非常高的现象。
拓展一下
对比普通复制和并行复制计算方式上的差异，可以知道以下几个特点：
- 开启并行复制之后，延迟时间会经常性的在 0 和 1 之间跳变。
- alter 操作，单个大事务等在并行复制的场景下容易导致延迟时间不准，而普通的复制方式不会。
- 由于主从时间差是在 IO 线程启动时就计算好的，所以期间 slave 的时间出现偏差之后，延迟时间也会出现偏差。
总结一下
严谨的延迟判断，还是依靠 GTID 的差距和 binlog 的 position 差距会比较好，从 8.0 的 event 执行时间变化来看，至少 Oracle 官方还是在认真干活的，希望这些小毛病能尽快的修复吧。
以上就是MySQL 发生同步延迟时Seconds_Behind_Master还为0的原因的详细内容，更多关于MySQL 同步延迟Seconds_Behind_Master为0的资料请关注自学编程网其它相关文章！
