11250758 - Githubissues

saza-ku commented 10 months ago

isucon1

alp

+-------+--------+------------------------------------------+-------+-------+-------+-------+-------+
| COUNT | METHOD |                   URI                    |  MIN  |  MAX  |  SUM  |  AVG  |  P99  |
+-------+--------+------------------------------------------+-------+-------+-------+-------+-------+
| 11    | GET    | /api/livestream/search                   | 0.068 | 0.300 | 2.248 | 0.204 | 0.300 |
| 22    | POST   | /api/livestream/reservation              | 0.012 | 0.020 | 0.316 | 0.014 | 0.020 |
| 42    | GET    | /api/livestream/.+/reaction              | 0.000 | 0.004 | 0.140 | 0.003 | 0.004 |
| 4     | GET    | /api/livestream                          | 0.016 | 0.040 | 0.116 | 0.029 | 0.040 |
| 24    | POST   | /api/livestream/.+/reaction              | 0.004 | 0.004 | 0.092 | 0.004 | 0.004 |
| 2     | POST   | /api/register                            | 0.036 | 0.040 | 0.076 | 0.038 | 0.040 |
| 2     | GET    | /api/user/.+/statistics                  | 0.024 | 0.028 | 0.052 | 0.026 | 0.028 |
| 2     | GET    | /api/livestream/.+/statistics            | 0.024 | 0.028 | 0.052 | 0.026 | 0.028 |
| 5     | GET    | /api/tag                                 | 0.004 | 0.004 | 0.016 | 0.003 | 0.004 |
| 7     | POST   | /api/login                               | 0.000 | 0.004 | 0.016 | 0.002 | 0.004 |
| 2     | POST   | /api/livestream/.+/livecomment/.+/report | 0.004 | 0.008 | 0.012 | 0.006 | 0.008 |
| 3     | POST   | /api/livestream/.+/livecomment           | 0.004 | 0.004 | 0.012 | 0.004 | 0.004 |
| 6     | GET    | /api/user/.+                             | 0.000 | 0.004 | 0.008 | 0.001 | 0.004 |
| 4     | GET    | /api/user/.+/icon                        | 0.004 | 0.004 | 0.008 | 0.002 | 0.004 |
| 2     | POST   | /api/icon                                | 0.004 | 0.004 | 0.008 | 0.004 | 0.004 |
| 1     | GET    | /api/livestream/.+                       | 0.004 | 0.004 | 0.004 | 0.004 | 0.004 |
| 1     | DELETE | /api/livestream/.+/exit                  | 0.004 | 0.004 | 0.004 | 0.004 | 0.004 |
| 1     | GET    | /api/livestream/.+/report                | 0.004 | 0.004 | 0.004 | 0.004 | 0.004 |
| 1     | GET    | /api/payment                             | 0.004 | 0.004 | 0.004 | 0.004 | 0.004 |
| 2     | POST   | /api/livestream/.+/enter                 | 0.000 | 0.000 | 0.000 | 0.000 | 0.000 |
| 1     | GET    | /api/user/.+/theme                       | 0.000 | 0.000 | 0.000 | 0.000 | 0.000 |
| 1     | GET    | /api/livestream/.+/livecomment           | 0.000 | 0.000 | 0.000 | 0.000 | 0.000 |
+-------+--------+------------------------------------------+-------+-------+-------+-------+-------+

slow query

explain

Reading from STDIN ...

# No events processed.

netdata

http://localhost:19991/#menu_services;after=1700899123898;before=1700899199959

pprof

go tool pprof -http=0.0.0.0:1080 http://isucon1/pprof/11250758

saza-ku commented 10 months ago

isucon2

alp

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

slow query

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

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

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

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

Count: 2  Time=0.00s (0s)  Lock=0.00s (0s)  Rows=0.0 (0), isudns[isudns]@isucon1
  delete from records where domain_id=N and name='S' and type='S'

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

Count: 2  Time=0.00s (0s)  Lock=0.00s (0s)  Rows=0.0 (0), isudns[isudns]@isucon1
  insert into records (content,ttl,prio,type,domain_id,disabled,name,ordername,auth) values ('S',N,N,'S',N,N,'S',NULL,N)

