MySQL-17.主备一致及核心基础binlog

2019-08-16 本文已影响80人王侦

binlog 在 MySQL 的各种高可用方案上扮演了重要角色。以下内容可以说是所有 MySQL 高可用方案的基础。在这之上演化出了诸如多节点、半同步、MySQL group replication 等相对复杂的方案。

1.主备的基本原理

在状态 1 中，客户端的读写都直接访问节点 A，而节点 B 是 A 的备库，只是将 A 的更新都同步过来，到本地执行。这样可以保持节点 B 和 A 的数据是相同的。
需要切换的时候，就切成状态 2。这时候客户端读写访问的都是节点 B，而节点 A 是 B 的备库。
在状态 1 中，虽然节点 B 没有被直接访问，但是依然建议你把节点 B（也就是备库）设置成只读（readonly）模式。这样做，有以下几个考虑：
1）有时候一些运营类的查询语句会被放到备库上去查，设置为只读可以防止误操作；
2）防止切换逻辑有 bug，比如切换过程中出现双写，造成主备不一致；
3）可以用 readonly 状态，来判断节点的角色。

readonly 设置对超级 (super) 权限用户是无效的，而用于同步更新的线程，就拥有超级权限。

一个update 语句在节点 A 执行，然后同步到节点 B 的完整流程图。

备库 B 跟主库 A 之间维持了一个长连接。主库 A 内部有一个线程，专门用于服务备库 B 的这个长连接。一个事务日志同步的完整过程是这样的：

step1. 在备库 B 上通过 change master 命令，设置主库 A 的 IP、端口、用户名、密码，以及要从哪个位置开始请求 binlog，这个位置包含文件名和日志偏移量。
step2. 在备库 B 上执行 start slave 命令，这时候备库会启动两个线程，就是图中的 io_thread 和sql_thread。其中 io_thread 负责与主库建立连接。
step3. 主库 A 校验完用户名、密码后，开始按照备库 B 传过来的位置，从本地读取 binlog，发给B。
step4. 备库 B 拿到 binlog 后，写到本地文件，称为中转日志（relay log）。
step5. sql_thread 读取中转日志，解析出日志里的命令，并执行。后来由于多线程复制方案的引入，sql_thread 演化成为了多个线程。

2.binlog 的三种格式对比

一种是 statement
一种是 row
第三种格式叫作 mixed，其实它就是前两种格式的混合

 CREATE TABLE `test_24` (
 `id` int(11) NOT NULL,
 `a` int(11) DEFAULT NULL,
 `t_modified` timestamp NOT NULL DEFAULT CURRENT_TIMESTAMP,
 PRIMARY KEY (`id`),
 KEY `a` (`a`),
 KEY `t_modified`(`t_modified`)
) ENGINE=InnoDB;

insert into test_24 values(1,1,'2018-11-13');
insert into test_24 values(2,2,'2018-11-12');
insert into test_24 values(3,3,'2018-11-11');
insert into test_24 values(4,4,'2018-11-10');
insert into test_24 values(5,5,'2018-11-09');

2.1 statement格式下执行情况

delete from test_24  /*comment*/ where a>=4 and t_modified<='2018-11-10' limit 1;

查看binlog如下（show binlog events）：

| mysql-bin.000001 | 479 | Anonymous_Gtid |         1 |         544 | SET @@SESSION.GTID_NEXT= 'ANONYMOUS'                                                 |
| mysql-bin.000001 | 544 | Query          |         1 |         639 | BEGIN                                                                                |
| mysql-bin.000001 | 639 | Query          |         1 |         797 | use `sqllearn`; delete from test_24  where a>=4 and t_modified<='2018-11-10' limit 1 |
| mysql-bin.000001 | 797 | Xid            |         1 |         828 | COMMIT /* xid=71 */

