CS MySQL Database Backup and Recovery Validation for System Administrators

The CS MySQL database backup and recovery procedures should be validated periodically.

Example restore of mysql.cs with verification

The database backups on CS MySQL servers use Percona innobackupex augmented with MySQL binary logs (binlog). This example shows verification of the innobackupex backup and restore procedure by comparing before and after logical dumps using mysqldump. Additional checks during the procedure demonstrate other validation opportunities.

Overview of the procedure

• Daily cron jobs on the production MySQL server currently take an innobackupex backup and a mysqldump logical backup at different times to a local filesystem.
• An hourly cron job on the backup server uses rsync to copy the local backups and the binlogs.
• In this test we copy these files from the backup server to a spare unused MySQL server.
• Perform an innobackupex restore on the spare server.
• Do a binlog point-in-time restore to match the time of the mysqldump logical backup.
• Use mysqldump on the restored database.
• Compare the old and new mysqldumps.

Detailed procedure

• On the mysql remote backup host, find the latest backup files, including the mysqldump logical dump.

ubuntu1404-202# latestmysqldump=`ls -d /mysql/backups/mysql.cs/mysqldump-*--all-databases.sql | tail -1`
ubuntu1404-202# latestinnobackupex=`ls -d /mysql/backups/mysql.cs/*-innobackupex | tail -1`
ubuntu1404-202# latestetcmysql=`ls -d /mysql/backups/mysql.cs/*-etcmysql.tar | tail -1`
ubuntu1404-202# last2daysbinlog=`find /mysql/backups/mysql.cs/binlog* -mmin -2880`

ubuntu1404-202# ls -ldtr $latestmysqldump $latestinnobackupex $latestetcmysql $last2daysbinlog
-rw-rw----  1 mysql adm     42593850 Sep  9 06:39 /mysql/backups/mysql.cs/binlog.000235
-r--------  1 root  root       20480 Sep 10 05:27 /mysql/backups/mysql.cs/mysql-172-1441877221-etcmysql.tar
dr-x------ 31 root  root        4096 Sep 10 05:35 /mysql/backups/mysql.cs/mysql-172-1441877221-innobackupex
-r--------  1 root  root 52827191306 Sep 10 06:11 /mysql/backups/mysql.cs/mysqldump-mysql-172-1441878421--all-databases.sql
-rw-rw----  1 mysql adm     42473665 Sep 10 06:42 /mysql/backups/mysql.cs/binlog.000236
-rw-rw----  1 mysql adm          348 Sep 10 06:42 /mysql/backups/mysql.cs/binlog.index
-rw-rw----  1 mysql adm     15965897 Sep 10 12:39 /mysql/backups/mysql.cs/binlog.000237

• Copy them to an unused spare mysql server.

ubuntu1404-202# for i in $latestmysqldump $latestinnobackupex $latestetcmysql $last2daysbinlog ; do echo === $i ; time rsync -a $i marmoset_db-002.student.cs:/var/backups/mysql/mysql.cs ; done
=== /mysql/backups/mysql.cs/mysqldump-mysql-172-1441878421--all-databases.sql
real  16m48.973s ...
=== /mysql/backups/mysql.cs/mysql-172-1441877221-innobackupex
real  20m40.535s ...
=== /mysql/backups/mysql.cs/mysql-172-1441877221-etcmysql.tar
real  0m0.229s ...
=== /mysql/backups/mysql.cs/binlog.000235
real  0m1.371s ...
=== /mysql/backups/mysql.cs/binlog.000236
real  0m1.323s ...
=== /mysql/backups/mysql.cs/binlog.000237
real  0m0.851s ...
=== /mysql/backups/mysql.cs/binlog.index
real  0m0.305s ...

ubuntu1404-202# time rsync -a $latestmysqldump $latestinnobackupex $latestetcmysql $last2daysbinlog marmoset_db-002.student.cs:/var/backups/mysql/mysql.cs
real  0m0.425s ...

• On the spare mysql server, stop mysqld. It may be running independent of the service command for testing. Make sure both are stopped. mysqld may take several seconds to shut down.

marmoset_db-002# service mysql status
mysql stop/waiting

marmoset_db-002# ps -elf | grep '[m]ysql'
4 S root      4721  4527  0  80   0 -  1112 wait   Sep09 pts/0    00:00:00 /bin/sh /usr/bin/mysqld_safe --skip-networking --read-only
4 S mysql     5254  4721  0  80   0 - 645291 poll_s Sep09 pts/0   00:05:57 /usr/sbin/mysqld --basedir=/usr --datadir=/var/lib/mysql --plugin-dir=/usr/lib/mysql/plugin --user=mysql --skip-networking --read-only --log-error=/var/log/mysql/error.log --pid-file=/var/run/mysqld/mysqld.pid --socket=/var/run/mysqld/mysqld.sock --port=3306

marmoset_db-002# kill 5254

marmoset_db-002# ps -elf | grep '[m]ysql'
[nothing]

• This host currently has no useful mysql data, configuration or logs. So, just delete them before doing the restore.

marmoset_db-002# rm -r /var/lib/mysql && mkdir /var/lib/mysql && chown mysql:mysql /var/lib/mysql && chmod 700 /var/lib/mysql

marmoset_db-002# rm -r /etc/mysql

marmoset_db-002# rm /var/log/mysql/*

• Restore the mysql configuration from the backups we just copied here. Fix the bind-address to listen only on localhost for testing.

marmoset_db-002# tar --directory / -xf `ls -1d /var/backups/mysql/mysql.cs/*-etcmysql.tar | tail -1`

marmoset_db-002# cp /etc/mysql/my.cnf /tmp/mysqlbackuptest$$

marmoset_db-002# vi /etc/mysql/my.cnf

marmoset_db-002# diff -t /tmp/mysqlbackuptest$$/my.cnf /etc/mysql/my.cnf
47c47,51
< bind-address            = 172.19.155.9
---
> # Was:
> # bind-address          = 172.19.155.9
> # ( == mysql-172.cs.uwaterloo.ca. )
> # Testing:
> bind-address            = 127.0.0.1

• Use Percona innobackupex to restore the latest full backup.
• First, the backup must be "prepared" before it can be restored. This modifies the backup. So, use a temporary copy. Check for "innobackupex: completed OK!".

marmoset_db-002# latestinnobackupex=`ls -d /var/backups/mysql/mysql.cs/*-innobackupex | tail -1`

marmoset_db-002# ls -ld $latestinnobackupex
dr-x------ 1 root root 944 Sep 10 05:35 /var/backups/mysql/mysql.cs/mysql-172-1441877221-innobackupex

marmoset_db-002# innobackupex --use-memory=2G --apply-log $latestinnobackupex
[...]
[notice (again)]
  If you use binary log and don't use any hack of group commit,
  the binary log position seems to be:
InnoDB: Last MySQL binlog file position 0 39749596, file name /var/log/mysql/binlog.000236

xtrabackup: starting shutdown with innodb_fast_shutdown = 1
InnoDB: FTS optimize thread exiting.
InnoDB: Starting shutdown...
InnoDB: Shutdown completed; log sequence number 262165949596
150910 14:37:55  innobackupex: completed OK!

• Now, restore from the prepared backup. Check for "innobackupex: completed OK!".
• (Note, this LXC container has lots of RAM and a fast SSD array. So the local copy-back is much faster than the earlier rsync.)

marmoset_db-002# time innobackupex --copy-back $latestinnobackupex
[...]
150910 14:42:54  innobackupex: completed OK!
real  1m33.205s
user  0m0.476s
sys   1m9.568s

• After the --copy-back, we need to fix permissions.

marmoset_db-002# chown -R mysql:mysql /var/lib/mysql/.

• Check total data size.

marmoset_db-002# du -hs $latestinnobackupex /var/lib/mysql
61G   /var/backups/mysql/mysql.cs/mysql-172-1441877221-innobackupex
61G   /var/lib/mysql

• The data is now restored to the state of the last full backup.

