MySQL：主从同步延迟Seconds_Behind_Master越来越大，什么鬼？

戏说数据那点事 2019-08-13

5132

【此为"一森咖记"公众号——第29篇文章】

【前言】

使用MHA搭建了一套MySQL高可用架构。通过slave的Seconds_Behind_Master参数发现，从库slave的数值变得越来越大，大家都知道，Seconds_Behind_Master理论上应该为0，虽然该参数不能准确判断主从间的数据同步，但可以通过该参数来简单监控/判断主从库间的同步状况。而新搭建MHA架构中Seconds_Behind_Master越来越大，这显然就不正常了。

针对此情况，本文将讲述针对此问题如何分析，并提出解决方法。

环境：

[root@mysql ~]# cat etc/redhat-release

Red Hat Enterprise Linux Server release 7.3 (Maipo)

[root@mysql ~]# mysql -V

mysql Ver 14.14 Distrib 5.7.26, for el7 (x86_64) using EditLine wrapper

[root@mysql ~]# more etc/hosts

192.168.10.111 mysql_master

192.168.10.112 mysql_candidate_master

192.168.10.113 mysql_slave

架构：

MHA

GTID同步

192.168.10.111读写

192.168.10.113读

背景知识

大家都知道，MySQL的默认同步机制异步同步，其中IO thread负责接收从主库dump的binlog到从库上生成relay log，然后SQL thead负责解析relay log后在从库上进行重新执行来完成主从同步。这个2步是完全异步的，单独停止其中一个，并不会影响另一个的正行工作。当这两个thread都正常工作的时候，show slave status会显示双Yes状态，表示同步正常。

除了这两个状态外，还有另外一个非常重要参数seconds_behind_master，代表从库和主库的同步延迟时间，数值越高意味着延迟越大，但是当seconds_behind_master为0的时候，并不真正意味着从库已经追上主库了。

熟悉MySQL的童鞋可能都碰到过这样的场景，seconds_behind_master一直都是0，某一个时间点之后突然就变得非常高。一个场景举例：主库上执行了一个非常大的event，这个event在主库上没执行完毕的时候，从库的seconds_behind_master会显示为0，而当主库执行完毕传到从库上重演时，seconds_behind_master的值就会变得非常大。

Seconds_Behind_Master计算主从延时，官方解释如下：

It is also possible that transient values for Seconds_Behind_Master may not reflect the situation accurately. When the slave SQL thread has caught up on I/O, Seconds_Behind_Master displays 0; but when the slave I/O thread is still queuing up a new event, Seconds_Behind_Master may show a large value until the SQL thread finishes executing the new event. This is especially likely when the events have old timestamps; in such cases, if you execute SHOW SLAVE STATUS several times in a relatively short period, you may see this value change back and forth repeatedly between 0 and a relatively large value.

seconds_behind_master的值到底是怎么计算出来的呢？官方的解释如下：

Seconds_Behind_Master: The number of seconds that the slave SQL thread is behind processing the master binary log

SQL thread在执行IO thread dump下来的relay log的时间差。大家知道relay log中event记录的时间戳是主库上的时间戳，而SQL thread的时间戳是从库上的，如果主库和从库的时间是一致的，SBM代表的确实是从库延后主库的一个时间差。但是如果主库和从库的时间不是一致的，那么这个SBM的意义就基本不存在了。

简述之，Seconds_Behind_Master计算方法为：

1、当SQL线程执行event时，从库执行时刻的timestamp值减去该event上附带的时间戳（当时主库上的timestamp）间两者的差值。

2、一旦SQL线程未在执行event，则SBM为0

3、IO线程或SQL线程 is not running，则SBM为NULL

至此，我们了解了seconds_behind_master值得含义。

接下来，说说今天的问题现象。

问题现象

MHA架构，发现从库mysql_slave的参数Seconds_Behind_Master越来越大。已排除主从服务器时间不一致；那么主要就判断两点：是io thread慢还是 sql thread慢？先观察show slave status\G 。

