Monday, March 25, 2013

Intrepreting MySQL Binary Logs using mysqlbinlog

MySQL Database Server logs each change data statement in binary logs. Binary logs generally used for replicating all changes on master database server to slave database server. These logs can be used for disaster recovery, to perform some specific database maintenance activities or for database incremental backup. Binary logging can be enabled using log-bin parameter in my.cnf ( the MySQL configuration  file ). So to analyze and process logs in binary format mysqlbinlog utility is used. This tools convert the binary logs into plain text or human readable format depending upon the binlog format set in my.cnf.
There are three binary log format STATEMENT : queries logged in plain text format, ROW : queries logged on binary format and MIXED. Default binary log format is STATEMENT.

To start with binary logs lets execute some data change queries on mysql :

create table test ( id int );
insert into test values (1);
insert into test values (2);
alter table test add column( id2 int);

$ mysqlbinlog mysql-bin.000004

/*!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
#130325 16:20:55 server id 1  end_log_pos 107   Start: binlog v 4, server v 5.5.30-log created 130325 16:20:55 at startup
# Warning: this binlog is either in use or was not closed properly.
ROLLBACK/*!*/;
BINLOG '
DyxQUQ8BAAAAZwAAAGsAAAABAAQANS41LjMwLWxvZwAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA
AAAAAAAAAAAAAAAAAAAPLFBREzgNAAgAEgAEBAQEEgAAVAAEGggAAAAICAgCAA==
'/*!*/;
# at 107
#130325 16:21:08 server id 1  end_log_pos 198   Query   thread_id=1     exec_time=0     error_code=0
use `test`/*!*/;
SET TIMESTAMP=1364208668/*!*/;
SET @@session.pseudo_thread_id=1/*!*/;
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=8/*!*/;
SET @@session.lc_time_names=0/*!*/;
SET @@session.collation_database=DEFAULT/*!*/;
create table test ( id int )
/*!*/;
# at 198
#130325 16:21:17 server id 1  end_log_pos 266   Query   thread_id=1     exec_time=0     error_code=0
SET TIMESTAMP=1364208677/*!*/;
BEGIN
/*!*/;
# at 266
#130325 16:21:17 server id 1  end_log_pos 356   Query   thread_id=1     exec_time=0     error_code=0
SET TIMESTAMP=1364208677/*!*/;
insert into test values (1)
/*!*/;
# at 356
#130325 16:21:17 server id 1  end_log_pos 383   Xid = 8
COMMIT/*!*/;
# at 383
#130325 16:21:18 server id 1  end_log_pos 451   Query   thread_id=1     exec_time=0     error_code=0
SET TIMESTAMP=1364208678/*!*/;
BEGIN
/*!*/;
# at 451
#130325 16:21:18 server id 1  end_log_pos 541   Query   thread_id=1     exec_time=0     error_code=0
SET TIMESTAMP=1364208678/*!*/;
insert into test values (2)
/*!*/;
# at 541
#130325 16:21:18 server id 1  end_log_pos 568   Xid = 9
COMMIT/*!*/;
# at 568
#130325 16:21:26 server id 1  end_log_pos 668   Query   thread_id=1     exec_time=0     error_code=0
SET TIMESTAMP=1364208686/*!*/;
alter table test add column( id2 int)
/*!*/;
DELIMITER ;
# End of log file
ROLLBACK /* added by mysqlbinlog */;
/*!50003 SET COMPLETION_TYPE=@OLD_COMPLETION_TYPE*/;
/*!50530 SET @@SESSION.PSEUDO_SLAVE_MODE=0*/;


We could see all queries in plain text from above mysqlbinlog output when binary log format is STATEMENT.

mysqlbinlog displays row events encoded as base-64 string which is not human readable.
Here is mysqlbinlog output with ROW format:

$ mysqlbinlog mysql-bin.000004 

