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の設定が良さそうです。デフォルトもそうですしね。

以上です。