bellwood4486 commented 3 years ago


# 660ms user time, 30ms system time, 39.70M rss, 47.64M vsz
# Current date: Sun Aug 29 12:01:27 2021
# Hostname: ubuntu-focal
# Files: /var/log/mysql/mariadb-slow.log
# Overall: 5.79k total, 22 unique, 85.19 QPS, 5.98x concurrency __________
# Time range: 2021-08-29 06:59:05 to 07:00:13
# Attribute          total     min     max     avg     95%  stddev  median
# ============     ======= ======= ======= ======= ======= ======= =======
# Exec time           406s    10ms   334ms    70ms   189ms    60ms    48ms
# Lock time          665ms       0    17ms   114us   273us   729us     9us
# Rows sent        988.27k       0   1.60k  174.69  833.10  299.96   11.95
# Rows examine     135.17M       0  72.40k  23.89k  65.68k  21.53k  17.59k
# Rows affecte         447       0      28    0.08    0.99    0.44       0
# Bytes sent       154.82M       0 268.23k  27.37k 123.85k  46.49k   2.27k
# Query size         1.44M       6 790.36k  261.14  246.02   9.89k  112.70
# Boolean:
# QC hit         0% yes,  99% no

# Profile
# Rank Query ID                            Response time  Calls R/Call V/M
# ==== =================================== ============== ===== ====== ===
#    1 0x8155B89FFD74A9D523D19AC409FD97AF  162.0353 39.9%  1413 0.1147  0.04 SELECT isu_condition
#    2 0x931A992E852C61FC6D46141A39DEF4FE  158.7346 39.1%  2641 0.0601  0.04 SELECT isu_condition
#    3 0x9C6C682008AE0D08F3E2A0049B030C70   50.0435 12.3%   500 0.1001  0.03 SELECT isu_condition
#    4 0x5F580A12ADA1633C9634298BE5BD9422   16.1447  4.0%   151 0.1069  0.04 SELECT isu_condition
#    5 0xB8B32624C3268C0925657C305C0ED778    7.2100  1.8%   419 0.0172  0.00 INSERT isu_condition
#    6 0xFFFCA4D67EA0A788813031B8BBC3B329    6.9619  1.7%   412 0.0169  0.00 COMMIT
#    7 0xDA556F9115773A1A99AA0165670CE848    2.3408  0.6%   152 0.0154  0.00 ADMIN PREPARE
#    8 0x677D4DCDF729CC334DE038E9477B32B3    1.6274  0.4%    28 0.0581  0.04 SELECT isu_condition
#    9 0x1E561CE87F050ED58A7E1A7FBB6C2285    0.5093  0.1%    28 0.0182  0.00 SELECT isu
#   10 0xADCA4F127A769A45A2D1B74705103105    0.1302  0.0%     8 0.0163  0.00 SELECT user
# MISC 0xMISC                                0.7068  0.2%    41 0.0172   0.0 <12 ITEMS>

# Query 1: 23.55 QPS, 2.70x concurrency, ID 0x8155B89FFD74A9D523D19AC409FD97AF at byte 2860277
# Scores: V/M = 0.04
# Time range: 2021-08-29 06:59:11 to 07:00:11
# Attribute    pct   total     min     max     avg     95%  stddev  median
# ============ === ======= ======= ======= ======= ======= ======= =======
# Count         24    1413
# Exec time     39    162s    10ms   334ms   115ms   230ms    66ms   110ms
# Lock time     27   184ms     5us    13ms   130us   403us   715us     9us
# Rows sent      0   1.38k       0       1    1.00    0.99    0.06    0.99
# Rows examine  42  57.84M     719  70.57k  41.91k  68.96k  20.25k  44.45k
# Rows affecte   0       0       0       0       0       0       0       0
# Bytes sent     0   1.01M     589     775  746.62  755.64   18.18  719.66
# Query size    11 172.49k     125     125     125     125       0     125
# String:
# Databases    isucondition
# Hosts        localhost
# Users        isucon
# Query_time distribution
#   1us
#  10us
# 100us
#   1ms
#  10ms  #############################################
# 100ms  ################################################################
#    1s
#  10s+
# Tables
#    SHOW TABLE STATUS FROM `isucondition` LIKE 'isu_condition'\G
#    SHOW CREATE TABLE `isucondition`.`isu_condition`\G
# EXPLAIN /*!50100 PARTITIONS*/
SELECT * FROM `isu_condition` WHERE `jia_isu_uuid` = 'd4b0d226-c1ef-48fc-bb46-8c143bae1817' ORDER BY `timestamp` DESC LIMIT 1\G

bellwood4486 commented 3 years ago

インデックスが効いていない

MariaDB [isucondition]> explain SELECT * FROM `isu_condition` WHERE `jia_isu_uuid` = 'd4b0d226-c1ef-48fc-bb46-8c143bae1817' ORDER BY `timestamp` DESC LIMIT 1\G
*************************** 1. row ***************************
           id: 1
  select_type: SIMPLE
        table: isu_condition
         type: ALL
possible_keys: NULL
          key: NULL
      key_len: NULL
          ref: NULL
         rows: 76675
        Extra: Using where; Using filesort
