mysql slow query を眺めて改善する

[k5342]

ref: #8

mysqld: File '/home/isucon/slow_query.log' not found (Errcode: 13 - Permission denied)
2020-09-12T06:43:31.969977Z 0 [ERROR] Could not use /home/isucon/slow_query.log for logging (error 13 - Permission denied). Turning logging off for the server process. To turn it on again: fix the cause, then either restart the query logging by using "SET GLOBAL SLOW_QUERY_LOG=ON" or restart the MySQL server.

[chigichan24]

/usr/sbin/mysqld, Version: 5.7.31-0ubuntu0.18.04.1 ((Ubuntu)). started with:
Tcp port: 3306  Unix socket: /var/run/mysqld/mysqld.sock
Time                 Id Command    Argument
# Time: 2020-09-12T07:04:29.503403Z
# User@Host: isucon[isucon] @ localhost [127.0.0.1]  Id:   325
# Query_time: 0.887994  Lock_time: 0.000000 Rows_sent: 0  Rows_examined: 0
use isuumo;
SET timestamp=1599894269;
COMMIT;
# Time: 2020-09-12T07:04:30.468267Z
# User@Host: isucon[isucon] @ localhost [127.0.0.1]  Id:   330
# Query_time: 0.978713  Lock_time: 0.000000 Rows_sent: 0  Rows_examined: 0
SET timestamp=1599894270;
COMMIT;
# Time: 2020-09-12T07:04:30.468730Z
# User@Host: isucon[isucon] @ localhost [127.0.0.1]  Id:   329
# Query_time: 1.685014  Lock_time: 0.000000 Rows_sent: 0  Rows_examined: 0
SET timestamp=1599894270;
COMMIT;
# Time: 2020-09-12T07:04:32.216870Z
# User@Host: isucon[isucon] @ localhost [127.0.0.1]  Id:   349
# Query_time: 1.528023  Lock_time: 0.000000 Rows_sent: 0  Rows_examined: 0
SET timestamp=1599894272;
COMMIT;

[chigichan24]

Query 0
19.954640%

Summary:
total query time:   26.44s
total query count:  112

+--------------+------------+-------+----------+----------+----------+---------+----------+
| ATTRIBUTE    |      TOTAL |   MIN |      MAX |      AVG |      95% |  STDDEV |   MEDIAN |
+--------------+------------+-------+----------+----------+----------+---------+----------+
| Exec Time    |        26s | 101ms |       3s |    236ms |       1s |   416ms |    124ms |
| Lock Time    |        9ms |   0us |      3ms |     82us |     96us |   373us |     16us |
| Rows Sent    |    2200.00 |  0.00 |    20.00 |    19.82 |    20.00 |    2.66 |    20.00 |
| Rows Examine | 3301700.00 |  0.00 | 30020.00 | 29745.05 | 30020.00 | 3993.15 | 30020.00 |
+--------------+------------+-------+----------+----------+----------+---------+----------+

Query_time distribution:
  1us:
 10us:
100us:
  1ms:
 10ms:
100ms:  ###########################################################################
   1s:  ####
 10s~:

QueryExample:
SELECT * FROM chair WHERE stock > 0 ORDER BY price ASC, id ASC LIMIT 20;

Query 1
12.658496%

Summary:
total query time:   16.78s
total query count:  114

+--------------+------------+----------+----------+----------+----------+--------+----------+
| ATTRIBUTE    |      TOTAL |      MIN |      MAX |      AVG |      95% | STDDEV |   MEDIAN |
+--------------+------------+----------+----------+----------+----------+--------+----------+
| Exec Time    |        17s |    102ms |    308ms |    147ms |    206ms |   42ms |    132ms |
| Lock Time    |        3ms |     18us |    193us |     25us |     42us |   19us |     20us |
| Rows Sent    |    2280.00 |    20.00 |    20.00 |    20.18 |    20.00 |   0.00 |    20.00 |
| Rows Examine | 3419780.00 | 29520.00 | 30020.00 | 30263.54 | 30020.00 | 102.84 | 30020.00 |
+--------------+------------+----------+----------+----------+----------+--------+----------+

Query_time distribution:
  1us:
 10us:
100us:
  1ms:
 10ms:
100ms:  ###########################################################################
   1s:
 10s~:

QueryExample:
SELECT * FROM estate WHERE (door_width >= 54 AND door_height >= 171) OR (door_width >= 54 AND door_height >= 90) OR (door_width >= 171 AND door_height >= 54) OR (door_width >= 171 AND door_height >= 90) OR (door_width >= 90 AND door_height >= 54) OR (door_width >= 90 AND door_height >= 171) ORDER BY popularity DESC, id ASC LIMIT 20;

