kenken0807_DBメモ

つば九郎が好きなDBAです。Oracle Standard Editionでの運用やツールとかとかの備忘録。特に記載がない場合はoracle11gR2です。時々MySQL

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が待機する原因は?

www.percona.com

– 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                     |
 |
・
・
  • このように userテーブルをupdateしたあとに、userテーブルをselect して、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
  • この場合のデッドロック検知の仕組みはないので、tx2はinnodb_lock_wait_timeout, tx3とtx1はlock_wait_timeout まで待機することになる。

対策方法など

  • 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で実行可能なもの一覧

    • Adding a column
    • Dropping the column default value
    • Modifying the definition of an ENUM or SET column
    • Adding a VIRTUAL column
  • 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日目の記事です。

さて、MySQLSQLステートメントの統計情報を見る時ってどうしますか? 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 について軽い感じで書きます」です。楽しみですね。

InnoDBで行ロックを取得してるSQLを調べる

InnoDBでSELECT FOR UPDATEでセッションが溢れて、原因のpidはわかるけど、ロック取得しているSQLがなんとかとれないかなと調べてみた。

MySQL5.7以降であれば下のSQLでとれるかも。たぶんいけるはず。

SELECT 
    lo.*,
    t.thread_id AS blocking_thread_id,
    GROUP_CONCAT(CONCAT('\n',LPAD('', 25, ' '),event_id,':',sql_text) ORDER BY event_id) blocking_thread_sqlinfo
FROM
    (SELECT 
        GROUP_CONCAT(CONCAT('\n',LPAD('', 25, ' '), waiting_pid, ':', waiting_query)) wait_pidlist,
            blocking_pid,
            MAX(sql_kill_blocking_query) killsql,
            blocking_query
    FROM
        sys.innodb_lock_waits a
    LEFT JOIN (SELECT DISTINCT
        waiting_pid AS wpid
    FROM
        sys.innodb_lock_waits) b ON a.blocking_pid = b.wpid
    WHERE
        wpid IS NULL
    GROUP BY blocking_pid) lo
        LEFT JOIN
    performance_schema.threads t ON lo.blocking_pid = t.processlist_id
        LEFT JOIN
    performance_schema.events_statements_current USING (thread_id)
GROUP BY 2\G

試す

下を同時に動かして2つのレコードロックと待機を発生させる

  • session 1 :begin;SELECT * FROM t0 WHERE id=1 FOR UPDATE; ← ロック取得
  • session 2 : begin;SELECT * FROM t0 WHERE id=2-1 FOR UPDATE; ← session 1で待機
  • session 3 : begin;SELECT * FROM t0 WHERE id=3-2 FOR UPDATE; ← session 1で待機

  • session 4 : begin;SELECT * FROM t0 WHERE id=2 FOR UPDATE; ← ロック取得

  • session 5 : begin;SELECT * FROM t0 WHERE id=4-2 FOR UPDATE; ← session 4で待機

でさっきのSQLを実行

*************************** 1. row ***************************
           wait_pidlist:
                         8:SELECT * FROM t0 WHERE id=2-1 FOR UPDATE,
                         17:SELECT * FROM t0 WHERE id=3-2 FOR UPDATE
           blocking_pid: 5
                killsql: KILL QUERY 5
         blocking_query: NULL
     blocking_thread_id: 30
blocking_thread_sqlinfo:
                         35:SELECT * FROM t0 WHERE id=1 FOR UPDATE
*************************** 2. row ***************************
           wait_pidlist:
                         6:SELECT * FROM t0 WHERE id=4-2 FOR UPDATE
           blocking_pid: 7
                killsql: KILL QUERY 7
         blocking_query: NULL
     blocking_thread_id: 28
blocking_thread_sqlinfo:
                         27:SELECT * FROM t0 WHERE id=2 FOR UPDATE

blocking_thread_sqlinfoがロックを取得しているSQL
ロックを取得してるセッションをkillするにはkill sqlを実行すればOK。
現在進行系のものであればとれるけど、過去のものはわからない。

最近知ったSET型について

MySQL Casual Advent Calendar 2017の15日目の記事です。

MySQLには古くからSET型というカラムの型がありまして、知らない人もいるかもしれません。
私は聞いたことあるぐらいで、使ったこと、使っている現場に遭遇したことなかったです。

今回は初めてめぐり逢ったSET型について、今更ながら調べた話です。

ググってみるとあまり使用することをおすすめしないことが書いてあることが多いのですが、その理由は少しわかりました。

ざっくりSET型とは

  • 文字列オブジェクト
  • 0個以上のメンバーを格納
  • 最大 64 個 の メンバー
  • ENUM型と似ているが、ENUM型は1つのメンバーのみ格納できるが、SET型は複数メンバー可。
  • 複数のメンバーをセットする場合はカンマで区切る

