分析-004(6476→7303)

sunakan commented 1 month ago

https://github.com/sunakan/isunarabe13-suburi/issues/4

の続き

スコア：6476

sunakan commented 1 month ago

そろそろalpも見ていく

sunakan commented 1 month ago

make alp
# or
alp json --sort sum -r -o count,method,uri,min,avg,max,sum --file tmp/analysis/latest/nginx-access.log.* -m '/api/user/\w+/statistics,/api/user/\w+/icon,/api/user/\w+/theme,/api/livestream/\d+/livecomment,/api/livestream/\d+/reaction,/api/livestream/\d+/moderate,/api/livestream/\d+/report,/api/livestream/\d+/ngwords,/api/livestream/\d+/exit,/api/livestream/\d+/enter,/api/livestream/\d+/statistics,/api/livestream/\d+'

+-------+--------+---------------------------------+--------+--------+--------+---------+
| COUNT | METHOD |               URI               |  MIN   |  AVG   |  MAX   |   SUM   |
+-------+--------+---------------------------------+--------+--------+--------+---------+
| 3445  | GET    | /api/user/\w+/icon              | 0.004  | 0.050  | 0.532  | 170.808 |
| 381   | GET    | /api/livestream/\d+/livecomment | 0.004  | 0.278  | 1.136  | 105.796 |
| 8     | GET    | /api/user/\w+/statistics        | 0.392  | 13.204 | 20.004 | 105.636 |
| 32    | POST   | /api/livestream/\d+/moderate    | 0.192  | 3.223  | 6.556  | 103.128 |
| 413   | GET    | /api/livestream/\d+/reaction    | 0.004  | 0.239  | 1.028  | 98.608  |
| 450   | POST   | /api/livestream/\d+/livecomment | 0.004  | 0.148  | 0.544  | 66.404  |
| 70    | GET    | /api/livestream/search          | 0.052  | 0.842  | 1.924  | 58.936  |
| 116   | POST   | /api/livestream/reservation     | 0.128  | 0.424  | 1.028  | 49.240  |
| 345   | POST   | /api/register                   | 0.008  | 0.130  | 0.628  | 44.816  |
| 343   | POST   | /api/icon                       | 0.012  | 0.102  | 0.732  | 35.084  |
| 358   | POST   | /api/livestream/\d+/reaction    | 0.004  | 0.091  | 0.692  | 32.644  |
| 350   | POST   | /api/login                      | 0.004  | 0.059  | 0.652  | 20.700  |
| 1     | POST   | /api/initialize                 | 13.788 | 13.788 | 13.788 | 13.788  |
| 99    | GET    | /api/livestream                 | 0.012  | 0.132  | 0.656  | 13.024  |
| 2     | GET    | /api/livestream/\d+/statistics  | 5.400  | 5.480  | 5.560  | 10.960  |
| 46    | GET    | /api/livestream/\d+/ngwords     | 0.008  | 0.118  | 0.360  | 5.428   |
| 97    | GET    | /api/tag                        | 0.020  | 0.052  | 0.324  | 5.044   |
| 68    | GET    | /api/livestream/\d+/report      | 0.004  | 0.073  | 0.408  | 4.988   |
| 38    | POST   | /api/livestream/\d+/enter       | 0.004  | 0.063  | 0.324  | 2.408   |
| 29    | DELETE | /api/livestream/\d+/exit        | 0.008  | 0.056  | 0.204  | 1.632   |
| 7     | GET    | /api/user/\w+/theme             | 0.012  | 0.058  | 0.116  | 0.404   |
| 1     | GET    | /api/user/test                  | 0.004  | 0.004  | 0.004  | 0.004   |
| 3     | GET    | /api/user/me                    | 0.004  | 0.001  | 0.004  | 0.004   |
| 1     | GET    | /api/livestream/\d+             | 0.004  | 0.004  | 0.004  | 0.004   |
| 1     | GET    | /api/payment                    | 0.000  | 0.000  | 0.000  | 0.000   |
+-------+--------+---------------------------------+--------+--------+--------+---------+

