Lately, I saw many cases when users specified the option --base64-output=DECODE-ROWS to print out a statement representation of row events in MySQL binary logs just to get nothing. Reason for this is obvious: option --base64-output=DECODE-ROWS does not convert row events into its string representation, this is the job of the option -- verbose. But why users mix these two options so often? This blog post is the result of my investigations.
MySQL binary logs
There are already two great blog posts about printing row events on the Percona blog: “Debugging problems with row based replication” by Justin Swanhart and “Identifying useful info from MySQL row-based binary logs” by Alok Pathak.
Both authors run mysqlbinlog with options –base64-output=decode-rows -vv and demonstrate how a combination of them can produce human-readable output of row events. However, one thing which is not clear yet is what the differences are between these options. I want to underline the differences in this post.
Let’s check the user manual first.
–base64-output=value
This option determines when events should be displayed encoded as base-64 strings using BINLOG statements. The option has these permissible values (not case sensitive):
AUTO (“automatic”) or UNSPEC (“unspecified”) displays BINLOG statements automatically when necessary (that is, for format description events and row events). If no –base64-output option is given, the effect is the same as –base64-output=AUTO.
Note
Automatic BINLOG display is the only safe behavior if you intend to use the output of mysqlbinlog to re-execute binary log file contents. The other option values are intended only for debugging or testing purposes because they may produce output that does not include all events in executable form.
NEVER causes BINLOG statements not to be displayed. mysqlbinlog exits with an error if a row event is found that must be displayed using BINLOG.
DECODE-ROWS specifies to mysqlbinlog that you intend for row events to be decoded and displayed as commented SQL statements by also specifying the –verbose option. Like NEVER, DECODE-ROWS suppresses display of BINLOG statements, but unlike NEVER, it does not exit with an error if a row event is found.
For examples that show the effect of –base64-output and –verbose on row event output, see Section 4.6.8.2, “mysqlbinlog Row Event Display”.
Literally --base64-output=DECODE-ROWS just suppresses BINLOG statement and does not print anything.
To test its effect I run command
1 |
insert into t values (2, 'bar'); |
on an InnoDB table while binary log uses ROW format. As expected if I specify no option I will receive unreadable output:
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 38 39 40 41 42 43 44 |
$mysqlbinlog var/mysqld.1/data/master-bin.000002 /*!50530 SET @@SESSION.PSEUDO_SLAVE_MODE=1*/; /*!40019 SET @@session.max_insert_delayed_threads=0*/; /*!50003 SET @[email protected]@COMPLETION_TYPE,COMPLETION_TYPE=0*/; DELIMITER /*!*/; # at 4 #150720 15:19:15 server id 1 end_log_pos 120 CRC32 0x3d52aee2 Start: binlog v 4, server v 5.6.25-73.1-debug-log created 150720 15:19:15 BINLOG ' Q+esVQ8BAAAAdAAAAHgAAAAAAAQANS42LjI1LTczLjEtZGVidWctbG9nAAAAAAAAAAAAAAAAAAAA AAAAAAAAAAAAAAAAAAAAAAAAEzgNAAgAEgAEBAQEEgAAXAAEGggAAAAICAgCAAAACgoKGRkAAeKu Uj0= '/*!*/; # at 120 #150720 15:19:21 server id 1 end_log_pos 192 CRC32 0xbebac59d Query thread_id=2 exec_time=0 error_code=0 SET TIMESTAMP=1437394761/*!*/; 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=1073741824/*!*/; 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=8/*!*/; SET @@session.lc_time_names=0/*!*/; SET @@session.collation_database=DEFAULT/*!*/; BEGIN /*!*/; # at 192 #150720 15:19:21 server id 1 end_log_pos 239 CRC32 0xe143838b Table_map: `test`.`t` mapped to number 70 # at 239 #150720 15:19:21 server id 1 end_log_pos 283 CRC32 0x75523a2d Write_rows: table id 70 flags: STMT_END_F BINLOG ' SeesVRMBAAAALwAAAO8AAAAAAEYAAAAAAAEABHRlc3QAAXQAAgMPAv8AA4uDQ+E= SeesVR4BAAAALAAAABsBAAAAAEYAAAAAAAEAAgAC//wCAAAAA2Jhci06UnU= '/*!*/; # at 283 #150720 15:19:21 server id 1 end_log_pos 314 CRC32 0xd183c769 Xid = 14 COMMIT/*!*/; # at 314 #150720 15:19:22 server id 1 end_log_pos 362 CRC32 0x892fe43b Rotate to master-bin.000003 pos: 4 DELIMITER ; # End of log file ROLLBACK /* added by mysqlbinlog */; /*!50003 SET [email protected]_COMPLETION_TYPE*/; /*!50530 SET @@SESSION.PSEUDO_SLAVE_MODE=0*/; |
The INSERT is here:
1 2 3 4 |
BINLOG ' SeesVRMBAAAALwAAAO8AAAAAAEYAAAAAAAEABHRlc3QAAXQAAgMPAv8AA4uDQ+E= SeesVR4BAAAALAAAABsBAAAAAEYAAAAAAAEAAgAC//wCAAAAA2Jhci06UnU= '/*!*/; |
But this string is not for humans.
What will happen if I add option --base64-output=DECODE-ROWS ?
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 |
$mysqlbinlog var/mysqld.1/data/master-bin.000002 --base64-output=DECODE-ROWS /*!50530 SET @@SESSION.PSEUDO_SLAVE_MODE=1*/; /*!40019 SET @@session.max_insert_delayed_threads=0*/; /*!50003 SET @[email protected]@COMPLETION_TYPE,COMPLETION_TYPE=0*/; DELIMITER /*!*/; # at 4 #150720 15:19:15 server id 1 end_log_pos 120 CRC32 0x3d52aee2 Start: binlog v 4, server v 5.6.25-73.1-debug-log created 150720 15:19:15 # at 120 #150720 15:19:21 server id 1 end_log_pos 192 CRC32 0xbebac59d Query thread_id=2 exec_time=0 error_code=0 SET TIMESTAMP=1437394761/*!*/; 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=1073741824/*!*/; 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=8/*!*/; SET @@session.lc_time_names=0/*!*/; SET @@session.collation_database=DEFAULT/*!*/; BEGIN /*!*/; # at 192 #150720 15:19:21 server id 1 end_log_pos 239 CRC32 0xe143838b Table_map: `test`.`t` mapped to number 70 # at 239 #150720 15:19:21 server id 1 end_log_pos 283 CRC32 0x75523a2d Write_rows: table id 70 flags: STMT_END_F # at 283 #150720 15:19:21 server id 1 end_log_pos 314 CRC32 0xd183c769 Xid = 14 COMMIT/*!*/; # at 314 #150720 15:19:22 server id 1 end_log_pos 362 CRC32 0x892fe43b Rotate to master-bin.000003 pos: 4 DELIMITER ; # End of log file ROLLBACK /* added by mysqlbinlog */; /*!50003 SET [email protected]_COMPLETION_TYPE*/; /*!50530 SET @@SESSION.PSEUDO_SLAVE_MODE=0*/; |
Row event was just suppressed!
Lets now check option verbose:
–verbose, -v
Reconstruct row events and display them as commented SQL statements. If this option is given twice, the output includes comments to indicate column data types and some metadata.
For examples that show the effect of –base64-output and –verbose on row event output, see Section 4.6.8.2, “mysqlbinlog Row Event Display”.
Surprisingly --base64-output=DECODE-ROWS is not needed!:
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 38 39 40 41 42 43 44 45 46 47 48 |
$mysqlbinlog var/mysqld.1/data/master-bin.000002 --verbose /*!50530 SET @@SESSION.PSEUDO_SLAVE_MODE=1*/; /*!40019 SET @@session.max_insert_delayed_threads=0*/; /*!50003 SET @[email protected]@COMPLETION_TYPE,COMPLETION_TYPE=0*/; DELIMITER /*!*/; # at 4 #150720 15:19:15 server id 1 end_log_pos 120 CRC32 0x3d52aee2 Start: binlog v 4, server v 5.6.25-73.1-debug-log created 150720 15:19:15 BINLOG ' Q+esVQ8BAAAAdAAAAHgAAAAAAAQANS42LjI1LTczLjEtZGVidWctbG9nAAAAAAAAAAAAAAAAAAAA AAAAAAAAAAAAAAAAAAAAAAAAEzgNAAgAEgAEBAQEEgAAXAAEGggAAAAICAgCAAAACgoKGRkAAeKu Uj0= '/*!*/; # at 120 #150720 15:19:21 server id 1 end_log_pos 192 CRC32 0xbebac59d Query thread_id=2 exec_time=0 error_code=0 SET TIMESTAMP=1437394761/*!*/; 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=1073741824/*!*/; 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=8/*!*/; SET @@session.lc_time_names=0/*!*/; SET @@session.collation_database=DEFAULT/*!*/; BEGIN /*!*/; # at 192 #150720 15:19:21 server id 1 end_log_pos 239 CRC32 0xe143838b Table_map: `test`.`t` mapped to number 70 # at 239 #150720 15:19:21 server id 1 end_log_pos 283 CRC32 0x75523a2d Write_rows: table id 70 flags: STMT_END_F BINLOG ' SeesVRMBAAAALwAAAO8AAAAAAEYAAAAAAAEABHRlc3QAAXQAAgMPAv8AA4uDQ+E= SeesVR4BAAAALAAAABsBAAAAAEYAAAAAAAEAAgAC//wCAAAAA2Jhci06UnU= '/*!*/; ### INSERT INTO `test`.`t` ### SET ### @1=2 ### @2='bar' # at 283 #150720 15:19:21 server id 1 end_log_pos 314 CRC32 0xd183c769 Xid = 14 COMMIT/*!*/; # at 314 #150720 15:19:22 server id 1 end_log_pos 362 CRC32 0x892fe43b Rotate to master-bin.000003 pos: 4 DELIMITER ; # End of log file ROLLBACK /* added by mysqlbinlog */; /*!50003 SET [email protected]_COMPLETION_TYPE*/; /*!50530 SET @@SESSION.PSEUDO_SLAVE_MODE=0*/; |
INSERT statement successfully restored as:
1 2 3 4 5 |
### INSERT INTO `test`.`t` ### SET ### @1=2 ### @2='bar' # at 283 |
Why do the bloggers mentioned above suggest to use --base64-output=DECODE-ROWS ? Lets try to use both options:
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 38 |
$mysqlbinlog var/mysqld.1/data/master-bin.000002 --base64-output=DECODE-ROWS --verbose /*!50530 SET @@SESSION.PSEUDO_SLAVE_MODE=1*/; /*!40019 SET @@session.max_insert_delayed_threads=0*/; /*!50003 SET @[email protected]@COMPLETION_TYPE,COMPLETION_TYPE=0*/; DELIMITER /*!*/; # at 4 #150720 15:19:15 server id 1 end_log_pos 120 CRC32 0x3d52aee2 Start: binlog v 4, server v 5.6.25-73.1-debug-log created 150720 15:19:15 # at 120 #150720 15:19:21 server id 1 end_log_pos 192 CRC32 0xbebac59d Query thread_id=2 exec_time=0 error_code=0 SET TIMESTAMP=1437394761/*!*/; 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=1073741824/*!*/; 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=8/*!*/; SET @@session.lc_time_names=0/*!*/; SET @@session.collation_database=DEFAULT/*!*/; BEGIN /*!*/; # at 192 #150720 15:19:21 server id 1 end_log_pos 239 CRC32 0xe143838b Table_map: `test`.`t` mapped to number 70 # at 239 #150720 15:19:21 server id 1 end_log_pos 283 CRC32 0x75523a2d Write_rows: table id 70 flags: STMT_END_F ### INSERT INTO `test`.`t` ### SET ### @1=2 ### @2='bar' # at 283 #150720 15:19:21 server id 1 end_log_pos 314 CRC32 0xd183c769 Xid = 14 COMMIT/*!*/; # at 314 #150720 15:19:22 server id 1 end_log_pos 362 CRC32 0x892fe43b Rotate to master-bin.000003 pos: 4 DELIMITER ; # End of log file ROLLBACK /* added by mysqlbinlog */; /*!50003 SET [email protected]_COMPLETION_TYPE*/; /*!50530 SET @@SESSION.PSEUDO_SLAVE_MODE=0*/; |
In this case row event was suppressed and statement is printed. Also, the resulting file cannot be used to re-apply events, because statements are commented out. This is very useful when binary log is big and you just need to investigate what it contains, not re-apply events.
This is not main purpose of this post, but you can also find information about columns metadata if specify option --verbose twice:
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 38 |
$mysqlbinlog var/mysqld.1/data/master-bin.000002 --base64-output=DECODE-ROWS --verbose --verbose /*!50530 SET @@SESSION.PSEUDO_SLAVE_MODE=1*/; /*!40019 SET @@session.max_insert_delayed_threads=0*/; /*!50003 SET @[email protected]@COMPLETION_TYPE,COMPLETION_TYPE=0*/; DELIMITER /*!*/; # at 4 #150720 15:19:15 server id 1 end_log_pos 120 CRC32 0x3d52aee2 Start: binlog v 4, server v 5.6.25-73.1-debug-log created 150720 15:19:15 # at 120 #150720 15:19:21 server id 1 end_log_pos 192 CRC32 0xbebac59d Query thread_id=2 exec_time=0 error_code=0 SET TIMESTAMP=1437394761/*!*/; 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=1073741824/*!*/; 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=8/*!*/; SET @@session.lc_time_names=0/*!*/; SET @@session.collation_database=DEFAULT/*!*/; BEGIN /*!*/; # at 192 #150720 15:19:21 server id 1 end_log_pos 239 CRC32 0xe143838b Table_map: `test`.`t` mapped to number 70 # at 239 #150720 15:19:21 server id 1 end_log_pos 283 CRC32 0x75523a2d Write_rows: table id 70 flags: STMT_END_F ### INSERT INTO `test`.`t` ### SET ### @1=2 /* INT meta=0 nullable=1 is_null=0 */ ### @2='bar' /* VARSTRING(255) meta=255 nullable=1 is_null=0 */ # at 283 #150720 15:19:21 server id 1 end_log_pos 314 CRC32 0xd183c769 Xid = 14 COMMIT/*!*/; # at 314 #150720 15:19:22 server id 1 end_log_pos 362 CRC32 0x892fe43b Rotate to master-bin.000003 pos: 4 DELIMITER ; # End of log file ROLLBACK /* added by mysqlbinlog */; /*!50003 SET [email protected]_COMPLETION_TYPE*/; /*!50530 SET @@SESSION.PSEUDO_SLAVE_MODE=0*/; |
Note, this is, again, the job of --verbose , not --base64-output=DECODE-ROWS
To conclude:
If you want to see statement representation of row events use option
--verbose (-v)
If you want to see metadata of columns specify
--verbose twice:
--verbose --verbose or
-vv
If you want to suppress output of row events specify the option
--base64-output=DECODE-ROWS
Hello Sveta, Thanks for the above information but the confusion of re-applying the binlog events incase of failure is not clear. What options should we use to get the statements in uncommented format so that it can be re-applied.
There is no such an option. If you need to re-apply events you should not use –base64-output=DECODE-ROWS: binary events will be applied. SQL events exist for information purpose only. For example, when you are trying to find which statement caused replication failure.
Loved the article and want to suggest a tool for base64 decode http://codebeautify.org/base64-decode
Very nice article. Use very good online tool OnlineUtility,in to convert string to Base64 format.
Hello Sveta, I am stuck with a issue where my binary logs from AWS RDS mariadb 10.0.35 are grouped together. To elaborate more, all the # at ‘offset number’ are grouped one after another, all the event date time rows are grouped together, all SQL statements are grouped, etc. I used mysqlbinlog to read a particular event
eg:- “mysqlbinlog mysql-bin-changelog.640132 –start-position=9319572 –stop-position=9321524 –base64-output=DECODE-ROWS -v”
but it returns empty value within the delimiter section as given below:
DELIMITER /*!*/;
# at 9319572
# at 9320552
DELIMITER ;
# End of log file
On checking mysql docs, I found this is a property of binlog event grouping. https://dev.mysql.com/doc/refman/8.0/en/mysqlbinlog.html
How can this be fixed. How should I know which position affects which rows. I tried converting them to different format like txt .log but nothing helped.(mysqlbinlog Ver 3.3 for Linux at x86_64)