判断3个参数（参数后面的值是默认空闲时候的正常值）：

Slave_IO_State: Waiting for master to send event

Slave_SQL_Running_State: Slave has read all relay log; waiting for the slave I/O thread to update it

Seconds_Behind_Master: 0

1.sql thread慢的表现：

Seconds_Behind_Master越来越大

Slave_SQL_Running_State: Reading event from the relay log

2.io thread慢的表现：

Seconds_Behind_Master为0

Slave_SQL_Running_State: 显示正常值

Slave_IO_State:显示忙碌状态

本文观察到的值：

Slave_IO_State: Queueing master event to the relay log

Seconds_Behind_Master: 30880

Slave_SQL_Running_State: Reading event from the relay log

上述三个参数，推断是sql thread慢

同步延迟信息详见如下：

mysql> show master status \G
*************************** 1. row ***************************
             File: mysql-bin.000057
         Position: 214873221
     Binlog_Do_DB:
 Binlog_Ignore_DB:
Executed_Gtid_Set: 838ad3df-a43d-11e8-8b02-6c92bf7daa8d:1,
efd10b43-a43c-11e8-85d8-6c92bf7d9fd1:1-134202381
1 row in set (0.00 sec)

从库延迟：

mysql> show slave status \G
*************************** 1. row ***************************
               Slave_IO_State: Queueing master event to the relay log
                  Master_Host: 192.168.10.111
                  Master_User: repl
                  Master_Port: 3306
                Connect_Retry: 60
              Master_Log_File: mysql-bin.000057
          Read_Master_Log_Pos: 214813221
               Relay_Log_File: relay-bin.00045
                Relay_Log_Pos: 28055325
        Relay_Master_Log_File: mysql-bin.000057
             Slave_IO_Running: Yes
            Slave_SQL_Running: Yes
          Exec_Master_Log_Pos: 94286319
              Relay_Log_Space: 956058939
             Seconds_Behind_Master: 30880
             Master_Server_Id: 113306
                  Master_UUID: efd10b43-a43c-11e8-85d8-6c92bf7d9fd1
             Master_Info_File: mysql.slave_master_info
                    SQL_Delay: 0
          SQL_Remaining_Delay: NULL
      Slave_SQL_Running_State: Reading event from the relay log
           Master_Retry_Count: 86400
           Retrieved_Gtid_Set: efd10b43-a43c-11e8-85d8-6c92bf7d9fd1:153917-55474510
            Executed_Gtid_Set: 838ad3df-a43d-11e8-8b02-6c92bf7daa8d:1,
efd10b43-a43c-11e8-85d8-6c92bf7d9fd1:1-54003557
                Auto_Position: 1
1 row in set (0.00 sec)

注意： Seconds_Behind_Master: 30880

分析步骤：

开始怀疑是参数配置的差异，比对/etc/my.cnf后发现，发现配置并无差异。

从库使用操作系统命令dstat观察，发现繁忙时候，slave的IO写速度上不去

