【Mysql 实战】问题分析利器之 binlog

公众号：程序员架构进阶

文章链接：https://mp.weixin.qq.com/s/JOhdZE6ctDI0y53G_qXR8w

一 摘要

   在【Mysql-InnoDB 系列】事务提交过程及系列文章中，对mysql（InnoDB引擎）的redolog、undolog、binlog及事务的提交过程有了一些介绍，本篇将尝试去实践binlog在日常操作中的查看、分析方式，以及可能遇到的问题和解决方法。

二 binlog的位置

2.1 寻找方式

2.1.1 文件遍历

   直接简单粗暴地根据命名查找，因为binlog文件通常都是mysql-bin.000001这样的命名方式，所以sudo find / -name mysql-bin.000001即可。但效率低下，所以一般不会这样查找。

2.1.2 配置文件

   可以通过配置文件查看，Linux/Mac系统中通常是/etc/my.cnf。在实际查找时，也可以查看配置文件使用的优先级，mysql提供了相关的命令：mysqld --verbose --help | grep -A 1 'Default options'

在本地执行后的结果如下：

xxx$ mysqld --verbose --help | grep -A 1 'Default options'
Default options are read from the following files in the given order:
/etc/my.cnf /etc/mysql/my.cnf /usr/local/etc/my.cnf ~/.my.cnf 

可见，mysql加载配置文件的优先级是：

1、/etc/my.cnf

2、/etc/mysql/my.cnf

3、/usr/local/etc/my.cnf

4、~/.my.cnf

本地配置了/etc/my.cnf，所以直接vi /etc/my.cnf查看即可。内容如下：

图1 my.cnf

标红的部分就是binlog的目录。

此时目录下的文件列表：

图2 binlog目录下文件列表

2.2 客户端常用命令

2.2.1 查看开启状态及基本配置

命令：show variables like 'log_%';

可以查看binlog的相关信息（也可以通过这种方式查看binlog位置），log_bin的value，ON表示开启，否则关闭：

图3 客户端SQL查询binlog配置

2.2.2 查看所有binlog日志列表

命令：show master logs;

图4 查看binlog列表命令

2.2.3 查看最新一个binlog日志的编号名称，及其最后一个操作事件结束点 

命令：show master status;

图5 查看binlog最后一个编号命令

2.2.4 清空binlog日志

命令：reset master;

三 查看方法

3.1 直接查看内容

cat mysql-bin.000022 查看文件内容：

图6 直接查看binlog文本

有很多乱码，同时也能大概看出一部分以往的操作，例如两个建表语句。

3.2 正确方式

3.2.1 mysqlbinlog

   mysql本身提供了binlog的查看工具：mysqlbinlog，与mysqld、mysql同位于mysql的bin目录下。使用方式为：mysqlbinlog 【binlog文件路径】。例如在我们刚才查到的binlog目录下，mysqlbinlog mysql-bin.000022：

图7 mysqlbinlog报错信息

很遗憾，出了点小问题，抛了unknown variable 'default-character-set=utf8mb4'的错误。到本文上面翻一下my.cnf，可以看到其中配置了默认字符集，而mysqlbinlog表示无法识别。

3.2.2 解决方法

Mysql操作binlog时报错这篇文章中提到过两种方法，第一种是修改配置，把default-character-set=utf8mb4 修改为 character-set-server = utf8mb4，但这种方式需要修改my.cnf并重启mysql服务。生产环境显然不适合。而且本地版本（5.7.28）如此操作后，发现也并没有解决问题，所以跳过。

方法二：

mysqlbinlog --no-defaults mysql-bin.000022

经验证可以生效，查询结果如下：

图8 mysqlbinlog查询结果

与图6直接查看文本的结果对比，可以看到不再有乱码，我们可以据此分析mysql操作过程中产生的binlog，并进而分析线上问题。

四 一个真实的问题分析案例

4.1 案例操作重现

案例篇 | 记一次 MySQL 主从双写导致的数据丢失问题 这篇文章中提到了两台互为主从的机器上都进行了写入导致数据丢失的排查记录，使用的主要方法就是分析binlog（Row格式下的RelayLog重放）。

我们尝试在本地复现其中章节：二、Row 格式下 RelayLog 的重放 的内容，在本地分析update语句带来的binlog变更：

mysqlbinlog --no-defaults mysql-bin.000025查看，binlog的内容如下：

# at 291
#210323 12:05:11 server id 1  end_log_pos 346 CRC32 0xa9ba861a 	Table_map: `test`.`t20200709` mapped to number 108
# at 346
#210323 12:05:11 server id 1  end_log_pos 402 CRC32 0x32082f49 	Update_rows: table id 108 flags: STMT_END_F

BINLOG '
92hZYBMBAAAANwAAAFoBAAAAAGwAAAAAAAEABHRlc3QACXQyMDIwMDcwOQACAw8CkAEAGoa6qQ==
92hZYB8BAAAAOAAAAJIBAAAAAGwAAAAAAAEAAgAC///8AQAAAAUAbmFtZTT8AQAAAAEAMUkvCDI=
'/*!*/;
# at 402
#210323 12:05:11 server id 1  end_log_pos 433 CRC32 0x03c4c109 	Xid = 9
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下出现了类似base64编码后的结果，而不是Update语句，是否是日志格式的问题？查看binlog格式配置，使用命令: show variables like '%binlog%';

图片

