読者です 読者をやめる 読者になる 読者になる

Query_time - Lock_time > long_query_time

mysql

MySQL(InnoDB)でロック待ちタイムアウトになるクエリはスロークエリログに記録されるのか?

気になったので調べていた。

ロック待ちタイムアウト

スロークエリログ (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)

Webエンジニアのための データベース技術[実践]入門 (Software Design plus)