Bilog parameter in MySQL: binlog_rows_query_log_events

When using RBR, that is, line format, to parse binlog, it is necessary to reverse to analyze the corresponding original SQL, and the corresponding content is each specific line change. Of course, you can turn on general log, but if all we need is to record the corresponding row changes, instead of recording the normal queries of these select s, because general log will record all the operations online. This function is suitable for us to audit statistics, but not for us to judge transactions, so we use binlog_rows_query_log_events to check. Look. The analysis in the official website is as follows

 binlog_rows_query_log_events

The binlog_rows_query_log_events system variable affects row-based logging only. When enabled, it causes a MySQL 5.6.2 or later server 
to write informational log events such as row query log events into its binary log. This information can be used for debugging and related purposes; 
such as obtaining the original query issued on the master when it cannot be reconstructed from the row updates.

These events are normally ignored by MySQL programs reading the binary log and so cause no issues when replicating or restoring from backup. 
To view them, increase the verbosity level by using mysqlbinlog's --verbose option twice, either as "-vv" or "--verbose --verbose".  

 

As you can see, it is a dynamic, global, conversational variable that can be turned on and off through SQL mode.

Use in the Unopened State

[root@localhost][boss]> flush logs;
Query OK, 0 rows affected (0.90 sec)

[root@localhost][boss]> flush logs;
Query OK, 0 rows affected (0.18 sec)

[root@gzx-master-01 logs]# ll
total 8977656
-rw-r----- 1 mysql mysql      79405 Apr 24 08:42 error.log
-rw-r----- 1 mysql mysql        217 Mar 10 10:42 mysql_bin.000013
-rw-r----- 1 mysql mysql  658363086 Apr 24 08:43 mysql_bin.000027
-rw-r----- 1 mysql mysql        241 Apr 24 08:43 mysql_bin.000028
-rw-r----- 1 mysql mysql        194 Apr 24 08:43 mysql_bin.000029
-rw-r----- 1 mysql mysql 194 Apr 24 08:53 mysql_bin.000030

-rw-r----- 1 mysql mysql 132 Apr 24 08:43 mysql_bin.index

-rw-r----- 1 mysql mysql 8534643198 Apr 24 08:43 slow.log  

At present, the latest binlog switch to 30 files, do the corresponding DML

[root@localhost][boss]> select * from t;
+------+
| id   |
+------+
|    1 |
|    1 |
|    1 |
|    1 |
|    1 |
|    2 |
|    2 |
|    2 |
|    3 |
|    3 |
|    7 |
+------+
11 rows in set (0.00 sec)

[root@localhost][boss]> update t set id = 8 where id=7;
Query OK, 1 row affected (0.07 sec)
Rows matched: 1  Changed: 1  Warnings: 0

[root@localhost][boss]> select * from t;
+------+
| id   |
+------+
|    1 |
|    1 |
|    1 |
|    1 |
|    1 |
|    2 |
|    2 |
|    2 |
|    3 |
|    3 |
|    8 |
+------+
11 rows in set (0.00 sec) 

View binlog

[root@gzx-master-01 logs]# mysqlbinlog --no-defaults -v -v --base64-output=DECODE-ROWS mysql_bin.000030 
/*!50530 SET @@SESSION.PSEUDO_SLAVE_MODE=1*/;
/*!50003 SET @OLD_COMPLETION_TYPE=@@COMPLETION_TYPE,COMPLETION_TYPE=0*/;
DELIMITER /*!*/;
# at 4
#170424  8:58:35 server id 37306  end_log_pos 123 CRC32 0x48e80ee3     Start: binlog v 4, server v 5.7.17-log created 170424  8:58:35
# Warning: this binlog is either in use or was not closed properly.
# at 123
#170424  8:58:35 server id 37306  end_log_pos 194 CRC32 0xaf41def6     Previous-GTIDs
# a0c06ec7-fef0-11e6-9f85-525400a7d662:1-812
# at 194
#170424  8:58:52 server id 37306  end_log_pos 259 CRC32 0xac26b3b1     GTID    last_committed=sequence_number=1
SET @@SESSION.GTID_NEXT= 'a0c06ec7-fef0-11e6-9f85-525400a7d662:813'/*!*/;
# at 259
#170424  8:58:52 server id 37306  end_log_pos 331 CRC32 0xb56db594     Query    thread_id=34   exec_time=0    error_code=0
SET TIMESTAMP=1492995532/*!*/;
SET @@session.pseudo_thread_id=34/*!*/;
SET @@session.foreign_key_checks=1, @@session.sql_auto_is_null=0, @@session.unique_checks=1, @@session.autocommit=1/*!*/;
SET @@session.sql_mode=1436549120/*!*/;
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.lc_time_names=0/*!*/;
SET @@session.collation_database=DEFAULT/*!*/;
BEGIN
/*!*/;
# at 331
#170424  8:58:52 server id 37306  end_log_pos 385 CRC32 0x88acf1be     Rows_query

