gho-stでスレーブからバイナリーログを食いながらインデックスを足してみる

TL;DR

• マスターから食ってもスレーブから食っても動作が変わっているような気はしない
• 能動的なスレーブの遅延監視を入れるなら --throttle-control-replicas を自分で入れないといけない

---

昨日 の続き。
昨日の時点では pt-online-schema-change っぽくマスターに接続してバイナリーログを吸いながらマスターに食わせたけれど、今日はデフォルトの「スレーブに接続してバイナリーログを吸ってマスターに食わせる」をやってみる。

早速。

$ master/my sqlslap --auto-generate-sql --auto-generate-sql-execute-number=100000 --auto-generate-sql-guid-primary

$ gh-ost --database=mysqlslap --table=t1 --alter="ADD KEY (intcol1)" --host=127.0.0.1 --port=21801 --user=msandbox --password=msandbox
2019-02-26 12:31:43 FATAL 127.0.0.1:21801 must have log_slave_updates enabled for executing migration

転けた。
log_slave_updates がONでないといけない（8.0からデフォルトでONになったんだけどそういえばこれは5.7.25でテストしている）

有効にしてから再起動。

( ´-｀).oO（ log_slave_updates は mysqld の再起動が必要だから、有効にしてない環境だとここで pt-online-schema-change か --allow-on-master にするしかなくなるな…

$ gh-ost --database=mysqlslap --table=t1 --alter="ADD KEY (intcol1)" --host=127.0.0.1 --port=
21801 --user=msandbox --password=msandbox
[2019/02/26 12:39:08] [info] binlogsyncer.go:133 create BinlogSyncer with config {99999 mysql 127.0.0.1 21801 msandbox    false false
<nil> false UTC true 0 0s 0s 0 false}
[2019/02/26 12:39:08] [info] binlogsyncer.go:354 begin to sync binlog from position (mysql-bin.000002, 2215735)
[2019/02/26 12:39:08] [info] binlogsyncer.go:203 register slave for master server 127.0.0.1:21801
[2019/02/26 12:39:08] [info] binlogsyncer.go:723 rotate to (mysql-bin.000002, 2215735)
2019-02-26 12:39:08 ERROR parsing time "" as "2006-01-02T15:04:05.999999999Z07:00": cannot parse "" as "2006"
# Migrating `mysqlslap`.`t1`; Ghost table is `mysqlslap`.`_t1_gho`
[2019/02/26 12:39:08] [info] binlogsyncer.go:203 register slave for master server 127.0.0.1:21801
[2019/02/26 12:39:08] [info] binlogsyncer.go:723 rotate to (mysql-bin.000002, 2215735)
2019-02-26 12:39:08 ERROR parsing time "" as "2006-01-02T15:04:05.999999999Z07:00": cannot parse "" as "2006"
# Migrating `mysqlslap`.`t1`; Ghost table is `mysqlslap`.`_t1_gho`
# Migrating 163-44-175-117:21800; inspecting 163-44-175-117:21801; executing on 163-44-175-117
# Migration started at Tue Feb 26 12:39:07 +0900 2019
# chunk-size: 1000; max-lag-millis: 1500ms; dml-batch-size: 10; max-load: ; critical-load: ; nice-ratio: 0.000000
# throttle-additional-flag-file: /tmp/gh-ost.throttle
# Serving on unix socket: /tmp/gh-ost.mysqlslap.t1.sock
# Migrating `mysqlslap`.`t1`; Ghost table is `mysqlslap`.`_t1_gho`
# Migrating 163-44-175-117:21800; inspecting 163-44-175-117:21801; executing on 163-44-175-117
# Migration started at Tue Feb 26 12:39:07 +0900 2019
# chunk-size: 1000; max-lag-millis: 1500ms; dml-batch-size: 10; max-load: ; critical-load: ; nice-ratio: 0.000000
# throttle-additional-flag-file: /tmp/gh-ost.throttle
# Serving on unix socket: /tmp/gh-ost.mysqlslap.t1.sock
Copy: 0/5160 0.0%; Applied: 0; Backlog: 0/1000; Time: 0s(total), 0s(copy); streamer: mysql-bin.000002:2226774; State: migrating; ETA: N/A
Copy: 0/0 100.0%; Applied: 0; Backlog: 0/1000; Time: 0s(total), 0s(copy); streamer: mysql-bin.000002:2226774; State: migrating; ETA: due
CREATE TABLE `_t1_gho` (
  `id` varchar(36) NOT NULL,
  `intcol1` int(32) DEFAULT NULL,
  `charcol1` varchar(128) DEFAULT NULL,
  PRIMARY KEY (`id`),
  KEY `intcol1` (`intcol1`)
) ENGINE=InnoDB DEFAULT CHARSET=latin1
[2019/02/26 12:39:08] [info] binlogsyncer.go:164 syncer is closing...
[2019/02/26 12:39:08] [error] binlogstreamer.go:77 close sync with err: sync is been closing...
[2019/02/26 12:39:08] [info] binlogsyncer.go:179 syncer is closed
# Done

なんか ERROR parsing time "" as "2006-01-02T15:04:05.999999999Z07:00": cannot parse "" as "2006" が気になるんだけどなにこれ……今度ソース読もう。