/*!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
#130325 16:42:34 server id 1  end_log_pos 107   Start: binlog v 4, server v 5.5.30-log created 130325 16:42:34 at startup
# Warning: this binlog is either in use or was not closed properly.
ROLLBACK/*!*/;
BINLOG '
IjFQUQ8BAAAAZwAAAGsAAAABAAQANS41LjMwLWxvZwAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA
AAAAAAAAAAAAAAAAAAAiMVBREzgNAAgAEgAEBAQEEgAAVAAEGggAAAAICAgCAA==
'/*!*/;
# at 107
#130325 16:42:52 server id 1  end_log_pos 198   Query   thread_id=1     exec_time=0     error_code=0
use `test`/*!*/;
SET TIMESTAMP=1364209972/*!*/;
SET @@session.pseudo_thread_id=1/*!*/;
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=8/*!*/;
SET @@session.lc_time_names=0/*!*/;
SET @@session.collation_database=DEFAULT/*!*/;
create table test ( id int )
/*!*/;
# at 198
#130325 16:42:57 server id 1  end_log_pos 266   Query   thread_id=1     exec_time=0     error_code=0
SET TIMESTAMP=1364209977/*!*/;
BEGIN
/*!*/;
# at 266
#130325 16:42:57 server id 1  end_log_pos 309   Table_map: `test`.`test` mapped to number 34
# at 309
#130325 16:42:57 server id 1  end_log_pos 343   Write_rows: table id 34 flags: STMT_END_F

BINLOG '
OTFQURMBAAAAKwAAADUBAAAAACIAAAAAAAEABHRlc3QABHRlc3QAAQMAAQ==
OTFQURcBAAAAIgAAAFcBAAAAACIAAAAAAAEAAf/+AQAAAA==
'/*!*/;
# at 343
#130325 16:42:57 server id 1  end_log_pos 370   Xid = 8
COMMIT/*!*/;
# at 370
#130325 16:43:00 server id 1  end_log_pos 438   Query   thread_id=1     exec_time=0     error_code=0
SET TIMESTAMP=1364209980/*!*/;
BEGIN
/*!*/;
# at 438
#130325 16:43:00 server id 1  end_log_pos 481   Table_map: `test`.`test` mapped to number 34
# at 481
#130325 16:43:00 server id 1  end_log_pos 515   Write_rows: table id 34 flags: STMT_END_F

BINLOG '
PDFQURMBAAAAKwAAAOEBAAAAACIAAAAAAAEABHRlc3QABHRlc3QAAQMAAQ==
PDFQURcBAAAAIgAAAAMCAAAAACIAAAAAAAEAAf/+AgAAAA==
'/*!*/;
# at 515
#130325 16:43:00 server id 1  end_log_pos 542   Xid = 9
COMMIT/*!*/;
# at 542
#130325 16:43:03 server id 1  end_log_pos 642   Query   thread_id=1     exec_time=0     error_code=0
SET TIMESTAMP=1364209983/*!*/;
alter table test add column( id2 int)
/*!*/;
DELIMITER ;
# End of log file
ROLLBACK /* added by mysqlbinlog */;
/*!50003 SET COMPLETION_TYPE=@OLD_COMPLETION_TYPE*/;
/*!50530 SET @@SESSION.PSEUDO_SLAVE_MODE=0*/;


 To display row events as comments run mysqlbinlog with -v option:

$mysqlbinlog SM-Couple1-bin.000004 -v
 

/*!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
#130325 16:42:34 server id 1  end_log_pos 107   Start: binlog v 4, server v 5.5.30-log created 130325 16:42:34 at startup
# Warning: this binlog is either in use or was not closed properly.
ROLLBACK/*!*/;
BINLOG '
IjFQUQ8BAAAAZwAAAGsAAAABAAQANS41LjMwLWxvZwAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA
AAAAAAAAAAAAAAAAAAAiMVBREzgNAAgAEgAEBAQEEgAAVAAEGggAAAAICAgCAA==
'/*!*/;
# at 107
#130325 16:42:52 server id 1  end_log_pos 198   Query   thread_id=1     exec_time=0     error_code=0
use `test`/*!*/;
SET TIMESTAMP=1364209972/*!*/;
SET @@session.pseudo_thread_id=1/*!*/;
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=8/*!*/;
SET @@session.lc_time_names=0/*!*/;
SET @@session.collation_database=DEFAULT/*!*/;
create table test ( id int )
/*!*/;
# at 198
#130325 16:42:57 server id 1  end_log_pos 266   Query   thread_id=1     exec_time=0     error_code=0
SET TIMESTAMP=1364209977/*!*/;
BEGIN
/*!*/;
# at 266
#130325 16:42:57 server id 1  end_log_pos 309   Table_map: `test`.`test` mapped to number 34
# at 309
#130325 16:42:57 server id 1  end_log_pos 343   Write_rows: table id 34 flags: STMT_END_F

