MySQL, Linux

Percona XtraBackup ロールフォワード

Percona XtraBackup mysqldumpリストア時間比較 おまけでロールフォワード

寄稿しました。

 

どっちを使う?

  • XtraBackup
    レプリケーションが行われているシステム。
    WEBサービス。1秒も止められないようなもの。1秒で利益や損失が発生するサービス。
    XtraBackup, mysqldumpの併用しておく。
  • mysqldump
    業務アプリ。深夜や早朝、お客さんの業務が止まる時間のあるシステム。
    バイナリログは出力しておくにしても、最悪、当日の早朝や深夜のどちらかのチェックポイントにデータが戻っても良いもの、ブログとか。

 

ロールフォワードするのでバイナリはもちろん出しておきます。

# vi /etc/my.cnf

[mysqld]
#
# Remove leading # and set to the amount of RAM for the most important data
# cache in MySQL. Start at 70% of total RAM for dedicated server, else 10%.
# innodb_buffer_pool_size = 128M
#
# Remove leading # to turn on a very important data integrity option: logging
# changes to the binary log between backups.
# log_bin
#
# Remove leading # to set options mainly useful for reporting servers.
# The server defaults are faster for transactions and fast SELECTs.
# Adjust sizes as needed, experiment to find the optimal values.
# join_buffer_size = 128M
# sort_buffer_size = 2M
# read_rnd_buffer_size = 2M
datadir=/var/lib/mysql
socket=/var/lib/mysql/mysql.sock


binlog-do-db                    = test_db
binlog-ignore-db                = mysql
server-id                       = 1
log-bin                         = mysql-bin
relay-log                       = relay-log
#bind-address                    = 0.0.0.0
expire_logs_days                = 10
max_binlog_size                 = 128M
binlog_format                   = mixed

character-set-server = utf8
default_password_lifetime = 0

# Disabling symbolic-links is recommended to prevent assorted security risks
symbolic-links=0

log-error=/var/log/mysqld.log
pid-file=/var/run/mysqld/mysqld.pid

 

 

この記事の主題とは関係ないけども、

[mysqld]
log_bin = /var/log/mysql
log_slave_updates
expire_log_days = 20

レプリケーションするならスレーブでもバイナリを出しておくこと。

 

 

 

この記事の目的

MySQLの運用において、リストアが問題になります。XtraBackupとmysqldumpでリストア時間を計測しました。

 

 

環境

  • 1CPU 3.30GHz
  • メモリ8GB
  • バックアップ対象DB容量:3.5GB
  • CentOS7

 

 

先に結論

 

バックアップ リストア
mysqldump 48秒 3分23秒
xtrabackup 29秒 25秒

mysqldumpがSQLに対して、xtrabackupは解凍なので当たり前っちゃ当たり前ですが恐ろしい差がでますね。レプリケーションとかしているとリストアしている間の時間はシビアなので速いにこしたことはないのです。

 

MySQLで普通にmysqldumpする

 

普通にmysqldumpします。

# time mysqldump -u root -p --all-databases --single-transaction --master-data=2 --flush-logs > alldump20171129.sql

Enter password:

real    0m48.273s
user    0m17.952s
sys     0m2.024s

48秒で出来ました。

 

リストア

# time mysql -u root -p < alldump20171129.sql

Enter password:

real    3m23.844s
user    0m19.109s
sys     0m1.608s

3分23秒

 

Xtrabackupのインストール

 

# yum install gpg

 

# yum install https://www.percona.com/downloads/XtraBackup/Percona-XtraBackup-2.4.8/binary/redhat/7/x86_64/percona-xtrabackup-24-2.4.8-1.el7.x86_64.rpm

インストール:
  percona-xtrabackup-24.x86_64 0:2.4.8-1.el7

依存性関連をインストールしました:
  libev.x86_64 0:4.15-7.el7                              perl-Digest.noarch 0:1.17-245.el7                              perl-Digest-MD5.x86_64 0:2.52-3.el7

 

バックアップディレクトリの作成

# mkdir -p /backupdb/xtrabackup

 

バックアップ

# time /usr/bin/innobackupex --user root --password パスワード --no-lock /backupdb/xtrabackup

xtrabackup: Transaction log of lsn (61580269) to (61580278) was copied.
171129 18:59:34 completed OK!

real    0m29.636s
user    0m0.241s
sys     0m2.765s

29秒

 

 

 

いきなり!ロールフォワード

XtrraBackupがめちゃ速!という結論は出ていますし、会社記事作成用とはいえ、せっかくDBのバックアップとリストアする作業を設けたので、ロールフォワードの訓練もしておくことにします。

 