Query 2
12.497068%

Summary:
total query time:   16.56s
total query count:  96

+--------------+------------+-------+----------+----------+----------+---------+----------+
| ATTRIBUTE    |      TOTAL |   MIN |      MAX |      AVG |      95% |  STDDEV |   MEDIAN |
+--------------+------------+-------+----------+----------+----------+---------+----------+
| Exec Time    |        17s | 102ms |       2s |    173ms |    196ms |   271ms |    126ms |
| Lock Time    |        8ms |   0us |      3ms |     85us |     44us |   416us |     17us |
| Rows Sent    |    1880.00 |  0.00 |    20.00 |    19.79 |    20.00 |    2.87 |    20.00 |
| Rows Examine | 2821380.00 |  0.00 | 30020.00 | 29698.74 | 30020.00 | 4309.69 | 30020.00 |
+--------------+------------+-------+----------+----------+----------+---------+----------+

Query_time distribution:
  1us:
 10us:
100us:
  1ms:
 10ms:
100ms:  ###########################################################################
   1s:  #
 10s~:

QueryExample:
SELECT * FROM estate ORDER BY rent ASC, id ASC LIMIT 20;

Query 3
7.344613%

Summary:
total query time:   9.73s
total query count:  69

+--------------+------------+----------+----------+----------+----------+--------+----------+
| ATTRIBUTE    |      TOTAL |      MIN |      MAX |      AVG |      95% | STDDEV |   MEDIAN |
+--------------+------------+----------+----------+----------+----------+--------+----------+
| Exec Time    |        10s |    104ms |    248ms |    141ms |    205ms |   27ms |    136ms |
| Lock Time    |        2ms |     11us |    295us |     23us |     35us |   34us |     17us |
| Rows Sent    |    1725.00 |    25.00 |    25.00 |    25.37 |    25.00 |   0.00 |    25.00 |
| Rows Examine | 2074000.00 | 30025.00 | 30125.00 | 30500.00 | 30125.00 |  36.00 | 30050.00 |
+--------------+------------+----------+----------+----------+----------+--------+----------+

Query_time distribution:
  1us:
 10us:
100us:
  1ms:
 10ms:
100ms:  ###########################################################################
   1s:
 10s~:

QueryExample:
SELECT * FROM estate WHERE rent >= 50000 AND rent < 100000 ORDER BY popularity DESC, id ASC LIMIT 25 OFFSET 0;

Query 4
6.447226%

Summary:
total query time:   8.54s
total query count:  36

+--------------+------------+-------+----------+----------+----------+---------+----------+
| ATTRIBUTE    |      TOTAL |   MIN |      MAX |      AVG |      95% |  STDDEV |   MEDIAN |
+--------------+------------+-------+----------+----------+----------+---------+----------+
| Exec Time    |         9s | 105ms |       2s |    237ms |    820ms |   388ms |    152ms |
| Lock Time    |        1ms |   0us |    369us |     31us |     47us |    59us |     19us |
| Rows Sent    |     850.00 |  0.00 |    25.00 |    24.29 |    25.00 |    5.81 |    25.00 |
| Rows Examine | 1022350.00 |  0.00 | 30125.00 | 29210.00 | 30125.00 | 6985.48 | 30075.00 |
+--------------+------------+-------+----------+----------+----------+---------+----------+

Query_time distribution:
  1us:
 10us:
100us:
  1ms:
 10ms:
100ms:  ###########################################################################
   1s:  ##
 10s~:

QueryExample:
SELECT * FROM chair WHERE kind = '座椅子' AND stock > 0 ORDER BY popularity DESC, id ASC LIMIT 25 OFFSET 100;

[chigichan24]

querydigest -f /tmp/mysql-slow.log -n 5

[k5342]

17 適用後

isucon@team473-001:~/k$ querydigest -f /tmp/mysql-slow.log -n 5

Query 0
80.401707%

Summary:
total query time:       22.19s
total query count:      9

+--------------+--------+-------+-------+-------+-------+--------+--------+
| ATTRIBUTE    |  TOTAL |   MIN |   MAX |   AVG |   95% | STDDEV | MEDIAN |
+--------------+--------+-------+-------+-------+-------+--------+--------+
| Exec Time    |    22s | 932ms |    3s |    2s |    3s |  672ms |     3s |
| Lock Time    |  172us |   0us |  45us |  19us |  45us |   12us |   17us |
| Rows Sent    | 160.00 |  0.00 | 20.00 | 20.00 | 20.00 |   6.67 |  20.00 |
| Rows Examine | 160.00 |  0.00 | 20.00 | 20.00 | 20.00 |   6.67 |  20.00 |
+--------------+--------+-------+-------+-------+-------+--------+--------+

Query_time distribution:
  1us:
 10us:
100us:
  1ms:
 10ms:
100ms:  #########
   1s:  ###########################################################################
 10s~:

QueryExample:
SELECT * FROM chair WHERE stock > 0 ORDER BY price ASC, id ASC LIMIT 20;

Query 1
16.035835%

Summary:
total query time:       4.43s
total query count:      1

+--------------+-------+------+------+------+------+--------+--------+
| ATTRIBUTE    | TOTAL |  MIN |  MAX |  AVG |  95% | STDDEV | MEDIAN |
+--------------+-------+------+------+------+------+--------+--------+
| Exec Time    |    4s |   4s |   4s |   4s |   4s |      - |     4s |
| Lock Time    |  13us | 13us | 13us | 13us | 13us |      - |   13us |
| Rows Sent    |  0.00 | 0.00 | 0.00 |    - | 0.00 |      - |   0.00 |
| Rows Examine |  1.00 | 1.00 | 1.00 |    - | 1.00 |      - |   1.00 |
+--------------+-------+------+------+------+------+--------+--------+

Query_time distribution:
  1us:
 10us:
100us:
  1ms:
 10ms:
100ms:
   1s:  ###########################################################################
 10s~:

QueryExample:
UPDATE chair SET stock = stock - 1 WHERE id = 29021;

Query 2
1.261829%

Summary:
total query time:       0.35s
total query count:      1

+--------------+---------+---------+---------+-------+---------+--------+---------+
| ATTRIBUTE    |   TOTAL |     MIN |     MAX |   AVG |     95% | STDDEV |  MEDIAN |
+--------------+---------+---------+---------+-------+---------+--------+---------+
| Exec Time    |   348ms |   348ms |   348ms | 348ms |   348ms |      - |   348ms |
| Lock Time    |    41us |    41us |    41us |  41us |    41us |      - |    41us |
| Rows Sent    |    1.00 |    1.00 |    1.00 |     - |    1.00 |      - |    1.00 |
| Rows Examine | 4700.00 | 4700.00 | 4700.00 |     - | 4700.00 |      - | 4700.00 |
+--------------+---------+---------+---------+-------+---------+--------+---------+

Query_time distribution:
  1us:
 10us:
100us:
  1ms:
 10ms:
100ms:  ###########################################################################
   1s:
 10s~:

QueryExample:
SELECT COUNT(*) FROM chair WHERE price >= 12000 AND price < 15000 AND height >= 110 AND height < 150 AND features LIKE CONCAT('%', '中華風', '%') AND features LIKE CONCAT('%', '現代的デザイン', '%') AND features LIKE CONCAT('%', 'メッシュ貼地', '%') AND stock > 0;

Query 3
1.190472%

Summary:
total query time:       0.33s
total query count:      1

+--------------+---------+---------+---------+-------+---------+--------+---------+
| ATTRIBUTE    |   TOTAL |     MIN |     MAX |   AVG |     95% | STDDEV |  MEDIAN |
+--------------+---------+---------+---------+-------+---------+--------+---------+
| Exec Time    |   329ms |   329ms |   329ms | 329ms |   329ms |      - |   329ms |
| Lock Time    |    17us |    17us |    17us |  17us |    17us |      - |    17us |
| Rows Sent    |   10.00 |   10.00 |   10.00 |     - |   10.00 |      - |   10.00 |
| Rows Examine | 7633.00 | 7633.00 | 7633.00 |     - | 7633.00 |      - | 7633.00 |
+--------------+---------+---------+---------+-------+---------+--------+---------+

Query_time distribution:
  1us:
 10us:
100us:
  1ms:
 10ms:
100ms:  ###########################################################################
   1s:
 10s~:

QueryExample:
SELECT * FROM chair WHERE width >= 150 AND kind = 'エルゴノミクス' AND stock > 0 ORDER BY popularity DESC, id ASC LIMIT 10 OFFSET 0;

Query 4
1.110158%

Summary:
total query time:       0.31s
total query count:      1