[root@mysql ~]# dstat
You did not select any stats, using -cdngy by default.
----total-cpu-usage---- -dsk/total- -net/total- ---paging-- ---system--
usr sys idl wai hiq siq| read  writ| recv  send|  in   out | int   csw
  0   0 100   0   0   0|  19k  686k|   0     0 |   0     0 | 231   648
  0   0  99   1   0   0|   0  1388k| 798B  396B|   0     0 | 358  1596
  0   0  99   1   0   0|   0  1676k| 244B  170B|   0     0 | 397  1949
  0   0  99   1   0   0|   0  1796k|1490B  236B|   0     0 | 451  2107
  0   0  99   1   0   0|   0  1764k| 244B  170B|   0     0 | 414  2104
  0   0 100   0   0   0|   0  1536k|1068B  170B|   0     0 | 390  1649
  0   0  99   1   0   0|   0  1516k| 244B  170B|   0     0 | 373  1575
  0   0  99   1   0   0|   0  1552k|  34k  500B|   0     0 | 410  1602
  0   0 100   0   0   0|   0  1556k| 126B  236B|   0     0 | 363  1527
  0   0  99   1   0   0|   0  1384k|  60B  170B|   0     0 | 349  1369
  0   0  99   1   0   0|   0  1440k|  13k  434B|   0     0 | 400  1513
  0   0 100   0   0   0|   0  1800k| 612B  170B|   0     0 | 418  1905
  0   0  99   0   0   0|   0  1484k| 246B  236B|   0     0 | 622  1568
  0   0  99   1   0   0|   0  1272k|  60B  170B|   0     0 | 347  1294
  0   0  99   1   0   0|   0  1624k| 126B  236B|   0     0 | 400  1815
  0   0  99   1   0   0|   0  1580k|  60B  170B|   0     0 | 358  1712
  0   0 100   0   0   0|   0  1536k|  22k  302B|   0     0 | 395  1583
  0   0 100   0   0   0|   0  1440k| 514B  368B|   0     0 | 383  1765
  0   0  99   1   0   0|   0  1596k|  28k  500B|   0     0 | 446  2151

看到从库的写只能达到每秒1.5M左右，IO性能不是很好，也印证了初步的推测。

那么问题来了，

要如何优化IO性能比较差的slave呢？

简单，本文做了如下两个参数的修改：

mysql> set global innodb_flush_log_at_trx_commit=2;
Query OK, 0 rows affected (0.00 sec)
 
mysql> set global sync_binlog=20 ;
Query OK, 0 rows affected (0.00 sec)

innodb_flush_log_at_trx_commit和sync_binlog这两个参数又是个啥？

innodb_flush_log_at_trx_commit

1. innodb_flush_log_at_trx_commit设置为0，log buffer将每秒一次地写入log file中，并且log file的flush(刷到磁盘)操作同时进行.该模式下，在事务提交的时候，不会主动触发写入磁盘的操作。

2. innodb_flush_log_at_trx_commit设置为1，每次事务提交时MySQL都会把log buffer的数据写入log file，并且flush(刷到磁盘)中去.

3. innodb_flush_log_at_trx_commit设置为2，每次事务提交时MySQL都会把log buffer的数据写入log file.但是flush(刷到磁盘)操作并不会同时进行。该模式下,MySQL会每秒执行一次 flush(刷到磁盘)操作。

注意：

由于进程调度策略问题,这个“每秒执行一次 flush(刷到磁盘)操作”并不是标准意义上的保证100%的“每秒”。

sync_binlog

sync_binlog 的默认值是0，像操作系统刷其他文件的机制一样，MySQL不会同步到磁盘中去而是依赖操作系统来刷新binary log。

当sync_binlog =N (N>0) ，MySQL 在每写 N次二进制日志binary log时，会使用fdatasync()函数将它的写二进制日志binary log同步到磁盘中去。

注意:

如果启用了autocommit，那么每一个语句statement就会有一次写操作；否则每个事务对应一个写操作。mysql服务默认是autocommit打开的。

如上sync_binlog,autocommit,innodb_flush_log_at_trx_commit三个参数，详见从库mysql_slave设置如下：

mysql> show variables like '%sync_binlog%';
+---------------+-------+
| Variable_name | Value |
+---------------+-------+
| sync_binlog   | 0     |
+---------------+-------+
1 row in set (0.01 sec)
 
mysql>
mysql> show variables like '%innodb_flush_log_at_trx_commit%';
+--------------------------------+-------+
| Variable_name                  | Value |
+--------------------------------+-------+
| innodb_flush_log_at_trx_commit | 1     |
+--------------------------------+-------+
1 row in set (0.00 sec)
 
mysql> show variables like '%autocommit%';
+---------------+-------+
| Variable_name | Value |
+---------------+-------+
| autocommit    | ON    |
+---------------+-------+
1 row in set (0.00 sec)