BINLOG '
OTFQURMBAAAAKwAAADUBAAAAACIAAAAAAAEABHRlc3QABHRlc3QAAQMAAQ==
OTFQURcBAAAAIgAAAFcBAAAAACIAAAAAAAEAAf/+AQAAAA==
'/*!*/;
### INSERT INTO `test`.`test`
### SET
###   @1=1
# at 343
#130325 16:42:57 server id 1  end_log_pos 370   Xid = 8
COMMIT/*!*/;
# at 370
#130325 16:43:00 server id 1  end_log_pos 438   Query   thread_id=1     exec_time=0     error_code=0
SET TIMESTAMP=1364209980/*!*/;
BEGIN
/*!*/;
# at 438
#130325 16:43:00 server id 1  end_log_pos 481   Table_map: `test`.`test` mapped to number 34
# at 481
#130325 16:43:00 server id 1  end_log_pos 515   Write_rows: table id 34 flags: STMT_END_F

BINLOG '
PDFQURMBAAAAKwAAAOEBAAAAACIAAAAAAAEABHRlc3QABHRlc3QAAQMAAQ==
PDFQURcBAAAAIgAAAAMCAAAAACIAAAAAAAEAAf/+AgAAAA==
'/*!*/;
### INSERT INTO `test`.`test`
### SET
###   @1=2
# at 515
#130325 16:43:00 server id 1  end_log_pos 542   Xid = 9
COMMIT/*!*/;
# at 542
#130325 16:43:03 server id 1  end_log_pos 642   Query   thread_id=1     exec_time=0     error_code=0
SET TIMESTAMP=1364209983/*!*/;
alter table test add column( id2 int)
/*!*/;
DELIMITER ;
# End of log file
ROLLBACK /* added by mysqlbinlog */;
/*!50003 SET COMPLETION_TYPE=@OLD_COMPLETION_TYPE*/;
/*!50530 SET @@SESSION.PSEUDO_SLAVE_MODE=0*/;


We can suppress BINLOG for row events using

$  mysqlbinlog SM-Couple1-bin.000005 -v --base64-output=DECODE-ROWS

/*!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
#130325 16:42:34 server id 1  end_log_pos 107   Start: binlog v 4, server v 5.5.30-log created 130325 16:42:34 at startup
# Warning: this binlog is either in use or was not closed properly.
ROLLBACK/*!*/;
# at 107
#130325 16:42:52 server id 1  end_log_pos 198   Query   thread_id=1     exec_time=0     error_code=0
use `test`/*!*/;
SET TIMESTAMP=1364209972/*!*/;
SET @@session.pseudo_thread_id=1/*!*/;
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=8/*!*/;
SET @@session.lc_time_names=0/*!*/;
SET @@session.collation_database=DEFAULT/*!*/;
create table test ( id int )
/*!*/;
# at 198
#130325 16:42:57 server id 1  end_log_pos 266   Query   thread_id=1     exec_time=0     error_code=0
SET TIMESTAMP=1364209977/*!*/;
BEGIN
/*!*/;
# at 266
#130325 16:42:57 server id 1  end_log_pos 309   Table_map: `test`.`test` mapped to number 34
# at 309
#130325 16:42:57 server id 1  end_log_pos 343   Write_rows: table id 34 flags: STMT_END_F
### INSERT INTO `test`.`test`
### SET
###   @1=1
# at 343
#130325 16:42:57 server id 1  end_log_pos 370   Xid = 8
COMMIT/*!*/;
# at 370
#130325 16:43:00 server id 1  end_log_pos 438   Query   thread_id=1     exec_time=0     error_code=0
SET TIMESTAMP=1364209980/*!*/;
BEGIN
/*!*/;
# at 438
#130325 16:43:00 server id 1  end_log_pos 481   Table_map: `test`.`test` mapped to number 34
# at 481
#130325 16:43:00 server id 1  end_log_pos 515   Write_rows: table id 34 flags: STMT_END_F
### INSERT INTO `test`.`test`
### SET
###   @1=2
# at 515
#130325 16:43:00 server id 1  end_log_pos 542   Xid = 9
COMMIT/*!*/;
# at 542
#130325 16:43:03 server id 1  end_log_pos 642   Query   thread_id=1     exec_time=0     error_code=0
SET TIMESTAMP=1364209983/*!*/;
alter table test add column( id2 int)
/*!*/;
DELIMITER ;
# End of log file
ROLLBACK /* added by mysqlbinlog */;
/*!50003 SET COMPLETION_TYPE=@OLD_COMPLETION_TYPE*/;
/*!50530 SET @@SESSION.PSEUDO_SLAVE_MODE=0*/;


You should not suppress BINLOG statements if you intend to re-execute mysqlbinlog output.


1 comment: