search

saza-ku / isucon13

0 stars 0 forks source link

11250300 #19

Open saza-ku opened 1 year ago

saza-ku commented 1 year ago

isucon1

alp

+-------+--------+--------------+-------+-------+-------+-------+-------+
| COUNT | METHOD |     URI      |  MIN  |  MAX  |  SUM  |  AVG  |  P99  |
+-------+--------+--------------+-------+-------+-------+-------+-------+
| 1     | GET    | /api/tag     | 0.004 | 0.004 | 0.004 | 0.004 | 0.004 |
| 1     | GET    | /api/user/.+ | 0.000 | 0.000 | 0.000 | 0.000 | 0.000 |
+-------+--------+--------------+-------+-------+-------+-------+-------+

slow query

Count: 48  Time=0.00s (0s)  Lock=0.00s (0s)  Rows=0.8 (36), isudns[isudns]@localhost
  SELECT content,ttl,prio,type,domain_id,disabled,name,auth FROM records WHERE disabled=N and name='S' and domain_id=N

Count: 43  Time=0.00s (0s)  Lock=0.00s (0s)  Rows=0.5 (22), isudns[isudns]@localhost
  SELECT content,ttl,prio,type,domain_id,disabled,name,auth FROM records WHERE disabled=N and type='S' and name='S'

Count: 52  Time=0.00s (0s)  Lock=0.00s (0s)  Rows=0.0 (0), isudns[isudns]@localhost
  select kind,content from domains, domainmetadata where domainmetadata.domain_id=domains.id and name='S'

Count: 123  Time=0.00s (0s)  Lock=0.00s (0s)  Rows=0.0 (0), isudns[isudns]@localhost
  #

Count: 1  Time=0.00s (0s)  Lock=0.00s (0s)  Rows=103.0 (103), isucon[isucon]@localhost
  SELECT * FROM tags

Count: 1  Time=0.00s (0s)  Lock=0.00s (0s)  Rows=0.0 (0), isucon[isucon]@localhost
  START TRANSACTION

Count: 1  Time=0.00s (0s)  Lock=0.00s (0s)  Rows=0.0 (0), isucon[isucon]@localhost
  COMMIT

Count: 123  Time=0.00s (0s)  Lock=0.00s (0s)  Rows=0.0 (0), 0users@0hosts
  administrator command: Reset stmt

explain

Reading from STDIN ...

# 140ms user time, 30ms system time, 36.25M rss, 50.69M vsz
# Current date: Sat Nov 25 03:01:26 2023
# Hostname: ip-192-168-0-11
# Files: STDIN
# Overall: 276 total, 13 unique, 3.58 QPS, 0.00x concurrency _____________
# Time range: 2023-11-25T03:00:09 to 2023-11-25T03:01:26
# Attribute          total     min     max     avg     95%  stddev  median
# ============     ======= ======= ======= ======= ======= ======= =======
# Exec time           94ms    11us     4ms   339us     1ms   466us    89us
# Lock time          202us       0    27us       0     1us     1us     1us
# Rows sent            165       0     103    0.60    0.99    6.14       0
# Rows examine     113.85k       0   1.25k  422.42   1.20k  578.40       0
# Query size        21.95k       6     195   81.43  136.99   47.54  112.70

# Profile
# Rank Query ID                        Response time Calls R/Call V/M   It
# ==== =============================== ============= ===== ====== ===== ==
#    1 0x42EF7D7D98FBCC9723BF896EBF...  0.0416 44.4%    48 0.0009  0.00 SELECT records
#    2 0x3D83BC87F3B3A00D571FFC8104...  0.0364 38.8%    43 0.0008  0.00 SELECT records
#    3 0x22279D81D51006139E0C76405B...  0.0058  6.2%    52 0.0001  0.00 SELECT domains domainmetadata
#    4 0xE77769C62EF669AA7DD5F6760F...  0.0050  5.3%     2 0.0025  0.00 SHOW VARIABLES
# MISC 0xMISC                           0.0049  5.3%   131 0.0000   0.0 <9 ITEMS>

# Query 1: 5.33 QPS, 0.00x concurrency, ID 0x42EF7D7D98FBCC9723BF896EBFC51D24 at byte 11657
# This item is included in the report because it matches --limit.
# Scores: V/M = 0.00
# Time range: 2023-11-25T03:00:09 to 2023-11-25T03:00:18
# Attribute    pct   total     min     max     avg     95%  stddev  median
# ============ === ======= ======= ======= ======= ======= ======= =======
# Count         17      48
# Exec time     44    42ms   712us     2ms   867us     1ms   270us   725us
# Lock time     24    50us       0     2us     1us     1us       0     1us
# Rows sent     21      36       0       1    0.75    0.99    0.43    0.99
# Rows examine  52  60.00k   1.25k   1.25k   1.25k   1.25k       0   1.25k
# Query size    28   6.34k     129     144  135.17  143.84    5.30  130.47
# String:
# Hosts        localhost
# Users        isudns
# Query_time distribution
#   1us
#  10us
# 100us  ################################################################
#   1ms  ##############
#  10ms
# 100ms
#    1s
#  10s+
# Tables
#    SHOW TABLE STATUS LIKE 'records'\G
#    SHOW CREATE TABLE `records`\G
# EXPLAIN /*!50100 PARTITIONS*/
SELECT content,ttl,prio,type,domain_id,disabled,name,auth FROM records WHERE disabled=0 and name='rootd.u.isucon.dev' and domain_id=3\G
# EXPLAIN failed: DBD::mysql::st execute failed: Table 'isupipe.records' doesn't exist [for Statement "EXPLAIN SELECT content,ttl,prio,type,domain_id,disabled,name,auth FROM records WHERE disabled=0 and name='rootd.u.isucon.dev' and domain_id=3"] at /usr/bin/pt-query-digest line 7796.

# Query 2: 4.78 QPS, 0.00x concurrency, ID 0x3D83BC87F3B3A00D571FFC8104A6E50C at byte 12785
# This item is included in the report because it matches --limit.
# Scores: V/M = 0.00
# Time range: 2023-11-25T03:00:09 to 2023-11-25T03:00:18
# Attribute    pct   total     min     max     avg     95%  stddev  median
# ============ === ======= ======= ======= ======= ======= ======= =======
# Count         15      43
# Exec time     38    36ms   671us     2ms   845us     1ms   247us   690us
# Lock time     25    52us     1us     4us     1us     1us       0     1us
# Rows sent     13      22       0       1    0.51    0.99    0.50    0.99
# Rows examine  47  53.75k   1.25k   1.25k   1.25k   1.25k       0   1.25k
# Query size    24   5.47k     126     143  130.35  136.99    4.53  124.25
# String:
# Hosts        localhost
# Users        isudns
# Query_time distribution
#   1us
#  10us
# 100us  ################################################################
#   1ms  ###################
#  10ms
# 100ms
#    1s
#  10s+
# Tables
#    SHOW TABLE STATUS LIKE 'records'\G
#    SHOW CREATE TABLE `records`\G
# EXPLAIN 
SELECT content,ttl,prio,type,domain_id,disabled,name,auth FROM records WHERE disabled=0 and type='SOA' and name='bacula-sd.u.isucon.dev'\G
# EXPLAIN failed: DBD::mysql::st execute failed: Table 'isupipe.records' doesn't exist [for Statement "EXPLAIN SELECT content,ttl,prio,type,domain_id,disabled,name,auth FROM records WHERE disabled=0 and type='SOA' and name='bacula-sd.u.isucon.dev'"] at /usr/bin/pt-query-digest line 7796.

# Query 3: 5.78 QPS, 0.00x concurrency, ID 0x22279D81D51006139E0C76405B54C261 at byte 12232
# This item is included in the report because it matches --limit.
# Scores: V/M = 0.00
# Time range: 2023-11-25T03:00:09 to 2023-11-25T03:00:18
# Attribute    pct   total     min     max     avg     95%  stddev  median
# ============ === ======= ======= ======= ======= ======= ======= =======
# Count         18      52
# Exec time      6     6ms    83us   193us   110us   167us    25us    98us
# Lock time     33    68us     1us     2us     1us     1us       0     1us
# Rows sent      0       0       0       0       0       0       0       0
# Rows examine   0       0       0       0       0       0       0       0
# Query size    26   5.79k     114     114     114     114       0     114
# String:
# Hosts        localhost
# Users        isudns
# Query_time distribution
#   1us
#  10us  ########################################
# 100us  ################################################################
#   1ms
#  10ms
# 100ms
#    1s
#  10s+
# Tables
#    SHOW TABLE STATUS LIKE 'domains'\G
#    SHOW CREATE TABLE `domains`\G
#    SHOW TABLE STATUS LIKE 'domainmetadata'\G
#    SHOW CREATE TABLE `domainmetadata`\G
# EXPLAIN 
select kind,content from domains, domainmetadata where domainmetadata.domain_id=domains.id and name='u.isucon.dev'\G
# EXPLAIN failed: DBD::mysql::st execute failed: Table 'isupipe.domains' doesn't exist [for Statement "EXPLAIN select kind,content from domains, domainmetadata where domainmetadata.domain_id=domains.id and name='u.isucon.dev'"] at /usr/bin/pt-query-digest line 7796.

