saza-ku
commented
1 year ago isucon1
alp
+-------+--------+--------------------+-------+-------+--------+-------+-------+
| COUNT | METHOD | URI | MIN | MAX | SUM | AVG | P99 |
+-------+--------+--------------------+-------+-------+--------+-------+-------+
| 9110 | GET | / | 0.000 | 0.108 | 55.785 | 0.006 | 0.020 |
| 6030 | GET | /posts/.+ | 0.000 | 0.056 | 24.592 | 0.004 | 0.016 |
| 2389 | GET | /@.+ | 0.004 | 0.068 | 22.393 | 0.009 | 0.024 |
| 1352 | POST | / | 0.004 | 0.088 | 13.724 | 0.010 | 0.060 |
| 6329 | POST | /login | 0.000 | 0.040 | 11.088 | 0.002 | 0.008 |
| 520 | GET | /posts | 0.004 | 0.052 | 6.236 | 0.012 | 0.028 |
| 2562 | POST | /register | 0.004 | 0.056 | 5.676 | 0.002 | 0.012 |
| 2076 | POST | /comment | 0.004 | 0.040 | 4.572 | 0.002 | 0.008 |
| 4149 | GET | /favicon.ico | 0.000 | 0.020 | 4.404 | 0.001 | 0.008 |
| 2562 | GET | /admin/banned | 0.000 | 0.020 | 4.192 | 0.002 | 0.008 |
| 4149 | GET | /js/main.js | 0.000 | 0.024 | 4.160 | 0.001 | 0.008 |
| 4149 | GET | /css/style.css | 0.000 | 0.016 | 3.896 | 0.001 | 0.008 |
| 4149 | GET | /js/timeago.min.js | 0.000 | 0.016 | 3.892 | 0.001 | 0.008 |
| 226 | GET | /login | 0.000 | 0.012 | 0.432 | 0.002 | 0.012 |
| 113 | GET | /logout | 0.004 | 0.016 | 0.240 | 0.002 | 0.012 |
| 28792 | GET | /image/.+ | 0.000 | 0.000 | 0.000 | 0.000 | 0.000 |
+-------+--------+--------------------+-------+-------+--------+-------+-------+
slow query
Count: 9648 Time=0.00s (4s) Lock=0.00s (0s) Rows=14.6 (141093), 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: 9648 Time=0.00s (3s) Lock=0.00s (0s) Rows=1.8 (17778), 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: 19483 Time=0.00s (2s) Lock=0.00s (0s) Rows=1.0 (19483), isuconp[isuconp]@localhost
SELECT * FROM `users` WHERE `id` = N
Count: 9110 Time=0.00s (1s) Lock=0.00s (0s) Rows=20.0 (182200), 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: 6031 Time=0.00s (1s) Lock=0.00s (0s) Rows=8.4 (50880), isuconp[isuconp]@localhost
SELECT * FROM comments WHERE post_id IN (N) ORDER BY `created_at` DESC
Count: 5502 Time=0.00s (1s) Lock=0.00s (0s) Rows=19.8 (108871), 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: 6329 Time=0.00s (1s) Lock=0.00s (0s) Rows=1.0 (6216), isuconp[isuconp]@localhost
SELECT * FROM users WHERE account_name = 'S' AND del_flg = N
Count: 6031 Time=0.00s (0s) Lock=0.00s (0s) Rows=0.9 (5292), isuconp[isuconp]@localhost
SELECT `post_id`, COUNT(*) AS `count` FROM `comments` WHERE `post_id` IN (N) GROUP BY `post_id`
Count: 6030 Time=0.00s (0s) Lock=0.00s (0s) Rows=1.0 (6030), isuconp[isuconp]@localhost
SELECT * FROM `not_banned_posts_without_imgdata` WHERE `id` = N
Count: 2562 Time=0.00s (0s) Lock=0.00s (0s) Rows=0.0 (0), isuconp[isuconp]@localhost
INSERT INTO `users` (`account_name`, `passhash`) VALUES ('S','S')
explain
Reading from STDIN ...
# 9.2s user time, 70ms system time, 37.56M rss, 50.94M vsz
# Current date: Thu Nov 9 23:58:40 2023
# Hostname: private-isu
# Files: STDIN
# Overall: 115.45k total, 22 unique, 1.48k QPS, 0.36x concurrency ________
# Time range: 2023-11-09T14:57:13 to 2023-11-09T14:58:31
# Attribute total min max avg 95% stddev median
# ============ ======= ======= ======= ======= ======= ======= =======
# Exec time 28s 17us 99ms 240us 568us 409us 167us
# Lock time 197ms 0 3ms 1us 1us 13us 1us
# Rows sent 1.30M 0 251 11.77 59.77 28.23 0.99
# Rows examine 2.48M 0 502 22.51 118.34 51.15 0.99
# Query size 14.10M 17 1.33k 128.03 223.14 116.27 97.36
# Profile
# Rank Query ID Response time Calls R/Call V/M Item
# ==== ============================= ============= ===== ====== ===== ====
# 1 0x1ADC9E80BE48F05D4A5F6D65... 7.3015 26.3% 18049 0.0004 0.00 SELECT comments
# 2 0x9B36FBB6889AD40E391C181F... 5.0920 18.3% 18049 0.0003 0.00 SELECT comments
# 3 0x395AE969FAFDA16C400891B7... 4.7966 17.3% 18049 0.0003 0.00 SELECT users
# 4 0x396201721CD58410E070DA94... 2.6831 9.7% 19483 0.0001 0.00 SELECT users
# MISC 0xMISC 7.9239 28.5% 41824 0.0002 0.0 <18 ITEMS>
# Query 1: 295.89 QPS, 0.12x concurrency, ID 0x1ADC9E80BE48F05D4A5F6D6502F7A387 at byte 847
# This item is included in the report because it matches --limit.
# Scores: V/M = 0.00
# Time range: 2023-11-09T14:57:13 to 2023-11-09T14:58:14
# Attribute pct total min max avg 95% stddev median
# ============ === ======= ======= ======= ======= ======= ======= =======
# Count 15 18049
# Exec time 26 7s 90us 99ms 404us 1ms 845us 273us
# Lock time 16 33ms 0 3ms 1us 1us 21us 1us
# Rows sent 31 419.60k 0 251 23.81 130.47 47.78 0.99
# Rows examine 31 789.51k 0 502 44.79 258.32 96.37 1.96
# Query size 18 2.60M 70 207 151.15 202.40 59.45 192.76
# 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 (9999, 9998, 9997, 9996, 9995, 9994, 9993, 9991, 9990, 9989, 9988, 9987, 9986, 9985, 9983, 9982, 9981, 9980, 9979, 9977) 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: 219
# filtered: 100.00
# Extra: Using index condition; Using filesort
# Query 2: 295.89 QPS, 0.08x concurrency, ID 0x9B36FBB6889AD40E391C181F37DD0542 at byte 24590202
# This item is included in the report because it matches --limit.
# Scores: V/M = 0.00
# Time range: 2023-11-09T14:57:13 to 2023-11-09T14:58:14
# Attribute pct total min max avg 95% stddev median
# ============ === ======= ======= ======= ======= ======= ======= =======
# Count 15 18049
# Exec time 18 5s 90us 9ms 282us 490us 250us 247us
# Lock time 16 33ms 0 3ms 1us 1us 22us 1us
# Rows sent 3 45.81k 0 20 2.60 12.54 4.58 0.99
# Rows examine 16 419.60k 0 251 23.81 130.47 47.78 0.99
# Query size 21 3.03M 95 232 176.15 223.14 57.63 212.52
# 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 (9876) GROUP BY `post_id`\G
# *************************** 1. row ***************************
# id: 1
# select_type: SIMPLE
# table: comments
# partitions: NULL
# type: ref
# possible_keys: comments_post_id_index
# key: comments_post_id_index
# key_len: 4
# ref: const
# rows: 16
# filtered: 100.00
# Extra: Using index
# Query 3: 295.89 QPS, 0.08x concurrency, ID 0x395AE969FAFDA16C400891B7C96D9565 at byte 7315696
# This item is included in the report because it matches --limit.
# Scores: V/M = 0.00
# Time range: 2023-11-09T14:57:13 to 2023-11-09T14:58:14
# Attribute pct total min max avg 95% stddev median
# ============ === ======= ======= ======= ======= ======= ======= =======
# Count 15 18049
# Exec time 17 5s 71us 7ms 265us 690us 258us 176us
# Lock time 14 28ms 0 448us 1us 1us 5us 1us
# Rows sent 44 586.98k 1 243 33.30 124.25 42.46 19.46
# Rows examine 23 586.98k 1 243 33.30 124.25 42.46 19.46
# Query size 25 3.60M 36 1.33k 209.04 755.64 238.43 124.25
# 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
# EXPLAIN
SELECT * FROM users WHERE id IN (885, 35, 97, 473, 975, 371, 246, 159, 485, 85, 401, 910, 299, 404, 90, 545, 854, 479, 997, 971/*... omitted 216 items ...*/)\G
# *************************** 1. row ***************************
# id: 1
# select_type: SIMPLE
# table: users
# partitions: NULL
# type: range
# possible_keys: PRIMARY
# key: PRIMARY
# key_len: 4
# ref: NULL
# rows: 20
# filtered: 100.00
# Extra: Using where
# Query 4: 324.72 QPS, 0.04x concurrency, ID 0x396201721CD58410E070DA9421CA8C8D at byte 46743
# This item is included in the report because it matches --limit.
# Scores: V/M = 0.00
# Time range: 2023-11-09T14:57:13 to 2023-11-09T14:58:13
# Attribute pct total min max avg 95% stddev median
# ============ === ======= ======= ======= ======= ======= ======= =======
# Count 16 19483
# Exec time 9 3s 65us 15ms 137us 214us 167us 113us
# Lock time 16 33ms 0 670us 1us 1us 6us 1us
# Rows sent 1 19.03k 1 1 1 1 0 1
# Rows examine 0 19.03k 1 1 1 1 0 1
# Query size 5 726.37k 37 40 38.18 38.53 0.62 36.69
# 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
# EXPLAIN
SELECT * FROM `users` WHERE `id` = 24\G
# *************************** 1. row ***************************
# id: 1
# select_type: SIMPLE
# table: users
# partitions: NULL
# type: const
# possible_keys: PRIMARY
# key: PRIMARY
# key_len: 4
# ref: const
# rows: 1
# filtered: 100.00
# Extra: NULL
netdata
http://localhost:19991/#menu_apps_submenu_cpu;after=1699541833391;before=1699541909670
pprof
go tool pprof -http=0.0.0.0:1080 http://isucon1/pprof/11091157
https://github.com/Saza-ku/private-isu-2023/pull/73
95595