11250736 - Githubissues

saza-ku commented 8 months ago

isucon1

alp

+-------+--------+------------------------------------------+-------+-------+-------+-------+-------+
| COUNT | METHOD |                   URI                    |  MIN  |  MAX  |  SUM  |  AVG  |  P99  |
+-------+--------+------------------------------------------+-------+-------+-------+-------+-------+
| 2     | GET    | /api/livestream/.+/statistics            | 0.024 | 0.028 | 0.052 | 0.026 | 0.028 |
| 2     | GET    | /api/user/.+/statistics                  | 0.024 | 0.024 | 0.048 | 0.024 | 0.024 |
| 1     | POST   | /api/register                            | 0.036 | 0.036 | 0.036 | 0.036 | 0.036 |
| 2     | POST   | /api/livestream/.+                       | 0.012 | 0.020 | 0.032 | 0.016 | 0.020 |
| 2     | GET    | /api/livestream/.+                       | 0.004 | 0.016 | 0.020 | 0.010 | 0.016 |
| 3     | POST   | /api/livestream/.+/reaction              | 0.004 | 0.004 | 0.012 | 0.004 | 0.004 |
| 2     | POST   | /api/livestream/.+/livecomment/.+/report | 0.004 | 0.008 | 0.012 | 0.006 | 0.008 |
| 4     | GET    | /api/tag                                 | 0.004 | 0.004 | 0.012 | 0.003 | 0.004 |
| 2     | POST   | /api/livestream/.+/livecomment           | 0.004 | 0.004 | 0.008 | 0.004 | 0.004 |
| 2     | POST   | /api/livestream/.+/enter                 | 0.004 | 0.004 | 0.004 | 0.002 | 0.004 |
| 1     | GET    | /api/user/.+                             | 0.004 | 0.004 | 0.004 | 0.004 | 0.004 |
| 3     | POST   | /api/login                               | 0.000 | 0.000 | 0.000 | 0.000 | 0.000 |
| 1     | GET    | /api/payment                             | 0.000 | 0.000 | 0.000 | 0.000 | 0.000 |
| 1     | DELETE | /api/livestream/.+/exit                  | 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=1700897778518;before=1700897854574

pprof

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

saza-ku commented 8 months ago

isucon2

alp

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

slow query

Count: 52  Time=0.00s (0s)  Lock=0.00s (0s)  Rows=0.8 (42), 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: 49  Time=0.00s (0s)  Lock=0.00s (0s)  Rows=0.5 (25), 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: 54  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: 143  Time=0.00s (0s)  Lock=0.00s (0s)  Rows=0.0 (0), isudns[isudns]@isucon1
  #

Count: 1  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: 2  Time=0.00s (0s)  Lock=0.00s (0s)  Rows=0.5 (1), 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: 3  Time=0.00s (0s)  Lock=0.00s (0s)  Rows=0.0 (0), isudns[isudns]@isucon1
  SET SESSION TRANSACTION ISOLATION LEVEL READ COMMITTED

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

Count: 1  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: 1  Time=0.00s (0s)  Lock=0.00s (0s)  Rows=0.0 (0), isudns[isudns]@isucon1
  commit

explain

Reading from STDIN ...

# 150ms user time, 20ms system time, 36.50M rss, 50.69M vsz
# Current date: Sat Nov 25 07:37:38 2023
# Hostname: ip-192-168-0-12
# Files: STDIN
# Overall: 315 total, 20 unique, 3.94 QPS, 0.00x concurrency _____________
# Time range: 2023-11-25T07:36:18 to 2023-11-25T07:37:38
# Attribute          total     min     max     avg     95%  stddev  median
# ============     ======= ======= ======= ======= ======= ======= =======
# Exec time           92ms     1us     4ms   293us   761us   395us    80us
# Lock time          176us       0    10us       0     1us       0       0
# Rows sent             73       0       1    0.23    0.99    0.42       0
# Rows examine     130.02k       0   1.25k  422.67   1.20k  578.83       0
# Query size        24.80k       5     195   80.62  136.99   47.55  112.70

