pt-online-schema-changeとgh-ostの比較(データが損失するかもしれないAlterTable編)
こちらのエントリーは MySQL Advent Calendar 2021の14日目の記事になります。
今年はオンラインスキーママイグレーションツールのpt-online-schema-change(pt-osc)とgh-ostをよく調べていたので、その中から一つ。
mysqlコマンドではエラーになるけど、制約違反などでデータが損失する可能性のあるAlter Tableを実施するとそれぞれどうなるか比較したいと思います。
昨今ではMySQL8.0からのInstance Alter Tableが使えるのであれば、まずこれを使うでしょう。
それ以外だとOnlineDDL機能を使ってスキーマ変更するでしょうけど、これはレプリカの遅延が発生するため、pt-oscや gh-ostを使う機会はまだ多いと感じます。
各種ツールについて詳しく説明はしません。
gh-ostについてはがんばって書いた記事があるのでそちらを参照してください。pt-oscはググればいっぱい記事がでますのでそちらでご確認を。
* 第138回 オンラインスキーママイグレーションツール gh-ostを使ってみよう［その1］
* 第139回 オンラインスキーママイグレーションツール gh-ostを使ってみよう［その2］
* 第140回 オンラインスキーママイグレーションツール gh-ostを使ってみよう［その3］
使用するVersionはこちらです。
| Tool | Version |
|---|---|
| pt-osc | 3.3.1 |
| gh-ost | 1.1.2 |
それでは、今回は以下の4つのケースを比較してみます。
* Unique keyの追加
* 既存の Unique key付きカラムの変更
* Foreign Key追加
* Check制約追加
では、見ていきましょう。以後、出力されるログは一部割愛しています。
Unique keyの追加
以下のようなテーブルとデータを用意します。
col1にUnique Keyを追加します。col1=1が2行あるためユニークではありません。
mysql> CREATE TABLE `t0` ( `id` bigint unsigned NOT NULL AUTO_INCREMENT, `col1` int DEFAULT NULL, PRIMARY KEY (`id`) ); mysql> SELECT * FROM t0; +----+------+ | id | col1 | +----+------+ | 1 | 1 | | 2 | 1 | | 3 | 100 | +----+------+
mysqlコマンド
エラーになります。
mysql> ALTER TABLE t0 ADD UNIQUE KEY(col1); ERROR 1062 (23000): Duplicate entry '1' for key 't0.col1'
pt-osc
pt-online-schema-change \
--alter "ADD UNIQUE KEY(col1)" D=test,t=t0 \
--defaults-file=./my.cnf \
--execute
<snip>
You are trying to add an unique key. This can result in data loss if the data is not unique.
Please read the documentation for the --check-unique-key-change parameter.
You can check if the column(s) contain duplicate content by running this/these query/queries:
SELECT IF(COUNT(DISTINCT col1) = COUNT(*),
'Yes, the desired unique index currently contains only unique values',
'No, the desired unique index contains duplicated values. There will be data loss'
) AS IsThereUniqueness FROM `test`.`t0`;
Keep in mind that these queries could take a long time and consume a lot of resources
`test`.`t0` was not altered.
エラーメッセージがでます。
データが一意じゃないとデータ損失するから、SQLで確認してね。--check-unique-key-change のドキュメントを読んで確認してね。
というメッセージです。
デフォルトでは--check-unique-key-change が有効なため、このメッセージが表示されます。
--no-check-unique-key-changeを付けて実行すると、このチェックを無視して通るようになります。
pt-online-schema-change \ --alter "ADD UNIQUE KEY(col1)" D=test,t=t0 \ --defaults-file=./my.cnf \ --no-check-unique-key-change \ --execute <snip> 2021-12-13T11:28:19 Creating triggers... 2021-12-13T11:28:19 Created triggers OK. 2021-12-13T11:28:19 Copying approximately 3 rows... 2021-12-13T11:28:19 Copied rows OK. 2021-12-13T11:28:19 Analyzing new table... 2021-12-13T11:28:19 Swapping tables... 2021-12-13T11:28:19 Swapped original and new tables OK. 2021-12-13T11:28:19 Dropping old table... 2021-12-13T11:28:19 Dropped old table `test`.`_t0_old` OK. 2021-12-13T11:28:19 Dropping triggers... 2021-12-13T11:28:19 Dropped triggers OK. Successfully altered `test`.`t0`.
結果はもちろんデータがユニークではないので、id=2のデータが損失しました。
mysql> SHOW CREATE TABLE t0; CREATE TABLE `t0` ( `id` bigint unsigned NOT NULL AUTO_INCREMENT, `col1` int DEFAULT NULL, PRIMARY KEY (`id`), UNIQUE KEY `col1` (`col1`) ) mysql> SELECT * FROM t0; +----+------+ | id | col1 | +----+------+ | 1 | 1 | | 3 | 100 | +----+------+
gh-ost
gh-ost \ --alter="ADD UNIQUE KEY(col1)" \ --database="test" \ --table="t0" \ --host=127.0.0.1 \ --port=21224 \ --user="msandbox" \ --password='msandbox' \ --execute <snip> . Copy: 2/2 100.0%; Applied: 0; Backlog: 0/1000; Time: 2s(total), 1s(copy); streamer: mysql-bin.000001:23347; Lag: 0.02s, HeartbeatLag: 0.02s, State: migrating; ETA: due [2021/12/13 11:14:44] [info] binlogsyncer.go:164 syncer is closing... [2021/12/13 11:14:44] [error] binlogstreamer.go:77 close sync with err: sync is been closing... [2021/12/13 11:14:44] [info] binlogsyncer.go:179 syncer is closed # Done
特にUnique Keyに関するメッセージもなく #Done がでて完了しました。
結果を見ると、Unique Keyは追加されていますが、データのid=2の行がなくなってしまいました。
mysql> SHOW CREATE TABLE t0; CREATE TABLE `t0` ( `id` bigint unsigned NOT NULL AUTO_INCREMENT, `col1` int DEFAULT NULL, UNIQUE KEY `id` (`id`), UNIQUE KEY `col1` (`col1`) ) mysql> SELECT * FROM t0; +----+------+ | id | col1 | +----+------+ | 1 | 1 | | 3 | 100 | +----+------+
既存の Unique key付きカラムの変更
つづいて、以下のようなテーブルとデータを用意します。
mojiretu カラムのcollationはutf8mb4_binで Unique keyがあります。
mojiretuカラムをutf8mb4_binからutf8mb4_general_ciに変更します。
utf8mb4_binはcase sensitiveなので'A'と'a'を区別しますが、utf8mb4_general_ciは区別されません。そのため、Unique key制約に違反します。
mysql> CREATE TABLE `t1` ( `id` bigint unsigned NOT NULL AUTO_INCREMENT, `mojiretu` varchar(255) CHARACTER SET utf8mb4 COLLATE utf8mb4_bin DEFAULT NULL, PRIMARY KEY (`id`), UNIQUE KEY `mojiretu` (`mojiretu`) ); mysql> SELECT * FROM t1; +----+----------+ | id | mojiretu | +----+----------+ | 1 | a | | 2 | A | | 3 | Z | +----+----------+
mysqlコマンド
エラーになります。
mysql> ALTER TABLE t1 MODIFY mojiretu varchar(255) CHARACTER SET utf8mb4 COLLATE utf8mb4_general_ci; ERROR 1062 (23000): Duplicate entry 'A' for key 't1.mojiretu'
pt-osc
pt-online-schema-change \ --alter "MODIFY mojiretu varchar(255) CHARACTER SET utf8mb4 COLLATE utf8mb4_general_ci" D=test,t=t1 \ --defaults-file=./my.cnf \ --execute 2021-12-13T11:54:01 Creating triggers... 2021-12-13T11:54:01 Created triggers OK. 2021-12-13T11:54:01 Copying approximately 3 rows... 2021-12-13T11:54:01 Copied rows OK. 2021-12-13T11:54:01 Analyzing new table... 2021-12-13T11:54:01 Swapping tables... 2021-12-13T11:54:01 Swapped original and new tables OK. 2021-12-13T11:54:01 Dropping old table... 2021-12-13T11:54:01 Dropped old table `test`.`_t1_old` OK. 2021-12-13T11:54:01 Dropping triggers... 2021-12-13T11:54:01 Dropped triggers OK. Successfully altered `test`.`t1`.
エラーなく完了しました。
結果を見ると、mojiretu カラムはutf8mb4_binからutf8mb4_general_ciに変更されています。
しかし、id=1の行が損失しました。
mysql> SHOW CREATE TABLE t1; CREATE TABLE `t1` ( `id` bigint unsigned NOT NULL AUTO_INCREMENT, `mojiretu` varchar(255) CHARACTER SET utf8mb4 COLLATE utf8mb4_general_ci DEFAULT NULL, PRIMARY KEY (`id`), UNIQUE KEY `mojiretu` (`mojiretu`) ) mysql> SELECT * FROM t1; +----+----------+ | id | mojiretu | +----+----------+ | 2 | A | | 3 | Z | +----+----------+
gh-ost
gh-ost \ --alter="MODIFY mojiretu varchar(255) CHARACTER SET utf8mb4 COLLATE utf8mb4_general_ci" \ --database="test" \ --table="t1" \ --host=127.0.0.1 \ --port=21224 \ --user="msandbox" \ --password='msandbox' \ --execute <snip> Copy: 2/2 100.0%; Applied: 0; Backlog: 0/1000; Time: 2s(total), 1s(copy); streamer: mysql-bin.000001:58610; Lag: 0.01s, HeartbeatLag: 0.02s, State: migrating; ETA: due [2021/12/13 11:57:10] [info] binlogsyncer.go:164 syncer is closing... [2021/12/13 11:57:10] [error] binlogstreamer.go:77 close sync with err: sync is been closing... [2021/12/13 11:57:10] [info] binlogsyncer.go:179 syncer is closed # Done
#Done がでて完了しました。
結果を見ると、、mojiretu カラムはutf8mb4_binからutf8mb4_general_ciに変更されています。
しかし、データのid=2の行が損失しました。
mysql> SHOW CREATE TABLE t1; CREATE TABLE `t1` ( `id` bigint unsigned NOT NULL AUTO_INCREMENT, `mojiretu` varchar(255) CHARACTER SET utf8mb4 COLLATE utf8mb4_general_ci DEFAULT NULL, PRIMARY KEY (`id`), UNIQUE KEY `mojiretu` (`mojiretu`) ) mysql> SELECT * FROM t1; +----+----------+ | id | mojiretu | +----+----------+ | 1 | a | | 3 | Z | +----+----------+
Foreign Key追加
parentとchildテーブルを用意します。
parent.idカラムを参照するchild.parent_idにForeign Keyを作成するとします。
しかし、childテーブルにはparentテーブルが持っていないparent_id=1000というデータが存在します。
mysql> CREATE TABLE `parent` ( `id` bigint NOT NULL, `col1` varchar(10) DEFAULT NULL, PRIMARY KEY (`id`) ); mysql> CREATE TABLE `child` ( `id` bigint NOT NULL, `parent_id` bigint NOT NULL, PRIMARY KEY (`id`), KEY `parent_id` (`parent_id`) ); mysql> SELECT * FROM parent; +----+------+ | id | col1 | +----+------+ | 1 | NULL | | 2 | NULL | | 3 | NULL | +----+------+ mysql> SELECT * FROM child; +----+-----------+ | id | parent_id | +----+-----------+ | 1 | 1 | | 2 | 2 | | 3 | 1000 | +----+-----------+
mysqlコマンド
エラーになります
mysql> ALTER TABLE child ADD CONSTRAINT `fk_test` FOREIGN KEY (parent_id) REFERENCES `parent` (`id`); ERROR 1452 (23000): Cannot add or update a child row: a foreign key constraint fails (`test`.`#sql-1a43_c`, CONSTRAINT `fk_test` FOREIGN KEY (`parent_id`) REFERENCES `parent` (`id`))
pt-osc
pt-online-schema-change \
--alter "ADD CONSTRAINT fk_test FOREIGN KEY (parent_id) REFERENCES parent (id)" D=test,t=child \
--defaults-file=./my.cnf \
--execute
<snip>
2021-12-13T20:39:04 Creating triggers...
2021-12-13T20:39:04 Created triggers OK.
2021-12-13T20:39:04 Copying approximately 3 rows...
2021-12-13T20:39:04 Dropping triggers...
2021-12-13T20:39:04 Dropped triggers OK.
2021-12-13T20:39:04 Dropping new table...
2021-12-13T20:39:04 Dropped new table OK.
`test`.`child` was not altered.
(in cleanup) 2021-12-13T20:39:04 Error copying rows from `test`.`child` to `test`.`_child_new`: 2021-12-13T20:39:04 Copying rows caused a MySQL error 1452:
Level: Warning
Code: 1452
Message: Cannot add or update a child row: a foreign key constraint fails (`test`.`_child_new`, CONSTRAINT `fk_test` FOREIGN KEY (`parent_id`) REFERENCES `parent` (`id`))
Query: INSERT LOW_PRIORITY IGNORE INTO `test`.`_child_new` (`id`, `parent_id`) SELECT `id`, `parent_id` FROM `test`.`child` LOCK IN SHARE MODE /*pt-online-schema-change 60956 copy table*/
2021-12-13T20:39:04 Dropping triggers...
2021-12-13T20:39:04 Dropped triggers OK.
`test`.`child` was not altered.
エラーになりました。
mysqlコマンドで実施した結果と同様のエラーメッセージが表示されています。
gh-ost
gh-ost \ --alter="ADD CONSTRAINT fk_test FOREIGN KEY (parent_id) REFERENCES parent (id)" \ --database="test" \ --table="child" \ --host=127.0.0.1 \ --port=21224 \ --user="msandbox" \ --password='msandbox' \ --execute <snip> Copy: 2/2 100.0%; Applied: 0; Backlog: 0/1000; Time: 2s(total), 1s(copy); streamer: mysql-bin.000001:85347; Lag: 0.04s, HeartbeatLag: 0.05s, State: migrating; ETA: due [2021/12/13 20:40:52] [info] binlogsyncer.go:164 syncer is closing... [2021/12/13 20:40:52] [error] binlogstreamer.go:77 close sync with err: sync is been closing... [2021/12/13 20:40:52] [info] binlogsyncer.go:179 syncer is closed # Done
#Done がでて完了しました。
結果を見ると、child テーブルにForeign Keyが作成されています。
しかし、データのid=3(parent_id=1000)の行が損失しました。
mysql> SHOW CREATE TABLE child; CREATE TABLE `child` ( `id` bigint NOT NULL, `parent_id` bigint NOT NULL, PRIMARY KEY (`id`), KEY `parent_id` (`parent_id`), CONSTRAINT `fk_test` FOREIGN KEY (`parent_id`) REFERENCES `parent` (`id`) ) mysql> SELECT * FROM child; +----+-----------+ | id | parent_id | +----+-----------+ | 1 | 1 | | 2 | 2 | +----+-----------+
Check制約追加
最後に、8.0の新機能Check制約についても試してみます。
以下のようなテーブルとデータを用意します。
num < 10の条件でCheck制約を追加します。 しかし、num=1000が存在します。
mysql> CREATE TABLE `t2` ( `id` bigint unsigned NOT NULL AUTO_INCREMENT, `num` int DEFAULT NULL, PRIMARY KEY (`id`) ); mysql> SELECT * FROM t2; +----+----------+ | id | check_no | +----+----------+ | 1 | 1 | | 2 | 2 | | 3 | 1000 | +----+----------+
mysqlコマンド
mysql> ALTER TABLE t2 ADD CONSTRAINT num_check CHECK (num < 10); ERROR 3819 (HY000): Check constraint 'num_check' is violated.
エラーになります。
pt-osc
pt-online-schema-change \
--alter "ADD CONSTRAINT num_check CHECK (num < 10)" D=test,t=t2 \
--defaults-file=./my.cnf \
--execute
<snip>
2021-12-13T20:53:31 Creating triggers...
2021-12-13T20:53:31 Created triggers OK.
2021-12-13T20:53:31 Copying approximately 3 rows...
2021-12-13T20:53:31 Dropping triggers...
2021-12-13T20:53:31 Dropped triggers OK.
2021-12-13T20:53:31 Dropping new table...
2021-12-13T20:53:31 Dropped new table OK.
`test`.`t2` was not altered.
(in cleanup) 2021-12-13T20:53:31 Error copying rows from `test`.`t2` to `test`.`_t2_new`: 2021-12-13T20:53:31 Copying rows caused a MySQL error 3819:
Level: Warning
Code: 3819
Message: Check constraint 'num_check' is violated.
Query: INSERT LOW_PRIORITY IGNORE INTO `test`.`_t2_new` (`id`, `num`) SELECT `id`, `num` FROM `test`.`t2` LOCK IN SHARE MODE /*pt-online-schema-change 65146 copy table*/
2021-12-13T20:53:31 Dropping triggers...
2021-12-13T20:53:31 Dropped triggers OK.
`test`.`t2` was not altered.
エラーになりました。
mysqlコマンドで実施した結果と同様のエラーメッセージが表示されています。
gh-ost
gh-ost \ --alter="ADD CONSTRAINT num_check CHECK (num < 10)" \ --database="test" \ --table="t2" \ --host=127.0.0.1 \ --port=21224 \ --user="msandbox" \ --password='msandbox' \ --execute <snip> Copy: 2/2 100.0%; Applied: 0; Backlog: 0/1000; Time: 2s(total), 1s(copy); streamer: mysql-bin.000001:110085; Lag: 0.01s, HeartbeatLag: 0.02s, State: migrating; ETA: due [2021/12/13 20:54:17] [info] binlogsyncer.go:164 syncer is closing... [2021/12/13 20:54:17] [error] binlogstreamer.go:77 close sync with err: sync is been closing... [2021/12/13 20:54:17] [info] binlogsyncer.go:179 syncer is closed # Done
#Done がでて完了しました。
結果を見ると、、t2 テーブルにCheck制約が作成されています。
しかし、データのid=3(num=1000)の行が損失しました。
mysql> SHOW CREATE TABLE t2; CREATE TABLE `t2` ( `id` bigint unsigned NOT NULL AUTO_INCREMENT, `num` int DEFAULT NULL, PRIMARY KEY (`id`), CONSTRAINT `num_check` CHECK ((`num` < 10)) ) mysql> SELECT * FROM t2; +----+------+ | id | num | +----+------+ | 1 | 1 | | 2 | 2 | +----+------+
まとめ
今回の結果は以下の通りです。
| 条件 | mysqlコマンド | pt-osc結果 | gh-ost結果 |
|---|---|---|---|
| Unique keyの追加 | エラー | データ損失する(Optionで制御あり) | データ損失する |
| 既存の Unique key付きカラムの変更 | エラー | データ損失する | データ損失する |
| Foreign Key追加 | エラー | エラー | データ損失する |
| Check制約追加 | エラー | エラー | データ損失する |
pt-oscのほうが制約違反をちゃんと拾ってエラーにしてくれていそうです。
ちなみに、pt-oscもgh-ostも既存のデータをコピーする際にINSERT IGNOREを使用します。
そこでpt-oscはSHOW WARNINGSを使って丁寧にエラーチェックをしているため、制約違反時にエラーにしてくれるとのことをyokuさんが教えてくれました!! さすがやで！
日々の覚書: INSERT IGNORE INTOがNOT NULL DEFAULTを裏切る
pt-oscもgh-ostもたいへん便利で運用者を助けてくれる強力なツールですが、闇雲に実施するのではなく、制約違反などが起こりうるAlter Tableのリスクもしっかりと把握して使っていきたいですね。
performance_schema.events_statements_historyを使って直近に実行されたクエリを見る
さくっと、直近で実行されたクエリの情報がみたいです。
それにはperformance_schema.events_statements_historyテーブルを使います。
performance_schema.events_statements_historyはスレッドごとにperformance_schema_events_statements_history_size(default 10)で指定した個数分のステートメントを格納します。
MySQL5.7以降であればデフォルトONです。
以下のようなSQLを実行すればいい感じみれる。
SELECT * FROM
(
SELECT THREAD_ID,EVENT_ID,
BaseDate - interval (BaseUptime-ROUND(TIMER_START/1000000000000)) second as QUERY_START,
BaseDate - interval (BaseUptime-ROUND(TIMER_END/1000000000000)) second as QUERY_END,
sys.format_time(TIMER_WAIT) ElapsedTime,
substr(SQL_TEXT,1,150) sqltext
FROM performance_schema.events_statements_history,
(
SELECT now() as BaseDate ,
ROUND(TIMER_START/1000000000000) as BaseUptime,
THREAD_ID as BaseThreadID
FROM performance_schema.events_statements_current
WHERE THREAD_ID IN (SELECT THREAD_ID FROM performance_schema.threads WHERE PROCESSLIST_ID=connection_id())
) Base
WHERE BaseThreadID != THREAD_ID
) a
ORDER BY THREAD_ID,EVENT_ID;
+-----------+----------+---------------------+---------------------+-------------+----------------------------------+
| THREAD_ID | EVENT_ID | QUERY_START | QUERY_END | ElapsedTime | sqltext |
+-----------+----------+---------------------+---------------------+-------------+----------------------------------+
| 4560 | 1 | 2020-07-03 13:57:15 | 2020-07-03 13:57:15 | 290.46 us | select @@version_comment limit 1 |
| 4560 | 2 | 2020-07-03 13:57:22 | 2020-07-03 13:57:22 | 99.98 us | SELECT DATABASE() |
| 4560 | 3 | 2020-07-03 13:57:22 | 2020-07-03 13:57:22 | 17.21 us | NULL |
| 4560 | 4 | 2020-07-03 13:57:29 | 2020-07-03 13:57:29 | 31.28 us | select now() |
| 4561 | 1 | 2020-07-03 13:57:15 | 2020-07-03 13:57:15 | 663.76 us | select @@version_comment limit 1 |
| 4561 | 2 | 2020-07-03 13:57:22 | 2020-07-03 13:57:22 | 63.55 us | SELECT DATABASE() |
| 4561 | 3 | 2020-07-03 13:57:22 | 2020-07-03 13:57:22 | 48.33 us | NULL |
| 4561 | 4 | 2020-07-03 13:57:29 | 2020-07-03 13:57:29 | 182.38 us | select now() |
| 4562 | 1 | 2020-07-03 13:57:15 | 2020-07-03 13:57:15 | 620.98 us | select @@version_comment limit 1 |
| 4562 | 2 | 2020-07-03 13:57:22 | 2020-07-03 13:57:22 | 31.73 us | SELECT DATABASE() |
| 4562 | 3 | 2020-07-03 13:57:22 | 2020-07-03 13:57:22 | 42.64 us | NULL |
| 4562 | 4 | 2020-07-03 13:57:29 | 2020-07-03 13:57:29 | 119.97 us | select now() |
| 4563 | 1 | 2020-07-03 13:57:15 | 2020-07-03 13:57:15 | 629.58 us | select @@version_comment limit 1 |
| 4563 | 2 | 2020-07-03 13:57:22 | 2020-07-03 13:57:22 | 128.83 us | SELECT DATABASE() |
| 4563 | 3 | 2020-07-03 13:57:22 | 2020-07-03 13:57:22 | 21.02 us | NULL |
| 4563 | 4 | 2020-07-03 13:57:29 | 2020-07-03 13:57:29 | 119.84 us | select now() |
| 4564 | 1 | 2020-07-03 13:57:16 | 2020-07-03 13:57:16 | 799.33 us | select @@version_comment limit 1 |
| 4564 | 2 | 2020-07-03 13:57:22 | 2020-07-03 13:57:22 | 107.73 us | SELECT DATABASE() |
| 4564 | 3 | 2020-07-03 13:57:22 | 2020-07-03 13:57:22 | 28.56 us | NULL |
| 4564 | 4 | 2020-07-03 13:57:29 | 2020-07-03 13:57:29 | 54.92 us | select now() |
+-----------+----------+---------------------+---------------------+-------------+----------------------------------+
SQLが開始された時間と完了した時間はこのテーブルにカラムはないけど、yoku大先生のアドバイスから導出することができました。
俺は「p_sをクエリーするスレッド自身のタイマーと比較して」ってことをやっているようですhttps://t.co/fOnJt3tMtN
— yoku0825 (@yoku0825) 2019年10月31日
UPDATE setup_consumers SET ENABLED='YES' WHERE NAME='events_transactions_history_long'して、events_statements_history_longテーブルを使用するようにするともっと多くのクエリを確認することができます。
mysqldumpがFLUSH TABLESでタイムアウトしたので調べた話
この記事は MySQL Advent Calendar 2019 11日目の記事です。
mysqldumpがFLUSH TABLESでタイムアウトしたので調べたという記録です。
（SQLステートメントや出力結果は一部省略しています）
問題
とある日、スレーブが壊れましてmysqldumpを使ってマスターから復旧しようとしました。
しかし、以下のようにFLUSH TABLESがtimeoutしてしまい、exportできない事象が...
MySQL5.7です。
# mysqldump -p --single-transaction --master-data=2 --default-character-set=utf8mb4 --routines --triggers --events --hex-blob --databases db > backup.dump mysqldump: Couldn't execute 'FLUSH /*!40101 LOCAL */ TABLES': Lock wait timeout exceeded; try restarting transaction (1205)
その時のSHOW PROCESSLISTは、userテーブルで詰まっており、 Waiting for table flush がいっぱいでてるのであります。
show processlist; +---------+------+----------------------+-----------------+---------+------+-------------------------+--------------------------------------------------------------------------+ | Id | User | Host | db | Command | Time | State | Info | +---------+------+----------------------+-----------------+---------+------+-------------------------+--------------------------------------------------------------------------+ | 1165964 | user | 192.168.0.111:38330 | db | Query | 2 | Waiting for table flush | select this_.id .. ... from user this_ where ... | | 1166202 | user | 192.168.0.111:40166 | db | Query | 2 | Waiting for table flush | select this_.id .. ... from user this_ where ... | | 1166206 | user | 192.168.0.111:40174 | db | Query | 2 | Waiting for table flush | select this_.id .. ... from user this_ where ... | | 1166216 | user | 192.168.0.111:40190 | db | Sleep | 0 | | NULL| | 1166246 | user | 192.168.0.111:40948 | db | Sleep | 0 | | NULL| | 1166272 | user | 192.168.0.111:40240 | db | Query | 2 | Waiting for table flush | select this_.id .. ... from user this_ where ... | | 1166579 | user | 192.168.0.111:43240 | db | Query | 2 | Waiting for table flush | select this_.id .. ... from user this_ where ... | | 1166580 | user | 192.168.0.111:43244 | db | Query | 2 | Waiting for table flush | select this_.id .. ... from user this_ where ... | | 1166621 | user | 192.168.0.111:44008 | db | Query | 2 | Waiting for table flush | select this_.id .. ... from user this_ where ... | | 1166723 | user | 192.168.0.111:44056 | db | Query | 2 | Waiting for table flush | update user set user_name='xxx', lower_user_name='xx' where id=xxx| | 1166847 | user | 192.168.0.111:45880 | db | Query | 2 | Waiting for table flush | select this_.id .. ... from user this_ where ... | | 1166885 | user | 192.168.0.111:47868 | db | Query | 2 | updating | update user set user_name='xxx', lower_user_name='xx' where id=xxx | | 1167040 | user | 192.168.0.111:48230 | db | Query | 2 | Waiting for table flush | select this_.id .. ... from user this_ where ... | | 1167041 | user | 192.168.0.111:48244 | db | Query | 2 | Waiting for table flush | select this_.id .. ... from user this_ where ... | | 1167111 | user | 192.168.0.111:49400 | db | Query | 1 | Waiting for table flush | select this_.id .. ... from user this_ where ... | | 1167112 | user | 192.168.0.111:49404 | db | Query | 1 | Waiting for table flush | select this_.id .. ... from user this_ where ... | | 1167115 | user | 192.168.0.111:49410 | db | Query | 0 | Waiting for table flush | select this_.id .. ... from user this_ where ... | | 1167117 | user | 192.168.0.111:49414 | db | Query | 0 | Waiting for table flush | select this_.id .. ... from user this_ where ... | | 1167118 | root | localhost | NULL | Query | 2 | Waiting for table flush | FLUSH /*!40101 LOCAL */ TABLES | +---------+-----------+----------------------+--------------------+---------+------+-------------------------+------------------------------------------------------------------+
しかし、↓はmysqldump前の通常時のSHOW PROCESSLIST。FLUSH TABLESが待たさせる要因は見つかりません。。
でも何度やってもFLUSH TABLESでtimeoutしてしまうので、これの調査を実施。
show full processlist; +---------+----------------------+----------------------+--------------------+---------+------+-----------------------+-----------------------+ | Id | User | Host | db | Command | Time | State | Info | +---------+----------------------+----------------------+--------------------+---------+------+-----------------------+-----------------------+ | 23 | agent | 127.0.0.1:43702 | mysql | Sleep | 8 | | NULL | | 1164598 | root | localhost | performance_schema | Query | 0 | starting | show full processlist | | 1165963 | user | 192.168.0.111:38328 | db | Sleep | 1 | | NULL | | 1165964 | user | 192.168.0.111:38330 | db | Sleep | 1 | | NULL | | 1166171 | user | 192.168.0.111:39784 | db | Sleep | 21 | | NULL | | 1166202 | user | 192.168.0.111:40166 | db | Sleep | 8 | | NULL | | 1166206 | user | 192.168.0.111:40174 | db | Sleep | 9 | | NULL | | 1166216 | user | 192.168.0.111:40190 | db | Sleep | 0 | | NULL | | 1166246 | user | 192.168.0.111:40948 | db | Sleep | 0 | | NULL | | 1166272 | user | 192.168.0.111:40240 | db | Sleep | 6 | | NULL | | 1166579 | user | 192.168.0.111:43240 | db | Sleep | 11 | | NULL | | 1166580 | user | 192.168.0.111:43244 | db | Sleep | 1 | | NULL | | 1166621 | user | 192.168.0.111:44008 | db | Sleep | 0 | | NULL | | 1166722 | user | 192.168.0.111:44054 | db | Sleep | 11 | | NULL | | 1166723 | user | 192.168.0.111:44056 | db | Sleep | 0 | | NULL | | 1166847 | user | 192.168.0.111:45880 | db | Sleep | 0 | | NULL | | 1166885 | user | 192.168.0.111:47868 | db | Sleep | 3 | | NULL | +---------+----------------------+----------------------+--------------------+---------+------+-----------------------+-----------------------+
調査
そもそも、なぜmysqldumpがFLUSH TABLESするか
- --master-data option をつけることで、FLUSH TABLES → FLUSH TABLE WITH READ LOCK (FTWRL) → SHOW MASTER STATUS → UNLOCK TABLES というように現在のbinlog情報を取得するため実行される
- FLUSH TABLES → FTWRLと実行している理由が以下。
mysql-server/mysqldump.cc at 8.0 · mysql/mysql-server · GitHub
ざっくりいうと、FTWRLすることがメインだけどlong updateがあって、FTWRLが詰まるとMySQL全体ストールするからそれを最小限に抑えるため。FLUSH TABLESであれば、long updateが実行されたテーブルのみで詰まる。残念ながら、FLUSH TABLES → FTWRLの間にlong updateきたら詰まる。
FLUSH TABLESが待機する原因は？
– Lot of concurrency
– A long running query
– Run an ANALYZE TABLE on a table accessed by the long running query
これらの原因があるらしい。しかし、今回は特にあてはまることはなさそう。
SHOW ENGINE INNODB STATUS
該当時間のSHOW ENGINE INNODB STATUS。
------------ TRANSACTIONS ------------ . . ---TRANSACTION 421797545187632, not started 0 lock struct(s), heap size 1136, 0 row lock(s) ---TRANSACTION 421797545185808, not started 0 lock struct(s), heap size 1136, 0 row lock(s) ---TRANSACTION 421797545175776, not started 0 lock struct(s), heap size 1136, 0 row lock(s) ---TRANSACTION 421797545181248, not started 0 lock struct(s), heap size 1136, 0 row lock(s) ---TRANSACTION 421797545180336, not started 0 lock struct(s), heap size 1136, 0 row lock(s) ---TRANSACTION 4396173272, ACTIVE 6 sec starting index read mysql tables in use 1, locked 1 LOCK WAIT 2 lock struct(s), heap size 1136, 1 row lock(s) MySQL thread id 1170116, OS thread handle 140313433372416, query id 333190246 10.126.200.210 user updating update user set user_name='xxx', lower_user_name='xx' where id=xxx ------- TRX HAS BEEN WAITING 6 SEC FOR THIS LOCK TO BE GRANTED: RECORD LOCKS space id 221 page no 1822 n bits 128 index PRIMARY of table `db`.`user` trx id 4396173272 lock_mode X locks rec but not gap waiting Record lock, heap no 25 PHYSICAL RECORD: n_fields 19; compact format; info bits 0 0: len 8; hex 800000000176c5bd; asc v ;; 1: len 6; hex 00010608476c; asc Gl;; 2: len 7; hex 2e000000532c93; asc . S, ;; ------------------ ---TRANSACTION 4396173164, ACTIVE 7 sec 2 lock struct(s), heap size 1136, 1 row lock(s), undo log entries 1 MySQL thread id 1169613, OS thread handle 140313120376576, query id 333191368 10.126.200.211 user Waiting for table flush select this_.id .. ... from user this_ where ...
- TRANSACTION 4396173272
- レコードロックで待機。しかし、行ロックを保持していたトランザクションがみつからない
- TRANSACTION 4396173164
- FLUSH TABLESが完了していないため、SELECT(non-blocking read)がWaiting for table flush で待機している
- かつ、1 row lock(s) に注目すると、このトランザクションはなにかレコードロックを保持しているのがわかる。よって、このSELECTを実施する前になにかしらの更新をしたと考えられる。
performance_schema.events_statements_historyから傾向を見てみる
- performance_schema.events_statements_historyはMySQL5.7からデフォルト ONなので確認可能。
mysql> SELECT THREAD_ID,EVENT_ID,SQL_TEXT FROM performance_schema.events_statements_history ORDER BY 1,2; +-----------+----------+---------------------------------------------------------------------------------------------------+ | THREAD_ID | EVENT_ID | SQL_TEXT | +-----------+----------+---------------------------------------------------------------------------------------------------+ | 1344268 | 1097 | begin | 1344268 | 1098 | update user set user_name='xxx', ... where id=xxx | 1344268 | 1099 | select this_.id .. ... from user this_ where ... | | 1344268 | 1100 | commit | | ・ ・
該当時間のアクセス状況
- QPSは1000ぐらいで、writeは90/secほどで高負荷ではない。
- ただ、短期間でレコードロックの待機が頻繁に行われていたことが、myStatusgoから確認できた。
myStatusgoというMySQLリアルタイムモニタリングツールがありまして、便利なので使ってね♪
2019-11-xx 13:00:01 --------------------- ----- - -------------------------- InnoDB Lock Info ----------------------------------------------------------------------------------------------------- Hostname Port * BlockPid Locked Table Locked Index time Cnt Waiting Pid --------------------- ----- - ---------- ------------------------------ ------------------------------ ---- ---- -------------------------------------------------------------- master 3306 * 1223420 `db`.`user` PRIMARY 0 1 1222605 2019-11-xx 13:00:02 --------------------- ----- - -------------------------- InnoDB Lock Info ----------------------------------------------------------------------------------------------------- Hostname Port * BlockPid Locked Table Locked Index time Cnt Waiting Pid --------------------- ----- - ---------- ------------------------------ ------------------------------ ---- ---- -------------------------------------------------------------- master 3306 * 1223022 `db`.`user` PRIMARY 1 1 1223204 2019-11-xx 13:00:03 --------------------- ----- - -------------------------- InnoDB Lock Info ----------------------------------------------------------------------------------------------------- Hostname Port * BlockPid Locked Table Locked Index time Cnt Waiting Pid --------------------- ----- - ---------- ------------------------------ ------------------------------ ---- ---- -------------------------------------------------------------- master 3306 * 1223204 `db`.`user` PRIMARY 0 1 1222605
原因
これらの理由から、以下ようなデッドロックが起こったことがわかった。
| tx1 | tx2 | tx3 |
|---|---|---|
| BEGIN | ||
| BEGIN | ||
| UPDATE a | ||
| UPDATE a → Waiting from tx1 | ||
| FLUSH TABLES → Waiting from tx2 | ||
| SELECT a -> Waiting from tx3 |
対策方法など
- innodb_lock_wait_timeoutを小さめの値にする
- FLUSH TABLESだけでなく、
SET GLOBAL READ_ONLY=ONも同様の事象が発生するので注意。- スレーブをマスターにpromoteするときなど使用しているところもありそう。READ_ONLY=ONではなく、MySQL5.7以上であればOFFLINE_MODE=ONを使用するほうが良い。OFFLINE_MODEはlong updateなどあっても待機しない。
innodb_lock_wait_timeoutとlock_wait_timeoutのちょっとしたこと
- innodb_lock_wait_timeout・・行ロックが解除されるまで InnoDB トランザクションが待機する時間の長さ (秒単位) です。デフォルト値は 50 秒です
- lock_wait_timeout・・メタデータロックを取得するための待機時間（秒）となります。デフォルトは31536000秒（1年）です。
今回の設定では、innodb_lock_wait_timeout=30とlock_wait_timeout=30で同じ値を設定していました。すると、以下のような動作になりました。
| tx1 | tx2 | tx3 |
|---|---|---|
| BEGIN | ||
| BEGIN | ||
| UPDATE a | ||
| UPDATE a → Waiting from tx1 | ||
| FLUSH TABLES → Waiting from tx2 | ||
| SELECT a -> Waiting from tx3 | ||
| ERROR 1205 (HY000): Lock wait timeout exceeded; try restarting transaction | ERROR 1205 (HY000): Lock wait timeout exceeded; try restarting transaction |
同じ値なので、tx2、tx3の順でほぼ同時に実行されたとしても、期待することはtx2がtimeoutすると、あとから実行されたtx3が実行されると思ってました。
しかし、実際は違っていてtx2とtx3がtimeoutとなります。
lock_wait_timeoutの検知にほうが若干早いみたい。lock_wait_timeoutはユーザスレッドが管理して、innodb_lock_wait_timeoutはバックグラウンドスレッド(srv_lock_timeout_thread)が管理してるからかなと予想。詳しくは知りませんが。
というわけで、innodb_lock_wait_timeout < lock_wait_timeoutの設定が良さそうです。デフォルトもそうですしね。
以上です。
Instant Add Columnして全行UPDATEしてみる
MySQL8.0の Instant Add Columnで追加したカラムを全行updateするとデータサイズとか実行時間ととかどうなるか試してみた。
まず、 Instant Add Columnとは...
データディクショナリのみを変更することで、add column処理が即時で完了する操作。
ALTER TABLE t2 ADD id3 int not null default 0 , ALGORITHM = INSTANT ; Query OK, 0 rows affected (0.02 sec) Records: 0 Duplicates: 0 Warnings: 0
こんな感じで実行する。
ALGORITHM句を省略すると、 instant -> inplace -> copyの順番で可能なものを実行する
INSTANTで実行可能なもの一覧
Add columnでも INSTANTで実行できないもの
- テーブルの間にカラムを追加すること(必ず最後の列に追加すること)
- ALGORITHM=COPY/INPLACE が必要な他のalter tableと一緒に実行
- ROW_FORMAT=COMPRESSED
- a FULLTEXT indexのあるテーブル
- Temporary tables
- Table in the data dictionary tablespace
Instant Add Columnで追加したカラムを全行updateする
NULLABLE(DEFAULTありなし)、とNOT NULL (DEFAULTありなし)のカラムを追加して試してみる。 NOT NULLのDEFAULTありなしはどっちも同じだと思ったけど、一応追加。
テーブル作成
- instant_null テーブル : ALGORITHM = INSTANTでNULLABLEなカラムを追加
- inplace_null テーブル : ALGORITHM = INPLACEでNULLABLEなカラムを追加
- instant_notnull テーブル : ALGORITHM = INSTANTでNOT NULLなカラムを追加
- inplace_notnull テーブル : ALGORITHM = INPLACEでNOT NULLなカラムを追加
- instant_null_default テーブル : ALGORITHM = INSTANTでNULLABLEでDEFAULT値付きなカラムを追加
- inplace_null_default テーブル : ALGORITHM = INPLACEでNULLABLEでDEFAULT値付きなカラムを追加
- instant_notnull_default テーブル : ALGORITHM = INSTANTでNOT NULLでDEFAULT値付きなカラムを追加
- inplace_notnull_default テーブル : ALGORITHM = INPLACEでNOT NULLでDEFAULT値付きなカラムを追加
CREATE TABLE instant_null (id serial,id2 int); insert into instant_null (id2) values (1); insert into instant_null (id2) select id2 from instant_null; 繰り返しで数回実行
CREATE TABLE inplace_null like instant_null; CREATE TABLE instant_notnull like instant_null; CREATE TABLE inplace_notnull like instant_null; CREATE TABLE inplace_null_default like instant_null; CREATE TABLE instant_null_default like instant_null; CREATE TABLE inplace_notnull_default like instant_null; CREATE TABLE instant_notnull_default like instant_null; insert into inplace_null (id2) select id2 from instant_null; insert into instant_notnull (id2) select id2 from instant_null; insert into inplace_notnull (id2) select id2 from instant_null; insert into inplace_null_default (id2) select id2 from instant_null; insert into instant_null_default (id2) select id2 from instant_null; insert into inplace_notnull_default (id2) select id2 from instant_null; insert into instant_notnull_default (id2) select id2 from instant_null;
データの状態
buffer pool に載った状態で、データサイズは同じ。
select (select count(*) from instant_null) as instant_null, (select count(*) from inplace_null) as inplace_null, (select count(*) from instant_notnull) as instant_notnull, (select count(*) from inplace_notnull) as inplace_notnull, (select count(*) from instant_null_default) as instant_null_default, (select count(*) from inplace_null_default) as inplace_null_default, (select count(*) from instant_notnull_default) as instant_notnull_default, (select count(*) from inplace_notnull_default) as inplace_notnull_default; +--------------+--------------+-----------------+-----------------+----------------------+----------------------+-------------------------+-------------------------+ | instant_null | inplace_null | instant_notnull | inplace_notnull | instant_null_default | inplace_null_default | instant_notnull_default | inplace_notnull_default | +--------------+--------------+-----------------+-----------------+----------------------+----------------------+-------------------------+-------------------------+ | 8388608 | 8388608 | 8388608 | 8388608 | 8388608 | 8388608 | 8388608 | 8388608 | +--------------+--------------+-----------------+-----------------+----------------------+----------------------+-------------------------+-------------------------+ select NAME,FILE_SIZE from information_schema.INNODB_TABLESPACES where NAME like '%t/instant%' or NAME like '%t/inplace%'; +---------------------------+-----------+ | NAME | FILE_SIZE | +---------------------------+-----------+ | t/instant_null | 297795584 | | t/inplace_null | 297795584 | | t/instant_notnull | 297795584 | | t/inplace_notnull | 297795584 | | t/inplace_null_default | 297795584 | | t/instant_null_default | 297795584 | | t/inplace_notnull_default | 297795584 | | t/instant_notnull_default | 297795584 | +---------------------------+-----------+ SELECT * FROM sys.innodb_buffer_stats_by_table WHERE object_name like 'instant%' or object_name like 'inplace%'; +---------------+-------------------------+------------+------------+-------+--------------+-----------+-------------+ | object_schema | object_name | allocated | data | pages | pages_hashed | pages_old | rows_cached | +---------------+-------------------------+------------+------------+-------+--------------+-----------+-------------+ | t | instant_notnull | 271.73 MiB | 248.30 MiB | 17391 | 0 | 6419 | 8405998 | | t | instant_notnull_default | 271.73 MiB | 248.30 MiB | 17391 | 0 | 6419 | 8405998 | | t | instant_null | 271.73 MiB | 248.30 MiB | 17391 | 0 | 6096 | 8405998 | | t | instant_null_default | 271.73 MiB | 248.30 MiB | 17391 | 0 | 6419 | 8405998 | | t | inplace_notnull | 271.73 MiB | 248.30 MiB | 17391 | 0 | 6420 | 8405998 | | t | inplace_notnull_default | 271.73 MiB | 248.30 MiB | 17391 | 0 | 6427 | 8405998 | | t | inplace_null | 271.73 MiB | 248.30 MiB | 17391 | 0 | 6419 | 8405998 | | t | inplace_null_default | 271.73 MiB | 248.30 MiB | 17391 | 0 | 6421 | 8405998 | +---------------+-------------------------+------------+------------+-------+--------------+-----------+-------------+
bigint typeをAdd columnする
ALTER TABLE instant_null ADD col bigint NULL , ALGORITHM = instant; Query OK, 0 rows affected (0.01 sec) ALTER TABLE inplace_null ADD col bigint NULL , ALGORITHM = inplace; Query OK, 0 rows affected (8.49 sec) ALTER TABLE instant_notnull ADD col bigint NOT NULL , ALGORITHM = instant; Query OK, 0 rows affected (0.01 sec) ALTER TABLE inplace_notnull ADD col bigint NOT NULL , ALGORITHM = inplace; Query OK, 0 rows affected (9.09 sec) ALTER TABLE instant_null_default ADD col bigint NULL DEFAULT 100, ALGORITHM = instant; Query OK, 0 rows affected (0.01 sec) ALTER TABLE inplace_null_default ADD col bigint NULL DEFAULT 100, ALGORITHM = inplace; Query OK, 0 rows affected (9.37 sec) ALTER TABLE instant_notnull_default ADD col bigint NOT NULL DEFAULT 100, ALGORITHM = instant; Query OK, 0 rows affected (0.01 sec) ALTER TABLE inplace_notnull_default ADD col bigint NOT NULL DEFAULT 100, ALGORITHM = inplace; Query OK, 0 rows affected (9.05 sec)
サイズ
mysql> select NAME,FILE_SIZE from information_schema.INNODB_TABLESPACES where NAME like '%t/instant%' or NAME like '%t/inplace%'; +---------------------------+-----------+ | NAME | FILE_SIZE | +---------------------------+-----------+ | t/instant_null | 297795584 | | t/instant_notnull | 297795584 | | t/instant_null_default | 297795584 | | t/instant_notnull_default | 297795584 | | t/inplace_null | 335544320 | | t/inplace_notnull | 419430400 | | t/inplace_null_default | 419430400 | | t/inplace_notnull_default | 419430400 | +---------------------------+-----------+
全行UPDATEする
UPDATE instant_null SET col=99999; Query OK, 8388608 rows affected (4 min 9.00 sec) UPDATE inplace_null SET col=99999; Query OK, 8388608 rows affected (6 min 26.18 sec) UPDATE instant_notnull SET col=99999; Query OK, 8388608 rows affected (8 min 41.67 sec) UPDATE inplace_notnull SET col=99999; Query OK, 8388608 rows affected (1 min 3.24 sec) UPDATE instant_null_default SET col=99999; Query OK, 8388608 rows affected (7 min 37.58 sec) UPDATE inplace_null_default SET col=99999; Query OK, 8388608 rows affected (1 min 4.49 sec) UPDATE instant_notnull_default SET col=99999; Query OK, 8388608 rows affected (6 min 21.13 sec) UPDATE inplace_notnull_default SET col=99999; Query OK, 8388608 rows affected (1 min 7.99 sec)
サイズ
mysql> select NAME,FILE_SIZE from information_schema.INNODB_TABLESPACES where NAME like '%t/instant%' or NAME like '%t/inplace%'; +---------------------------+-----------+ | NAME | FILE_SIZE | +---------------------------+-----------+ | t/instant_null | 666894336 | | t/instant_notnull | 666894336 | | t/instant_null_default | 666894336 | | t/instant_notnull_default | 666894336 | | t/inplace_null | 666894336 | | t/inplace_notnull | 419430400 | | t/inplace_null_default | 419430400 | | t/inplace_notnull_default | 419430400 | +---------------------------+-----------+
まとめ
| table | 元々のサイズ | Add col実行時間 | Add col後サイズ | UPDATE実行時間 | UPDATE後サイズ |
|---|---|---|---|---|---|
| instant_null | 297,795,584 | 0.01 sec | 297,795,584 | 4 min 9.00 sec | 666,894,336 |
| inplace_null | 297,795,584 | 8.49 sec | 335,544,320 | 6 min 26.18 sec | 666,894,336 |
| instant_notnull | 297,795,584 | 0.01 sec | 297,795,584 | 8 min 41.67 sec | 666,894,336 |
| inplace_notnull | 297,795,584 | 9.09 sec | 419,430,400 | 1 min 3.24 sec | 419,430,400 |
| instant_null_default | 297,795,584 | 0.01 sec | 297,795,584 | 7 min 37.58 sec | 666,894,336 |
| inplace_null_default | 297,795,584 | 9.37 sec | 419,430,400 | 1 min 4.49 sec | 419,430,400 |
| instant_notnull_default | 297,795,584 | 0.01 sec | 297,795,584 | 6 min 21.13 sec | 666,894,336 |
| inplace_notnull_default | 297,795,584 | 9.05 sec | 419,430,400 | 1 min 7.99 sec | 419,430,400 |
- instantはAdd col後サイズは増えない。metadataだけ変えるっていうもんね。
- inplaceはdefault値があれば、Add col後サイズとUPDATE後サイズが変わらない。ただし、defaultなしのNULLABLEのカラムは別。
- UPDATE実行時間は1回しかとってないので誤差はあると思うけど、inplaceのdefault値ありが3倍ぐらい早い。
- 基本的にはUPDATE後サイズはinstantのほうが大きくなる。
- inplaceのdefaultなしのNULLABLEはUPDATE後サイズはinstantと同じ値になった。
- inplaceのdefaultなしのNULLABLEとinstantの更新処理はほぼ同じ動きなんだろうなと思った。
参考
https://mysqlserverteam.com/mysql-8-0-innodb-now-supports-instant-add-column/
https://dev.mysql.com/doc/refman/8.0/en/alter-table.html
https://dev.mysql.com/doc/refman/8.0/en/innodb-online-ddl-operations.html
https://dev.mysql.com/doc/refman/8.0/en/innodb-tables-table.html
https://dev.mysql.com/doc/refman/8.0/en/innodb-columns-table.html
Serverside Prepare Statementの統計情報を見る
この記事は MySQL Casual Advent Calendar 2018 の12日目の記事です。
さて、MySQLでSQLステートメントの統計情報を見る時ってどうしますか？ performance_schema.events_statements_summary_by_digest テーブルであったり、sys.statement_analysis ビューを見ますよね。少なくとも私は見ます。
しかし、残念ながら events_statements_summary_by_digest には serverside prepare statement の情報は収集されないのです。
MySQL5.7以降からは performance_schema に prepared_statements_instances テーブルがあり、 ここから serverside prepare statement のキャッシュされたステートメントや統計情報が確認できるようになりました。
mysql > show create table prepared_statements_instances\G
*************************** 1. row ***************************
Table: prepared_statements_instances
Create Table: CREATE TABLE `prepared_statements_instances` (
`OBJECT_INSTANCE_BEGIN` bigint(20) unsigned NOT NULL,
`STATEMENT_ID` bigint(20) unsigned NOT NULL,
`STATEMENT_NAME` varchar(64) DEFAULT NULL,
`SQL_TEXT` longtext NOT NULL,
`OWNER_THREAD_ID` bigint(20) unsigned NOT NULL,
`OWNER_EVENT_ID` bigint(20) unsigned NOT NULL,
`OWNER_OBJECT_TYPE` enum('EVENT','FUNCTION','PROCEDURE','TABLE','TRIGGER') DEFAULT NULL,
`OWNER_OBJECT_SCHEMA` varchar(64) DEFAULT NULL,
`OWNER_OBJECT_NAME` varchar(64) DEFAULT NULL,
`TIMER_PREPARE` bigint(20) unsigned NOT NULL,
`COUNT_REPREPARE` bigint(20) unsigned NOT NULL,
`COUNT_EXECUTE` bigint(20) unsigned NOT NULL,
`SUM_TIMER_EXECUTE` bigint(20) unsigned NOT NULL,
`MIN_TIMER_EXECUTE` bigint(20) unsigned NOT NULL,
`AVG_TIMER_EXECUTE` bigint(20) unsigned NOT NULL,
`MAX_TIMER_EXECUTE` bigint(20) unsigned NOT NULL,
`SUM_LOCK_TIME` bigint(20) unsigned NOT NULL,
`SUM_ERRORS` bigint(20) unsigned NOT NULL,
`SUM_WARNINGS` bigint(20) unsigned NOT NULL,
`SUM_ROWS_AFFECTED` bigint(20) unsigned NOT NULL,
`SUM_ROWS_SENT` bigint(20) unsigned NOT NULL,
`SUM_ROWS_EXAMINED` bigint(20) unsigned NOT NULL,
`SUM_CREATED_TMP_DISK_TABLES` bigint(20) unsigned NOT NULL,
`SUM_CREATED_TMP_TABLES` bigint(20) unsigned NOT NULL,
`SUM_SELECT_FULL_JOIN` bigint(20) unsigned NOT NULL,
`SUM_SELECT_FULL_RANGE_JOIN` bigint(20) unsigned NOT NULL,
`SUM_SELECT_RANGE` bigint(20) unsigned NOT NULL,
`SUM_SELECT_RANGE_CHECK` bigint(20) unsigned NOT NULL,
`SUM_SELECT_SCAN` bigint(20) unsigned NOT NULL,
`SUM_SORT_MERGE_PASSES` bigint(20) unsigned NOT NULL,
`SUM_SORT_RANGE` bigint(20) unsigned NOT NULL,
`SUM_SORT_ROWS` bigint(20) unsigned NOT NULL,
`SUM_SORT_SCAN` bigint(20) unsigned NOT NULL,
`SUM_NO_INDEX_USED` bigint(20) unsigned NOT NULL,
`SUM_NO_GOOD_INDEX_USED` bigint(20) unsigned NOT NULL,
PRIMARY KEY (`OBJECT_INSTANCE_BEGIN`),
UNIQUE KEY `OWNER_THREAD_ID` (`OWNER_THREAD_ID`,`OWNER_EVENT_ID`),
KEY `STATEMENT_ID` (`STATEMENT_ID`),
KEY `STATEMENT_NAME` (`STATEMENT_NAME`),
KEY `OWNER_OBJECT_TYPE` (`OWNER_OBJECT_TYPE`,`OWNER_OBJECT_SCHEMA`,`OWNER_OBJECT_NAME`)
) ENGINE=PERFORMANCE_SCHEMA DEFAULT CHARSET=utf8mb4 COLLATE=utf8mb4_0900_ai_ci
1 row in set (0.00 sec)
(MySQL8.0.13を使ってます。)
このテーブルにはevents_statements_summary_by_digestと同じように、そのステートメントのトータルレイテンシーや実行回数などが格納されます。 セッション単位でprepareされたタイミングでレコードを確認することができて、同一のステートメントであったとしても集約せずにそれぞれ作成されます。
Session 1 mysql> PREPARE s1_statement FROM 'select sleep(?)'; Query OK, 0 rows affected (0.00 sec) Statement prepared Session 2 mysql> PREPARE s2_statement FROM 'select sleep(?)'; Query OK, 0 rows affected (0.00 sec) Statement prepared mysql> SELECT STATEMENT_NAME,SQL_TEXT FROM performance_schema.prepared_statements_instances; +----------------+-----------------+ | STATEMENT_NAME | SQL_TEXT | +----------------+-----------------+ | s1_statement | select sleep(?) | | s2_statement | select sleep(?) | +----------------+-----------------+
実行すると、それぞれのステートメント統計情報がカウントされます。
Session 1 mysql> SET @t=1; Query OK, 0 rows affected (0.00 sec) mysql> EXECUTE s1_statement USING @t; +----------+ | sleep(?) | +----------+ | 0 | +----------+ 1 row in set (1.00 sec) mysql> SET @t=10; Query OK, 0 rows affected (0.00 sec) mysql> EXECUTE s1_statement USING @t; +----------+ | sleep(?) | +----------+ | 0 | +----------+ 1 row in set (10.00 sec) Session 2 mysql> SET @t=5; Query OK, 0 rows affected (0.00 sec) mysql> EXECUTE s2_statement USING @t; +----------+ | sleep(?) | +----------+ | 0 | +----------+ 1 row in set (5.00 sec) mysql> SELECT STATEMENT_NAME,SQL_TEXT,COUNT_EXECUTE,SUM_TIMER_EXECUTE,SUM_ROWS_EXAMINED FROM performance_schema.prepared_statements_instances; +----------------+-----------------+---------------+-------------------+-------------------+ | STATEMENT_NAME | SQL_TEXT | COUNT_EXECUTE | SUM_TIMER_EXECUTE | SUM_ROWS_EXAMINED | +----------------+-----------------+---------------+-------------------+-------------------+ | s1_statement | select sleep(?) | 2 | 11001261779000 | 0 | | s2_statement | select sleep(?) | 1 | 5000721345000 | 0 | +----------------+-----------------+---------------+-------------------+-------------------+
そして、これを同一ステートメントを集計してsys.statement_analysis ビューっぽく人間が理解しやすいように見たいときは、こんな感じ(ビューのSQLは拝借)で実行します。
mysql> SELECT
`sys`.`format_statement`(ps_psi.`SQL_TEXT`) AS `query`,
IF(((SUM(ps_psi.`SUM_NO_GOOD_INDEX_USED`) > 0)
OR (SUM(ps_psi.`SUM_NO_INDEX_USED`) > 0)),
'*',
'') AS `full_scan`,
SUM(ps_psi.`COUNT_EXECUTE`) AS `exec_count`,
SUM(ps_psi.`SUM_ERRORS`) AS `err_count`,
SUM(ps_psi.`SUM_WARNINGS`) AS `warn_count`,
`sys`.`format_time`(SUM(ps_psi.`SUM_TIMER_EXECUTE`)) AS `total_latency`,
`sys`.`format_time`(SUM(ps_psi.`MAX_TIMER_EXECUTE`)) AS `max_latency`,
`sys`.`format_time`(SUM(ps_psi.`AVG_TIMER_EXECUTE`)) AS `avg_latency`,
`sys`.`format_time`(SUM(ps_psi.`SUM_LOCK_TIME`)) AS `lock_latency`,
SUM(ps_psi.`SUM_ROWS_SENT`) AS `rows_sent`,
ROUND(IFNULL((SUM(ps_psi.`SUM_ROWS_SENT`) / NULLIF(SUM(ps_psi.`COUNT_EXECUTE`),
0)),
0),
0) AS `rows_sent_avg`,
SUM(ps_psi.`SUM_ROWS_EXAMINED`) AS `rows_examined`,
ROUND(IFNULL((SUM(ps_psi.`SUM_ROWS_EXAMINED`) / NULLIF(SUM(ps_psi.`COUNT_EXECUTE`),
0)),
0),
0) AS `rows_examined_avg`,
SUM(ps_psi.`SUM_ROWS_AFFECTED`) AS `rows_affected`,
ROUND(IFNULL((SUM(ps_psi.`SUM_ROWS_AFFECTED`) / NULLIF(SUM(ps_psi.`COUNT_EXECUTE`),
0)),
0),
0) AS `rows_affected_avg`,
SUM(ps_psi.`SUM_CREATED_TMP_TABLES`) AS `tmp_tables`,
SUM(ps_psi.`SUM_CREATED_TMP_DISK_TABLES`) AS `tmp_disk_tables`,
SUM(ps_psi.`SUM_SORT_ROWS`) AS `rows_sorted`,
SUM(ps_psi.`SUM_SORT_MERGE_PASSES`) AS `sort_merge_passes`,
ps_psi.`SQL_TEXT`
FROM
`performance_schema`.`prepared_statements_instances` ps_psi GROUP BY ps_psi.`SQL_TEXT`
ORDER BY SUM(ps_psi.`SUM_TIMER_EXECUTE`) DESC\G
*************************** 1. row ***************************
query: select sleep(?)
full_scan:
exec_count: 3
err_count: 0
warn_count: 0
total_latency: 16.00 s
max_latency: 15.00 s
avg_latency: 10.50 s
lock_latency: 0 ps
rows_sent: 3
rows_sent_avg: 1
rows_examined: 0
rows_examined_avg: 0
rows_affected: 0
rows_affected_avg: 0
tmp_tables: 0
tmp_disk_tables: 0
rows_sorted: 0
sort_merge_passes: 0
SQL_TEXT: select sleep(?)
1 row in set (0.00 sec)
これでserverside prepare statementを使用したアプリがあったとしても、ステートメントの統計情報が見れてめでたしめでたし。
と思ったのですが、これdeallocateすると消えます
Session 1 mysql> DEALLOCATE PREPARE s1_statement; Query OK, 0 rows affected (0.00 sec) Session 2 mysql> DEALLOCATE PREPARE s2_statement; Query OK, 0 rows affected (0.00 sec) mysql> SELECT STATEMENT_NAME,SQL_TEXT FROM performance_schema.prepared_statements_instances; Empty set (0.00 sec)
以上です。
明日は@taka_yuki_04さんで「zerofill について軽い感じで書きます」です。楽しみですね。
