2020/04/28

performance_schema.clone_progress が何となくそれっぽい順番に並ぶ理由

TL;DR

datadir/#clone/#view_progress という平文のファイルがこのテーブルの本体だから

俺は途中まで作業をしていて聞き逃したんですけど、 Open Source Conference 2020 Online/Spring のかじやまさんのセッションでそんな話題が挙がったらしく。

ps.clone_progress からのSELECTの時ってORDER BY なくても「良い感じの順」で返してくれるのかな。返してくれるような気もするけど「ORDER BY を指定しないときの順は不定ですよ」と入門講座とかで口を酸っぱくしている身には、少し気持ち悪い(笑)。 #mysql_jp #osc20on
— 坂井恵(SAKAI Kei) (@sakaik) April 24, 2020

performance_schema.clone_progress は CLONEステートメントが走っている間の進捗どうですかを人間に見えるようにするためのテーブルで、

mysql> SELECT * FROM performance_schema.clone_progress;
+------+-----------+-----------+----------------------------+----------------------------+---------+------------+------------+------------+------------+---------------+
| ID   | STAGE     | STATE     | BEGIN_TIME                 | END_TIME                   | THREADS | ESTIMATE   | DATA       | NETWORK    | DATA_SPEED | NETWORK_SPEED |
+------+-----------+-----------+----------------------------+----------------------------+---------+------------+------------+------------+------------+---------------+
|    1 | DROP DATA | Completed | 2020-04-28 08:28:31.995013 | 2020-04-28 08:28:32.196990 |       1 |          0 |          0 |  0 |          0 |             0 |
|    1 | FILE COPY | Completed | 2020-04-28 08:28:32.197136 | 2020-04-28 08:30:19.792994 |       2 | 7608587553 | 7608587553 | 7609004364 |          0 |             0 |
|    1 | PAGE COPY | Completed | 2020-04-28 08:30:19.863918 | 2020-04-28 08:30:21.697040 |       2 |          0 |          0 |197 |          0 |             0 |
|    1 | REDO COPY | Completed | 2020-04-28 08:30:26.150594 | 2020-04-28 08:30:26.803841 |       2 |       2560 |       2560 |       3129 |          0 |             0 |
|    1 | FILE SYNC | Completed | 2020-04-28 08:30:28.247954 | 2020-04-28 08:30:35.971538 |       2 |          0 |          0 |  0 |          0 |             0 |
|    1 | RESTART   | Completed | 2020-04-28 08:30:35.971538 | 2020-04-28 08:30:41.140485 |       0 |          0 |          0 |  0 |          0 |             0 |
|    1 | RECOVERY  | Completed | 2020-04-28 08:30:41.140485 | 2020-04-28 08:30:41.562447 |       0 |          0 |          0 |  0 |          0 |             0 |
+------+-----------+-----------+----------------------------+----------------------------+---------+------------+------------+------------+------------+---------------+

こんな風に見える。 CLONE INSTANCE FROM でリモートにデータ転送をしている場合、このテーブルが見えるのはレシピエント ( CLONE INSTANCE FROM を実行した側) であってドナー (データを供給している側) ではない。

MySQL :: MySQL 8.0 Reference Manual :: 5.6.7.9 Monitoring Cloning Operations