第一行 SET @@SESSION.GTID_NEXT='ANONYMOUS’在介绍主备切换的时候再分析；
第二行是一个 BEGIN，跟第四行的 commit 对应，表示中间是一个事务；
第三行就是真实执行的语句了。可以看到，在真实执行的 delete 命令之前，还有一个use sqllearn命令。这条命令不是我们主动执行的，而是 MySQL 根据当前要操作的表所在的数据库，自行添加的。这样做可以保证日志传到备库去执行的时候，不论当前的工作线程在哪个库里，都能够正确地更新到 test 库的表 test_24。
use sqllearn命令之后的 delete 语句，就是我们输入的 SQL 原文了。可以看到，binlog“忠实”地记录了 SQL 命令。
最后一行是一个 COMMIT。你可以看到里面写着 xid=71。

关于xid：

redo log 和 binlog 是怎么关联起来的?
回答：它们有一个共同的数据字段，叫 XID。崩溃恢复的时候，会按顺序扫描 redo log：
1）如果碰到既有 prepare、又有 commit 的 redo log，就直接提交；
2）如果碰到只有 parepare、而没有 commit 的 redo log，就拿着 XID 去 binlog 找对应的事务。

看一下这条 delete 命令的执行效果图：

mysql> delete from test_24 /*comment*/ where a>=4 and t_modified<='2018-11-10' limit 1;
Query OK, 1 row affected, 1 warning (0.01 sec)

mysql> show warnings;
+-------+------+---------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+
| Level | Code | Message                                                                                                                                                                                                                         |
+-------+------+---------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+
| Note  | 1592 | Unsafe statement written to the binary log using statement format since BINLOG_FORMAT = STATEMENT. The statement is unsafe because it uses a LIMIT clause. This is unsafe because the set of rows included cannot be predicted. |
+-------+------+---------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+
1 row in set (0.00 sec)

可以看到，运行这条 delete 命令产生了一个 warning，原因是当前 binlog 设置的是statement 格式，并且语句中有 limit，所以这个命令可能是 unsafe 的。

为什么这么说呢？这是因为 delete 带 limit，很可能会出现主备数据不一致的情况。比如上面这个例子：

step1. 如果 delete 语句使用的是索引 a，那么会根据索引 a 找到第一个满足条件的行，也就是说删除的是 a=4 这一行；
step2. 但如果使用的是索引 t_modified，那么删除的就是 t_modified='2018-11-09’也就是a=5 这一行。

由于 statement 格式下，记录到 binlog 里的是语句原文，因此可能会出现这样一种情况：在主库执行这条 SQL 语句的时候，用的是索引 a；而在备库执行这条 SQL 语句的时候，却使用了索引 t_modified。因此，MySQL 认为这样写是有风险的。

2.2 row格式下执行情况

修改/etc/my.cnf 的binlog_format=row并重启systemctl restart mysqld。
查看是否修改成功：

mysql> show variables like 'binlog%';
+--------------------------------------------+--------------+
| Variable_name                              | Value        |
+--------------------------------------------+--------------+
| binlog_cache_size                          | 32768        |
| binlog_checksum                            | CRC32        |
| binlog_direct_non_transactional_updates    | OFF          |
| binlog_error_action                        | ABORT_SERVER |
| binlog_format                              | ROW          |
| binlog_group_commit_sync_delay             | 0            |
| binlog_group_commit_sync_no_delay_count    | 0            |
| binlog_gtid_simple_recovery                | ON           |
| binlog_max_flush_queue_time                | 0            |
| binlog_order_commits                       | ON           |
| binlog_row_image                           | FULL         |
| binlog_rows_query_log_events               | OFF          |
| binlog_stmt_cache_size                     | 32768        |
| binlog_transaction_dependency_history_size | 25000        |
| binlog_transaction_dependency_tracking     | COMMIT_ORDER |
+--------------------------------------------+--------------+

执行delete语句：

| mysql-bin.000002 | 724 | Anonymous_Gtid |         1 |         789 | SET @@SESSION.GTID_NEXT= 'ANONYMOUS'  |
| mysql-bin.000002 | 789 | Query          |         1 |         873 | BEGIN                                 |
| mysql-bin.000002 | 873 | Table_map      |         1 |         930 | table_id: 124 (sqllearn.test_24)      |
| mysql-bin.000002 | 930 | Delete_rows    |         1 |         978 | table_id: 124 flags: STMT_END_F       |
| mysql-bin.000002 | 978 | Xid            |         1 |        1009 | COMMIT /* xid=54 */

