saza-ku
commented
10 months ago isucon3
alp
+-------+--------+-----+-----+-----+-----+-----+-----+
| COUNT | METHOD | URI | MIN | MAX | SUM | AVG | P99 |
+-------+--------+-----+-----+-----+-----+-----+-----+
+-------+--------+-----+-----+-----+-----+-----+-----+
slow query
Count: 53218 Time=0.00s (41s) Lock=0.00s (0s) Rows=1.0 (53218), isucon[isucon]@isucon1
SELECT * FROM themes WHERE user_id = N
Count: 45061 Time=0.00s (9s) Lock=0.00s (0s) Rows=4.6 (206294), isucon[isucon]@isucon1
SELECT livestream_id, tags.id AS tag_id, tags.name as tag_name FROM livestream_tags as l LEFT JOIN tags ON l.tag_id = tags.id WHERE livestream_id = N
Count: 570 Time=0.01s (7s) 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: 571 Time=0.01s (6s) Lock=0.00s (0s) Rows=10.0 (5715), isucon[isucon]@isucon1
SELECT * FROM reservation_slots WHERE start_at >= N AND end_at <= N FOR UPDATE
Count: 52612 Time=0.00s (5s) Lock=0.00s (0s) Rows=1.0 (52612), isucon[isucon]@isucon1
SELECT * FROM users WHERE id = N
Count: 283 Time=0.01s (3s) Lock=0.00s (0s) Rows=3.3 (943), isucon[isucon]@isucon1
SELECT * FROM livestreams WHERE user_id = N
Count: 25245 Time=0.00s (2s) Lock=0.00s (0s) Rows=1.0 (25203), isucon[isucon]@isucon1
SELECT * FROM livestreams WHERE id = N
Count: 21018 Time=0.00s (2s) Lock=0.00s (0s) Rows=0.0 (0), isucon[isucon]@isucon1
COMMIT
Count: 2851 Time=0.00s (2s) Lock=0.00s (0s) Rows=1.3 (3607), isucon[isucon]@isucon1
SELECT * FROM themes WHERE user_id IN (N, N)
Count: 2467 Time=0.00s (1s) Lock=0.00s (0s) Rows=1.0 (2467), isucon[isucon]@isucon1
SELECT * FROM themes WHERE user_id IN (N)
explain
Reading from STDIN ...
# 17.4s user time, 80ms system time, 37.88M rss, 52.24M vsz
# Current date: Sat Nov 25 08:38:17 2023
# Hostname: ip-192-168-0-13
# Files: STDIN
# Overall: 274.14k total, 65 unique, 3.12k QPS, 1.14x concurrency ________
# Time range: 2023-11-25T08:36:37 to 2023-11-25T08:38:05
# Attribute total min max avg 95% stddev median
# ============ ======= ======= ======= ======= ======= ======= =======
# Exec time 100s 1us 127ms 365us 925us 1ms 108us
# Lock time 276ms 0 3ms 1us 1us 18us 1us
# Rows sent 1.75M 0 7.87k 6.71 4.96 133.31 0.99
# Rows examine 91.75M 0 13.81k 350.96 1.39k 830.82 0.99
# Query size 16.21M 6 453 62.00 151.03 52.25 40.45
# Profile
# Rank Query ID Response time Calls R/Call V/M Item
# ==== ============================ ============= ====== ====== ===== ====
# 1 0x38BC86A45F31C6B1EE32467... 41.2340 41.2% 53218 0.0008 0.00 SELECT themes
# 2 0xA0E56FBF29E0231425D4BA3... 9.3108 9.3% 45061 0.0002 0.00 SELECT livestream_tags tags
# 3 0xA3401CA3ABCC04C3AB221DB... 7.7936 7.8% 570 0.0137 0.00 UPDATE reservation_slots
# 4 0x7F9C0C0BA9473953B723EE1... 6.8683 6.9% 571 0.0120 0.00 SELECT reservation_slots
# MISC 0xMISC 34.8909 34.9% 174716 0.0002 0.0 <61 ITEMS>
# Query 1: 782.62 QPS, 0.61x concurrency, ID 0x38BC86A45F31C6B1EE324671506C898A at byte 71474302
# This item is included in the report because it matches --limit.
# Scores: V/M = 0.00
# Time range: 2023-11-25T08:36:37 to 2023-11-25T08:37:45
# Attribute pct total min max avg 95% stddev median
# ============ === ======= ======= ======= ======= ======= ======= =======
# Count 19 53218
# Exec time 41 41s 241us 16ms 774us 2ms 640us 596us
# Lock time 22 62ms 0 3ms 1us 1us 21us 1us
# Rows sent 2 51.97k 1 1 1 1 0 1
# Rows examine 71 65.31M 1000 1.53k 1.26k 1.46k 157.71 1.20k
# Query size 12 2.08M 38 41 40.89 40.45 0.57 40.45
# 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 = 1272\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: 1570
# filtered: 10.00
# Extra: Using where
# Query 2: 662.66 QPS, 0.14x concurrency, ID 0xA0E56FBF29E0231425D4BA3CE21653D3 at byte 13351071
# This item is included in the report because it matches --limit.
# Scores: V/M = 0.00
# Time range: 2023-11-25T08:36:37 to 2023-11-25T08:37:45
# Attribute pct total min max avg 95% stddev median
# ============ === ======= ======= ======= ======= ======= ======= =======
# Count 16 45061
# Exec time 9 9s 81us 57ms 206us 384us 762us 138us
# Lock time 21 60ms 0 2ms 1us 1us 15us 1us
# Rows sent 11 201.46k 0 11 4.58 4.96 1.15 4.96
# Rows examine 0 402.92k 0 22 9.16 9.83 2.27 9.83
# Query size 40 6.57M 150 153 152.98 151.03 0.29 151.03
# String:
# Hosts isucon1
# Users isucon
# Query_time distribution
# 1us
# 10us #
# 100us ################################################################
# 1ms #
# 10ms #
# 100ms
# 1s
# 10s+
# Tables
# SHOW TABLE STATUS LIKE 'livestream_tags'\G
# SHOW CREATE TABLE `livestream_tags`\G
# SHOW TABLE STATUS LIKE 'tags'\G
# SHOW CREATE TABLE `tags`\G
# EXPLAIN
SELECT livestream_id, tags.id AS tag_id, tags.name as tag_name FROM livestream_tags as l LEFT JOIN tags ON l.tag_id = tags.id WHERE livestream_id = 7628\G
# *************************** 1. row ***************************
# id: 1
# select_type: SIMPLE
# table: l
# partitions: NULL
# type: ref
# possible_keys: livestream_id
# key: livestream_id
# key_len: 8
# ref: const
# rows: 5
# filtered: 100.00
# Extra: NULL
# *************************** 2. row ***************************
# id: 1
# select_type: SIMPLE
# table: tags
# partitions: NULL
# type: eq_ref
# possible_keys: PRIMARY
# key: PRIMARY
# key_len: 8
# ref: isupipe.l.tag_id
# rows: 1
# filtered: 100.00
# Extra: NULL
# Query 3: 8.38 QPS, 0.11x concurrency, ID 0xA3401CA3ABCC04C3AB221DB8AD5CBF26 at byte 52343745
# This item is included in the report because it matches --limit.
# Scores: V/M = 0.00
# Time range: 2023-11-25T08:36:37 to 2023-11-25T08:37:45
# Attribute pct total min max avg 95% stddev median
# ============ === ======= ======= ======= ======= ======= ======= =======
# Count 0 570
# Exec time 7 8s 5ms 73ms 14ms 26ms 7ms 12ms
# Lock time 0 499us 0 2us 0 1us 0 1us
# Rows sent 0 0 0 0 0 0 0 0
# Rows examine 5 4.76M 8.55k 8.55k 8.55k 8.55k 0 8.55k
# Query size 0 54.55k 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 >= 1704002400 AND end_at <= 1704063600\G
# Converted for EXPLAIN
# EXPLAIN
select slot = slot - 1 from reservation_slots where start_at >= 1704002400 AND end_at <= 1704063600\G
# Query 4: 8.40 QPS, 0.10x concurrency, ID 0x7F9C0C0BA9473953B723EE16C08655F1 at byte 52537484
# This item is included in the report because it matches --limit.
# Scores: V/M = 0.00
# Time range: 2023-11-25T08:36:37 to 2023-11-25T08:37:45
# Attribute pct total min max avg 95% stddev median
# ============ === ======= ======= ======= ======= ======= ======= =======
# Count 0 571
# Exec time 6 7s 5ms 45ms 12ms 20ms 5ms 11ms
# Lock time 0 593us 0 23us 1us 1us 1us 1us
# Rows sent 0 5.58k 1 21 10.01 19.46 5.85 9.83
# Rows examine 5 4.77M 8.55k 8.55k 8.55k 8.55k 0 8.55k
# Query size 0 53.53k 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 >= 1704020400 AND end_at <= 1704074400 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: 8773
# filtered: 11.11
# Extra: Using where
netdata
http://localhost:19993/#menu_services;after=1700901397547;before=1700901477554
pprof
go tool pprof -http=0.0.0.0:1080 http://isucon3/pprof/11250836
isucon1
alp
slow query
explain
netdata
http://localhost:19991/#menu_services;after=1700901397544;before=1700901473582
pprof