根据上述分析过程，修改如下值：

mysql> set global sync_binlog=20;
mysql> set global innodb_flush_log_at_trx_commit=2;

接下来，我们观察和验证从库同步情况

1. 使用dstat命令观察磁盘IO，下图可以看到从库的写有原来的每秒1.5M左右提升为4M以上，

[root@mysql ~]# dstat
You did not select any stats, using -cdngy by default.
----total-cpu-usage---- -dsk/total- -net/total- ---paging-- ---system--
usr sys idl wai hiq siq| read  writ| recv  send|  in   out | int   csw
  0   0 100   0   0   0|  19k  686k|   0     0 |   0     0 | 231   648
  0   0  99   1   0   0|   0  4756k| 882B  462B|   0     0 | 601  6690
  0   0  99   1   0   0|   0  4208k| 430B  236B|   0     0 | 642  8771
  0   0  99   1   0   0|   0  4452k| 428B  170B|   0     0 | 607  7803
  0   0  99   1   0   0|   0  7964k|  26k  500B|   0     0 | 589  6835
  0   0  99   1   0   0|   0  3832k|1166B  170B|   0     0 | 368  2467
  0   0  99   1   0   0|   0  4584k|2042B  236B|   0     0 | 523  4632
  0   0  99   1   0   0|   0  4972k|1296B  170B|   0     0 | 661  9298
  0   0  99   1   0   0|   0  4792k|1046B  236B|   0     0 | 606  9634
  0   0  99   1   0   0|   0  5244k|3032B  212B|   0     0 | 745  9965
  0   0  99   0   0   0|   0  4648k| 796B  170B|   0     0 |1166    19k
  0   0  99   1   0   0|   0  4608k|  21k  434B|   0     0 | 827    14k
  0   0  99   0   0   0|   0  4552k|1858B  236B|   0     0 | 971    17k
  0   0  99   0   0   0|   0  4580k| 980B  170B|   0     0 | 936    17k
  0   0  99   1   0   0|   0  8332k|  21k  434B|   0     0 | 940    13k
  0   0  99   0   0   0|   0  4136k|1112B  236B|   0     0 |1112    20k
  0   0  99   0   0   0|   0  4940k| 796B  170B|   0     0 |1045    19k
  0   0  99   0   0   0|   0  4496k|  22k  500B|   0     0 | 951    15k
  0   0  99   0   0   0|   0  4652k| 862B  170B|   0     0 |1022    18k
  0   0  99   0   0   0|   0  5472k|1546B  236B|   0     0 | 950    15k
  0   0  99   0   0   0|   0  2616k|  20k  434B|   0     0 | 901    15k
  0   0  99   1   0   0|   0  9564k|2410B  170B|   0     0 | 958    14

2. 从库使用 show slave status \G，观察到Seconds_Behind_Master: 21202在持续缩小和主库的差距。Seconds_Behind_Master:由原来的30880降为21202，且在持续减少中。

mysql> show slave status \G
*************************** 1. row ***************************
               Slave_IO_State: Queueing master event to the relay log
                  Master_Host: 192.168.10.111
                  Master_User: repl
                  Master_Port: 3306
                Connect_Retry: 60
              Master_Log_File: mysql-bin.000057
          Read_Master_Log_Pos: 214833221
               Relay_Log_File: relay-bin.00045
                Relay_Log_Pos: 28064325
        Relay_Master_Log_File: mysql-bin.000057
             Slave_IO_Running: Yes
            Slave_SQL_Running: Yes
          Exec_Master_Log_Pos: 544925182
              Relay_Log_Space: 973436169
           Master_SSL_Allowed: No
        Seconds_Behind_Master: 21202
  Replicate_Ignore_Server_Ids: 
             Master_Server_Id: 113306
                  Master_UUID: efd10b43-a43c-11e8-85d8-6c92bf7d9fd1
             Master_Info_File: mysql.slave_master_info
                    SQL_Delay: 0
          SQL_Remaining_Delay: NULL
      Slave_SQL_Running_State: Waiting for dependent transaction to commit
           Master_Retry_Count: 86400
           Retrieved_Gtid_Set: efd10b43-a43c-11e8-85d8-6c92bf7d9fd1:153917-55504200
            Executed_Gtid_Set: 838ad3df-a43d-11e8-8b02-6c92bf7daa8d:1,
