2019/02/26

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 より軽いような気がするのですよ、はふん。

2019/02/25

第一印象 of gh-ost

TL;DR

ギフハフもすなる gh-ost といふものをゼロハチニーゴーもしてみむとしてするなり
- github/gh-ost: GitHub’s Online Schema Migrations for MySQL
インストールの仕方と取り敢えず試してみての感想

インストール

releases にrpmパッケージもあるので yum でサクっと入れた。
- コマンド1個だけが入っているとてもシンプルなパッケージ…

$ sudo yum install -y https://github.com/github/gh-ost/releases/download/v1.0.48/gh-ost-1.0.48-1.x86_64.rpm

$ rpm -ql gh-ost
/usr/bin/gh-ost

テスト

ドキュメントを一切合切読まずに試してみる。
MySQL::Sandbox と mysqlslap でテキトーなテーブル定義にテキトーなクエリーを流させておく。 general_log はオンにしてみた。

$ make_replication_sandbox 5.7.25
$ cd ~/sandboxes/rsandbox_5_7_25/
$ ./m

master [localhost] {msandbox} ((none)) > SET GLOBAL general_log= 1;
Query OK, 0 rows affected (0.00 sec)

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

何もオプションを指定せずに打ってみた（何故）

$ gh-ost
2019-02-25 17:18:10 FATAL --database must be provided and database name must not be empty

--database が要ることは分かった。

$ gh-ost --database=mysqlslap
2019-02-25 17:18:45 FATAL --table must be provided and table name must not be empty

--table も要ることは分かった。

$ gh-ost --database=mysqlslap --table=t1
2019-02-25 17:19:10 FATAL --alter must be provided and statement must not be empty

--alter も要ることはわかった。これは pt-online-schema-change と一緒で、ALTERオペレーションの部分だけを書けばいいのかしらん。

$ gh-ost --database=mysqlslap --table=t1 --alter="ADD KEY (intcol1)"
2019-02-25 17:20:17 FATAL dial tcp 127.0.0.1:3306: connect: connection refused

ここで初めて接続エラーになった。たぶん --host と --port と --user と --password でイケるだろ、と思う。

$ gh-ost --database=mysqlslap --table=t1 --alter="ADD KEY (intcol1)" --host=127.0.0.1 --port=21800 --user=msandbox --password=msandbox
2019-02-25 17:21:14 FATAL No PRIMARY nor UNIQUE key found in table! Bailing out

テーブルに PRIMARY KEY または UNIQUE KEY がないと適用できない。
確かに binlog_format= ROW なバイナリログを食わせて、ALTER適用済のテンポラリーテーブル（gh-ost的には「ゴーストテーブル」というらしい）を作るにはないと具合が悪い。

2019-02-25T08:23:03.835939Z        11 Connect   msandbox@localhost on mysqlslap using TCP/IP
..
2019-02-25T08:23:03.838067Z        11 Query     show /* gh-ost */ grants for current_user()
2019-02-25T08:23:03.838364Z        11 Query     select @@global.log_bin, @@global.binlog_format
2019-02-25T08:23:03.838580Z        11 Query     select @@global.binlog_row_image
2019-02-25T08:23:03.839329Z        12 Connect   msandbox@localhost on information_schema using TCP/IP
2019-02-25T08:23:03.839500Z        12 Query     SELECT @@max_allowed_packet
2019-02-25T08:23:03.839623Z        12 Query     SET autocommit=true
2019-02-25T08:23:03.839737Z        12 Query     SET NAMES utf8mb4
2019-02-25T08:23:03.839966Z        12 Query     show slave status
2019-02-25T08:23:03.840312Z        12 Quit
2019-02-25T08:23:03.840475Z        11 Query     show /* gh-ost */ table status from `mysqlslap` like 't1'
2019-02-25T08:23:03.841162Z        11 Query     SELECT
..
                FROM INFORMATION_SCHEMA.KEY_COLUMN_USAGE
                WHERE
                                REFERENCED_TABLE_NAME IS NOT NULL
                                AND ((TABLE_SCHEMA='mysqlslap' AND TABLE_NAME='t1')
                                        OR (REFERENCED_TABLE_SCHEMA='mysqlslap' AND REFERENCED_TABLE_NAME='t1')
                                )