そもそもよく考えれば、 PERFORMANCE_SCHEMA ストレージエンジンは「統計情報格納専用のインメモリストレージエンジン」だと散々聞かされてきたのに、コイツは揮発しない( CLONE INSTANCE FROM はそもそもデータをコピーしてきたあと自動で再起動するし、そのあと何度 mysqld の停止起動を挟んでもこのテーブルは同じ値を返し続ける）

さてさて…取り敢えずソースコードをテーブル名の “clone_progress” で検索してみた。

https://github.com/mysql/mysql-server/blob/mysql-8.0.20/plugin/clone/src/clone_status.cc#L58-L60

変数の名前が CLONE_VIEW_PROGRESS_FILE でなんかもうここでオチが見えた。

Progress_pfs::Data::write で書いてるんだろうけど、 std::ofstream でファイルを開いて書いてるだけ。

https://github.com/mysql/mysql-server/blob/mysql-8.0.20/plugin/clone/src/clone_status.cc#L703-L741

ファイルを読み出してテーブルとして見せるところで頑張っているっぽい。

https://github.com/mysql/mysql-server/blob/mysql-8.0.20/plugin/clone/src/clone_status.cc#L743-L831

となるとやることは1つで、このファイル(確かに今はシンクロしている)を

$ cat /var/lib/mysql/#clone/#view_progress
1
2 1 1588062511995013 1588062512196990 0 0 0
2 2 1588062512197136 1588062619792994 7608587553 7608587553 7609004364
2 2 1588062619863918 1588062621697040 0 0 197
2 2 1588062626150594 1588062626803841 2560 2560 3129
2 2 1588062628247954 1588062635971538 0 0 0
2 0 1588062635971538 1588062641140485 0 0 0
2 0 1588062641140485 1588062641562447 0 0 0

こうじゃ

$ cat /var/lib/mysql/#clone/#view_progress
1
2 1 082508250825 1588062512196990 0 0 0
2 2 1588062512197136 1588062619792994 7608587553 7608587553 7609004364
2 2 1588062619863918 1588062621697040 0 0 197
2 2 1588062626150594 1588062626803841 2560 2560 3129
2 2 1588062628247954 1588062635971538 0 0 0
2 0 1588062635971538 1588062641140485 0 0 0
2 0 1588062641140485 1588062641562447 0 0 0

ただ SELECT し直しても FLUSH TABLES でテーブルを閉じても反映はされなかった。これを読むのは mysqld の起動時のみっぽい(と予測)

mysql> RESTART;

mysql> SELECT * FROM performance_schema.clone_progress;
+------+-----------+-----------+----------------------------+----------------------------+---------+------------+------------+------------+------------+---------------+
| ID   | STAGE     | STATE     | BEGIN_TIME                 | END_TIME                   | THREADS | ESTIMATE   | DATA       | NETWORK    | DATA_SPEED | NETWORK_SPEED |
+------+-----------+-----------+----------------------------+----------------------------+---------+------------+------------+------------+------------+---------------+
|    1 | DROP DATA | Completed | 1970-01-01 22:55:08.250825 | 2020-04-28 08:28:32.196990 |       1 |          0 |          0 |          0 |          0 |             0 |
|    1 | FILE COPY | Completed | 2020-04-28 08:28:32.197136 | 2020-04-28 08:30:19.792994 |       2 | 7608587553 | 7608587553 | 7609004364 |          0 |             0 |
|    1 | PAGE COPY | Completed | 2020-04-28 08:30:19.863918 | 2020-04-28 08:30:21.697040 |       2 |          0 |          0 |        197 |          0 |             0 |
|    1 | REDO COPY | Completed | 2020-04-28 08:30:26.150594 | 2020-04-28 08:30:26.803841 |       2 |       2560 |       2560 |       3129 |          0 |             0 |
|    1 | FILE SYNC | Completed | 2020-04-28 08:30:28.247954 | 2020-04-28 08:30:35.971538 |       2 |          0 |          0 |          0 |          0 |             0 |
|    1 | RESTART   | Completed | 2020-04-28 08:30:35.971538 | 2020-04-28 08:30:41.140485 |       0 |          0 |          0 |          0 |          0 |             0 |
|    1 | RECOVERY  | Completed | 2020-04-28 08:30:41.140485 | 2020-04-28 08:30:41.562447 |       0 |          0 |          0 |          0 |          0 |             0 |
+------+-----------+-----------+----------------------------+----------------------------+---------+------------+------------+------------+------------+---------------+
7 rows in set (0.00 sec)

DROP DATAのBEGIN_TIMEが 08秒250825 になってるので書き換え成功してますね ;)

なるほど道理で、InnoDB Clusterの実験している時に mysqld を停止して起動させてから mysqlsh で戻そうとする時に、CLONEもしてないbinlogの差分同期だけでも Status:CLONEING みたいになる訳だ…（このファイルはずっと残り続けるから…