efd10b43-a43c-11e8-85d8-6c92bf7d9fd1:1-54771730
                Auto_Position: 1
1 row in set (4.98 sec)

至此，Seconds_Behind_Master越来越打的问题得到解决。

休息一下，看看下图哪个图案是自己的星座标识.

好了，这时还有一个问题：

既然Seconds_Behind_Master不能准确表明主从同步的状态，那有什么方法进行更准确地判断？

这里提供两个方法：

方法1:

MySQL5.5之后增加了relication的heartbeat机制，可以在从库上通过执行show global status like 'Slave_received_heartbeats'进行查看。当主库没有写入的时候会按照间隔时间跳动，可以依据此进行一定的health-check。

mysql> STOP SLAVE;

mysql> CHANGE MASTER TO master_heartbeat_period= milliseconds;

mysql> START SLAVE;

mysql> SHOW STATUS like 'slave_heartbeat period';

mysql> SHOW STATUS like 'slave_received_heartbeats';

方法2：

mk-heartbeat，Maatkit万能工具包中的一个工具，可以准确判断复制延时的方法。简单介绍下：

mk-heartbeat的实现也是借助timestmp的比较实现的，它首先需要保证主从服务器必须要保持一致，通过与相同的一个NTP server同步时钟。它需要在主库上创建一个heartbeat的表，里面至少有id与ts两个字段，id为server_id，ts就是当前的时间戳 now()，该结构也会被复制到从库上，表建好以后，会在主库上以后台进程的模式去执行一行更新操作的命令，定期去向表中的插入数据，这个周期默认为1 秒，同时从库也会在后台执行一个监控命令，与主库保持一致的周期去比较，复制过来记录的ts值与主库上的同一条ts值，差值为0表示无延时，差值越大表示延时的秒数越多。我们都知道复制是异步的ts不肯完全一致，所以该工具允许半秒的差距，在这之内的差异都可忽略认为无延时。这个工具就是通过实打实的复制，巧妙的借用timestamp来检查延时。

To be continued.

【总结】

1. MySQL的默认同步机制异步同步，其中IO thread负责接收从主库dump的binlog到从库上生成relay log，然后SQL thead负责解析relay log后在从库上进行重新执行来完成主从同步。这个2步是完全异步的，单独停止其中一个，并不会影响另一个的正行工作。

2. SQL thread在执行IO thread dump下来的relay log的时间差。大家知道relay log中event记录的时间戳是主库上的时间戳，而SQL thread的时间戳是从库上的，如果主库和从库的时间是一致的，SBM代表的确实是从库延后主库的一个时间差。

3. 最后，文末提供heartbeat机制和mk-heartbeat两种方法来判断主从同步，后续将进一步实验验证。

【参考】

https://blog.csdn.net/leonpenn/article/details/76489480

【参考】

https://www.cnblogs.com/billyxp/p/3470376.html

【参考】

https://blog.csdn.net/leonpenn/article/details/76489480

【参考】

http://blog.chinaunix.net/uid-27038861-id-3686311.html

如果大家觉得此文有帮助，欢迎关注个人微信公众号；

长按识别二维码或公众号搜索“一森咖记”

mysql

文章转载自戏说数据那点事，如果涉嫌侵权，请发送邮件至：contact@modb.pro进行举报，并提供相关证据，一经查实，墨天轮将立刻删除相关内容。

MySQL：主从同步延迟Seconds_Behind_Master越来越大，什么鬼？

评论