ex) set('a','b')の場合、以下が格納可能

null
'a'
'b'
'a,b'
  • ストレージの消費量
素数 バイト数
1 - 8 1
9 - 16 2
17 - 24 3
25 - 33 4
33 - 64 8
  • 2 進値 と 10 進値 で管理
    ex) set('a','b','c','d')の場合
要素 2進値 10進値
'a' 00000001 1
'b' 00000010 2
'c' 00000100 4
'd' 00001000 8

'a,d' は 10進値 1 + 8 = 9で表すこともできる。

SET型の詳細はこちら。MySQL :: MySQL 5.6 リファレンスマニュアル :: 11.4.5 SET 型

検索でインデックスが効かない

要素個別ではなくカラム全体にインデックスが作成される。

特定の要素を含むレコードを検索するときは FIND_IN_SET() 関数 か LIKE 演算子を使用するため、インデックスが効かない。

ex) 'b'を含むレコードを検索

SELECT * FROM t0 WHERE col like '%b%';

or

SELECT * FROM t0 WHERE FIND_IN_SET(col,'b');

以下のように完全一致で 'a,d' を検索する場合は インデックスは効く。

ex) 'a,d' または 10進値 1 + 8 = 9

SELECT * FROM t0 WHERE col = 'a,d';

or

SELECT * FROM t0 WHERE col = 9;

また カラム名 + 0 することで、そのレコードがもつ10進値の値を取得できるので、仮想列使ってうまくやれば特定の要素でもインデックス使えるかも。(全然思いついてないけど・・)

SELECT col , col+0 FROM t0 WHERE col = 'a,d';
+------+--------+
| col  | col +0 |
+------+--------+
| a,d  |      9 |
+------+--------+

要素リスト追加の罠

要素の追加は基本は即時で完了しますが、前述のストレージの消費量のバイトが増えるタイミングはALGORITHM=COPY の ALTER TABLE 発生。 9 , 17 , 25 , 33個目の要素追加時にテーブル全体のwrite lockが発生するので注意が必要。
もちろん、ALGORITHM=COPYなのでオンラインDDLが不可。

  • ex ) 要素8 , 9個目追加
mysql > SHOW CREATE TABLE t0;
+-------+----------------------------------------------------------------------------------------------------+
| Table | Create Table                                                                                       |
+-------+----------------------------------------------------------------------------------------------------+
| t0    | CREATE TABLE `t0` (
  `col` set('a','b','c') DEFAULT NULL
) ENGINE=InnoDB DEFAULT CHARSET=utf8mb4 |
+-------+----------------------------------------------------------------------------------------------------+

mysql > ALTER TABLE t0 modify col set('a','b','c','d','e','f','g','h');
Query OK, 0 rows affected (0.01 sec)
Records: 0  Duplicates: 0  Warnings: 0

mysql > ALTER TABLE t0 modify col set('a','b','c','d','e','f','g','h','i');
Query OK, 2 rows affected (0.10 sec) ← ALGORITHM=COPYで実行された
Records: 2  Duplicates: 0  Warnings: 0

要素リストのリネームができない

これはENUM型も同様ですが、
すでに変更する要素のデータが存在する場合は、リネームできない。

mysql > SHOW CREATE TABLE t0;
+-------+----------------------------------------------------------------------------------------------------+
| Table | Create Table                                                                                       |
+-------+----------------------------------------------------------------------------------------------------+
| t0    | CREATE TABLE `t0` (
  `col` set('a','b','c') DEFAULT NULL
) ENGINE=InnoDB DEFAULT CHARSET=utf8mb4 |
+-------+----------------------------------------------------------------------------------------------------+

mysql > SELECT * FROM t0;
+------+
| type |
+------+
| a,b  |
| a    |
+------+

mysql > SET sql_mode='STRICT_TRANS_TABLES';
mysql > ALTER TABLE t0 modify col set('zz','b','c');

ERROR 1265 (01000): Data truncated for column 'col' at row 1
Error (Code 1265): Data truncated for column 'col' at row 1
Error (Code 1317): Query execution was interrupted

変更する要素のデータが存在しない場合は、ALGORITHM=COPY の ALTER TABLE 発生。

mysql > SELECT * FROM t0;
+------+
| type |
+------+
| a,b  |
| a    |
+------+

mysql > SET sql_mode='STRICT_TRANS_TABLES';
mysql > ALTER TABLE t0 modify col set('a','b','zz');

Query OK, 2 rows affected (0.06 sec)
Records: 2  Duplicates: 0  Warnings: 0

以上、最近知ったSET型についてでした。