ちなみに、 yoku0825 とか整数型でなさそうな文字列を入れたらその行は NULL になりました。ためしてみましょう！

2020/04/07

MySQLのLAG()とかLEAD()に ERROR 1690 (22003): BIGINT UNSIGNED value is out of range と言われたら

TL;DR

sql_mode に NO_UNSIGNED_SUBTRACTION を追加してから実行する

たとえば、 performance_schema.events_statements_summary_by_digest の結果を延々とため込んでいるようなテーブルがあるとするじゃろ？

sum_rows_examined は累計値なので、グラフにする時なぞは前回との差分を取りたくなるので、MySQL 8.0からようやく使えるようになった LAG なぞ使うではないか。

mysql> WITH base AS
    -> (
    ->   SELECT
    ->     digest,
    ->     sum_rows_examined - LAG(sum_rows_examined) OVER w AS diff_exam,
    ->     last_update,
    ->     TIMESTAMPDIFF(second, LAG(last_update) OVER w, last_update) AS diff_time
    ->   FROM ps_digest_info
    ->   WINDOW w AS (PARTITION BY digest ORDER BY seq)
    -> )
    -> SELECT digest, last_update, diff_exam / diff_time, diff_time FROM base;
ERROR 1690 (22003): BIGINT UNSIGNED value is out of range in '(`admintool`.`ps_digest_info`.`sum_rows_examined` - `tmp_field_5`)'

エラった(´･ω･｀)

これは再起動でもはさんだのか、 sum_rows_examined - LAG(sum_rows_examined) OVER w (これが tmp_field_5 の正体) が負になるところがあると BIGINT UNSIGNED の範囲に収まらないから…ってこうなる。

確かに sum_rows_examined は BIGINT UNSIGNED で定義していたのでこれを BIGINT SIGNED にデータ型を変えてやれば動くようにはなるんだけど、必ずしもそうできるわけでもない。

mysql> show create table ps_digest_info\G
*************************** 1. row ***************************
       Table: ps_digest_info
