概要

以下の環境にて、MySQL のレプリケーションが正常に同期されない事象に遭遇しました。

• 使用している MySQL のバージョンは 5.5.32
• バイナリログのフォーマットには ROW を使用

現象としては以下の通りです。

• MasterDB で特定のテーブルに書き込んだ更新系 DML が SlaveDB に反映されない
• SlaveDB にて show slave status\G を実行した結果
  • Slave_(IO|SQL)_Running は Yes が表示される
  • Seconds_behind_master に 0 が表示される
  • Exec_Master_Log_Pos の値が MasterDB の Log position と一致する
• Slave 側の Relay-log には MasterDB で実行した更新系 DML が記載されている
• MasterDB, SlaveDB 共にエラーログには出力なし

なお、本バグは下記の通り既に報告されており、MySQl 5.6.11 以上では修正済みとなっています。

table_id is defined differently in sql/table.h vs sql/log_event.h

発生条件

以下の条件を全て満たした場合、本バグが発生します。

• SlaveDB の MySQL のバージョンが 5.6.10 以下
• バイナリログのフォーマットが ROW もしくは MIXED
• MasterDB の table_id が UINT_MAX (64bit Linux 環境で 4294967295) を超えた場合

MasterDB の table_id が UINT_MAX を超えると、SlaveDB 側でオーバーフローが発生し、書き込み対象のテーブルを取得できず、テーブルへの書き込みに失敗する、という事象です。

table_id は MySQL を再起動しない限り増え続ける値のため、長期間に渡り MySQL を運用している環境にて、特に注意が必要だと考えられます。

table_id の確認方法

MasterDB のテーブルに割り当てられている table_id は、以下の手順で binlog より確認することが出来ます。

# binlog の decode
ionice -c3 mysqlbinlog /var/lib/mysql/mysql-bin.000001 -v --base64-output=DECODE-ROWS > /tmp/mysql-bin-000001.decode

# decode 済み binlog から table_map_event を探す
grep 'Table_map:' /tmp/mysql-bin-000001.decode

下記のような出力が得られます。

:
#141215 19:18:04 server id 1  end_log_pos 328       Table_map: `testdb`.`table1` mapped to number 33
#141216 15:47:44 server id 1  end_log_pos 512       Table_map: `testdb`.`table1` mapped to number 33
#141216 15:50:00 server id 1  end_log_pos 696       Table_map: `testdb`.`table1` mapped to number 33
#141216 16:01:23 server id 1  end_log_pos 1093      Table_map: `testdb`.`table2` mapped to number 35
#141216 16:01:49 server id 1  end_log_pos 1277      Table_map: `testdb`.`table2` mapped to number 35
#141216 16:02:52 server id 1  end_log_pos 1461      Table_map: `testdb`.`table2` mapped to number 35
#141216 16:33:54 server id 1  end_log_pos 1645      Table_map: `testdb`.`table2` mapped to number 35
#141216 18:36:04 server id 1  end_log_pos 2307      Table_map: `testdb`.`table1` mapped to number 109
#141216 18:36:06 server id 1  end_log_pos 2491      Table_map: `testdb`.`table1` mapped to number 109
#141216 18:36:07 server id 1  end_log_pos 2675      Table_map: `testdb`.`table1` mapped to number 109
#141216 18:36:08 server id 1  end_log_pos 2859      Table_map: `testdb`.`table1` mapped to number 109
#141216 18:36:09 server id 1  end_log_pos 3043      Table_map: `testdb`.`table1` mapped to number 109
#141216 18:38:43 server id 1  end_log_pos 3220      Table_map: `testdb`.`table1` mapped to number 109
#141216 18:40:47 server id 1  end_log_pos 3511      Table_map: `testdb`.`table3` mapped to number 119
:

このログは、テーブルに INSERT/DELETE/UPDATE 等の更新系 DML が発行された際に binlog に出力されるものです。 (※もし出力がない場合には、新しくテーブルを作成し、INSERT 文等を発行することで確認することが出来ます。)

上記ログの末尾に書いてある数字が table_id となり、Table_map: ... の後に続いているのが当該の id が割り振られているテーブル名となります。