与 statement 格式的 binlog 相比，前后的 BEGIN 和 COMMIT 是一样的。但是，row 格式的 binlog 里没有了 SQL 语句的原文，而是替换成了两个 event：Table_map 和Delete_rows。

1）Table_map event，用于说明接下来要操作的表是 test 库的表 t;
2）Delete_rows event，用于定义删除的行为。

详细信息需要借助 mysqlbinlog 工具，这个事务的 binlog 是从724这个位置开始的，所以可以用 start-position 参数来指定从这个位置的日志开始解析。

log-bin = /var/log/mysql-bin.log
binlog_format=row
expire-logs-days = 14
max-binlog-size = 500M
server-id = 1

mysqlbinlog -vv /var/log/mysql-bin.000002 --start-position=724;

[root@izbp15dzsx0qokz9qdqojkz log]# mysqlbinlog -vv /var/log/mysql-bin.000002 --start-position=724;
/*!50530 SET @@SESSION.PSEUDO_SLAVE_MODE=1*/;
/*!50003 SET @OLD_COMPLETION_TYPE=@@COMPLETION_TYPE,COMPLETION_TYPE=0*/;
DELIMITER /*!*/;
# at 4
#190816  9:05:01 server id 1  end_log_pos 123 CRC32 0x3c06338a  Start: binlog v 4, server v 5.7.24-log created 190816  9:05:01 at startup
# Warning: this binlog is either in use or was not closed properly.
ROLLBACK/*!*/;
BINLOG '
PQFWXQ8BAAAAdwAAAHsAAAABAAQANS43LjI0LWxvZwAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA
AAAAAAAAAAAAAAAAAAA9AVZdEzgNAAgAEgAEBAQEEgAAXwAEGggAAAAICAgCAAAACgoKKioAEjQA
AYozBjw=
'/*!*/;
# at 724
#190816  9:09:00 server id 1  end_log_pos 789 CRC32 0x27deacc9  Anonymous_GTID  last_committed=2    sequence_number=3   rbr_only=yes
/*!50718 SET TRANSACTION ISOLATION LEVEL READ COMMITTED*//*!*/;
SET @@SESSION.GTID_NEXT= 'ANONYMOUS'/*!*/;
# at 789
#190816  9:09:00 server id 1  end_log_pos 873 CRC32 0xf74de073  Query   thread_id=2 exec_time=0 error_code=0
SET TIMESTAMP=1565917740/*!*/;
SET @@session.pseudo_thread_id=2/*!*/;
SET @@session.foreign_key_checks=1, @@session.sql_auto_is_null=0, @@session.unique_checks=1, @@session.autocommit=1/*!*/;
SET @@session.sql_mode=1436549152/*!*/;
SET @@session.auto_increment_increment=1, @@session.auto_increment_offset=1/*!*/;
/*!\C utf8 *//*!*/;
SET @@session.character_set_client=33,@@session.collation_connection=33,@@session.collation_server=8/*!*/;
SET @@session.time_zone='SYSTEM'/*!*/;
SET @@session.lc_time_names=0/*!*/;
SET @@session.collation_database=DEFAULT/*!*/;
BEGIN
/*!*/;
# at 873
#190816  9:09:00 server id 1  end_log_pos 930 CRC32 0x31dd725a  Table_map: `sqllearn`.`test_24` mapped to number 124
# at 930
#190816  9:09:00 server id 1  end_log_pos 978 CRC32 0x1fd11aef  Delete_rows: table id 124 flags: STMT_END_F

BINLOG '
LAJWXRMBAAAAOQAAAKIDAAAAAHwAAAAAAAEACHNxbGxlYXJuAAd0ZXN0XzI0AAMDAxEBAAJact0x
LAJWXSABAAAAMAAAANIDAAAAAHwAAAAAAAEAAgAD//gFAAAABQAAAFvkXYDvGtEf
'/*!*/;
### DELETE FROM `sqllearn`.`test_24`
### WHERE
###   @1=5 /* INT meta=0 nullable=0 is_null=0 */
###   @2=5 /* INT meta=0 nullable=1 is_null=0 */
###   @3=1541692800 /* TIMESTAMP(0) meta=0 nullable=0 is_null=0 */
# at 978
#190816  9:09:00 server id 1  end_log_pos 1009 CRC32 0x3f9ff1df     Xid = 54
COMMIT/*!*/;
SET @@SESSION.GTID_NEXT= 'AUTOMATIC' /* added by mysqlbinlog */ /*!*/;
DELIMITER ;
# End of log file
/*!50003 SET COMPLETION_TYPE=@OLD_COMPLETION_TYPE*/;
/*!50530 SET @@SESSION.PSEUDO_SLAVE_MODE=0*/;