Create Table: CREATE TABLE `ps_digest_info` (
  `seq` bigint(20) unsigned NOT NULL AUTO_INCREMENT,
  `ipaddr` varchar(15) NOT NULL,
  `port` smallint(5) unsigned NOT NULL,
  `schema_name` varchar(255) NOT NULL,
  `digest` varchar(255) NOT NULL,
  `digest_text` text NOT NULL,
  `count_star` bigint(20) unsigned NOT NULL,
  `sum_rows_examined` bigint(20) unsigned NOT NULL,
  `sum_rows_sent` bigint(20) unsigned NOT NULL,
..

MySQLは何故か整数の加減算の時に「片方が符号無しの場合は結果の型を符号無しにしようとする」という謎なポリシー(?)があって、それに違反すると出るエラーが ERROR 1690 (22003): BIGINT UNSIGNED value is out of range .

このポリシーを曲げさせて「結果の型が負になりそうなら符号ありにキャストする」ようにするのが NO_UNSIGNED_SUBTRACTION

mysql> SET sql_mode = CONCAT(@@sql_mode, ',NO_UNSIGNED_SUBTRACTION');
Query OK, 0 rows affected (0.00 sec)

mysql> WITH base AS  (    SELECT       digest,       sum_rows_examined - LAG(sum_rows_examined) OVER w AS diff_exam,      last_update,       TIMESTAMPDIFF(second, LAG(last_update) OVER w, last_update) AS diff_time    FROM ps_digest_info     WINDOW w AS (PARTITION BY digest ORDER BY seq))  SELECT digest, last_update, diff_exam / diff_time, diff_time FROM base;
+----------------------------------+---------------------+-----------------------+-----------+
| digest                           | last_update         | diff_exam / diff_time | diff_time |
+----------------------------------+---------------------+-----------------------+-----------+
|                                  | 2019-06-25 10:30:08 |                  NULL |      NULL |
|                                  | 2019-06-25 18:30:08 |               26.7571 |     28800 |
|                                  | 2019-07-02 10:30:08 |               68.2178 |    576000 |
..

結果が返ってくるようになった。良かった良かった。

2020/04/06

my.cnfの plugin_load の記法

TL;DR

INSTALL PLUGIN a SONAME 'b.so' は plugin_load= a=b.so と書く
複数つなげる時は ; で区切る、 plugin_load=rpl_semi_sync_master=semisync_master.so;rpl_semi_sync_slave=semisync_slave.so みたいに

…言いたいことは全部書いてしまった気がするので、ドキュメントを読んでつらつらと。

MySQL :: MySQL 8.0 Reference Manual :: 5.6.1 Installing and Uninstalling Plugins

plugin_load_add は使ったことなかったけど、 ; で複数区切りを「したくない」時に後ろに書けるらしい。地味にMySQL 5.6.3の新機能だったらしい。知らなかった。

plugin_load_add が追加で plugin_load は上書きな関係上、my.cnfの上では必ず plugin_load が先で plugin_load_add は後に書かないといけないらしい。

5.7のInnoDB暗号化の時から姿を現した early_plugin_load はプラグインをロードするタイミングが違うだけみたい。

early_plugin_load ( https://github.com/mysql/mysql-server/blob/mysql-5.7.29/sql/mysqld.cc#L4053 )

(gdb) bt
+bt
#0  ReplSemiSyncMaster::initObject (this=this@entry=0x7fffee604ca0 <repl_semisync>)
    at /home/yoku0825/mysql-5.7.29/plugin/semisync/semisync_master.cc:449
#1  0x00007fffee3fecfa in semi_sync_master_plugin_init (p=0x1fdc998)
    at /home/yoku0825/mysql-5.7.29/plugin/semisync/semisync_master_plugin.cc:596
#2  0x0000000000ca3fd4 in plugin_initialize (plugin=plugin@entry=0x1fdc998) at /home/yoku0825/mysql-5.7.29/sql/sql_plugin.cc:1252
#3  0x0000000000ca89ef in plugin_init_initialize_and_reap () at /home/yoku0825/mysql-5.7.29/sql/sql_plugin.cc:1388
#4  0x0000000000ca8d1f in plugin_register_early_plugins (argc=argc@entry=0x1dd5df0 <remaining_argc>, argv=0x1e9f930, flags=0)
    at /home/yoku0825/mysql-5.7.29/sql/sql_plugin.cc:1500
#5  0x000000000078950a in init_server_components () at /home/yoku0825/mysql-5.7.29/sql/mysqld.cc:4053
#6  0x000000000078cfb1 in mysqld_main (argc=4, argv=0x1e9f930) at /home/yoku0825/mysql-5.7.29/sql/mysqld.cc:4755
#7  0x00007ffff5ecf505 in __libc_start_main (main=0x7652a0 <main(int, char**)>, argc=4, argv=0x7fffffffe3c8, init=<optimized out>,
    fini=<optimized out>, rtld_fini=<optimized out>, stack_end=0x7fffffffe3b8) at ../csu/libc-start.c:266
#8  0x00000000007829ec in _start ()

フツーのplugin_load ( https://github.com/mysql/mysql-server/blob/mysql-5.7.29/sql/mysqld.cc#L4074 )

(gdb) bt
+bt
#0  ReplSemiSyncMaster::initObject (this=this@entry=0x7fffe3b22ca0 <repl_semisync>)
    at /home/yoku0825/mysql-5.7.29/plugin/semisync/semisync_master.cc:449
#1  0x00007fffe391ccfa in semi_sync_master_plugin_init (p=0x26eab48)
    at /home/yoku0825/mysql-5.7.29/plugin/semisync/semisync_master_plugin.cc:596
#2  0x0000000000ca3fd4 in plugin_initialize (plugin=plugin@entry=0x26eab48) at /home/yoku0825/mysql-5.7.29/sql/sql_plugin.cc:1252
#3  0x0000000000ca89ef in plugin_init_initialize_and_reap () at /home/yoku0825/mysql-5.7.29/sql/sql_plugin.cc:1388
#4  0x0000000000cab1ee in plugin_register_dynamic_and_init_all (argc=argc@entry=0x1dd5df0 <remaining_argc>, argv=0x1e9f930,
    flags=flags@entry=0) at /home/yoku0825/mysql-5.7.29/sql/sql_plugin.cc:1673
#5  0x0000000000789561 in init_server_components () at /home/yoku0825/mysql-5.7.29/sql/mysqld.cc:4074
#6  0x000000000078cfb1 in mysqld_main (argc=4, argv=0x1e9f930) at /home/yoku0825/mysql-5.7.29/sql/mysqld.cc:4755
#7  0x00007ffff5ecf505 in __libc_start_main (main=0x7652a0 <main(int, char**)>, argc=4, argv=0x7fffffffe3c8, init=<optimized out>,
    fini=<optimized out>, rtld_fini=<optimized out>, stack_end=0x7fffffffe3b8) at ../csu/libc-start.c:266