• Start mysqld to facilitate further testing.
• Use --skip-networking to make sure that users and applications can't connect to the database by accident.
• This assumes there are no unexpected connections from the local host, e.g. cron jobs or local unprivileged users.
• Additionally, enforce read-only (except for users with the SUPER privilege).

marmoset_db-002# ps -elf | grep '[m]ysql'
[nothing]

marmoset_db-002# cd /tmp

marmoset_db-002# mysqld_safe --skip-networking --read-only &
[1] 6058
marmoset_db-002# 150910 14:49:00 mysqld_safe Can't log to error log and syslog at the same time.  Remove all --log-error configuration options for --syslog to take effect.
150910 14:49:00 mysqld_safe Logging to '/var/log/mysql/error.log'.
150910 14:49:00 mysqld_safe Starting mysqld daemon with databases from /var/lib/mysql

• Check mysqld is running, not listening for TCP connections, is accepting local connections, and has reasonable status.

marmoset_db-002# ps -elf | grep '[m]ysql'
4 S root      6058  4527  0  80   0 -  1112 wait   14:49 pts/0    00:00:00 /bin/sh /usr/bin/mysqld_safe --skip-networking --read-only
4 S mysql     6591  6058  0  80   0 - 563321 poll_s 14:49 pts/0   00:00:00 /usr/sbin/mysqld --basedir=/usr --datadir=/var/lib/mysql --plugin-dir=/usr/lib/mysql/plugin --user=mysql --skip-networking --read-only --log-error=/var/log/mysql/error.log --pid-file=/var/run/mysqld/mysqld.pid --socket=/var/run/mysqld/mysqld.sock --port=3306

marmoset_db-002# lsof -i | grep mysql
[nothing]

marmoset_db-002# mysqladmin --defaults-file=/etc/mysql/debian.cnf status
Uptime: 91  Threads: 1  Questions: 2  Slow queries: 0  Opens: 33  Flush tables: 1  Open tables: 26  Queries per second avg: 0.021

• Check the restored database by using a point-in-time recovery to match the state of the test logical dump we did at the beginning.

• First, examine the binary logs and database state. Determine which binary logs to use and the start and end positions.

• Find the start position, i.e. the binary log position of the full backup we just restored.

marmoset_db-002# cat $latestinnobackupex/xtrabackup_binlog_info
binlog.000236   39752067

• Find and check the binary log end position that corresponds to the mysqldump.
• This procedure is made complicated because the dump took 24 minutes and each database in it is in some intermediate state.

• The end time of the innobackupex backup.

marmoset_db-002# grep end_time $latestinnobackupex/xtrabackup_info
end_time = 2015-09-10 05:35:19

• The start time of the mysqldump.

marmoset_db-002# oldmysqldump=`ls -d /var/backups/mysql/mysql.cs/mysqldump-*.sql | tail -1`

marmoset_db-002# ls -l $oldmysqldump
-r-------- 1 root root 52827191306 Sep 10 06:11 /var/backups/mysql/mysql.cs/mysqldump-mysql-172-1441878421--all-databases.sql

marmoset_db-002# date --date=@1441878421
Thu Sep 10 05:47:01 EDT 2015

• The end time of the mysqldump.

marmoset_db-002# tail -1 $oldmysqldump
-- Dump completed on 2015-09-10  6:11:07

• The update time of the binary logs.

marmoset_db-002# cd /var/backups/mysql/mysql.cs/

marmoset_db-002# ls -ldtr binlog*
-rw-rw---- 1 mysql adm 42593850 Sep  9 06:39 binlog.000235
-rw-rw---- 1 mysql adm 42473665 Sep 10 06:42 binlog.000236
-rw-rw---- 1 mysql adm      348 Sep 10 06:42 binlog.index
-rw-rw---- 1 mysql adm 18804316 Sep 10 13:40 binlog.000237

• So, all the transactions of interest are in binlog.000236.

• Examine the transactions between the end of the innobackupex and the start of the mysqldump.

marmoset_db-002# mysqlbinlog binlog.000236 --start-position=39752067 --stop-datetime='2015-09-10 05:47:01' | wc
     60     230    2588