sunakan commented 1 month ago

make pt-query-digest
# or
pt-query-digest --limit 10 tmp/analysis/latest/mysql-slow.log.*

# 16.9s user time, 100ms system time, 55.83M rss, 392.66G vsz
# Current date: Sun Sep 22 20:07:25 2024
# Hostname: 
# Files: tmp/analysis/latest/mysql-slow.log.isu-1, tmp/analysis/latest/mysql-slow.log.isu-2, tmp/analysis/latest/mysql-slow.log.isu-3
# Overall: 389.71k total, 94 unique, 3.58k QPS, 3.55x concurrency ________
# Time range: 2024-09-22T10:56:19 to 2024-09-22T10:58:08
# Attribute          total     min     max     avg     95%  stddev  median
# ============     ======= ======= ======= ======= ======= ======= =======
# Exec time           387s     1us   375ms   992us     4ms     4ms   194us
# Lock time             1s       0    28ms     2us     1us    86us     1us
# Rows sent        295.77k       0   7.32k    0.78    0.99   21.54       0
# Rows examine      85.35M       0  14.03k  229.64   1.14k  828.06    0.99
# Query size        64.10M       5   1.94M  172.46  329.68   3.91k   42.48

# Profile
# Rank Query ID                            Response time  Calls  R/Call V/
# ==== =================================== ============== ====== ====== ==
#    1 0x38BC86A45F31C6B1EE324671506C898A   41.7528 10.8%  17683 0.0024  0.00 SELECT themes
#    2 0xF1B8EF06D6CA63B24BFF433E06CCEB22   40.6518 10.5%   4356 0.0093  0.01 SELECT users livestreams livecomments
#    3 0x4ADE2DC90689F1C4891749AF54FB8D14   40.5902 10.5%  48764 0.0008  0.00 DELETE SELECT livecomments
#    4 0xDB74D52D39A7090F224C4DEEAF3028C9   38.7257 10.0%   4360 0.0089  0.01 SELECT users livestreams reactions
#    5 0x59F1B6DD8D9FEC059E55B3BFD624E8C3   22.8206  5.9%   1024 0.0223  0.01 SELECT reservation_slots
#    6 0x84B457C910C4A79FC9EBECB8B1065C66   22.6447  5.9%  21118 0.0011  0.00 SELECT icons
#    7 0xFBC5564AE716EAE82F20BFB45F6C37E7   20.6098  5.3%  45389 0.0005  0.00 SELECT tags
#    8 0x64CC8A4E8E4B390203375597CE4D611F   18.2271  4.7%    396 0.0460  0.01 SELECT ng_words
#    9 0xFFFCA4D67EA0A788813031B8BBC3B329   17.2524  4.5%   3554 0.0049  0.01 COMMIT
#   10 0x22279D81D51006139E0C76405B54C261   15.0354  3.9%  31034 0.0005  0.00 SELECT domains domainmetadata
# MISC 0xMISC                              108.6425 28.1% 212032 0.0005   0.0 <84 ITEMS>

# Query 1: 213.05 QPS, 0.50x concurrency, ID 0x38BC86A45F31C6B1EE324671506C898A at byte 110773455
# Scores: V/M = 0.00
# Time range: 2024-09-22T10:56:45 to 2024-09-22T10:58:08
# Attribute    pct   total     min     max     avg     95%  stddev  median
# ============ === ======= ======= ======= ======= ======= ======= =======
# Count          4   17683
# Exec time     10     42s   262us    38ms     2ms     8ms     3ms     1ms
# Lock time      5    60ms       0     4ms     3us     1us    53us     1us
# Rows sent      5  17.27k       1       1       1       1       0       1
# Rows examine  23  19.84M    1000   1.31k   1.15k   1.26k  102.85   1.14k
# Query size     1 705.86k      38      41   40.88   40.45    0.62   40.45
# String:
# Databases    isupipe
# Hosts        localhost
# Users        isucon
# Query_time distribution
#   1us
#  10us
# 100us  ###################################################
#   1ms  ################################################################
#  10ms  ##
# 100ms
#    1s
#  10s+
# Tables
#    SHOW TABLE STATUS FROM `isupipe` LIKE 'themes'\G
#    SHOW CREATE TABLE `isupipe`.`themes`\G
# EXPLAIN /*!50100 PARTITIONS*/
SELECT * FROM themes WHERE user_id = 1019\G

