2012-07-04

Mysql5.5でスロークエリに関して調べたのでまとめました。
Mysql5.1からスロークエリのパラメータが変わっているので注意しましょう。
そのためMysql5.1より前のバージョンでは内容が異なります。

設定を確認する

Mysqlのコンソールからshow variablesコマンドで、スロークエリの設定を確認できます。

mysql> show variables like 'slow%';
+---------------------+----------------+
| Variable_name       | Value          |
+---------------------+----------------+
| slow_launch_time    | 2              |
| slow_query_log      | OFF            |
| slow_query_log_file | mysql-slow.log |
+---------------------+----------------+

slow_query_log がOFFになっているとスロークエリの出力は行われません。

mysql> show variables like 'long%';
+-----------------+-----------+
| Variable_name   | Value     |
+-----------------+------------+
| long_query_time | 10.000000 |
+-----------------+-----------+

slow_query_logがONのとき、long_query_timeを超えるクエリがスロークエリとして出力されます。

スロークエリを出力する（コンソールからの設定）

コンソールから設定を変更する場合はset globalコマンドで変更することができます。

mysql> set global slow_query_log_file = '/tmp/mysql-slow.log';
mysql> set global long_query_time = 5;
mysql> set global slow_query_log = ON;

show vairables コマンドで設定を確認すると、変更されていることが確認できます。
long_query_time の値が変更されていない場合がありますが、その時は一度コンソールを閉じ
最ログインすると変更されていることが確認できます。
変更には相当のユーザー権限が必要です。rootでログイン出来る場合はrootで作業しましょう。

スロークエリを出力する（my.cnfの設定）

my.cnf にパラメータを設定してスロークエリのログを出力します。
root権限で設定ファイルを編集します。

$ sudo vim /etc/my.cnf

[mysqld]
slow_query_log
slow_query_log-file = /var/log/mysql/mysql-slow.sql
long_query_time = 5

slow_query_log = ONを記述することでスロークエリの出力を有効にします。
デフォルトでは無効になっています。
mysql5.0以前ではlog_slow_queriesというオプションなので、記述してある場合はコメントアウトしてください。

log_output=FILEが指定されているとき、slow_query_log_fileオプションで指定されているファイルへログが記録されます。
long_query_timeで何秒以上かかったスロークエリをログへ記録するかを指定します。
Mysql5.1から、1秒未満の秒数（マイクロ秒まで）を小数で指定できるようになりました。

mysqldumpslowを使って集計する

mysqldumpslow コマンドを使ってスロークエリの集計を行うことができます。
-s オプションでどの項目でソートするかを指定することができます。
例では t: query timeを指定しました。その他のオプションは -h でヘルプを確認して下さい。

$  mysqldumpslow -s t /var/log/mysql/mysql-slow.sql

Count: 93  Time=4.40s (409s)  Lock=0.00s (0s)  Rows=5.0 (465), ebisu[ebisu]@2hosts
  show index from `bom`.`logs`

Count: 86  Time=3.76s (323s)  Lock=0.00s (0s)  Rows=0.4 (34), meguro[meguro]@localhost
  SELECT `hash`.`id` FROM `hash` WHERE (`key` = 'S')

スロークエリとなっているSQLが種類別に集計され、実行時間の遅いものから順番にレポートされました。
これをもとに上から順に対策を行っていけば良いというわけです。

これを応用すると、スロークエリだけでなくすべてのクエリの実行状況を集計することができます。
先に説明したパラメータをコンソールから変更してすべてのクエリをログに出力するように設定しましょう。

mysql > set global slow_query_log_file = '/tmp/slow.log';
mysql > set global long_query_time = 0;

このように設定することで、/tmp/slow.logに実行されたすべてのSQLが出力されます。
こうすると相応の負荷がサーバーにかかるので、ディスクやCPUを観察しながら数十秒〜数分間待ってから設定をもとに戻します。
出力されたログファイルを分析しましょう。
今回はソートオプションに c: count を指定します。

$ mysqldumpslow -s  c /tmp/slow.log

Count: 27153  Time=0.00s (1s)  Lock=0.00s (0s)  Rows=0.0 (0), ebisu[ebisu]@localhost
  SELECT `m`.`id`, report.ratio  AS `ratio` FROM `l` AS `l`  LEFT JOIN `report` AS `report` ON l.id = report.l_id AND report.d = 'S' WHERE (l.p_id = 'S') AND (l.kind = 'S') AND (l.status = N) AND (l.deleted = N) AND (l.id not in (N))

Count: 18762  Time=0.00s (1s)  Lock=0.00s (0s)  Rows=0.0 (0), sugamo[sugamo]@localhost
  SELECT `settings`.`value` FROM `settings` WHERE (`key` = 'S')

Count: 4032  Time=0.00s (0s)  Lock=0.00s (0s)  Rows=0.0 (0), 2users@2hosts
  #

Count: 4031  Time=0.00s (0s)  Lock=0.00s (0s)  Rows=0.0 (0), tamachi[tamachi]@localhost
  SELECT `l`.* FROM `l` WHERE (id = N) AND (deleted = N)

Count: 4026  Time=0.00s (0s)  Lock=0.00s (0s)  Rows=0.0 (0), 0users@0hosts
  administrator command: Quit

Count: 4012  Time=0.00s (0s)  Lock=0.00s (0s)  Rows=0.0 (0), mejiro[mejiro]@localhost
  SELECT `filter`.`l_id` FROM `filter` WHERE (c_id = 'S') ORDER BY `l_id` asc

Count: 4012  Time=0.00s (3s)  Lock=0.00s (0s)  Rows=0.1 (563), yoyogi[yoyogi]@localhost
  SELECT `hash`.`id` FROM `hash` WHERE (`key` = 'S')

Count: 4012  Time=0.00s (0s)  Lock=0.00s (0s)  Rows=0.0 (0), osaki[osaki]@localhost
  set names 'S'

この方法をとれば、1回の実行には0.1秒しかかからないけれど毎分1万回実行されるため負荷の大半を占めている、
といったSQLを簡単に特定することができます。

スロークエリをDBに出力する

Mysql5.1からはスロークエリをログファイルではなくDBに保存することができるようになりました。
先にも少し出てきましたが、log_output オプションに TABLE を指定します。
my.cnf の場合は

[mysqld]
log_output = TABLE

コンソールからの場合は

mysql> set global log_output = 'TABLE';

そうするとスロークエリログが mysql.slow_log というテーブルに出力されるようになります。
また、あわせて一般ログも mysql.general_log というテーブルに出用されるのでこちらも意識しておいてください。

これらのテーブルはCSVストレージエンジンを用いて作成され、以下のような構成になります。

mysql> show create table mysql.slow_log \G
*************************** 1. row ***************************
       Table: slow_log
Create Table: CREATE TABLE `slow_log` (
  `start_time` timestamp NOT NULL DEFAULT CURRENT_TIMESTAMP ON UPDATE CURRENT_TIMESTAMP,
  `user_host` mediumtext NOT NULL,
  `query_time` time NOT NULL,
  `lock_time` time NOT NULL,
  `rows_sent` int(11) NOT NULL,
  `rows_examined` int(11) NOT NULL,
  `db` varchar(512) NOT NULL,
  `last_insert_id` int(11) NOT NULL,
  `insert_id` int(11) NOT NULL,
  `server_id` int(10) unsigned NOT NULL,
  `sql_text` mediumtext NOT NULL
) ENGINE=CSV DEFAULT CHARSET=utf8 COMMENT='Slow log'
1 row in set (0.00 sec)