MySQL のスロークエリログを解析する

スロークエリログを有効にする

Vim を使用して、/etc/mysql/mysql.conf.d/mysqld.cnf の以下の設定を有効にする

[mysqld]
slow_query_log = 1
slow_query_log_file = /var/log/mysql/mysql-slow.log
long_query_time = 0

Vim を起動するとき、以下のように sudo コマンドを使用しないと readonly で起動してしまう

sudo vim /etc/mysql/mysql.conf.d/mysqld.cnf

readonly で起動すると上書き保存がうまくいかなかったりしたので、一旦閉じて sudo で開くのが手っ取り早いかも（OK なのかは分からない😇）

設定が完了したら以下のコマンドで MySQL を再起動する

sudo systemctl restart mysql

どぎー

Vim のコマンド分からない

どぎー

MySQL のコマンドも分からない

どぎー

インデックスを貼る

MySQL にログインする

sudo mysql -u root

使用するデータベースを指定する

mysql> use isuconp
> Reading table information for completion of table and column names
> You can turn off this feature to get a quicker startup with -A
>
> Database changed

インデックスを貼る

mysql> ALTER TABLE comments ADD INDEX post_id_idx (post_id, created_at DESC);
> Query OK, 0 rows affected (0.77 sec)
> Records: 0  Duplicates: 0  Warnings: 0

一応インデックスが貼られているか確認する

mysql> show index from comments

インデックスを貼れていたら以下のようなログが出力される

+----------+------------+-------------+--------------+-------------+-----------+-------------+----------+--------+------+------------+---------+---------------+---------+------------+
| Table    | Non_unique | Key_name    | Seq_in_index | Column_name | Collation | Cardinality | Sub_part | Packed | Null | Index_type | Comment | Index_comment | Visible | Expression |
+----------+------------+-------------+--------------+-------------+-----------+-------------+----------+--------+------+------------+---------+---------------+---------+------------+
| comments |          0 | PRIMARY     |            1 | id          | A         |      100170 |     NULL |   NULL |      | BTREE      |         |               | YES     | NULL       |
| comments |          1 | post_id_idx |            1 | post_id     | A         |        9822 |     NULL |   NULL |      | BTREE      |         |               | YES     | NULL       |
| comments |          1 | post_id_idx |            2 | created_at  | D         |      100116 |     NULL |   NULL |      | BTREE      |         |               | YES     | NULL       |
+----------+------------+-------------+--------------+-------------+-----------+-------------+----------+--------+------+------------+---------+---------------+---------+------------+
3 rows in set (0.00 sec)

インデックスの確認方法はこちらを参考にした

どぎー

スロークエリログを確認する

pp.123~125 を参考にして pt-query-digest をインストールしたが、うまく動かず…（別途要調査）

代わりに "SHOW PROCESSLIST" 句を使用

mysql> SHOW PROCESSLIST;

以下のような結果となり、見たいデータ（各クエリの実行時間、実行数）を確認できず…（別途要調査）

+----+-----------------+-----------+---------+---------+------+------------------------+------------------+
| Id | User            | Host      | db      | Command | Time | State                  | Info             |
+----+-----------------+-----------+---------+---------+------+------------------------+------------------+
|  5 | event_scheduler | localhost | NULL    | Daemon  | 7112 | Waiting on empty queue | NULL             |
|  8 | isuconp         | localhost | isuconp | Sleep   |   12 |                        | NULL             |
| 12 | root            | localhost | isuconp | Sleep   |  558 |                        | NULL             |
| 13 | root            | localhost | NULL    | Query   |    0 | init                   | SHOW PROCESSLIST |
+----+-----------------+-----------+---------+---------+------+------------------------+------------------+
4 rows in set, 1 warning (0.00 sec)

結局、"mysqldumpslow" を使用

sudo mysqldumpslow /var/log/mysql/mysql-slow.log

以下のような出力を確認できた

Count: 2  Time=0.15s (0s)  Lock=0.00s (0s)  Rows=0.0 (0), isuconp[isuconp]@localhost
  DELETE FROM posts WHERE id > N

Count: 75  Time=0.02s (1s)  Lock=0.00s (0s)  Rows=0.0 (0), isuconp[isuconp]@localhost
  INSERT INTO `posts` (`user_id`, `mime`, `imgdata`, `body`) VALUES (N,'S','S','S')

Count: 62  Time=0.02s (1s)  Lock=0.00s (0s)  Rows=9938.5 (616187), isuconp[isuconp]@localhost
  SELECT `id`, `user_id`, `body`, `mime`, `created_at` FROM `posts` WHERE `created_at` <= 'S' ORDER BY `created_at` DESC
...

クエリ時間でソートしたかったので、明示的にオプションを指定した

sudo mysqldumpslow -s t /var/log/mysql/mysql-slow.log

以下のように、ボトルネックとなっているクエリを発見できた

Count: 15850  Time=0.00s (59s)  Lock=0.00s (0s)  Rows=1.1 (16800), isuconp[isuconp]@localhost
  SELECT * FROM `comments` WHERE `post_id` = N ORDER BY `created_at` DESC LIMIT N

Count: 16227  Time=0.00s (19s)  Lock=0.00s (0s)  Rows=1.0 (16227), isuconp[isuconp]@localhost
  SELECT COUNT(*) AS `count` FROM `comments` WHERE `post_id` = N

Count: 643  Time=0.02s (10s)  Lock=0.00s (0s)  Rows=10033.4 (6451487), isuconp[isuconp]@localhost
  SELECT `id`, `user_id`, `body`, `created_at`, `mime` FROM `posts` ORDER BY `created_at` DESC
...

💡 デフォルトだと平均クエリ時間でソートされるらしい

どぎー

ISUCON 本に言われるがままインデックスを貼ったので、実際にインデックスを貼った前後でパフォーマンスが向上しているのかを確認してみた

インデックスを貼った後

{"pass":true,"score":8464,"success":7221,"fail":0,"messages":[]}

インデックスを貼る前

{"pass":true,"score":421,"success":445,"fail":5,"messages":["リクエストがタイムアウトしました (POST /login)","リクエストがタイムアウトしました (POST /register)"]}

ちゃんと結果が変わっていた & クエリ時間が最大のクエリがボトルネックになっていたことを確認できた❗️

インデックスを削除するコマンドは以下を参考にした

どぎー

TODO

pt-query-digest を動かせるようにする
スロークエリログを解析する手順をまとめる
- スロークエリログを有効にする
- MySQL を再起動する
- スロークエリログを出力する
スロークエリログを解析観点を洗い出しておく
- クエリ時間
- 実行数
- 他にもある？

このスクラップは17日前にクローズされました