ヅラッシュ！ by NI-Lab.

スロークエリログ(Slow Query Log) は処理時間の長いクエリーをログに残す機能。

今回は OS: Debian GNU/Linux Sarge & MySQL 4.1 で試してみた。

mysqld を --log-slow-queries[=file_name] オプションで起動すると、実行に long_query_time 秒より長くかかった SQL コマンドがすべてログファイルに書き込まれます。最初のテーブルロックにかかった時間は実行時間に含まれません。
(中略)
スロークエリログは、実行に時間がかかり、最適化の対象となるクエリを見つけるために使用できます。大きなログでは、これは難しい作業になります。mysqldumpslow コマンドを使用すれば、ログのクエリサマリを取得できます。

MySQL AB :: MySQL 4.1 リファレンスマニュアル :: 4.10.5 スロークエリログ

英語版のドキュメントのほうが情報量が多い → MySQL AB :: MySQL 3.23, 4.0, 4.1 Reference Manual :: 5.11.5 The Slow Query Log

MySQL AB :: MySQL 4.1 リファレンスマニュアル :: 4.6.8.4 SHOW VARIABLES によると long_query_time の初期値は 10。

・set-variable = name=value
これは、コマンドラインの --set-variable=name=value と同等。 注意: --set-variable は MySQL 4.0 で廃止された。MySQL 4.0 では、プログラム変数名をオプション名として使用できる。コマンドラインでは、--name=value を使用する。オプション設定ファイルでは、name=value を使用する。

MySQL AB :: MySQL 4.1 リファレンスマニュアル :: 4.1.2 my.cnf オプション設定ファイル

/etc/mysql/my.cnf の [mysqld] セクションに以下を追加。

# 実行時間が1秒を超えたクエリをログファイルに記録する
log-slow-queries = /var/log/mysql/mysql-slow.log
long_query_time=1
# インデックスを使用しないクエリもスロークエリログに記録する
log-queries-not-using-indexes

実際に重いクエリーを実行してから、ログを見てみる。

localhost:/home/neko# tail -10 /var/log/mysql/mysql-slow.log
# Query_time: 14  Lock_time: 0  Rows_sent: 1  Rows_examined: 1
# administrator command: Execute;
# Time: 070721 15:47:19
# User@Host: hoge[hoge] @  [127.0.0.1]
# Query_time: 14  Lock_time: 0  Rows_sent: 1  Rows_examined: 1
# administrator command: Execute;
# Time: 070721 15:47:38
# User@Host: hoge[hoge] @  [127.0.0.1]
# Query_time: 7  Lock_time: 0  Rows_sent: 1  Rows_examined: 1
# administrator command: Execute;

なんだか期待したのとちがう……

SlowLogは，テキスト形式のファイルだ。処理時間がlong-query-timeを超えたSQL文が記録される。以下のような4行で1セットだ。

# Time: 040624 1:25:24
# User@Host: [ODBC] @ localhost [127.0.0.1]
# Query_time: 5 Lock_time: 0 Rows_sent: 30670 Rows_examined: 38828
select * from city ，country ，language where country.code=city.country and city.country=language.country;

1行目　記録日時
2行目　ユーザーIDとリクエストした端末
3行目　Query_time（実行時間）　Lock_time(ロック時間)　Rows_sent（送信行数）　Rows_examined（処理対象となった行数）
4行目　SQL文

このように設定時間を超えるSQL文が克明に記録される。

また，log-long-formatを指定していれば，インデックスを使用しなかったSQL文も記録される。Query_timeに関係なく記録されるので，見分けられるだろう。
【MySQLウォッチ】第8回 MySQLチューニングのテクニック：ITpro

やっぱり "administrator command: Execute;" というログはちょっとおかしいみたい。

「prepared statements を使ったときに、MySQL が役に立たないスロークエリーログを吐く」というバグがあるらしい。

When using prepared statements the slow query log contains no information about the statement itself, which makes it impossible to optimize statements:
(中略)
# Time: 050418 1:45:41
# User@Host: SAPMY1[SAPMY1] @ [10.17.70.89]
# Query_time: 103 Lock_time: 0 Rows_sent: 483077 Rows_examined: 483077
# administrator command: Execute;
(中略)
MySQL 4.1.14 works ok, so the bug is only in 5.
(中略)
fixed in 5.0.11
(中略)
I saw this in 4.1.10a. I'll check the logs once we upgrade to 4.1.14 or later to see if it's still happening.
MySQL Bugs: #9968: slow query log contains useless entries

これを見た感じでは、バグは修正されていると報告されつつも、4.1.14以降でもまだこの現象が出ているというコメントもある。

今回の環境は Debian GNU/Linux Sarge なので、

# COLUMNS=110 dpkg -l | grep mysql
ii  libdbd-mysql-perl     2.9006-1              A Perl5 database interface to the MySQL database
ii  libmysqlclient12      4.0.24-10sarge2       mysql database client library
ii  libmysqlclient14      4.1.11a-4sarge7       mysql database client library
ii  libmysqlclient14-dev  4.1.11a-4sarge7       mysql database development files
ii  mysql-client-4.1      4.1.11a-4sarge7       mysql database client binaries
ii  mysql-common-4.1      4.1.11a-4sarge7       mysql database common files (e.g. /etc/mysql/my.cnf)
ii  mysql-server-4.1      4.1.11a-4sarge7       mysql database server binaries

MySQL 4.1.11 ベースなので、あきらめるしかないかな。