【MySQL】ERROR 1205 (HY000): Lock wait timeout exceeded; try restarting transaction が出て困った話

先日MySQLで下記エラーに出会いました。

ERROR 1205 (HY000): Lock wait timeout exceeded; try restarting transaction

対応に手間取ったので、振り返ってみようと思います。

このエラーは何を表している？

データへ書き込むために待機していたトランザクションが、待機時間上限を超えた時に出るエラーのようです。
待機させられている理由は、前のトランザクションによって更新対象がロックされている為とのこと。

ちなみに待機時間の上限は innodb_lock_wait_timeout に定められており、デフォルトは50秒です。

どうやら行ロックを取得したトランザクションがcommitしないまま残ってしまったようで、
該当の行を更新しようとすると、50秒後に上記エラーが出るようになってしまいました。

wait_timeout（非対話型の接続）またはinteractive_timeout（対話型の接続）の時間を経過すると自動で切断されるようですが、
デフォルトは8時間と長いので急ぎ解消するためには、つかみっぱなしのトランザクションをkillする必要があります。

kill対象を判断するのに時間がかかってしまったので、その時調べたことをまとめておこうと思います。

killするスレッドを判断するために情報を集める

検証用にusersテーブルを作成します。MySqlのバージョンは 8.2.0でやっています。

CREATE TABLE users (
 id INT NOT NULL AUTO_INCREMENT ,
 name VARCHAR(255) NOT NULL ,
 email VARCHAR(255) NOT NULL ,
 PRIMARY KEY (id)
 );

INSERT INTO users(name, email)
VALUES ('TARO', 'taro@example.com'),
('JIRO', 'jiro@example.com'),
('SABURO', 'saburo@example.com');

mysql> select * from users;
 +----+--------+--------------------+
 | id | name | email |
 +----+--------+--------------------+
 | 1 | TARO | taro@example.com |
 | 2 | JIRO | jiro@example.com |
 | 3 | SABURO | saburo@example.com |
 +----+--------+--------------------+
 3 rows in set (0.00 sec)

この時点では、スレッドは１つです。

mysql>  show processlist;
 +----+------+-----------+------------+---------+------+-------+------------------+
 | Id | User | Host      | db         | Command | Time | State | Info             |
 +----+------+-----------+------------+---------+------+-------+------------------+
 | 13 | root | localhost | example_db | Query   |    0 | init  | show processlist |
 +----+------+-----------+------------+---------+------+-------+------------------+
 1 row in set, 1 warning (0.00 sec)

テーブルを作った上記のセッションを１つ目として、２つ目のセッションを新しく開始し、レコードの削除をしてcommitしないままクライアントを強制的に閉じます。
次に３つ目のセッションを新たに開始して1レコードのアップデートを行います。

-- ２つ目のセッションを新しく開始し、オートコミットをOFF
mysql> set autocommit = 0;
Query OK, 0 rows affected (0.00 sec)

-- レコードの削除
mysql> DELETE FROM users;
Query OK, 3 rows affected (0.00 sec)

-- commitしないまま切断

-- ３つ目のセッションを新しく開始し、オートコミットをOFF
mysql> set autocommit = 0;
Query OK, 0 rows affected (0.00 sec)

-- アップデートすると、50秒後に今回のエラーが発生する
 mysql> UPDATE users set name = 'ichiro' WHERE id = 1;
 ERROR 1205 (HY000): Lock wait timeout exceeded; try restarting transaction
 mysql> rollback;

再現できました。

ロックしているトランザクションを終了させないと、usersテーブルを更新出来ない状況になりました。
このまま8時間（デフォルト）経過すれば終了するのですが、８時間は長いので、どうにかkillしたいです。

show processlist

この時点でスレッドは３つ表示されます。

