性能文章>MySQL-Seconds_behind_master 的精度误差>

MySQL-Seconds_behind_master 的精度误差原创

3天前
137301

前言

Seconds_behind_master 是我们观察主从延迟的一个重要指标。但任何指标所能表示的精度都是有限的。例如用精度只能到秒的指标去衡量毫秒级的表现就会产生非常大的误差。如果再以此误差去分析问题,就会让思维走上弯路。例如用 Seconds_behind_master 去评估 1s 内的主从延迟就是一个典型的例子。
 

问题现场

在一些问题的排查中,我们注意到一个很奇怪的现象。那就是相同配置的从库表现出来的主从延迟差距有将近 500ms。而这两个从库之间的差别就是所在的机房不一样 (和主库都不在同一个机房)。如下图所示:

70312513-CCBF-4BCF-9998-5C2CFE3E8F7D.png

 
 

网络问题

难道是网络问题?那我们 ping 一下吧,最多也就相差 1ms。那么还有 499ms 去哪里了呢,看来还得继续挖掘。
 
Seconds_behind_master 的取点数据
 
直觉上来说网络问题不可能导致 500ms 这么大的误差,而机器配置和 MySQL 版本又是一样的。这就让笔者不得不怀疑这个兼容数据的准确性。所以就先看看这个 500ms 是怎么计算出来的。 

A05CF236-1F64-4FF2-A923-50434205C45C.png

从监控取点数据来看从库 C 确实有主从延迟,不然为什么有那么多取点为 0 呢。
 
Seconds_behind_master 什么时候计算出来为 1
 
这时候笔者突然想到一个点,如果主从延迟一个是 501ms 一个是 499ms,那么 Seconds_behind_master 计算的时候会不会采用四舍五入法。501ms (>=500ms) 的就是 1,499 (<500ms) 的就是 0?为了了解这一问题,笔者就去翻了翻源码。 ###Seconds_behind_master 在 MySQL 中的计算源码 计算这个指标的代码有很多微妙的分支,应对了各种 corner case。在此笔者只列出和当前问题相关的源码。
 
long time_diff= ((long)(time(0) - mi->rli->last_master_timestamp)
                       - mi->clock_diff_with_master);
 
前面 time (0) - mi->rli->last_master_timestamp 明显就是指时间差。但是,我们要考虑到一个很容易被忽略的常识,也就是不同机器的时间戳是不一样的!

132FF2E1-7D72-4273-A1BF-74CEAE452742.png

 
那么很明显的,如果主从实际延迟是 0,但是计算的时候没有剔除掉机器时钟的差异。那么主从延迟就是 6s。源码中的 mi->clock_diff_with_master 就是去修正这个差距!而计算这个 clock_diff_with_master 就会引起不小的误差。
 

什么时候计算 clock_diff_with_master

 
笔者在源码中翻阅时候注意到 clock_diff_with_master 不是每次都去计算的,而是在主从连接上或者重连 (reconnect) 的那一刻去计算一次。
 
handle_slave_io
	/* 建立主从连接 */
	|->safe_connect(thd, mysql, mi)) 
	/* connected: 主从连接成功后,计算一下主从clock_diff_with_master */
	|->get_master_version_and_clock
 
这就自然会导致下面的现象,假设一旦 clock_diff_with_master 计算有了误差。那么这个误差就会一直存在,直到下次重连为止!
 

clock_diff_with_master 跨秒误差

 
接着笔者又注意到 clock_diff_with_master 精度只能到秒。那么自然就会出现下面这几种现象。为了简单起见,我们假设绝对时钟是从 0 开始,而且我们假设主从延迟是 0。只看精度误差所能造成的影响。
 
在实际主从延迟为 0 的情况下 clock_diff_with_master 计算出来是 - 1,Seconds_behind_master 计算为 1
 
尽管有 NTP,我们也不可能做到两台机器的时间戳在完全一致 (除非两台机器有铯原子钟,那基本就没有毫秒级的误差了)。两台机器之间出现几百毫秒甚至数秒的延迟非常正常。例如假设我当前从库的 clock 是 0.5s,主库的 clock 是 1s。那么由于计算精度 (只能到秒) 的原因,实际实际只有 0.5s 的时间差会放大到 1s。 

F4A132BB-4E8D-4DDF-AD2C-72EE7CE8C761.png

那么我们现在可以计算出来在这种情况下 Seconds_behind_master 的平均值,在这里有一个预先假设就是我们取监控点的时间是随机的。

0B9AB93B-1EA9-4670-ABB1-442D4E6EF610.png

 
在上图中我们可以看到,在我们取从库时钟 [0.5,1.5) 这个 1s 的时间段范围内。在前 0.5s,也就是 [0.5,1) 这个区间中我们计算出来的
Seconds_behind_master 是 0,而在 [1,1.5) 区间计算的确是 1 。那我们的平均值就可以计算出来为 (0.5*0+0.5*1)/(1.5-0.5)=0.5=500ms!
也就是说,在没有任何实际主从延迟的情况下,仅仅跨秒这一个因素就能造成好几百毫秒的误差。
 
实际主从延迟为 0 的情况下 clock_diff_with_master 计算为 0,Seconds_behind_master 计算为 - 1 并被校正为 0
 
