11091044 - Githubissues

isucon1

alp

+-------+--------+--------------------+-------+-------+--------+-------+-------+
| COUNT | METHOD |        URI         |  MIN  |  MAX  |  SUM   |  AVG  |  P99  |
+-------+--------+--------------------+-------+-------+--------+-------+-------+
| 7105  | GET    | /                  | 0.004 | 0.056 | 51.606 | 0.007 | 0.024 |
| 5356  | GET    | /posts/.+          | 0.004 | 0.108 | 26.045 | 0.005 | 0.016 |
| 1899  | GET    | /@.+               | 0.004 | 0.068 | 19.925 | 0.010 | 0.028 |
| 1172  | POST   | /                  | 0.000 | 0.208 | 16.381 | 0.014 | 0.064 |
| 1889  | POST   | /register          | 0.004 | 0.228 | 15.512 | 0.008 | 0.020 |
| 1589  | POST   | /comment           | 0.004 | 0.252 | 13.360 | 0.008 | 0.020 |
| 5022  | POST   | /login             | 0.000 | 0.032 | 9.860  | 0.002 | 0.012 |
| 530   | GET    | /posts             | 0.004 | 0.056 | 6.756  | 0.013 | 0.032 |
| 4057  | GET    | /favicon.ico       | 0.000 | 0.016 | 4.156  | 0.001 | 0.008 |
| 4057  | GET    | /js/timeago.min.js | 0.000 | 0.016 | 3.932  | 0.001 | 0.008 |
| 4057  | GET    | /css/style.css     | 0.000 | 0.028 | 3.676  | 0.001 | 0.008 |
| 4057  | GET    | /js/main.js        | 0.004 | 0.020 | 3.496  | 0.001 | 0.008 |
| 1889  | GET    | /admin/banned      | 0.000 | 0.020 | 3.388  | 0.002 | 0.012 |
| 248   | GET    | /login             | 0.000 | 0.012 | 0.484  | 0.002 | 0.008 |
| 124   | GET    | /logout            | 0.000 | 0.012 | 0.228  | 0.002 | 0.008 |
| 28868 | GET    | /image/.+          | 0.000 | 0.000 | 0.000  | 0.000 | 0.000 |
+-------+--------+--------------------+-------+-------+--------+-------+-------+

slow query

Count: 1889  Time=0.01s (10s)  Lock=0.00s (0s)  Rows=0.0 (0), isuconp[isuconp]@localhost
  INSERT INTO `users` (`account_name`, `passhash`) VALUES ('S','S')

Count: 1589  Time=0.01s (9s)  Lock=0.00s (0s)  Rows=0.0 (0), isuconp[isuconp]@localhost
  INSERT INTO `comments` (`post_id`, `user_id`, `comment`) VALUES (N,N,'S')

Count: 586  Time=0.01s (3s)  Lock=0.00s (0s)  Rows=0.0 (0), isuconp[isuconp]@localhost
  INSERT INTO `not_banned_posts_without_imgdata` (`user_id`, `mime`, `body`) VALUES (N,'S','S')

Count: 7643  Time=0.00s (3s)  Lock=0.00s (0s)  Rows=17.9 (137110), isuconp[isuconp]@localhost
  SELECT * FROM comments WHERE post_id IN (N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N) ORDER BY `created_at` DESC

Count: 7643  Time=0.00s (2s)  Lock=0.00s (0s)  Rows=2.1 (16006), isuconp[isuconp]@localhost
  SELECT `post_id`, COUNT(*) AS `count` FROM `comments` WHERE `post_id` IN (N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N) GROUP BY `post_id`

Count: 15077  Time=0.00s (2s)  Lock=0.00s (0s)  Rows=1.0 (15077), isuconp[isuconp]@localhost
  SELECT * FROM `users` WHERE `id` = N

Count: 7105  Time=0.00s (1s)  Lock=0.00s (0s)  Rows=20.0 (142100), isuconp[isuconp]@localhost
  SELECT `id`, `user_id`, `body`, `mime`, `created_at` FROM `not_banned_posts_without_imgdata` ORDER BY `created_at` DESC LIMIT N

Count: 5356  Time=0.00s (1s)  Lock=0.00s (0s)  Rows=8.5 (45613), isuconp[isuconp]@localhost
  SELECT * FROM comments WHERE post_id IN (N) ORDER BY `created_at` DESC

Count: 4384  Time=0.00s (0s)  Lock=0.00s (0s)  Rows=19.8 (86815), isuconp[isuconp]@localhost
  SELECT * FROM users WHERE id IN (N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N)

