Flashback Recovery in MariaDB/MySQL Servers

In this blog, we will see how to do a flashback recovery or rolling back the data in MariaDB, MySQL and Percona.

As we know the saying  “All humans make mistakes”, following that in Database environment the data modified accidentally can bring havoc to any organisations.

Recover the lost data

  • The data can be recovered from the latest full backup or incremental backup when data size is huge it could take hours to restore it.
  • From backup of Binlogs.
  • Data can also be recovered from delayed slaves, this case would be helpful when the mistake is found immediately, within the period of delay.

We can use anyone of the above ways or other that can help to recover the lost data, but what really matters is, What is the time taken to rollback or recover the data? and How much downtime was taken to get back to the initial state ?

To overcome this disaster mysqlbinlog (MariaDB 10.2) has a very useful option i.e –flashback that comes along with binary of MariaDB server 10.2 linux ,debian and ubuntu ,though it comes with MariaDB server, it works well with Oracle Mysql servers and Percona flavour of MySQL.

What is Flashback?

Restoring back the data to the previous snapshot in a MySQL database or in a table is called Flashback.

Flashback options help us to undo the executed row changes(DML events).

For instance, it can change DELETE events to INSERTs and vice versa, and also it will swap WHERE and SET parts of the UPDATE events.

Prerequisites for using flashback :

  • binlog_format = ROW
  • binlog_row_image = FULL

Flash back uses the mysqlbinlog to create the rollback statements and it needs a FULL image (Minimal is not supported). Let us simulate a few test cases where flashback comes as a boon for recovering data.

For simulating the test cases I am using employees table and Mariadb version 10.2

MariaDB [employees]> select @@version;
+---------------------+
| @@version           |
+---------------------+
| 10.2.23-MariaDB-log |
+---------------------+
1 row in set (0.02 sec)

Table structure :

MariaDB [employees]> show create table employees\G
*************************** 1. row ***************************
       Table: employees
Create Table: CREATE TABLE `employees` (
  `emp_no` int(11) NOT NULL,
  `birth_date` date NOT NULL,
  `first_name` varchar(14) NOT NULL,
  `last_name` varchar(16) NOT NULL,
  `gender` enum('M','F') NOT NULL,
  `hire_date` date NOT NULL,
  PRIMARY KEY (`emp_no`)
) ENGINE=InnoDB DEFAULT CHARSET=latin1
1 row in set (0.00 sec)

Case 1:  Rollback the Deleted data.

Consider the data is deleted was from employees table where first_name =’Chirstian’ .

MariaDB [employees]> select COUNT(*) from employees where first_name ='Chirstian';
+----------+
| COUNT(*) |
+----------+
|      226 |
+----------+
1 row in set (0.07 sec)

MariaDB [employees]> delete from employees where first_name ='Chirstian';
Query OK, 226 rows affected (0.15 sec)

To revert the data to the previous state ,we need to decode the binlog and fetch the right start and stop position of the delete event happened on employees table. Start position should be taken exactly after BEGIN and Stop position is before the final COMMIT.

[root@vm3 vagrant]# mysqlbinlog -v --base64-output=DECODE-ROWS /var/lib/mysql/mysql-bin.000007 > mysql-bin.000007.txt

BEGIN
/*!*/;
# at 427
# at 501
#190417 17:49:49 server id 1  end_log_pos 501 CRC32 0xc7f1c84b  Annotate_rows:
#Q> delete from employees where first_name ='Chirstian'
#190417 17:49:49 server id 1  end_log_pos 569 CRC32 0x6b1b5c98  Table_map: `employees`.`employees` mapped to number 29
# at 569
#190417 17:49:49 server id 1  end_log_pos 7401 CRC32 0x6795a972         Delete_rows: table id 29 flags: STMT_END_F
### DELETE FROM `employees`.`employees`
### WHERE
###   @1=10004
###   @2='1954:05:01'
###   @3='Chirstian'
###   @4='Koblick'
###   @5=1
###   @6='1986:12:01'
# at 23733
#190417 17:49:49 server id 1  end_log_pos 23764 CRC32 0xf9ed5c3e        Xid = 455
### DELETE FROM `employees`.`employees`
### WHERE
### @1=498513
### @2='1964:10:01'
### @3='Chirstian'
### @4='Mahmud'
### @5=1
### @6='1992:06:03'
# at 7401
COMMIT/*!*/;
# at 23764
#190417 17:49:49 server id 1  end_log_pos 23811 CRC32 0x60dfac86        Rotate to mysql-bin.000008  pos: 4
DELIMITER ;
# End of log file
ROLLBACK /* added by mysqlbinlog */;

