Detailed introduction to binlog log files in MySQL

This article brings you a detailed introduction to the binlog log file in MySQL. It has certain reference value. Friends in need can refer to it. I hope it will be helpful to you.

MySQL’s binlog log file records all modification operations of the database table. This article briefly summarizes the knowledge related to MySQL binlog and how to use binlog to restore or flashback database data.

binlog in STATEMENT format

To enable binlog, you need to pass in the --log-bin parameter when starting MySQL. Or you can set log_bin in the MySQL configuration file /etc/my.cnf to enable binlog. Starting from MySQL 5.7, after enabling binlog, the --server-id parameter must also be specified, otherwise the MySQL server will fail to start.

binlog_format supports three formats: STATEMENT, ROW, and MIXED. MySQL 5.5 and 5.6 default to STATEMENT, and MySQL 5.7.7 starts to default to ROW. like SQL uses UUID(), RAND(), VERSION() and other functions, or uses stored procedures, custom functions, based on STATEMENT It is unsafe when master-slave is replicated (many people may think that NOW(), CURRENT_TIMESTAMP and these functions are also unsafe, but in fact they are safe) [doc1, doc2]. Master-slave replication based on ROW is the safest replication method.

Now let’s take a look at the binlog in STATEMENT format. The modified content of the /etc/my.cnf file is as follows:

server_id = 1
log_bin = mysql-bin
binlog_format = STATEMENT
binlog_row_image=FULL

After restarting MySQL, under the data directory datadir, such as /var/lib /mysql/, the corresponding binlog files, mysql-bin.index and mysql-bin.000001, will be generated. Files with the .index suffix save all binlog file names. The mysql-bin.000001 file records binlog content. Every time MySQL starts or flushes the log, a new log file will be created according to the sequence number. Additionally, when the log file size exceeds max_binlog_size, a new log file is also created.

Now let’s try the binlog function. Assume that there is a hello table in the testdb library, and a certain row is modified:

mysql> select * from hello;
+----+-------+
| id | name  |
+----+-------+
|  1 | Andy  |
|  2 | Bill  |
|  3 | Candy |
+----+-------+
4 rows in set (0.00 sec)

mysql> update hello set name = 'Will' where id = 3;
Query OK, 1 row affected (0.02 sec)
Rows matched: 1  Changed: 1  Warnings: 0

binlog is a binary file, and you need to use the mysqlbinlog (doc, man) command to view it:

$ sudo mysqlbinlog /var/lib/mysql/mysql-bin.000001  # 直接在 mysql 服务器上读取 binlog 文件
$ mysqlbinlog -R -h192.168.2.107 -uroot -p123456 mysql-bin.000001  # 或者，远程读取 binlog 文件

Execute update The content of the newly added binlog file is:

# at 154
#180617 22:47:49 server id 1  end_log_pos 219 CRC32 0x4bd9d69b     Anonymous_GTID    last_committed=0    sequence_number=1    rbr_only=no
SET @@SESSION.GTID_NEXT= 'ANONYMOUS'/*!*/;
# at 219
#180617 22:47:49 server id 1  end_log_pos 302 CRC32 0x476fafc9     Query    thread_id=2    exec_time=0    error_code=0
SET TIMESTAMP=1529246869/*!*/;
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=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.lc_time_names=0/*!*/;
SET @@session.collation_database=DEFAULT/*!*/;
BEGIN
/*!*/;
# at 302
#180617 22:47:49 server id 1  end_log_pos 423 CRC32 0x7f2c2c7a     Query    thread_id=2    exec_time=0    error_code=0
use `testdb`/*!*/;
SET TIMESTAMP=1529246869/*!*/;
update hello set name = 'Will' where id = 3
/*!*/;
# at 423
#180617 22:47:49 server id 1  end_log_pos 454 CRC32 0x68da744a     Xid = 12
COMMIT/*!*/;

binlog in ROW format

Modify the binlog_format of /etc/my.cnf to ROW, and then restart MySQL. After the format is modified, a new binlog file mysql-bin.000002 will be generated.

