第95回　行ベースレプリケーションのモニタリング

MySQL 8.0から行ベースレプリケーションに対するモニタリング機能ができました。MySQL 5.7とそれ以前では、行ベースレプリケーションをmysqlコマンド等からリアルタイムで確認できる情報は少なく、レプリケーション遅延が発生した場合などの原因特定に時間がかかりました。今回は、MySQL 8.0から可能な行ベースレプリケーションのモニタリングについて紹介します。

MySQL 5.7とそれ以前の行ベースレプリケーション

行ベースレプリケーションについては、過去の連載でもいくつか触れてきました。以下の記事をご参照ください。

MySQL 5.7とそれ以前の行ベースレプリケーション（以後RBR）では、SHOW SLAVE STATUS構文からSeconds_Behind_Masterの値が増えていくのですが、その原因を特定するのがすぐにはできないということがあります。

まず、ステートメントベースレプリケーション（以後SBR）ではどのSQLが遅延しているのかは、SHOW PROCESSLIST構文とSHOW SLAVE STATUS構文を見ればすぐにわかります。

SBRの場合

マスター側で以下のSQLを実行したとします。

mysql> show variables like 'binlog_format';
+---------------+-----------+
| Variable_name | Value     |
+---------------+-----------+
| binlog_format | STATEMENT |
+---------------+-----------+

mysql> DELETE FROM sbtest2;
Query OK, 1000000 rows affected (20.22 sec)

スレーブで確認します（表示は一部割愛しています⁠）⁠。

mysql> show processlist;
+--------+-------------+---------------------+------+-------------+---------+--------------------+----------------------+
| Id     | User        | Host                | db   | Command     | Time    | State              | Info                 |
+--------+-------------+---------------------+------+-------------+---------+--------------------+----------------------+
| 211476 | system user |                     | db   | Connect     |      17 | updating           | DELETE FROM sbtest2  |
+--------+-------------+---------------------+------+-------------+---------+--------------------+----------------------+

mysql> show slave status\G
*************************** 1. row ***************************
               Slave_IO_State: Waiting for master to send event
             Slave_IO_Running: Yes
            Slave_SQL_Running: Yes
        Seconds_Behind_Master: 17
      Slave_SQL_Running_State: updating

Seconds_Behind_Masterから遅延していることが確認でき、SHOW PROCESSLISTからどのようなSQLが実行されているか確認することができます。

RBRの場合

マスター側で以下のSQLを実行したとします。

mysql> show variables like 'binlog_format';
+---------------+-------+
| Variable_name | Value |
+---------------+-------+
| binlog_format | ROW   |
+---------------+-------+

mysql> DELETE FROM sbtest1 LIMIT 2000000;

スレーブで確認します（表示は一部割愛しています⁠）⁠。

mysql> show processlist;
+--------+-------------+---------------------+------+-------------+---------+---------------------------------------------------------------+------------------+
| Id     | User        | Host                | db   | Command     | Time    | State                                                         | Info             |
+--------+-------------+---------------------+------+-------------+---------+---------------------------------------------------------------+------------------+
| 211476 | system user |                     | NULL | Connect     |      41 | Reading event from the relay log                              | NULL             |
+--------+-------------+---------------------+------+-------------+---------+---------------------------------------------------------------+------------------+

mysql> show slave status\G
*************************** 1. row ***************************
               Slave_IO_State: Waiting for master to send event
             Slave_IO_Running: Yes
            Slave_SQL_Running: Yes
        Seconds_Behind_Master: 40
      Slave_SQL_Running_State: Reading event from the relay log

RBRの場合は、Seconds_Behind_Masterから遅延していることは確認することはできますが、SHOW PROCESSLISTからはReading event from the relay logと表示されるだけです。

Reading event from the relay log、この文字列があれば、SQLスレッドがRBRの更新をしているんだなということは検討がつくのですが、実際にどのSQLが原因かというのはすぐに確認できません。

原因を探るには、第72回行ベースレプリケーション関連のオプションで説明した、binlog_rows_query_log_eventsオプションを有効にして、該当時間にあたりをつけてバイナリログからがんばって探すという手法になるかと思います。

MySQL 8.0の行ベースレプリケーション

MySQL 8.0からは、まず新しい3つのステージが追加されました。

Applying batch of row changes (write) …RBRでInsertしている状態
Applying batch of row changes (update) …RBRでUpdateしている状態
Applying batch of row changes (delete) …RBRでDeleteしている状態

これらが追加されたことで、Reading event from the relay logというSQLスレッドがどのような処理をしているのかわからない状態ではなく、現在INSERT、UPDATEまたはDELETEなどの処理をしているということがわかるようになりました。

先ほどのように試してみます。

