【MySQL】ロールバックとロールフォワードによるデータリカバリ

どうも、開発2部サーバー担当の山本です。

先日サーバーの勉強会で発表したMySQLの「ロールバック」と「ロールフォワード」を使ったデータリカバリについて紹介します。
知識としてロールバックやロールフォワードを知っている方は多いと思いますが、実際に使ったことがある人って意外と少ないんじゃないでしょうか？

今回はバックアップとバイナリログを使って特定のタイミングにデータを復旧させる、いわゆる「ポイント・イン・タイム・リカバリ (PITR)」を実演形式で紹介しています。

障害対応で必要になる手順なので、使う場面はない方が平和でよいのですが、いざというときに思考停止に陥らないよう予め理解を深め実践することをおすすめします。

今回の実演は以下の構成で行っています。

MySQL 5.5.47
Master1台構成
行ベースのバイナリログ出力設定

ロールバックについて
ロールフォワードについて
想定されるケース
データリカバリの流れ
実践

ロールバックについて

今回使う「ロールバック」はトランザクションのロールバックではなく、チェックポイント時点のデータ（バックアップ）に戻すことを指します。
リストアと呼んだ方が一般的かもしれませんね。

ロールフォワードについて

「ロールフォワード」はチェックポイント時点のデータにバイナリログから抽出したクエリを反映し、データベースを特定タイミングの状態に戻すことです。
ロールフォワードを行うには2つの条件があります。

■チェックポイント時点のデータに戻せること
cronでmysqldumpを動かすなど、定期的にフルバックアップを取得します。

■チェックポイント以降のバイナリログが残っていること
レプリケーション構成であればバイナリログは必ず出力されていますが、バイナリログの保持期限（expire_logs_days）には注意しましょう。
レプリケーション構成でない場合はバイナリログを出力しましょう。

想定されるケース

ロールバックとロールフォワードは長時間のサービス停止と複雑な作業が必要となります。
作業面でのコストや運営面でのリスクが大きいため、スマホゲームの運営ではお詫び（補填、詫び石）により対応するのが一般的ですが、「ゲームバランスや価値観の崩壊」など、継続的に運営する上で致命的な問題に繋がる場合にはその限りではありません。

実際にありそうなシチュエーションはこんな感じでしょうか。

【ケース①】
ガチャから排出されないはずのキャラクターが排出されてしまった！
ガチャが始まった12:00のタイミングのデータに戻して！！
→特定時間へのロールバック

【ケース②】
オペレーションミスでユーザーデータが消えてしまった！
ユーザーデータを消す直前にデータを戻して！！
→特定タイミングへのロールバック

どちらも胃がキリキリします・・・

データリカバリの流れ

①サービス停止
メンテナンスなどでデータの更新を止めます。

↓

②バックアップ取得
オペレーションミスのリスク回避として作業前にフルバックアップを取得します。

↓

③ロールフォワード用のクエリ抽出
バイナリログよりチェックポイントから特定タイミングまでのクエリを抽出する。

↓

④ロールバック
チェックポイント時点のフルバックアップを投入します。

↓

⑤ロールフォワード
③のクエリを実行して、データをチェックポイントから特定タイミングまで進めます。

↓

⑥サービス再開
データが正常にリカバリできたことを確認してサービスを再開します。

データリカバリの実践

下準備

実演用にroll_fowardというDBに2つのテーブル（foo,bar）を作りました。
レプリケーションは構築していませんが、行ベースでバイナリログを出力するようにしました。

fooテーブルには6件のデータが存在する。

20160222_150500

barテーブルには3件のデータが存在する。

20160222_150515

チェックポイント時点のバックアップ取得

チェックポイント時点のバックアップ取得のため、mysqldumpによりフルバックアップを行います。

# mysqldump roll_forward --master-data=2 --single-transaction --flush-logs > /tmp/backup.sql

各オプションの説明は以下の通りです。

・master-data
バックアップ取得時点のバイナリログの位置（ファイル名、ログポジション）がダンプファイル中に出力されます。
master-data=1とすると、「CHANGE MASTER TO …」がそのまま出力されます。
master-data=2とすると、「CHANGE MASTER TO …」がコメントアウトされて出力されます。

・single-transaction
一貫性を保持したバックアップが可能です。
トランザクション開始時のスナップショットを取得し、他のトランザクションの影響を受けません。

・flush-logs
ダンプ出力のタイミングでバイナリログをflushします。
ダンプ出力以降のバイナリログが別ファイルに切り替わるためリカバリ作業が捗ります。

