Master记录改变数据库结构、内容的语句或者数据库结构、内容的改变至二进制日志;
Slave 的IO线程连接上 Master,并请求从指定日志文件的指定位置(或者从最开始的日志)之后的日志内容;
Master 接收到来自 Slave 的 IO 线程的请求后,通过Master的 Binlog dump 线程根据请求信息读取指定日志指定位置之后的日志信息,返回给 Slave 端的 IO 线程。返回信息中除了日志所包含的信息之外,还包括本次返回的信息在 Master 端的 Binary Log 文件的名称以及在 Binary Log 中的位置;
Slave 的 IO 线程接收到信息后,将接收到的日志内容依次写入到 Slave 端的Relay Log文件(mysql-relay-bin.xxxxxx)的最末端,并将读取到的Master端的bin-log的文件名和位置记录到master-info文件中,以便在下一次读取的时候能够清楚的高速Master
Slave 的 SQL 线程检测到 Relay Log 中新增加了内容后,会马上解析该 Log 文件中的内容成为在 Master 端真实执行时候的那些可执行的 Query 语句,并在自身执行这些 Query。这样,实际上就是在 Master 端和 Slave 端执行了同样的 Query,所以两端的数据是完全一样的。(每个slave独立进行上述两步,互不影响。master为每个slave创建独立的线程发送二进制日志)
实现复制的细节
共三个线程实现MySQL复制,一个在Master(Binlog dump thread)两个在Slave(Slave I/O thread,Slave SQL thread)。
Binlog dump thread 负责向Slave发二进制日志内容,该线程读取每个即将发往Slave的事件时会为Master的二进制日志加锁,读取后释放锁。
Slave I/O thread读取Master的Binlog dump thread发送来的二进制日志的更新并写进Slave本地的中继日志。
Slave SQL thread读取中继日志并执行其中的事件。
每个master/slave连接都独立的存在上述三个线程。可通过在master和slave上执行SHOW PROCESSLIST命令查看相关信息,每个线程会有不同的状态信息。Slave I/O thread和Slave SQL thread可分别由对应命令单独开启,也可由START SLAVE命令一并开启。SHOW SLAVE STATUS命令提供了关于复制过程的额外信息。
Master:
mysql> show processlist \G
*************************** 1. row ***************************
Id: 1
User: repluser
Host: 192.168.90.129:51293
db: NULL
Command: Binlog Dump
Time: 5043
State: Master has sent all binlog to slave; waiting for binlog to be updated
Info: NULL
Slave:
mysql> show processlist \G
*************************** 1. row ***************************
Id: 1
User: system user
Host:
db: NULL
Command: Connect
Time: 5077
State: Waiting for master to send event
Info: NULL
*************************** 2. row ***************************
Id: 2
User: system user
Host:
db: NULL
Command: Connect
Time: 4227
State: Slave has read all relay log; waiting for the slave I/O thread to update it
Info: NULL
binlog格式
mysql> show variables like 'binlog_format';
+---------------+-------+
| Variable_name | Value |
+---------------+-------+
| binlog_format | ROW |
+---------------+-------+
1 row in set (0.01 sec)
mysql> show binlog events in 'mysql-info.000010' from 313 ;
+-------------------+-----+------------+-----------+-------------+--------------------------------+
| Log_name | Pos | Event_type | Server_id | End_log_pos | Info |
+-------------------+-----+------------+-----------+-------------+--------------------------------+
| mysql-info.000010 | 313 | Query | 100 | 388 | BEGIN |
| mysql-info.000010 | 388 | Table_map | 100 | 435 | table_id: 70 (db_test.t) |
| mysql-info.000010 | 435 | Write_rows | 100 | 475 | table_id: 70 flags: STMT_END_F |
| mysql-info.000010 | 475 | Xid | 100 | 506 | COMMIT /* xid=31 */ |
| mysql-info.000010 | 506 | Query | 100 | 581 | BEGIN |
| mysql-info.000010 | 581 | Table_map | 100 | 628 | table_id: 70 (db_test.t) |
| mysql-info.000010 | 628 | Write_rows | 100 | 668 | table_id: 70 flags: STMT_END_F |
| mysql-info.000010 | 668 | Xid | 100 | 699 | COMMIT /* xid=32 */ |
+-------------------+-----+------------+-----------+-------------+--------------------------------+
8 rows in set (0.00 sec)
mysql> set global binlog_format = 'statement';
Query OK, 0 rows affected (0.00 sec)
mysql> set session binlog_format = 'statement';
Query OK, 0 rows affected (0.00 sec)
mysql> show variables like 'binlog_format';
+---------------+-----------+
| Variable_name | Value |
+---------------+-----------+
| binlog_format | STATEMENT |
+---------------+-----------+
1 row in set (0.01 sec)
mysql> show binlog events in 'mysql-info.000010' from 699 ;
+-------------------+------+------------+-----------+-------------+-----------------------------------------+
| Log_name | Pos | Event_type | Server_id | End_log_pos | Info |
+-------------------+------+------------+-----------+-------------+-----------------------------------------+
| mysql-info.000010 | 699 | Query | 100 | 784 | BEGIN |
| mysql-info.000010 | 784 | Query | 100 | 888 | use `db_test`; insert into t values(17) |
| mysql-info.000010 | 888 | Xid | 100 | 919 | COMMIT /* xid=43 */ |
| mysql-info.000010 | 919 | Query | 100 | 1004 | BEGIN |
| mysql-info.000010 | 1004 | Query | 100 | 1108 | use `db_test`; insert into t values(18) |
| mysql-info.000010 | 1108 | Xid | 100 | 1139 | COMMIT /* xid=44 */ |
+-------------------+------+------------+-----------+-------------+-----------------------------------------+
6 rows in set (0.00 sec)
“推”还是“拉”
首先, MySQL 的复制是“推”的,而不是“拉”的。“拉”是指 MySQL 的备库不断的循环询问主库是否有数据更新,这种方式资源消耗多,并且效率低。“推”是指 MySQL 的主库在自己有数据更新的时候推送这个变更给备库,这种方式只有在数据有变更的时候才会发生交互,资源消耗少。
那么 MySQL 具体是怎么“推”的列,实际上备库在向主库申请数据变更记录的时候,需要指定从主库 Binlog 的哪个文件 ( MASTER_LOG_FILE ) 的具体多少个字节偏移位置 ( MASTER_LOG_POS ) 。对应的,主库会启动一个 Binlog dump 的线程,将变更的记录从这个位置开始一条一条的发给备库。备库一直监听主库过来的变更,接收到一条,才会在本地应用这个数据变更。
Seconds_Behind_Master
当备库执行更新时,该字段表示从库当前时间戳与从库执行主库记录的原始时间戳的时间差
当备库没有处理事件时,该值为0
In essence, this field measures the time difference in seconds between the slave SQL thread
and the slave I/O thread.
即slave的SQL thread与Slave I/O thread的时间差
如主备之间网络环境良好,Slave的I/O thread 能很快的从Master的binlog中同步sql到Slave的relay-log里,这样,这个值就能基本反应的Slave落后master的秒数;当网络环境特别糟糕的情况下,这个值确会让我们产生幻觉,I/O thread同步很慢,每次同步过来,SQL thread就能立即执行,这样,我们看到的Seconds_Behind_Master是0,而实际上Slave已经落后Master很多很多。
Slave:
mysql> lock table t read ;
Query OK, 0 rows affected (0.00 sec)
Master:
mysql> insert into t values(1);
Query OK, 1 row affected (0.04 sec)
mysql> insert into t values(2);
Query OK, 1 row affected (0.04 sec)
Slave:
mysql> show slave status \G
*************************** 1. row ***************************
Slave_IO_Running: Yes
Slave_SQL_Running: Yes
Seconds_Behind_Master: 27
1 row in set (0.01 sec)
mysql> unlock tables;
Query OK, 0 rows affected (0.00 sec)
mysql> show slave status \G
*************************** 1. row ***************************
Slave_IO_Running: Yes
Slave_SQL_Running: Yes
Seconds_Behind_Master: 0
1 row in set (0.00 sec)
故障分析 重现步骤
搭建主备的复制,临时断开主库的网络,并 kill 掉主库 MySQL 的 binlog dump 线程。
Master:
mysql> insert into db_test.t values(1);
Query OK, 1 row affected (0.01 sec)
mysql> insert into db_test.t values(2);
Query OK, 1 row affected (0.01 sec)
mysql> select * from db_test.t;
+------+
| a |
+------+
| 1 |
| 2 |
+------+
2 rows in set (0.00 sec)
Slave:
mysql> select * from db_test.t;
Empty set (0.01 sec)
mysql> show slave status \G
Slave_IO_Running: Yes
Slave_SQL_Running: Yes
Seconds_Behind_Master: 0
但是此时把网络恢复以后,在主库做任何变更,备库都无法获得数据更新了。而且备库上的 show slave status 显示: IO 线程 SQL 线程一切正常,复制延迟一直是 0 。一切正常,普通的监控软件都不会发现备库有数据延迟。
原因解析
从上面的分析,我们可以大致猜到为什么 show slave status 显示一切正常,但是实际上主库的变更都无法同步到备库上来:
出现问题的时候, Binlog dump 程序被我们 kill 掉了。作为监听的一方,备库一直没有收到任何变更,它会认为主库上长时间没有任何变更,导致没有变更数据推送过来。备库是无法判断主库上对应的 Binlog dump 线程 到底是意外终止了,还是长时间没有任何数据变更的。所以,对这两种情况来说,备库都显示为正常。
当然, MySQL 会尽量避免这种情况。比如:
在 Binlog dump 被 kill 掉时通知备库 线程 被 kill 掉了。所以我们重现时需要保证这个通知发送不到备库,也就是说该问题重现的关键在于 Binlog dump 被 kill 的消息由于网络堵塞或者其他原因无法发送到备库。
备库如果长时间没有收到从主库过来的变更,它会每隔一段时间重连主库。
问题避免
基于上面的分析,我们知道 MySQL 在这种情况下确实无法避免,那么我们可以有哪些办法可以避开列:
被动处理:修改延迟的监控方法,发现问题及时处理。
主动预防:正确设置 --master-retry-count , --master-connect-retry , --slave-net-timeout 复制重试参数。
a) 被动处理
MySQL 的延迟监控大部分直接采集 show slave status 中的 Seconds_Behind_Master 。这种情况下, Seconds_Behind_Master 就无法用来真实的衡量主备之间的复制延迟了。我们建议通过在主库轮询插入时间信息,并通过复制到备库的时间差来获得主备延迟的方案。 Percona 提供了一种类似的方案 pt-heartbeat 。发现这个问题以后,我们只需要 stop slave; start slave; 重启复制就能解决这个问题。
b) 主动预防
MySQL 可以指定三个参数,用于复制线程重连主库: --master-retry-count , --master-connect-retry , --slave-net-timeout 。
其中 master-connect-retry 和 master-retry-count 需要在 Change Master 搭建主备复制时指定,而 slave-net-timeout 是一个全局变量,可以在 MySQL 运行时在线设置。
具体的重试策略为:备库过了 slave-net-timeout 秒还没有收到主库来的数据,它就会开始第一次重试。然后每过 master-connect-retry 秒,备库会再次尝试重连主库。直到重试了 master-retry-count 次,它才会放弃重试。如果重试的过程中,连上了主库,那么它认为当前主库是好的,又会开始 slave-net-timeout 秒的等待。
slave-net-timeout 的默认值是 3600 秒, master-connect-retry 默认为 60 秒, master-retry-count 默认为 86400 次。也就是说,如果主库一个小时都没有任何数据变更发送过来,备库才会尝试重连主库。这就是为什么在我们模拟的场景下,一个小时后,备库才会重连主库,继续同步数据变更的原因。
这样的话,如果你的主库上变更比较频繁,可以考虑将 slave-net-timeout 设置的小一点,避免主库 Binlog dump 线程 终止了,无法将最新的更新推送过来。
当然 slave-net-timeout 设置的过小也有问题,这样会导致如果主库的变更确实比较少的时候,备库频繁的重新连接主库,造成资源浪费。
参考:
http://www.woqutech.com/?p=1116
http://www.cnblogs.com/billyxp/p/3470376.html
http://dev.mysql.com/doc/refman/5.5/en/show-slave-status.html