mysql> show create table hello;
+-------+-------------------------------------------------------------------------+
| Table | Create Table
+-------+-------------------------------------------------------------------------+
| hello | CREATE TABLE `hello` (
  `id` bigint(20) NOT NULL AUTO_INCREMENT,
  `name` varchar(20) DEFAULT NULL,
  PRIMARY KEY (`id`)
) ENGINE=InnoDB AUTO_INCREMENT=4 DEFAULT CHARSET=utf8mb4 |
+-------+-------------------------------------------------------------------------+
1 row in set (0.00 sec)

mysql> select * from hello where id;
+----+------+
| id | name |
+----+------+
|  1 | Andy |
|  2 | Lily |
|  3 | Will |
+----+------+
1 row in set (0.00 sec)

mysql> update hello set name = 'David' where id = 3;
Query OK, 1 row affected (0.02 sec)
Rows matched: 1  Changed: 1  Warnings: 0

To view binlog in ROW format, you need to use the sudo mysqlbinlog -v --base64-output=DECODE-ROWS /var/lib/mysql/mysql-bin.000002 command. The corresponding newly added binlog content after executing update:

# at 154
#180617 22:54:13 server id 1  end_log_pos 219 CRC32 0x2ce70d4d     Anonymous_GTID    last_committed=0    sequence_number=1    rbr_only=yes
/*!50718 SET TRANSACTION ISOLATION LEVEL READ COMMITTED*//*!*/;
SET @@SESSION.GTID_NEXT= 'ANONYMOUS'/*!*/;
# at 219
#180617 22:54:13 server id 1  end_log_pos 293 CRC32 0x8183fddf     Query    thread_id=2    exec_time=0    error_code=0
SET TIMESTAMP=1529247253/*!*/;
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=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.lc_time_names=0/*!*/;
SET @@session.collation_database=DEFAULT/*!*/;
BEGIN
/*!*/;
# at 293
#180617 22:54:13 server id 1  end_log_pos 346 CRC32 0x0fc7e1a4     Table_map: `testdb`.`hello` mapped to number 110
# at 346
#180617 22:54:13 server id 1  end_log_pos 411 CRC32 0xb58e729d     Update_rows: table id 110 flags: STMT_END_F
### UPDATE `testdb`.`hello`
### WHERE
###   @1=3
###   @2='Will'
### SET
###   @1=3
###   @2='David'
# at 411
#180617 22:54:13 server id 1  end_log_pos 442 CRC32 0xef964db8     Xid = 13
COMMIT/*!*/;

If the following SQL is executed:

mysql> insert hello (name) values ('Frank');
Query OK, 1 row affected (0.02 sec)

The corresponding generated binlog content:

# at 442
#180617 22:55:47 server id 1  end_log_pos 507 CRC32 0x79de08a7     Anonymous_GTID    last_committed=1    sequence_number=2    rbr_only=yes
/*!50718 SET TRANSACTION ISOLATION LEVEL READ COMMITTED*//*!*/;
SET @@SESSION.GTID_NEXT= 'ANONYMOUS'/*!*/;
# at 507
#180617 22:55:47 server id 1  end_log_pos 581 CRC32 0x56f9eb6a     Query    thread_id=2    exec_time=0    error_code=0
SET TIMESTAMP=1529247347/*!*/;
BEGIN
/*!*/;
# at 581
#180617 22:55:47 server id 1  end_log_pos 634 CRC32 0xedb73620     Table_map: `testdb`.`hello` mapped to number 110
# at 634
#180617 22:55:47 server id 1  end_log_pos 684 CRC32 0x525a6a70     Write_rows: table id 110 flags: STMT_END_F
### INSERT INTO `testdb`.`hello`
### SET
###   @1=4
###   @2='Frank'
# at 684
#180617 22:55:47 server id 1  end_log_pos 715 CRC32 0x09a0d4de     Xid = 14
COMMIT/*!*/;

If the following SQL is executed:

mysql> delete from hello where id = 2;
Query OK, 1 row affected (0.02 sec)

The corresponding generated binlog content:

# at 715
#180617 22:56:44 server id 1  end_log_pos 780 CRC32 0x9f52450e     Anonymous_GTID    last_committed=2    sequence_number=3    rbr_only=yes
/*!50718 SET TRANSACTION ISOLATION LEVEL READ COMMITTED*//*!*/;
SET @@SESSION.GTID_NEXT= 'ANONYMOUS'/*!*/;
# at 780
#180617 22:56:44 server id 1  end_log_pos 854 CRC32 0x0959bc8d     Query    thread_id=2    exec_time=0    error_code=0
SET TIMESTAMP=1529247404/*!*/;
BEGIN
/*!*/;
# at 854
#180617 22:56:44 server id 1  end_log_pos 907 CRC32 0x2945260f     Table_map: `testdb`.`hello` mapped to number 110
# at 907
#180617 22:56:44 server id 1  end_log_pos 956 CRC32 0xc70df255     Delete_rows: table id 110 flags: STMT_END_F
### DELETE FROM `testdb`.`hello`
### WHERE
###   @1=2
###   @2='Bill'
# at 956
#180617 22:56:44 server id 1  end_log_pos 987 CRC32 0x0c98f18e     Xid = 15
COMMIT/*!*/;

Use binlog incremental recovery

MySQL logical backup usually combines full backup and incremental backup, and uses mysqldump regularly Back up the database in full, and then use binlog to save incremental data. When restoring data, the data backed up by mysqldump is restored to the backup time point. If the database is incrementally modified from the backup time point to the current time, the incremental data in the binlog will be restored to the database through mysqlbinlog. Now assume that mysqldump has been used to restore the database to:

mysql> select * from hello;
+----+------+
| id | name |
+----+------+
|  1 | Andy |
|  2 | Lily |
|  3 | Will |
+----+------+
3 rows in set (0.00 sec)

The SQL executed afterwards:

update hello set name = 'David' where id = 3;
insert hello (name) values ('Frank');
delete from hello where id = 2;

Whether using STATEMENT or ROW, the mysqlbinlog command can incrementally restore binlog to the database [doc] .

Observing the binlog, we can see that from the initial update hello set name = 'David' where id = 3; to the final delete from hello where id = 2;, the time is from "2018-06-17 22:54:13" to "2018-06-17 22:56:44", so based on time point recovery, the command is as follows:

$ sudo mysqlbinlog --start-datetime="2018-06-17 22:54:13" --stop-datetime="2018-06-17 22:56:44" mysql-bin.000002 | mysql -uroot -p123456

binlog's event position number is from " 154" to "956", but it should be noted that --start-position and --stop-position are used to specify the position point range, which logically corresponds to start <= position < stop, so based on point-in-time recovery, the command is as follows:

$ sudo mysqlbinlog --start-position=154 --stop-position=957 mysql-bin.000002 | mysql -uroot -p123456

If executed in either way, the data can be restored to:

mysql> select * from hello;
+----+-------+
| id | name  |
+----+-------+
|  1 | Andy  |
|  3 | David |
|  4 | Frank |
+----+-------+
3 rows in set (0.00 sec)<p><strong> Flashback using binlog2sql</strong></p>
<p>binlog2sql, written by Cao Danfeng, DBA of Dianping.com. binlog2sql, parses the SQL you want from MySQL binlog. Depending on the options, you can get original SQL, rollback SQL, INSERT SQL with primary key removed, etc. Binlog2sql, the underlying implementation relies on python-mysql-replication, which completes the parsing of the MySQL replication protocol and binlog format. </p>
<pre class="brush:php;toolbar:false">$ python binlog2sql/binlog2sql.py -h192.168.2.107 -uroot -p123456 --start-position=154 --stop-position=957 --start-file='mysql-bin.000002'
UPDATE `testdb`.`hello` SET `id`=3, `name`='David' WHERE `id`=3 AND `name`='Will' LIMIT 1; #start 4 end 411 time 2018-06-17 22:54:13
INSERT INTO `testdb`.`hello`(`id`, `name`) VALUES (4, 'Frank'); #start 442 end 684 time 2018-06-17 22:55:47
DELETE FROM `testdb`.`hello` WHERE `id`=2 AND `name`='Bill' LIMIT 1; #start 715 end 956 time 2018-06-17 22:56:44