• Examine the transactions between the end of the innobackupex and the end of the mysqldump.

marmoset_db-002# mysqlbinlog binlog.000236 --start-position=39752067 --stop-datetime='2015-09-10  6:11:07' | wc
     60     230    2588

• Good! There were no database updates during the mysqldump.

• Apply the transactions recorded in the binary logs between the start and end positions. Compare the before and after binlog state of the new database.

marmoset_db-002# echo 'show binary logs; show master status;' | mysql --defaults-file=/etc/mysql/debian.cnf
Log_name        File_size
binlog.000001   107
File    Position        Binlog_Do_DB    Binlog_Ignore_DB
binlog.000001   107

marmoset_db-002# mysqlbinlog binlog.000236 --start-position=39752067 --stop-datetime='2015-09-10 05:47:01' | mysql --defaults-file=/etc/mysql/debian.cnf

marmoset_db-002# echo 'show binary logs; show master status;' | mysql --defaults-file=/etc/mysql/debian.cnf
Log_name        File_size
binlog.000001   865
File    Position        Binlog_Do_DB    Binlog_Ignore_DB
binlog.000001   865

• Check that the last transaction was applied. Transactions that update date fields or autoincrement fields are especially useful.

mysqlbinlog binlog.000236 --start-position=39752067 --stop-datetime='2015-09-10  6:11:07'
...
use `app_saca`/*!*/;
...
SET INSERT_ID=2312/*!*/;
...
INSERT INTO apply (applyid, ...) VALUES("", ...)
...

marmoset_db-002# echo 'select max(applyid) from app_saca.apply' | mysql --defaults-file=/etc/mysql/debian.cnf
max(applyid)
2312

• Create a new mysqldump of the restored content to match the old mysqldump.

marmoset_db-002# newdump=/var/backups/mysql/`hostname | sed 's/\..*//'`-`date +%s`-mysqldump--all-databases.sql && time mysqldump --defaults-file=/etc/mysql/debian.cnf --add-drop-database --all-databases > $newdump
-- Warning: Skipping the data of table mysql.event. Specify the --events option explicitly.
real  15m26.000s
user  11m41.136s
sys   1m19.480s

• Check that the new mysqldump's size is close to the size of the files in the database and matches the size of the old mysqldump.

marmoset_db-002# du -hs /var/lib/mysql
61G   /var/lib/mysql

marmoset_db-002# ls -ltr $oldmysqldump $newdump
-r-------- 1 root root 52827191306 Sep 10 06:11 /var/backups/mysql/mysql.cs/mysqldump-mysql-172-1441878421--all-databases.sql
-rw-r--r-- 1 root root 52827191306 Sep 10 18:12 /var/backups/mysql/marmoset_db-002-1441922239-mysqldump--all-databases.sql

• Verify the innobackupex backup and restore process by comparing the old and new mysqldumps. Notice that there is essentially no difference.

marmoset_db-002# time diff --speed-large-files $oldmysqldump $newdump
3678,3679c3678,3679
<   CONSTRAINT `inv_dns_ibfk_2` FOREIGN KEY (`macAddressKey`) REFERENCES `inv_macAddress` (`id`) ON DELETE SET NULL ON UPDATE CASCADE,
<   CONSTRAINT `inv_dns_ibfk_1` FOREIGN KEY (`pKey`) REFERENCES `inventory` (`pKey`) ON DELETE CASCADE ON UPDATE CASCADE
---
>   CONSTRAINT `inv_dns_ibfk_1` FOREIGN KEY (`pKey`) REFERENCES `inventory` (`pKey`) ON DELETE CASCADE ON UPDATE CASCADE,
>   CONSTRAINT `inv_dns_ibfk_2` FOREIGN KEY (`macAddressKey`) REFERENCES `inv_macAddress` (`id`) ON DELETE SET NULL ON UPDATE CASCADE
56352c56352
< -- Dump completed on 2015-09-10  6:11:07
---
> -- Dump completed on 2015-09-10 18:12:45

real  29m1.590s
user  1m35.648s
sys   27m16.928s