# Profile
# Rank Query ID                        Response time Calls R/Call V/M   It
# ==== =============================== ============= ===== ====== ===== ==
#    1 0x42EF7D7D98FBCC9723BF896EBF...  0.0394 42.6%    52 0.0008  0.00 SELECT records
#    2 0x3D83BC87F3B3A00D571FFC8104...  0.0368 39.8%    49 0.0008  0.00 SELECT records
#    3 0x22279D81D51006139E0C76405B...  0.0050  5.4%    54 0.0001  0.00 SELECT domains domainmetadata
#    4 0xE77769C62EF669AA7DD5F6760F...  0.0048  5.1%     2 0.0024  0.00 SHOW VARIABLES
# MISC 0xMISC                           0.0065  7.1%   158 0.0000   0.0 <16 ITEMS>

# Query 1: 0 QPS, 0x concurrency, ID 0x42EF7D7D98FBCC9723BF896EBFC51D24 at byte 11386
# This item is included in the report because it matches --limit.
# Scores: V/M = 0.00
# Time range: all events occurred at 2023-11-25T07:36:18
# Attribute    pct   total     min     max     avg     95%  stddev  median
# ============ === ======= ======= ======= ======= ======= ======= =======
# Count         16      52
# Exec time     42    39ms   704us     1ms   757us   761us   101us   725us
# Lock time     26    46us       0     1us       0     1us       0     1us
# Rows sent     57      42       0       1    0.81    0.99    0.39    0.99
# Rows examine  49  65.01k   1.25k   1.25k   1.25k   1.20k       0   1.20k
# Query size    27   6.84k     129     144  134.71  143.84    4.93  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='x11-2.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='x11-2.u.isucon.dev' and domain_id=4"] at /usr/bin/pt-query-digest line 7796.

# Query 2: 0 QPS, 0x concurrency, ID 0x3D83BC87F3B3A00D571FFC8104A6E50C at byte 1068
# This item is included in the report because it matches --limit.
# Scores: V/M = 0.00
# Time range: all events occurred at 2023-11-25T07:36:18
# Attribute    pct   total     min     max     avg     95%  stddev  median
# ============ === ======= ======= ======= ======= ======= ======= =======
# Count         15      49
# Exec time     39    37ms   659us     1ms   750us     1ms   167us   690us
# Lock time     34    60us       0    10us     1us     1us     1us     1us
# Rows sent     34      25       0       1    0.51    0.99    0.50    0.99
# Rows examine  47  61.26k   1.25k   1.25k   1.25k   1.20k       0   1.20k
# Query size    25   6.22k     126     143  129.92  136.99    4.39  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: 0 QPS, 0x concurrency, ID 0x22279D81D51006139E0C76405B54C261 at byte 11963
# This item is included in the report because it matches --limit.
# Scores: V/M = 0.00
# Time range: all events occurred at 2023-11-25T07:36:18
# Attribute    pct   total     min     max     avg     95%  stddev  median
# ============ === ======= ======= ======= ======= ======= ======= =======
# Count         17      54
# Exec time      5     5ms    77us   132us    92us   108us    11us    89us
# Lock time     34    60us       0     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    24   6.01k     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 88165
# This item is included in the report because it matches --limit.
# Scores: V/M = 0.00
# Time range: all events occurred at 2023-11-25T07:37:38
# Attribute    pct   total     min     max     avg     95%  stddev  median
# ============ === ======= ======= ======= ======= ======= ======= =======
# Count          0       2
# Exec time      5     5ms   960us     4ms     2ms     4ms     2ms     2ms
# Lock time      2     5us     2us     3us     2us     3us       0     2us
# Rows sent      2       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=1700897778531;before=1700897858540

pprof

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

saza-ku commented 8 months ago

isucon3

alp

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

slow query

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

Count: 2  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: 2  Time=0.01s (0s)  Lock=0.00s (0s)  Rows=4.0 (8), isucon[isucon]@isucon1
  SELECT * FROM reservation_slots WHERE start_at >= N AND end_at <= N FOR UPDATE

Count: 2  Time=0.00s (0s)  Lock=0.00s (0s)  Rows=632.5 (1265), isucon[isucon]@isucon1
  SELECT u.id AS id, COUNT(*) AS count FROM users u
  INNER JOIN livestreams l ON l.user_id = u.id
  INNER JOIN reactions r ON r.livestream_id = l.id
  GROUP BY u.id

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

