MySQLのslow queryを出してEXPLAINしてインデックスを張る

2019-09-21 database mysql

MySQLのslow queryを出してEXPLAINしてインデックスを張るのを ISUCON9の予選問題でやってみる。

$ mysql --version
mysql  Ver 8.0.17 for osx10.14 on x86_64 (Homebrew)

slow_query_logをONにすると実行時間がlong_query_timeを超えていてmin_examined_row_limit以上の行を返すクエリがslow query logに出力される。 log_queries_not_using_indexesが有効ならインデックスを使用してないクエリもログに出て、 log_throttle_queries_not_using_indexesでその分あたりの数を制限できる。 MySQL 8.0.14から追加されたlog_slow_extraをONにするとフィールドが追加される。

mysql> show variables like '%slow%';
+---------------------------+-----------------------------------+
| Variable_name             | Value                             |
+---------------------------+-----------------------------------+
| log_slow_admin_statements | OFF                               |
| log_slow_extra            | OFF                               |
| log_slow_slave_statements | OFF                               |
| slow_launch_time          | 2                                 |
| slow_query_log            | OFF                               |
| slow_query_log_file       | /usr/local/var/mysql/mbp-slow.log |
+---------------------------+-----------------------------------+
6 rows in set (0.00 sec)

mysql> show variables like '%long_query%';
+-----------------+-----------+
| Variable_name   | Value     |
+-----------------+-----------+
| long_query_time | 10.000000 |
+-----------------+-----------+
1 row in set (0.00 sec)

mysql> show variables like '%not_using_indexes%';
+----------------------------------------+-------+
| Variable_name                          | Value |
+----------------------------------------+-------+
| log_queries_not_using_indexes          | OFF   |
| log_throttle_queries_not_using_indexes | 0     |
+----------------------------------------+-------+
2 rows in set (0.00 sec)


mysql> show variables like '%min_examined%';
+------------------------+-------+
| Variable_name          | Value |
+------------------------+-------+
| min_examined_row_limit | 0     |
+------------------------+-------+
1 row in set (0.01 sec)

ということでslow_query_logをONにして100ms以上のクエリを出すようにする。 set persistはMySQL 8.0からの構文でset globalとは異なり再起動しても消えない。

mysql> set persist slow_query_log = ON;
mysql> set persist long_query_time = 0.1;

ベンチマークを実行しslow.logが出ていることを確認する。

$ ./bin/benchmarker
{"pass":true,"score":2510,"campaign":0,"language":"Go","messages":[]}

$ head /usr/local/var/mysql/mbp-slow.log 
/usr/local/Cellar/mysql/8.0.17_1/bin/mysqld, Version: 8.0.17 (Homebrew). started with:
Tcp port: 3306  Unix socket: /tmp/mysql.sock
Time                 Id Command    Argument
# Time: 2019-09-19T00:52:13.957303Z
# User@Host: isucari[isucari] @ localhost [127.0.0.1]  Id:    23
# Query_time: 0.121599  Lock_time: 0.000058 Rows_sent: 49  Rows_examined: 50051
use isucari;
SET timestamp=1568854333;
SELECT * FROM `items` WHERE `seller_id` = 818 AND `status` IN ('on_sale','trading','sold_out') AND (`created_at` < '2019-08-12 09:59:09'  OR (`created_at` <= '2019-08-12 09:59:09' AND `id` < 28740)) ORDER BY `created_at` DESC, `id` DESC LIMIT 49;
# Time: 2019-09-19T00:52:14.000428Z

mysqldumpslowで平均実行時間(at)順にまとめて出力できる。

$ mysqldumpslow -s at /usr/local/var/mysql/mbp-slow.log

Reading mysql slow query log from /usr/local/var/mysql/mbp-slow.log
Count: 44  Time=0.29s (12s)  Lock=0.00s (0s)  Rows=49.0 (2156), isucari[isucari]@localhost
  SELECT * FROM `items` WHERE `status` IN ('S','S') AND (`created_at` < 'S'  OR (`created_at` <= 'S' AND `id` < N)) ORDER BY `created_at` DESC, `id` DESC LIMIT N

Count: 5  Time=0.19s (0s)  Lock=0.00s (0s)  Rows=0.0 (0), isucari[isucari]@localhost
  #

Count: 24  Time=0.19s (4s)  Lock=0.00s (0s)  Rows=34.2 (821), isucari[isucari]@localhost
  SELECT * FROM `items` WHERE `seller_id` = N AND `status` IN ('S','S','S') AND (`created_at` < 'S'  OR (`created_at` <= 'S' AND `id` < N)) ORDER BY `created_at` DESC, `id` DESC LIMIT N

Count: 6  Time=0.19s (1s)  Lock=0.00s (0s)  Rows=9.2 (55), isucari[isucari]@localhost
  SELECT * FROM `items` WHERE (`seller_id` = N OR `buyer_id` = N) AND `status` IN ('S','S','S','S','S') ORDER BY `created_at` DESC, `id` DESC LIMIT N

Count: 10  Time=0.18s (1s)  Lock=0.00s (0s)  Rows=49.0 (490), isucari[isucari]@localhost
  SELECT * FROM `items` WHERE `status` IN ('S','S') AND category_id IN (N, N, N, N) AND (`created_at` < 'S'  OR (`created_at` <= 'S' AND `id` < N)) ORDER BY `created_at` DESC, `id` DESC LIMIT N