# Query 2: 52.48 QPS, 0.49x concurrency, ID 0xF1B8EF06D6CA63B24BFF433E06CCEB22 at byte 113675648
# Scores: V/M = 0.01
# Time range: 2024-09-22T10:56:45 to 2024-09-22T10:58:08
# Attribute    pct   total     min     max     avg     95%  stddev  median
# ============ === ======= ======= ======= ======= ======= ======= =======
# Count          1    4356
# Exec time     10     41s     1ms    77ms     9ms    31ms    11ms     3ms
# Lock time      0     9ms       0     2ms     2us     1us    33us     1us
# Rows sent      1   4.25k       1       1       1       1       0       1
# Rows examine  10   8.88M   1.96k   2.71k   2.09k   2.38k  167.01   2.06k
# Query size     1 701.15k     163     166  164.83  158.58       0  158.58
# String:
# Databases    isupipe
# Hosts        localhost
# Users        isucon
# Query_time distribution
#   1us
#  10us
# 100us
#   1ms  ################################################################
#  10ms  ####################################
# 100ms
#    1s
#  10s+
# Tables
#    SHOW TABLE STATUS FROM `isupipe` LIKE 'users'\G
#    SHOW CREATE TABLE `isupipe`.`users`\G
#    SHOW TABLE STATUS FROM `isupipe` LIKE 'livestreams'\G
#    SHOW CREATE TABLE `isupipe`.`livestreams`\G
#    SHOW TABLE STATUS FROM `isupipe` LIKE 'livecomments'\G
#    SHOW CREATE TABLE `isupipe`.`livecomments`\G
# EXPLAIN /*!50100 PARTITIONS*/
SELECT IFNULL(SUM(l2.tip), 0) FROM users u
        INNER JOIN livestreams l ON l.user_id = u.id    
        INNER JOIN livecomments l2 ON l2.livestream_id = l.id
        WHERE u.id = 226\G

# Query 3: 812.73 QPS, 0.68x concurrency, ID 0x4ADE2DC90689F1C4891749AF54FB8D14 at byte 143564542
# Scores: V/M = 0.00
# Time range: 2024-09-22T10:57:08 to 2024-09-22T10:58:08
# Attribute    pct   total     min     max     avg     95%  stddev  median
# ============ === ======= ======= ======= ======= ======= ======= =======
# Count         12   48764
# Exec time     10     41s    99us    31ms   832us     3ms     1ms   316us
# Lock time     12   133ms       0     5ms     2us     1us    44us     1us
# Rows sent      0       0       0       0       0       0       0       0
# Rows examine   0  95.26k       2       4    2.00    1.96    0.02    1.96
# Query size    23  15.37M     263     538  330.41  363.48   27.65  313.99
# String:
# Databases    isupipe
# Hosts        localhost
# Users        isucon
# Query_time distribution
#   1us
#  10us
# 100us  ################################################################
#   1ms  #####################
#  10ms  #
# 100ms
#    1s
#  10s+
# Tables
#    SHOW TABLE STATUS FROM `isupipe` LIKE 'livecomments'\G
#    SHOW CREATE TABLE `isupipe`.`livecomments`\G
DELETE FROM livecomments
            WHERE
            id = 725 AND
            livestream_id = 7560 AND
            (SELECT COUNT(*)
            FROM
            (SELECT 'あっちの人、今めちゃくちゃ笑ってる場面で止まってるよ。何があったんだろ？' AS text) AS texts
            INNER JOIN
            (SELECT CONCAT('%', '逐瑢', '%')  AS pattern) AS patterns
            ON texts.text LIKE patterns.pattern) >= 1\G