Once the count is verified the from the taken positions, we can prepare rollback statements  as a sql file using flashback as below

[root@vm3 vagrant]# mysqlbinlog  -v --flashback --start-position=427 --stop-position=7401 /var/lib/mysql/mysql-bin.000007  > insert.sql

Below is the comparison of conversion from Delete to Insert for a single record:

### DELETE FROM `employees`.`employees`
### WHERE
### @1=498513
### @2='1964:10:01'
### @3='Chirstian'
### @4='Mahmud'
### @5=1
### @6='1992:06:03'

### INSERT INTO `employees`.`employees`
### SET
### @1=498513
### @2='1964:10:01'
### @3='Chirstian'
### @4='Mahmud'
### @5=1
### @6='1992:06:03'
MariaDB [employees]> source insert.sql
Query OK, 0 rows affected (0.01 sec)
Query OK, 0 rows affected (0.00 sec)
Query OK, 0 rows affected (0.01 sec)
Query OK, 0 rows affected (0.00 sec)
Query OK, 0 rows affected (0.00 sec)
Query OK, 0 rows affected (0.00 sec)
Query OK, 0 rows affected (0.00 sec)
Query OK, 0 rows affected (0.00 sec)
Query OK, 0 rows affected (0.00 sec)

And the count is verified after the data load.

MariaDB [employees]> select COUNT(*) from employees where first_name ='Chirstian';
+----------+
| COUNT(*) |
+----------+
|      226 |
+----------+
1 row in set (0.06 sec)

Case 2 :  Rollbacking the Updated data.

The data was updated based on below conditions

MariaDB [employees]> select COUNT(*) from employees where first_name ='Chirstian' and gender='M';
+----------+
| COUNT(*) |
+----------+
|      129 |
+----------+
1 row in set (0.14 sec)

MariaDB [employees]> update employees set gender='F' where first_name ='Chirstian' and gender='M';
Query OK, 129 rows affected (0.16 sec)
Rows matched: 129  Changed: 129  Warnings: 0

MariaDB [employees]> select COUNT(*) from employees where first_name ='Chirstian' and gender='M';
+----------+
| COUNT(*) |
+----------+
|        0 |
+----------+
1 row in set (0.07 sec)

To rollback the updated data, the same steps to be followed as in case 1.

[root@vm3 vagrant]# mysqlbinlog -v --flashback --start-position=427 --stop-position=8380 /var/lib/mysql/mysql-bin.000008 > update.sql


MariaDB [employees]> source update.sql
Query OK, 0 rows affected (0.00 sec)
Query OK, 0 rows affected (0.00 sec)
Query OK, 0 rows affected (0.00 sec)
Query OK, 0 rows affected (0.00 sec)
Query OK, 0 rows affected (0.00 sec)
Query OK, 0 rows affected (0.00 sec)
Query OK, 0 rows affected (0.00 sec)
Query OK, 0 rows affected (0.01 sec)
Query OK, 0 rows affected (0.00 sec)

MariaDB [employees]> select COUNT(*) from employees where first_name ='Chirstian' and gender='M';
+----------+
| COUNT(*) |
+----------+
|      129 |
+----------+
1 row in set (0.06 sec)

In the above two cases by using flashback option we were able to change Event Type statements from DELETE to INSERT and Update_Event statements by Swapping the SET part and WHERE part.

Rollbacking data based on Time 

There may be chance where DBA’s get the request from team to rollback the deleted /updated data. In those cases DBA flashback can be used with –start-datetime and –stop-datetime options.

Let us consider we get an information that data was deleted at approximate datetime 2019-05-17 4:15:00 and below query was executed.

MariaDB [employees]> delete from employees where emp_no between 10101 and 10210;
Query OK, 110 rows affected (0.00 sec)

MariaDB [employees]> select count(*) from employees where emp_no between 10101 and 10210;
+----------+
| count(*) |
+----------+
| 0 |
+----------+
1 row in set (0.00 sec)

By Analysing available binary logs , we can fetch the required binlog for the provided datetime.

-rw-rw----. 1 mysql mysql 1.1G May 16 03:11 mysql-bin.000025
-rw-rw----. 1 mysql mysql 1.1G May 16 03:36 mysql-bin.000026
-rw-rw----.1 mysql mysql 1.1G May 16 04:02 mysql-bin.000027
-rw-rw----. 1 mysql mysql 1.1G May 16 05:10 mysql-bin.000028
-rw-rw----. 1 mysql mysql 1.1G May 16 05:32 mysql-bin.000028