可以看到以下几个信息：

server id 1，表示这个事务是在 server_id=1 的这个库上执行的。
每个 event 都有 CRC32 的值，这是因为把参数 binlog_checksum 设置成了 CRC32。
Table_map event 显示了接下来要打开的表，map 到数字 124，与上面显示相同。
现在这条 SQL 语句只操作了一张表，如果要操作多张表呢？每个表都有一个对应的Table_map event、都会 map 到一个单独的数字，用于区分对不同表的操作。
在 mysqlbinlog 的命令中，使用了 -vv 参数是为了把内容都解析出来，所以从结果里面可以看到各个字段的值（比如，@1=5、 @2=5 这些值）。
binlog_row_image 的默认配置是 FULL，因此 Delete_event 里面，包含了删掉的行的所有字段的值。如果把 binlog_row_image 设置为 MINIMAL，则只会记录必要的信息，在这个例子里，就是只会记录 id=5 这个信息。
最后的 Xid event，用于表示事务被正确地提交了。

可以看到，当 binlog_format 使用 row 格式的时候，binlog 里面记录了真实删除行的主键id，这样 binlog 传到备库去的时候，就肯定会删除 id=5 的行，不会有主备删除不同行的问题。

3.为什么会有 mixed 格式的 binlog？

因为有些 statement 格式的 binlog 可能会导致主备不一致，所以要使用 row 格式。
但 row 格式的缺点是，很占空间。比如你用一个 delete 语句删掉 10 万行数据，用statement 的话就是一个 SQL 语句被记录到 binlog 中，占用几十个字节的空间。但如果用row 格式的 binlog，就要把这 10 万条记录都写到 binlog 中。这样做，不仅会占用更大的空间，同时写 binlog 也要耗费 IO 资源，影响执行速度。
所以，MySQL 就取了个折中方案，也就是有了 mixed 格式的 binlog。mixed 格式的意思是，MySQL 自己会判断这条 SQL 语句是否可能引起主备不一致，如果有可能，就用 row 格式，否则就用 statement 格式。

mixed 格式可以利用 statment 格式的优点，同时又避免了数据不一致的风险。

因此，如果线上 MySQL 设置的 binlog 格式是 statement 的话，那基本上就可以认为这是一个不合理的设置。至少应该把 binlog 的格式设置为 mixed。

现在越来越多的场景要求把 MySQL 的 binlog 格式设置成 row。这么做的理由有很多，一个可以直接看出来的好处：恢复数据。

从上文可以看出，即使执行的是 delete 语句，row 格式的 binlog 也会把被删掉的行的整行信息保存起来。所以，如果在执行完一条 delete 语句以后，发现删错数据了，可以直接把 binlog 中记录的 delete 语句转成 insert，把被错删的数据插入回去就可以恢复了。
如果执行错了 insert 语句呢？那就更直接了。row 格式下，insert 语句的 binlog 里会记录所有的字段信息，这些信息可以用来精确定位刚刚被插入的那一行。这时，直接把 insert 语句转成 delete 语句，删除掉这被误插入的一行数据就可以了。
如果执行的是 update 语句的话，binlog 里面会记录修改前整行的数据和修改后的整行数据。所以，如果误执行了 update 语句的话，只需要把这个 event 前后的两行信息对调一下，再去数据库里面执行，就能恢复这个更新操作了。

其实，由 delete、insert 或者 update 语句导致的数据操作错误，需要恢复到操作之前状态的情况，也时有发生。MariaDB 的Flashback工具就是基于上面介绍的原理来回滚数据的。

3.1 mixed模式下执行情况

修改binlog_format=mixed，重启mysql。

insert into test_24 values(10,10, now());