2019-02-25T08:23:03.851679Z        11 Query     SELECT
..
    FROM INFORMATION_SCHEMA.COLUMNS INNER JOIN (
      SELECT
..
      FROM INFORMATION_SCHEMA.STATISTICS
      WHERE
                                NON_UNIQUE=0
                                AND TABLE_SCHEMA = 'mysqlslap'
        AND TABLE_NAME = 't1'
      GROUP BY TABLE_SCHEMA, TABLE_NAME, INDEX_NAME
    ) AS UNIQUES
    ON (
      COLUMNS.COLUMN_NAME = UNIQUES.FIRST_COLUMN_NAME
    )
    WHERE
      COLUMNS.TABLE_SCHEMA = 'mysqlslap'
      AND COLUMNS.TABLE_NAME = 't1'
    ORDER BY
..
2019-02-25T08:23:03.853012Z        11 Quit

外部キー制約がついてるとこの辺で判定されそうな感じ。
mysqlslap が PRIMARY KEY を作るようにオプションを追加してやり直し。

$ 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=21800 --user=msandbox --password=msandbox

2019-02-25 17:28:29 FATAL It seems like this migration attempt to run directly on master. Preferably it would be executed on a replica (and this reduces load from the master). To proceed please provide --allow-on-master. Inspector config=127.0.0.1:21800, user=msandbox, usingTLS=false, applier config=127.0.0.1:21800, user=msandbox, usingTLS=false

直接マスターに接続するなら --allow-on-master 使えってことらしい。
バイナリーログはマスターから食ってもスレーブから食っても一緒なんでは？と思うけれどチートシートを見る感じ、デフォルトはスレーブでバイナリーログを食ってマスターにINSERT、のようだ。


$ gh-ost --database=mysqlslap --table=t1 --alter="ADD KEY (intcol1)" --host=127.0.0.1 --port=21800 --user=msandbox --password=msandbox --allow-on-master

[2019/02/25 17:32:48] [info] binlogsyncer.go:133 create BinlogSyncer with config {99999 mysql 127.0.0.1 21800 msandbox    false false <nil> false UTC true 0 0s 0s 0 false}

[2019/02/25 17:32:48] [info] binlogsyncer.go:354 begin to sync binlog from position (mysql-bin.000001, 34947374)

[2019/02/25 17:32:48] [info] binlogsyncer.go:203 register slave for master server 127.0.0.1:21800

[2019/02/25 17:32:48] [info] binlogsyncer.go:723 rotate to (mysql-bin.000001, 34947374)

# Migrating `mysqlslap`.`t1`; Ghost table is `mysqlslap`.`_t1_gho`

# Migrating 163-44-175-117:21800; inspecting 163-44-175-117:21800; executing on 163-44-175-117

# Migration started at Mon Feb 25 17:32:47 +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:21800; executing on 163-44-175-117

# Migration started at Mon Feb 25 17:32:47 +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/6772 0.0%; Applied: 0; Backlog: 1/1000; Time: 0s(total), 0s(copy); streamer: mysql-bin.000001:34958571; State: migrating; ETA: N/A

Copy: 0/0 100.0%; Applied: 0; Backlog: 1/1000; Time: 0s(total), 0s(copy); streamer: mysql-bin.000001:34958571; 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/25 17:32:48] [info] binlogsyncer.go:164 syncer is closing...

[2019/02/25 17:32:48] [error] binlogstreamer.go:77 close sync with err: sync is been closing...

[2019/02/25 17:32:48] [info] binlogsyncer.go:179 syncer is closed

# Done

master [localhost] {msandbox} (mysqlslap) > show create table t1\G

*************************** 1. row ***************************

       Table: t1

Create Table: CREATE TABLE `t1` (

  `id` varchar(36) NOT NULL,

  `intcol1` int(32) DEFAULT NULL,

  `charcol1` varchar(128) DEFAULT NULL,

  PRIMARY KEY (`id`)

) ENGINE=InnoDB DEFAULT CHARSET=latin1

