Hatena::ブログ(Diary)

SH2の日記 RSSフィード

2009-06-18 MySQL InnoDBにおけるロック競合の解析手順 このエントリーを含むブックマーク

データベースの運用で避けられないのが、ロック競合によって起こるシステムトラブルへの対応です。「2時までに終わるはずのバッチ処理が朝になっても終わっていない」とか「負荷が高いわけでもないのにシステムが無応答になっている」といったトラブルが発生したとき、DBエンジニアはそれがロック競合によるものなのかどうかを切り分けて、適切に対処しなければなりません。

これまでInnoDBはロック競合に対してほとんど打つ手がなかったのですが、最近ようやく対処方法がでてきました。今日はその手順を確認していきたいと思います。

前提

今回ご紹介する手順は、MySQLの以下のバージョンを対象にしています。

いきなりハードルを上げてしまって申し訳ありませんが、バージョン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)

ここから、

といった情報を読み取ることができます。これは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)をご参照ください。

にしおかあすかにしおかあすか 2012/12/14 17:40 いつも拝見しております。すいません教えてください。blocking_infoにcommitが(requesting_infoにupdate)くるというこはどういうことなんでしょうか。。slow.logにも大量のcommitがでてきてなにをしたらいいのか・・・

sh2sh2 2012/12/14 20:57 そのままですが、COMMITをしているセッションがまだ抱えているロックを、UPDATEをしているセッションが要求しているということですね。

COMMITが遅くて困るという状況は珍しいですが、単にHDDが遅い、RAID 5なので書き込みが遅い、LVMスナップショットが存在していて遅い、ストレージのレイヤで同期レプリケーションをしていて遅い、準同期レプリケーションをしていて遅い、binlog_cache_sizeが足りていない、innodb_log_buffer_sizeが足りていない、アプリケーションの作りがおかしいといった点が考えられます。

とっかかりとしては、iostat -xm 10でw/s、await、%utilを観察する、SHOW ENGINE INNODB STATUSを何度か打ち込んでみて変な処理がないかチェックする、 http://d.hatena.ne.jp/sh2/20090414 を参考に1トランザクション分の処理を抜き出して何をやっているのか調べてみる、アプリケーション開発者を問い詰める、といったところから始めるとよいと思います。

にしおかあすかにしおかあすか 2012/12/18 18:09 ありがとうございました。iostat %utilで常に90-100%の状態でした。短時間でたくさんのcommitを行うとこうなっちゃうんですね。開発にcommit減らせないか確認します。。