GA

2020/04/28

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

TL;DR

  • datadir/#clone/#view_progress という平文のファイルがこのテーブルの本体だから
俺は途中まで作業をしていて聞き逃したんですけど、 Open Source Conference 2020 Online/Spring の かじやまさんのセッション でそんな話題が挙がったらしく。






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 を実行した側) であってドナー (データを供給している側) ではない。
そもそもよく考えれば、 PERFORMANCE_SCHEMA ストレージエンジンは「統計情報格納専用のインメモリストレージエンジン」だと散々聞かされてきたのに、コイツは揮発しない( CLONE INSTANCE FROM はそもそもデータをコピーしてきたあと自動で再起動するし、そのあと何度 mysqld の停止起動を挟んでもこのテーブルは同じ値を返し続ける）
さてさて…取り敢えずソースコードをテーブル名の “clone_progress” で検索してみた。
変数の名前が CLONE_VIEW_PROGRESS_FILE でなんかもうここでオチが見えた。
Progress_pfs::Data::write で書いてるんだろうけど、 std::ofstream でファイルを開いて書いてるだけ。
ファイルを読み出してテーブルとして見せるところで頑張っているっぽい。
となるとやることは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 になりました。ためしてみましょう！
​
投稿者 時刻: 0 件のコメント :
ラベル: ,

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 |
..
結果が返ってくるようになった。良かった良かった。
​
投稿者 時刻: 0 件のコメント :
ラベル: ,

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 みたいに
…言いたいことは全部書いてしまった気がするので、ドキュメントを読んでつらつらと。
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 はプラグインをロードするタイミングが違うだけみたい。
(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 ()

(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
​
投稿者 時刻: 0 件のコメント :
ラベル:
登録: 投稿 ( Atom )