Long query log

いつの間にか会社で古株になったyamaokaです。

webアプリケーションのバックエンドにMySQLを使っている場合、
クエリ(SQL)のチューニングをする必要がありますよね。
皆さんはチューニングの計画をどのように立てていますか。

もちろん、既に明らかに重いことが想定されているページがあれば、
その処理で使われているクエリを中心にEXPLAINなどを使って解析していけばいいと思います。

でもそうではなく、全体的にクエリの見直しやチューニングを行いたい場合は
実際に実行されているクエリを確認していくという作業が必要です。
そこで使うことができる3つの方法について書きたいと思います。

遅いクエリを記録する

MySQLにはスロークエリログといって、
実行に時間がかかったクエリを記録する機能が最初から付いています。
/etc/my.cnfに次のように設定を書けば実行時間が1秒を超えたクエリが出力されるようになります。

slow_query_log = 1
slow_query_log_file = /path/to/mysql-slow.log
long_query_time = 1

オンラインでset globalを使って変更する場合は次のようにします。

set global slow_query_log = 1;
set global slow_query_log_file = '/path/to/mysql-slow.log';
set global long_query_time = 1;

出力されたログファイルをMySQLに付属しているmysqldumpslowというツールで解析すると便利です。次のように実行すれば、平均の実行時間が長い順にソートして表示してくれます。

mysqldumpslow -s at /path/to/mysql-slow.log

クエリのパラメータは数値はN、文字列はSに置換して表示してくれるので
同じクエリをまとめてチェックすることができます。

実行回数の多いクエリを記録する

実行時間は短いけれど多くの回数実行されるクエリというのもあります。
これらは通常のスローログには出てこないのですが、
実は負荷の大部分を占めている、ということもありえます。
キャッシュなど別の方法を考えることで
アプリケーションの負荷を減らすことができるかもしれません。

従来MySQLではlong_query_timeに1秒以上の値しか設定できませんでしたが、
MySQL 5.1から1秒未満の値も設定できるようになりました。
つまり、次のように/etc/my.cnfで「0」を設定すれば
全てのクエリが記録できることになります。

slow_query_log = 1
slow_query_log_file = /path/to/mysql-slow.log
long_query_time = 0

もちろん、全てのクエリの記録は負荷も大きくかかることを
理解してから設定を行うようにしてください。
また、ログの容量も大きくなるので、ディスクの空き容量にも注意が必要です。
オンラインでset globalを使って一時的に値を0に変更し、すぐに元の値(1など)に戻すのがオススメです。

set global slow_query_log = 1;
set global slow_query_log_file = '/path/to/mysql-slow.log';
set global long_query_time = 0;
# 後で set global long_query_time = 1; で元に戻す

出力されたログファイルをmysqldumpslowで次のように解析することで、
実行回数の多い順に表示することが可能です。

mysqldumpslow -s c /path/to/mysql-slow.log

mysqldumpslowは他にもいろいろ機能を持っているので、「–help」を付けて実行して
一度オプションを確認してみるといいかもしれません。

追記: MySQLでは/etc/my.cnfに次のような設定をすることで全てのクエリを記録することが可能です。
最初から全ての記録を保存したい場合はこちらの方法もいいかもしれません。

log = /path/to/mysql-query.log

インデックスを使っていないクエリを記録する

多くの場合、インデックスを使用しないクエリは遅いです。
インデックスの設計は計画的に行う必要があると思いますが、
今現在インデックスを使用していないクエリはどれなのか知りたい場合があると思います。
次のように/etc/my.cnfに記述することでインデックスを使用していないクエリを
スロークエリログに記録することができるようになります。

slow_query_log = 1
slow_query_log_file = /path/to/mysql-slow.log
long_query_time = 5
log_queries_not_using_indexes = 1

オンラインでset globalを使って設定する場合は次のようにします。

set global slow_query_log = 1;
set global slow_query_log_file = '/path/to/mysql-slow.log';
set global long_query_time = 5;
set global log_queries_not_using_indexes = 1;

出力されたログファイルは今までと同じように
mysqldumpslowを使って解析していくことになると思います。

終わりに

最近は、開発するときにフレームワークに付属のORマッパーを使ったりして
実際に発行されるクエリを意識しないことが多くなっていると思います。
もちろんそれはメリットだと思うのですが、実際に実行されるのはクエリ(SQL)である以上、
完全に意識しないで済むということはありません。

実際に発行されているクエリを眺めつつ、
少しでもパフォーマンスのよいwebアプリケーションを作っていけたらいいと思います。

追記: オプションの変数名がMySQL 5.1基準のものになっていなかったのでMySQL 5.1をベースに修正しました。

Memo

[mysqld]
long_query_time=1
log-slow-queries=/var/log/mysql/log-slow-queries.log

You must create the file manually and change owners this way:

mkdir /var/log/mysql
touch /var/log/mysql/log-slow-queries.log
chown mysql.mysql -R /var/log/mysql

Advertisements

Leave a Reply

Fill in your details below or click an icon to log in:

WordPress.com Logo

You are commenting using your WordPress.com account. Log Out / Change )

Twitter picture

You are commenting using your Twitter account. Log Out / Change )

Facebook photo

You are commenting using your Facebook account. Log Out / Change )

Google+ photo

You are commenting using your Google+ account. Log Out / Change )

Connecting to %s