スロークエリログの見方
提供：MySQL Practice Wiki
目次 |
概要
スロークエリログのタイムスタンプ
複数のスロークエリがほぼ同時に完了した場合、より厳密に言うとタイムスタンプが同じになる場合、スロークエリログにはタイムスタンプが一つしか記録されない。タイムスタンプは秒単位なので、1秒以内の時間差で完了したスロークエリは同じタイムスタンプになる可能性がある。
スロークエリログはsql/log.cc内のMYSQL_LOG::write()関数を用いて記録される。MYSQL_LOGクラスにはlast_timeというメンバがありログの最終更新時刻（タイムスタンプ）を記録している。last_timeと現在時刻を比較し、違う場合にだけ整形されたタイムスタンプをログに書き込む。該当箇所のソースコードは以下の通りである。
if (current_time != last_time)
{
last_time=current_time;
struct tm tm_tmp;
struct tm *start;
localtime_r(¤t_time,&tm_tmp);
start=&tm_tmp;
/* Note that my_b_write() assumes it knows the length for this */
sprintf(buff,"# Time: %02d%02d%02d %2d:%02d:%02d\n",
start->tm_year % 100,
start->tm_mon+1,
start->tm_mday,
start->tm_hour,
start->tm_min,
start->tm_sec);
if (my_b_write(&log_file, (byte*) buff,24))
tmp_errno=errno;
}
同時に完了するスロークエリ
長時間かかるクエリが同時に完了する確率は高いだろうか？もしクエリの完了時刻が正規分布であれば、答えはNoである。それではクエリが同時に完了するというのはどういう状況なのだろうか？答えは「多くのクエリをブロックする処理があり、その処理に時間が掛かっている」というような場合である。
例えばInnoDBは行レベルロックにより複数のセッションによるトランザクションの同時実行を実装しているが、あるセッションがSELECT ... FOR UPDATEをした場合、該当行に対して処理を行おうとするセッションは全てブロックされる。そしてロックを保持しているセッションが処理を完了した瞬間、ロックを待っていたセッションが一斉に処理を継続および完了するというような状況が考えられる。
ただし、LOCK TABLESによりテーブルをロックした場合にはスロークエリログには情報が記録されない点に注意すること。
長時間ロックを占有するクエリの対策
ある一つのクエリが、長時間InnoDBのロックを占有してしまうという状況は非常に好ましくない。他のクエリの実行を妨げるからである。一度に大量のスロークエリが記録されるということは、多くのクエリの実行が一つのクエリによって妨げられていたということである。対策としては長時間かかっているクエリを最適化するというものである。
同一タイムスタンプのスロークエリのうち、先頭にあるクエリがロックを占有していたものである原因が非常に高い。
しかしそのようなクエリはスロークエリログには残らない場合があるので、定期的にSHOW PROCESSLISTやSHOW ENGINE INNODB STATUSを実行してMySQLサーバ内で何が起こっていたかを突き止めると良いだろう。
クエリの実行時間のカウント
クエリの実行時間は、必要なテーブルロックを獲得してから完了するまでとして計測される。sql/sql_parse.ccにおいて、関数log_slow_statement()が定義されているが、以下の比較によりスロークエリログを記録するかどうかを決定している。
if ((ulong) (thd->start_time - thd->time_after_lock) >
紛らわしいがthd->start_timeはクエリが完了した時間であり、thd->time_after_lockはロックを獲得した時間である。後者はsql/lock.cc内のmysql_lock_tables()関数においてセットされる。
スロークエリログサンプル
# Time: 080404 7:31:43 # User@Host: wikiya[wikiya] @ localhost [] # Query_time: 48 Lock_time: 0 Rows_sent: 0 Rows_examined: 0 UPDATE some_table SET some_column=1 WHERE some_condition=1;
2008年4月4日 午前7時31分43秒に記録されたログであることを示している。（InnoDBの行レベルロックを使用して、わざと発生させたスロークエリである。）
mysqldumpslowコマンド
mysqldumpslowコマンドは、MySQLに標準で付属するperlで書かれたユーティリティプログラムである。RPM版ではサーバパッケージにつバンドルされている。スロークエリログの内容を走査し、どのような種類のクエリに時間がかかっているかということについて統計情報をとってくれるコマンドである。スロークエリログに書かれたログの量が少しだけであればそのような統計は必要ないが、非常に多くのクエリが記録されている場合に効果を発揮する。