Count: 2  Time=0.00s (0s)  Lock=0.00s (0s)  Rows=1.0 (2), isudns[isudns]@isucon1
  select id,name,master,last_check,notified_serial,type,options,catalog,account from domains where name='S'

Count: 4  Time=0.00s (0s)  Lock=0.00s (0s)  Rows=0.0 (0), isudns[isudns]@isucon1
  SET SESSION TRANSACTION ISOLATION LEVEL READ COMMITTED

Count: 2  Time=0.00s (0s)  Lock=0.00s (0s)  Rows=0.0 (0), isudns[isudns]@isucon1
  commit

explain

Reading from STDIN ...

# 180ms user time, 20ms system time, 36.25M rss, 50.68M vsz
# Current date: Sat Nov 25 08:00:04 2023
# Hostname: ip-192-168-0-12
# Files: STDIN
# Overall: 461 total, 20 unique, 5.69 QPS, 0.00x concurrency _____________
# Time range: 2023-11-25T07:58:43 to 2023-11-25T08:00:04
# Attribute          total     min     max     avg     95%  stddev  median
# ============     ======= ======= ======= ======= ======= ======= =======
# Exec time          151ms     1us     5ms   327us   972us   495us    80us
# Lock time          308us       0    26us       0     1us     1us       0
# Rows sent            106       0       1    0.23    0.99    0.42       0
# Rows examine     185.10k       0   1.25k  411.16   1.20k  574.65       0
# Query size        35.47k       5     195   78.79  136.99   47.62   51.63

# Profile
# Rank Query ID                        Response time Calls R/Call V/M   It
# ==== =============================== ============= ===== ====== ===== ==
#    1 0x42EF7D7D98FBCC9723BF896EBF...  0.0668 44.3%    73 0.0009  0.00 SELECT records
#    2 0x3D83BC87F3B3A00D571FFC8104...  0.0595 39.5%    69 0.0009  0.00 SELECT records
#    3 0x22279D81D51006139E0C76405B...  0.0077  5.1%    74 0.0001  0.00 SELECT domains domainmetadata
#    4 0xE77769C62EF669AA7DD5F6760F...  0.0057  3.8%     2 0.0029  0.00 SHOW VARIABLES
# MISC 0xMISC                           0.0110  7.3%   243 0.0000   0.0 <16 ITEMS>

# Query 1: 12.17 QPS, 0.01x concurrency, ID 0x42EF7D7D98FBCC9723BF896EBFC51D24 at byte 17393
# This item is included in the report because it matches --limit.
# Scores: V/M = 0.00
# Time range: 2023-11-25T07:58:43 to 2023-11-25T07:58:49
# Attribute    pct   total     min     max     avg     95%  stddev  median
# ============ === ======= ======= ======= ======= ======= ======= =======
# Count         15      73
# Exec time     44    67ms   706us     2ms   915us     2ms   410us   725us
# Lock time     29    92us       0    22us     1us     1us     2us     1us
# Rows sent     58      62       0       1    0.85    0.99    0.35    0.99
# Rows examine  49  91.30k   1.25k   1.25k   1.25k   1.20k       0   1.20k
# Query size    27   9.61k     129     144  134.78  143.84    4.54  130.47
# String:
# Hosts        isucon1
# 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='epmd.u.isucon.dev' and domain_id=4\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='epmd.u.isucon.dev' and domain_id=4"] at /usr/bin/pt-query-digest line 7796.

# Query 2: 11.50 QPS, 0.01x concurrency, ID 0x3D83BC87F3B3A00D571FFC8104A6E50C at byte 16823
# This item is included in the report because it matches --limit.
# Scores: V/M = 0.00
# Time range: 2023-11-25T07:58:43 to 2023-11-25T07:58:49
# Attribute    pct   total     min     max     avg     95%  stddev  median
# ============ === ======= ======= ======= ======= ======= ======= =======
# Count         14      69
# Exec time     39    59ms   661us     2ms   862us     2ms   373us   690us
# Lock time     28    87us       0     3us     1us     1us       0     1us
# Rows sent     33      36       0       1    0.52    0.99    0.50    0.99
# Rows examine  46  86.30k   1.25k   1.25k   1.25k   1.20k       0   1.20k
# Query size    24   8.75k     126     143  129.87  136.99    4.71  124.25
# String:
# Hosts        isucon1
# 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='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='u.isucon.dev'"] at /usr/bin/pt-query-digest line 7796.