1 row in set (0.00 sec)

動いたっぽい。
この時点では dry-run で、実行はされていない（って出力してくれてもいいのに）
- ちょくちょく pt-online-schema-change と動きが同じで嬉しい。
この時点では SHOW PROCESSLIST や SHOW SLAVE HOSTS などマスターからスレーブを探せるようなSQLは叩いていない。
# chunk-size: 1000; max-lag-millis: 1500ms; dml-batch-size: 10; max-load: ; critical-load: ; nice-ratio: 0.000000 あたりは、 --help を見た感じ負荷に合わせてよしなに指定するのであろう。
ちなみにこの時点で binlog_format <> ROW の場合はエラーが出る（ FATAL You must be using ROW binlog format. I can switch it for you, provided --switch-to-rbr and that 127.0.0.1:21800 doesn't have replicas ）


$ gh-ost --database=mysqlslap --table=t1 --alter="ADD KEY (intcol1)" --host=127.0.0.1 --port=21800 --user=msandbox --password=msandbox --allow-on-master --execute

[2019/02/25 17:38:56] [info] binlogsyncer.go:133 create BinlogSyncer with config {99999 mysql 127.0.0.1 21800 msandbox    false false <nil> false UTC true 0 0s 0s 0 false}

[2019/02/25 17:38:56] [info] binlogsyncer.go:354 begin to sync binlog from position (mysql-bin.000001, 80752389)

[2019/02/25 17:38:56] [info] binlogsyncer.go:203 register slave for master server 127.0.0.1:21800

[2019/02/25 17:38:56] [info] binlogsyncer.go:723 rotate to (mysql-bin.000001, 80752389)

# Migrating `mysqlslap`.`t1`; Ghost table is `mysqlslap`.`_t1_gho`

# Migrating 163-44-175-117:21800; inspecting 163-44-175-117:21800; executing on 163-44-175-117

# Migration started at Mon Feb 25 17:38:56 +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/3346 0.0%; Applied: 0; Backlog: 1/1000; Time: 0s(total), 0s(copy); streamer: mysql-bin.000001:80762720; State: migrating; ETA: N/A

Copy: 2000/3346 59.8%; Applied: 179; Backlog: 0/1000; Time: 1s(total), 1s(copy); streamer: mysql-bin.000001:81254459; State: migrating; ETA: 0s

Copy: 3365/3346 100.6%; Applied: 359; Backlog: 1/1000; Time: 2s(total), 2s(copy); streamer: mysql-bin.000001:81644106; State: migrating; ETA: due

Copy: 3365/3365 100.0%; Applied: 424; Backlog: 0/1000; Time: 2s(total), 2s(copy); streamer: mysql-bin.000001:81700141; State: migrating; ETA: due

Copy: 3365/3365 100.0%; Applied: 426; Backlog: 10/1000; Time: 3s(total), 2s(copy); streamer: mysql-bin.000001:81709653; State: migrating; ETA: due

# Migrating `mysqlslap`.`t1`; Ghost table is `mysqlslap`.`_t1_gho`

# Migrating 163-44-175-117:21800; inspecting 163-44-175-117:21800; executing on 163-44-175-117

# Migration started at Mon Feb 25 17:38:56 +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: 3365/3365 100.0%; Applied: 435; Backlog: 0/1000; Time: 3s(total), 2s(copy); streamer: mysql-bin.000001:81714074; State: migrating; ETA: due

[2019/02/25 17:39:00] [info] binlogsyncer.go:164 syncer is closing...

[2019/02/25 17:39:00] [error] binlogstreamer.go:77 close sync with err: sync is been closing...

[2019/02/25 17:39:00] [info] binlogsyncer.go:179 syncer is closed

# Done

流れ終わりは、した。


master [localhost] {msandbox} (mysqlslap) > SHOW CREATE TABLE t1\G

*************************** 1. row ***************************

       Table: t1