mysql> show processlist;
+----+------+-----------+------------+---------+------+-------+------------------+
| Id | User | Host      | db         | Command | Time | State | Info             |
+----+------+-----------+------------+---------+------+-------+------------------+
| 18 | root | localhost | example_db | Query   |    0 | init  | show processlist |
| 19 | root | localhost | example_db | Sleep   |  126 |       | NULL             |
| 20 | root | localhost | example_db | Sleep   |   53 |       | NULL             |
+----+------+-----------+------------+---------+------+-------+------------------+
3 rows in set, 1 warning (0.00 sec)

ちなみに、重いSQL等で処理が終わっていない場合は「Info」の部分にSQLステートメントが表示されますが、
今回はcommitまたはrallbackがされていないだけなので、Infoはnullになります。

SHOW ENGINE INNODB STATUS

killするならもう少し情報が欲しい、ということで、もう少し集めます。SHOW ENGINE INNODB STATUS で出てくる情報は多岐にわたりますが、トランザクションの情報も含まれています。

mysql> SHOW ENGINE INNODB STATUS;
-- (省略) --

------------
TRANSACTIONS
------------
Trx id counter 1871
Purge done for trx's n:o < 1870 undo n:o < 0 state: running but idle
History list length 0
LIST OF TRANSACTIONS FOR EACH SESSION:
---TRANSACTION 421357384966952, not started
0 lock struct(s), heap size 1128, 0 row lock(s)
---TRANSACTION 421357384965336, not started
0 lock struct(s), heap size 1128, 0 row lock(s)
---TRANSACTION 421357384964528, not started
0 lock struct(s), heap size 1128, 0 row lock(s)
---TRANSACTION 421357384963720, not started
0 lock struct(s), heap size 1128, 0 row lock(s)
---TRANSACTION 1865, ACTIVE 771 sec
2 lock struct(s), heap size 1128, 4 row lock(s), undo log entries 3
MySQL thread id 19, OS thread handle 139881921705728, query id 218 localhost root

-- (省略) --

「TRANSACTIONS」の部分を確認します。

「undo log entries 3」の部分がコミットもロールバックもしていない行数です。

「MySQL thread id 19」がSHOW PROCESSLISTのIdと一致します。Id:19が長時間(771秒)経過しているという情報が取れました。加えて「３行変更しているのにコミットされていない」という情報を取得出来ました。

select * from information_schema.INNODB_TRX

information_schema.INNODB_TRX から現在実行されているすべてのトランザクションに関する情報を取得出来ます。

mysql> select * from information_schema.INNODB_TRX order by trx_id\G
*************************** 1. row ***************************
                    trx_id: 1865
                 trx_state: RUNNING
               trx_started: 2023-11-29 10:17:20
     trx_requested_lock_id: NULL
          trx_wait_started: NULL
                trx_weight: 5
       trx_mysql_thread_id: 19
                 trx_query: NULL
       trx_operation_state: NULL
         trx_tables_in_use: 0
         trx_tables_locked: 1
          trx_lock_structs: 2
     trx_lock_memory_bytes: 1128
           trx_rows_locked: 4
         trx_rows_modified: 3
   trx_concurrency_tickets: 0
       trx_isolation_level: REPEATABLE READ
         trx_unique_checks: 1
    trx_foreign_key_checks: 1
trx_last_foreign_key_error: NULL
 trx_adaptive_hash_latched: 0
 trx_adaptive_hash_timeout: 0
          trx_is_read_only: 0
trx_autocommit_non_locking: 0
       trx_schedule_weight: NULL
*************************** 2. row ***************************
                    trx_id: 421357384966952
                 trx_state: RUNNING
               trx_started: 2023-11-29 10:30:55
     trx_requested_lock_id: NULL
          trx_wait_started: NULL
                trx_weight: 0
       trx_mysql_thread_id: 20
                 trx_query: NULL
       trx_operation_state: NULL
         trx_tables_in_use: 0
         trx_tables_locked: 0
          trx_lock_structs: 0
     trx_lock_memory_bytes: 1128
           trx_rows_locked: 0
         trx_rows_modified: 0
   trx_concurrency_tickets: 0
       trx_isolation_level: REPEATABLE READ
         trx_unique_checks: 1
    trx_foreign_key_checks: 1