例えば、Log position 328 の段階では、testdb.table1 に 33 という table_id が割り当てられています。

割り当てられてる table_id が UINT_MAX を超えた場合、当該テーブルへの書き込みは SlaveDB に反映されません。

table_id の割り当てタイミング

table_id の割り当ては、table_definition_cache に乗っていないテーブルのオープン時に行われます。

具体的には、show open tables; 句を発行した際に一覧に出ないテーブルをオープンした際です。 例としては、下記の操作が考えられます。

• CREATE TABLE にて新たなテーブルを作成し書き込みを実施
• FLUSH TABLES にてテーブルを閉じた後に読み込みを実施
• ソート時などのバッファ溢れにより一時テーブルを作成し書き込みを実施

table_id は MySQL の起動時から、割り当てられる度に 1 ずつ上昇していく値となります。 具体的には、last_table_id という値で管理されています。

また、MasterDB と SlaveDB では異なる last_table_id を保持しているため、 単純に Master から Slave へスイッチオーバしても table_id をリセットすることは出来ません。

取りうる回避策

MySQL 5.6.11 以降へのアップデート

もちろんこれが適切な改善策です。 ちなみに、MySQL 5.6 以降では information_schema に INNODB_SYS_TABLES というテーブルがあり、 その中の table_id というカラムから、テーブルの ID を取得できるようになっています。

MasterDB 再起動

table_id の値は、MySQL を再起動するまでリセットされません。 そのため、table_id が UINT_MAX を超える前に MasterDB の MySQL を再起動する必要があります。

SlaveDB 再起動 + スイッチオーバ

冗長構成ならこちらの方法が現実的かなと思います。 単純に SlaveDB にスイッチオーバするだけだと、スイッチオーバした際に、 SlaveDB が保持している table_id から増加していくため、 table_id が大きく減る保証はありません。

事前に SlaveDB を再起動しておくことで、last_table_id をリセットすることが出来るので、 SlaveDB を再起動し、MasterDB から SlaveDB にスイッチオーバすることで、 table_id が UINT_MAX を超えることを防ぐことが出来ます。

table_id の急激な増加を防ぐために

table_id は前述の通り、新たにテーブルをオープンした際に割り当てられます。 特に table_id が増加しやすい原因として、以下の 3 つが考えられます。

• 各種バッファサイズが小さすぎる
• テーブル数に対して table_definition_cache が小さすぎる
• FLUSH TABLES を実行しすぎている

各種バッファサイズが小さすぎる

各種バッファサイズが小さすぎる場合、ソートなどの操作により一時テーブルが生成されます。 table_id は一時テーブルにも割り当てられるため、頻繁に一時テーブルが作成されるような環境だと、 table_id が不必要に増加してしまう原因となります。 ソート時に一時テーブルが頻繁に作られてしまうような環境では、 sort_buffer_size 等のパラメータを調整する必要があるかもしれません。

テーブル数に対して table_definition_cache が小さすぎる

table_definition_cache の値がテーブル数に対して小さすぎる場合、 頻繁に table_definition_cache からの追い出しが発生し、 次にオープンするタイミングで、table_id が増加します。 多くのテーブルをそれぞれ頻繁に使用するような場合は、 パラメータを調整する必要があるかもしれません。

FLUSH TABLES を実行しすぎている

FLUSH TABLES 句は、全てのテーブルを一度閉じます。 次にテーブルを開くタイミングで、table_id が新たに割り当てられることになるため、 FLUSH TABLES 句を頻繁に使用した場合、table_id が急激に増加することになります。

まとめ

MySQL 5.6.10 以下に存在するレプリケーションのバグについて現象を説明しました。 table_id は普通に MySQL を使用していても増え続ける値であり、皆さんの環境でもいつこのバグが発生するとも限りません。

また、RDS で発生したという報告が挙がっていたり、MariaDB にも当該コード部分がそのままであったりするので、 気になる方は確認してみるのが良いかと思います。

この件に関しては引き続き対応や調査を進めますので、また何か公開できる事があればブログに書くかもしれません。 その際はまたよろしくお願いします。