# at 429
#170424  8:58:52 server id 37306  end_log_pos 475 CRC32 0xf2505403     Update_rows: table id 118 flags: STMT_END_F
### UPDATE `boss`.`t`
### WHERE
###   @1=7 /* INT meta=0 nullable=1 is_null=0 */
### SET
###   @1=8 /* INT meta=0 nullable=1 is_null=0 */
# at 475
#170424  8:58:52 server id 37306  end_log_pos 506 CRC32 0xefebd387     Xid = 2444
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*/;

 

Here we will only record in detail each piece of information for the corresponding change line, so if we open it

[root@localhost][(none)]> set global binlog_rows_query_log_events=on;

 

Execute approximate SQL again, query log discovery

[root@localhost][boss]> set global binlog_rows_query_log_events=on;
Query OK, 0 rows affected (0.00 sec)

[root@localhost][boss]> flush logs;
Query OK, 0 rows affected (0.41 sec)

[root@localhost][boss]> update t set id = 9 where id=8;
Query OK, 1 row affected (0.06 sec)
Rows matched: 1  Changed: 1  Warnings: 0
[root@gzx-master-01 logs]# mysqlbinlog --no-defaults -v -v --base64-output=DECODE-ROWS mysql_bin.000031 
/*!50530 SET @@SESSION.PSEUDO_SLAVE_MODE=1*/;
/*!50003 SET @OLD_COMPLETION_TYPE=@@COMPLETION_TYPE,COMPLETION_TYPE=0*/;
DELIMITER /*!*/;
# at 4
#170424  9:03:47 server id 37306  end_log_pos 123 CRC32 0xa04cc14a     Start: binlog v 4, server v 5.7.17-log created 170424  9:03:47
# Warning: this binlog is either in use or was not closed properly.
# at 123
#170424  9:03:47 server id 37306  end_log_pos 194 CRC32 0xc3c3b085     Previous-GTIDs
# a0c06ec7-fef0-11e6-9f85-525400a7d662:1-813
# at 194
#170424  9:03:55 server id 37306  end_log_pos 259 CRC32 0xbf9d2c93     GTID    last_committed=sequence_number=1
SET @@SESSION.GTID_NEXT= 'a0c06ec7-fef0-11e6-9f85-525400a7d662:814'/*!*/;
# at 259
#170424  9:03:55 server id 37306  end_log_pos 331 CRC32 0xeddbf07c     Query    thread_id=34   exec_time=0    error_code=0
SET TIMESTAMP=1492995835/*!*/;
SET @@session.pseudo_thread_id=34/*!*/;
SET @@session.foreign_key_checks=1, @@session.sql_auto_is_null=0, @@session.unique_checks=1, @@session.autocommit=1/*!*/;
SET @@session.sql_mode=1436549120/*!*/;
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.lc_time_names=0/*!*/;
SET @@session.collation_database=DEFAULT/*!*/;
BEGIN
/*!*/;
# at 331
#170424  9:03:55 server id 37306  end_log_pos 385 CRC32 0x912f4086     Rows_query
# update t set id = 9 where id=8
# at 385
#170424  9:03:55 server id 37306  end_log_pos 429 CRC32 0x16eec7d7     Table_map: `boss`.`t` mapped to number 118
# at 429
#170424  9:03:55 server id 37306  end_log_pos 475 CRC32 0x920862af     Update_rows: table id 118 flags: STMT_END_F
### UPDATE `boss`.`t`
### WHERE
###   @1=8 /* INT meta=0 nullable=1 is_null=0 */
### SET
###   @1=9 /* INT meta=0 nullable=1 is_null=0 */
# at 475
#170424  9:03:55 server id 37306  end_log_pos 506 CRC32 0xa37b82e5     Xid = 2447
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*/;

 

Look at the underline, you can know clearly what the corresponding SQL is.

Tags: MySQL Session SQL mysqlbinlog

Posted on Mon, 11 Feb 2019 03:42:18 -0800 by RabPHP