ロールフォワード(前進復帰)

例えば、夕方17時に障害が発生し、朝5時にバックアップした復旧ポイントにデータをリストアすることをロールバック。ロールバックした地点から夕方17時まで、更新処理を改めて行うことで復旧することをロールフォワードといいます。

 

 

ロールフォワードのシナリオ

  1. データ入力する作業中に誤ってデータの削除をしてしまっている事に後で気付いた!
  2. そこでロールバック&ロールフォワードによる復旧!

茶番にお付き合い下さい。

 

 

大切なデータの追加1

INSERT INTO `msg` (`msg_id`, `msg`) VALUES ('999991', '遅いじゃないか・・ミッターマイヤー。');

INSERT INTO `msg` (`msg_id`, `msg`) VALUES ('999992', '卿がくるまで、生きていようと思ったのに、間に・合わないじゃないか・・。');

 

大切なデータの追加2

DELETE FROM `msg` WHERE `msg`.`msg_id` = 2

 

大切なデータの追加3

INSERT INTO `msg` (`msg_id`, `msg`) VALUES ('999993', '疾風ウォルフの名に恥じるじゃないか。。');

 

 

…!!!

サンプルデータの追加したと思ったら消してしまっています。

DELETE FROM `msg` WHERE `msg`.`msg_id` = 2

大変ですね。

 

 

緊急メンテナンスモードにしましょう。

サンプルデータの追加2をなかったことにしつつ、追加1と追加3は反映させた状態で復旧させなくてはいけません。

 

メンテナンスモードにして復旧するというシナリオです。

 

 

リストア

MySQLを止めます。

# systemctl stop mysqld

 

旧ファイル退避。mysql.oldにバイナリログも退避される

# mv /var/lib/mysql /var/lib/mysql.old

# mkdir /var/lib/mysql

 

バックアップディレクトリの確認

# ls -laht /backupdb/xtrabackup

合計 0
drwxr-x--- 8 root root 267 11月 29 19:16 2017-11-29_19-15-51
drwxr-xr-x 3 root root  33 11月 29 19:15 .
drwxr-xr-x 3 root root  24 11月 29 19:07 ..

 

バイナリのポジションの把握

# cat /backupdb/xtrabackup/2017-11-29_19-15-51/xtrabackup_binlog_info

mysql-bin.000001        154

mysql-bin.000001のファイルの154から見ればいいことがわかります。

 

リストアします。

# time /usr/bin/innobackupex --copy-back /backupdb/xtrabackup/2017-11-29_19-15-51

171129 17:53:07 completed OK!

real    0m25.178s
user    0m0.022s
sys     0m2.795s

25秒。

速いですね!

 

感動している場合じゃありません、復旧しなければ!!

 

binlogの具合を見てみよう。

# mysqlbinlog /var/lib/mysql.old/mysql-bin.000001