マスター側で以下のSQLを実行したとします。

mysql> show variables like 'binlog_format';
+---------------+-------+
| Variable_name | Value |
+---------------+-------+
| binlog_format | ROW   |
+---------------+-------+

mysql> DELETE FROM test LIMIT 1000000;
Query OK, 1000000 rows affected (4.88 sec)

スレーブで確認します（表示は一部割愛しています⁠）⁠。

mysql> show processlist;
+----+-----------------+-----------+------+---------+-------+----------------------------------------+------------------+
| Id | User            | Host      | db   | Command | Time  | State                                  | Info             |
+----+-----------------+-----------+------+---------+-------+----------------------------------------+------------------+
| 17 | system user     |           | test | Query   |     9 | Applying batch of row changes (delete) | NULL             |
+----+-----------------+-----------+------+---------+-------+----------------------------------------+------------------+

mysql> show slave status\G
*************************** 1. row ***************************
               Slave_IO_State: Waiting for master to send event
             Slave_IO_Running: Yes
            Slave_SQL_Running: Yes
        Seconds_Behind_Master: 8
      Slave_SQL_Running_State: Applying batch of row changes (delete)

このように、SQLスレッドが現在リレーログから読み取ってDELETEを実施している、ということがわかるようになりました。

さらに、前述のbinlog_rows_query_log_eventsオプション（デフォルト:OFF）をONにすると、SHOW PROCESSLISTのINFOカラムに実行しているSQLが表示されるようになります。

mysql> show processlist;
+----+-----------------+-----------+------+---------+-------+----------------------------------------+--------------------------------+
| Id | User            | Host      | db   | Command | Time  | State                                  | Info                           |
+----+-----------------+-----------+------+---------+-------+----------------------------------------+--------------------------------+
| 19 | system user     |           | test | Query   |     8 | Applying batch of row changes (delete) | DELETE FROM test LIMIT 1000000 |
+----+-----------------+-----------+------+---------+-------+----------------------------------------+--------------------------------+

このように、RBRであってもマスターで実行されたSQLが表示されるようになっています。バイナリーログから確認する必要はありません。

最後に、もう1つ追加機能として、RBRのステートメント実行の進捗を表示する機能も追加されました。これを見るためには、以下のSQLを実行して対象のインストゥルメンタルをONにします。MySQL 8.0.15現在ではデフォルトでONとなっていますので、ONになっているか確認すれば良いかと思います。

mysql> UPDATE performance_schema.setup_instruments SET ENABLED = 'YES' WHERE NAME LIKE 'stage/sql/Applying batch of row changes%';
Query OK, 0 rows affected (0.01 sec)
Rows matched: 3  Changed: 0  Warnings: 0

mysql> SELECT * from performance_schema.setup_instruments WHERE NAME LIKE 'stage/sql/Applying batch of row changes%';

+--------------------------------------------------+---------+-------+------------+------------+---------------+
| NAME                                             | ENABLED | TIMED | PROPERTIES | VOLATILITY | DOCUMENTATION |
+--------------------------------------------------+---------+-------+------------+------------+---------------+
| stage/sql/Applying batch of row changes (write)  | YES     | YES   | progress   |          0 | NULL          |
| stage/sql/Applying batch of row changes (update) | YES     | YES   | progress   |          0 | NULL          |
| stage/sql/Applying batch of row changes (delete) | YES     | YES   | progress   |          0 | NULL          |
+--------------------------------------------------+---------+-------+------------+------------+---------------+

そして、performance_schema.events_stages_currentテーブルから確認します。

WORK_COMPLETED …完了作業量
WORK_ESTIMATED …見積り作業量

となっており、比較することでRBRの適用進捗がわかります。

mysql> SELECT WORK_COMPLETED, WORK_ESTIMATED FROM performance_schema.events_stages_current WHERE EVENT_NAME LIKE 'stage/sql/Applying batch of row changes%'
+--------------------------------------------------+----------------+----------------+
| EVENT_NAME                                       | WORK_COMPLETED | WORK_ESTIMATED |
+--------------------------------------------------+----------------+----------------+
| stage/sql/Applying batch of row changes (delete) |            561 |            908 |
+--------------------------------------------------+----------------+----------------+

しかし、筆者も試してみましたが、WORK_COMPLETEDの値の増減が繰り返しが発生して、まだ正確な値とは言えないでしょう。これから精度が上がっていく機能として期待しています。

まとめ

MySQL 8.0から、RBRの更新内容がリアルタイムでも確認できるようになりました。マスターで実行されたSQLをすぐに確認できるようになったのは、MySQL運用者としては大変助かる機能だと思います。

今回紹介した内容は、マニュアルの17.3.3 Monitoring Row-based Replicationをご参照ください。