ablog

不器用で落着きのない技術者のメモ

MySQL でショート／ロングトランザクション実行中のインデックス作成の影響

MySQL

MySQL (5.7 InnoDB) で本番稼働中にインデックス作成すると、対象テーブルにショートトランザクション実行中の場合は並行でできるけど、ロングトランザクションが実行中*1の場合は Waiting for table metadata lock (synch/cond/sql/MDL_context::COND_wait_status) で metadata lock を延々待ち続ける。DML はオブジェクト定義のメタデータに共有ロックを取り、DDL は排他ロックをかけるため、ロングトランザクションが実行中にインデックスを作成すると、そのトランザクションが終了するまで排他ロックを取れず待ち続ける。

環境

Aurora Mysql
エンジンバージョン: 5.7.mysql_aurora.2.07.2

検証結果

sysbench を Amazon Linux 2 にインストールする
- Amazon Linux 2 に sysbench をインストールしようとすると、libmysqlclient_r.so.16 とlibmysqlclient_r.so.16 が必要と怒られる - ablog

接続確認

mysql -h aurora-mysql-57.cluster-********.ap-northeast-1.rds.amazonaws.com -u awsuser -p

初期データロード

$ sysbench /usr/local/share/sysbench/oltp_read_write.lua \
 --db-driver=mysql \
 --table-size=1000000 \
 --mysql-host=aurora-mysql-57.cluster-********.ap-northeast-1.rds.amazonaws.com \
 --mysql-user=awsuser \
 --mysql-password=******** \
 --mysql-db=db1 \
 --db-ps-mode=disable \
 prepare

ベースラインを計測

$ sysbench /usr/local/share/sysbench/oltp_read_write.lua \
 --db-driver=mysql \
 --table-size=1000000 \
 --mysql-db=db1 \
 --mysql-host=aurora-mysql-57.cluster-********.ap-northeast-1.rds.amazonaws.com \
 --mysql-user=awsuser \
 --mysql-password=******** \
 --time=60 \
 --db-ps-mode=disable \
 --threads=16 \
 run

（中略）

sysbench 1.1.0-bbee5d5 (using bundled LuaJIT 2.1.0-beta3)

Running the test with following options:
Number of threads: 16
Initializing random number generator from current time


Initializing worker threads...

Threads started!

SQL statistics:
    queries performed:
        read:                            335944
        write:                           95984
        other:                           47992
        total:                           479920
    transactions:                        23996  (399.81 per sec.)
    queries:                             479920 (7996.30 per sec.)
    ignored errors:                      0      (0.00 per sec.)
    reconnects:                          0      (0.00 per sec.)

Throughput:
    events/s (eps):                      399.8149
    time elapsed:                        60.0178s
    total number of events:              23996

Latency (ms):
         min:                                   13.70
         avg:                                   40.02
         max:                                  133.53
         95th percentile:                       63.32
         sum:                               960213.46

Threads fairness:
    events (avg/stddev):           1499.7500/7.55
    execution time (avg/stddev):   60.0133/0.00

無風時のインデックス作成所要時間

約7秒

5.7.12-log awsuser: [db1] 06:47> create index idx_sbtest1 on sbtest1(id, k, c, pad);
Query OK, 0 rows affected (6.87 sec)
Records: 0  Duplicates: 0  Warnings: 0

ショートトランザクション実行時のインデックス作成所要時間

約32秒

5.7.12-log awsuser: [db1] 06:48> create index idx_sbtest1 on sbtest1(id, k, c, pad);
Query OK, 0 rows affected (31.97 sec)
Records: 0  Duplicates: 0  Warnings: 0

実行したワークロードは以下の通り

$ sysbench /usr/local/share/sysbench/oltp_read_write.lua \
 --db-driver=mysql \
 --table-size=1000000 \
 --mysql-db=db1 \
 --mysql-host=aurora-mysql-57.cluster-********.ap-northeast-1.rds.amazonaws.com \
 --mysql-user=awsuser \
 --mysql-password=******** \
 --time=60 \
 --db-ps-mode=disable \
 --threads=16 \
 run

（中略）

Threads started!

SQL statistics:
    queries performed:
        read:                            265076
        write:                           75712
        other:                           37862
        total:                           378650
    transactions:                        18928  (315.31 per sec.)
    queries:                             378650 (6307.72 per sec.)
    ignored errors:                      6      (0.10 per sec.)
    reconnects:                          0      (0.00 per sec.)