+--------------+----------+----------+----------+-------+----------+--------+----------+
| ATTRIBUTE    |    TOTAL |      MIN |      MAX |   AVG |      95% | STDDEV |   MEDIAN |
+--------------+----------+----------+----------+-------+----------+--------+----------+
| Exec Time    |    306ms |    306ms |    306ms | 306ms |    306ms |      - |    306ms |
| Lock Time    |    249us |    249us |    249us | 249us |    249us |      - |    249us |
| Rows Sent    |    20.00 |    20.00 |    20.00 |     - |    20.00 |      - |    20.00 |
| Rows Examine | 29520.00 | 29520.00 | 29520.00 |     - | 29520.00 |      - | 29520.00 |
+--------------+----------+----------+----------+-------+----------+--------+----------+

Query_time distribution:
  1us:
 10us:
100us:
  1ms:
 10ms:
100ms:  ###########################################################################
   1s:
 10s~:

QueryExample:
SELECT * FROM estate WHERE (door_width >= 158 AND door_height >= 118) OR (door_width >= 158 AND door_height >= 200) OR (door_width >= 118 AND door_height >= 158) OR (door_width >= 118 AND door_height >= 200) OR (door_width >= 200 AND door_height >= 158) OR (door_width >= 200 AND door_height >= 118) ORDER BY popularity DESC, id ASC LIMIT 20;

[chigichan24]

Query 0
100.000000%

Summary:
total query time:   0.51s
total query count:  1

+--------------+-------+-------+-------+-------+-------+--------+--------+
| ATTRIBUTE    | TOTAL |   MIN |   MAX |   AVG |   95% | STDDEV | MEDIAN |
+--------------+-------+-------+-------+-------+-------+--------+--------+
| Exec Time    | 510ms | 510ms | 510ms | 510ms | 510ms |      - |  510ms |
| Lock Time    |   7ms |   7ms |   7ms |   7ms |   7ms |      - |    7ms |
| Rows Sent    |  0.00 |  0.00 |  0.00 |     - |  0.00 |      - |   0.00 |
| Rows Examine |  0.00 |  0.00 |  0.00 |     - |  0.00 |      - |   0.00 |
+--------------+-------+-------+-------+-------+-------+--------+--------+

Query_time distribution:
  1us:  
 10us:  
100us:  
  1ms:  
 10ms:  
100ms:  ###########################################################################
   1s:  
 10s~:  