# Query 3: 12.33 QPS, 0.00x concurrency, ID 0x22279D81D51006139E0C76405B54C261 at byte 28239
# This item is included in the report because it matches --limit.
# Scores: V/M = 0.00
# Time range: 2023-11-25T07:58:43 to 2023-11-25T07:58:49
# Attribute    pct   total     min     max     avg     95%  stddev  median
# ============ === ======= ======= ======= ======= ======= ======= =======
# Count         16      74
# Exec time      5     8ms    76us   171us   103us   159us    25us    89us
# Lock time     37   115us     1us    26us     1us     1us     2us     1us
# Rows sent      0       0       0       0       0       0       0       0
# Rows examine   0       0       0       0       0       0       0       0
# Query size    23   8.24k     114     114     114     114       0     114
# String:
# Hosts        isucon1
# 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 129014
# This item is included in the report because it matches --limit.
# Scores: V/M = 0.00
# Time range: all events occurred at 2023-11-25T08:00:04
# Attribute    pct   total     min     max     avg     95%  stddev  median
# ============ === ======= ======= ======= ======= ======= ======= =======
# Count          0       2
# Exec time      3     6ms   978us     5ms     3ms     5ms     3ms     3ms
# Lock time      0     3us       0     3us     1us     3us     2us     1us
# 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:19992/#menu_services;after=1700899123905;before=1700899203914

pprof

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

saza-ku commented 10 months ago

isucon3

alp

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

slow query

Count: 1306  Time=0.00s (0s)  Lock=0.00s (0s)  Rows=1.0 (1306), isucon[isucon]@isucon1
  SELECT * FROM themes WHERE user_id = N

Count: 22  Time=0.01s (0s)  Lock=0.00s (0s)  Rows=0.0 (0), isucon[isucon]@isucon1
  UPDATE reservation_slots SET slot = slot - N WHERE start_at >= N AND end_at <= N

Count: 22  Time=0.01s (0s)  Lock=0.00s (0s)  Rows=1.3 (28), isucon[isucon]@isucon1
  SELECT * FROM reservation_slots WHERE start_at >= N AND end_at <= N FOR UPDATE

Count: 2151  Time=0.00s (0s)  Lock=0.00s (0s)  Rows=1.0 (2151), isucon[isucon]@isucon1
  SELECT * FROM tags WHERE id = N

Count: 1266  Time=0.00s (0s)  Lock=0.00s (0s)  Rows=1.7 (2151), isucon[isucon]@isucon1
  SELECT * FROM livestream_tags WHERE livestream_id = N

Count: 1302  Time=0.00s (0s)  Lock=0.00s (0s)  Rows=1.0 (1302), isucon[isucon]@isucon1
  SELECT * FROM users WHERE id = N

Count: 1096  Time=0.00s (0s)  Lock=0.00s (0s)  Rows=1.0 (1096), isucon[isucon]@isucon1
  SELECT * FROM livestreams WHERE id = N

Count: 641  Time=0.00s (0s)  Lock=0.00s (0s)  Rows=0.0 (3), isucon[isucon]@isucon1
  SELECT icon_path FROM icons WHERE user_id = N

Count: 6  Time=0.00s (0s)  Lock=0.00s (0s)  Rows=12.3 (74), isucon[isucon]@isucon1
  SELECT * FROM livestreams WHERE user_id = N

Count: 9  Time=0.00s (0s)  Lock=0.00s (0s)  Rows=112.9 (1016), isucon[isucon]@isucon1
  SELECT * FROM livestream_tags WHERE tag_id IN (N) ORDER BY livestream_id DESC

explain

Reading from STDIN ...