Count: 2  Time=0.00s (0s)  Lock=0.00s (0s)  Rows=642.0 (1284), isucon[isucon]@isucon1
  SELECT u.id AS id, IFNULL(SUM(l2.tip), N) AS count FROM users u
  INNER JOIN livestreams l ON l.user_id = u.id  
  INNER JOIN livecomments l2 ON l2.livestream_id = l.id
  GROUP BY u.id

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

Count: 2  Time=0.00s (0s)  Lock=0.00s (0s)  Rows=933.5 (1867), isucon[isucon]@isucon1
  SELECT l.id AS id, IFNULL(SUM(l2.tip), N) AS count FROM livestreams l INNER JOIN livecomments l2 ON l.id = l2.livestream_id GROUP BY l.id

explain

Reading from STDIN ...

# 160ms user time, 20ms system time, 36.62M rss, 51.07M vsz
# Current date: Sat Nov 25 07:37:38 2023
# Hostname: ip-192-168-0-13
# Files: STDIN
# Overall: 286 total, 54 unique, 3.58 QPS, 0.00x concurrency _____________
# Time range: 2023-11-25T07:36:18 to 2023-11-25T07:37:38
# Attribute          total     min     max     avg     95%  stddev  median
# ============     ======= ======= ======= ======= ======= ======= =======
# Exec time          105ms    12us     9ms   367us     2ms     1ms    60us
# Lock time          151us       0     5us       0     1us       0       0
# Rows sent         23.96k       0   7.32k   85.77  107.34  639.36    0.99
# Rows examine     129.04k       0  10.72k  462.01   1.96k   1.49k    0.99
# Query size        18.37k       6     724   65.78  166.51   96.73   40.45

# Profile
# Rank Query ID                        Response time Calls R/Call V/M   It
# ==== =============================== ============= ===== ====== ===== ==
#    1 0x050F7D44808F43E5D33D0B90BC...  0.0170 16.1%     2 0.0085  0.00 SELECT livestreams
#    2 0xA3401CA3ABCC04C3AB221DB8AD...  0.0107 10.1%     2 0.0053  0.00 UPDATE reservation_slots
#    3 0x7F9C0C0BA9473953B723EE16C0...  0.0102  9.7%     2 0.0051  0.00 SELECT reservation_slots
#    4 0xD00CB321F396631866985B8902...  0.0090  8.6%     2 0.0045  0.00 SELECT users livestreams reactions
# MISC 0xMISC                           0.0583 55.4%   278 0.0002   0.0 <50 ITEMS>

# Query 1: 0 QPS, 0x concurrency, ID 0x050F7D44808F43E5D33D0B90BCF57CC9 at byte 11956
# This item is included in the report because it matches --limit.
# Scores: V/M = 0.00
# Time range: all events occurred at 2023-11-25T07:36:18
# Attribute    pct   total     min     max     avg     95%  stddev  median
# ============ === ======= ======= ======= ======= ======= ======= =======
# Count          0       2
# Exec time     16    17ms     8ms     9ms     8ms     9ms   688us     8ms
# Lock time      1     2us     1us     1us     1us     1us       0     1us
# Rows sent     61  14.64k   7.32k   7.32k   7.32k   7.32k       0   7.32k
# Rows examine  11  14.64k   7.32k   7.32k   7.32k   7.32k       0   7.32k
# Query size     0      50      25      25      25      25       0      25
# String:
# Hosts        isucon1
# Users        isucon
# Query_time distribution
#   1us
#  10us
# 100us
#   1ms  ################################################################
#  10ms
# 100ms
#    1s
#  10s+
# Tables
#    SHOW TABLE STATUS LIKE 'livestreams'\G
#    SHOW CREATE TABLE `livestreams`\G
# EXPLAIN /*!50100 PARTITIONS*/
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: 7348
#      filtered: 100.00
#         Extra: NULL