/*!50530 SET @@SESSION.PSEUDO_SLAVE_MODE=1*/;
/*!50003 SET @OLD_COMPLETION_TYPE=@@COMPLETION_TYPE,COMPLETION_TYPE=0*/;
DELIMITER /*!*/;
# at 4
#171129 19:14:18 server id 1  end_log_pos 123 CRC32 0xea09430a  Start: binlog v 4, server v 5.7.20-log created 171129 19:14:18 at startup
ROLLBACK/*!*/;
BINLOG '
eogeWg8BAAAAdwAAAHsAAAAAAAQANS43LjIwLWxvZwAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA
AAAAAAAAAAAAAAAAAAB6iB5aEzgNAAgAEgAEBAQEEgAAXwAEGggAAAAICAgCAAAACgoKKioAEjQA
AQpDCeo=
'/*!*/;
# at 123
#171129 19:14:18 server id 1  end_log_pos 154 CRC32 0x657305ad  Previous-GTIDs
# [empty]
# at 154
#171129 19:24:50 server id 1  end_log_pos 219 CRC32 0x8a369a1e  Anonymous_GTID  last_committed=0        sequence_number=1       rbr_only=no
SET @@SESSION.GTID_NEXT= 'ANONYMOUS'/*!*/;
# at 219
#171129 19:24:50 server id 1  end_log_pos 310 CRC32 0x4e906b8a  Query   thread_id=63    exec_time=1     error_code=0
SET TIMESTAMP=1511951090/*!*/;
SET @@session.pseudo_thread_id=63/*!*/;
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 utf8mb4 *//*!*/;
SET @@session.character_set_client=45,@@session.collation_connection=224,@@session.collation_server=33/*!*/;
SET @@session.lc_time_names=0/*!*/;
SET @@session.collation_database=DEFAULT/*!*/;
BEGIN
/*!*/;
# at 310
#171129 19:24:50 server id 1  end_log_pos 629 CRC32 0xc383e379  Query   thread_id=63    exec_time=1     error_code=0
use `test_db`/*!*/;
SET TIMESTAMP=1511951090/*!*/;
INSERT INTO `msg` (`msg_id`, `msg`) VALUES ('999991', '遅いじゃないか・・ミッターマイヤー。')
/*!*/;
# at 629
#171129 19:24:50 server id 1  end_log_pos 660 CRC32 0xdf4fc2f8  Xid = 575
COMMIT/*!*/;
# at 660
#171129 19:25:57 server id 1  end_log_pos 725 CRC32 0x82b81ec8  Anonymous_GTID  last_committed=1        sequence_number=2       rbr_only=no
SET @@SESSION.GTID_NEXT= 'ANONYMOUS'/*!*/;
# at 725
#171129 19:25:57 server id 1  end_log_pos 816 CRC32 0x72fd2605  Query   thread_id=73    exec_time=0     error_code=0
SET TIMESTAMP=1511951157/*!*/;
BEGIN
/*!*/;
# at 816
#171129 19:25:57 server id 1  end_log_pos 1186 CRC32 0x08b147d5         Query   thread_id=73    exec_time=0     error_code=0
SET TIMESTAMP=1511951157/*!*/;
INSERT INTO `msg` (`msg_id`, `msg`) VALUES ('999992', '卿がくるまで、生きていようと思ったのに、間に・合わないじゃないか・・。')
/*!*/;
# at 1186
#171129 19:25:57 server id 1  end_log_pos 1217 CRC32 0xeed258fe         Xid = 661
COMMIT/*!*/;
# at 1217
#171129 19:26:25 server id 1  end_log_pos 1282 CRC32 0xf66f5e54         Anonymous_GTID  last_committed=2        sequence_number=3       rbr_only=no
SET @@SESSION.GTID_NEXT= 'ANONYMOUS'/*!*/;
# at 1282
#171129 19:26:25 server id 1  end_log_pos 1373 CRC32 0x70ac6c88         Query   thread_id=89    exec_time=0     error_code=0
SET TIMESTAMP=1511951185/*!*/;
BEGIN
/*!*/;
# at 1373
#171129 19:26:25 server id 1  end_log_pos 1501 CRC32 0xbc5036a8         Query   thread_id=89    exec_time=0     error_code=0
SET TIMESTAMP=1511951185/*!*/;
DELETE FROM `msg` WHERE `msg`.`msg_id` = 2
/*!*/;
# at 1501
#171129 19:26:25 server id 1  end_log_pos 1532 CRC32 0xd54ce32e         Xid = 978
COMMIT/*!*/;
# at 1532
#171129 19:27:09 server id 1  end_log_pos 1597 CRC32 0x143bba6e         Anonymous_GTID  last_committed=3        sequence_number=4       rbr_only=no
SET @@SESSION.GTID_NEXT= 'ANONYMOUS'/*!*/;
# at 1597
#171129 19:27:09 server id 1  end_log_pos 1688 CRC32 0xa554ccdb         Query   thread_id=99    exec_time=0     error_code=0
SET TIMESTAMP=1511951229/*!*/;
BEGIN
/*!*/;
# at 1688
#171129 19:27:09 server id 1  end_log_pos 2010 CRC32 0xcff8cf32         Query   thread_id=99    exec_time=0     error_code=0
SET TIMESTAMP=1511951229/*!*/;
INSERT INTO `msg` (`msg_id`, `msg`) VALUES ('999993', '疾風ウォルフの名に恥じるじゃないか。。')
/*!*/;
# at 2010
#171129 19:27:09 server id 1  end_log_pos 2041 CRC32 0xeca4c678         Xid = 1078
COMMIT/*!*/;
# at 2041
#171129 19:27:37 server id 1  end_log_pos 2064 CRC32 0xce9d6960         Stop
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*/;

わけがわからない。文字が多すぎですよね。事前知識がないと意味わからんです。

 

書いてある内容の解説

ヒント1.  

# at 154
#171129 19:24:50 server id 1  end_log_pos 219 CRC32 0x8a369a1e  Anonymous_GTID  last_committed=0        sequence_number=1       rbr_only=no
SET @@SESSION.GTID_NEXT= 'ANONYMOUS'/*!*/;

バイナリポジションの把握から154から見ていけばいいことがわかっています。

 

ヒント2. 

#171129 19:26:25

上記は2017年11月29日19時26分25秒をあらわします。

 

ヒント3. 