Throughput:
    events/s (eps):                      315.3109
    time elapsed:                        60.0296s
    total number of events:              18928

Latency (ms):
         min:                                   15.08
         avg:                                   50.74
         max:                                  439.32
         95th percentile:                       80.03
         sum:                               960409.86

Threads fairness:
    events (avg/stddev):           1183.0000/6.95
    execution time (avg/stddev):   60.0256/0.00

ロングトランザクション実行中にインデックス作成すると

metadata lock 解放待ちで待機し続ける。

5.7.12-log awsuser: [db1] 06:51> create index idx_sbtest1 on sbtest1(id, k, c, pad);

以下のトランザクション実行後にインデックス作成

5.7.12-log awsuser: [db1] 06:51> begin;
Query OK, 0 rows affected (0.00 sec)

5.7.12-log awsuser: [db1] 06:51> update sbtest1 set k=1;
Query OK, 196455 rows affected (15.54 sec)
Rows matched: 1000000  Changed: 196455  Warnings: 0

SHOW PROCESSLIST で確認すると、create index は Waiting for table metadata lock で待機している。

5.7.12-log awsuser: [db1] 06:52> SHOW PROCESSLIST;
+-----+----------+--------------------+------+---------+-------+---------------------------------+----------------------------------------------------+
| Id  | User     | Host               | db   | Command | Time  | State                           | Info                                               |
+-----+----------+--------------------+------+---------+-------+---------------------------------+----------------------------------------------------+
|   8 | rdsadmin | localhost          | NULL | Sleep   |     0 | cleaning up                     | NULL                                               |
|   9 | rdsadmin | localhost          | NULL | Sleep   |     1 | cleaning up                     | NULL                                               |
|  11 | rdsadmin | localhost          | NULL | Sleep   |     9 | cleaning up                     | NULL                                               |
|  12 | rdsadmin | localhost          | NULL | Sleep   |   149 | cleaning up                     | NULL                                               |
|  17 | rdsadmin | localhost          | NULL | Sleep   |     0 | cleaning up                     | NULL                                               |
|  59 | awsuser  | 54.***.**.85:54622 | db1  | Sleep   |  9504 | cleaning up                     | NULL                                               |
| 141 | awsuser  | 54.***.**.85:55150 | db1  | Sleep   | 16773 | cleaning up                     | NULL                                               |
| 158 | awsuser  | 54.***.**.85:55276 | db1  | Sleep   |  9769 | cleaning up                     | NULL                                               |
| 224 | awsuser  | 54.***.**.85:57430 | db1  | Sleep   |    82 | cleaning up                     | NULL                                               |
| 225 | awsuser  | 54.***.**.85:57434 | db1  | Query   |    55 | Waiting for table metadata lock | create index idx_sbtest1 on sbtest1(id, k, c, pad) |
| 259 | awsuser  | 54.***.**.85:57542 | db1  | Query   |     0 | starting                        | SHOW PROCESSLIST                                   |
+-----+----------+--------------------+------+---------+-------+---------------------------------+----------------------------------------------------+
11 rows in set (0.02 sec)

Performance Insights で見るとこんな感じ
- synch/cond/sql/MDL_context::COND_wait_status で待機している。

f:id:yohei-a:20201126160832p:plain

synch/cond/sql/MDL_context::COND_wait_status
この待機イベントの場合、テーブルのメタデータロックを待機中のスレッドがあります。詳細については、MySQL ドキュメントの「ロック操作の最適化」を参照してください。
Amazon Aurora MySQL のリファレンス - Amazon Aurora

参考

メタデータのロック？？
主な目的としてはデータの一貫性を確保するためです。
明示、暗黙的問わず開始されたトランザクションはメタデータロックを保持し、利用されてるテーブルに対してDDLを実行を禁止します。またこれはトランザクション終了まで保持されます。　
詳しくは: https://dev.mysql.com/doc/refman/5.6/ja/metadata-locking.html
mysql 5.6~でのalter tableでやらかさない - Qiita

MySQLでmetadata lockにハマりやすいパターン - なからなLife

関連

*1:インデックス作成前にトランザクションが開始して、commit/rollback していない