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.
Very explanatory!!! Thanks
ReplyDelete