mysqldumpの使い方はこちらで詳しく説明されています。

http://www.risewill.co.jp/blog/archives/195

データの変更

以下の流れでクエリを実行してデータを更新しました。

①insert into foo values (7, ‘test7’);
②insert into bar values (4, ‘test4’);
③drop table bar;
④insert into foo values (8, ‘test8’);

後程③のテーブルの削除以降をなかったことにする想定です。
データを変更した後はこんな感じになっています。

fooテーブルには8件のデータが存在する。

20160222_152249

barテーブルが消えている。

20160222_152207

作業前のバックアップ取得

作業前にmysqldumpでフルバックアップを行います。
オプションは先ほどと同じですが、ファイル名は重複しないようにします。
（ファイル名が重複すると上書きでチェックポイントがなくなってしまいます！！）

# mysqldump roll_forward --master-data=2 --single-transaction --flush-logs > /tmp/before_recovery.sql

ロールフォワード用のクエリ抽出

まずはチェックポイント時点のバックアップの先頭付近にバイナリログの位置が出力されているので確認します。
赤丸で囲んでいる「MASTER_LOG_FILE=’binary-log.000016′, MASTER_LOG_POS=107」が
バイナリログの位置です。

20160222_153334

チェックポイント以降に出力されたバイナリログを確認します。
「binary-log.000016」が対象となるため、binary-log.000016、binary-log.000017の2ファイルが対象となりますが、今回は作業前のバックアップでflushしているのでbinary-log.000016のみとなります。

20160222_153910

mysqlbinlogを使ってbinary-log.000016からDROP TABLEのクエリを抽出します。
（複数のバイナリログを一度に指定することもできます。）
mysqlbinlogはmysqlをインストールするとデフォルトでついてくるユーティリティです。
mysqlbinlogとgrepで前後5行ほど表示すると、ログポジション:622でDROP TABLEしていました。

# mysqlbinlog --verbose --database="roll_forward" --start-position=107 /var/lib/mysql/binary-log.000016 | grep DROP -B 5 -A 5

# at 509
#160222  6:19:39 server id 1  end_log_pos 622   Query   thread_id=12    exec_time=0     error_code=0
use `roll_forward`/*!*/;
SET TIMESTAMP=1456089579/*!*/;
DROP TABLE `bar` /* generated by server */
/*!*/;
# at 622
#160222  6:19:49 server id 1  end_log_pos 698   Query   thread_id=12    exec_time=0     error_code=0
SET TIMESTAMP=1456089589/*!*/;
BEGIN

上記コマンドの各オプションの説明は以下の通りです。

・verbose
行ベースでバイナリログを出力している場合にクエリの内容が分からないのでコメントにクエリを出力します。

・database
出力対象とするデータベーススキーマを指定します。

・start-position
出力開始するログポジションを指定します。

mysqlbinlogの使い方はこちらで詳しく説明されています。

https://dev.mysql.com/doc/refman/5.6/ja/mysqlbinlog.html

次にクエリの抽出ですが、DROP TABLEのひとつ前のログポジションは509となっているので、そこまでを抽出します。

# mysqlbinlog --database="roll_forward" --start-position=107 --stop-position=509 /var/lib/mysql/binary-log.000016 > /tmp/recovery.sql

ロールバック

チェックポイント時点のフルバックアップからデータに戻します。

# mysql roll_forward < /tmp/backup.sql

チェックポイント時点のデータに復元しました。

20160222_164446

20160222_164510

ロールフォワード

DROP TABLEまでのロールフォワードのため、先ほどmysqlbinlogで抽出したクエリを実行します。

# mysql roll_forward < /tmp/recovery.sql

先ほど実行した以下の4つのクエリのうち①②まで反映されていることを確認できます。

反映　　→　①insert into foo values (7, ‘test7’);
反映　　→　②insert into bar values (4, ‘test4’);
未反映　→　③drop table bar;
未反映　→　④insert into foo values (8, ‘test8’);

20160222_164722

20160222_164745

今回は分かりやすいようにシンプルな構成で実演したので、簡単に思われるかもしれません。
実際にはトランザクション量やデータ量が膨大になるため作業には長時間を要します。
また、DBのレプリケーション構成やバージョン、時間指定のロールバック、クエリ指定のロールバックなど環境やシチュエーションによって手順が変わります。
手順を誤った場合にはデータロストや不整合が発生します。

ケースバイケースで柔軟に対応できるよう、手順の意味をしっかりと理解して、いざというときに備えましょう。

ではでは。