# Converted for EXPLAIN
# EXPLAIN /*!50100 PARTITIONS*/
select * from  livecomments
            WHERE
            id = 725 AND
            livestream_id = 7560 AND
            (SELECT COUNT(*)
            FROM
            (SELECT 'あっちの人、今めちゃくちゃ笑ってる場面で止まってるよ。何があったんだろ？' AS text) AS texts
            INNER JOIN
            (SELECT CONCAT('%', '逐瑢', '%')  AS pattern) AS patterns
            ON texts.text LIKE patterns.pattern) >= 1\G

# Query 4: 52.53 QPS, 0.47x concurrency, ID 0xDB74D52D39A7090F224C4DEEAF3028C9 at byte 93244501
# Scores: V/M = 0.01
# Time range: 2024-09-22T10:56:45 to 2024-09-22T10:58:08
# Attribute    pct   total     min     max     avg     95%  stddev  median
# ============ === ======= ======= ======= ======= ======= ======= =======
# Count          1    4360
# Exec time     10     39s     1ms    84ms     9ms    31ms    10ms     3ms
# Lock time      1    15ms       0     3ms     3us     1us    57us     1us
# Rows sent      1   4.26k       1       1       1       1       0       1
# Rows examine  10   8.88M   1.96k   2.65k   2.09k   2.27k  127.92   2.06k
# Query size     0 616.64k     143     146  144.83  143.84    0.84  143.84
# String:
# Databases    isupipe
# Hosts        localhost
# Users        isucon
# Query_time distribution
#   1us
#  10us
# 100us
#   1ms  ################################################################
#  10ms  ##################################
# 100ms
#    1s
#  10s+
# Tables
#    SHOW TABLE STATUS FROM `isupipe` LIKE 'users'\G
#    SHOW CREATE TABLE `isupipe`.`users`\G
#    SHOW TABLE STATUS FROM `isupipe` LIKE 'livestreams'\G
#    SHOW CREATE TABLE `isupipe`.`livestreams`\G
#    SHOW TABLE STATUS FROM `isupipe` LIKE 'reactions'\G
#    SHOW CREATE TABLE `isupipe`.`reactions`\G
# EXPLAIN /*!50100 PARTITIONS*/
SELECT COUNT(*) FROM users u
        INNER JOIN livestreams l ON l.user_id = u.id
        INNER JOIN reactions r ON r.livestream_id = l.id
        WHERE u.id = 264\G

# Query 5: 12.34 QPS, 0.27x concurrency, ID 0x59F1B6DD8D9FEC059E55B3BFD624E8C3 at byte 78693221
# Scores: V/M = 0.01
# Time range: 2024-09-22T10:56:45 to 2024-09-22T10:58:08
# Attribute    pct   total     min     max     avg     95%  stddev  median
# ============ === ======= ======= ======= ======= ======= ======= =======
# Count          0    1024
# Exec time      5     23s     2ms   103ms    22ms    48ms    14ms    19ms
# Lock time      0     5ms       0     1ms     4us     1us    51us     1us
# Rows sent      0   1.00k       1       1       1       1       0       1
# Rows examine  10   8.55M   8.55k   8.55k   8.55k   8.55k       0   8.55k
# Query size     0  86.00k      86      86      86      86       0      86
# String:
# Databases    isupipe
# Hosts        localhost
# Users        isucon
# Query_time distribution
#   1us
#  10us
# 100us
#   1ms  #################
#  10ms  ################################################################
# 100ms  #
#    1s
#  10s+
# Tables
#    SHOW TABLE STATUS FROM `isupipe` LIKE 'reservation_slots'\G
#    SHOW CREATE TABLE `isupipe`.`reservation_slots`\G
# EXPLAIN /*!50100 PARTITIONS*/
SELECT slot FROM reservation_slots WHERE start_at = 1701226800 AND end_at = 1701230400\G

