この記事はMySQLのカレンダー | Advent Calendar 2023 - Qiitaの19日目の記事です。

MySQLのredoログには何が書かれているのだろうか？
そんな疑問を解決するために私はアマゾンの奥地へと旅立つことにしました。

MySQLはSQLをパースし、実行計画を立てたあと、実際にストレージ(メモリ含む)でデータを処理する部分はプラガブルなストレージエンジンに実装を移譲する設計になっています。
しかし、処理をストレージエンジンがトランザクションをサポートしないことも選択できるため、クラッシュリカバリのための機構を実装していない可能性もあります。
そのため、レプリケーションにも利用されるバイナリログがWrite Ahead Loggingされていて、クラッシュリカバリやPITRにもバイナリログが主に使われています。(と、筆者は理解しています。). なので、運用上はバイナリログを理解していれば、MySQLのリカバリ関連の作業が全てできると言って問題ありません。

一方で、MySQL8.0からはメタデータがData Dictionary(InnoDBを低レイヤ部分を流用して実装されている)に一元管理されるようになったことで、ストレージエンジンにInnoDBしか使っていないのであれば、InnoDBのRedoログだけでクラッシュリカバリが可能になっています。しかし、実は変化の激しいRedoログの詳細について解説したブログや書籍はなく、Redoログの中身がどうなっているのか知るにはソースコードを読みつつ探るしかないようです。

「うーん気になる。。。」

ということで、Redoログの中身を探っている探索記を残します。

Redoログの書き込み側から探る

Redoログに対する書き込みはミニトランザクション(mtr)という単位で行われます。
ミニトランザクションは物理論理ロギング(physiological logging)という手法、つまりページに対して物理的、ページ内で論理的な情報が書かれます。
「物理論理」というのは書き込むデータと書き込み先のオフセットをロギングする、物理ロギングとデータを再生成するための論理的なデータを書く論理ロギングの良いとこ取りをした手法で、"物理オブジェクト(ぺーじまたはセッション)の変更を表すのに論理ロギングを使用することから由来している"*1そうです。

このミニトランザクションはmtr_tクラス *2が担っており、ページに対する更新があるごとに、mtr_t::start()から始まり、mtr_t::commit()で確定し、mtr_t::m_logに保持したログを書き込む処理で終わります。

つまり、1つのクエリで複数生成されるmtr_tインスタンスが生成された後、コード上の様々な場所から行われるこのクラスに対する更新を全て追わないと、どんなRedoログが書かれるかわからないことになります。そもそもRedoログにも、InnoDBの内部実装にも詳しくない状態で、これらを追っていくのは筋が悪いと感じたので、書き込み側から探るのは諦めました。

それよりもRedoログを読み出して処理するとき、すなわちクラッシュリカバリの処理を観たほうがRedoログを理解するには早そうです。

Redoログの読み取り(パース)処理から探る

クラッシュリカバリは基本的に、Redoログを読んでcheckpoint以降のデータを復元するredoフェーズ、その後、未コミットのデータをロールバックするundoフェーズからなります。

サーバの起動処理(srv_start())からこれらの処理を行っているところを探すと、recv_recovery_from_checkpoint_start()で最大のcheckpoint lsnを見つけ、recv_recovery_begin()あたりからredoフェーズが始まっているとわかります。
さらいこの中で、recv_read_log_seg()でredoログを4ページずつバッファに読み出し、続くrecv_scan_log_recs()でパースと適用を適宜同時に行っている事がわかります。
これらの"読み出してパースする部分"は並列化されていないので、解析のために弄るのには好都合に見えます。

そこで、まずはリカバリ時にredoログをパース、適用する部分に、プリントデバッグと同じ要領で、読みだしたログを出力して見てみることにしました。

redoログをプリントする方針

ここまで説明したように、MySQLは起動時にクラッシュリカバリ処理として、Checkpoint lsnから、正常に書き込みが完了しているredoログまでのリカバリを行うため、観測したい処理の前にシャープチェックポイントを実行し、それ以降のcheckpointを無効化すれば、特定の処理(とその副作用)によって書き込まれるredoログをリカバリフェーズに仕込んだプリントでバッグで観測できるという寸法です。

これらはデバッグビルドしたMySQLで以下のコマンドで実現できる。

シャープチェックポイントの実行 SET GLOBAL INNODB_LOG_CHECKPOINT_NOW = ON;
チェックポイントの停止 SET GLOBAL INNODB_CHECKPOINT_DISABLED = ON

というわけでパース部分、具体的にはrecv_parse_log_recs()とその呼出先にプリントでバッグを加えるなどしたコマンドを作って様子を見てみます。

単純なinsert文を実行したときに書かれたredo log

クラッシュリカバリ処理中にredoログを読み出し、パースする部分を流用して、mysqlredoというredoログをダンプ出力するクライアントコマンドを作っていますが、まだ出来が悪く、この記事で同時に公開する事はできませんでした。:bow: (ちなみにmysqlbinlog的なのりでmysqlredoにしました。)

単純なinsert文を実行したときに、mysqlredoコマンドがredoログのダンプ出力する例だけ載せておきます。

実行したクエリ

以下のクエリで最後のinsert文周辺のredoログを出力してみます。

mysql> create table t(id int not null primary key);
Query OK, 0 rows affected (0.08 sec)

mysql> insert into t (id) values (1);
Query OK, 1 row affected (0.01 sec)

mysql> set global innodb_log_checkpoint_now = on;
Query OK, 0 rows affected (0.00 sec)

mysql> set global innodb_checkpoint_disabled = on;
Query OK, 0 rows affected (0.00 sec)

mysql> insert into t (id) values (2);
Query OK, 1 row affected (0.00 sec)

redoログをプリントした結果

https://gist.github.com/tom--bo/040bf4f83b9c953ff15c6ca1fe38af32

(上記の出力結果の説明)

この出力結果はcheckpointを行ったところからMySQLのシステムが生成するredoログも含んでいるので、insert文そのものによってredoログ以外のものも含んでいます。
redoログは1つのredoログタイプだけで完結するものと複数のログをグルーピングしたものの2つに別れており、最初にその区別を示すために以下のどちらかの出力を追加しています。

- recv_single_rec()
- recv_multi_rec()

これ以外で1行に出力されているのがRedoログ1つの中身をダンプした結果です。
基本的にredoログの先頭は、以下の3つのフィールドから始まっています。