概要

MySQLを運用するうえで、データ復旧やポイントインタイムリカバリPITRには一貫性のあるバックアップとバイナリログ(以降binlog)が理解できていれば十分なので、Redoログを意識することは殆どありません。
これはMySQLが現場で利用される際は、冗長化や負荷分散のために、レプリケーション構成とともに利用されることが大きな理由です。特にMySQLのレプリケーションは論理レプリケーションのみがサポートされており、デフォルトでは非同期レプリケーションな上に、ほとんどの場合レプリケーションのためのbinlogが、トランザクション処理中のロギングのボトルネックになるため、Redoログ関連のチューニングする必要も滅多にないためです。
しかし、MySQLはNo-Forceなトランザクション処理を実現するために、RDBMSの教科書通りのWrite Ahead Logging(WAL)方式に従ってRedoログを出力しています。システム障害に対するクラッシュリカバリに必須なRedoログにはどんな内容が書かれているのでしょうか？

No-Force: トランザクションのコミット時に更新結果をディスクに永続化しなくて良い方式。ディスクまで永続化していなくても、コミット済みのトランザクションによる更新は障害後に復旧できるようにRedoログが必要になる。

この記事ではMySQLがどのようなRedoログを出力しているのか読み解き、Redoログから更新クエリを処理する際に、物理的にどういったデータを更新しているのかを調べた様子を紹介します。

MySQLにおけるRedoログはInnoDBのRedoログ

MySQLはテーブルごとにストレージエンジンを選択することができ、ストレージエンジンがメモリやディスク上でのデータ管理の実装を担っています。そのため、MySQLのRedoログと言っても、統一したredoログはないんじゃないの？と思われた方もいるかも知れません。確かにMySQLではテーブル単位でストレージエンジンを選択することができ、ストレージエンジンごとにトランザクションをサポートしたり、していなかったりします。しかし、現実にMySQLを利用する方はデフォルトのInnoDBを選択していることでしょう。更に言うと、MySQLがサポートしているInnoDBとNDBストレージエンジン以外のストレージエンジンはトランザクショナルではありません。

注釈: NDBストレージエンジンはMySQL (NDB) Clusterというクラスタ構成で利用するストレージエンジンのため、特殊な構成とします。(ちなみにMySQL ClusterはGroup replicationを使ったInnoDB Clusterとは別物です)

そして、MySQL 8.0ではテーブル定義などのメタデータである辞書データがストレージエンジンごとのファイルではなく、InnoDBのシステムテーブルとして統一して管理されるようになりました。具体的には、Data dictionaryのデータはData dictionary tablesという特殊なテーブルで管理され、ファイルシステム上ではmysql.ibdファイルに保存されます。

https://dev.mysql.com/doc/refman/8.0/en/data-dictionary-file-removal.html
https://dev.mysql.com/doc/refman/8.0/en/data-dictionary-transactional-storage.html

これにより、デフォルトのInnoDBストレージエンジンのテーブルのみを利用している場合は、MySQLのredoログはInnoDB Redoログであると言えます。

Redoログは8.0.30以降はデフォルトの初期状態では#innodb_redoディレクトリ以下にinnodb_redo_log_capacityの設定値を32で割ったファイルサイズで以下のように32個作成されるものです。

図1, Redoログファイル

mysqlredoコマンド

Data DictionaryがInnoDBで管理されるようになったことで、MySQLに対するメタデータの更新も含めた物理的な更新がInnoDBのRedoログに書かれることがわかりました。

早速InnoDBのRedoログを読んでみましょう。と言いたいところですが、PostgreSQLにおけるpg_waldump, OracleにおけるLogMinerやlogdumpのような仕組みはなく、MySQLには公式でRedoログをダンプするツールがありません。

ないものは仕方ないので作りました。mysqlredoコマンドです。

このコマンドはInnoDBのRedoログをダンプ出力するために筆者が開発しているクライアントツールです。binlogをダンプ出力するmysqlbinlogという公式クライアントツールの様に、redoログをダンプするのでmysqlredoと名付けました。起動時のクラッシュリカバリの実装を再利用して、クライアントツールとして再実装したものです。検証・学習用のツールなので、不完全かつMySQL 8.0.32でしか動作確認していませんが、ソースコードから他のクライアントツール同様の手順でビルドして利用することができます。詳しくはREADMEを参照してください。

このツールを利用して、開始・終了地点となるLSN(Redoログに割り当てられるLog Sequence Number)とredoログ・ファイルを指定することでログレコードの中身をダンプします。

$ mysqlredo --start-lsn=NNN --stop-lsn=MMM --file-path=/path/to/#ib_redoN