# Query 4: 0 QPS, 0x concurrency, ID 0xE77769C62EF669AA7DD5F6760F2D2EBB at byte 76996
# This item is included in the report because it matches --limit.
# Scores: V/M = 0.00
# Time range: all events occurred at 2023-11-25T03:01:26
# Attribute    pct   total     min     max     avg     95%  stddev  median
# ============ === ======= ======= ======= ======= ======= ======= =======
# Count          0       2
# Exec time      5     5ms   945us     4ms     2ms     4ms     2ms     2ms
# Lock time      2     5us     1us     4us     2us     4us     2us     2us
# Rows sent      1       2       1       1       1       1       0       1
# Rows examine   0       2       1       1       1       1       0       1
# Query size     0      77      35      42   38.50      42    4.95   38.50
# String:
# Databases    isupipe
# Hosts        localhost
# Users        isucon
# Query_time distribution
#   1us
#  10us
# 100us  ################################################################
#   1ms  ################################################################
#  10ms
# 100ms
#    1s
#  10s+
SHOW VARIABLES LIKE 'wait\_timeout'\G

netdata

http://localhost:19991/#menu_services;after=1700881209913;before=1700881285901

pprof

go tool pprof -http=0.0.0.0:1080 http://isucon1/pprof/11250300
saza-ku commented 1 year ago

isucon3

alp

+-------+--------+-----+-----+-----+-----+-----+-----+
| COUNT | METHOD | URI | MIN | MAX | SUM | AVG | P99 |
+-------+--------+-----+-----+-----+-----+-----+-----+
+-------+--------+-----+-----+-----+-----+-----+-----+

slow query

explain

Reading from STDIN ...

# No events processed.

netdata

http://localhost:19993/#menu_services;after=1700881209895;before=1700881289902

pprof

go tool pprof -http=0.0.0.0:1080 http://isucon3/pprof/11250300
saza-ku commented 1 year ago

isucon2

alp

+-------+--------+------------------------------------------+-------+-------+-------+-------+-------+
| COUNT | METHOD |                   URI                    |  MIN  |  MAX  |  SUM  |  AVG  |  P99  |
+-------+--------+------------------------------------------+-------+-------+-------+-------+-------+
| 2     | GET    | /api/user/.+/statistics                  | 4.084 | 4.148 | 8.232 | 4.116 | 4.148 |
| 2     | GET    | /api/livestream/.+/statistics            | 0.028 | 0.032 | 0.060 | 0.030 | 0.032 |
| 1     | POST   | /api/register                            | 0.044 | 0.044 | 0.044 | 0.044 | 0.044 |
| 1     | POST   | /api/livestream/.+                       | 0.036 | 0.036 | 0.036 | 0.036 | 0.036 |
| 3     | POST   | /api/livestream/.+/reaction              | 0.008 | 0.012 | 0.032 | 0.011 | 0.012 |
| 2     | POST   | /api/livestream/.+/livecomment           | 0.012 | 0.016 | 0.028 | 0.014 | 0.016 |
| 2     | POST   | /api/livestream/.+/livecomment/.+/report | 0.012 | 0.016 | 0.028 | 0.014 | 0.016 |
| 1     | POST   | /api/livestream/.+/enter                 | 0.008 | 0.008 | 0.008 | 0.008 | 0.008 |
| 3     | POST   | /api/login                               | 0.000 | 0.004 | 0.004 | 0.001 | 0.004 |
| 3     | GET    | /api/tag                                 | 0.000 | 0.004 | 0.004 | 0.001 | 0.004 |
| 1     | GET    | /api/payment                             | 0.000 | 0.000 | 0.000 | 0.000 | 0.000 |
+-------+--------+------------------------------------------+-------+-------+-------+-------+-------+

slow query

Count: 2000  Time=0.00s (3s)  Lock=0.00s (0s)  Rows=1.0 (2000), isucon[isucon]@localhost
  SELECT IFNULL(SUM(l2.tip), N) 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 = N

Count: 2000  Time=0.00s (3s)  Lock=0.00s (0s)  Rows=1.0 (2000), isucon[isucon]@localhost
  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 = N

Count: 19  Time=0.00s (0s)  Lock=0.00s (0s)  Rows=0.0 (0), isucon[isucon]@localhost
  COMMIT

