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 1mysql>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记录写入事件中