2019年6月3日月曜日

第一印象 of MySQL Ripple

TL;DR

  • MySQL Ripple を試してそっと閉じたメモ。
  • 多分 こういう状態で使うんだと思う
    • マスターの部分はよしなに冗長化されていると思いねえ
    • (おそらく準同期レプリケーションで)マスターに直接スレーブをぶら下げると死んじゃうようなケース
    • あと、このMySQL Ripple自体もたぶん多段構成するんだろうな、とデフォルトのパラメーター(主に -ripple-master-port )を見て思う

ビルド

Dockerイメージで起動

$ docker run -v $PWD:/root/binlog mysql-ripple \
  --ripple-server-address=0.0.0.0 \
  --ripple-master-address=172.17.0.3 \
  --ripple-master-port=3306 \
  --ripple-datadir=/root/binlog
ホスト側にbinlogの保管ディレクトリーをマウントしてるのは深い意味はない。
-ripple-server-address は外側のIPアドレスなり0.0.0.0なりにしておかないと他所のホストからつつけない(デフォルトがlocalhostなので)
-ripple-master-port のデフォルトが3306 ではなく MySQL Rippleが使う51005なので、MySQL Ripple同士で多段構成するのが前提なのかも知れない。

コマンドラインクライアントで接続してみる

  • デフォルトのポートは51005
  • 接続すること自体はできるが、クエリーのパースはできないので、何かコマンドやSQLを叩いても大抵エラーになる
$ mysql -h172.17.0.4 -P51005
Welcome to the MySQL monitor.  Commands end with ; or \g.
Your MySQL connection id is 28
Server version: 5.6.0-ripple ripple version comment

mysql> status
ERROR 2013 (HY000): Lost connection to MySQL server during query

mysql> SHOW MASTER LOGS;
ERROR 2006 (HY000): MySQL server has gone away
No connection. Trying to reconnect...
Connection id:    28
Current database: *** NONE ***

ERROR 2013 (HY000): Lost connection to MySQL server during query

マスターにぶら下げてみる

  • gtid_mode= ON のみのサポート
  • master_log_file とか設定するオプションはないし、 gtid_mode != ON なところにぶら下げようとすると怒られる
I0603 09:05:54.490025     7 mysql_client_connection.cc:148] connected to host: 172.17.0.5, port: 3306
I0603 09:05:54.493810     7 mysql_master_session.cc:137] Connected to host: 172.17.0.5, port: 3306, server_id: 102, server_name:
W0603 09:05:54.495193     7 mysql_master_session.cc:197] master does not support semi sync
I0603 09:05:54.495231     7 mysql_master_session.cc:206] start replicating from 'f9874359-85da-11e9-a9fb-0242ac110003:0-0-4'
I0603 09:05:54.495659     7 mysql_master_session.cc:229] Master session entering main loop
E0603 09:05:54.495913     7 mysql_master_session.cc:296] Failed to read packet: Got error reading packet from server: The replication sender thread cannot start in AUTO_POSITION mode: this server has GTID_MODE = OFF instead of ON.
I0603 09:05:54.495939     7 binlog.cc:675] Connection closed last position binlog file: binlog.000000:1608, gtid: 0-0-4

スレーブをぶら下げてみる

  • こっちももちろん gtid_mode= ON のみのサポート
mysql> CHANGE MASTER TO master_host= '172.17.0.4', master_port= 51005, master_user= 'root' /* Non-GTID */;
Query OK, 0 rows affected, 2 warnings (0.04 sec)

mysql> start slave;
Query OK, 0 rows affected (0.01 sec)

mysql> show slave status\G
*************************** 1. row ***************************
               Slave_IO_State:
                  Master_Host: 172.17.0.4
                  Master_User: root
                  Master_Port: 51005
..
                Last_IO_Errno: 1593
                Last_IO_Error: The replication receiver thread cannot start because the master has GTID_MODE = ON and this server has GTID_MODE = OFF.
               Last_SQL_Errno: 0
               Last_SQL_Error:
..
  • gtid_mode >= ON_PERMISSIVE にして master_auto_position= 1 で設定すると動く
    • ちゃんとデータも転送されてきた。
mysql> stop slave;
Query OK, 0 rows affected (0.01 sec)