1 row in set (0.002 sec)

bellwood4486 commented 3 years ago

複合インデックスを貼ったら、それが使われるようになった。

MariaDB [isucondition]> explain SELECT * FROM `isu_condition` WHERE `jia_isu_uuid` = 'd4b0d226-c1ef-48fc-bb46-8c143bae1817' ORDER BY `timestamp` DESC LIMIT 1\G
*************************** 1. row ***************************
           id: 1
  select_type: SIMPLE
        table: isu_condition
         type: ref
possible_keys: idx_jia_isu_uuid_timestamp
          key: idx_jia_isu_uuid_timestamp
      key_len: 144
          ref: const
         rows: 1
        Extra: Using where
1 row in set (0.003 sec)

bellwood4486 commented 3 years ago

一番遅いのが別のクエリに変わった。(LIMIT 1がない)

# 450ms user time, 20ms system time, 39.43M rss, 47.61M vsz
# Current date: Mon Aug 30 13:36:31 2021
# Hostname: ubuntu-focal
# Files: /var/log/mysql/mariadb-slow.log
# Overall: 3.19k total, 19 unique, 49.14 QPS, 1.04x concurrency __________
# Time range: 2021-08-30 13:31:07 to 13:32:12
# Attribute          total     min     max     avg     95%  stddev  median
# ============     ======= ======= ======= ======= ======= ======= =======
# Exec time            68s    10ms   123ms    21ms    46ms    14ms    16ms
# Lock time          321ms       0    16ms   100us   185us   644us     9us
# Rows sent          1.61M       0   1.71k  528.82   1.33k  503.35  400.73
# Rows examine       1.61M       0   1.71k  529.03   1.33k  503.15  400.73
# Rows affecte       1.71k       0      28    0.55    9.83    2.27       0
# Bytes sent       249.95M       0 289.97k  80.13k 201.74k  75.96k  59.57k
# Query size         1.33M       6 790.36k  437.42   1.39k  13.33k  112.70
# Boolean:
# QC hit         1% yes,  98% no

# Profile
# Rank Query ID                            Response time Calls R/Call V/M
# ==== =================================== ============= ===== ====== ====
#    1 0x931A992E852C61FC6D46141A39DEF4FE  36.6229 54.2%  1606 0.0228  0.01 SELECT isu_condition
#    2 0x9C6C682008AE0D08F3E2A0049B030C70  13.0335 19.3%   563 0.0232  0.01 SELECT isu_condition
#    3 0xFFFCA4D67EA0A788813031B8BBC3B329   8.1671 12.1%   491 0.0166  0.00 COMMIT
#    4 0x5F580A12ADA1633C9634298BE5BD9422   3.4043  5.0%   140 0.0243  0.01 SELECT isu_condition
#    5 0xB8B32624C3268C0925657C305C0ED778   3.0747  4.5%   173 0.0178  0.00 INSERT isu_condition
#    6 0xDA556F9115773A1A99AA0165670CE848   1.5886  2.4%   116 0.0137  0.00 ADMIN PREPARE
#    7 0x8155B89FFD74A9D523D19AC409FD97AF   0.5074  0.8%    33 0.0154  0.00 SELECT isu_condition
#    8 0x8C2BC651CBBBF3DB41D1CAD61AA0BD68   0.2206  0.3%    14 0.0158  0.00 SELECT isu
#    9 0xADCA4F127A769A45A2D1B74705103105   0.2055  0.3%    12 0.0171  0.00 SELECT user
#   10 0xB5F4855605637317357023AD70B91455   0.1796  0.3%    13 0.0138  0.00 SELECT isu
# MISC 0xMISC                               0.5739  0.8%    33 0.0174   0.0 <9 ITEMS>

# Query 1: 27.22 QPS, 0.62x concurrency, ID 0x931A992E852C61FC6D46141A39DEF4FE at byte 1827817
# Scores: V/M = 0.01
# Time range: 2021-08-30 13:31:13 to 13:32:12
# Attribute    pct   total     min     max     avg     95%  stddev  median
# ============ === ======= ======= ======= ======= ======= ======= =======
# Count         50    1606
# Exec time     54     37s    10ms   123ms    23ms    51ms    15ms    17ms
# Lock time     60   196ms     5us    16ms   121us   236us   770us    10us
# Rows sent     64   1.04M       6   1.71k  679.11   1.33k  478.36  563.87
# Rows examine  64   1.04M       6   1.71k  679.11   1.33k  478.36  563.87
# Rows affecte   0       0       0       0       0       0       0       0
# Bytes sent    64 160.38M   1.45k 289.97k 102.26k 211.82k  72.32k  83.83k
# Query size    13 180.36k     115     115     115     115       0     115
# String:
# Databases    isucondition
# Hosts        localhost
# Users        isucon
# Query_time distribution
#   1us
#  10us
# 100us
#   1ms
#  10ms  ################################################################
# 100ms  #
#    1s
#  10s+
# Tables
#    SHOW TABLE STATUS FROM `isucondition` LIKE 'isu_condition'\G
#    SHOW CREATE TABLE `isucondition`.`isu_condition`\G
# EXPLAIN /*!50100 PARTITIONS*/
SELECT * FROM `isu_condition` WHERE `jia_isu_uuid` = 'cf2ee9c2-ea54-4b0c-b71c-6e447cc3e45c' ORDER BY timestamp DESC\G

