最近Webサイトのパフォーマンスチューニングにハマっている私、約8年の時を経てISUCONにまた挑戦してみようかなと考えている今日このごろです。ISUCONに興味がある人は練習問題とかもあるのでぜひお試しを~
今日はその中でMySQLのスロークエリについて計測して解析する方法を紹介したいと思います。スロークエリとは実行が遅いクエリのことで、スロークエリを見つけて修正することでWebページのパフォーマンスを大きく改善することができます。今回はMySQLについて記述していますが、PostgreSQLやOracle等にも同等の機能があるので計測・解析の流れは参考になるはず…!
スロークエリログを出力するための設定
MySQLのデフォルトではスロークエリログは出力されないので設定する必要があります。MySQLの設定ファイルのmy.cnfへ次のように記述することでスロークエリログが出力されるようになります。(環境によっては設定ファイルがmy.cnfではない場合があります。)設定後はMySQLの再起動を忘れずに!
[mysqld]
slow_query_log = 1 # スロークエリログを有効にする
slow_query_log_file = /var/log/mysql-slow.log # スロークエリログの出力ファイルの指定
long_query_time = 2 # ログとして残すクエリの閾値(秒)。この場合は2秒以上かかったクエリをログとして残す。
long_query_time=0とすることで全てのクエリをログとして出力することも可能ですが、ログが大量に出力されサーバーの処理能力やストレージを使ってしまうので0より大きい値を設定するのが一般的です。ただしlong_query_timeを0にすることでクエリ1つの処理時間は短くてもN+1問題により大量に発行されているクエリを見つけることができるので、開発環境やISUCONなどでは有効な設定となります。
スロークエリログの解析
mysqldumpslowを利用したスロークエリログの集計
mysqldumpslowコマンドでスロークエリログファイルを指定することで、集計結果をみることができます。今回はlong_query_time=0にしているので全てのクエリが集計されています。
$ mysqldumpslow /var/log/mysql-slow.log
Reading mysql slow query log from mysql-slow.log
Count: 1 Time=0.09s (0s) Lock=0.00s (0s) Rows=0.0 (0), root[root]@localhost
FLUSH LOGS
Count: 5 Time=0.07s (0s) Lock=0.00s (0s) Rows=0.0 (0), root[root]@webapp-app-1.webapp_default
DELETE FROM posts WHERE id > N
Count: 210 Time=0.03s (6s) Lock=0.00s (0s) Rows=0.0 (0), root[root]@webapp-app-1.webapp_default
INSERT INTO `posts` (`user_id`, `mime`, `imgdata`, `body`) VALUES ('S','S','S','S')
Count: 340 Time=0.01s (4s) Lock=0.00s (0s) Rows=0.0 (0), root[root]@webapp-app-1.webapp_default
INSERT INTO `comments` (`post_id`, `user_id`, `comment`) VALUES ('S','S','S')
集計結果は2行で1ブロックになっています。デフォルトでは実行時間の合計が長い順にソートされています。-s c オプションで発生回数にソートしたりもできます。
# 1ブロック分の集計
Count: 5 Time=0.07s (0s) Lock=0.00s (0s) Rows=0.0 (0), root[root]@webapp-app-1.webapp_default
DELETE FROM posts WHERE id > N
2行目にクエリの内容、1行目にクエリの集計情報がのっており次のような内容になっています。
Count | クエリが発行された回数 |
Time | クエリ1回あたりの平均処理時間(合計時間) |
Lock | クエリ1回あたりのテーブルロック平均時間(合計時間) |
Rows | 読み取り/更新した平均レコード数(合計レコード数) |
これらの数字から例えばCountが想定より多い場合は、どこかでN+1問題が起こっている可能性があることがわかります。またRowsが想定より多い場合は、Indexが正しく設定できていないということも読み取れます。これらの問題があったときの改善方法についてはまた別の記事で紹介したいと思います!