日々の覚書: わざと件数をズラしたグループレプリケーションで、「遅延中」の動きを観察する

日々の覚書: シングルプライマリーモードだろうとInnoDB Cluster内のデータをズラす方法の続き。

件数をズラした上で OPTIMIZE TABLE をかけるといくらでもセカンダリーが遅延した状況が作り出せる、というとことまでは良いとして。

node3のグループレプリケーションを一旦止める。

### node3
mysql> STOP GROUP_REPLICATION;
Query OK, 0 rows affected (4.49 sec)

またnode1から OPTIMIZE TABLE を5発くらい叩き込んでついでに更新SQLを入れておく。

### node1
mysql> OPTIMIZE TABLE sbtest.sbtest1; -- これを5回くらい

mysql> INSERT INTO d1.t1 VALUES (4, 'four');
Query OK, 1 row affected (0.01 sec)

mysql> SELECT * FROM d1.t1;
+-----+-------+
| num | val   |
+-----+-------+
|   1 | one   |
|   2 | two   |
|   3 | three |
|   4 | four  |
+-----+-------+
4 rows in set (0.00 sec)

### node2
mysql> SELECT * FROM d1.t1; -- OPTIMIZE TABLEにやられて遅れてる
+-----+-------+
| num | val   |
+-----+-------+
|   1 | one   |
|   2 | two   |
|   3 | three |
+-----+-------+
3 rows in set (0.00 sec)

### node3
mysql> SELECT * FROM d1.t1;  -- そもそもグループレプリケーション止めてるので同期されない
+-----+-------+
| num | val   |
+-----+-------+
|   1 | one   |
|   2 | two   |
|   3 | three |
+-----+-------+
3 rows in set (0.00 sec)

ここでnode3のグループレプリケーションを再開。

### node3
mysql> START GROUP_REPLICATION;
Query OK, 0 rows affected (4.93 sec)

$ for f in /var/lib/mysql/*.0000* ; do mysqlbinlog -vv $f | stdbuf -oL awk '{print "'$f'", $0}'; done | grep INSERT | grep d1
/var/lib/mysql/binlog.000002 ### INSERT INTO `d1`.`t1`
/var/lib/mysql/binlog.000002 ### INSERT INTO `d1`.`t1`
/var/lib/mysql/binlog.000002 ### INSERT INTO `d1`.`t1`
/var/lib/mysql/ip-172-31-1-48-relay-bin-group_replication_recovery.000003 ### INSERT INTO `d1`.`t1`

この時点で、「グループレプリケーション停止中に更新した行はrecoveryの方のリレーログに入る」のは実験済み。

日々の覚書: グループレプリケーションの group_replication_applier と group_replication_recovery のリレーログ

じゃあ、 “RECOVERING” 中に新しく突っ込まれた更新の行は？

### node1
mysql> INSERT INTO d1.t1 VALUES (5, 'five');
Query OK, 1 row affected (0.01 sec)

### node3
$ for f in /var/lib/mysql/*.0000* ; do mysqlbinlog -vv $f | stdbuf -oL awk '{print "'$f'", $0}'; done | grep INSERT | grep d1
/var/lib/mysql/binlog.000002 ### INSERT INTO `d1`.`t1`
/var/lib/mysql/binlog.000002 ### INSERT INTO `d1`.`t1`
/var/lib/mysql/binlog.000002 ### INSERT INTO `d1`.`t1`
/var/lib/mysql/ip-172-31-1-48-relay-bin-group_replication_recovery.000003 ### INSERT INTO `d1`.`t1`
/var/lib/mysql/ip-172-31-1-48-relay-bin-group_replication_recovery.000003 ### INSERT INTO `d1`.`t1`

これもrecoveryの方に入った。recoveryが動きを止める

遅延が完全に追い付いてからnode1にINSERTした値はapplierの方に入る。

### node1
mysql> INSERT INTO d1.t1 VALUES (6, 'six');
Query OK, 1 row affected (0.01 sec)

### node3
for f in /var/lib/mysql/*.0000* ; do mysqlbinlog -vv $f | stdbuf -oL awk '{print "'$f'", $0}'; done | grep INSERT | grep d1
/var/lib/mysql/binlog.000002 ### INSERT INTO `d1`.`t1`
/var/lib/mysql/binlog.000002 ### INSERT INTO `d1`.`t1`
/var/lib/mysql/binlog.000002 ### INSERT INTO `d1`.`t1`
/var/lib/mysql/binlog.000002 ### INSERT INTO `d1`.`t1`
/var/lib/mysql/binlog.000002 ### INSERT INTO `d1`.`t1`
/var/lib/mysql/binlog.000002 ### INSERT INTO `d1`.`t1`
/var/lib/mysql/ip-172-31-1-48-relay-bin-group_replication_applier.000002 ### INSERT INTO `d1`.`t1`
/var/lib/mysql/ip-172-31-1-48-relay-bin-group_replication_applier.000002 ### INSERT INTO `d1`.`t1`

ん？何故かapplierの方に (5, ‘five’) と思しきイベントも入ってる

### node3
$ mysqlbinlog -vv /var/lib/mysql/ip-172-31-1-48-relay-bin-group_replication_applier.000002
..
SET @@SESSION.GTID_NEXT= '14b471b9-66e5-11ea-888f-12c40920c9ad:454'/*!*/;
### INSERT INTO `d1`.`t1`
### SET
###   @1=5
###   @2='five'
..
SET @@SESSION.GTID_NEXT= '14b471b9-66e5-11ea-888f-12c40920c9ad:455'/*!*/;
### INSERT INTO `d1`.`t1`
### SET
###   @1=6
###   @2='six'

recoveryの方のリレーログすぐ消えちゃうからな… relay_log_purge=OFF したら残ってくれるかしらん。

### node3
mysql> SELECT channel_name, service_state, last_applied_transaction AS last_gtid, last_applied_transaction_original_commit_timestamp AS orig_ts, last_applied_transaction_immediate_commit_timestamp AS my_ts FROM performance_schema.replication_applier_status_by_worker;
+----------------------------+---------------+------------------------------------------+----------------------------+----------------------------+
| channel_name               | service_state | last_gtid                                | orig_ts                    | my_ts                      |
+----------------------------+---------------+------------------------------------------+----------------------------+----------------------------+
| group_replication_applier  | ON            | 14b471b9-66e5-11ea-888f-12c40920c9ad:455 | 2020-03-15 18:23:10.568424 | 0000-00-00 00:00:00.000000 |
| group_replication_recovery | OFF           | 14b471b9-66e5-11ea-888f-12c40920c9ad:453 | 0000-00-00 00:00:00.000000 | 2020-03-15 18:18:30.913861 |
+----------------------------+---------------+------------------------------------------+----------------------------+----------------------------+
2 rows in set (0.00 sec)

performance_schemaで調べる限り、RECOVERING中に入ってきた2行はapplierの方が処理しているっぽい。
正直どっちが処理してくれても（recoveryが止まって初めてapplierが動くなら）構いはしない気がするけど、これがDMLだからなのかDDLなのかちょっと気になるね。

…と調べてみたら、DML/DDLに関わらずグループレプリケーションを再開した後に打たれたSQLはrecoveryのリレーログで一度受けた後にapplierの方に回すっぽい。

謎が深まった。

日々の覚書

GA

2020/03/16

わざと件数をズラしたグループレプリケーションで、「遅延中」の動きを観察する

0 件のコメント :

コメントを投稿