# Query 6: 254.43 QPS, 0.27x concurrency, ID 0x84B457C910C4A79FC9EBECB8B1065C66 at byte 102184325
# Scores: V/M = 0.00
# Time range: 2024-09-22T10:56:45 to 2024-09-22T10:58:08
# Attribute    pct   total     min     max     avg     95%  stddev  median
# ============ === ======= ======= ======= ======= ======= ======= =======
# Count          5   21118
# Exec time      5     23s    73us    44ms     1ms     4ms     2ms   424us
# Lock time     11   123ms       0     6ms     5us     1us   114us     1us
# Rows sent      5  17.39k       0       1    0.84    0.99    0.36    0.99
# Rows examine   0  17.39k       0       1    0.84    0.99    0.36    0.99
# Query size     1 904.54k      41      44   43.86   42.48    0.23   42.48
# String:
# Databases    isupipe
# Hosts        localhost
# Users        isucon
# Query_time distribution
#   1us
#  10us  ##
# 100us  ################################################################
#   1ms  ############################
#  10ms  #
# 100ms
#    1s
#  10s+
# Tables
#    SHOW TABLE STATUS FROM `isupipe` LIKE 'icons'\G
#    SHOW CREATE TABLE `isupipe`.`icons`\G
# EXPLAIN /*!50100 PARTITIONS*/
SELECT image FROM icons WHERE user_id = 1050\G

# Query 7: 677.45 QPS, 0.31x concurrency, ID 0xFBC5564AE716EAE82F20BFB45F6C37E7 at byte 30064961
# Scores: V/M = 0.00
# Time range: 2024-09-22T10:57:01 to 2024-09-22T10:58:08
# Attribute    pct   total     min     max     avg     95%  stddev  median
# ============ === ======= ======= ======= ======= ======= ======= =======
# Count         11   45389
# Exec time      5     21s    44us    28ms   454us     2ms   888us   138us
# Lock time     15   164ms       0    10ms     3us     1us    77us     1us
# Rows sent     14  44.33k       1       1       1       1       0       1
# Rows examine   0  44.33k       1       1       1       1       0       1
# Query size     2   1.38M      31      33   31.92   31.70    0.45   31.70
# String:
# Databases    isupipe
# Hosts        localhost
# Users        isucon
# Query_time distribution
#   1us
#  10us  #################################################
# 100us  ################################################################
#   1ms  ##############
#  10ms  #
# 100ms
#    1s
#  10s+
# Tables
#    SHOW TABLE STATUS FROM `isupipe` LIKE 'tags'\G
#    SHOW CREATE TABLE `isupipe`.`tags`\G
# EXPLAIN /*!50100 PARTITIONS*/
SELECT * FROM tags WHERE id = 20\G

# Query 8: 5.28 QPS, 0.24x concurrency, ID 0x64CC8A4E8E4B390203375597CE4D611F at byte 34032653
# Scores: V/M = 0.01
# Time range: 2024-09-22T10:56:53 to 2024-09-22T10:58:08
# Attribute    pct   total     min     max     avg     95%  stddev  median
# ============ === ======= ======= ======= ======= ======= ======= =======
# Count          0     396
# Exec time      4     18s     4ms   194ms    46ms    78ms    22ms    46ms
# Lock time      0   708us       0    99us     1us     1us     7us     1us
# Rows sent      0     144       0       3    0.36    0.99    0.59       0
# Rows examine   6   5.42M  14.00k  14.03k  14.02k  13.78k       0  13.78k
# Query size     0  38.28k      97      99   98.99   97.36    0.33   97.36
# String:
# Databases    isupipe
# Hosts        localhost
# Users        isucon
# Query_time distribution
#   1us
#  10us
# 100us
#   1ms  ##
#  10ms  ################################################################
# 100ms  #
#    1s
#  10s+
# Tables
#    SHOW TABLE STATUS FROM `isupipe` LIKE 'ng_words'\G
#    SHOW CREATE TABLE `isupipe`.`ng_words`\G
# EXPLAIN /*!50100 PARTITIONS*/
SELECT id, user_id, livestream_id, word FROM ng_words WHERE user_id = 1014 AND livestream_id = 7523\G

