注册 登录
  • 欢迎访问"运维那点事",推荐使用Google浏览器访问,可以扫码关注本站的"微信公众号"。
  • 如果您觉得本站对你有帮助,那么可以扫码捐助以帮助本站更好地发展。

MySQL从库延迟计算方式分析(Seconds_Behind_Master)

MySQL 彭东稳 8065次浏览 已收录 2个评论

一、背景

在MySQL主备环境下,主备同步过程如下,主库更新产生binlog,备库io线程拉取主库binlog生成relay log。备库sql线程执行relay log从而保持和主库同步。

MySQL从库延迟计算方式分析(Seconds_Behind_Master)

理论上主库有更新时,备库都存在延迟,且延迟时间为备库执行时间+网络传输时间,即t4-t2。但实际情况是,我们一般都是通过Slave上执行SHOW SLAVE STATUS命令得到Seconds_Behind_Master列,理论上的显示了Slave的延时,但由于各种各样的情况,这个值并不总是准确的:

  • 从库Seconds_Behind_Master是通过拿Slave服务器当前的时间戳与SQL线程读取relay log中的事件的时间戳相比得到的,所以只有当SQL线程执行事件时才会报告延迟,不然Seconds_Behind_Master=0。
  • 如果备库复制线程没有运行,则Seconds_Behind_Master = NULL。
  • 即使备库线程正在运行,备库有时候可能无法计算延时,如果发生这种情况,Seconds_Behind_Master会报0或者NULL。
  • 如果网络延迟,导致从库拉取日志速度跟不上主库;但此时从库IO线程跟SQL线程在同一位点,那么Seconds_Behind_Master值为0,误以为没有延迟。
  • 一个大事务可能会导致延迟波动,例如一个事务更新数据长达1个小时,最后提交;这条更新语句将比它实际发生时间要晚一个小时才记录到二进制日志中(Binlog记录开始执行时间以及执行时间),当备库执行这条语句时,会临时报告备库延迟1小时,然后又很快变为0。
  • 长期未提交的事物延迟(如begin…dml…wait…commit),会造成延迟的瞬时增加。
  • 当表上无主键或唯一键时会造成主从延迟,那么对于在该表上做的DML,如果是以ROW模式复制,在从库回放时则每一个行记录前镜像都需要执行一遍,这是与主库不同的地方。在从库回放行记录时,遵循先找主键定位数据,其次是唯一键或二级索引;但唯一键或二级索引都需要回表,比主键要慢。在无主键或索引情况下,在备库每一个行记录都会产生一次全表扫描(也就是说一条delete,如果删了10条,从库会做10次全表扫),大多数情况下,这种开销都是非常不可接受的,并且产生大量的延迟。但有二级索引的情况下会比无主键无索引情况要好一些。

二、源码实现

Seconds_Behind_Master计算的源码实现如下:

大致可以看出seconds_behind_master值是通过时间和位点来计算的,其计算公式如下:

seconds_behind_master = SELECT UNIX_TIMESTAMP() on slave – timestamp of the master’s binary log event – (SELECT UNIX_TIMESTAMP() on slave – SELECT UNIX_TIMESTAMP() on master)

在源码中,if里面条件表示如果io线程拉取主库binlog的位置和sql线程执行的relay log相对于主库binlog的位置相等,那么认为延迟为0。一般情况下,io线程比sql线程快。但如果网络状况特别差,导致sql线程需等待io线程的情况,那么这两个位点可能相等,会导致误认为延迟为0。

再看else里:

  • time(0)

取当前slave服务器系统时间。

  • clock_diff_with_master(SELECT UNIX_TIMESTAMP() on slave – SELECT UNIX_TIMESTAMP() on master)

io线程启动时会向主库发送sql语句“SELECT UNIX_TIMESTAMP()”,获取主库当前时间。然而用备库当前时间减去此时间或者主备时间差值即为clock_diff_with_master。这里如果有用户中途修改了主库系统时间或修改了timestamp变量,那么计算出备库延迟时间就是不准确的。

  • last_master_timestamp(timestamp of the master’s binary log event)

表示主库执行binlog event的时间(可以简单理解为事务中第一条语句发起时间),此时间在并行复制和非并行复制时的计算方法是不同的。

非并行复制

备库sql线程读取了relay log中的event,然后会在event未执行之前就会更新last_master_timestamp,这里时间的更新是以event为单位。

其中ev->when.tv_sec表示event的开始时间,exec_time指event在主库的执行时间,但只有Query event和Load event才会统计exec_time。也就是说last_master_timestamp的值等于event header timestamp+exec_time,如果此event没有exec_time,那么基本就是把event header timestamp更新进last_master_timestamp。下面会详细说一下Query event在不同二进制日志格式下对DDL和DML的影响,因为这个影响着seconds_behind_master计算方式。

另外一种情况是sql线程在等待io线程获取binlog时,会将last_master_timestamp设为0,按上面的算法Seconds_Behind_Master为0,此时认为备库是没有延迟的。

