In this blog post, we’ll look at a workaround for MySQL bug 72804.
Recently I worked on a ticket where a customer performed a point-in-time recovery PITR using a large set of binary logs. Normally we handle this by applying the last backup, then re-applying all binary logs created since the last backup. In the middle of the procedure, their new server crashed. We identified the binary log position and tried to restart the PITR from there. However, using the option --start-position, the restore failed with the error “The BINLOG statement of type Table_map was not preceded by a format description BINLOG statement.” This is a known bug and is reported as MySQL Bug #72804: “BINLOG statement can no longer be used to apply Query events.”
I created a small test to demonstrate a workaround that we implemented (and worked).
First, I ran a large import process that created several binary logs. I used a small value in max_binlog_size and tested using the database “employees” (a standard database used for testing).Then I dropped the database.
1 2 3 4 5 | mysql> set sql_log_bin=0; Query OK, 0 rows affected (0.33 sec) mysql> drop database employees; Query OK, 8 rows affected (1.25 sec) |
To demonstrate the recovery process, I joined all the binary log files into one SQL file and started an import.
1 2 3 4 | sveta@Thinkie:~/build/ps-5.7/mysql-test$ ../bin/mysqlbinlog var/mysqld.1/data/master.000001 var/mysqld.1/data/master.000002 var/mysqld.1/data/master.000003 var/mysqld.1/data/master.000004 var/mysqld.1/data/master.000005 > binlogs.sql sveta@Thinkie:~/build/ps-5.7/mysql-test$ GENERATE_ERROR.sh binlogs.sql sveta@Thinkie:~/build/ps-5.7/mysql-test$ mysql < binlogs.sql ERROR 1064 (42000) at line 9020: You have an error in your SQL syntax; check the manual that corresponds to your MySQL server version for the right syntax to use near 'inserting error |
I intentionally generated a syntax error in the resulting file with the help of the GENERATE_ERROR.sh script (which just inserts a bogus SQL statement in a random row). The error message clearly showed where the import stopped: line 9020. I then created a file that cropped out the part that had already been imported (lines 1- 9020), and tried to import this new file.
1 2 3 | sveta@Thinkie:~/build/ps-5.7/mysql-test$ tail -n +9021 binlogs.sql >binlogs_rest.sql sveta@Thinkie:~/build/ps-5.7/mysql-test$ mysql < binlogs_rest.sql ERROR 1609 (HY000) at line 134: The BINLOG statement of type `Table_map` was not preceded by a format description BINLOG statement. |
Again, the import failed with exactly the same error as the customer. The reason for this error is that the BINLOG statement – which applies changes from the binary log – expects that the format description event gets run in the same session as the binary log import, but before it. The format description existed initially at the start of the import that failed at line 9020. The later import (from line 9021 on) doesn’t contain this format statement.
Fortunately, this format is the same for the same version! We can simply take it from the beginning the SQL log file (or the original binary file) and put into the file created after the crash without lines 1-9020.
With MySQL versions 5.6 and 5.7, this event is located in the first 11 rows:
1 2 3 4 5 6 7 8 9 10 11 12 | sveta@Thinkie:~/build/ps-5.7/mysql-test$ head -n 11 binlogs.sql | cat -n 1 /*!50530 SET @@SESSION.PSEUDO_SLAVE_MODE=1*/; 2 /*!50003 SET @OLD_COMPLETION_TYPE=@@COMPLETION_TYPE,COMPLETION_TYPE=0*/; 3 DELIMITER /*!*/; 4 # at 4 5 #170128 17:58:11 server id 1 end_log_pos 123 CRC32 0xccda074a Start: binlog v 4, server v 5.7.16-9-debug-log created 170128 17:58:11 at startup 6 ROLLBACK/*!*/; 7 BINLOG ' 8 g7GMWA8BAAAAdwAAAHsAAAAAAAQANS43LjE2LTktZGVidWctbG9nAAAAAAAAAAAAAAAAAAAAAAAA 9 AAAAAAAAAAAAAAAAAACDsYxYEzgNAAgAEgAEBAQEEgAAXwAEGggAAAAICAgCAAAACgoKKioAEjQA 10 AUoH2sw= 11 '/*!*/; |
The first six rows are meta information, and rows 6-11 are the format event itself. The only thing we need to export into our resulting file is these 11 lines:
1 2 3 4 | sveta@Thinkie:~/build/ps-5.7/mysql-test$ head -n 11 binlogs.sql > binlogs_rest_with_format.sql sveta@Thinkie:~/build/ps-5.7/mysql-test$ cat binlogs_rest.sql >> binlogs_rest_with_format.sql sveta@Thinkie:~/build/ps-5.7/mysql-test$ mysql < binlogs_rest_with_format.sql sveta@Thinkie:~/build/ps-5.7/mysql-test$ |
After this, the import succeeded!
Hi Svela, if I understand well, Bug#72804 can happen if you do not restart the import at a transaction boundary. In this case, wouldn’t your import be inconsistent (missing the previous statements in the transaction) ? If this is the case, I think it should be closed as “Not a Bug”.
For PITR, I prefer to use Binlog Server. I wrote a blog post in the past about this: [1]. The advantage of using Binlog Server is using all power of replication: easy restart, transaction skipping, parallel replication, possibility of using filtering, … I also understand that Facebook built their own Binlog Server exactly for that ([2]).
[1]: http://jfg-mysql.blogspot.nl/2015/10/binlog-servers-for-backups-and-point-in-time-recovery.html
[2]: https://www.percona.com/live/plam16/sessions/binlog-server-facebook
Best regards.
No, although I did not explicitly mention this, I am not trying to apply partial transaction.
I think you’ve misunderstood bug 72804. In the bug report he encodes a QUERY event in base64 and applies after a having already appied a binlog format description event. Which is currently not allowed.
In your hypothetical example, you were making a mistake by not having sent a format description event before your table_map event. Using –start-position with mysqlbinlog it should still emit a format_description_event before applying the event at the start position
The issue your customer had, where they were using the –start-position option with mysqlbinlog, that sounds like a bug with the version of mysqlbinlog they were using to me. I don’t know whether this once has been a problem
Happy to be corrected if I’m mistaken
This is true that if you run mysqlbinlog with option –start-position it will print format event.
Issue with my customer was that they already had SQL file, generated by mysqlbinlog command. And importing this SQL file failed.
Now they had two options: re-generate SQL file using mysqlbinlog command or make changes manually. They had many huge binlog files (several GB) and this would take a lot of time.
You can test this with quite small binary log file, generated by 1200 seconds standard SysBench OLTP test run:
sveta@delly:~/tmp$ ls -lh master.000001
-rw-rw—- 1 sveta sveta 716M Feb 19 23:36 master.000001
sveta@delly:~/tmp$ time ~/build/mysql-5.7/bin/mysqlbinlog master.000001 > master.000001.sql
real 0m46.651s
user 0m41.256s
sys 0m5.308s
sveta@delly:~/tmp$ ls -lh master.000001.sql
-rw-rw-r– 1 sveta sveta 1.4G Feb 19 23:40 master.000001.sql
So it takes 46 seconds to generate 1.4G SQL file out of 716M binary log.
Now lets assume import has broken at some position and next transaction starts at position 190111037. So we need to re-generate SQL file, starting from this position:
sveta@delly:~/tmp$ time ~/build/mysql-5.7/bin/mysqlbinlog master.000001 –start-position=190111037 > master.000001.sql.4
real 0m40.570s
user 0m36.504s
sys 0m3.924s
It takes 40 seconds if use mysqlbinlog.
However if use OS tools whole operation will take much less time:
sveta@delly:~/tmp$ time tail -n +3410882 master.000001.sql > master.000001.sql.2
real 0m3.202s
user 0m0.108s
sys 0m3.084s
sveta@delly:~/tmp$ time head -n 11 master.000001.sql > master.000001.sql.3; time cat master.000001.sql.2 >> master.000001.sql.3
real 0m0.266s
user 0m0.000s
sys 0m0.264s
real 0m2.879s
user 0m0.012s
sys 0m2.856s
Total amount is 3.202+0.266+2.879 = 6.347 seconds which is more than 6 times faster than if use msyqlbinlog.
For this tiny amount timing, while noticeable, does not matter much, but if you have larger amount of binary logs you may not want to re-generate SQL from binary logs again.
> I think you’ve misunderstood bug 72804. In the bug report he encodes a QUERY event in base64 and applies after a having already appied a binlog format description event. Which is currently not allowed.
No, he is not. He just tries to apply any query event using command line client. This worked fine for years and was very useful when you tried to find out a reason why one or another event, replicated, from master fails on slave. Or if you needed to continue loading broken imports like my customer did.
Bibliography MySQL concept is very interesting.
Nicely explained. Thanks for sharing.
Siddhesh-C Programming
Sorry for my autocorrect
*Binlog
Is it a bit dangerous that use the binlog_rest.sql directly? If there is a transaction just cross the 9020th line, this transaction will fail and rollback when it occur the error in 9020. After that, when we use the second part, the transaction is partial. So it may lead to data lost.
Yes, this is dangerous. I skipped this part for brevity, but you have to care yourself about your transactions. There are two techniques to find a row at which you need to split the file: find a row where import failed and either skip forward to the next transaction or skip backward to the start of failed transaction, then crop the file.
But you should care about partial transactions if use mysqlbinlog wth –start-position option as well.
Lets consider following case:
mysql> create table t(f1 int) engine=innodb;
Query OK, 0 rows affected (0.00 sec)
mysql> begin;
Query OK, 0 rows affected (0.00 sec)
mysql> insert into t values(1);
Query OK, 1 row affected (0.00 sec)
mysql> insert into t values(2);
Query OK, 1 row affected (0.00 sec)
mysql> insert into t values(3);
Query OK, 1 row affected (0.00 sec)
mysql> commit;
Query OK, 0 rows affected (0.00 sec)
Now lets flush logs and truncate the table. We will have binary log file master.000001 with transaction which inserts 3 rows and next log file will contain truncate statement.
mysql> flush logs;
Query OK, 0 rows affected (0.00 sec)
mysql> truncate t;
Query OK, 0 rows affected (0.02 sec)
If run mysqlbinlog without any option we will have all 3 INSERT statements in the output:
/*!50530 SET @@SESSION.PSEUDO_SLAVE_MODE=1*/;
/*!50003 SET @OLD_COMPLETION_TYPE=@@COMPLETION_TYPE,COMPLETION_TYPE=0*/;
DELIMITER /*!*/;
# at 4
#170220 4:04:14 server id 1 end_log_pos 123 CRC32 0x40dc8145 Start: binlog v 4, server v 5.7.17-log created 170220 4:04:14 at startup
ROLLBACK/*!*/;
BINLOG ‘
DrGqWA8BAAAAdwAAAHsAAAAAAAQANS43LjE3LWxvZwAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA
AAAAAAAAAAAAAAAAAAAOsapYEzgNAAgAEgAEBAQEEgAAXwAEGggAAAAICAgCAAAACgoKKioAEjQA
AUWB3EA=
‘/*!*/;
# at 123
#170220 4:04:14 server id 1 end_log_pos 154 CRC32 0xb42a8615 Previous-GTIDs
# [empty]
# at 154
#170220 4:04:57 server id 1 end_log_pos 219 CRC32 0x792b0944 Anonymous_GTID last_committed=0 sequence_number=1
SET @@SESSION.GTID_NEXT= ‘ANONYMOUS’/*!*/;
# at 219
#170220 4:04:57 server id 1 end_log_pos 329 CRC32 0xebcbbc8c Query thread_id=3 exec_time=0 error_code=0
use
test/*!*/;SET TIMESTAMP=1487581497/*!*/;
SET @@session.pseudo_thread_id=3/*!*/;
SET @@session.foreign_key_checks=1, @@session.sql_auto_is_null=0, @@session.unique_checks=1, @@session.autocommit=1/*!*/;
SET @@session.sql_mode=1436549152/*!*/;
SET @@session.auto_increment_increment=1, @@session.auto_increment_offset=1/*!*/;
/*!\C latin1 *//*!*/;
SET @@session.character_set_client=8,@@session.collation_connection=8,@@session.collation_server=8/*!*/;
SET @@session.lc_time_names=0/*!*/;
SET @@session.collation_database=DEFAULT/*!*/;
create table t(f1 int) engine=innodb
/*!*/;
# at 329
#170220 4:05:23 server id 1 end_log_pos 394 CRC32 0xbfe8f73a Anonymous_GTID last_committed=1 sequence_number=2
SET @@SESSION.GTID_NEXT= ‘ANONYMOUS’/*!*/;
# at 394
#170220 4:05:13 server id 1 end_log_pos 466 CRC32 0x38458ff5 Query thread_id=3 exec_time=0 error_code=0
SET TIMESTAMP=1487581513/*!*/;
BEGIN
/*!*/;
# at 466
#170220 4:05:13 server id 1 end_log_pos 510 CRC32 0xd5c3e335 Table_map:
test.tmapped to number 221# at 510
#170220 4:05:13 server id 1 end_log_pos 550 CRC32 0xd8dd2cb4 Write_rows: table id 221 flags: STMT_END_F
BINLOG ‘
SbGqWBMBAAAALAAAAP4BAAAAAN0AAAAAAAEABHRlc3QAAXQAAQMAATXjw9U=
SbGqWB4BAAAAKAAAACYCAAAAAN0AAAAAAAEAAgAB//4BAAAAtCzd2A==
‘/*!*/;
### INSERT INTO
test.t### SET
### @1=1
# at 550
#170220 4:05:15 server id 1 end_log_pos 594 CRC32 0x2370970c Table_map:
test.tmapped to number 221# at 594
#170220 4:05:15 server id 1 end_log_pos 634 CRC32 0x3fa551f8 Write_rows: table id 221 flags: STMT_END_F
BINLOG ‘
S7GqWBMBAAAALAAAAFICAAAAAN0AAAAAAAEABHRlc3QAAXQAAQMAAQyXcCM=
S7GqWB4BAAAAKAAAAHoCAAAAAN0AAAAAAAEAAgAB//4CAAAA+FGlPw==
‘/*!*/;
### INSERT INTO
test.t### SET
### @1=2
# at 634
#170220 4:05:21 server id 1 end_log_pos 678 CRC32 0x97555a06 Table_map:
test.tmapped to number 221# at 678
#170220 4:05:21 server id 1 end_log_pos 718 CRC32 0xef3753a3 Write_rows: table id 221 flags: STMT_END_F
BINLOG ‘
UbGqWBMBAAAALAAAAKYCAAAAAN0AAAAAAAEABHRlc3QAAXQAAQMAAQZaVZc=
UbGqWB4BAAAAKAAAAM4CAAAAAN0AAAAAAAEAAgAB//4DAAAAo1M37w==
‘/*!*/;
### INSERT INTO
test.t### SET
### @1=3
# at 718
#170220 4:05:23 server id 1 end_log_pos 749 CRC32 0x2ade2d48 Xid = 8
COMMIT/*!*/;
# at 749
#170220 4:05:26 server id 1 end_log_pos 793 CRC32 0x3ba055c0 Rotate to master.000002 pos: 4
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*/;
But if we start, say, from position 634, we will have partial transaction:
sveta.smirnova@bm-support01:~/mysql-5.7.17-linux-glibc2.5-x86_64/mysql-test$ ../bin/mysqlbinlog -v –start-position=634 var/mysqld.1/data/master.000001 > test_634.sql
sveta.smirnova@bm-support01:~/mysql-5.7.17-linux-glibc2.5-x86_64/mysql-test$ cat test_634.sql
/*!50530 SET @@SESSION.PSEUDO_SLAVE_MODE=1*/;
/*!50003 SET @OLD_COMPLETION_TYPE=@@COMPLETION_TYPE,COMPLETION_TYPE=0*/;
DELIMITER /*!*/;
# at 4
#170220 4:04:14 server id 1 end_log_pos 123 CRC32 0x40dc8145 Start: binlog v 4, server v 5.7.17-log created 170220 4:04:14 at startup
ROLLBACK/*!*/;
BINLOG ‘
DrGqWA8BAAAAdwAAAHsAAAAAAAQANS43LjE3LWxvZwAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA
AAAAAAAAAAAAAAAAAAAOsapYEzgNAAgAEgAEBAQEEgAAXwAEGggAAAAICAgCAAAACgoKKioAEjQA
AUWB3EA=
‘/*!*/;
# at 634
#170220 4:05:21 server id 1 end_log_pos 678 CRC32 0x97555a06 Table_map:
test.tmapped to number 221# at 678
#170220 4:05:21 server id 1 end_log_pos 718 CRC32 0xef3753a3 Write_rows: table id 221 flags: STMT_END_F
BINLOG ‘
UbGqWBMBAAAALAAAAKYCAAAAAN0AAAAAAAEABHRlc3QAAXQAAQMAAQZaVZc=
UbGqWB4BAAAAKAAAAM4CAAAAAN0AAAAAAAEAAgAB//4DAAAAo1M37w==
‘/*!*/;
### INSERT INTO
test.t### SET
### @1=3
# at 718
#170220 4:05:23 server id 1 end_log_pos 749 CRC32 0x2ade2d48 Xid = 8
COMMIT/*!*/;
# at 749
#170220 4:05:26 server id 1 end_log_pos 793 CRC32 0x3ba055c0 Rotate to master.000002 pos: 4
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*/;
And if we then try to apply this file we receive partial set of rows in our table too:
sveta.smirnova@bm-support01:~/mysql-5.7.17-linux-glibc2.5-x86_64/mysql-test$ ../bin/mysql -uroot -h127.0.0.1 -P13000 test < test_634.sql sveta.smirnova@bm-support01:~/mysql-5.7.17-linux-glibc2.5-x86_64/mysql-test$ ../bin/mysql -uroot -h127.0.0.1 -P13000 test Reading table information for completion of table and column names You can turn off this feature to get a quicker startup with -AWelcome to the MySQL monitor. Commands end with ; or \g. Your MySQL connection id is 5 Server version: 5.7.17-log MySQL Community Server (GPL)Copyright (c) 2000, 2016, Oracle and/or its affiliates. All rights reserved.Oracle is a registered trademark of Oracle Corporation and/or its affiliates. Other names may be trademarks of their respective owners.Type 'help;' or '\h' for help. Type '\c' to clear the current input statement.mysql> select * from t;
+——+
| f1 |
+——+
| 3 |
+——+
1 row in set (0.00 sec)
So no matter which method you use to apply partial updates you have to care about data consistency yourself.
thanks a lot