trx_last_foreign_key_error: NULL
 trx_adaptive_hash_latched: 0
 trx_adaptive_hash_timeout: 0
          trx_is_read_only: 0
trx_autocommit_non_locking: 0
       trx_schedule_weight: NULL
2 rows in set (0.00 sec)

２行出力されましたが、trx_started (トランザクション開始時間)が早い方が長い間完了していないことになります。

より長時間経過している１行目を見ると、trx_rows_modified（このトランザクションで変更および挿入された行の数）が３で、ここでも３行更新しているが完了していないことが読み取れます。また、trx_mysql_thread_id（MySQL スレッド ID）はSHOW PROCESSLISTのIdと一致するので、これはshow processlistのId:19を指しています。

過去発行したクエリも確認する

先ほどから目を付けているID:19が発行したクエリを見てみます。

まずはMySQL スレッド IDとperformance_schema.threadsからTHREAD_IDを取得します。

mysql> SELECT thread_id FROM performance_schema.threads WHERE processlist_id = 19;
+-----------+
| thread_id |
+-----------+
|        56 |
+-----------+
1 row in set (0.00 sec)

そのTHREAD_IDとperformance_schema.events_statements_historyから、過去のクエリが少し分かります。killして大丈夫かの判断材料になりそうです。

ただし、performance_schema.events_statements_history は最新10件（デフォルト）しか保持していないので、それより前の情報はここからは取得出来ません。

mysql> SELECT THREAD_ID,SQL_TEXT FROM performance_schema.events_statements_history WHERE thread_id = 56 ORDER BY TIMER_START;
+-----------+----------------------------------+
| THREAD_ID | SQL_TEXT                         |
+-----------+----------------------------------+
|        56 | select @@version_comment limit 1 |
|        56 | select $$                        |
|        56 | SELECT DATABASE()                |
|        56 | NULL                             |
|        56 | show databases                   |
|        56 | show tables                      |
|        56 | NULL                             |
|        56 | select * from users              |
|        56 | set autocommit = 0               |
|        56 | DELETE FROM users                |
+-----------+----------------------------------+
10 rows in set (0.00 sec)

情報を集めたので、最後にID:19をkillしてアップデートできるようになることを確認します。

mysql> kill 19;
Query OK, 0 rows affected (0.00 sec)

mysql> show processlist;
+----+------+-----------+------------+---------+------+-------+------------------+
| Id | User | Host      | db         | Command | Time | State | Info             |
+----+------+-----------+------------+---------+------+-------+------------------+
| 18 | root | localhost | example_db | Query   |    0 | init  | show processlist |
| 20 | root | localhost | example_db | Sleep   | 1911 |       | NULL             |
+----+------+-----------+------------+---------+------+-------+------------------+
2 rows in set, 1 warning (0.00 sec)

mysql> UPDATE users set name = 'ichiro' WHERE id = 1;
Query OK, 1 row affected (0.01 sec)
Rows matched: 1  Changed: 1  Warnings: 0

mysql> commit;
Query OK, 0 rows affected (0.01 sec)

-- id1のnameがTAROからichiroに更新されている
mysql> select * from users;
+----+--------+--------------------+
| id | name   | email              |
+----+--------+--------------------+
|  1 | ichiro | taro@example.com   |
|  2 | JIRO   | jiro@example.com   |
|  3 | SABURO | saburo@example.com |
+----+--------+--------------------+
3 rows in set (0.00 sec)

usersテーブルをアップデート出来ました。

今回は【MySQL】ERROR 1205 (HY000): Lock wait timeout exceeded; try restarting transactionが発生しkillしないと解決しない場合の調査方法についてまとめてみました。まだまだ知らないことが多いので、今後もMySQLを学んでいきたいと思います。

ブログ