ダンプ出力の結果とそこから分かることを後述しますが、その前に、次の章でRedoログのフォーマットと基本的な情報を説明します。

Redoログレコードのフォーマット

Redoログの構造は公式ドキュメント等で説明されていませんが、一定のフォーマットに従って出力されています。ここではほとんどのログレコードが共通して先頭に持っている3つのデータをRedoログヘッダーとします。 Redoログヘッダーは、ログタイプ、スペースID, ページ番号で構成されます。ログタイプはそのログレコードに格納されているデータ種別を示す値が格納されています。スペースIDはテーブルスペース(テーブル)、ページ番号はテーブル中の更新対象のページを示す値が格納されています。ヘッダーの情報からも分かるように、RedoログはスペースID, ページ番号をKeyにして更新情報を示しています。ヘッダーに続くペイロードにはオフセットなどのメタ情報のほか、物理的な更新データ(bit列)が格納されています。

図2, Redoログレコードのフォーマットイメージ

mysqlredoコマンドはこのヘッダー情報は必ず表示し、ペイロード部分は実データがなくても表示できる部分のみを出力しています。

ログタイプ

ログタイプはmtr_log_tというenumで定義されています。

図3, Redoログのログタイプ一覧

名前からある程度の操作が想像できますが、主要なものは以下です。

MLOG_FILE_xxx: ファイル操作を示すRedoログレコード
MLOG_REC_xxx: レコードに対する操作
MLOG_UNDO_xxx: Undoレコードに対する操作
MLOG_{N}BYTE: N byte分のデータ書き込みを示す(N=1,2,4,8)

ログレコードの大半はMLOG_{N}BYTEなので、解析には骨が折れますが、これについては後述します。

space_id

スペースIDはテーブルに一意に割り当てられるIDです。ハードコードされているものも含めある程度割り当てられる範囲が決まっています。これはコンフィグにもよりますが、デフォルト設定だと以下です。

0: システムテーブル(ibdata1)
1: sys/sysconfigテーブル
2以降: ユーザが作成するテーブル
429497294: データディクショナリ
429497298, 429497299: Undoテーブルスペース(デフォルト2つ)

また、MySQLからはinformation_schema.innodb_tablespacesテーブルで確認することが可能です。

図4, information_schema.innodb_tablespacesテーブルで確認するテーブルスペース情報の例

UPDATE文によるredoログを見てみる

基本的な情報を抑えたので、実際の更新クエリによって生成されるRedoログを見ていきましょう。

初期データ

初期データは以下のように用意しました。

mysql> create database d1;
mysql> use d1
mysql> create table t1(id int not null primary key, c1 int not null);
mysql> insert into ...;
mysql> select * from t1; 
+----+----+
|id|c1|
+----+----+
|1|1|
|2|2|
|3|3|
+----+----+
3 rows in set (0.00 sec)

更新クエリとLSNの確認

開始点と終了地点となるLSNを確認しつつ、次のようにupdate文で更新します。

mysql> show global status like '%flushed_to_disk_lsn%';
+-------------------------------------+----------+
| Variable_name                       | Value    |
+-------------------------------------+----------+
| Innodb_redo_log_flushed_to_disk_lsn | 19529906 |
+-------------------------------------+----------+
1 rows in set (0.00 sec)
 
mysql> update t1 set c1=20 where id = 2;
Query OK, 1 row affected (0.01 sec)
Rows matched: 1 Changed: 1 Warnings: 0
 
mysql> show global status like '%flushed_to_disk_lsn%';
+-------------------------------------+----------+
| Variable_name                       | Value    |
+-------------------------------------+----------+
| Innodb_redo_log_flushed_to_disk_lsn | 19530158 |
+-------------------------------------+----------+
1 rows in set (0.00 sec)

ダンプ出力の結果

先ほど確認したLSNを指定しつつ、redoログをダンプします。私の実験環境では以下のように実行しました。

$ mysqlredo –header –b 19529906 –e 19530158 –v –f /mysql_remote/redo/#innodb_redo/#ib_redo18

出力結果の全体はこちらにあります。

出力結果を元に処理内容を分析する

UPDATE文により生成されたログ範囲をまとめると以下のような出力が得られました。

図5, UPDATEにより出力されたRedoログのダンプ結果

出力の見方を説明します。

