Query_time - Lock_time > long_query_time
MySQL(InnoDB)でロック待ちタイムアウトになるクエリはスロークエリログに記録されるのか?
気になったので調べていた。
ロック待ちタイムアウト
- あるトランザクションで UPDATE 中の行を他のトランザクションから UPDATE しようとするとロック待ちになる
- ロック待ちの時間が innodb_lock_wait_timeout に設定された秒数を超えると
Lock wait timeout exceeded; try restarting transaction
というエラーが発生する
スロークエリログ (MySQl 5.0)
さて、このときスロークエリログは?
# Query_time: 51 Lock_time: 0 Rows_sent: 0 Rows_examined: 0 SET timestamp=1423478293; update ...
こういう記録が残っていた。 ちなみにバージョンは MySQL 5.0.96。
エラーが発生している時にリアルタイムでログを見ていたわけじゃないのでなんともだけど、
- エラーが発生しているクエリと同じ
- innodb_lock_wait_timeout は50秒で、Query_time: 51 となっている
という点からこれだろうな、と思った。
スロークエリログ (MySQl 5.6)
この状況を MySQL 5.6 で再現させたいので実験をしていたのだが、long_query_time=1
で実験してもタイムアウトしたクエリが出てこない。おかしいな?と思ってlong_query_time=0
にしたら以下のように出てきた。
# Query_time: 51.042682 Lock_time: 51.042330 Rows_sent: 0 Rows_examined: 0
んで、ちょっと考えるとスロークエリログに記録されるのは
Query_time - Lock_time > long_query_time
こういう条件なのだな、と思ったのだった。
long_query_time には(MySQL 5.1から)マイクロ秒まで指定できるので、試しに以下のように Query_time - Lock_time を少し下回る値を設定してみたら、今度はちゃんとログに出てきたのでした。
long_query_time=0.0001
MySQL のリファレンスを見る
MySQL 5.6 のリファレンス MySQL :: MySQL 5.6 Reference Manual :: 5.2.5 The Slow Query Log を見ると以下のように書いてあって
The time to acquire the initial locks is not counted as execution time.
これは long_query_time で指定する値(execution time)に ロック獲得時間が含まれないよ、ということなのかなあ(推測)。initial
というのがよくわからないけれど。(initial なロックとそうじゃないロックの違いって?)
ソースコード
MySQL 5.0.96 で Lock_time が 0 になるのが気になったのでソースをダウンロードしてきて追ってみた。Lock_time で grep すると以下のコードに辿り着くので変数名を頼りに少しさまよってみたのだが、力不足で追いきれなかった。無念。
sql/log.cc
2345 if (query_start_arg) 2346 { 2347 /* For slow query log */ 2348 if (my_b_printf(&log_file, 2349 "# Query_time: %lu Lock_time: %lu Rows_sent: %lu Rows_examined: %lu\n", 2350 (ulong) (current_time - query_start_arg), 2351 (ulong) (thd->time_after_lock - query_start_arg), 2352 (ulong) thd->sent_row_count, 2353 (ulong) thd->examined_row_count) == (uint) -1) 2354 tmp_errno=errno; 2355 }
まとめ
- スロークエリログには
Query_time - Lock_time > long_query_time
のクエリが記録される - Lock_time にはロックを獲得するまでの時間が記録される
- ただし MySQL 5.0 では Lock_time が 0 になっていた...
- ソースコードを追えばもっと深く理解できそうだけど、力不足だった
力不足なので以下の書籍を買って勉強します。
「第10章 MySQLのソースコードを追ってみよう」という章があるので読みます。
Webエンジニアのための データベース技術[実践]入門 (Software Design plus)
- 作者: 松信嘉範
- 出版社/メーカー: 技術評論社
- 発売日: 2012/03/09
- メディア: 単行本(ソフトカバー)
- 購入: 20人 クリック: 486回
- この商品を含むブログを見る