マスターへのクエリーは、 マスターに直接接続してバイナリーログを食った時 とほぼ変わらず。
バイナリーログを食うもとになったスレーブでも、指定していない方のスレーブでも特に SHOW SLAVE STATUS は叩かれていないので、やっぱり --throttle-control-replicas で指定しない限りはスレーブのラグは計算してくれない様子。

$ gh-ost --database=mysqlslap --table=t1 --alter="ADD KEY (intcol1)" --host=127.0.0.1 --port=
21801 --user=msandbox --password=msandbox --execute
[2019/02/26 14:14:36] [info] binlogsyncer.go:133 create BinlogSyncer with config {99999 mysql 127.0.0.1 21801 msandbox    false false
<nil> false UTC true 0 0s 0s 0 false}
[2019/02/26 14:14:36] [info] binlogsyncer.go:354 begin to sync binlog from position (mysql-bin.000003, 8755243)
[2019/02/26 14:14:36] [info] binlogsyncer.go:203 register slave for master server 127.0.0.1:21801
[2019/02/26 14:14:36] [info] binlogsyncer.go:723 rotate to (mysql-bin.000003, 8755243)
2019-02-26 14:14:36 ERROR parsing time "" as "2006-01-02T15:04:05.999999999Z07:00": cannot parse "" as "2006"
# Migrating `mysqlslap`.`t1`; Ghost table is `mysqlslap`.`_t1_gho`
# Migrating 163-44-175-117:21800; inspecting 163-44-175-117:21801; executing on 163-44-175-117
# Migration started at Tue Feb 26 14:14:36 +0900 2019
# chunk-size: 1000; max-lag-millis: 1500ms; dml-batch-size: 10; max-load: ; critical-load: ; nice-ratio: 0.000000
# throttle-additional-flag-file: /tmp/gh-ost.throttle
# Serving on unix socket: /tmp/gh-ost.mysqlslap.t1.sock
Copy: 0/3316 0.0%; Applied: 0; Backlog: 0/1000; Time: 0s(total), 0s(copy); streamer: mysql-bin.000003:8765344; State: migrating; ETA: N/A
Copy: 0/3316 0.0%; Applied: 0; Backlog: 415/1000; Time: 1s(total), 1s(copy); streamer: mysql-bin.000003:8947956; State: migrating; ET$: N/A
Copy: 3337/3337 100.0%; Applied: 529; Backlog: 0/1000; Time: 2s(total), 1s(copy); streamer: mysql-bin.000003:9305011; State: migratin$; ETA: due
Copy: 3337/3337 100.0%; Applied: 529; Backlog: 54/1000; Time: 2s(total), 1s(copy); streamer: mysql-bin.000003:9736765; State: migrati$g; ETA: due
# Migrating `mysqlslap`.`t1`; Ghost table is `mysqlslap`.`_t1_gho`
# Migrating 163-44-175-117:21800; inspecting 163-44-175-117:21801; executing on 163-44-175-117
# Migration started at Tue Feb 26 14:14:36 +0900 2019
# throttle-additional-flag-file: /tmp/gh-ost.throttle
# Serving on unix socket: /tmp/gh-ost.mysqlslap.t1.sock
Copy: 0/3316 0.0%; Applied: 0; Backlog: 0/1000; Time: 0s(total), 0s(copy); streamer: mysql-bin.000003:8765344; State: migrating; ETA: N/A
Copy: 0/3316 0.0%; Applied: 0; Backlog: 415/1000; Time: 1s(total), 1s(copy); streamer: mysql-bin.000003:8947956; State: migrating; ETA: N/A
Copy: 3337/3337 100.0%; Applied: 529; Backlog: 0/1000; Time: 2s(total), 1s(copy); streamer: mysql-bin.000003:9305011; State: migrating; ETA: due
Copy: 3337/3337 100.0%; Applied: 529; Backlog: 54/1000; Time: 2s(total), 1s(copy); streamer: mysql-bin.000003:9736765; State: migrating; ETA: due
# Migrating `mysqlslap`.`t1`; Ghost table is `mysqlslap`.`_t1_gho`
# Migrating 163-44-175-117:21800; inspecting 163-44-175-117:21801; executing on 163-44-175-117
# Migration started at Tue Feb 26 14:14:36 +0900 2019
# chunk-size: 1000; max-lag-millis: 1500ms; dml-batch-size: 10; max-load: ; critical-load: ; nice-ratio: 0.000000
# throttle-additional-flag-file: /tmp/gh-ost.throttle
# Serving on unix socket: /tmp/gh-ost.mysqlslap.t1.sock
Copy: 3337/3337 100.0%; Applied: 582; Backlog: 0/1000; Time: 3s(total), 1s(copy); streamer: mysql-bin.000003:9754093; State: migrating; ETA: due
[2019/02/26 14:14:39] [info] binlogsyncer.go:164 syncer is closing...
[2019/02/26 14:14:39] [error] binlogstreamer.go:77 close sync with err: sync is been closing...
[2019/02/26 14:14:39] [info] binlogsyncer.go:179 syncer is closed
# Done

今のところ雑に放置している # throttle-additional-flag-file: /tmp/gh-ost.throttle とか # Serving on unix socket: /tmp/gh-ost.mysqlslap.t1.sock とか、対話的にできるのがいいんだろうな、って気配は感じる。

あとやっぱり（ローカルで大した負荷かけてないとはいえ）トリガー使っている pt-online-schema-change より軽いような気がするのですよ、はふん。

​