QueryExample:
INSERT INTO isuumo.chair (id, thumbnail, name, price, height, width, depth, popularity, stock, color, description, features, kind) VALUES ('1001', '/images/chair/45f81b8a5149d505b9bd98b79fe050f6f56039c434d1ec52778162a8173972c8.png', '【伝説の一品】子供用ハンモック', '13

[chigichan24]

Query 0
8.905454%

Summary:
total query time:   34.70s
total query count:  336

+--------------+-------------+------+----------+----------+----------+---------+----------+
| ATTRIBUTE    |       TOTAL |  MIN |      MAX |      AVG |      95% |  STDDEV |   MEDIAN |
+--------------+-------------+------+----------+----------+----------+---------+----------+
| Exec Time    |         35s | 61us |    245ms |    103ms |    159ms |    32ms |     92ms |
| Lock Time    |        19ms |  0us |      7ms |     57us |     50us |   394us |     16us |
| Rows Sent    |     8290.00 | 0.00 |    25.00 |    24.75 |    25.00 |    2.51 |    25.00 |
| Rows Examine | 10057240.00 | 0.00 | 30625.00 | 30021.61 | 30530.00 | 2325.16 | 30050.00 |
+--------------+-------------+------+----------+----------+----------+---------+----------+

Query_time distribution:
  1us:
 10us:
100us:
  1ms:
 10ms:  ###########################################################################
100ms:  ##########################################
   1s:
 10s~:

QueryExample:
SELECT * FROM estate WHERE rent >= 100000 AND rent < 150000 ORDER BY popularity DESC, id ASC LIMIT 25 OFFSET 0;

Query 1
8.346603%

Summary:
total query time:   32.53s
total query count:  242

+--------------+------------+------+----------+----------+----------+---------+----------+
| ATTRIBUTE    |      TOTAL |  MIN |      MAX |      AVG |      95% |  STDDEV |   MEDIAN |
+--------------+------------+------+----------+----------+----------+---------+----------+
| Exec Time    |        33s |  3ms |    308ms |    134ms |    218ms |    49ms |    117ms |
| Lock Time    |       11ms |  0us |      6ms |     47us |     47us |   363us |     20us |
| Rows Sent    |    4760.00 | 0.00 |    20.00 |    19.75 |    20.00 |    2.56 |    20.00 |
| Rows Examine | 7160260.00 | 0.00 | 30520.00 | 29710.62 | 30520.00 | 3848.73 | 30020.00 |
+--------------+------------+------+----------+----------+----------+---------+----------+

Query_time distribution:
  1us:
 10us:
100us:
  1ms:  #
 10ms:  ################
100ms:  ###########################################################################
   1s:
 10s~:

QueryExample:
SELECT * FROM estate WHERE (door_width >= 34 AND door_height >= 115) OR (door_width >= 34 AND door_height >= 30) OR (door_width >= 115 AND door_height >= 34) OR (door_width >= 115 AND door_height >= 30) OR (door_width >= 30 AND door_height >= 34) OR (door_width >= 30 AND door_height >= 115) ORDER BY popularity DESC, id ASC LIMIT 20;

Query 2
5.005020%

Summary:
total query time:   19.50s
total query count:  207

+--------------+------------+----------+----------+----------+----------+--------+----------+
| ATTRIBUTE    |      TOTAL |      MIN |      MAX |      AVG |      95% | STDDEV |   MEDIAN |
+--------------+------------+----------+----------+----------+----------+--------+----------+
| Exec Time    |        20s |     12ms |    169ms |     94ms |    149ms |   28ms |     85ms |
| Lock Time    |        7ms |     10us |      2ms |     32us |     41us |  136us |     16us |
| Rows Sent    |    5130.00 |    10.00 |    25.00 |    24.90 |    25.00 |   1.80 |    25.00 |
| Rows Examine | 6234230.00 | 30025.00 | 30625.00 | 30263.25 | 30566.25 | 166.51 | 30050.00 |
+--------------+------------+----------+----------+----------+----------+--------+----------+

Query_time distribution:
  1us:
 10us:
100us:
  1ms:
 10ms:  ###########################################################################
100ms:  ###############################
   1s:
 10s~:

QueryExample:
SELECT * FROM estate WHERE rent >= 150000 ORDER BY popularity DESC, id ASC LIMIT 25 OFFSET 0;

Query 3
4.241589%

Summary:
total query time:   16.53s
total query count:  18601

+--------------+----------+------+-------+-------+------+--------+--------+
| ATTRIBUTE    |    TOTAL |  MIN |   MAX |   AVG |  95% | STDDEV | MEDIAN |
+--------------+----------+------+-------+-------+------+--------+--------+
| Exec Time    |      17s | 78us | 783ms | 889us |  4ms |    6ms |  326us |
| Lock Time    |    918ms |  0us |  13ms |  49us | 93us |  355us |   13us |
| Rows Sent    | 12384.00 | 0.00 |  1.00 |  0.67 | 1.00 |   0.47 |   1.00 |
| Rows Examine | 12384.00 | 0.00 |  1.00 |  0.67 | 1.00 |   0.47 |   1.00 |
+--------------+----------+------+-------+-------+------+--------+--------+

Query_time distribution:
  1us:
 10us:  ######
100us:  ###########################################################################
  1ms:  #################
 10ms:
100ms:
   1s:
 10s~:

QueryExample:
SELECT * FROM estate WHERE id = 4007 AND ST_Contains(ST_PolygonFromText('POLYGON((34.945616 138.905005,34.959783 138.891032,35.132330 138.878911,35.196652 138.943122,35.219424 138.973915,35.217276 138.998456,35.146903 138.987388,34.964241 138.950588,34.945616 138.905005))'), ST_GeomFromText('POINT(35.130047 138.993909)'));

Query 4
3.712147%

Summary:
total query time:   14.47s
total query count:  163

+--------------+-----------+------+---------+---------+---------+--------+---------+
| ATTRIBUTE    |     TOTAL |  MIN |     MAX |     AVG |     95% | STDDEV |  MEDIAN |
+--------------+-----------+------+---------+---------+---------+--------+---------+
| Exec Time    |       14s |  4ms |   209ms |    89ms |   140ms |   31ms |    80ms |
| Lock Time    |      12ms |  0us |     4ms |    73us |    51us |  373us |    23us |
| Rows Sent    |   3990.00 | 0.00 |   25.00 |   24.63 |   25.00 |   3.02 |   25.00 |
| Rows Examine | 777743.00 | 0.00 | 4994.00 | 4800.88 | 4994.00 | 389.04 | 4777.00 |
+--------------+-----------+------+---------+---------+---------+--------+---------+

Query_time distribution:
  1us:
 10us:
100us:
  1ms:
 10ms:  ###########################################################################
100ms:  ###################################
   1s:
 10s~:

QueryExample:
SELECT * FROM chair WHERE price >= 9000 AND price < 12000 AND stock > 0 ORDER BY popularity DESC, id ASC LIMIT 25 OFFSET 0;