mysqlbinlog解析binlog乱码问题解密
- PHP中文网Original
- 2017-03-31 16:51:453397browse
发现mysql库的binlog日志出来都是乱码，如下所示：
BINLOG ’
IXZqVhNIAAAALQAAAGcBAAAAAHoAAAAAAAEABHRlc3QAAno0AAEDAABUOcnY
IXZqVh5IAAAAKAAAAI8BAAAAAHoAAAAAAAEAAgAB//4BAAAAcu+UpA==，如果强行用-v出来也得不到具体执行的sql语句，这个问题困扰了很近，今天深入研究才发现核心问题所在。
1，binlog日志的困扰，先看下日志格式
mysql> show variables like '%binlog%'; +-----------------------------------------+----------------------+ | Variable_name | Value | +-----------------------------------------+----------------------+ | binlog_cache_size | 1048576 | | binlog_checksum | CRC32 | | binlog_direct_non_transactional_updates | OFF | | binlog_format | MIXED | | 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 | | innodb_api_enable_binlog | OFF | | innodb_locks_unsafe_for_binlog | OFF | | max_binlog_cache_size | 18446744073709547520 | | max_binlog_size | 1073741824 | | max_binlog_stmt_cache_size | 18446744073709547520 | | sync_binlog | 1 | +-----------------------------------------+----------------------+ 15 rows in set (0.01 sec) mysql>
日志格式是MIXED的，这个表示一些特殊的uuid以及now()之类会记录成row，其它的仍然是记录sql模式。
2，测试例子：
mysql> use test; Reading table information for completion of table and column names You can turn off this feature to get a quicker startup with -A Database changed mysql> create table z4 select 1 as a; Query OK, 1 row affected (0.02 sec) Records: 1 Duplicates: 0 Warnings: 0 mysql> insert into z4 select 2; Query OK, 1 row affected (0.00 sec) Records: 1 Duplicates: 0 Warnings: 0 mysql>
blog为csdn博主黄杉(mchdba)所有，原地址为：http://blog.csdn.net/mchdba/article/details/50300035，谢绝转载。
3，查看binlog，打开是乱码模式，看不到执行的sql语句，如下所示
[[email protected] binlog_new]# ll 总用量 32 -rw-rw----. 1 mysql mysql 143 12月 10 21:09 mysql-bin.000001 -rw-rw----. 1 mysql mysql 17549 12月 11 15:06 mysql-bin.000002 -rw-rw----. 1 mysql mysql 618 12月 11 15:07 mysql-bin.000003 -rw-rw----. 1 mysql mysql 135 12月 11 15:06 mysql-bin.index [[email protected] binlog_new]# /usr/local/mysql/bin/mysqlbinlog mysql-bin.000003 /*!50530 SET @@SESSION.PSEUDO_SLAVE_MODE=1*/; /*!40019 SET @@session.max_insert_delayed_threads=0*/; /*!50003 SET @OLD_COMPLETION_TYPE=@@COMPLETION_TYPE,COMPLETION_TYPE=0*/; DELIMITER /*!*/; # at 4 #151211 15:06:46 server id 72 end_log_pos 120 CRC32 0x9961ff72 Start: binlog v 4, server v 5.6.12-log created 151211 15:06:46 # Warning: this binlog is either in use or was not closed properly. BINLOG ' BnZqVg9IAAAAdAAAAHgAAAABAAQANS42LjEyLWxvZwAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA AAAAAAAAAAAAAAAAAAAAAAAAEzgNAAgAEgAEBAQEEgAAXAAEGggAAAAICAgCAAAACgoKGRkAAXL/ YZk= '/*!*/; # at 120 #151211 15:07:13 server id 72 end_log_pos 192 CRC32 0x3ea43b0e Query thread_id=732 exec_time=0 error_code=0 SET TIMESTAMP=1449817633/*!*/; SET @@session.pseudo_thread_id=732/*!*/; SET @@session.foreign_key_checks=1, @@session.sql_auto_is_null=0, @@session.unique_checks=1, @@session.autocommit=1/*!*/; SET @@session.sql_mode=1075838976/*!*/; 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 192 #151211 15:07:13 server id 72 end_log_pos 314 CRC32 0xcaec51ae Query thread_id=732 exec_time=0 error_code=0 use `test`/*!*/; SET TIMESTAMP=1449817633/*!*/; CREATE TABLE `z4` ( `a` int(1) NOT NULL DEFAULT '0' ) /*!*/; # at 314 #151211 15:07:13 server id 72 end_log_pos 359 CRC32 0xd8c93954 Table_map: `test`.`z4` mapped to number 122 # at 359 #151211 15:07:13 server id 72 end_log_pos 399 CRC32 0xa494ef72 Write_rows: table id 122 flags: STMT_END_F BINLOG ' IXZqVhNIAAAALQAAAGcBAAAAAHoAAAAAAAEABHRlc3QAAno0AAEDAABUOcnY IXZqVh5IAAAAKAAAAI8BAAAAAHoAAAAAAAEAAgAB//4BAAAAcu+UpA== '/*!*/; # at 399 #151211 15:07:13 server id 72 end_log_pos 430 CRC32 0xd1ab5b55 Xid = 6908 COMMIT/*!*/; # at 430 #151211 15:07:20 server id 72 end_log_pos 502 CRC32 0xdfc3212d Query thread_id=732 exec_time=0 error_code=0 SET TIMESTAMP=1449817640/*!*/; BEGIN /*!*/; # at 502 #151211 15:07:20 server id 72 end_log_pos 547 CRC32 0xc59aab0e Table_map: `test`.`z4` mapped to number 122 # at 547 #151211 15:07:20 server id 72 end_log_pos 587 CRC32 0x648b02a4 Write_rows: table id 122 flags: STMT_END_F BINLOG ' KHZqVhNIAAAALQAAACMCAAAAAHoAAAAAAAEABHRlc3QAAno0AAEDAAAOq5rF KHZqVh5IAAAAKAAAAEsCAAAAAHoAAAAAAAEAAgAB//4CAAAApAKLZA== '/*!*/; # at 587 #151211 15:07:20 server id 72 end_log_pos 618 CRC32 0x9b35600a Xid = 6915 COMMIT/*!*/; DELIMITER ; # End of log file ROLLBACK /* added by mysqlbinlog */; /*!50003 SET COMPLETION_TYPE=@OLD_COMPLETION_TYPE*/; /*!50530 SET @@SESSION.PSEUDO_SLAVE_MODE=0*/; [[email protected] binlog_new]#
PS：大家看到/usr/local/mysql/bin/mysqlbinlog mysql-bin.000003解析出来的都是KHZqVhNIAAAALQAAACMCAAAAAHoAAAA这样的乱码格式。
4，google，得知可以用–base64-output=DECODE-ROWS -v查看出来sql语句，如下所示
[[email protected] binlog_new]# /usr/local/mysql/bin/mysqlbinlog --base64-output=DECODE-ROWS -v mysql-bin.000003 /*!50530 SET @@SESSION.PSEUDO_SLAVE_MODE=1*/; /*!40019 SET @@session.max_insert_delayed_threads=0*/; /*!50003 SET @OLD_COMPLETION_TYPE=@@COMPLETION_TYPE,COMPLETION_TYPE=0*/; DELIMITER /*!*/; # at 4 #151211 15:06:46 server id 72 end_log_pos 120 CRC32 0x9961ff72 Start: binlog v 4, server v 5.6.12-log created 151211 15:06:46 # Warning: this binlog is either in use or was not closed properly. # at 120 #151211 15:07:13 server id 72 end_log_pos 192 CRC32 0x3ea43b0e Query thread_id=732 exec_time=0 error_code=0 SET TIMESTAMP=1449817633/*!*/; SET @@session.pseudo_thread_id=732/*!*/; SET @@session.foreign_key_checks=1, @@session.sql_auto_is_null=0, @@session.unique_checks=1, @@session.autocommit=1/*!*/; SET @@session.sql_mode=1075838976/*!*/; 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 192 #151211 15:07:13 server id 72 end_log_pos 314 CRC32 0xcaec51ae Query thread_id=732 exec_time=0 error_code=0 use `test`/*!*/; SET TIMESTAMP=1449817633/*!*/; CREATE TABLE `z4` ( `a` int(1) NOT NULL DEFAULT '0' ) /*!*/; # at 314 #151211 15:07:13 server id 72 end_log_pos 359 CRC32 0xd8c93954 Table_map: `test`.`z4` mapped to number 122 # at 359 #151211 15:07:13 server id 72 end_log_pos 399 CRC32 0xa494ef72 Write_rows: table id 122 flags: STMT_END_F ### INSERT INTO `test`.`z4` ### SET ### @1=1 # at 399 #151211 15:07:13 server id 72 end_log_pos 430 CRC32 0xd1ab5b55 Xid = 6908 COMMIT/*!*/; # at 430 #151211 15:07:20 server id 72 end_log_pos 502 CRC32 0xdfc3212d Query thread_id=732 exec_time=0 error_code=0 SET TIMESTAMP=1449817640/*!*/; BEGIN /*!*/; # at 502 #151211 15:07:20 server id 72 end_log_pos 547 CRC32 0xc59aab0e Table_map: `test`.`z4` mapped to number 122 # at 547 #151211 15:07:20 server id 72 end_log_pos 587 CRC32 0x648b02a4 Write_rows: table id 122 flags: STMT_END_F ### INSERT INTO `test`.`z4` ### SET ### @1=2 # at 587 #151211 15:07:20 server id 72 end_log_pos 618 CRC32 0x9b35600a Xid = 6915 COMMIT/*!*/; DELIMITER ; # End of log file ROLLBACK /* added by mysqlbinlog */; /*!50003 SET COMPLETION_TYPE=@OLD_COMPLETION_TYPE*/; /*!50530 SET @@SESSION.PSEUDO_SLAVE_MODE=0*/; [[email protected] binlog_new]#
确实可以看到sql语句，不过都是row模式的，如下所示：
### INSERT INTO `test`.`z4` ### SET ### @1=2 # at 587
看到不到应用程序或者客户端执行的真正sql语句，这样也不利于进行业务分析数据分析，无助于对程序的优化。
5，问题分析
这样binlog日志格式MIXED都录制为乱码，那我将换成STATEMENT格式看看是否会持续乱码？，修改完my.cnf后，重启mysql数据库，开始建表测试，但是报错如下：
mysql> create table z3 select 1 as a; ERROR 1665 (HY000): Cannot execute statement: impossible to write to binary log since BINLOG_FORMAT = STATEMENT and at least one table uses a storage engine limited to row-based logging. InnoDB is limited to row-logging when transaction isolation level is READ COMMITTED or READ UNCOMMITTED. mysql>
问题发现了，看到问题贺新郎，隔离级别太低了，我的默认隔离级别是READ-COMMITTED，所以导致binlog记录的必须都是row模式，解析出来的是乱码，强行用-v显示出来也是row模式，所以我将隔离级别升级为REPEATABLE-READ的话，就会有row格式也会有statement格式了。接下来为了用2个小实例来验证我的判断：
4.1 REPEATABLE-READ和STATEMENT测试结果
**所以我将隔离级别升级为REPEATABLE-READ，binlog设置为binlog_format=STATEMENT
如下所示：**
# Set the default transaction isolation level. Levels available are: # READ-UNCOMMITTED, READ-COMMITTED, REPEATABLE-READ, SERIALIZABLE transaction_isolation = REPEATABLE-READ binlog_format=STATEMENT
然后重启mysql，看binlog的记录形式是啥样的，如下所示：
BEGIN /*!*/; # at 219 # at 251 #151211 16:15:02 server id 72 end_log_pos 251 CRC32 0x4ea440db Intvar SET INSERT_ID=10550/*!*/; #151211 16:15:02 server id 72 end_log_pos 435 CRC32 0xa37c5f2d Query thread_id=1 exec_time=0 error_code=0 use `parking_db`/*!*/; SET TIMESTAMP=1449821702/*!*/; INSERT INTO access_log.access_log VALUES(NULL,CONNECTION_ID(),NOW(),USER(),CURRENT_USER()) /*!*/; # at 435 #151211 16:15:02 server id 72 end_log_pos 466 CRC32 0x2970e89a Xid = 3 COMMIT/*!*/; # at 466 #151211 16:16:22 server id 72 end_log_pos 569 CRC32 0xbe43b367 Query thread_id=2 exec_time=0 error_code=0 use `test`/*!*/; SET TIMESTAMP=1449821782/*!*/; create table z4 select 1 as a /*!*/; # at 569 #151211 16:16:32 server id 72 end_log_pos 648 CRC32 0x69b2383c Query thread_id=2 exec_time=0 error_code=0 SET TIMESTAMP=1449821792/*!*/; BEGIN /*!*/; # at 648 #151211 16:16:32 server id 72 end_log_pos 745 CRC32 0xcd1721a4 Query thread_id=2 exec_time=0 error_code=0 SET TIMESTAMP=1449821792/*!*/; insert into z4 select 2 /*!*/; # at 745 #151211 16:16:32 server id 72 end_log_pos 776 CRC32 0xfc0dcfc4 Xid = 70 COMMIT/*!*/; DELIMITER ; # End of log file ROLLBACK /* added by mysqlbinlog */; /*!50003 SET COMPLETION_TYPE=@OLD_COMPLETION_TYPE*/; /*!50530 SET @@SESSION.PSEUDO_SLAVE_MODE=0*/; [[email protected] binlog_new]#
看到有类似的INSERT INTO access_log.access_log VALUES(NULL,CONNECTION_ID(),NOW(),USER(),CURRENT_USER())这里的一些函数最好用row模式，因为主从复制的时候，uuid已经now()等会造成时间延迟，故而为了数据一致性，statement格式不是最佳选择。
4.2 REPEATABLE-READ和MIXED测试结果
my.cnf里面修改设置：
transaction_isolation = REPEATABLE-READ binlog_format=MIXED
重启mysql数据库后，录入测试数据：
mysql> insert into z4 select 3; Query OK, 1 row affected (0.00 sec) Records: 1 Duplicates: 0 Warnings: 0 mysql> exit
查看binlog数据，会看到insert into z4 select 3这条sql记录，表明在mixed模式下，解析出来的sql是正常的，有些now()已经uuid的直接解析成row格式了，如下所示：
[[email protected] binlog_new]# /usr/local/mysql/bin/mysqlbinlog --base64-output=DECODE-ROWS -v mysql-bin.000007 ... # at 274 #151211 16:21:02 server id 72 end_log_pos 368 CRC32 0x156a1c51 Write_rows: table id 70 flags: STMT_END_F ### INSERT INTO `access_log`.`access_log` ### SET ### @1=10551 ### @2=1 ### @3=1449822062 ### @4='[email protected]' ### @5='[email protected]%' # at 368 #151211 16:21:02 server id 72 end_log_pos 399 CRC32 0x8254defe Xid = 3 COMMIT/*!*/; # at 399 #151211 16:21:25 server id 72 end_log_pos 478 CRC32 0xe252f5c7 Query thread_id=2 exec_time=0 error_code=0 SET TIMESTAMP=1449822085/*!*/; BEGIN /*!*/; # at 478 #151211 16:21:25 server id 72 end_log_pos 575 CRC32 0x34308ad6 Query thread_id=2 exec_time=0 error_code=0 use `test`/*!*/; SET TIMESTAMP=1449822085/*!*/; insert into z4 select 3 /*!*/; # at 575 #151211 16:21:25 server id 72 end_log_pos 606 CRC32 0x67c460eb Xid = 61 COMMIT/*!*/; DELIMITER ; # End of log file ROLLBACK /* added by mysqlbinlog */; /*!50003 SET COMPLETION_TYPE=@OLD_COMPLETION_TYPE*/; /*!50530 SET @@SESSION.PSEUDO_SLAVE_MODE=0*/; [[email protected] binlog_new]#
Statement：
The content of this article is voluntarily contributed by netizens, and the copyright belongs to the original author. This site does not assume corresponding legal responsibility. If you find any content suspected of plagiarism or infringement, please contact admin@php.cn
Previous article：MySQL分区总结_MySQLNext article：Mysql优化--skip-name-resolve_MySQL