Create Table: CREATE TABLE `t1` (

  `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

1 row in set (0.00 sec)

slave1 [localhost] {msandbox} (mysqlslap) > SHOW CREATE TABLE t1\G

*************************** 1. row ***************************

       Table: t1

Create Table: CREATE TABLE `t1` (

  `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

1 row in set (0.01 sec)

$ less ~/sandboxes/rsandbox_5_7_25/node1/data/163-44-175-117.log

..

マスターでもスレーブでもインデックスが足されているのはいいけれど、どうもgeneral_logを見る限り Seconds_Behind_Master を見に来ている気配はない。。
- これはスレーブからバイナリーログを受け取る設定にしている時に、その接続先で SHOW SLAVE STATUS 叩いたり --throttle-control-replicas を指定した時にだけその先で叩いてくれるのかしらん。謎。


$ cat -v ~/sandboxes/rsandbox_5_7_25/master/data/163-44-175-117.log | grep "gh-ost"

..

2019-02-25T08:38:56.880696Z        41 Query     show /* gh-ost */ grants for current_user()

2019-02-25T08:38:56.882845Z        41 Query     show /* gh-ost */ table status from `mysqlslap` like 't1'

2019-02-25T08:38:56.902645Z        41 Query     explain select /* gh-ost */ * from `mysqlslap`.`t1` where 1=1

2019-02-25T08:38:56.907683Z        41 Query     show /* gh-ost readCurrentBinlogCoordinates */ master status

2019-02-25T08:38:56.917044Z        41 Query     show /* gh-ost */ table status from `mysqlslap` like '_t1_gho'

2019-02-25T08:38:56.917296Z        41 Query     show /* gh-ost */ table status from `mysqlslap` like '_t1_del'

2019-02-25T08:38:56.917506Z        41 Query     drop /* gh-ost */ table if exists `mysqlslap`.`_t1_ghc`

2019-02-25T08:38:56.920110Z        41 Query     create /* gh-ost */ table `mysqlslap`.`_t1_ghc` (

2019-02-25T08:38:56.931295Z        41 Query     create /* gh-ost */ table `mysqlslap`.`_t1_gho` like `mysqlslap`.`t1`

2019-02-25T08:38:56.946308Z        41 Query     alter /* gh-ost */ table `mysqlslap`.`_t1_gho` ADD KEY (intcol1)

2019-02-25T08:38:56.959104Z        41 Query     insert /* gh-ost */ into `mysqlslap`.`_t1_ghc`

2019-02-25T08:38:56.962483Z        41 Query     insert /* gh-ost */ into `mysqlslap`.`_t1_ghc`

2019-02-25T08:38:56.965301Z        41 Query     insert /* gh-ost */ into `mysqlslap`.`_t1_ghc`

2019-02-25T08:38:56.972091Z        41 Query     select /* gh-ost `mysqlslap`.`t1` */ `id`

2019-02-25T08:38:56.972536Z        47 Query     select /* gh-ost `mysqlslap`.`t1` */ `id`

2019-02-25T08:38:56.973362Z        47 Query     insert /* gh-ost */ into `mysqlslap`.`_t1_ghc`

2019-02-25T08:38:56.973989Z        41 Query     replace /* gh-ost `mysqlslap`.`_t1_gho` */ into

2019-02-25T08:38:56.977606Z        47 Query     replace /* gh-ost `mysqlslap`.`_t1_gho` */ into

2019-02-25T08:38:56.982191Z        41 Query     replace /* gh-ost `mysqlslap`.`_t1_gho` */ into

2019-02-25T08:38:56.986080Z        47 Query     replace /* gh-ost `mysqlslap`.`_t1_gho` */ into

...

2019-02-25T08:38:59.213685Z        66 Query     replace /* gh-ost `mysqlslap`.`_t1_gho` */ into

2019-02-25T08:38:59.221449Z        67 Query     select  /* gh-ost `mysqlslap`.`t1` iteration:4 */

2019-02-25T08:38:59.221871Z        66 Query     select /* gh-ost `mysqlslap`.`t1` iteration:4 */ `id`

2019-02-25T08:38:59.222528Z        67 Query     replace /* gh-ost `mysqlslap`.`_t1_gho` */ into

2019-02-25T08:38:59.222842Z        66 Query     insert /* gh-ost */ into `mysqlslap`.`_t1_ghc`

2019-02-25T08:38:59.228316Z        67 Query     replace /* gh-ost `mysqlslap`.`_t1_gho` */ into

2019-02-25T08:38:59.241504Z        66 Query     select get_lock('gh-ost.66.lock', 0)

2019-02-25T08:38:59.242713Z        67 Query     show /* gh-ost */ table status from `mysqlslap` like '_t1_del'

2019-02-25T08:38:59.246396Z        67 Query     create /* gh-ost */ table `mysqlslap`.`_t1_del` (

2019-02-25T08:38:59.272465Z        69 Query     insert /* gh-ost */ into `mysqlslap`.`_t1_ghc`

2019-02-25T08:38:59.272797Z        66 Query     lock /* gh-ost */ tables `mysqlslap`.`t1` write, `mysqlslap`.`_t1_del` write

2019-02-25T08:38:59.276302Z        67 Query     insert /* gh-ost */ into `mysqlslap`.`_t1_ghc`

2019-02-25T08:38:59.279341Z        69 Query     insert /* gh-ost */ into `mysqlslap`.`_t1_ghc`

2019-02-25T08:38:59.371523Z        67 Query     insert /* gh-ost */ into `mysqlslap`.`_t1_ghc`

2019-02-25T08:38:59.471494Z        69 Query     insert /* gh-ost */ into `mysqlslap`.`_t1_ghc`

2019-02-25T08:38:59.571439Z        67 Query     insert /* gh-ost */ into `mysqlslap`.`_t1_ghc`

2019-02-25T08:38:59.671521Z        69 Query     insert /* gh-ost */ into `mysqlslap`.`_t1_ghc`

2019-02-25T08:38:59.771526Z        67 Query     insert /* gh-ost */ into `mysqlslap`.`_t1_ghc`

2019-02-25T08:38:59.871520Z        69 Query     insert /* gh-ost */ into `mysqlslap`.`_t1_ghc`

2019-02-25T08:38:59.971540Z        67 Query     insert /* gh-ost */ into `mysqlslap`.`_t1_ghc`

2019-02-25T08:38:59.976502Z        69 Query     insert /* gh-ost */ into `mysqlslap`.`_t1_ghc`

2019-02-25T08:39:00.071569Z        67 Query     insert /* gh-ost */ into `mysqlslap`.`_t1_ghc`

2019-02-25T08:39:00.171486Z        69 Query     insert /* gh-ost */ into `mysqlslap`.`_t1_ghc`

2019-02-25T08:39:00.251211Z        67 Query     replace /* gh-ost `mysqlslap`.`_t1_gho` */ into

2019-02-25T08:39:00.251556Z        67 Query     replace /* gh-ost `mysqlslap`.`_t1_gho` */ into

2019-02-25T08:39:00.251754Z        67 Query     replace /* gh-ost `mysqlslap`.`_t1_gho` */ into

2019-02-25T08:39:00.251977Z        67 Query     replace /* gh-ost `mysqlslap`.`_t1_gho` */ into

2019-02-25T08:39:00.252143Z        67 Query     replace /* gh-ost `mysqlslap`.`_t1_gho` */ into

2019-02-25T08:39:00.252348Z        67 Query     replace /* gh-ost `mysqlslap`.`_t1_gho` */ into

2019-02-25T08:39:00.252505Z        67 Query     replace /* gh-ost `mysqlslap`.`_t1_gho` */ into

2019-02-25T08:39:00.252679Z        67 Query     replace /* gh-ost `mysqlslap`.`_t1_gho` */ into

2019-02-25T08:39:00.252847Z        67 Query     replace /* gh-ost `mysqlslap`.`_t1_gho` */ into

2019-02-25T08:39:00.264470Z        69 Query     insert /* gh-ost */ into `mysqlslap`.`_t1_ghc`

2019-02-25T08:39:00.271783Z        67 Query     insert /* gh-ost */ into `mysqlslap`.`_t1_ghc`

2019-02-25T08:39:00.285571Z        69 Query     rename /* gh-ost */ table `mysqlslap`.`t1` to `mysqlslap`.`_t1_del`, `mysqlslap`.`_t1_gho` to `mysqlslap`.`t1`

2019-02-25T08:39:00.297535Z        70 Query     select is_used_lock('gh-ost.66.lock')

2019-02-25T08:39:00.297781Z        66 Query     drop /* gh-ost */ table if exists `mysqlslap`.`_t1_del`

2019-02-25T08:39:00.361910Z        70 Query     show /* gh-ost */ table status from `mysqlslap` like '_t1_del'

2019-02-25T08:39:00.374467Z        67 Query     insert /* gh-ost */ into `mysqlslap`.`_t1_ghc`

2019-02-25T08:39:00.383095Z        69 Query     drop /* gh-ost */ table if exists `mysqlslap`.`_t1_ghc`

なんか *_ghc テーブルと *_gho テーブルを使ってる？


..

2019-02-25T08:39:00.264470Z        69 Query     insert /* gh-ost */ into `mysqlslap`.`_t1_ghc`

                                (id, hint, value)

                        values

                                (NULLIF(0, 0), 'copy iteration 4 at 1551083940', 'Copy: 3365/3365 100.0%; Applied: 435; Backlog: 0/100

0; Time: 3s(total), 2s(copy); streamer: mysql-bin.000001:81714074; State: migrating; ETA: due')

                        on duplicate key update

                                last_update=NOW(),

                                value=VALUES(value)

..

2019-02-25T08:39:00.374467Z        67 Query     insert /* gh-ost */ into `mysqlslap`.`_t1_ghc`

                                (id, hint, value)

                        values

                                (NULLIF(1, 0), 'heartbeat', '2019-02-25T17:39:00.374212828+09:00')

                        on duplicate key update

                                last_update=NOW(),

                                value=VALUES(value)

..

ghcの方は制御情報を書き込んでるっぽいのかな。


2019-02-25T08:38:59.221449Z        67 Query     select  /* gh-ost `mysqlslap`.`t1` iteration:4 */

                                                `id`

                                        from

                                                `mysqlslap`.`t1`

                                        where ((`id` > _binary'ca4dbc9a-38d8-11e9-98dc-0201a32caf75')) and ((`id` < _binary'ca4dbc9a-3

8d8-11e9-98dc-0201a32caf75') or ((`id` = _binary'ca4dbc9a-38d8-11e9-98dc-0201a32caf75')))

                                        order by

                                                `id` asc

                                        limit 1

                                        offset 999

2019-02-25T08:38:59.221871Z        66 Query     select /* gh-ost `mysqlslap`.`t1` iteration:4 */ `id`

                                from (

                                        select

                                                        `id`

                                                from

                                                        `mysqlslap`.`t1`

                                                where ((`id` > _binary'ca4dbc9a-38d8-11e9-98dc-0201a32caf75')) and ((`id` < _binary'ca

4dbc9a-38d8-11e9-98dc-0201a32caf75') or ((`id` = _binary'ca4dbc9a-38d8-11e9-98dc-0201a32caf75')))

                                                order by

                                                        `id` asc

                                                limit 1000

                                ) select_osc_chunk

                        order by

                                `id` desc

                        limit 1

--chunk-size ぶんの行を探している気配がする。
- --concurrent-rowcount=true （デフォルト）の時は count rows after row-copy begins, concurrently, and adjust row estimate later on らしいのでその処理かしらん。
general_logを眺めていたら DROP が ghc なテーブルにしか流れてなかったことに気が付く。


master [localhost] {msandbox} (mysqlslap) > SHOW TABLES;

+---------------------+

| Tables_in_mysqlslap |

+---------------------+

| _t1_del             |

| t1                  |

+---------------------+

2 rows in set (0.00 sec)

デフォルトではスワップさせた旧テーブルはDROPしないっぽい。
- pt-online-schema-change はデフォルトで旧テーブルをDROPするのでそれを知らないとたまにアイタタタタってなるけれど
- 容量問題にぶち当たっている場合はこれを憶えておかないとアイタタタタってなると思うので憶えておこう

取り敢えず今日はここまで。

登録: 投稿 ( Atom )

日々の覚書

GA

2019/02/26

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

TL;DR

2019/02/25

第一印象 of gh-ost

TL;DR

インストール

テスト