MySQL InnoDBにおけるロック競合の解析手順
データベースの運用で避けられないのが、ロック競合によって起こるシステムトラブルへの対応です。「2時までに終わるはずのバッチ処理が朝になっても終わっていない」とか「負荷が高いわけでもないのにシステムが無応答になっている」といったトラブルが発生したとき、DBエンジニアはそれがロック競合によるものなのかどうかを切り分けて、適切に対処しなければなりません。
これまでInnoDBはロック競合に対してほとんど打つ手がなかったのですが、最近ようやく対処方法がでてきました。今日はその手順を確認していきたいと思います。
前提
今回ご紹介する手順は、MySQLの以下のバージョンを対象にしています。
- MySQL 5.1＋InnoDB Plugin 1.0
- MySQL 5.4
いきなりハードルを上げてしまって申し訳ありませんが、バージョン5.0以下や素の5.1では使えませんのでご注意ください。以降の実行例はすべてMySQL Community Server 5.1.35＋InnoDB Plugin 1.0.3で行ったものです。
information_schemaの新しいテーブル
InnoDBの最新バージョンでは、information_schemaデータベースに新しいテーブルが7つ追加されています。
mysql> show tables like 'INNO%'; +--------------------------------------+ | Tables_in_information_schema (INNO%) | +--------------------------------------+ | INNODB_CMP_RESET | | INNODB_TRX | | INNODB_CMPMEM_RESET | | INNODB_LOCK_WAITS | | INNODB_CMPMEM | | INNODB_CMP | | INNODB_LOCKS | +--------------------------------------+ 7 rows in set (0.01 sec)
もうお分かりかと思いますが、これらのテーブルからロック状態を取得することができるというわけです。今回はこのうち3つを使います。まずはINNODB_TRXから確認していきましょう。
mysql> desc INNODB_TRX;
+-----------------------+---------------------+------+-----+---------------------+-------+
| Field | Type | Null | Key | Default | Extra |
+-----------------------+---------------------+------+-----+---------------------+-------+
| trx_id | varchar(18) | NO | | | |
| trx_state | varchar(13) | NO | | | |
| trx_started | datetime | NO | | 0000-00-00 00:00:00 | |
| trx_requested_lock_id | varchar(81) | YES | | NULL | |
| trx_wait_started | datetime | YES | | NULL | |
| trx_weight | bigint(21) unsigned | NO | | 0 | |
| trx_mysql_thread_id | bigint(21) unsigned | NO | | 0 | |
| trx_query | varchar(1024) | YES | | NULL | |
+-----------------------+---------------------+------+-----+---------------------+-------+
8 rows in set (0.00 sec)
mysql> select * from INNODB_TRX order by trx_id\G
*************************** 1. row ***************************
trx_id: F09
trx_state: RUNNING
trx_started: 2009-06-17 23:03:18
trx_requested_lock_id: NULL
trx_wait_started: NULL
trx_weight: 3
trx_mysql_thread_id: 8
trx_query: NULL
*************************** 2. row ***************************
trx_id: F0A
trx_state: LOCK WAIT
trx_started: 2009-06-17 23:03:21
trx_requested_lock_id: F0A:3:3:9
trx_wait_started: 2009-06-17 23:03:21
trx_weight: 2
trx_mysql_thread_id: 9
trx_query: update emp set sal = sal + 200 where empno = 7788
2 rows in set (0.00 sec)INNODB_TRXは現在実行中のトランザクションを表示するテーブルです。InnoDBが内部で持っているトランザクションID(trx_id)やトランザクションの開始時刻(trx_started)、実行中のSQLがあればそのSQL文(trx_query)が出力されます。InnoDBのトランザクションIDとshow processlistで表示されるスレッドID(trx_mysql_thread_id)との対応づけができるところもポイントです。
次はINNODB_LOCKSです。
mysql> desc INNODB_LOCKS;
+-------------+---------------------+------+-----+---------+-------+
| Field | Type | Null | Key | Default | Extra |
+-------------+---------------------+------+-----+---------+-------+
| lock_id | varchar(81) | NO | | | |
| lock_trx_id | varchar(18) | NO | | | |
| lock_mode | varchar(32) | NO | | | |
| lock_type | varchar(32) | NO | | | |
| lock_table | varchar(1024) | NO | | | |
| lock_index | varchar(1024) | YES | | NULL | |
| lock_space | bigint(21) unsigned | YES | | NULL | |
| lock_page | bigint(21) unsigned | YES | | NULL | |
| lock_rec | bigint(21) unsigned | YES | | NULL | |
| lock_data | varchar(8192) | YES | | NULL | |
+-------------+---------------------+------+-----+---------+-------+
10 rows in set (0.01 sec)
mysql> select * from INNODB_LOCKS order by lock_id\G
*************************** 1. row ***************************
lock_id: F09:3:3:9
lock_trx_id: F09
lock_mode: X
lock_type: RECORD
lock_table: `scott`.`emp`
lock_index: `PRIMARY`
lock_space: 3
lock_page: 3
lock_rec: 9
lock_data: 0x9E6C
*************************** 2. row ***************************
lock_id: F0A:3:3:9
lock_trx_id: F0A
lock_mode: X
lock_type: RECORD
lock_table: `scott`.`emp`
lock_index: `PRIMARY`
lock_space: 3
lock_page: 3
lock_rec: 9
lock_data: 0x9E6C
2 rows in set (0.00 sec)INNODB_LOCKSはロック競合を起こしているトランザクションの情報を表示するテーブルです。待たせている方と待たされている方の両方が出力されます。一方、ロックを取得していても他のセッションと競合していないトランザクションは出力されません。ここでは、どのテーブル(lock_table)のどのインデックス(lock_index)をつかんでいるかが分かるようになっているところがポイントです。
3つ目は、INNODB_LOCK_WAITSです。
mysql> desc INNODB_LOCK_WAITS; +-------------------+-------------+------+-----+---------+-------+ | Field | Type | Null | Key | Default | Extra | +-------------------+-------------+------+-----+---------+-------+ | requesting_trx_id | varchar(18) | NO | | | | | requested_lock_id | varchar(81) | NO | | | | | blocking_trx_id | varchar(18) | NO | | | | | blocking_lock_id | varchar(81) | NO | | | | +-------------------+-------------+------+-----+---------+-------+ 4 rows in set (0.00 sec) mysql> select * from INNODB_LOCK_WAITS\G *************************** 1. row *************************** requesting_trx_id: F0A requested_lock_id: F0A:3:3:9 blocking_trx_id: F09 blocking_lock_id: F09:3:3:9 1 row in set (0.01 sec)
INNODB_LOCK_WAITSはどのトランザクションがどのトランザクションを待たせているのかを出力するテーブルです。blockingが待たせている方、requestingが待たされている方になります。
ロック競合を表示するSQL
このように、InnoDBの最新バージョンではロック競合を出力するための部品が十分に揃っています。あとは解析に必要な情報をつなげて出してあげればよいというわけです。例えば以下のようなSQLになるでしょう。
select t_b.trx_mysql_thread_id blocking_id,
t_w.trx_mysql_thread_id requesting_id,
p_b.HOST blocking_host,
p_w.HOST requesting_host,
l.lock_table lock_table,
l.lock_index lock_index,
l.lock_mode lock_mode,
p_w.TIME seconds,
p_b.INFO blocking_info,
p_w.INFO requesting_info
from information_schema.INNODB_LOCK_WAITS w,
information_schema.INNODB_LOCKS l,
information_schema.INNODB_TRX t_b,
information_schema.INNODB_TRX t_w,
information_schema.PROCESSLIST p_b,
information_schema.PROCESSLIST p_w
where w.blocking_lock_id = l.lock_id
and w.blocking_trx_id = t_b.trx_id
and w.requesting_trx_id = t_w.trx_id
and t_b.trx_mysql_thread_id = p_b.ID
and t_w.trx_mysql_thread_id = p_w.ID
order by requesting_id,
blocking_id
\G実行結果(横)です。
+-------------+---------------+-----------------+-----------------+---------------+------------+-----------+---------+---------------+---------------------------------------------------+ | blocking_id | requesting_id | blocking_host | requesting_host | lock_table | lock_index | lock_mode | seconds | blocking_info | requesting_info | +-------------+---------------+-----------------+-----------------+---------------+------------+-----------+---------+---------------+---------------------------------------------------+ | 8 | 9 | localhost:37001 | localhost:37002 | `scott`.`emp` | `PRIMARY` | X | 72 | NULL | update emp set sal = sal + 200 where empno = 7788 | +-------------+---------------+-----------------+-----------------+---------------+------------+-----------+---------+---------------+---------------------------------------------------+ 1 row in set (0.01 sec)
実行結果(縦)です。
*************************** 1. row ***************************
blocking_id: 8
requesting_id: 9
blocking_host: localhost:37001
requesting_host: localhost:37002
lock_table: `scott`.`emp`
lock_index: `PRIMARY`
lock_mode: X
seconds: 86
blocking_info: NULL
requesting_info: update emp set sal = sal + 200 where empno = 7788
1 row in set (0.00 sec)ここから、
- 8番のスレッドが9番のスレッドを86秒間待たせている
- 8番のスレッドはempテーブルの主キーを排他ロック(X)している
- 8番のスレッドは現在アイドル状態である
- 9番のスレッドはempno = 7788のレコードを更新しようとしている
といった情報を読み取ることができます。これはOracle Databaseと遜色のない内容になっており(参考：ロックをつぶせ！ 最初に疑うべき原因（1/3） − ＠IT)、ほぼ完璧といってよいレベルです。
それから、今回の例のようにデータベースにTCP/IP経由で接続している場合は、TCPのポート番号からクライアントプロセスを特定することができます。
# netstat -np | grep 37001 tcp 0 0 127.0.0.1:37001 127.0.0.1:3306 ESTABLISHED 6105/mysql tcp 0 0 127.0.0.1:3306 127.0.0.1:37001 ESTABLISHED 6000/mysqld
この例では8番のクライアントはmysqlコマンドラインツールであり、プロセスIDは6105番であることが分かります。ここまで分かればあとは該当のプロセスをkillするといった暫定対処や、プログラムを修正するといった本格対処をとることができます。
所感
InnoDBはやはりYet Another Oracle Databaseとしてとらえる人が多く、そのとき機能面でOracle DatabaseにあってInnoDBにないものは何かと考えると、今回のようなロックの可視化とデッドロックのロギングが常に上位に来ます。
2008年にMySQL Conference & ExpoでInnoDBの会議に出席したのですが、周りの参加者は案の定Oracleエンジニアがほとんどでしたし、みな口々にロックが見えるようにしろと要望を出していました。これがようやくMySQL 5.4で実装される運びとなり、いよいよMySQLも企業向けの利用が進むことになるのかもしれません。ラリー・エリソンがヘソを曲げなければ(^^;
2009/06/27追記
MySQL 5.4についてですが、5.4.1の時点ではまだこれらのinformation schemaのテーブル群は実装されていませんのでご注意ください。新機能のアナウンスについてはMySQL Conference & Expo 2009の資料InnoDB: Innovative Technologies for Performance and Data Protection (PDF)をご参照ください。