# at 310
#171129 19:24:50 server id 1  end_log_pos 629 CRC32 0xc383e379  Query   thread_id=63    exec_time=1     error_code=0
use `test_db`/*!*/;
SET TIMESTAMP=1511951090/*!*/;
INSERT INTO `msg` (`msg_id`, `msg`) VALUES ('999991', '遅いじゃないか・・ミッターマイヤー。')
/*!*/;
# at 629

# at 数字はファイルの場所を指定していると考えてください。ポジション310と629の間にINSERTのクエリがあることがわかります。

 

また、事故のクエリはDELETEです、DELETEで検索すれば良いかもしれません!

 

 

DELETEで前後5行を検索します。

# mysqlbinlog /var/lib/mysql.old/mysql-bin.000001 | grep -A 5 -B 5 "DELETE"

BEGIN
/*!*/;
# at 1373
#171129 19:26:25 server id 1  end_log_pos 1501 CRC32 0xbc5036a8         Query   thread_id=89    exec_time=0     error_code=0
SET TIMESTAMP=1511951185/*!*/;
DELETE FROM `msg` WHERE `msg`.`msg_id` = 2
/*!*/;
# at 1501
#171129 19:26:25 server id 1  end_log_pos 1532 CRC32 0xd54ce32e         Xid = 978
COMMIT/*!*/;
# at 1532

あっいいですね。

ポジション1373と1501の間に問題のクエリがあることがわかります。

 

もしくは、事故った時間がわかれば話は早いです。

# mysqlbinlog --start-datetime="2017-11-29 17:30:00" /var/lib/mysql.old/mysql-bin.000001

時間を指定することでそこの時点からファイルを参照することが出来ます。

 

 

 

復旧用クエリ抽出

# mysqlbinlog --database="test_db" --start-position=154 --stop-position=1373 /var/lib/mysql.old/mysql-bin.000001 > /root/recovery_1.sql

# mysqlbinlog --database="test_db" --start-position=1501 --stop-position=2041 /var/lib/mysql.old/mysql-bin.000001 > /root/recovery_2.sql

事故ったクエリを迂回するように指定することで復旧用クエリを抽出することが出来ます。

 

 

MySQLの起動

# chown -R mysql:mysql /var/lib/mysql

# systemctl restart mysqld

 

復旧用クエリによるロールフォワード

# mysql -u root -p < /root/recovery_1.sql

# mysql -u root -p < /root/recovery_2.sql

 

データの確認

mysql> SELECT * FROM `msg` WHERE msg_id = 2;
+--------+----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+------+----------+---------+---------------------+
| msg_id | msg                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                          | img  | girl_flg | del_flg | regdate             |
+--------+----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+------+----------+---------+---------------------+
|      2 | テスト                                                                                                                                                                   |      |        1 |       0 | 2013-06-29 21:03:59 |
+--------+----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+------+----------+---------+---------------------+
1 row in set (0.00 sec)



mysql> SELECT * FROM `msg` WHERE msg_id = 999991;
+--------+--------------------------------------------------------
| msg_id | msg                                                    
+--------+--------------------------------------------------------
| 999991 | 遅いじゃないか・・ミッターマイヤー。                   
+--------+--------------------------------------------------------
1 row in set (0.00 sec)

mysql> SELECT * FROM `msg` WHERE msg_id = 999992;
+--------+---------+-----------------------------------------------------------------------------------------------------------+
| msg_id | user_cd | msg                                                                                                       |
+--------+---------+-----------------------------------------------------------------------------------------------------------+
| 999992 |  999992 | 卿がくるまで、生きていようと思ったのに、間に・合わないじゃないか・・。                                    |
+--------+---------+-----------------------------------------------------------------------------------------------------------+
1 row in set (0.00 sec)

mysql> SELECT * FROM `msg` WHERE msg_id = 999993;
+--------+-----------------------------------------------------------+
| msg_id | msg                                                       |
+--------+-----------------------------------------------------------+
| 999993 | 疾風ウォルフの名に恥じるじゃないか。。                    |
+--------+-----------------------------------------------------------+
1 row in set (0.00 sec)

 

大丈夫そうですね。

 

無事復旧できましたね。

お疲れ様です。

 

 

 

 

Amazonおすすめ

iPad 9世代 2021年最新作

iPad 9世代出たから買い替え。安いぞ!🐱 初めてならiPad。Kindleを外で見るならiPad mini。ほとんどの人には通常のiPadをおすすめします><

コメントを残す

メールアドレスが公開されることはありません。 * が付いている欄は必須項目です

日本語が含まれない投稿は無視されますのでご注意ください。(スパム対策)