MTS（マルチスレッドスレーブ）を使う場合の注意点

2018年8月7日

この記事は最終更新から6年以上経過しています。内容が古くなっている可能性があります。

MySQL5.6で実装されたMulti Threads Slave（以下、MTS）は、MySQLレプリケーションを利用するユーザ共通の悩みである「スレーブ遅延」に対するソリューションの一つです。
スレーブ遅延の主因の一つは、スレーブのSQLスレッドが「1つ」しかないことでした。しかし、MySQL5.6からMTSを用いることで異なるデータベース間で複数スレッドによる並列処理が可能となり、MySQL5.7からは同一データベースでも並列処理が可能となりました。この結果、スレーブの遅延はかなり軽減されています。

しかし、以前MTSの検証をしていて気になる挙動を見つけたので、記載したいと思います。

事象の内容

きっかけは大きなバッチ処理を実行した時、マスタの実行時間よりも大幅に長くスレーブでの処理に時間がかかってしまう、という事象でした。

調査を進めるうちにエラーログに以下のようなメッセージが大量に出力されているのが分かりました。

[Note] Multi-threaded slave: Coordinator has waited 611 times hitting slave_pending_jobs_size_max; current event size = 8169.

1	[Note] Multi-threaded slave: Coordinator has waited 611 times hitting slave_pending_jobs_size_max; current event size = 8169.

上記のメッセージは、マスタから送られたレプリケーションイベントのサイズが、スレーブのworkerスレッドの使用メモリ量を超えてしまった場合に、処理が待ち状態になっていることを示しています。「workerスレッドの使用メモリ量」は、slave_pending_jobs_size_max変数で決められます。

再現手順

AWSの「c5.xlarge」インスタンスを3台作成し、MySQL5.7の最新版をyumインストールします（この時点ではMySQL5.7.21）。
その後、「マスタ1台：スレーブ2台」のGTIDレプリケーション環境を構築し、MTSを設定します。なお、パラメータは以下の通り変更します。

master : max_allowed_packet=32MB
slave1 : max_allowed_packet=32MB / slave_pending_jobs_size_max=16MB
slave2 : max_allowed_packet=32MB / slave_pending_jobs_size_max=128MB

※ slave_parallel_workers変数は “4” で統一しています

この環境で、マスタでランダムデータのINSERT文を実行しています。

master$ mysql -u root -p

mysql> CREATE DATABASE d1;
mysql> USE d1;
mysql> CREATE TABLE t1 (id int auto_increment primary key, col1 varchar(30), col2 varchar(30), col3 varchar(30));

mysql> INSERT t1 (col1,col2,col3) SELECT SUBSTRING(MD5(RAND()), 1, 30),SUBSTRING(MD5(RAND()), 1, 30),SUBSTRING(MD5(RAND()), 1, 30);
mysql> INSERT t1 (col1,col2,col3) SELECT SUBSTRING(MD5(RAND()), 1, 30),SUBSTRING(MD5(RAND()), 1, 30),SUBSTRING(MD5(RAND()), 1, 30) FROM t1;
... 以下、繰り返し

master$ mysql -u root -p

mysql> CREATE DATABASE d1;

mysql> USE d1;

mysql> CREATE TABLE t1 (id int auto_increment primary key, col1 varchar(30), col2 varchar(30), col3 varchar(30));

mysql> INSERT t1 (col1,col2,col3) SELECT SUBSTRING(MD5(RAND()), 1, 30),SUBSTRING(MD5(RAND()), 1, 30),SUBSTRING(MD5(RAND()), 1, 30);

mysql> INSERT t1 (col1,col2,col3) SELECT SUBSTRING(MD5(RAND()), 1, 30),SUBSTRING(MD5(RAND()), 1, 30),SUBSTRING(MD5(RAND()), 1, 30) FROM t1;

... 以下、繰り返し

するとトランザクションのサイズが一定を超えた段階で、以下のようなメッセージがslave1のエラーログに出力されます。この時、スレーブで大幅な遅延が起きている可能性があります。

※ 別コンソールで tail -f /var/log/mysqld.log を実行しておくと分かりやすいです

2018-04-25T05:39:08.474653-00:00 2 [Note] Multi-threaded slave: Coordinator has waited 611 times hitting slave_pending_jobs_size_max; current event size = 8169.
2018-04-25T05:39:08.477240-00:00 2 [Note] Multi-threaded slave: Coordinator has waited 621 times hitting slave_pending_jobs_size_max; current event size = 8169.
2018-04-25T05:39:08.485007-00:00 2 [Note] Multi-threaded slave: Coordinator has waited 631 times hitting slave_pending_jobs_size_max; current event size = 8169.
2018-04-25T05:39:08.487578-00:00 2 [Note] Multi-threaded slave: Coordinator has waited 641 times hitting slave_pending_jobs_size_max; current event size = 8169.

2018-04-25T05:39:08.474653-00:00 2 [Note] Multi-threaded slave: Coordinator has waited 611 times hitting slave_pending_jobs_size_max; current event size = 8169.

2018-04-25T05:39:08.477240-00:00 2 [Note] Multi-threaded slave: Coordinator has waited 621 times hitting slave_pending_jobs_size_max; current event size = 8169.

2018-04-25T05:39:08.485007-00:00 2 [Note] Multi-threaded slave: Coordinator has waited 631 times hitting slave_pending_jobs_size_max; current event size = 8169.

2018-04-25T05:39:08.487578-00:00 2 [Note] Multi-threaded slave: Coordinator has waited 641 times hitting slave_pending_jobs_size_max; current event size = 8169.

一方で、slave_pending_jobs_size_max変数を大きく設定しているslave2では同様のメッセージは発生していません。

対策

上記の問題を回避するためには、slave_pending_jobs_size_max 変数をあらかじめ大きくすることが推奨されます。特にマスタで巨大なトランザクションが実行されるケースが想定されるなら、ある程度大きい数値を設定すると良いでしょう。
また、max_allowed_packet > slave_pending_jobs_size_max という設定をしてしまうと、ペンディングが頻発する可能性があります。slave_pending_jobs_size_max のデフォルト値は「16MB」と少し小さめなので、注意しましょう。