To recover the data based on datetime, we should use date and time local timezone.

mysql-bin.000028 is the binlog which is nearest time to 4:15:00 

snap from binlog

BEGIN
/*!*/;
# at 662711655
# at 662711736
#190516  4:39:42 server id 1  end_log_pos 662711736 CRC32 0xcd7cd191    Annotate_rows:
#Q> delete from employees where emp_no between 10101 and 10210
#190516  4:39:42 server id 1  end_log_pos 662711804 CRC32 0x77719f68    Table_map: `employees`.`employees` mapped to number 29
# at 662711804
#190516  4:39:42 server id 1  end_log_pos 662714885 CRC32 0xde765d28    Delete_rows: table id 29 flags: STMT_END_F
### DELETE FROM `employees`.`employees`
### WHERE
###   @1=10101
###   @2='1952:04:15'
###   @3='Perla'
###   @4='Heyers'
###   @5=2
###   @6='1992:12:28'
### DELETE FROM `employees`.`employees`
### WHERE
###   @1=10102
###   @2='1959:11:04'
###   @3='Paraskevi'
###   @4='Luby'
###   @5=2
###   @6='1994:01:26'
### DELETE FROM `employees`.`employees`
### WHERE
###   @1=10210
###   @2='1958:01:24'
###   @3='Yuping'
###   @4='Alpin'
###   @5=1
###   @6='1994:05:10'
# at 662714885
#190517  4:39:42 server id 1  end_log_pos 662714916 CRC32 0xf9ba3c0a    Xid = 2860541
COMMIT/*!*/;
# at 662714916

The from the binlog we can see actual delete was happened at 4:39:42

[root@vm3]# mysqlbinlog --flashback --start-datetime="2019-05-17 04:39:00"  /var/lib/mysql/mysql-bin.000028  -v --database=employees --table=employees  > insert.sql

MariaDB [employees]> source insert.sql
Query OK, 0 rows affected (0.00 sec)
Query OK, 0 rows affected (0.00 sec)
Query OK, 0 rows affected (0.00 sec)
Query OK, 0 rows affected (0.01 sec)
Query OK, 0 rows affected (0.00 sec)

MariaDB [employees]> select count(*) from employees where emp_no between 10101 and 10210;
+----------+
| count(*) |
+----------+
|      110 |
+----------+
1 row in set (0.04 sec)

Using Flashback in MySQL Community/Percona server.

To check the compatibility of mysqlbinlog tool with Mysql/Percona variants , i have also tested the with MySQL version 5.7.24 .

mysql> select @@version;
+---------------+
| @@version     |
+---------------+
| 5.7.24-27-log |
+---------------+
1 row in set (0.00 sec)

mysql> select count(*) from employees where emp_no between 10001 and 10110;
+----------+
| count(*) |
+----------+
|      110 |
+----------+
1 row in set (0.00 sec)

mysql> delete from employees where emp_no between 10001 and 10110;
Query OK, 110 rows affected (0.00 sec)

Flashback option comes only with Mariadb 10.2 server and above ,so i have copied the binlog which contains my lost transactions to a new server with Mariadb binaries installed.

Mariadb server (binaries) can also be installed in a local system (linux and Debian and Ubuntu) or the binlogs can be copied to pre-installed Mariadb server.

Snap of delete events from MySQL 5.7 binlog

BEGIN
/*!*/;
# at 336
#190506 10:04:25 server id 11  end_log_pos 404 CRC32 0x2b6e0318         Table_map: `employees`.`employees` mapped to number 255
# at 404
#190506 10:04:25 server id 11  end_log_pos 3459 CRC32 0x64cf7a16        Delete_rows: table id 255 flags: STMT_END_F
### DELETE FROM `employees`.`employees`
### WHERE
###   @1=10001
###   @2='1953:09:02'
###   @3='Georgi'
###   @4='Facello'
###   @5=1
###   @6='1986:06:26'
### DELETE FROM `employees`.`employees`
### WHERE
###   @1=10002
###   @2='1964:06:02'
###   @3='Bezalel'
###   @4='Simmel'
###   @5=2
###   @6='1985:11:21'
mysqlbinlog --flashback -v --start-position=336 --stop-position=3459 mysql-bin.000024 > insert_57.sql