另外一个有意思的点是,既然误差能加 1,自然也能减 1。也就是 Seconds_behind_master 计算为 - 1。这就会给观察人员造成一个错觉,从库比主库快!当然了 MySQL 源码考虑到了这一点,强制校正为 0。
 
在这里,笔者将主从连接的那一刻稍微往前偏移 0.1s,就可以构造出刚才说的现象,如下图所示: 
 

3846D14C-20F3-4F94-85E8-820BED0BB2E5.png

MySQL 中的源码注释和强行校正逻辑如下所示:
 
    
 long time_diff= ((long)(time(0) - mi->rli->last_master_timestamp)
                       - mi->clock_diff_with_master);
      /*
        Apparently on some systems time_diff can be <0. Here are possible
        reasons related to MySQL:
        - the master is itself a slave of another master whose time is ahead.
        - somebody used an explicit SET TIMESTAMP on the master.
        Possible reason related to granularity-to-second of time functions
        (nothing to do with MySQL), which can explain a value of -1:
        assume the master's and slave's time are perfectly synchronized, and
        that at slave's connection time, when the master's timestamp is read,
        it is at the very end of second 1, and (a very short time later) when
        the slave's timestamp is read it is at the very beginning of second
        2. Then the recorded value for master is 1 and the recorded value for
        slave is 2. At SHOW SLAVE STATUS time, assume that the difference
        between timestamp of slave and rli->last_master_timestamp is 0
        (i.e. they are in the same second), then we get 0-(2-1)=-1 as a result.
        This confuses users, so we don't go below 0: hence the max().

        last_master_timestamp == 0 (an "impossible" timestamp 1970) is a
        special marker to say "consider we have caught up".
      */
      protocol->store((longlong)(mi->rli->last_master_timestamp ?
                                   max(0L, time_diff) : 0));
 

如何获得精确的毫秒级的主从延迟

 
由于 Seconds_behind_master 精度的原因,完全无法衡量毫秒级的主从延迟,所以出现了 pt-heartbeat 这样的工具去精确的计算主从间毫秒级的延迟。在后续采用 pt-heartbeat 对两个库进行监控后,这两个看上去平均延迟相差 500ms 的从库实际主从延迟差距在 10ms 之内。
 

总结

 
任何指标都有其表示的精度,而在其精度表示范围之外就会产生相当大的误差,以至于能够误导我们的判断。当对某一项的指标感到很反常识的时候,可以考虑是不是本身指标并不能描述当前我们想要观察的现象。例如本文中的阐述就表明 Seconds_behind_master 对 1s 的主从延迟的刻画没有太大的意义。
 

公众号

关注笔者公众号,获取更多干货文章:

57B9FC03-F81B-4DD9-892D-D999B161B928.png

💥看到这里的你,如果对于我写的内容很感兴趣,有任何疑问,欢迎在下面留言📥,会第一次时间给大家解答,谢谢!

 

请先登录,感受更多精彩内容
快去登录吧,你将获得
  • 浏览更多精彩评论
  • 和开发者讨论交流,共同进步

为你推荐

MySQL之KEY分区引发的血案
需求背景业务表tb_image部分数据如下所示,其中id唯一,image_no不唯一。image_no表示每个文件的编号,每个文件在业务系统中会生成若干个文件,每个文件的唯一ID就是字段id:业务表t
MySQL 死锁套路:一次诡异的批量插入死锁问题分析
线上最近出现了批量insert的死锁,百思不得解。死锁记录如下:```2018-10-26T11:04:41.759589Z 8530809 [Note] InnoDB: (1) TRANSACTI
MySQL 死锁套路:唯一索引下批量插入顺序不一致
死锁的本质是资源竞争,批量插入如果顺序不一致很容易导致死锁,我们来分析一下这个情况。为了方便演示,把批量插入改写为了多条 insert。先来做几个小实验,简化的表结构如下:```CREATE TABL
MySQL 死锁套路:再来看一例走不同索引更新的例子
前面有文章介绍了利用调试MySQL源码的方式来调试锁相关的信息,这里利用这个工具来解决一个比较简单的问题,线上的表字段较多,这里简单成为了一个表:```CREATE TABLE `t3` ( `id
如何在 Mac 下用 Clion 调试 MySQL 源码
前面写了几篇文章来通过调试 MySQL 源码来分析死锁问题,有读者问如何用 IDE 调试源码,这篇文章简单介绍一下如何在 Mac 下调试。之所以使用调试的方式来分析死锁问题是因为在解决 MySQL 死
掉坑了!GROUP_CONCAT函数引发的线上问题
本文分享一篇在工作遇到的一个问题,关于MySQL GROUP_CONCAT函数导致的问题。希望能帮忙到你。 业务场景在说遇到的坑之前,先描述一下大致的业务场景。系统有一个排班的功能,一个医生一天可以排
空中楼阁之纸上谈兵 mysql的dbcp的配置
maxWait=-1 最大等待时间:当没有可用连接时,连接池等待连接被归还的最大时间(以毫秒计数),超过时间则抛出异常,如果设置为-1表示无限等待testOnBorrow=true指明是否在从池中取出
一个诡异的MySQL查询超时问题,居然隐藏着存在了两年的BUG
这一周线上碰到一个诡异的BUG。线上有个定时任务,这个任务需要查询一个表几天范围内的一些数据做一些处理,每隔十分钟执行一次,直至成功。通过日志发现,从凌晨5:26分开始到5:56任务执行了三次,三次都