Count: 5356  Time=0.00s (0s)  Lock=0.00s (0s)  Rows=0.9 (4713), isuconp[isuconp]@localhost
  SELECT `post_id`, COUNT(*) AS `count` FROM `comments` WHERE `post_id` IN (N) GROUP BY `post_id`

explain

Reading from STDIN ...

# 8s user time, 60ms system time, 37.35M rss, 50.94M vsz
# Current date: Thu Nov  9 22:45:46 2023
# Hostname: private-isu
# Files: STDIN
# Overall: 101.57k total, 23 unique, 1.30k QPS, 0.59x concurrency ________
# Time range: 2023-11-09T13:44:20 to 2023-11-09T13:45:38
# Attribute          total     min     max     avg     95%  stddev  median
# ============     ======= ======= ======= ======= ======= ======= =======
# Exec time            46s     1us   249ms   451us     1ms     2ms   167us
# Lock time          170ms       0     2ms     1us     1us     9us     1us
# Rows sent          1.08M       0     245   11.19   51.63   28.30    0.99
# Rows examine       2.07M       0     490   21.37  118.34   50.97    0.99
# Query size        11.59M      17   1.29k  119.63  223.14  118.32   92.72

# Profile
# Rank Query ID                      Response time Calls R/Call V/M   Item
# ==== ============================= ============= ===== ====== ===== ====
#    1 0x26489ECBE26887E480CA8067... 10.7120 23.3%  1889 0.0057  0.01 INSERT users
#    2 0x9F2038550F51B0A3AB05CA52...  9.3097 20.3%  1589 0.0059  0.01 INSERT comments
#    3 0x1ADC9E80BE48F05D4A5F6D65...  6.1361 13.4% 14890 0.0004  0.00 SELECT comments
#    4 0x9B36FBB6889AD40E391C181F...  4.2233  9.2% 14890 0.0003  0.00 SELECT comments
# MISC 0xMISC                        15.5257 33.8% 68315 0.0002   0.0 <19 ITEMS>

# Query 1: 31.48 QPS, 0.18x concurrency, ID 0x26489ECBE26887E480CA8067F971EA04 at byte 10066623
# This item is included in the report because it matches --limit.
# Scores: V/M = 0.01
# Time range: 2023-11-09T13:44:20 to 2023-11-09T13:45:20
# Attribute    pct   total     min     max     avg     95%  stddev  median
# ============ === ======= ======= ======= ======= ======= ======= =======
# Count          1    1889
# Exec time     23     11s     2ms   227ms     6ms     8ms     7ms     5ms
# Lock time      1     3ms       0   240us     1us     1us     6us     1us
# Rows sent      0       0       0       0       0       0       0       0
# Rows examine   0       0       0       0       0       0       0       0
# Query size     3 398.46k     216     216     216     216       0     216
# String:
# Hosts        localhost
# Users        isuconp
# Query_time distribution
#   1us
#  10us
# 100us
#   1ms  ################################################################
#  10ms  #
# 100ms  #
#    1s
#  10s+
# Tables
#    SHOW TABLE STATUS LIKE 'users'\G
#    SHOW CREATE TABLE `users`\G
INSERT INTO `users` (`account_name`, `passhash`) VALUES ('Pzb9Wqxz7HhwDY2q7DKXe3HFI','f1c15bb79cc6ceea9a89a9ccb56faf1618db2ce5b7d89b6a3dc361a980ea392e7ebd4d2bc5a78bcde0616462439c140d53df5d535da9e6955fa63d7fb713d648')\G

# Query 2: 26.48 QPS, 0.16x concurrency, ID 0x9F2038550F51B0A3AB05CA526E3FEDDC at byte 24294119
# This item is included in the report because it matches --limit.
# Scores: V/M = 0.01
# Time range: 2023-11-09T13:44:20 to 2023-11-09T13:45:20
# Attribute    pct   total     min     max     avg     95%  stddev  median
# ============ === ======= ======= ======= ======= ======= ======= =======
# Count          1    1589
# Exec time     20      9s     3ms   249ms     6ms     8ms     9ms     5ms
# Lock time      1     3ms       0   208us     1us     1us     5us     1us
# Rows sent      0       0       0       0       0       0       0       0
# Rows examine   0       0       0       0       0       0       0       0
# Query size     1 212.73k      84     210  137.09  174.84   24.47  130.47
# String:
# Hosts        localhost
# Users        isuconp
# Query_time distribution
#   1us
#  10us
# 100us
#   1ms  ################################################################
#  10ms  #
# 100ms  #
#    1s
#  10s+
# Tables
#    SHOW TABLE STATUS LIKE 'comments'\G
#    SHOW CREATE TABLE `comments`\G
INSERT INTO `comments` (`post_id`, `user_id`, `comment`) VALUES (9663,27,'(=^ｰ^)ﾉ彡☆゜・。・゜★ﾊﾞｲﾊﾞｲ')\G

