はじめに
MySQLでデッドロックに関する問題があり調査したいとき、InnoDB Monitor出力の LATEST DETECTED DEADLOCK セクションから直近に発生したデッドロックを確認することができます。ただし、これは直近で発生した1件しか確認ができません。
innodb_print_all_deadlocksを有効にすることで発生したデッドロックの情報を全てエラーログに出力できます。しかし、デッドロックが頻発している場合、その分ログへの出力も増えてしまいます。
Percona Toolkitに含まれるpt-deadlock-loggerを使用することで、定期的にSHOW ENGINE INNODB STATUSを実行し、LATEST DETECTED DEADLOCKが更新されたときのみ、その情報を記録することができます。
pt-deadlock-loggerの使用
インストールと設定ファイル
pt-deadlock-loggerのインストールの詳細はマニュアルを確認してください。
|
1 |
# yum install percona-toolkit |
pt-deadlock-loggerのログインの簡略化のために、設定ファイルを追加しておきます
Percona Toolkitにおける設定ファイルの書き方については、マニュアルを確認してください。
|
1 2 3 4 5 |
$ cat > ~/.pt-deadlock-logger.conf <<-EOF user=pt_deadlock password=MySQL8.0 host=localhost EOF |
MySQL用のユーザを作成します。必要な権限はPROCESSです。
|
1 2 |
mysql> create user pt_deadlock@localhost identified with mysql_native_password by 'MySQL8.0'; mysql> grant PROCESS on *.* to pt_deadlock@localhost; |
使用方法
オプション無しで実行するとすぐにデッドロック情報の収集を開始します。
SHOW ENGINE INNODB STATUSの LATEST DETECTED DEADLOCK セクションから直近に発生したデッドロックの情報を取得し、そこから一部の情報を抜き出し出力します。
|
1 2 3 4 |
$ pt-deadlock-logger server ts thread txn_id txn_time user hostname ip db tbl idx lock_type lock_mode wait_hold victim query localhost 2023-03-16T12:13:29 81 0 8 root localhost sakila rental PRIMARY RECORD X w 1 INSERT INTO sakila.rental values (16060 , "2022-01-01 00:00:00" , 120, 220 , "2005-05-26 04:00:00" , 1, "2022-01-01 00:00:00") localhost 2023-03-16T12:13:29 86 0 12 root localhost sakila actor PRIMARY RECORD X w 0 UPDATE sakila.actor SET last_name = "DEF" WHERE actor_id =1 |
デフォルトでは30秒おきに永続的にSHOW ENGINE INNODB STATUSを実施し、前回とLATEST DETECTED DEADLOCKの内容が異なる場合は新たなデッドロックの情報を出力します。
役立つオプションを紹介します。
-
--run-time
終了するまでの実行時間。 デフォルトでは、pt-deadlock-logger は永久に実行され、--interval秒ごとにデッドロックをチェックします。 -
--interval
デッドロックをチェックする頻度。--run-timeが指定されていない場合、pt-deadlock-logger は無期限に実行され、間隔ごとにデッドロックをチェックします。デフォルトで30秒です。 -
--iterations
デッドロックをチェックする回数。デフォルトでは、このオプションは未定義であり、無限回の反復を意味します。
なお、--run-timeと--iterationsを同時に指定した場合は、常に--run-timeの指定時間で終了します。
例えば、--run-time 1m --iterations 4 --interval 30とすると、30秒間隔で4回実行すると2分かかりますが、ツールは開始から1分で終了します。
例
|
1 |
$ pt-deadlock-logger --run-time 1h --iterations 4 |
この場合、4秒間隔で1時間の間デッドロックの情報収集を続けます。
-
--daemonize
バックグラウンドで実行されます。 -
--log
出力先のファイルを指定できます。--daemonizeと一緒に使用します。
例
|
1 |
$ pt-deadlock-logger --daemonize --log=/var/log/mysql/deadlock.log |
2回デッドロックを発生させたときの出力例です。
|
1 2 3 4 5 6 |
$ cat /tmp/deadlock.log server ts thread txn_id txn_time user hostname ip db tbl idx lock_type lock_mode wait_hold victim query localhost 2023-03-16T12:13:29 81 0 8 root localhost sakila rental PRIMARY RECORD X w 1 INSERT INTO sakila.rental values (16060 , "2022-01-01 00:00:00" , 120, 220 , "2005-05-26 04:00:00" , 1, "2022-01-01 00:00:00") localhost 2023-03-16T12:13:29 86 0 12 root localhost sakila actor PRIMARY RECORD X w 0 UPDATE sakila.actor SET last_name = "DEF" WHERE actor_id =1 localhost 2023-03-16T18:49:05 81 0 10 root localhost sakila actor PRIMARY RECORD X w 1 UPDATE sakila.actor SET last_name = "DEF" WHERE actor_id =1 localhost 2023-03-16T18:49:05 86 0 227 root localhost sakila rental PRIMARY RECORD X w 0 UPDATE sakila.rental SET staff_id = 1 WHERE rental_id = 1 |
各収集方法の比較
デッドロックが何パターンか発生している可能性がある場合、SHOW ENGINE INNODB STATUSを1回実行するだけではデッドロックの情報を網羅的に集めることはできません。今回は、次の3つの方法を比較してみます
SHOW ENGINE INNODB STATUSを定期的に実行する- innodb_print_all_deadlocksを有効にする
- pt-deadlock-loggerを使用する
出力内容
デッドロックを起こしたあと、それぞれの出力内容を確認します。
デッドロックを発生させる
trx1とtrx2はそれぞれ別の接続であることを示しています。
|
1 2 3 4 5 6 7 8 9 |
mysql(trx1)> begin; mysql(trx1)> UPDATE sakila.actor SET last_name = "DEF" WHERE actor_id =1; mysql(trx2)> begin; mysql(trx2)> UPDATE sakila.rental SET staff_id = 1 WHERE rental_id = 1; mysql(trx1)> UPDATE sakila.rental SET staff_id = 1 WHERE rental_id = 1; mysql(trx2)> UPDATE sakila.actor SET last_name = "DEF" WHERE actor_id =1; ERROR 1213 (40001): Deadlock found when trying to get lock; try restarting transaction |
SHOW ENGINE INNODB STATUSの出力
|
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 38 39 40 41 42 43 44 45 46 47 48 49 50 51 52 53 54 55 56 57 58 59 60 61 62 63 64 65 66 67 68 69 70 71 72 73 74 75 76 77 78 79 80 81 82 83 84 85 86 87 88 89 |
mysql> SHOW ENGINE INNODB STATUS\G *************************** 1. row *************************** Type: InnoDB Name: Status: ===================================== 2023-03-16 18:51:05 140616227919616 INNODB MONITOR OUTPUT ===================================== Per second averages calculated from the last 10 seconds ----------------- BACKGROUND THREAD ----------------- srv_master_thread loops: 25 srv_active, 0 srv_shutdown, 27474 srv_idle srv_master_thread log flush and writes: 0 ... (略) ... ------------------------ LATEST DETECTED DEADLOCK ------------------------ 2023-03-16 18:49:05 140616286668544 *** (1) TRANSACTION: TRANSACTION 40783, ACTIVE 227 sec starting index read mysql tables in use 1, locked 1 LOCK WAIT 4 lock struct(s), heap size 1128, 2 row lock(s), undo log entries 1 MySQL thread id 86, OS thread handle 140616223700736, query id 393 localhost root updating UPDATE sakila.rental SET staff_id = 1 WHERE rental_id = 1 *** (1) HOLDS THE LOCK(S): RECORD LOCKS space id 56 page no 4 n bits 288 index PRIMARY of table 'sakila'.'actor' trx id 40783 lock_mode X locks rec but not gap Record lock, heap no 219 PHYSICAL RECORD: n_fields 6; compact format; info bits 0 0: len 2; hex 0001; asc ;; 1: len 6; hex 000000009f4f; asc O;; 2: len 7; hex 0200000146265e; asc F&^;; 3: len 8; hex 50454e454c4f5045; asc PENELOPE;; 4: len 3; hex 444546; asc DEF;; 5: len 4; hex 6412e52e; asc d .;; *** (1) WAITING FOR THIS LOCK TO BE GRANTED: RECORD LOCKS space id 80 page no 9 n bits 424 index PRIMARY of table 'sakila'.'rental' trx id 40783 lock_mode X locks rec but not gap waiting Record lock, heap no 2 PHYSICAL RECORD: n_fields 9; compact format; info bits 0 0: len 4; hex 80000001; asc ;; 1: len 6; hex 000000006191; asc a ;; 2: len 7; hex 82000001510110; asc Q ;; 3: len 5; hex 9975b16d5e; asc u m^;; 4: len 3; hex 00016f; asc o;; 5: len 2; hex 0082; asc ;; 6: len 5; hex 9975b5611e; asc u a ;; 7: len 1; hex 01; asc ;; 8: len 4; hex 43f31efd; asc C ;; *** (2) TRANSACTION: TRANSACTION 40784, ACTIVE 10 sec starting index read mysql tables in use 1, locked 1 LOCK WAIT 4 lock struct(s), heap size 1128, 2 row lock(s) MySQL thread id 81, OS thread handle 140615836735232, query id 394 localhost root updating UPDATE sakila.actor SET last_name = "DEF" WHERE actor_id =1 *** (2) HOLDS THE LOCK(S): RECORD LOCKS space id 80 page no 9 n bits 424 index PRIMARY of table 'sakila'.'rental' trx id 40784 lock_mode X locks rec but not gap Record lock, heap no 2 PHYSICAL RECORD: n_fields 9; compact format; info bits 0 0: len 4; hex 80000001; asc ;; 1: len 6; hex 000000006191; asc a ;; 2: len 7; hex 82000001510110; asc Q ;; 3: len 5; hex 9975b16d5e; asc u m^;; 4: len 3; hex 00016f; asc o;; 5: len 2; hex 0082; asc ;; 6: len 5; hex 9975b5611e; asc u a ;; 7: len 1; hex 01; asc ;; 8: len 4; hex 43f31efd; asc C ;; *** (2) WAITING FOR THIS LOCK TO BE GRANTED: RECORD LOCKS space id 56 page no 4 n bits 288 index PRIMARY of table 'sakila'.'actor' trx id 40784 lock_mode X locks rec but not gap waiting Record lock, heap no 219 PHYSICAL RECORD: n_fields 6; compact format; info bits 0 0: len 2; hex 0001; asc ;; 1: len 6; hex 000000009f4f; asc O;; 2: len 7; hex 0200000146265e; asc F&^;; 3: len 8; hex 50454e454c4f5045; asc PENELOPE;; 4: len 3; hex 444546; asc DEF;; 5: len 4; hex 6412e52e; asc d .;; *** WE ROLL BACK TRANSACTION (2) ... (略) ... ---------------------------- END OF INNODB MONITOR OUTPUT ============================ |
- エラーログの出力
|
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 38 39 40 41 42 43 44 45 46 47 48 49 50 51 52 53 54 55 |
$ less /var/log/mysqld.log ...(略) 2023-03-16T02:12:02.807801Z 0 [System] [MY-010931] [Server] /usr/sbin/mysqld: ready for connections. Version: '8.0.32' socket: '/var/lib/mysql/mysql.sock' port: 3306 MySQL Community Server - GPL. 2023-03-16T02:12:02.807885Z 0 [System] [MY-011323] [Server] X Plugin ready for connections. Bind-address: '::' port: 33060, socket: /var/run/mysqld/mysqlx.sock TRANSACTION 40783, ACTIVE 227 sec starting index read mysql tables in use 1, locked 1 LOCK WAIT 4 lock struct(s), heap size 1128, 2 row lock(s), undo log entries 1 MySQL thread id 86, OS thread handle 140616223700736, query id 393 localhost root updating UPDATE sakila.rental SET staff_id = 1 WHERE rental_id = 1 RECORD LOCKS space id 56 page no 4 n bits 288 index PRIMARY of table 'sakila'.'actor' trx id 40783 lock_mode X locks rec but not gap Record lock, heap no 219 PHYSICAL RECORD: n_fields 6; compact format; info bits 0 0: len 2; hex 0001; asc ;; 1: len 6; hex 000000009f4f; asc O;; 2: len 7; hex 0200000146265e; asc F&^;; 3: len 8; hex 50454e454c4f5045; asc PENELOPE;; 4: len 3; hex 444546; asc DEF;; 5: len 4; hex 6412e52e; asc d .;; RECORD LOCKS space id 80 page no 9 n bits 424 index PRIMARY of table 'sakila'.'rental' trx id 40783 lock_mode X locks rec but not gap waiting Record lock, heap no 2 PHYSICAL RECORD: n_fields 9; compact format; info bits 0 0: len 4; hex 80000001; asc ;; 1: len 6; hex 000000006191; asc a ;; 2: len 7; hex 82000001510110; asc Q ;; 3: len 5; hex 9975b16d5e; asc u m^;; 4: len 3; hex 00016f; asc o;; 5: len 2; hex 0082; asc ;; 6: len 5; hex 9975b5611e; asc u a ;; 7: len 1; hex 01; asc ;; 8: len 4; hex 43f31efd; asc C ;; TRANSACTION 40784, ACTIVE 10 sec starting index read mysql tables in use 1, locked 1 LOCK WAIT 4 lock struct(s), heap size 1128, 2 row lock(s) MySQL thread id 81, OS thread handle 140615836735232, query id 394 localhost root updating UPDATE sakila.actor SET last_name = "DEF" WHERE actor_id =1 RECORD LOCKS space id 80 page no 9 n bits 424 index PRIMARY of table 'sakila'.'rental' trx id 40784 lock_mode X locks rec but not gap Record lock, heap no 2 PHYSICAL RECORD: n_fields 9; compact format; info bits 0 0: len 4; hex 80000001; asc ;; 1: len 6; hex 000000006191; asc a ;; 2: len 7; hex 82000001510110; asc Q ;; 3: len 5; hex 9975b16d5e; asc u m^;; 4: len 3; hex 00016f; asc o;; 5: len 2; hex 0082; asc ;; 6: len 5; hex 9975b5611e; asc u a ;; 7: len 1; hex 01; asc ;; 8: len 4; hex 43f31efd; asc C ;; RECORD LOCKS space id 56 page no 4 n bits 288 index PRIMARY of table 'sakila'.'actor' trx id 40784 lock_mode X locks rec but not gap waiting Record lock, heap no 219 PHYSICAL RECORD: n_fields 6; compact format; info bits 0 0: len 2; hex 0001; asc ;; 1: len 6; hex 000000009f4f; asc O;; 2: len 7; hex 0200000146265e; asc F&^;; 3: len 8; hex 50454e454c4f5045; asc PENELOPE;; 4: len 3; hex 444546; asc DEF;; 5: len 4; hex 6412e52e; asc d .;; |
- pt-deadlock-loggerの出力
1234$ less /var/log/mysql/deadlock.logserver ts thread txn_id txn_time user hostname ip db tbl idx lock_type lock_mode wait_hold victim querylocalhost 2023-03-16T18:49:05 81 0 10 root localhost sakila actor PRIMARY RECORD X w 1 UPDATE sakila.actor SET last_name = "DEF" WHERE actor_id =1localhost 2023-03-16T18:49:05 86 0 227 root localhost sakila rental PRIMARY RECORD X w 0 UPDATE sakila.rental SET staff_id = 1 WHERE rental_id = 1
それぞれを比べると、SHOW ENGINE INNODB STATUSの出力とinnodb_print_all_deadlocksを有効にした場合のエラーログの出力はほとんど変わらないことがわかります。エラーログの方は*** (1) TRANSACTION:や*** (2) WAITING FOR THIS LOCK TO BE GRANTED:といった部分が出力されていません。また、*** WE ROLL BACK TRANSACTION (2)という出力もないため、エラーログからはどちらのトランザクションがロールバックされたかはわかりません。
また、SHOW ENGINE INNODB STATUSの出力にはデッドロックの情報以外にもInnoDBに関連する情報が多数含まれております。デッドロックの調査に役立つ情報が含まれているかもしれません。
pt-deadlock-loggerの出力は他の2つに比べるとかなり少ないです。ただし、発生した時間やデッドロックを起こしたクエリ、どのテーブルのロックが解放されるのを待機していたかなど、調査に有益な情報は多く含まれています。
また、innodb_print_all_deadlocksを有効にした場合の出力とpt-deadlock-loggerの出力の場合、デッドロックが新たに発生したらその情報が出力されます。つまり出力内容に重複はありません。
一方、SHOW ENGINE INNODB STATUSを定期的に実行して情報収集する場合、デッドロックが発生していないとLATEST DETECTED DEADLOCKの内容は毎回同じです。
発生したデッドロック情報の網羅性
SHOW ENGINE INNODB STATUSから確認できるデッドロック情報は直近の1件です。例えば、1分間隔でSHOW ENGINE INNODB STATUSを実行する場合、1分間に2回デッドロックが発生すると片方のデッドロックの情報は取得漏れしてしまします。
pt-deadlock-loggerもSHOW ENGINE INNODB STATUSから情報を取得するため、同じことが言えます。
一方、innodb_print_all_deadlocksは発生するたびにエラーログに出力するので、短い期間に連続して発生しても情報の取得漏れを起こすことはありません。
SHOW ENGINE INNODB STATUSの実行間隔を短くすることで網羅性は高まりますが、その分重複して出力される情報も多くなります。
どの程度網羅的にデッドロックの情報を集めたいかと考えて収集間隔は選択するといいでしょう。
実行の簡易性
それぞれの方法を実行するために必要な準備について比較します。
SHOW ENGINE INNODB STATUSを定期的に実行する場合、そもそも定期的に実行する際に人が手動で実行するのは現実的ではありません。
スクリプトを作成したりして自動で実行するようにするのが一般的でしょう。そのような準備が必要となります。
innodb_print_all_deadlocksは動的に変更できるため、SETコマンドを実行するだけですぐに有効化できます。
pt-deadlock-loggerはツールのインストールなどが必要です。使用するために複雑な設定は不要ですが、商用環境ではツールのインストールは許可されていないといったこともあるかもしれません。
まとめ
それぞれの方法にメリットデメリットがありました。
SHOW ENGINE INNODB STATUSの出力結果には様々な情報が含まれており、一見優れているようにも思いますが、SHOW ENGINE INNODB STATUSを普段から読み慣れていないと、逆にどの部分を確認すればいいか困ってしまうかもしれません。
pt-deadlock-loggerは重要な部分を抜き出してくれているので、あまりSHOW ENGINE INNODB STATUSを見慣れていない人にはおすすめです。
また、SHOW ENGIN INNODB STATUSは1h間隔、pt-deadlock-loggerのモニター間隔は1m間隔と組み合わせて使ってもいいかもしれません。
