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