并行复制

并行复制有一个分发队列gaq,sql线程将binlog事务读取到gaq,然后再分发给worker线程执行。并行复制时,binlog事件是并发穿插执行的,gaq中有一个checkpoint点称为lwm,lwm之前的binlog都已经执行,而lwm之后的binlog有些执行有些没有执行。

假设worker线程数为2,gap有1,2,3,4,5,6,7,8个事务。worker 1已执行的事务为1 4 6, woker 2执行的事务为2 3 ,那么lwm为4。

并行复制更新gap checkpiont时,会推进lwm点,同时更新last_master_timestamp为lwm所在事务结束的event的时间。因此,并行复制是在事务执行完成后才更新last_master_timestamp,更新是以事务为单位。同时更新gap checkpiont还受slave_checkpoint_period参数的影响。

这导致并行复制下和非并行复制统计延迟存在差距,差距可能为slave_checkpoint_period + 事务在备库执行的时间。这就是为什么在并行复制下有时候会有很小的延迟,而改为非并行复制时反而没有延迟的原因。

另外当sql线程等待io线程时且gaq队列为空时,会将last_master_timestamp设为0。同样此时认为没有延迟,计算得出seconds_Behind_Master为0。

三、位点信息维护

一般在从库经常会执行SHOW SLAVE STATUS,总要的参数有这么几个:

  • IO线程拉取主库Binlog的位点

Master_Log_File:读取到主库ROTATE_EVENT时会更新(process_io_rotate)。

Read_Master_Log_Pos:io线程每取到一个event都会从event中读取pos信息并更新mi->set_master_log_pos(mi->get_master_log_pos() + inc_pos)。

  • SQL线程执行Relay log的位点

Relay_Log_File:sql线程处理ROTATE_EVENT时更新(Rotate_log_event::do_update_pos)。

Relay_Log_Pos:非并行复制时,每个语句执行完成更新(stmt_done) 。并行复制时,事务完成时更新(Rotate_log_event::do_update_pos/ Xid_log_event::do_apply_event/stmt_done)。

  • SQL线程执行的Relay log相对于主库Binlog的位置

Relay_Master_Log_File:sql线程处理ROTATE_EVENT时更新(Rotate_log_event::do_update_pos)

Exec_Master_Log_Pos和Relay_Log_Pos同时更新:非并行复制时,每个语句执行完成更新(stmt_done) 并行复制时,事务完成时更新(Rotate_log_event::do_update_pos/ Xid_log_event::do_apply_event/stmt_done)。

谈到位点更新就有必要说到两个事件:HEARTBEAT_LOG_EVENT和ROTATE_EVENT。

  • HEARTBEAT_LOG_EVENT

HEARTBEAT_LOG_EVENT我们的了解一般作用是,在主库没有更新的时候,每隔master_heartbeat_period时间都发送此事件保持主库与备库的连接。而HEARTBEAT_LOG_EVENT另一个作用是,在gtid模式下,主库有些gtid备库已经执行同时,这些事件虽然不需要再备库执行,但读取和应用binglog的位点还是要推进。因此,这里将这类event转化为HEARTBEAT_LOG_EVENT,由HEARTBEAT_LOG_EVENT帮助我们推进位点。

  • ROTATE_EVENT

主库binlog切换产生的ROTATE_EVENT,备库io线程收到时会也有切换relay log。此rotate也会记入relay log,sql线程执行ROTATE_EVENT只更新位点信息。备库io线程接受主库的HEARTBEAT_LOG_EVENT,一般不用户处理。前面提到,gtid模式下,当HEARTBEAT_LOG_EVENT的位点大于当前记录的位点时,会构建一个ROTATE_EVENT,从而让sql线程推进位点信息。

另外,在replicate_same_server_id为0时,备库接收到的binlog与主库severid相同时,备库会忽略此binlog,但位点仍然需要推进。为了效率,此binlog不需要记入relay log。而是替换为ROTATE_EVENT来推进位点。

四、延迟现象

初始主备是同步的,且没有任何更新。假设主备库执行某个DDL在都需要30s,执行某个大更新事务(例如insert..select * from )需要30s。不考虑网络延迟。

MySQL从库延迟计算方式分析(Seconds_Behind_Master)

  • 非并行复制时

执行DDL:t2时刻主库执行完,t2时刻备库执行show slave status,Seconds_Behind_Master值为0。同时t2至t3,Seconds_Behind_Master依次从1s增大至30s,然后跌0。

执行大事务(二进制为ROW格式):t2时刻主库执行完,t2时刻备库执行show slave status,Seconds_Behind_Master值为30。同时t2至t3,Seconds_Behind_Master依次从30s增大至60s,然后跌0。

执行大事务(二进制为STATEMENT格式):t2时刻主库执行完,t2时刻备库执行show slave status,Seconds_Behind_Master值为0。同时t2至t3,Seconds_Behind_Master依次从1s增大至30s,然后跌0。

