MySQL解密-->如何查看二进制日志ROW模式下最原始的SQL语句
MySQL的binlog的ROW模式解析
在mysql5.6以后，对主从数据一致性要求变高了，statement格式逐渐不太适合业务的需求了，所以生产环境大家都采用了row模式，row模式是传输最底层的数据变化的insert的模块来进行主从数据的传输，那么在binlog里面就和普通的statement模式有何差别？能否看到最原始的sql语句呢？
1、准备录入数据
mysql> create table test1(id int,c1 varchar(20),type int,address varchar(20),create_time datetime); Query OK, 0 rows affected (0.00 sec) mysql> insert into test1 select 1,'zhangsan','1','zhangsan road No 870,floor 602',now(); ERROR 1406 (22001): Data too long for column 'address' at row 1 mysql> mysql> show create table test1; +-------+--------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+ | Table | Create Table | +-------+--------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+ | test1 | CREATE TABLE `test1` ( `id` int(11) DEFAULT NULL, `c1` varchar(20) DEFAULT NULL, `type` int(11) DEFAULT NULL, `address` varchar(20) DEFAULT NULL, `create_time` datetime DEFAULT NULL ) ENGINE=InnoDB DEFAULT CHARSET=utf8 | +-------+--------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+ 1 row in set (0.00 sec) mysql> alter table test1 modify `address` varchar(200) DEFAULT NULL; Query OK, 0 rows affected (0.03 sec) Records: 0 Duplicates: 0 Warnings: 0 mysql> insert into test1 select 1,'zhangsan','1','zhangsan road No 870,floor 602',now(); Query OK, 1 row affected (0.00 sec) Records: 1 Duplicates: 0 Warnings: 0 mysql> insert into test1 select 2,'lisi','1','zhangsan road No 870,floor 602',now(); Query OK, 1 row affected (0.01 sec) Records: 1 Duplicates: 0 Warnings: 0 mysql> |
2、Row模式binlog是乱码
Row模式下面，binlog里面的ddl语句是正常显示的，但是dml是乱码，如下所示：
[root@hch_test_dbm1_121_63 binlog]# /usr/local/mysql/bin/mysqlbinlog mysql-bin.000215 …… # 这里前面的省略 #160722 17:02:38 server id 62 end_log_pos 4291 CRC32 0x369e3244 Query thread_id=60 exec_time=4294967271 error_code=0 SET TIMESTAMP=1469178158/*!*/; CREATE DATABASE IF NOT EXISTS `percona` /* pt-table-checksum */ /*!*/; # at 4291 #160722 17:02:38 server id 62 end_log_pos 5079 CRC32 0x8abc6e67 Query thread_id=60 exec_time=4294967271 error_code=0 use `percona`/*!*/; SET TIMESTAMP=1469178158/*!*/; CREATE TABLE IF NOT EXISTS `percona`.`checksums` ( db char(64) NOT NULL, tbl char(64) NOT NULL, chunk int NOT NULL, chunk_time float NULL, chunk_index varchar(200) NULL, lower_boundary text NULL, upper_boundary text NULL, this_crc char(40) NOT NULL, this_cnt int NOT NULL, master_crc char(40) NULL, master_cnt int NULL, ts timestamp NOT NULL DEFAULT CURRENT_TIMESTAMP ON UPDATE CURRENT_TIMESTAMP, PRIMARY KEY (db, tbl, chunk), INDEX ts_db_tbl (ts, db, tbl) ) ENGINE=InnoDB /*!*/; # at 5079 #160820 10:21:10 server id 63 end_log_pos 5280 CRC32 0xd147bd8e Query thread_id=16 exec_time=0 error_code=0 SET TIMESTAMP=1471659670/*!*/; SET @@session.sql_mode=1075838976/*!*/; GRANT ALL PRIVILEGES ON *.* TO 'tim'@'192.168%' IDENTIFIED BY PASSWORD '*2976819BD2CCD13612E03F812A2CD297C1A18B23' /*!*/; # at 5280 #160820 10:22:40 server id 63 end_log_pos 5445 CRC32 0x85811be7 Query thread_id=18 exec_time=0 error_code=0 use `test`/*!*/; SET TIMESTAMP=1471659760/*!*/; create table test1(id int,c1 varchar(20),type int,address varchar(20),create_time datetime) /*!*/; # at 5445 #160820 10:24:34 server id 63 end_log_pos 5580 CRC32 0x2626220c Query thread_id=18 exec_time=0 error_code=0 SET TIMESTAMP=1471659874/*!*/; alter table test1 modify `address` varchar(200) DEFAULT NULL /*!*/; # at 5580 #160820 10:24:36 server id 63 end_log_pos 5660 CRC32 0x7b7c645f Query thread_id=18 exec_time=0 error_code=0 SET TIMESTAMP=1471659876/*!*/; SET @@session.time_zone='SYSTEM'/*!*/; BEGIN /*!*/; # at 5660 # at 5764 #160820 10:24:36 server id 63 end_log_pos 5821 CRC32 0x08bc94c3 Table_map: `test`.`test1` mapped to number 74 # at 5821 #160820 10:24:36 server id 63 end_log_pos 5911 CRC32 0x2f577f52 Write_rows: table id 74 flags: STMT_END_F BINLOG ' ZL+3VxM/AAAAOQAAAL0WAAAAAEoAAAAAAAEABHRlc3QABXRlc3QxAAUDDwMPEgU8AFgCAB/DlLwI ZL+3Vx4/AAAAWgAAABcXAAAAAEoAAAAAAAEAAgAF/+ABAAAACHpoYW5nc2FuAQAAAB4Aemhhbmdz YW4gcm9hZCBObyA4NzAsZmxvb3IgNjAymZoopiRSf1cv '/*!*/; # at 5911 #160820 10:24:36 server id 63 end_log_pos 5942 CRC32 0xb26af81b Xid = 199 COMMIT/*!*/; # at 5942 #160820 10:24:48 server id 63 end_log_pos 6022 CRC32 0x09eab31d Query thread_id=18 exec_time=0 error_code=0 SET TIMESTAMP=1471659888/*!*/; BEGIN /*!*/; # at 6022 # at 6122 #160820 10:24:48 server id 63 end_log_pos 6179 CRC32 0xdc6dc34b Table_map: `test`.`test1` mapped to number 74 # at 6179 #160820 10:24:48 server id 63 end_log_pos 6265 CRC32 0x5f7ad700 Write_rows: table id 74 flags: STMT_END_F BINLOG ' cL+3VxM/AAAAOQAAACMYAAAAAEoAAAAAAAEABHRlc3QABXRlc3QxAAUDDwMPEgU8AFgCAB9Lw23c cL+3Vx4/AAAAVgAAAHkYAAAAAEoAAAAAAAEAAgAF/+ACAAAABGxpc2kBAAAAHgB6aGFuZ3NhbiBy b2FkIE5vIDg3MCxmbG9vciA2MDKZmiimMADXel8= '/*!*/; # at 6265 #160820 10:24:48 server id 63 end_log_pos 6296 CRC32 0xf6833d28 Xid = 200 COMMIT/*!*/; # at 6296 #160820 10:31:30 server id 63 end_log_pos 6343 CRC32 0xcfcdd344 Rotate to mysql-bin.000216 pos: 4 DELIMITER ; # End of log file ROLLBACK /* added by mysqlbinlog */; /*!50003 SET COMPLETION_TYPE=@OLD_COMPLETION_TYPE*/; /*!50530 SET @@SESSION.PSEUDO_SLAVE_MODE=0*/; [root@hch_test_dbm1_121_63 binlog]# |
3、通过--base64-output=decode-rows -v来查看dml语句
执行命令是：/usr/local/mysql/bin/mysqlbinlog --base64-output=decode-rows -v mysql-bin.000215
可以看到如下效果，不过都是最原始的dml块sql语句：
[root@hch_test_dbm1_121_63 binlog]# /usr/local/mysql/bin/mysqlbinlog --base64-output=decode-rows -v mysql-bin.000215 /*!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 /*!*/; …… #160820 10:24:36 server id 63 end_log_pos 5821 CRC32 0x08bc94c3 Table_map: `test`.`test1` mapped to number 74 # at 5821 #160820 10:24:36 server id 63 end_log_pos 5911 CRC32 0x2f577f52 Write_rows: table id 74 flags: STMT_END_F ### INSERT INTO `test`.`test1` ### SET ### @1=1 ### @2='zhangsan' ### @3=1 ### @4='zhangsan road No 870,floor 602' ### @5='2016-08-20 10:24:36' # at 5911 #160820 10:24:36 server id 63 end_log_pos 5942 CRC32 0xb26af81b Xid = 199 COMMIT/*!*/; # at 5942 #160820 10:24:48 server id 63 end_log_pos 6022 CRC32 0x09eab31d Query thread_id=18 exec_time=0 error_code=0 SET TIMESTAMP=1471659888/*!*/; BEGIN /*!*/; # at 6022 # at 6122 #160820 10:24:48 server id 63 end_log_pos 6179 CRC32 0xdc6dc34b Table_map: `test`.`test1` mapped to number 74 # at 6179 #160820 10:24:48 server id 63 end_log_pos 6265 CRC32 0x5f7ad700 Write_rows: table id 74 flags: STMT_END_F ### INSERT INTO `test`.`test1` ### SET ### @1=2 ### @2='lisi' ### @3=1 ### @4='zhangsan road No 870,floor 602' ### @5='2016-08-20 10:24:48' # at 6265 #160820 10:24:48 server id 63 end_log_pos 6296 CRC32 0xf6833d28 Xid = 200 COMMIT/*!*/; # at 6296 #160820 10:31:30 server id 63 end_log_pos 6343 CRC32 0xcfcdd344 Rotate to mysql-bin.000216 pos: 4 DELIMITER ; # End of log file ROLLBACK /* added by mysqlbinlog */; /*!50003 SET COMPLETION_TYPE=@OLD_COMPLETION_TYPE*/; /*!50530 SET @@SESSION.PSEUDO_SLAVE_MODE=0*/; [root@hch_test_dbm1_121_63 binlog]# |
PS：这样是可以看到了dml的insert语句，但是只看到了最终的insert块，而看不到原始的过来的insert语句，很多时候排查问题需要原始的insert语句而不是底层的insert块。所以问题来了，如何看到最原始的insert sql语句呢？
4、通过binlog_rows_query_log_events参数来查看最原始的insert sql
（4.1）先在线设置全局的binlog_rows_query_log_events参数，刷新日志：
mysql> set binlog_rows_query_log_events=1; Query OK, 0 rows affected (0.01 sec) mysql> mysql> flush logs; Query OK, 0 rows affected (0.01 sec) mysql>exit |
（4.2）然后重新登录录入新的数据记录：
[root@hch_test_dbm1_121_63 ~]# mysql -utim -ptimgood -h192.168.121.63 Warning: Using a password on the command line interface can be insecure. Welcome to the MySQL monitor. Commands end with ; or \g. Your MySQL connection id is 19 Server version: 5.6.12-log Source distribution Copyright (c) 2000, 2013, Oracle and/or its affiliates. All rights reserved. Oracle is a registered trademark of Oracle Corporation and/or its affiliates. Other names may be trademarks of their respective owners. Type 'help;' or '\h' for help. Type '\c' to clear the current input statement. mysql> mysql> use test; Database changed mysql> insert into test1 select 3,'wanger','3','zhangsan road No 870,floor 603',now(); Query OK, 1 row affected (0.00 sec) Records: 1 Duplicates: 0 Warnings: 0 mysql> |
（4.3）解析binlog，没有看到原始的insert语句
[root@hch_test_dbm1_121_63 binlog]# /usr/local/mysql/bin/mysqlbinlog --base64-output=decode-rows -v mysql-bin.000216 >1.sql [root@hch_test_dbm1_121_63 binlog]# more 1.sql /*!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 #160820 10:31:30 server id 63 end_log_pos 120 CRC32 0x1e4d0366 Start: binlog v 4, server v 5.6.12-log created 160820 10:31:30 # Warning: this binlog is either in use or was not closed properly. # at 120 #160820 10:32:04 server id 63 end_log_pos 200 CRC32 0xab0e625e Query thread_id=19 exec_time=0 error_code=0 SET TIMESTAMP=1471660324/*!*/; SET @@session.pseudo_thread_id=19/*!*/; 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 utf8 *//*!*/; SET @@session.character_set_client=33,@@session.collation_connection=33,@@session.collation_server=33/*!*/; SET @@session.time_zone='SYSTEM'/*!*/; SET @@session.lc_time_names=0/*!*/; SET @@session.collation_database=DEFAULT/*!*/; BEGIN /*!*/; # at 200 # at 302 #160820 10:32:04 server id 63 end_log_pos 359 CRC32 0x41bf2876 Table_map: `test`.`test1` mapped to number 74 # at 359 #160820 10:32:04 server id 63 end_log_pos 447 CRC32 0x1a3ab3d8 Write_rows: table id 74 flags: STMT_END_F ### INSERT INTO `test`.`test1` ### SET ### @1=3 ### @2='wanger' ### @3=3 ### @4='zhangsan road No 870,floor 603' ### @5='2016-08-20 10:32:04' # at 447 #160820 10:32:04 server id 63 end_log_pos 478 CRC32 0xc5081021 Xid = 208 COMMIT/*!*/; DELIMITER ; # End of log file ROLLBACK /* added by mysqlbinlog */; /*!50003 SET COMPLETION_TYPE=@OLD_COMPLETION_TYPE*/; /*!50530 SET @@SESSION.PSEUDO_SLAVE_MODE=0*/; [root@hch_test_dbm1_121_63 binlog]# |
（4.4）通过mysql的命令行查看最原始的insert sql语句，如下所示：
mysql> show binlog events in 'mysql-bin.000216'; +------------------+-----+-------------+-----------+-------------+----------------------------------------------------------------------------------+ | Log_name | Pos | Event_type | Server_id | End_log_pos | Info | +------------------+-----+-------------+-----------+-------------+----------------------------------------------------------------------------------+ | mysql-bin.000216 | 4 | Format_desc | 63 | 120 | Server ver: 5.6.12-log, Binlog ver: 4 | | mysql-bin.000216 | 120 | Query | 63 | 200 | BEGIN || mysql-bin.000216 | 200 | Rows_query | 63 | 302 | # insert into test1 select 3,'wanger','3','zhangsan road No 870,floor 603',now() || mysql-bin.000216 | 302 | Table_map | 63 | 359 | table_id: 74 (test.test1) | | mysql-bin.000216 | 359 | Write_rows | 63 | 447 | table_id: 74 flags: STMT_END_F | | mysql-bin.000216 | 447 | Xid | 63 | 478 | COMMIT /* xid=208 */ | +------------------+-----+-------------+-----------+-------------+----------------------------------------------------------------------------------+ 6 rows in set (0.00 sec) mysql> |
5、试验总结
基于以上的试验，可以得出在row模式下，可以通过mysqlbinlog --base64-output=decode-rows –v查看最底层的insert数据模块，也可以通过命令行show binlog events in 'mysql-bin.000216';来实时查看最原始的insertsql记录。
我们可以在搭建数据库的时候，在启动参数文件my.cnf里面事先设置好，如下所示：
# vim my.cnf [mysqld] binlog_format=row # binlog 日志格式 binlog_rows_query_log_events = 1 # 将原始的操作sql记录写入事件中 |