#8  0x00000000007829ec in _start ()

間にビルトインプラグインと主要ストレージエンジンのロードが入っているので、InnoDB暗号化は確かにInnoDBの起動より先にやらないといけなくてearlyの方じゃないとダメそう。

逆にInnoDB MemcachedとかInnoDBに依存してそうだからearlyでやると転けた。

plugin_load っていうとプラグインInnoDBとか思い出しますね :D

2020/03/19

MySQL 8.0のデュアルパスワードを使った記念メモ

TL;DR

デュアルパスワードの情報は mysql.user.User_attributes カラムにJSONで入ってくるのでその辺で確認できる
- SHOW CREATE USER には入ってこないのでここで確認するしかない？
SELECTステートメントでデュアルパスワード持ってるアカウントだけを引っ張るなら mysql.user.user_attributes に additional_password って要素を持ってるかどうかで判定ができる

mysql80 7> SELECT user, host FROM mysql.user WHERE user_attributes->>'$.additional_password' IS NOT NULL;
+----------+------+
| user     | host |
+----------+------+
| yoku0825 | %    |
+----------+------+
1 row in set (0.00 sec)

「セカンダリーパスワード」とかそんな名前かと思ったら、「デュアルパスワード」が公式用語っぽいのも今回初めて気が付いた。

やり方そのものは日本語でも記事が存在するしドキュメントもある。

試しにやってみるだけなら、 IDENTIFIED WITH mysql_native_password BY '..' でmysql_native_passwordプラグインを使った方が出力が化けなくて良いかも ( print_identified_with_as_hex は SELECT で直接のぞき込む時には使えないから)

mysql80 82> CREATE USER yoku0825 IDENTIFIED BY 'yoku0826';
Query OK, 0 rows affected (0.01 sec)