以上延迟计算的区别原因是exec_time在二进制中只有Query event和Load event才会统计,在STATEMENT格式下,操作都属于Query而ROW格式下的DML event操作没有记录exec_time统计导致。简单来说就是在二进制日志格式为ROW时执行DDL跟DML记录二进制日志信息是不同的。

下面是一个ROW格式的DDL记录信息:

可以看出正常情况下语句就包含在Query event中,而exec_time是Query event的数据,记录了执行时间。

而同样在ROW格式下,DML记录信息就不一样了。真正的数据包含在了DML event(Update_rows)中而不是包含在Query event中,所以exec_time一直为0。

如果你把二进制格式改为STATEMENT模式,那么同样记录的DML也是Query event,也会记录exec_time时间。

但是跟ROW格式DDL记录方式不同的是,DML有一个COMMIT,是属于Xid event出来的。这样由于这个Xid event exec_time为0,所以你在看到从库Seconds_Behind_Master延迟会有一个下面的变化:

从1s依次增大到25s后,一下子跳到51s,然后变为0。很奇怪吧。这个就是因为从库对event是顺序执行的,因为STATEMENT格式下DML操作多了一个Xid event,所以根据Seconds_Behind_Master的计算方式会出现上面的问题,我们简化一下Seconds_Behind_Master就是:从库本地时间 – (event header timestamp+exec_time) ,对应伪数据如下,方便明白问题:

对的,就是因为从库对event是顺序执行的,所以前面都是正常的,但到了Xid event后由于exec_time为0,所以Seconds_Behind_Master值一下子会变大,然后又突然变为0。

  • 并行复制时

执行DDL:t2时刻主库执行完,t2至t3备库执行show slave status,Seconds_Behind_Master值一直为0。

执行大事务:t2时刻主库执行完,t2至t3备库执行show slave status,Seconds_Behind_Master值一直为0。

这是因为执行语句之前主备是完全同步的,gaq队列为空,会将last_master_timestamp设为0。而执行DDL过程中,gap checkpoint一直没有推进,last_master_timestamp一直未0,直到DDL或大事务完成。

所以t2至t3时刻Seconds_Behind_Master值一直为0。而t3时刻有一瞬间last_master_timestamp是会重置的,但又因slave_checkpoint_period会推进checkpoint,gaq队列变为空,会将last_master_timestamp重设为0。

因此t3时刻可能看到瞬间有延迟(对于DDL是延迟30s,对于大事务时延迟60s)。

这似乎很不合理,gaq队列为空,会将last_master_timestamp设为0,这条规则实际可以去掉。

五、总结

Seconds_Behind_Master的计算并不准确和可靠。并行复制下Seconds_Behind_Master值比非并行复制时偏大。因此当我们判断备库是否延迟时,根据Seconds_Behind_Master=0不一定可靠。但是,当我们进行主备切换时,在主库停写的情况下,我们可以根据位点来判断是否完全同步。

如果(Relay_Master_Log_File, Exec_Master_Log_Pos)和(Relay_Master_Log_File, Read_Master_Log_Pos)位置相等且Seconds_Behind_Master=0,那么我们可以认为主备是完成同步的,可以进行切换。

相关bug

BUG#72376, PREVIOUS_GTIDS_LOG_EVENT 事件记录在每个binlog的开头,表示先前所有文件的gtid集合。relay-log本身event记录是主库的时间,但relay log开头的PREVIOUS_GTIDS_LOG_EVENT事件,是在slave端生成的,时间也是以slave为准的。因此不能用此时间计算last_master_timestamp。修复方法是在relay log写PREVIOUS_GTIDS_LOG_EVENT事件是标记是relay log产生的,在统计last_master_timestamp时,发现是relay产生的事件则忽略统计。

参考:https://www.kancloud.cn/taobaomysql/monthly/140089

感谢朋友@八怪跟踪源码解惑


如果您觉得本站对你有帮助,那么可以支付宝扫码捐助以帮助本站更好地发展,在此谢过。
喜欢 (3)or分享 (0)
关于作者:

您必须 登录 才能发表评论!

(2)个小伙伴在吐槽
  1. Hello,文章有一个点我觉得有误,如下: “由于表中没有主键,所以导致了每一个事务条目的更新都是全表扫描”。 我觉得应该是这样,如果表没有主键,那么会判断是否有二级索引,如果有,那么利用第一个最长的索引匹配主键;如果没有,那么才有走全表扫描。 欢迎作者指正,互相学习。
    binbin2019-01-10 10:34 (6天前) Windows 7 | Chrome 71.0.3578.98
    • 恩,这里没有说那么详细,有一篇文章详细说了从库应用规则及数据库提供了哪些优化策略。
      彭东稳2019-01-11 11:19 (5天前) 未知操作系统 | Chrome 70.0.3538.110