# Query 3: 244.10 QPS, 0.10x concurrency, ID 0x1ADC9E80BE48F05D4A5F6D6502F7A387 at byte 40939
# This item is included in the report because it matches --limit.
# Scores: V/M = 0.00
# Time range: 2023-11-09T13:44:20 to 2023-11-09T13:45:21
# Attribute    pct   total     min     max     avg     95%  stddev  median
# ============ === ======= ======= ======= ======= ======= ======= =======
# Count         14   14890
# Exec time     13      6s    92us    20ms   412us     1ms   535us   273us
# Lock time     16    29ms       0   477us     1us     1us     8us     1us
# Rows sent     32 361.88k       0     245   24.89  143.84   49.07    1.96
# Rows examine  32 679.23k       0     490   46.71  284.79   98.93    1.96
# Query size    18   2.10M      70     207  147.84  202.40   59.98  183.58
# String:
# Hosts        localhost
# Users        isuconp
# Query_time distribution
#   1us
#  10us  #
# 100us  ################################################################
#   1ms  ####
#  10ms  #
# 100ms
#    1s
#  10s+
# Tables
#    SHOW TABLE STATUS LIKE 'comments'\G
#    SHOW CREATE TABLE `comments`\G
# EXPLAIN /*!50100 PARTITIONS*/
SELECT * FROM comments WHERE post_id IN (9849, 9795, 9263, 7200, 7156, 6297, 6129, 5635, 4777, 3440, 2551, 1747) ORDER BY `created_at` DESC\G
# *************************** 1. row ***************************
#            id: 1
#   select_type: SIMPLE
#         table: comments
#    partitions: NULL
#          type: range
# possible_keys: comments_post_id_index
#           key: comments_post_id_index
#       key_len: 4
#           ref: NULL
#          rows: 108
#      filtered: 100.00
#         Extra: Using index condition; Using filesort

# Query 4: 244.10 QPS, 0.07x concurrency, ID 0x9B36FBB6889AD40E391C181F37DD0542 at byte 3799219
# This item is included in the report because it matches --limit.
# Scores: V/M = 0.00
# Time range: 2023-11-09T13:44:20 to 2023-11-09T13:45:21
# Attribute    pct   total     min     max     avg     95%  stddev  median
# ============ === ======= ======= ======= ======= ======= ======= =======
# Count         14   14890
# Exec time      9      4s    91us     6ms   283us   515us   240us   247us
# Lock time     15    27ms       0     2ms     1us     1us    16us     1us
# Rows sent      3  38.67k       0      20    2.66   13.83    4.76    0.99
# Rows examine  17 361.89k       0     245   24.89  143.84   49.07    1.96
# Query size    21   2.45M      95     232  172.84  223.14   58.18  202.40
# String:
# Hosts        localhost
# Users        isuconp
# Query_time distribution
#   1us
#  10us  #
# 100us  ################################################################
#   1ms  #
#  10ms
# 100ms
#    1s
#  10s+
# Tables
#    SHOW TABLE STATUS LIKE 'comments'\G
#    SHOW CREATE TABLE `comments`\G
# EXPLAIN 
SELECT `post_id`, COUNT(*) AS `count` FROM `comments` WHERE `post_id` IN (9258, 9177, 8201, 7308, 6631, 5011, 4532, 4274, 4103, 3051, 3015, 2476, 2233, 696, 509) GROUP BY `post_id`\G
# *************************** 1. row ***************************
#            id: 1
#   select_type: SIMPLE
#         table: comments
#    partitions: NULL
#          type: range
# possible_keys: comments_post_id_index
#           key: comments_post_id_index
#       key_len: 4
#           ref: NULL
#          rows: 118
#      filtered: 100.00
#         Extra: Using where; Using index

netdata

http://localhost:19991/#menu_apps_submenu_cpu;after=1699537460312;before=1699537536472

pprof

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

saza-ku / private-isu-2023-public

11091044 #61

isucon1

alp

slow query

explain

netdata

pprof