mysql> CHANGE MASTER TO master_auto_position = 1;
Query OK, 0 rows affected (0.01 sec)

mysql> start slave;
Query OK, 0 rows affected (0.01 sec)

mysql> SHOW SLAVE STATUS\G
*************************** 1. row ***************************
               Slave_IO_State: Waiting for master to send event
                  Master_Host: 172.17.0.4
                  Master_User: root
                  Master_Port: 51005
..
             Slave_IO_Running: Yes
            Slave_SQL_Running: Yes
..

MySQL Rippleの吐いたバイナリログファイル

  • よく訓練されたMySQLerにはわかると思うんだけど、フツーのバイナリログとちょっと違う。
    • ちなみにマスターはMySQL 5.7.26でbinlog_format= ROW
$ xxd binlog.000000
0000000: fe62 696e 0000 0000 0f53 b601 00f0 0000  .bin.....S......
0000010: 00f4 0000 0000 0004 0035 2e36 2e30 2d72  .........5.6.0-r
0000020: 6970 706c 6500 0000 0000 0000 0000 0000  ipple...........
..
00000f0: 0413 0400 0000 0000 0fea 0300 0073 0000  .............s..
0000100: 0067 0100 0000 0004 0035 2e37 2e32 362d  .g.......5.7.26-
0000110: 6c6f 6700 0000 0000 0000 0000 0000 0000  log.............
0000120: 0000 0000 0000 0000 0000 0000 0000 0000  ................
0000130: 0000 0000 0000 0000 0000 008a dcf4 5c13  ..............\.
0000140: 380d 0008 0012 0004 0404 0412 0000 5f00  8............._.
0000150: 041a 0800 0000 0808 0802 0000 000a 0a0a  ................
0000160: 2a2a 0012 3400 0000 0000 0096 53b6 0100  **..4.......S...
0000170: 2b00 0000 9201 0000 0000 ff00 0000 81dd  +...............
0000180: f45c 78c0 0e77 0815 e466 fa6c bd26 d9f5  .\x..w...f.l.&..
0000190: b607 3200 0000 b929 f7d4 aa18 4bdf 954e  ..2....)....K..N
  • マスターから取り出した生のバイナリログはこちら