Count: 2  Time=0.01s (0s)  Lock=0.00s (0s)  Rows=7496.0 (14992), isucon[isucon]@localhost
  SELECT * FROM livestreams

Count: 8  Time=0.00s (0s)  Lock=0.00s (0s)  Rows=0.0 (0), isucon[isucon]@localhost
  SELECT * FROM livestream_tags WHERE livestream_id = N

Count: 7  Time=0.00s (0s)  Lock=0.00s (0s)  Rows=1.0 (7), isucon[isucon]@localhost
  SELECT slot FROM reservation_slots WHERE start_at = N AND end_at = N

Count: 2  Time=0.00s (0s)  Lock=0.00s (0s)  Rows=9.0 (18), isucon[isucon]@localhost
  SELECT * FROM livestreams WHERE user_id = N

Count: 2  Time=0.00s (0s)  Lock=0.00s (0s)  Rows=0.0 (0), isucon[isucon]@localhost
  SELECT id, user_id, livestream_id, word FROM ng_words WHERE user_id = N AND livestream_id = N

explain

Reading from STDIN ...

# 480ms user time, 10ms system time, 37.12M rss, 51.34M vsz
# Current date: Sat Nov 25 03:01:30 2023
# Hostname: ip-192-168-0-12
# Files: STDIN
# Overall: 4.25k total, 56 unique, 52.44 QPS, 0.10x concurrency __________
# Time range: 2023-11-25T03:00:09 to 2023-11-25T03:01:30
# Attribute          total     min     max     avg     95%  stddev  median
# ============     ======= ======= ======= ======= ======= ======= =======
# Exec time             8s     1us    23ms     2ms     2ms   756us     2ms
# Lock time            5ms       0    20us     1us     1us       0     1us
# Rows sent         24.59k       0   7.32k    5.93    0.99  166.09    0.99
# Rows examine       7.92M       0  14.00k   1.91k   1.96k  703.39   1.86k
# Query size       618.31k       5     413  149.05  158.58   26.82  143.84

# Profile
# Rank Query ID                       Response time Calls R/Call V/M   Ite
# ==== ============================== ============= ===== ====== ===== ===
#    1 0xF1B8EF06D6CA63B24BFF433E0...  3.9874 49.5%  2000 0.0020  0.00 SELECT users livestreams livecomments
#    2 0xDB74D52D39A7090F224C4DEEA...  3.8557 47.9%  2000 0.0019  0.00 SELECT users livestreams reactions
#    3 0xFFFCA4D67EA0A788813031B8B...  0.0612  0.8%    20 0.0031  0.00 COMMIT
#    4 0x050F7D44808F43E5D33D0B90B...  0.0274  0.3%     2 0.0137  0.00 SELECT livestreams
# MISC 0xMISC                          0.1219  1.5%   226 0.0005   0.0 <52 ITEMS>

# Query 1: 250 QPS, 0.50x concurrency, ID 0xF1B8EF06D6CA63B24BFF433E06CCEB22 at byte 877253
# This item is included in the report because it matches --limit.
# Scores: V/M = 0.00
# Time range: 2023-11-25T03:00:10 to 2023-11-25T03:00:18
# Attribute    pct   total     min     max     avg     95%  stddev  median
# ============ === ======= ======= ======= ======= ======= ======= =======
# Count         47    2000
# Exec time     49      4s     2ms    23ms     2ms     2ms   617us     2ms
# Lock time     46     2ms       0     3us     1us     1us       0     1us
# Rows sent      7   1.95k       1       1       1       1       0       1
# Rows examine  48   3.82M   1.96k   1.96k   1.96k   1.96k       2   1.96k
# Query size    52 322.06k     163     166  164.89  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 = 163\G
# *************************** 1. row ***************************
#            id: 1
#   select_type: SIMPLE
#         table: u
#    partitions: NULL
#          type: const
# possible_keys: PRIMARY
#           key: PRIMARY
#       key_len: 8
#           ref: const
#          rows: 1
#      filtered: 100.00
#         Extra: Using index
# *************************** 2. row ***************************
#            id: 1
#   select_type: SIMPLE
#         table: l2
#    partitions: NULL
#          type: ALL
# possible_keys: NULL
#           key: NULL
#       key_len: NULL
#           ref: NULL
#          rows: 1003
#      filtered: 100.00
#         Extra: NULL
# *************************** 3. row ***************************
#            id: 1
#   select_type: SIMPLE
#         table: l
#    partitions: NULL
#          type: eq_ref
# possible_keys: PRIMARY
#           key: PRIMARY
#       key_len: 8
#           ref: isupipe.l2.livestream_id
#          rows: 1
#      filtered: 10.00
#         Extra: Using where