mysql80 82> SHOW CREATE USER yoku0825;
+----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+
| CREATE USER for yoku0825@%                                                                                                                                                                                                                                                                   |
+----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+
| CREATE USER 'yoku0825'@'%' IDENTIFIED WITH 'caching_sha2_password' AS '$A$005$]f|)Pd<I#(i
                                                                                                ij[HzpqNoMwkaEO.dS2orkm5nQ/2Mgulxlh.8aumbjfYa8' REQUIRE NONE PASSWORD EXPIRE DEFAULT ACCOUNT UNLOCK PASSWORD HISTORY DEFAULT PASSWORD REUSE INTERVAL DEFAULT PASSWORD REQUIRE CURRENT DEFAULT |
+----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+
1 row in set (0.00 sec)

mysql80 82> ALTER USER yoku0825 IDENTIFIED BY 'yoku0827' RETAIN CURRENT PASSWORD;
Query OK, 0 rows affected (0.00 sec)

mysql80 82> SHOW CREATE USER yoku0825;
+-------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+
| CREATE USER for yoku0825@%                                                                                                                                                                                                                                                                      |
+-------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+
| CREATE USER 'yoku0825'@'%' IDENTIFIED WITH 'caching_sha2_password' AS '$A$005$V=]bHk2\r~l8f\"\ZpB]DoKqTjmFtEz20yaFYDbvkXx0kOOCmGzuhCByA5lXPi5' REQUIRE NONE PASSWORD EXPIRE DEFAULT ACCOUNT UNLOCK PASSWORD HISTORY DEFAULT PASSWORD REUSE INTERVAL DEFAULT PASSWORD REQUIRE CURRENT DEFAULT |
+-------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+
1 row in set (0.00 sec)

SHOW CREATE USER には以前のパスワードっぽいものは見えない。デュアルパスワードになってるのかどうかも見えない。

mysql.user あたりを眺めていたら user_attributes というカラムに突っ込んでいるっぽかった(caching_sha2_passwordプラグインだと authentication_string カラムはやっぱり潰れちゃうねえ…)

mysql80 82> SELECT user, host, authentication_string, user_attributes FROM mysql.user WHERE user = 'yoku0825'\G
*************************** 1. row ***************************
                 user: yoku0825
                 host: %
~l8f"pB]DoKqTjmFtEz20yaFYDbvkXx0kOOCmGzuhCByA5lXPi5
      user_attributes: {"additional_password": "$A$005$]\u000ff|)Pd<\u0017I#(i\u0006 \t\u000bij[HzpqNoMwkaEO.dS2orkm5nQ/2Mgulxlh.8aumbjfYa8"}
1 row in set (0.00 sec)

mysql80 82> ALTER USER yoku0825 DISCARD OLD PASSWORD;
Query OK, 0 rows affected (0.02 sec)

mysql80 82> SELECT user, host, authentication_string, user_attributes FROM mysql.user WHERE user = 'yoku0825'\G
*************************** 1. row ***************************
                 user: yoku0825
                 host: %
~l8f"pB]DoKqTjmFtEz20yaFYDbvkXx0kOOCmGzuhCByA5lXPi5
      user_attributes: NULL
1 row in set (0.00 sec)

user_attributesの構造体はこのへんで、更新してるのはこのへん、使ってるフラグを管理してるのはこのへんなので、8.0.19現在ではデュアルパスワードとログインの失敗回数制御、 partial_revokes で使っているっぽい。

mysql80 7> SELECT user, host, authentication_string, user_attributes FROM mysql.user WHERE user = 'yoku0825'\G
*************************** 1. row ***************************
                 user: yoku0825
                 host: %
authentication_string: $A$005$LMJP\MS%cmy/Gv NIMCTPSdqYBmL2txa9mWq7ki0jYncHsWW99iyXk8CyD
      user_attributes: {"Restrictions": [{"Database": "mysql", "Privileges": ["SELECT"]}], "Password_locking": {"failed_login_attempts": 4, "password_lock_time_days": -1}, "additional_password": "$A$005$>PuHNir\n\t&\b\u0004B/Kf\u000b\u000e\u0010\u000bYZEIELtEpe7xFBDXqiQhC6EFNSOy.DQy.11P5iFl4v4"}
1 row in set (0.00 sec)

SELECTステートメントでデュアルパスワード持ってるアカウントだけを引っ張るならこうかな。

mysql80 7> SELECT user, host FROM mysql.user WHERE user_attributes->>'$.additional_password' IS NOT NULL;
+----------+------+
| user     | host |
+----------+------+
| yoku0825 | %    |
+----------+------+
1 row in set (0.00 sec)

2020/03/16

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

日々の覚書: シングルプライマリーモードだろうと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の方に回すっぽい。

謎が深まった。

登録: 投稿 ( Atom )

GA

2020/04/28

performance_schema.clone_progress が何となくそれっぽい順番に並ぶ理由

TL;DR

2020/04/07

MySQLのLAG()とかLEAD()に ERROR 1690 (22003): BIGINT UNSIGNED value is out of range と言われたら

TL;DR

2020/04/06

my.cnfの plugin_load の記法

TL;DR

2020/03/19

MySQL 8.0のデュアルパスワードを使った記念メモ

TL;DR

2020/03/16

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