# 770ms user time, 10ms system time, 36.88M rss, 51.33M vsz
# Current date: Sat Nov 25 08:00:04 2023
# Hostname: ip-192-168-0-13
# Files: STDIN
# Overall: 8.44k total, 58 unique, 105.50 QPS, 0.01x concurrency _________
# Time range: 2023-11-25T07:58:44 to 2023-11-25T08:00:04
# Attribute          total     min     max     avg     95%  stddev  median
# ============     ======= ======= ======= ======= ======= ======= =======
# Exec time             1s    12us     9ms   124us   236us   423us    52us
# Lock time            4ms       0    15us       0     1us       0       0
# Rows sent         32.39k       0   7.32k    3.93    1.96  118.69    0.99
# Rows examine       1.82M       0  10.89k  226.72  964.41  825.19    0.99
# Query size       340.45k       6     410   41.31   54.21   20.04   38.53

# Profile
# Rank Query ID                       Response time Calls R/Call V/M   Ite
# ==== ============================== ============= ===== ====== ===== ===
#    1 0x38BC86A45F31C6B1EE3246715...  0.3223 30.6%  1306 0.0002  0.00 SELECT themes
#    2 0xA3401CA3ABCC04C3AB221DB8A...  0.1165 11.0%    22 0.0053  0.00 UPDATE reservation_slots
#    3 0x7F9C0C0BA9473953B723EE16C...  0.1141 10.8%    22 0.0052  0.00 SELECT reservation_slots
#    4 0xFBC5564AE716EAE82F20BFB45...  0.1092 10.4%  2151 0.0001  0.00 SELECT tags
# MISC 0xMISC                          0.3925 37.2%  4939 0.0001   0.0 <54 ITEMS>

# Query 1: 25.12 QPS, 0.01x concurrency, ID 0x38BC86A45F31C6B1EE324671506C898A at byte 802582
# This item is included in the report because it matches --limit.
# Scores: V/M = 0.00
# Time range: 2023-11-25T07:58:44 to 2023-11-25T07:59:36
# Attribute    pct   total     min     max     avg     95%  stddev  median
# ============ === ======= ======= ======= ======= ======= ======= =======
# Count         15    1306
# Exec time     30   322ms   236us   640us   246us   260us    21us   236us
# Lock time     15   619us       0    14us       0     1us       0       0
# Rows sent      3   1.28k       1       1       1       1       0       1
# Rows examine  68   1.25M    1000    1002 1001.10  964.41    0.00  964.41
# Query size    14  51.05k      38      41   40.02   40.45    0.77   38.53
# String:
# Hosts        isucon1
# Users        isucon
# Query_time distribution
#   1us
#  10us
# 100us  ################################################################
#   1ms
#  10ms
# 100ms
#    1s
#  10s+
# Tables
#    SHOW TABLE STATUS LIKE 'themes'\G
#    SHOW CREATE TABLE `themes`\G
# EXPLAIN /*!50100 PARTITIONS*/
SELECT * FROM themes WHERE user_id = 128\G
# *************************** 1. row ***************************
#            id: 1
#   select_type: SIMPLE
#         table: themes
#    partitions: NULL
#          type: ALL
# possible_keys: NULL
#           key: NULL
#       key_len: NULL
#           ref: NULL
#          rows: 1002
#      filtered: 10.00
#         Extra: Using where

# Query 2: 22 QPS, 0.12x concurrency, ID 0xA3401CA3ABCC04C3AB221DB8AD5CBF26 at byte 254202
# This item is included in the report because it matches --limit.
# Scores: V/M = 0.00
# Time range: 2023-11-25T07:58:44 to 2023-11-25T07:58:45
# Attribute    pct   total     min     max     avg     95%  stddev  median
# ============ === ======= ======= ======= ======= ======= ======= =======
# Count          0      22
# Exec time     11   117ms     5ms     6ms     5ms     5ms   109us     5ms
# Lock time      0    13us       0     1us       0     1us       0     1us
# Rows sent      0       0       0       0       0       0       0       0
# Rows examine  10 188.18k   8.55k   8.55k   8.55k   8.55k       0   8.55k
# Query size     0   2.11k      98      98      98      98       0      98
# String:
# Hosts        isucon1
# Users        isucon
# Query_time distribution
#   1us
#  10us
# 100us
#   1ms  ################################################################
#  10ms
# 100ms
#    1s
#  10s+
# Tables
#    SHOW TABLE STATUS LIKE 'reservation_slots'\G
#    SHOW CREATE TABLE `reservation_slots`\G
UPDATE reservation_slots SET slot = slot - 1 WHERE start_at >= 1711933200 AND end_at <= 1711936800\G
# Converted for EXPLAIN
# EXPLAIN 
select  slot = slot - 1 from reservation_slots where  start_at >= 1711933200 AND end_at <= 1711936800\G