まず、- recv_multi_rec()または-recv_single_rec()から始まっている行はmysqlredoが補足しているメタデータです。 Redoログはミニトランザクションという、トランザクション中の更新を一括で記録できる単位でログレコードをまとめて出力しています。 MySQLでは、ミニトランザクション中で1行のログレコードだけを書くか、複数行を書くかで処理が分岐しているので、mysqlredoでもこの情報を出力するようにしています。- recv_single_rec()で始まっているミニトランザクションは1行のログレコードのみが含まれているもの、-recv_multi_rec()は複数行を含んでいるものです。図5に示したダンプ結果では4つのミニトランザクションが出力されていることがわかります。各ログレコードをダンプ出力した結果はスペース2つのインデントを付けて出力されています。ログヘッダのログタイプ、スペースID、ページ番号に続いて、ペイロード部分が出力されています。行末につけた(-- 数値)の文字列はこの説明用に後から追加したものです。この数値は後で説明する実行時のコールスタックと対応しています。

次に各ミニトランザクションで出力されているログレコードを見てみます。ほとんどのログレコードがMLOG_(N)BYTESのログタイプで、特定のページのoffsetに何かしらの値を書いているということしかわかりませんが、よく見ると3つ目のミニトランザクションはスペースIDが2、つまりinnodb_tablespacesテーブルで確認した、t1テーブルへの書き込みで、それ以外はスペースIDが‭4294967279‬のUndoテーブルスペースへの書き込みになっていることがわかります(図4も参照)。

また、最初の3つのミニトランザクションの最初のログレコードのログタイプは以下のようになっています。

1つ目: MLOG_UNDO_HDR_CREATE
2つ目: MLOG_UNDO_INSERT
3つ目: MLOG_REC_UPDATE_IN_PLACE

これとスペースIDを合わせると、なんとなくUPDATEによる更新が以下の流れで行われていることが想像できるかと思います。

UNDO領域のヘッダーの作成
UNDO領域へのレコードのINSERT
t1テーブルへのIN_PLACE更新

InnoDBが追記型ではなくIN_PLACE型でレコードを更新していることを知っていると大まかな更新の流れとしては想定通りの結果になりました。しかし、この出力だけでは具体的に何を更新しているのかを把握することはできません。

ここからはmysqlredoの出力を手がかりにgdbを利用して各Redoログレコードの出力タイミングでどんな処理をしているのかを探っていきます。

直接ログを出力するタイミングで止めてもよいですが、高速化のためか、実装上は複数の出力方法があるため、確実に1レコード書ききったタイミングを掴みたいと思います。少し周辺のコードを読んでみると、mtr_t構造体のadded_rec()メソッドを呼ぶことで、内部的に1行のRedoログレコードを出力したことをカウントしている処理が見つかります。このメソッドにブレークポイントを貼って、スタックトレースを取り、出力されたログレコードとマッピングしてみます。

その結果が以下です。関数の呼び出しの関係を、関数が呼び出されるごとに1スペースのインデントをつけて表現しています。

AUTOCOMMIT=ON(default設定)で単文のUPDATE文を実行したので、dispatch_sql_command()から処理が始まり、Sql_cmd_dml::execute()、続くSql_cmd_update::execute_inner()でUPDATE処理が走り、その後trans_commit_stmt()から始まるコミット処理が続いていることがわかります。

関数名からもおおよその察しが着きますが、このスタックトレースの結果を頼りに、さらにログレコードを出力している処理の周辺を読むことで、ログレコード出力時の内部処理を理解していきます。

UPDATEによる処理内容まとめ

スタックトレースを元にRedoログを出力したときの処理内容をまとめた表が以下です。

id	関数	内容
1	trx_undo_header_create()	確保したundoの先頭ページを記録(rseg->insert())
2	trx_undo_header_add_space_for_xid()	undo headerにページの空き領域を記録
3	trx_undo_header_add_space_for_xid()	undo headerにページの空き領域を記録 (mlog_write_ulint(page_hdr + TRX_UNDO_PAGE_FREE, new_free, MLOG_2BYTES, mtr);)
4	trx_undo_header_add_space_for_xid()	undo headerにページの空き領域を記録 (mlog_write_ulint(log_hdr + TRX_UNDO_LOG_START, new_free, MLOG_2BYTES, mtr);)
5	trx_undo_page_report_modify()	更新対象のレコードをundoに移す(btr_cur_upd_lock_and_undo)
6	mlog_open_and_write_index()	更新対象のレコードをインプレースに更新
7	trx_undo_set_state_at_finish()	ヘッダーにトランザクションのステート(TRX_UNDO_CACHED)を書く
8 ~ 15	trx_purge_add_update_undo_to_history()	undoのhistory listにundoのヘッダをノードと見立ててキューに追加する。
16	trx_purge_add_update_undo_to_history()	undoのhistory listのbaseノードで全体の長さを更新
17	trx_purge_add_update_undo_to_history()	ロールバック・セグメントの最大トランザクション番号を更新
18	trx_purge_add_update_undo_to_history()	undo log headerにトランザクション番号を記述
19	trx_purge_add_update_undo_to_history()	undo log headerに削除マークを記述。