mysql> source insert_57.sql
Query OK, 0 rows affected (0.00 sec)
Query OK, 0 rows affected, 1 warning (0.00 sec)
Query OK, 0 rows affected (0.00 sec)
Query OK, 0 rows affected (0.00 sec)
Query OK, 0 rows affected (0.00 sec)
Query OK, 0 rows affected (0.00 sec)
Query OK, 0 rows affected (0.00 sec)
Query OK, 0 rows affected (0.01 sec)
Query OK, 0 rows affected (0.00 sec)

mysql> select count(*) from employees where emp_no between 10001 and 10110;
+----------+
| count(*) |
+----------+
|      110 |
+----------+
1 row in set (0.00 sec)

mysql> select @@version;
+---------------+ 
| @@version     | 
+---------------+ 
| 5.7.24-27-log |
+---------------+ 
1 row in set (0.00 sec)

The MariaDB flashback option works fine with MySQL variants too.

Flashback with MySQL GTID

The flashback works fine with the conversion of delete into insert statements in GTID, but it fails to execute the when the data is loaded.

Snap of binlog from GTID enabled MySQL server

SET @@SESSION.GTID_NEXT= '7d60dbfb-29dd-11e9-a71a-080027dfb17a:64'/*!*/;
# at 259
#190506 11:36:29 server id 11  end_log_pos 336 CRC32 0xaa55b2c9         Query   thread_id=29022 exec_time=0     error_code=0
SET TIMESTAMP=1557142589/*!*/;
SET @@session.pseudo_thread_id=29022/*!*/;
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/*!*/;
BEGIN
/*!*/;
# at 336
#190506 11:36:29 server id 11  end_log_pos 404 CRC32 0x8e10c960         Table_map: `employees`.`employees` mapped to number 255
# at 404
#190506 11:36:29 server id 11  end_log_pos 3459 CRC32 0x02d82af3        Delete_rows: table id 255 flags: STMT_END_F
### DELETE FROM `employees`.`employees`
### WHERE
###   @1=10001
###   @2='1953:09:02'
###   @3='Georgi'
###   @4='Facello'
###   @5=1
###   @6='1986:06:26'
mysqlbinlog --flashback -v --start-position=336 --stop-position=3459 mysql-bin.000029  > gtid.sql

mysql> source gtid.sql
Query OK, 0 rows affected (0.00 sec)
Query OK, 0 rows affected, 1 warning (0.00 sec)
Query OK, 0 rows affected (0.00 sec)
Query OK, 0 rows affected (0.00 sec)
ERROR 1782 (HY000): @@SESSION.GTID_NEXT cannot be set to ANONYMOUS when @@GLOBAL.GTID_MODE = ON.
ERROR 1782 (HY000): @@SESSION.GTID_NEXT cannot be set to ANONYMOUS when @@GLOBAL.GTID_MODE = ON.
ERROR 1782 (HY000): @@SESSION.GTID_NEXT cannot be set to ANONYMOUS when @@GLOBAL.GTID_MODE = ON.
Query OK, 0 rows affected (0.00 sec)
Query OK, 0 rows affected (0.00 sec)

In this case, we need to disable the GTID mode and restore data,ta , which in painful for production servers.

Limitations of Flashback 

  • It Doesn’t support DDL ( DROP/TRUNCATE or other DDL’s)
  • It Doesn’t support encrypted binlog
  • It Doesn’t support compressed binlog

Use cases of flashback

  • When we are not aware of exact start and stop positions , use –start-datetime and –stop-datetime
  • Also, we can transform the changes for a particular database or a table using the options –database(-d) and table (-T)
  • For more Binlog options refer Link

Key Takeaways:

  • To reverse the mishandled operations from binary logs.
  • No need to stop the server to carry out this operation.
  • When the data is small to revert back, flashback process is very faster than recovering the data from Full Backup.
  • Point in time recovery (PITR) becomes easy.

There is a similar open source tool called binlog2sql developed by US team review DBA team (Shanghai) , which works on the same principle of mysqlbinlog flashback.

This tool can also be used based on convienient and usecase.

Photo by Jiyeon Park on Unsplash

Advertisements

Leave a Reply

Fill in your details below or click an icon to log in:

WordPress.com Logo

You are commenting using your WordPress.com account. Log Out /  Change )

Google photo

You are commenting using your Google account. Log Out /  Change )

Twitter picture

You are commenting using your Twitter account. Log Out /  Change )

Facebook photo

You are commenting using your Facebook account. Log Out /  Change )

Connecting to %s