Generate rollback sql:

$ python binlog2sql/binlog2sql.py --flashback -h192.168.2.107 -uroot -p123456 --start-position=154 --stop-position=956 --start-file='mysql-bin.000002'
INSERT INTO `testdb`.`hello`(`id`, `name`) VALUES (2, 'Bill'); #start 715 end 956 time 2018-06-17 22:56:44
DELETE FROM `testdb`.`hello` WHERE `id`=4 AND `name`='Frank' LIMIT 1; #start 442 end 684 time 2018-06-17 22:55:47
UPDATE `testdb`.`hello` SET `id`=3, `name`='Will' WHERE `id`=3 AND `name`='David' LIMIT 1; #start 154 end 411 time 2018-06-17 22:54:13

The actual principle of flashback is very simple. First dump the binlog through the com-binlog-dump command of the MySQL replication protocol, and then follow the binlog Parse the binlog according to the format specification, convert the binlog into SQL, convert these SQL into reverse logical SQL, and finally execute it in reverse order.

Java parsing binlog

上文中的 binlog2sql 其实底层依赖 python-mysql-replication 库，这是 Python 库。如果想使用 Java 解析 binlog 可以使用 mysql-binlog-connector-java（github）库。目前开源的 CDC 工具，如 Zendesk maxwell、Redhat debezium、LinkedIn Databus 等都底层依赖 mysql-binlog-connector-java 或者其前身 open-replicator。使用 mysql-binlog-connector-java 的示例代码如下：

BinaryLogClient client = new BinaryLogClient("192.168.2.107", 3306, "root", "123456");
client.setBinlogFilename("mysql-bin.000001");
client.setBinlogPosition(4);
client.setBlocking(false);
client.registerEventListener(event -> {
    System.out.println(event);
});
client.connect();

输出（省略部分内容）：

...
Event{header=EventHeaderV4{timestamp=1529247253000, eventType=TABLE_MAP, serverId=1, headerLength=19, dataLength=34, nextPosition=346, flags=0}, data=TableMapEventData{tableId=110, database='testdb', table='hello', columnTypes=8, 15, columnMetadata=0, 40, columnNullability={1}}}
Event{header=EventHeaderV4{timestamp=1529247253000, eventType=EXT_UPDATE_ROWS, serverId=1, headerLength=19, dataLength=46, nextPosition=411, flags=0}, data=UpdateRowsEventData{tableId=110, includedColumnsBeforeUpdate={0, 1}, includedColumns={0, 1}, rows=[
    {before=[3, Will], after=[3, David]}
]}}
...
Event{header=EventHeaderV4{timestamp=1529247347000, eventType=TABLE_MAP, serverId=1, headerLength=19, dataLength=34, nextPosition=634, flags=0}, data=TableMapEventData{tableId=110, database='testdb', table='hello', columnTypes=8, 15, columnMetadata=0, 40, columnNullability={1}}}
Event{header=EventHeaderV4{timestamp=1529247347000, eventType=EXT_WRITE_ROWS, serverId=1, headerLength=19, dataLength=31, nextPosition=684, flags=0}, data=WriteRowsEventData{tableId=110, includedColumns={0, 1}, rows=[
    [4, Frank]
]}}
...
Event{header=EventHeaderV4{timestamp=1529247404000, eventType=TABLE_MAP, serverId=1, headerLength=19, dataLength=34, nextPosition=907, flags=0}, data=TableMapEventData{tableId=110, database='testdb', table='hello', columnTypes=8, 15, columnMetadata=0, 40, columnNullability={1}}}
Event{header=EventHeaderV4{timestamp=1529247404000, eventType=EXT_DELETE_ROWS, serverId=1, headerLength=19, dataLength=30, nextPosition=956, flags=0}, data=DeleteRowsEventData{tableId=110, includedColumns={0, 1}, rows=[
    [2, Bill]
]}}

The above is the detailed content of Detailed introduction to binlog log files in MySQL. For more information, please follow other related articles on the PHP Chinese website!