# Query 3: 22 QPS, 0.11x concurrency, ID 0x7F9C0C0BA9473953B723EE16C08655F1 at byte 474595
# This item is included in the report because it matches --limit.
# Scores: V/M = 0.00
# Time range: 2023-11-25T07:58:44 to 2023-11-25T07:58:45
# Attribute    pct   total     min     max     avg     95%  stddev  median
# ============ === ======= ======= ======= ======= ======= ======= =======
# Count          0      22
# Exec time     10   114ms     5ms     6ms     5ms     5ms   261us     5ms
# Lock time      0    13us       0     1us       0     1us       0     1us
# Rows sent      0      28       1       7    1.27    0.99    1.25    0.99
# Rows examine  10 188.18k   8.55k   8.55k   8.55k   8.55k       0   8.55k
# Query size     0   2.06k      96      96      96      96       0      96
# String:
# Hosts        isucon1
# Users        isucon
# Query_time distribution
#   1us
#  10us
# 100us
#   1ms  ################################################################
#  10ms
# 100ms
#    1s
#  10s+
# Tables
#    SHOW TABLE STATUS LIKE 'reservation_slots'\G
#    SHOW CREATE TABLE `reservation_slots`\G
# EXPLAIN 
SELECT * FROM reservation_slots WHERE start_at >= 1711962000 AND end_at <= 1711965600 FOR UPDATE\G
# *************************** 1. row ***************************
#            id: 1
#   select_type: SIMPLE
#         table: reservation_slots
#    partitions: NULL
#          type: ALL
# possible_keys: NULL
#           key: NULL
#       key_len: NULL
#           ref: NULL
#          rows: 8593
#      filtered: 11.11
#         Extra: Using where

# Query 4: 430.20 QPS, 0.02x concurrency, ID 0xFBC5564AE716EAE82F20BFB45F6C37E7 at byte 228832
# This item is included in the report because it matches --limit.
# Scores: V/M = 0.00
# Time range: 2023-11-25T07:58:44 to 2023-11-25T07:58:49
# Attribute    pct   total     min     max     avg     95%  stddev  median
# ============ === ======= ======= ======= ======= ======= ======= =======
# Count         25    2151
# Exec time     10   109ms    41us   123us    50us    60us     6us    49us
# Lock time     25     1ms       0     2us       0     1us       0       0
# Rows sent      6   2.10k       1       1       1       1       0       1
# Rows examine   0   2.10k       1       1       1       1       0       1
# Query size    19  66.96k      31      33   31.88   31.70    0.61   31.70
# String:
# Hosts        isucon1
# Users        isucon
# Query_time distribution
#   1us
#  10us  ################################################################
# 100us  #
#   1ms
#  10ms
# 100ms
#    1s
#  10s+
# Tables
#    SHOW TABLE STATUS LIKE 'tags'\G
#    SHOW CREATE TABLE `tags`\G
# EXPLAIN 
SELECT * FROM tags WHERE id = 50\G
# *************************** 1. row ***************************
#            id: 1
#   select_type: SIMPLE
#         table: tags
#    partitions: NULL
#          type: const
# possible_keys: PRIMARY
#           key: PRIMARY
#       key_len: 8
#           ref: const
#          rows: 1
#      filtered: 100.00
#         Extra: NULL

netdata

http://localhost:19993/#menu_services;after=1700899123901;before=1700899203907

pprof

go tool pprof -http=0.0.0.0:1080 http://isucon3/pprof/11250758

saza-ku / isucon13

11250758 #87

isucon1

alp

slow query

explain

netdata

pprof

isucon2

alp

slow query

explain

netdata

pprof

isucon3

alp

slow query

explain

netdata

pprof