日志格式确实是ROW，有讨论说在MIX格式下会出现乱码，那么我们的这个就不是binlog_format的问题了，继续尝试其他方法。在mysqlbinlog解析binlog乱码问题解密 中找到了一种方法，通过--base64-output=DECODE-ROWS -v 参数来格式化输出binlog中的Base64部分，输出如下（因为后续有操作，又生成了一个新的binlog文件）：

bogon:logs qingclass$ mysqlbinlog --base64-output=DECODE-ROWS -v mysql-bin.000026
/*!50530 SET @@SESSION.PSEUDO_SLAVE_MODE=1*/;
/*!50003 SET @OLD_COMPLETION_TYPE=@@COMPLETION_TYPE,COMPLETION_TYPE=0*/;
DELIMITER /*!*/;
# at 4
#210323 12:17:23 server id 1  end_log_pos 123 CRC32 0x4d34b223 	Start: binlog v 4, server v 5.7.28-log created 210323 12:17:23 at startup
# Warning: this binlog is either in use or was not closed properly.
ROLLBACK/*!*/;
# at 123
#210323 12:17:23 server id 1  end_log_pos 154 CRC32 0xffc92a6d 	Previous-GTIDs
# [empty]
# at 154
#210323 12:17:53 server id 1  end_log_pos 219 CRC32 0x9fc36419 	Anonymous_GTID	last_committed=0	sequence_number=1	rbr_only=yes
/*!50718 SET TRANSACTION ISOLATION LEVEL READ COMMITTED*//*!*/;
SET @@SESSION.GTID_NEXT= 'ANONYMOUS'/*!*/;
# at 219
#210323 12:17:53 server id 1  end_log_pos 291 CRC32 0x4fc28ff1 	Query	thread_id=2	exec_time=0	error_code=0
SET TIMESTAMP=1616473073/*!*/;
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 utf8mb4 *//*!*/;
SET @@session.character_set_client=45,@@session.collation_connection=45,@@session.collation_server=45/*!*/;
SET @@session.lc_time_names=0/*!*/;
SET @@session.collation_database=DEFAULT/*!*/;
BEGIN
/*!*/;
# at 291
#210323 12:17:53 server id 1  end_log_pos 346 CRC32 0x2f8d89e1 	Table_map: `test`.`t20200709` mapped to number 108
# at 346
#210323 12:17:53 server id 1  end_log_pos 398 CRC32 0xca0f72bd 	Update_rows: table id 108 flags: STMT_END_F
### UPDATE `test`.`t20200709`
### WHERE
###   @1=1
###   @2='5'
### SET
###   @1=1
###   @2='4'
# at 398
#210323 12:17:53 server id 1  end_log_pos 429 CRC32 0x5ce7c021 	Xid = 2
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*/;

在第32行，终于看到了预期的结果：

图9 关键语句日志

4.2 binlog格式问题分析

Mysql官方文档中有binlog格式的详细描述：5.4.4.1 Binary Logging Formats，包括:STATEMENT，ROW，MIXED三种格式。

• Replication capabilities in MySQL originally were based on propagation of SQL statements from source to replica. This is called statement-based logging. You can cause this format to be used by starting the server with --binlog-format=STATEMENT.
• In row-based logging, the source writes events to the binary log that indicate how individual table rows are affected. It is important therefore that tables always use a primary key to ensure rows can be efficiently identified. You can cause the server to use row-based logging by starting it with --binlog-format=ROW.
• A third option is also available: mixed logging. With mixed logging, statement-based logging is used by default, but the logging mode switches automatically to row-based in certain cases as described below. You can cause MySQL to use mixed logging explicitly by starting mysqld with the option --binlog-format=MIXED.

翻译过来：

1、MySQL中的复制功能最初是基于SQL语句从源到副本的传播。这称为基于语句的日志记录。可以通过mysqld命令，指定--binlog-format=STATEMENT参数来启动服务；

2、在基于行的日志记录中，源将事件写入二进制日志，以指示单个表行如何受到影响。因此，表始终使用主键来确保可以有效地标识行是很重要的；可以通过mysqld命令，指定--binlog-format=ROW参数来启动服务；

3、还有第三种选择：混合日志记录。对于混合日志记录，默认情况下使用基于语句的日志记录，但在某些情况下，日志记录模式会自动切换到基于行的日志记录。可以通过mysqld命令，指定--binlog-format=MIXED参数来启动服务。

不过需要注意，STATEMENT格式在生产环境应该很少使用，因为类似于：

INSERT INTO access_log.access_log VALUES(NULL,CONNECTION_ID(),NOW(),USER(),CURRENT_USER());

这里的一些函数最好用row模式，因为主从复制的时候，uuid已经now()等会造成时间延迟，故而为了数据一致性，STATEMENT格式不是最佳选择。

5.4.4.2 Setting The Binary Log Format也指出，可以通过下面语句在全局中设置binlog_format：

mysql> SET GLOBAL binlog_format = 'STATEMENT';
mysql> SET GLOBAL binlog_format = 'ROW';
mysql> SET GLOBAL binlog_format = 'MIXED';

也可以仅在当前会话中设置：

mysql> SET SESSION binlog_format = 'STATEMENT';
mysql> SET SESSION binlog_format = 'ROW';
mysql> SET SESSION binlog_format = 'MIXED';

五 总结

   本文由一个看到的真实案例分享开始，引起对binlog的学习和基础操作。在复现操作的过程中，遇到并解决了一些问题。希望可以对大家有一定的参考作用。