Count: 48  Time=0.18s (8s)  Lock=0.00s (0s)  Rows=17.2 (828), isucari[isucari]@localhost
  SELECT * FROM `items` WHERE `seller_id` = N AND `status` IN ('S','S','S') ORDER BY `created_at` DESC, `id` DESC LIMIT N

Count: 92  Time=0.17s (15s)  Lock=0.00s (0s)  Rows=49.0 (4508), isucari[isucari]@localhost
  SELECT * FROM `items` WHERE `status` IN ('S','S') AND category_id IN (N, N, N, N, N) AND (`created_at` < 'S'  OR (`created_at` <= 'S' AND `id` < N)) ORDER BY `created_at` DESC, `id` DESC LIMIT N

Count: 1  Time=0.17s (0s)  Lock=0.00s (0s)  Rows=49.0 (49), isucari[isucari]@localhost
  SELECT * FROM `items` WHERE `status` IN ('S','S') AND category_id IN (N, N, N, N, N, N) ORDER BY created_at DESC, id DESC LIMIT N
...

最も時間がかかっていた形式のクエリをEXPLAINしてみる。

mysql> EXPLAIN SELECT * FROM `items` WHERE `status` IN ('on_sale','sold_out') AND (`created_at` < '2019-08-12 15:41:31'  OR (`created_at` <= '2019-08-12 15:41:31' AND `id` < 49288)) ORDER BY `created_at` DESC, `id` DESC LIMIT 49 \G;
*************************** 1. row ***************************
           id: 1
  select_type: SIMPLE
        table: items
   partitions: NULL
         type: ALL
possible_keys: PRIMARY
          key: NULL
      key_len: NULL
          ref: NULL
         rows: 43831
     filtered: 16.29
        Extra: Using where; Using filesort
1 row in set, 1 warning (0.01 sec)

UNIONやサブクエリがないのでselect_type=SIMPLEで、またJOINもしていないので一件しか返ってこない。possible_keysがPRIMARYしかないため何のインデックスも使わず(key=NULL)フルテーブルスキャン(type=ALL)しているのをなんとかしたい。

mysql> show index from items \G;
*************************** 1. row ***************************
        Table: items
   Non_unique: 0
     Key_name: PRIMARY
 Seq_in_index: 1
  Column_name: id
    Collation: A
  Cardinality: 43827
     Sub_part: NULL
       Packed: NULL
         Null: 
   Index_type: BTREE
      Comment: 
Index_comment: 
      Visible: YES
   Expression: NULL
*************************** 2. row ***************************
        Table: items
   Non_unique: 1
     Key_name: idx_category_id
 Seq_in_index: 1
  Column_name: category_id
    Collation: A
  Cardinality: 34
     Sub_part: NULL
       Packed: NULL
         Null: 
   Index_type: BTREE
      Comment: 
Index_comment: 
      Visible: YES
   Expression: NULL
2 rows in set (0.01 sec)

そこでcreated_atにインデックスを張る。(status, created_at)の複合キーも試してみたがstatusのカーディナリティが低いからか使われなかった。created_atは範囲で取るので(created_at, status)だとstatusを絞るためにB+Treeのleaf nodeを全て見ていく必要があり意味がない。また、SELECTのカラムを絞って必要なデータがleaf nodeに揃っているカバリングインデックスにできれば、PKのB+Treeを見にいく必要がなくなり速くなるが、今回はクエリの内容は変えないことにする。

mysql> ALTER TABLE items ADD INDEX idx_created_at (created_at);

EXPLAINしてインデックスが使われていることを確認する。

mysql> ALTER TABLE items ADD INDEX idx_created_at (created_at);
mysql> EXPLAIN SELECT * FROM `items` WHERE `status` IN ('on_sale','sold_out') AND (`created_at` < '2019-08-12 15:41:31'  OR (`created_at` <= '2019-08-12 15:41:31' AND `id` < 49288)) ORDER BY `created_at` DESC, `id` DESC LIMIT 49 \G;
*************************** 1. row ***************************
           id: 1
  select_type: SIMPLE
        table: items
   partitions: NULL
         type: range
possible_keys: PRIMARY,idx_created_at
          key: idx_created_at
      key_len: 13
          ref: NULL
         rows: 21916
     filtered: 40.00
        Extra: Using index condition; Using where; Backward index scan
1 row in set, 1 warning (0.01 sec)

この状態で再度ベンチマークを実行したところ少しスコアが上がりslow.logに対象のクエリが出なくなった。

$ rm /usr/local/var/mysql/mbp-slow.log
$ touch /usr/local/var/mysql/mbp-slow.log
$ mysql.server restart
$ ./bin/benchmarker
{"pass":true,"score":2710,"campaign":0,"language":"Go","messages":[]}

$ $ mysqldumpslow -s at /usr/local/var/mysql/mbp-slow.log | grep 'SELECT * FROM `items` WHERE `SELECT * FROM `items` WHERE `status` IN ('S','S') AND (`created_at` < 'S'  OR (`created_at` <= 'S' AND `id` < N)) ORDER BY `created_at` DESC, `id` DESC LIMIT N'

Reading mysql slow query log from /usr/local/var/mysql/mbp-slow.log

参考

漢(オトコ)のコンピュータ道: MySQLのEXPLAINを徹底解説!!

MySQL with InnoDB のインデックスの基礎知識とありがちな間違い - クックパッド開発者ブログ