# Query 2: 0 QPS, 0x concurrency, ID 0xA3401CA3ABCC04C3AB221DB8AD5CBF26 at byte 1883
# This item is included in the report because it matches --limit.
# Scores: V/M = 0.00
# Time range: all events occurred at 2023-11-25T07:36:18
# Attribute    pct   total     min     max     avg     95%  stddev  median
# ============ === ======= ======= ======= ======= ======= ======= =======
# Count          0       2
# Exec time     10    11ms     5ms     5ms     5ms     5ms   115us     5ms
# Lock time      1     2us     1us     1us     1us     1us       0     1us
# Rows sent      0       0       0       0       0       0       0       0
# Rows examine  13  17.11k   8.55k   8.55k   8.55k   8.55k       0   8.55k
# Query size     1     196      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 >= 1700874000 AND end_at <= 1700899200\G
# Converted for EXPLAIN
# EXPLAIN 
select  slot = slot - 1 from reservation_slots where  start_at >= 1700874000 AND end_at <= 1700899200\G

# Query 3: 0 QPS, 0x concurrency, ID 0x7F9C0C0BA9473953B723EE16C08655F1 at byte 1581
# This item is included in the report because it matches --limit.
# Scores: V/M = 0.00
# Time range: all events occurred at 2023-11-25T07:36:18
# Attribute    pct   total     min     max     avg     95%  stddev  median
# ============ === ======= ======= ======= ======= ======= ======= =======
# Count          0       2
# Exec time      9    10ms     5ms     5ms     5ms     5ms    98us     5ms
# Lock time      1     2us     1us     1us     1us     1us       0     1us
# Rows sent      0       8       1       7       4       7    4.24       4
# Rows examine  13  17.11k   8.55k   8.55k   8.55k   8.55k       0   8.55k
# Query size     1     192      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 >= 1700874000 AND end_at <= 1700899200 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: 0 QPS, 0x concurrency, ID 0xD00CB321F396631866985B89023C5836 at byte 4669
# This item is included in the report because it matches --limit.
# Scores: V/M = 0.00
# Time range: all events occurred at 2023-11-25T07:36:18
# Attribute    pct   total     min     max     avg     95%  stddev  median
# ============ === ======= ======= ======= ======= ======= ======= =======
# Count          0       2
# Exec time      8     9ms     3ms     6ms     5ms     6ms     2ms     5ms
# Lock time      1     3us     1us     2us     1us     2us       0     1us
# Rows sent      5   1.24k     632     633  632.50     633    0.71  632.50
# Rows examine   4   5.87k   2.93k   2.94k   2.94k   2.94k    6.36   2.94k
# Query size     1     320     160     160     160     160       0     160
# String:
# Hosts        isucon1
# Users        isucon
# Query_time distribution
#   1us
#  10us
# 100us
#   1ms  ################################################################
#  10ms
# 100ms
#    1s
#  10s+
# Tables
#    SHOW TABLE STATUS LIKE 'users'\G
#    SHOW CREATE TABLE `users`\G
#    SHOW TABLE STATUS LIKE 'livestreams'\G
#    SHOW CREATE TABLE `livestreams`\G
#    SHOW TABLE STATUS LIKE 'reactions'\G
#    SHOW CREATE TABLE `reactions`\G
# EXPLAIN 
SELECT u.id AS id, COUNT(*) AS count FROM users u
    INNER JOIN livestreams l ON l.user_id = u.id
    INNER JOIN reactions r ON r.livestream_id = l.id
    GROUP BY u.id\G
# *************************** 1. 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: Using temporary
# *************************** 2. 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: 100.00
#         Extra: NULL
# *************************** 3. row ***************************
#            id: 1
#   select_type: SIMPLE
#         table: u
#    partitions: NULL
#          type: eq_ref
# possible_keys: PRIMARY,uniq_user_name
#           key: PRIMARY
#       key_len: 8
#           ref: isupipe.l.user_id
#          rows: 1
#      filtered: 100.00
#         Extra: Using index

netdata

http://localhost:19993/#menu_services;after=1700897778516;before=1700897858523

pprof

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

saza-ku / isucon13

11250736 #80

isucon1

alp

slow query

explain

netdata

pprof

isucon2

alp

slow query

explain

netdata

pprof

isucon3

alp

slow query

explain

netdata

pprof