HHeLiBeXの日記 正道編

日々の記憶の記録とメモ‥

トランザクションを強制的に終了させる

MySQL PHP

前置き

MySQL 5.1で、InnoDBなデータベースを使って何かを開発している最中には、トランザクションがコミット(またはロールバック)される前にプログラム側の処理が(Fatal errorなどで)異常終了したりして、トランザクションがロックを取得したまま放置状態になってしまうことがよくあるらしい(謎)。
そんな時、MySQLのコマンドラインから更新クエリを発行すると、しばらく後に次のようなエラーが返ってくることがある。

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

一応参考までに書いておくと、このエラーが返ってくるまでの時間は、次のコマンドで知ることができる。

mysql> show global variables like 'innodb_lock_wait_timeout';
+--------------------------+-------+
| Variable_name            | Value |
+--------------------------+-------+
| innodb_lock_wait_timeout | 50    |
+--------------------------+-------+

この場合は50秒がタイムアウト時間である。

このような「ロックを取得したまま放置状態」は、次のようなプログラムで再現させることができる。

<?php
$mysql = mysql_pconnect('localhost:3306', 'root', 'pass');
mysql_select_db('test', $mysql);

mysql_query("start transaction", $mysql);
mysql_query("update hoge set title = 'AAA' where id = 1", $mysql);
?>

ポイントは3つ。

  • mysql_pconnect を使用して接続していること。
    • (未確認)デバッガを使って動作確認している場合等は、不意にプログラムが停止状態になり、mysql_connect でもコネクションが残るかもしれない
  • コミットやロールバックの処理がないこと(これは、何らかの要因で異常終了するケースのシミュレーション)
  • Apacheのモジュールなどを介して実行すること
    • コマンドラインで実行する場合は、コネクションプールもなにもなくPHPエンジン自体が終了するので、mysql_pconnectの意味がない(はず)

順番が前後したが、一応テーブル定義も書いておく。

create table hoge(id int not null primary key, title varchar(8) not null, ts timestamp);
insert into hoge(id, title) values(1, 'aaa'), (2, 'bbb');

冒頭のエラーは、このテーブルに対して以下のクエリを実行した場合のもの。

update hoge set title = 'aaaaaa' where id = 1;

本題

前置きが長くなったが、何かがロックを保持したままになっているケースの解決方法として、よく見るのが、「show processlist」や「show open tables」を使って特定するという方法。しかし、上記のPHPスクリプトを実行した後だと、「show open tables」を実行しても、updateクエリ自体は終了しているため、望む情報は出てこない。
もう(素のMySQL 5.1では)お手上げだと思っていたのだが、ヒントになる情報は取れるかもしれない。
それは、次のコマンドを実行したときに現れる。

mysql> show processlist;
+----+------+-----------------+------+---------+------+-------+------------------+
| Id | User | Host            | db   | Command | Time | State | Info             |
+----+------+-----------------+------+---------+------+-------+------------------+
| 12 | root | localhost:64970 | test | Sleep   |  960 |       | NULL             |
| 14 | root | localhost:65345 | test | Query   |    0 | NULL  | show processlist |
| 18 | root | localhost:50495 | test | Sleep   | 1306 |       | NULL             |
+----+------+-----------------+------+---------+------+-------+------------------+

mysql> show innodb status;
+--------+------+-----------------------------(略)
| Type   | Name | Status
+--------+------+-----------------------------(略)
| InnoDB |      |
=====================================
110330  2:26:34 INNODB MONITOR OUTPUT
=====================================
Per second averages calculated from the last 56 seconds
----------
SEMAPHORES
----------
OS WAIT ARRAY INFO: reservation count 89, signal count 89
Mutex spin waits 0, rounds 1011, OS waits 27
RW-shared spins 124, OS waits 62; RW-excl spins 1, OS waits 0
------------
TRANSACTIONS
------------
Trx id counter 0 15917
Purge done for trx's n:o < 0 15914 undo n:o < 0 0
History list length 8
LIST OF TRANSACTIONS FOR EACH SESSION:
---TRANSACTION 0 15916, not started, OS thread id 7688
MySQL thread id 14, query id 656 localhost 127.0.0.1 root
show innodb status
---TRANSACTION 0 15889, not started, OS thread id 6124
MySQL thread id 12, query id 653 localhost 127.0.0.1 root
---TRANSACTION 0 15914, ACTIVE 1156 sec, OS thread id 4932
2 lock struct(s), heap size 320, 1 row lock(s)
MySQL thread id 18, query id 645 localhost 127.0.0.1 root
Trx read view will not see trx with id >= 0 15915, sees < 0 15915
--------
FILE I/O
--------
(以下略)

このコマンドを実行したとき、実際に3つのコネクションが張られていた。

  1. 「show innodb status」や「show processlist」を実行したコマンドラインツールからのコネクション
  2. update文を発行してタイムアウトだと言われたコマンドラインツールからのコネクション
  3. 上記PHPスクリプトを実行した際にmysql_pconnectで生成されたコネクション

で、「show innodb status」の実行結果をよく見てみると、「TRANSACTIONS」という項目のところで、以下のような記述を見つけることができる。

---TRANSACTION 0 15914, ACTIVE 1156 sec, OS thread id 4932
2 lock struct(s), heap size 320, 1 row lock(s)
MySQL thread id 18, query id 645 localhost 127.0.0.1 root
Trx read view will not see trx with id >= 0 15915, sees < 0 15915

既に1156秒間(約20分間程)トランザクションがアクティブなままであることが分かる。さらに「1 row lock(s)」の記述も見て取ることができる。そしてスレッドIDが「18」であることも。
実際には、複数のトランザクションが走っている可能性があるので、すぐに特定はできないかもしれないが、何度か「show innodb status」や「show processlist」で情報を取ってみると、放置状態のトランザクションがどれであるのか、なんとなく推測ができるであろう。
通常、トランザクションは長くてもせいぜい数秒で終わらなければ、アプリケーションとしてのレスポンス要求を満たさないだろう。そんな中で10秒、20秒もアクティブであるトランザクションがあるとしたら、そもそも問題だし。
問題を引き起こしているスレッドが特定できたら、以下のコマンドで強制終了させればよい。

mysql> kill 18;

killした後の最初のmysql_pconnectで以下のようなWarningが出るが、まぁ気にしない。

Warning:  mysql_pconnect() [function.mysql-pconnect]: MySQL server has gone away in C:\path\to\mysql.php on line 9