bellwood4486 commented 3 years ago

15 を入れたら、1位が変わった。

# 400ms user time, 30ms system time, 39.47M rss, 47.69M vsz
# Current date: Mon Aug 30 14:29:30 2021
# Hostname: ubuntu-focal
# Files: /var/log/mysql/mariadb-slow.log
# Overall: 2.67k total, 21 unique, 41.06 QPS, 0.79x concurrency __________
# Time range: 2021-08-30 14:24:32 to 14:25:37
# Attribute          total     min     max     avg     95%  stddev  median
# ============     ======= ======= ======= ======= ======= ======= =======
# Exec time            51s    10ms   109ms    19ms    42ms    11ms    15ms
# Lock time          342ms       0    12ms   128us   445us   648us     8us
# Rows sent          1.04M       0   1.63k  407.81   1.26k  480.87    2.90
# Rows examine       1.04M       0   1.63k  408.23   1.26k  480.56    0.99
# Rows affecte       1.59k       0      28    0.61    9.83    2.39       0
# Bytes sent       159.87M       0 264.74k  61.34k 192.13k  70.20k  17.59k
# Query size         1.33M       6 790.36k  522.56   1.39k  14.61k  118.34
# Boolean:
# QC hit         3% yes,  96% no

# Profile
# Rank Query ID                            Response time Calls R/Call V/M
# ==== =================================== ============= ===== ====== ====
#    1 0x9C6C682008AE0D08F3E2A0049B030C70  25.5941 50.1%  1078 0.0237  0.01 SELECT isu_condition
#    2 0xAC9E2250E1642BFE9823A9B9ECA1A419   6.7556 13.2%   451 0.0150  0.00 SELECT isu_condition
#    3 0xFFFCA4D67EA0A788813031B8BBC3B329   6.1389 12.0%   413 0.0149  0.00 COMMIT
#    4 0x5F580A12ADA1633C9634298BE5BD9422   4.9275  9.7%   228 0.0216  0.01 SELECT isu_condition
#    5 0xB8B32624C3268C0925657C305C0ED778   2.6318  5.2%   160 0.0164  0.00 INSERT isu_condition
#    6 0xDA556F9115773A1A99AA0165670CE848   2.1456  4.2%   158 0.0136  0.00 ADMIN PREPARE
#    7 0x8C2BC651CBBBF3DB41D1CAD61AA0BD68   0.6810  1.3%    36 0.0189  0.01 SELECT isu
#    8 0x8155B89FFD74A9D523D19AC409FD97AF   0.5420  1.1%    38 0.0143  0.00 SELECT isu_condition
#    9 0xADCA4F127A769A45A2D1B74705103105   0.4192  0.8%    29 0.0145  0.00 SELECT user
#   10 0xB5F4855605637317357023AD70B91455   0.3907  0.8%    25 0.0156  0.00 SELECT isu
# MISC 0xMISC                               0.8271  1.6%    53 0.0156   0.0 <11 ITEMS>

# Query 1: 18.27 QPS, 0.43x concurrency, ID 0x9C6C682008AE0D08F3E2A0049B030C70 at byte 1895316
# Scores: V/M = 0.01
# Time range: 2021-08-30 14:24:38 to 14:25:37
# Attribute    pct   total     min     max     avg     95%  stddev  median
# ============ === ======= ======= ======= ======= ======= ======= =======
# Count         40    1078
# Exec time     50     26s    10ms   109ms    24ms    51ms    13ms    19ms
# Lock time     46   160ms     6us    11ms   148us   541us   709us    10us
# Rows sent     81 867.31k       0   1.63k  823.86   1.39k  368.57  793.42
# Rows examine  81 867.31k       0   1.63k  823.86   1.39k  368.57  793.42
# Rows affecte   0       0       0       0       0       0       0       0
# Bytes sent    79 126.77M     589 264.74k 120.42k 201.74k  54.10k 117.95k
# Query size    12 165.28k     157     157     157     157       0     157
# String:
# Databases    isucondition
# Hosts        localhost
# Users        isucon
# Query_time distribution
#   1us
#  10us
# 100us
#   1ms
#  10ms  ################################################################
# 100ms  #
#    1s
#  10s+
# Tables
#    SHOW TABLE STATUS FROM `isucondition` LIKE 'isu_condition'\G
#    SHOW CREATE TABLE `isucondition`.`isu_condition`\G
# EXPLAIN /*!50100 PARTITIONS*/
SELECT * FROM `isu_condition` WHERE `jia_isu_uuid` = '4dfc6fff-1796-492a-9e1f-5e27e40f1d36'     AND `timestamp` < '2021-08-27 09:18:28' ORDER BY `timestamp` DESC\G

bellwood4486 / isucon11-qualify

pt-query-digest #4

15 を入れたら、1位が変わった。