# Query 9: 42.82 QPS, 0.21x concurrency, ID 0xFFFCA4D67EA0A788813031B8BBC3B329 at byte 50497044
# Scores: V/M = 0.01
# Time range: 2024-09-22T10:56:45 to 2024-09-22T10:58:08
# Attribute    pct   total     min     max     avg     95%  stddev  median
# ============ === ======= ======= ======= ======= ======= ======= =======
# Count          0    3554
# Exec time      4     17s    21us    66ms     5ms    14ms     5ms     4ms
# Lock time      0       0       0       0       0       0       0       0
# Rows sent      0       0       0       0       0       0       0       0
# Rows examine   0       0       0       0       0       0       0       0
# Query size     0  20.82k       6       6       6       6       0       6
# String:
# Databases    isupipe (3211/90%), isudns (343/9%)
# Hosts        localhost
# Users        isucon (3211/90%), isudns (343/9%)
# Query_time distribution
#   1us
#  10us  ###########################
# 100us  #############
#   1ms  ################################################################
#  10ms  ################
# 100ms
#    1s
#  10s+
COMMIT\G

# Query 10: 319.94 QPS, 0.16x concurrency, ID 0x22279D81D51006139E0C76405B54C261 at byte 63206694
# Scores: V/M = 0.00
# Time range: 2024-09-22T10:56:31 to 2024-09-22T10:58:08
# Attribute    pct   total     min     max     avg     95%  stddev  median
# ============ === ======= ======= ======= ======= ======= ======= =======
# Count          7   31034
# Exec time      3     15s    82us    19ms   484us     2ms   840us   176us
# Lock time      9    99ms       0     5ms     3us     1us    49us     1us
# Rows sent      0       0       0       0       0       0       0       0
# Rows examine   0       0       0       0       0       0       0       0
# Query size     5   3.34M     113     113     113     113       0     113
# String:
# Databases    isudns
# Hosts        localhost
# Users        isudns
# Query_time distribution
#   1us
#  10us  #
# 100us  ################################################################
#   1ms  ########
#  10ms  #
# 100ms
#    1s
#  10s+
# Tables
#    SHOW TABLE STATUS FROM `isudns` LIKE 'domains'\G
#    SHOW CREATE TABLE `isudns`.`domains`\G
#    SHOW TABLE STATUS FROM `isudns` LIKE 'domainmetadata'\G
#    SHOW CREATE TABLE `isudns`.`domainmetadata`\G
# EXPLAIN /*!50100 PARTITIONS*/
select kind,content from domains, domainmetadata where domainmetadata.domain_id=domains.id and name='t.isucon.pw'\G

バイナリも混じったせいか上手くコピペできなかったので、--limit 10をつける

sunakan commented 1 month ago

# Profile
# Rank Query ID                            Response time  Calls  R/Call V/
# ==== =================================== ============== ====== ====== ==
#    1 0x38BC86A45F31C6B1EE324671506C898A   41.7528 10.8%  17683 0.0024  0.00 SELECT themes
#    2 0xF1B8EF06D6CA63B24BFF433E06CCEB22   40.6518 10.5%   4356 0.0093  0.01 SELECT users livestreams livecomments

...

# Query_time distribution
#   1us
#  10us
# 100us  ###################################################
#   1ms  ################################################################
#  10ms  ##
# 100ms
#    1s
#  10s+
# Tables
#    SHOW TABLE STATUS FROM `isupipe` LIKE 'themes'\G
#    SHOW CREATE TABLE `isupipe`.`themes`\G
# EXPLAIN /*!50100 PARTITIONS*/
SELECT * FROM themes WHERE user_id = 1019\G

themesテーブルにuser_idにインデックスを貼るのはどうか

sunakan commented 1 month ago

インデックスは未だ貼られていない

alter table themes add index user_id_idx (user_id);

cat tmp/db-servers | xargs -I{} ssh {} "sudo mysql isupipe -e 'alter table themes add index user_id_idx (user_id);'"

sunakan commented 1 month ago

貼られたことを確認

make clean-log

して計測

スコア：7303

sunakan / isunarabe13-suburi

分析-004(6476→7303) #5