各ミニトランザクション中の最初のログレコードのログタイプ名から推測できたとおりではありますが、より具体的に処理の内容を把握することができました。まとめると図6のような処理を行っています。

図6, UPDATEにより出力されたRedoログのダンプ結果と概要

最初のミニトランザクションではUndo領域を確保し、そのヘッダーページに空き領域のサイズを保存し、2つ目のミニトランザクションでは、更新対象のレコードをundo領域に移し、 3つ目で実際に更新対象のレコードをインプレースで更新しています(このログレコードのペイロードに更新後のレコードの物理的なデータ(bit列)が続いています)。最後のミニトランザクションでUndo領域のヘッダーの更新と、purge処理のためのhistory listキューに追加しています。

このようにして、分析したいクエリのRedoログの内容とそれに紐づいた処理のコールスタックを把握することができました。さらに、これらの処理を行っている構造体や初期化処理を読むことで、内部の各コンポーネントやファイル上のメタデータの保存位置まで把握することができます。

Q: Commitを表すRedoログレコードがない?

ところで、AUTO COMMITによってcommit処理も完了したはずの処理の中で、Commit完了を示すRedoログが出てこなかったことに気付いた方もいるかも知れません。

mysqlredoによるダンプ結果にそれらしいログタイプはありませんし、mtr_id_tのenumを見返してみてもMLOG_COMMITなどのそれらしいものが見当たりません。一体どうやってこのトランザクションがコミットしたことを示しているのでしょうか？

ここでログレコードと紐づけたコールスタックを改めて眺めてみると、7番目のログはtrx_commit_low()の中、かつ、trx_undo_set_state_at_finish()という関数で呼ばれていることがわかります。関数名からもコミットを示していそうですし、この関数のコメントには"Sets the state of the undo log segment at a transaction finish."とあり、やはりトランザクションの終了を表していそうです。

特に7番目のredoログレコードはペイロード部分から、page_noが285のページのoffset 56に2という値を書いていることがわかります。 trx_undo_set_state_at_finish()を少し読むと、この56というオフセットはTRX_UNDO_SEG_HDRの定数であり、2という値はTRX_UNDO_CACHEDという値であることがわかります。

これらがコミットを表すかどうかは、この値を読み出してトランザクションを復元する時、つまり、クラッシュリカバリの処理中の実装を読む必要がありますが、筆者はたまたまmysqlredoを作る過程でリカバリ処理に目を通していたため、ある程度目星をつけて確認することができました。

結論を書くと、今回2(TRX_UNDO_SEG_HDR)に設定されていたトランザクションを表すステートは7つあり、trx_resurrect_insert()またはtrx_resurrect_update()の中で、undoのヘッダーにあるステートが、TRX_UNDO_ACTIVE, TRX_UNDO_PREPARED, TRX_UNDO__PREPARED_80028, TRX_UNDO_PREPARED_IN_TCの4つ以外であれば、TRX_STATE_COMMITTED_IN_MEMORYに設定し、この後に実行されるtrx_recovery_rollbackスレッドによるtrx_rollback_or_clean_recovered()関数でステートがTRX_STATE_COMMITTED_IN_MEMORYのものはコミット済みとして扱っています。上記4つの場合もbinlogの状態と合わせてコミットとするケースもありますが、ここでは省略し、別の記事にしたいと思います。

これで、今回実験したUPDATE文が7つ目のRedoログレコードで、undo領域中にstateを設定する書き込みをしたことが、このトランザクションのコミットを示していることがわかりました。

まとめ

mysqlredoコマンドを使ってクエリ実行時に出力されるredoログを確認し、その内容を足がかりにMySQLがどのデータ構造にどういった値を書いているのかを調べる方法を紹介しました。同様の方法で、セカンダリインデックスやオフロードページされるデータに対する更新がどの様にロギングされるのかや、DDL, DCLがどの様に記録されるのかを確認することもできます。

今回はRedoログを起点にMySQLの内部に迫ってみました。サービスの開発でもよく使うMySQLの中身に興味を持ってくれる人が増えたら幸いです。

また、この内容はMySQLアンカンファレンスでも発表した内容になっています。今回紹介した内容はかなりマニアックでしたが、MySQLに関する雑談や相談をしたい人と気軽につながるために開催しているイベントです。完全オンラインで毎月開催しているので、是非覗いてみてください。

Redoログから読み解くMySQLの物理的な更新処理

概要