# Query 2: 250 QPS, 0.48x concurrency, ID 0xDB74D52D39A7090F224C4DEEAF3028C9 at byte 881223
# This item is included in the report because it matches --limit.
# Scores: V/M = 0.00
# Time range: 2023-11-25T03:00:10 to 2023-11-25T03:00:18
# Attribute    pct   total     min     max     avg     95%  stddev  median
# ============ === ======= ======= ======= ======= ======= ======= =======
# Count         47    2000
# Exec time     47      4s     2ms    21ms     2ms     2ms   547us     2ms
# Lock time     49     2ms     1us    12us     1us     1us       0     1us
# Rows sent      7   1.95k       1       1       1       1       0       1
# Rows examine  48   3.82M   1.96k   1.96k   1.96k   1.96k       3   1.96k
# Query size    45 282.99k     143     146  144.89  143.84    0.65  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 
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 = 169\G
# *************************** 1. row ***************************
#            id: 1
#   select_type: SIMPLE
#         table: u
#    partitions: NULL
#          type: const
# possible_keys: PRIMARY
#           key: PRIMARY
#       key_len: 8
#           ref: const
#          rows: 1
#      filtered: 100.00
#         Extra: Using index
# *************************** 2. row ***************************
#            id: 1
#   select_type: SIMPLE
#         table: r
#    partitions: NULL
#          type: ALL
# possible_keys: NULL
#           key: NULL
#       key_len: NULL
#           ref: NULL
#          rows: 1004
#      filtered: 100.00
#         Extra: NULL
# *************************** 3. row ***************************
#            id: 1
#   select_type: SIMPLE
#         table: l
#    partitions: NULL
#          type: eq_ref
# possible_keys: PRIMARY
#           key: PRIMARY
#       key_len: 8
#           ref: isupipe.r.livestream_id
#          rows: 1
#      filtered: 10.00
#         Extra: Using where

# Query 3: 2.22 QPS, 0.01x concurrency, ID 0xFFFCA4D67EA0A788813031B8BBC3B329 at byte 744662
# This item is included in the report because it matches --limit.
# Scores: V/M = 0.00
# Time range: 2023-11-25T03:00:09 to 2023-11-25T03:00:18
# Attribute    pct   total     min     max     avg     95%  stddev  median
# ============ === ======= ======= ======= ======= ======= ======= =======
# Count          0      20
# Exec time      0    61ms    33us     8ms     3ms     6ms     3ms     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     120       6       6       6       6       0       6
# String:
# Databases    isupipe (19/95%), isudns (1/5%)
# Hosts        localhost
# Users        isucon (19/95%), isudns (1/5%)
# Query_time distribution
#   1us
#  10us  ####################################################
# 100us
#   1ms  ################################################################
#  10ms
# 100ms
#    1s
#  10s+
COMMIT\G

# Query 4: 0.50 QPS, 0.01x concurrency, ID 0x050F7D44808F43E5D33D0B90BCF57CC9 at byte 733021
# This item is included in the report because it matches --limit.
# Scores: V/M = 0.00
# Time range: 2023-11-25T03:00:14 to 2023-11-25T03:00:18
# Attribute    pct   total     min     max     avg     95%  stddev  median
# ============ === ======= ======= ======= ======= ======= ======= =======
# Count          0       2
# Exec time      0    27ms    13ms    14ms    14ms    14ms   464us    14ms
# Lock time      0     1us       0     1us       0     1us       0       0
# Rows sent     59  14.64k   7.32k   7.32k   7.32k   7.32k       0   7.32k
# Rows examine   0  14.64k   7.32k   7.32k   7.32k   7.32k       0   7.32k
# Query size     0      50      25      25      25      25       0      25
# 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 'livestreams'\G
#    SHOW CREATE TABLE `isupipe`.`livestreams`\G
# EXPLAIN 
SELECT * FROM livestreams\G
# *************************** 1. row ***************************
#            id: 1
#   select_type: SIMPLE
#         table: livestreams
#    partitions: NULL
#          type: ALL
# possible_keys: NULL
#           key: NULL
#       key_len: NULL
#           ref: NULL
#          rows: 7229
#      filtered: 100.00
#         Extra: NULL

netdata

http://localhost:19992/#menu_services;after=1700881209896;before=1700881289904

pprof

go tool pprof -http=0.0.0.0:1080 http://isucon2/pprof/11250300