mysql> show binlog events in 'mysql-bin.000003';
+------------------+------+----------------+-----------+-------------+--------------------------------------------------------------+
| Log_name         | Pos  | Event_type     | Server_id | End_log_pos | Info                                                         |
+------------------+------+----------------+-----------+-------------+--------------------------------------------------------------+

| mysql-bin.000003 |  804 | Anonymous_Gtid |         1 |         869 | SET @@SESSION.GTID_NEXT= 'ANONYMOUS'                         |
| mysql-bin.000003 |  869 | Query          |         1 |         964 | BEGIN                                                        |
| mysql-bin.000003 |  964 | Query          |         1 |        1094 | use `sqllearn`; insert into test_24 values(10,10, now())     |
| mysql-bin.000003 | 1094 | Xid            |         1 |        1125 | COMMIT /* xid=57 */

再用 mysqlbinlog 工具来看看：

mysqlbinlog -vv /var/log/mysql-bin.000003 --start-position=804;

[root@izbp15dzsx0qokz9qdqojkz log]# mysqlbinlog -vv /var/log/mysql-bin.000003 --start-position=804;
/*!50530 SET @@SESSION.PSEUDO_SLAVE_MODE=1*/;
/*!50003 SET @OLD_COMPLETION_TYPE=@@COMPLETION_TYPE,COMPLETION_TYPE=0*/;
DELIMITER /*!*/;
# at 4
#190816  9:35:48 server id 1  end_log_pos 123 CRC32 0x15c79aad  Start: binlog v 4, server v 5.7.24-log created 190816  9:35:48 at startup
# Warning: this binlog is either in use or was not closed properly.
ROLLBACK/*!*/;
BINLOG '
dAhWXQ8BAAAAdwAAAHsAAAABAAQANS43LjI0LWxvZwAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA
AAAAAAAAAAAAAAAAAAB0CFZdEzgNAAgAEgAEBAQEEgAAXwAEGggAAAAICAgCAAAACgoKKioAEjQA
Aa2axxU=
'/*!*/;
# at 804
#190816  9:39:59 server id 1  end_log_pos 869 CRC32 0x17cb6017  Anonymous_GTID  last_committed=2    sequence_number=3   rbr_only=no
SET @@SESSION.GTID_NEXT= 'ANONYMOUS'/*!*/;
# at 869
#190816  9:39:59 server id 1  end_log_pos 964 CRC32 0x637d51f3  Query   thread_id=3 exec_time=0 error_code=0
SET TIMESTAMP=1565919599/*!*/;
SET @@session.pseudo_thread_id=3/*!*/;
SET @@session.foreign_key_checks=1, @@session.sql_auto_is_null=0, @@session.unique_checks=1, @@session.autocommit=1/*!*/;
SET @@session.sql_mode=1436549152/*!*/;
SET @@session.auto_increment_increment=1, @@session.auto_increment_offset=1/*!*/;
/*!\C utf8 *//*!*/;
SET @@session.character_set_client=33,@@session.collation_connection=33,@@session.collation_server=8/*!*/;
SET @@session.time_zone='SYSTEM'/*!*/;
SET @@session.lc_time_names=0/*!*/;
SET @@session.collation_database=DEFAULT/*!*/;
BEGIN
/*!*/;
# at 964
#190816  9:39:59 server id 1  end_log_pos 1094 CRC32 0x2501beec     Query   thread_id=3 exec_time=0 error_code=0
use `sqllearn`/*!*/;
SET TIMESTAMP=1565919599/*!*/;
insert into test_24 values(10,10, now())
/*!*/;
# at 1094
#190816  9:39:59 server id 1  end_log_pos 1125 CRC32 0xd1e8ff2c     Xid = 57
COMMIT/*!*/;
SET @@SESSION.GTID_NEXT= 'AUTOMATIC' /* added by mysqlbinlog */ /*!*/;
DELIMITER ;
# End of log file
/*!50003 SET COMPLETION_TYPE=@OLD_COMPLETION_TYPE*/;
/*!50530 SET @@SESSION.PSEUDO_SLAVE_MODE=0*/;