$ xxd 935510b1506e-bin.000001
0000000: fe62 696e 8adc f45c 0fea 0300 0077 0000  .bin...\.....w..
0000010: 007b 0000 0001 0004 0035 2e37 2e32 362d  .{.......5.7.26-
0000020: 6c6f 6700 0000 0000 0000 0000 0000 0000  log.............
..
00000f0: 0000 0000 0000 0200 001f 0000 0000 0000  ................
0000100: 0120 00a0 5500 0000 0006 0373 7464 042d  . ..U......std.-
0000110: 002d 002d 000c 0164 3100 6431 0043 5245  .-.-...d1.d1.CRE
0000120: 4154 4520 4441 5441 4241 5345 2064 31e9  ATE DATABASE d1.
0000130: 5801 e9d4 dcf4 5c21 ea03 0000 4100 0000  X.....\!....A...
0000140: 7401 0000 0000 01f9 8743 5985 da11 e9a9  t........CY.....
0000150: fb02 42ac 1100 0302 0000 0000 0000 0002  ..B.............
0000160: 0100 0000 0000 0000 0200 0000 0000 0000  ................
0000170: 69f5 fb70 d4dc f45c 02ea 0300 0070 0000  i..p...\.....p..
0000180: 00e4 0100 0000 0004 0000 0000 0000 0002  ................
0000190: 0000 1f00 0000 0000 0001 2000 a055 0000  .......... ..U..
00001a0: 0000 0603 7374 6404 2d00 2d00 2d00 0c01  ....std.-.-.-...
00001b0: 6431 0064 3100 6372 6561 7465 2074 6162  d1.d1.create tab
00001c0: 6c65 2074 3120 286e 756d 2069 6e74 2c20  le t1 (num int,
00001d0: 7661 6c20 7661 7263 6861 7228 3332 2929  val varchar(32))
..
binlog_format= ROWでもフツーに記録されるはずのDDLが目視できない。 mysqlbinlog で食わせようとしても食えない。
どうやら暗号化されているっぽい。
$ docker run mysql-ripple --help | less
..
    -ripple_encryption_scheme (Encryption scheme used by ripple for local
      binlogs) type: int32 default: 255
..
-ripple-encryption-scheme=0 にすると暗号化されなくなって読めるようになる。
ただし rippled さん、結構バイナリログをバッファリングする(メモリー上にため込んで、 bin.000000 になかなか吐かない)ので、このあたりの動作を試して変だなと思ったらコンテナを止めてみるとフラッシュされたりする。
あと、 -ripple-encryption-scheme=255 で吐かせたバイナリログが残っているとそれに合わせて(?)同じ方式で暗号化し続けるっぽいので、 bin.000000 とかも削除して吸わせなおした方がいいと思われる。試すなら。
バイナリログを暗号化しておけるのは良いとして “MySQL Rippleからなら特に気にせず吸い上げられちゃう” ような気がするので、今のところあんまり期待してはいけないのかも知れない。難読化、くらいのつもりで。

2019年5月21日火曜日

エラーログに MY-010956 と MY-010957 が出まくるはなし

TL;DR

  • MySQL 8.0同士でレプリケーションを組んでいると、スレーブから以下のような MY-010956MY-010957 がぼこぼこエラーログに吐かれることがある
2019-05-20T14:25:17.121864+09:00 5 [Warning] [MY-010956] [Server] Invalid replication timestamps: original commit timestamp is more recent than the immediate commit timestamp. This may be an issue if delayed replication is active. Make sure that servers have their clocks set to the correct time. No further message will be emitted until after timestamps become valid again.
2019-05-20T14:25:17.177804+09:00 5 [Warning] [MY-010957] [Server] The replication timestamps have returned to normal values.

日々の覚書: MySQL 8.0.1でバイナリーログに original_commit_timestamp と immediate_commit_timestamp が追加された という記事で書いたように、MySQL 8.0からはバイナリーログのイベントに(正確には、トランザクションがコミットされた時にイベントに先行して記録されるGtid_log_eventに)マイクロ秒単位でタイムスタンプが記録される。
このタイムスタンプが、 original_commit_timestamp > immediate_commit_timestamp (スレーブで実行されたタイムスタンプよりマスターで実行されたタイムスタンプが未来)になってしまった時にエラーログに記録されるワーニングが MY-010956MY-010956 が記録された後に original_commit_timestamp <= immediate_commit_timestamp に戻った時に記録されるワーニングが MY-010957
ところで、運用しているMySQLの載っているマシンが「マイクロ秒単位で」正しいシステムクロックに設定されていることに自信のある方はいらっしゃるだろうか?
俺には自信はない、というか、いいとこ1桁ミリ秒単位ならズレるだろうとも思っている。ホストとクロックを定期的に同期するVMならまだしも(試してない)、NTPではこのくらいの精度は限界なんではなかろうか。
というわけで、だ。
$ date "+%s.%N" ### at master
1558337325.766668654

$ date "+%s.%N" ### at slave
1558337325.767114036
こんな状況は起こりえる。500usマスターが進んでいる。
この状態でマスターに更新を叩き込んで、 “500us以内にそのバイナリーログの適用が終わった場合” に MY-010956 が発火する(適用に500us以上かかれば、再びスレーブのタイムスタンプがマスターのそれを追い越すので何も起こらない。これが出まくったってことはそれくらいのレイテンシーで更新できてるってことで望ましいことではある)
そして MY-010956 が発火して以降( MY-010956 は一度発火すると、次にタイムスタンプの順序が戻る= MY-010957 が出るまでは連続で発火しない)、 “適用に500us以上かかったバイナリーログのイベント” が来ると MY-010957 が着火し、次に500us未満で適用が終わったイベントが…と、延々発火し得る。
きっちり一致させられないにしろ、マスターのシステムクロックを 進めれば 遅らせればいいのでは? と思ったりしたけど、いつNTPでじりじりと補正されるかわからないし、マスターを切り替えちゃったらまた出ることには変わりはないし、だいたいmysqldを起動したまま手で時刻を修正するとか嫌な予感しかしない。
ワーニングだし「これはどう考えても出る時は出る」って感じなので無視するのがいいんだろうけれど、 log_error_verbosity を1(エラーのみロギング、ワーニング以下を無視する)にするのはちょっと大雑把かなと思うし、かといってエラーログはでっかくなるし。
閾値を設定できるようにしませんか? というFeature Requestがこれ。
いいな(?)と思ったら “Affects me” ください…

2019年5月16日木曜日

MySQL 8.0のSHOW TABLE STATUSが全然更新されない件

TL;DR


空っぽのテーブルを用意する。
mysql80 111566> SHOW TABLE STATUS\G
*************************** 1. row ***************************
           Name: t1
         Engine: InnoDB
        Version: 10
     Row_format: Dynamic
           Rows: 0
 Avg_row_length: 0
    Data_length: 16384
Max_data_length: 0
   Index_length: 0
      Data_free: 0
 Auto_increment: NULL
    Create_time: 2019-05-16 15:41:52
    Update_time: NULL
     Check_time: NULL
      Collation: utf8mb4_0900_ai_ci
       Checksum: NULL
 Create_options:
        Comment:
1 row in set (0.00 sec)
データを1万行くらい入れる。
$ for n in $(seq 1 10000) ; do mysql80 -e "INSERT INTO t1 VALUES ($n, '')" d1; done

mysql80 111566> SELECT COUNT(*) FROM t1;
+----------+
| COUNT(*) |
+----------+
|    10000 |
+----------+
1 row in set (0.00 sec)
でも SHOW TABLE STATUS の結果は変わらない。。
mysql80 111566> SHOW TABLE STATUS\G
*************************** 1. row ***************************
           Name: t1
         Engine: InnoDB
        Version: 10
     Row_format: Dynamic
           Rows: 0
 Avg_row_length: 0
    Data_length: 16384
Max_data_length: 0
   Index_length: 0
      Data_free: 0
 Auto_increment: NULL
    Create_time: 2019-05-16 15:41:52
    Update_time: NULL
     Check_time: NULL
      Collation: utf8mb4_0900_ai_ci
       Checksum: NULL
 Create_options:
        Comment:
1 row in set (0.00 sec)
ちなみに SHOW CREATE TABLE の方の AUTO_INCREMENT の値はちゃんと増えてる。
mysql80 111566> SHOW CREATE TABLE t1\G
*************************** 1. row ***************************
       Table: t1
Create Table: CREATE TABLE `t1` (
  `num` bigint(20) unsigned NOT NULL AUTO_INCREMENT,
  `val` varchar(32) DEFAULT NULL,
  UNIQUE KEY `num` (`num`)
) ENGINE=InnoDB AUTO_INCREMENT=10001 DEFAULT CHARSET=utf8mb4 COLLATE=utf8mb4_0900_ai_ci
1 row in set (0.00 sec)
これはMySQL 8.0.3から information_schema_stats_expiry なるオプションが増えてからの挙動で、どうも information_schema.tables に含まれるほとんどの情報は mysql.table_stats テーブルにキャッシュされ、そのキャッシュがexpireされるまではずっとその値を使う様子( mysql.table_stats は隠れシステムテーブルなので、フツーにSQLを使っているだけだとそのテーブルは見えない)
mysql80 111566> SELECT * FROM mysql.table_stats;
ERROR 3554 (HY000): Access to data dictionary table 'mysql.table_stats' is rejected.
オプションにも書いてある通り、単位は秒でデフォルトは86400秒(= 24時間)
つまりどれだけテーブルを更新しようと、 information_schema.tablesSHOW TABLE STATUS の値は「最後に mysql.table_stats が更新されてから24時間」は全く変更されない(ように見える)
コード的には このへん でキャッシュがexpireされてるかとかそのへんを判定してて、元をたどって進んでいくと ここらへん でキャッシュを更新する処理に突入している。
(現在時刻 - キャッシュの更新時刻) > information_schema_stats_expiryになった場合はキャッシュを更新してその結果を、 information_schema_stats_expiry = 0 の場合はそもそも mysql.table_stats テーブルをキャッシュとして 使わない みたいな動作になるようだ。
mysql80 111566> SET SESSION information_schema_stats_expiry= 1;
Query OK, 0 rows affected (0.01 sec)

mysql80 111566> SHOW TABLE STATUS\G
*************************** 1. row ***************************
           Name: t1
         Engine: InnoDB
        Version: 10
     Row_format: Dynamic
           Rows: 10000
 Avg_row_length: 32
    Data_length: 327680
Max_data_length: 0
   Index_length: 0
      Data_free: 0
 Auto_increment: 10001
    Create_time: 2019-05-16 15:41:52
    Update_time: 2019-05-16 16:02:34
     Check_time: NULL
      Collation: utf8mb4_0900_ai_ci
       Checksum: NULL
 Create_options:
        Comment:
1 row in set (0.00 sec)
セッションスコープ, グローバルスコープが両方あるタイプの変数なので、監視用のセッションにだけ押し込んでおけばいいかと。
しかし SET_VAR 構文は使えないらしいので残念。

2019年4月26日金曜日

MySQL 8.0.16にCHECK制約が来て、NOT ENFORCEDなんてものまでついてきた

TL;DR

  • MySQL 8.0.16 についに CHECK制約 が実装された
  • NOT ENFORCED なんてオプションが “MySQLっぽい”
  • ちなみにCHECK制約の追加はオンラインDDL不可、引っぺがすのはできる

最初のFeature Requestから15年、ついにMySQL 8.0.16にCHECK制約が実装された。
アルファベットしか入ってほしくない val カラムに対して、ひらがなの “さん” とかが入力されるのを制限できる、みたいなヤーツ。
フツーの遊び方は @taka_yuki_04 さんの記事に書いてある(というかドキュメントにも書いてある)ので、俺は「既存のテーブルにCHECK制約」ででも遊んでみる。
まず、こんなテーブルがあるじゃろ?
mysql80 8> SELECT @@version;
+-----------+
| @@version |
+-----------+
| 8.0.16    |
+-----------+
1 row in set (0.00 sec)

mysql80 8> CREATE TABLE t1 (num serial, val varchar(32));
Query OK, 0 rows affected (0.02 sec)

mysql80 8> INSERT INTO t1 VALUES (1, 'one'), (2, 'two'), (3, 'さん');
Query OK, 3 rows affected (0.01 sec)
Records: 3  Duplicates: 0  Warnings: 0

mysql80 8> SELECT * FROM t1;
+-----+--------+
| num | val    |
+-----+--------+
|   1 | one    |
|   2 | two    |
|   3 | さん   |
+-----+--------+
3 rows in set (0.00 sec)
val にアルファベット以外( val RLIKE '^[a-z]+$' を満たさない)を入れさせないようなCHECK制約をかけようとするじゃろ?
mysql80 8> ALTER TABLE t1 ADD CHECK(val RLIKE '^[a-z]+$');
ERROR 3819 (HY000): Check constraint 't1_chk_1' is violated.
既に制約違反しているから ALTER TABLE がエラーになるんじゃ。
という訳で制約に違反している行を消すじゃろ?
mysql80 8> DELETE FROM t1 WHERE num = 3;
Query OK, 1 row affected (0.00 sec)

mysql80 8> SELECT * FROM t1;
+-----+------+
| num | val  |
+-----+------+
|   1 | one  |
|   2 | two  |
+-----+------+
2 rows in set (0.00 sec)
すると通るんじゃ。
mysql80 8> ALTER TABLE t1 ADD CHECK(val RLIKE '^[a-z]+$');
Query OK, 2 rows affected (0.03 sec)
Records: 2  Duplicates: 0  Warnings: 0

mysql80 8> SHOW CREATE TABLE t1\G
*************************** 1. row ***************************
       Table: t1
Create Table: CREATE TABLE `t1` (
  `num` bigint(20) unsigned NOT NULL AUTO_INCREMENT,
  `val` varchar(32) DEFAULT NULL,
  UNIQUE KEY `num` (`num`),
  CONSTRAINT `t1_chk_1` CHECK (regexp_like(`val`,_utf8mb4'^[a-z]+$'))
) ENGINE=InnoDB AUTO_INCREMENT=4 DEFAULT CHARSET=utf8mb4 COLLATE=utf8mb4_0900_ai_ci
1 row in set (0.00 sec)
CHECK制約があれば、 “さん” はそもそも入らないんじゃ。
mysql80 8> INSERT INTO t1 VALUES (3, 'さん');
ERROR 3819 (HY000): Check constraint 't1_chk_1' is violated.

mysql80 8> SELECT * FROM t1;
+-----+------+
| num | val  |
+-----+------+
|   1 | one  |
|   2 | two  |
+-----+------+
2 rows in set (0.00 sec)
Σ(゚д゚lll) フツーのDBMSっぽい!
しかしまあ、MySQLっぽいと言われる謎の NOT ENFORCED なんて句がついてきて
mysql80 8> ALTER TABLE t1 DROP CHECK t1_chk_1;
Query OK, 0 rows affected (0.01 sec)
Records: 0  Duplicates: 0  Warnings: 0

mysql80 8> ALTER TABLE t1 ADD CHECK(val RLIKE '^[a-z]+$') NOT ENFORCED;
Query OK, 0 rows affected (0.01 sec)
Records: 0  Duplicates: 0  Warnings: 0

mysql80 8> SHOW CREATE TABLE t1\G
*************************** 1. row ***************************
       Table: t1
Create Table: CREATE TABLE `t1` (
  `num` bigint(20) unsigned NOT NULL AUTO_INCREMENT,
  `val` varchar(32) DEFAULT NULL,
  UNIQUE KEY `num` (`num`),
  CONSTRAINT `t1_chk_1` CHECK (regexp_like(`val`,_utf8mb4'^[a-z]+$')) /*!80016 NOT ENFORCED */
) ENGINE=InnoDB AUTO_INCREMENT=4 DEFAULT CHARSET=utf8mb4 COLLATE=utf8mb4_0900_ai_ci
1 row in set (0.00 sec)

mysql80 8> INSERT INTO t1 VALUES (3, 'さん');
Query OK, 1 row affected (0.01 sec)

mysql80 8> SELECT * FROM t1;
+-----+--------+
| num | val    |
+-----+--------+
|   1 | one    |
|   2 | two    |
|   3 | さん   |
+-----+--------+
3 rows in set (0.00 sec)
:(;゙゚’ω゚’): なんと入る
誰得なんだろう…せめてワーニングとか出てくれるといいんだけどな。。
ところで、 ALTER TABLE でCHECK制約を追加するということは、それってオンラインでできるの的な疑問が湧いてくるんですが、2019年4月25日 20時10分02秒 JST 現在、InnoDBのオンラインDDL関連のページにはCHECK制約については特に記載なし。
mysql80 20> ALTER TABLE t1 ADD CHECK ('ワレワレ' <> '宇宙人'), ALGORITHM= INSTANT;
ERROR 1845 (0A000): ALGORITHM=INSTANT is not supported for this operation. Try ALGORITHM=COPY.

mysql80 20> ALTER TABLE t1 ADD CHECK ('ワレワレ' <> '宇宙人'), ALGORITHM= INPLACE;
ERROR 1845 (0A000): ALGORITHM=INPLACE is not supported for this operation. Try ALGORITHM=COPY.

mysql80 20> ALTER TABLE t1 ADD CHECK ('ワレワレ' <> '宇宙人'), ALGORITHM= COPY, LOCK= NONE;
ERROR 1846 (0A000): LOCK=NONE is not supported. Reason: COPY algorithm requires a lock. Try LOCK=SHARED.

mysql80 20> ALTER TABLE t1 ADD CHECK ('ワレワレ' <> '宇宙人'), ALGORITHM= COPY, LOCK= SHARED;
Query OK, 3 rows affected (0.04 sec)
Records: 3  Duplicates: 0  Warnings: 0

mysql80 20> ALTER TABLE t1 ADD CHECK ('ワレワレ' <> '宇宙人'), ALGORITHM= COPY, LOCK= EXCLUSIVE;
Query OK, 3 rows affected (0.03 sec)
Records: 3  Duplicates: 0  Warnings: 0
試した感じ、 ALGORITHM= COPY (テーブルコピー)で LOCK= SHARED (共有ロック、読めるけど書けない)か LOCK = EXCLUSIVE (排他ロック、読めないし書けない)しか選べない模様。。
このへん、せめてINPLACEとかできるようになるといいな(いくら全行チェックが必要とはいえ、テーブルコピーする必要はないはず…)