可以看到，原来 binlog 在记录 event 的时候，多记了一条命令：SET TIMESTAMP=1565919599。它用 SET TIMESTAMP 命令约定了接下来的 now() 函数的返回时间。

因此，不论这个 binlog 是 1 分钟之后被备库执行，还是 3 天后用来恢复这个库的备份，这个insert 语句插入的行，值都是固定的。也就是说，通过这条 SET TIMESTAMP 命令，MySQL就确保了主备数据的一致性。

如下方式重放binlog是有风险的：

用 mysqlbinlog 解析出日志，然后把里面的 statement 语句直接拷贝出来执行。因为有些语句的执行结果是依赖于上下文命令的，直接执行的结果很可能是错误的。

用 binlog 来恢复数据的标准做法是，用 mysqlbinlog 工具解析出来，然后把解析结果整个发给 MySQL 执行。类似下面的命令：

mysqlbinlog /var/log/mysql-bin.000003 --start-position=2738 --stop-position=2973 | mysql -h127.0.0.1 -P13000 -u$user -p$pwd;

这个命令的意思是，将/var/log/mysql-bin.000003文件里面从第 2738 字节到第 2942 字节中间这段内容解析出来，放到 MySQL 去执行。

4.循环复制问题

binlog 的特性确保了在备库执行相同的 binlog，可以得到与主库相同的状态。实际生产上使用比较多的是双 M 结构：

双 M 结构和 M-S 结构，其实区别只是多了一条线，即：节点A 和 B 之间总是互为主备关系。

双 M 结构还有一个问题需要解决（循环复制问题）：

业务逻辑在节点 A 上更新了一条语句，然后再把生成的 binlog 发给节点 B，节点 B 执行完这条更新语句后也会生成 binlog。（建议把参数 log_slave_updates 设置为 on，表示备库执行 relay log 后生成 binlog）。
那么，如果节点 A 同时是节点 B 的备库，相当于又把节点 B 新生成的 binlog 拿过来执行了一次，然后节点 A 和 B 间，会不断地循环执行这个更新语句，也就是循环复制了。这个要怎么解决呢？

MySQL 在 binlog 中记录了这个命令第一次执行时所在实例的server id。因此，可以用下面的逻辑，来解决两个节点间的循环复制的问题：

1）规定两个库的 server id 必须不同，如果相同，则它们之间不能设定为主备关系；
2）一个备库接到 binlog 并在重放的过程中，生成与原 binlog 的 server id 相同的新的binlog；
3）每个库在收到从自己的主库发过来的日志后，先判断 server id，如果跟自己的相同，表示这个日志是自己生成的，就直接丢弃这个日志。

按照这个逻辑，如果设置了双 M 结构，日志的执行流就会变成这样：

1）从节点 A 更新的事务，binlog 里面记的都是 A 的 server id；
2）传到节点 B 执行一次以后，节点 B 生成的 binlog 的 server id 也是 A 的 server id；
3）再传回给节点 A，A 判断到这个 server id 与自己的相同，就不会再处理这个日志。所以，死循环在这里就断掉了。

问题

MySQL 通过判断 server id 的方式，断掉死循环。但是，这个机制其实并不完备，在某些场景下，还是有可能出现死循环。

Ans：

1）一种场景是，在一个主库更新事务后，用命令 set global server_id=x 修改了 server_id。等日志再传回来的时候，发现 server_id 跟自己的 server_id 不同，就只能执行了。
2）另一种场景是，有三个节点的时候，如图所示，trx1 是在节点 B 执行的，因此 binlog 上的server_id 就是 B，binlog 传给节点 A，然后 A 和 A’搭建了双 M 结构，就会出现循环复制。

解决方法：

1）如果这时候 A 和 A’上没有任何更新，可以把其中一个节点（比如 A）的 server_id 临时改成 B 的 server_id，这样循环复制就会终止。终止循环复制之后，就要再设置回这个节点（比如 A）原来的 server_id 值。
2）不过一般出现循环复制的情况，往往线上同时还有更新，这时就不能修改 server_id 了。这种情况下，我们需要先在节点 A 上执行 stop slave 命令，先停止同步；然后手动执行change master 命令，指向 A’最后一个 binlog 文件的文件末尾，再 start slave 就可以结束循环复制了。