Open pinkumohikan opened 6 months ago
pinkumohikan
commented
6 months ago 初回ベンチ
isucon@ip-172-31-20-32:~$ ~/private_isu.git/benchmarker/bin/benchmarker -u ~/private_isu.git/benchmarker/userdata -t http://172.31.20.1
{"pass":true,"score":378,"success":383,"fail":4,"messages":["リクエストがタイムアウトしました (POST /login)"]} total used free shared buff/cache available
Mem: 3.7Gi 633Mi 2.5Gi 0.0Ki 643Mi 2.9Gi
Swap: 0B 0B 0BCOMMAND PID USER FD TYPE DEVICE SIZE/OFF NODE NAME
ruby 403 isucon 7u IPv4 16314 0t0 TCP *:http-alt (LISTEN)
nginx 521 root 6u IPv4 15988 0t0 TCP *:http (LISTEN)
nginx 525 www-data 6u IPv4 15988 0t0 TCP *:http (LISTEN)
nginx 526 www-data 6u IPv4 15988 0t0 TCP *:http (LISTEN)
mysqld 556 mysql 24u IPv4 17116 0t0 TCP localhost:mysql (LISTEN)
ruby 739 isucon 7u IPv4 16314 0t0 TCP *:http-alt (LISTEN) UNIT LOAD ACTIVE SUB DESCRIPTION
apparmor.service loaded active exited Load AppArmor profiles
apport.service loaded active exited LSB: automatic crash report generation
blk-availability.service loaded active exited Availability of block devices
chrony.service loaded active running chrony, an NTP client/server
cloud-config.service loaded active exited Apply the settings specified in cloud-config
cloud-final.service loaded active exited Execute cloud user/final scripts
cloud-init-local.service loaded active exited Initial cloud-init job (pre-networking)
cloud-init.service loaded active exited Initial cloud-init job (metadata service crawler)
console-setup.service loaded active exited Set console font and keymap
cron.service loaded active running Regular background program processing daemon
dbus.service loaded active running D-Bus System Message Bus
finalrd.service loaded active exited Create final runtime dir for shutdown pivot root
getty@tty1.service loaded active running Getty on tty1
irqbalance.service loaded active running irqbalance daemon
isu-ruby.service loaded active running isu-ruby
keyboard-setup.service loaded active exited Set the console keyboard layout
kmod-static-nodes.service loaded active exited Create List of Static Device Nodes
lvm2-monitor.service loaded active exited Monitoring of LVM2 mirrors, snapshots etc. using dmeventd or progress polling
memcached.service loaded active running memcached daemon
multipathd.service loaded active running Device-Mapper Multipath Device Controller
mysql.service loaded active running MySQL Community Server
networkd-dispatcher.service loaded active running Dispatcher daemon for systemd-networkd
nginx.service loaded active running A high performance web server and a reverse proxy server
plymouth-quit-wait.service loaded active exited Hold until boot process finishes up
plymouth-quit.service loaded active exited Terminate Plymouth Boot Screen
plymouth-read-write.service loaded active exited Tell Plymouth To Write Out Runtime Data
polkit.service loaded active running Authorization Manager
rsyslog.service loaded active running System Logging Service
serial-getty@ttyS0.service loaded active running Serial Getty on ttyS0
setvtrgb.service loaded active exited Set console scheme
snap.amazon-ssm-agent.amazon-ssm-agent.service loaded active running Service for snap application amazon-ssm-agent.amazon-ssm-agent
snapd.apparmor.service loaded active exited Load AppArmor profiles managed internally by snapd
snapd.seeded.service loaded active exited Wait until snapd is fully seeded
snapd.service loaded active running Snap Daemon
ssh.service loaded active running OpenBSD Secure Shell server
systemd-binfmt.service loaded active exited Set Up Additional Binary Formats
systemd-fsck-root.service loaded active exited File System Check on Root Device
systemd-fsck@dev-disk-by\x2dlabel-UEFI.service loaded active exited File System Check on /dev/disk/by-label/UEFI
systemd-journal-flush.service loaded active exited Flush Journal to Persistent Storage
systemd-journald.service loaded active running Journal Service
systemd-logind.service loaded active running User Login Management
systemd-modules-load.service loaded active exited Load Kernel Modules
systemd-networkd-wait-online.service loaded active exited Wait for Network to be Configured
systemd-networkd.service loaded active running Network Configuration
systemd-random-seed.service loaded active exited Load/Save Random Seed
systemd-remount-fs.service loaded active exited Remount Root and Kernel File Systems
systemd-resolved.service loaded active running Network Name Resolution
systemd-sysctl.service loaded active exited Apply Kernel Variables
systemd-sysusers.service loaded active exited Create System Users
systemd-tmpfiles-setup-dev.service loaded active exited Create Static Device Nodes in /dev
systemd-tmpfiles-setup.service loaded active exited Create Volatile Files and Directories
systemd-udev-trigger.service loaded active exited Coldplug All udev Devices
systemd-udevd.service loaded active running Rule-based Manager for Device Events and Files
systemd-update-utmp.service loaded active exited Record System Boot/Shutdown in UTMP
systemd-user-sessions.service loaded active exited Permit User Sessions
ufw.service loaded active exited Uncomplicated firewall
unattended-upgrades.service loaded active running Unattended Upgrades Shutdown
user-runtime-dir@1000.service loaded active exited User Runtime Directory /run/user/1000
user@1000.service loaded active running User Manager for UID 1000
LOAD = Reflects whether the unit definition was properly loaded.
ACTIVE = The high-level unit activation state, i.e. generalization of SUB.
SUB = The low-level unit activation state, values depend on unit type.
59 loaded units listed.
To show all installed unit files use 'systemctl list-unit-files'.MySQL slow query logを吐くように設定
$ ~/private_isu.git/benchmarker/bin/benchmarker -u ~/private_isu.git/benchmarker/userdata -t http://172.31.20.1
{"pass":true,"score":362,"success":368,"fail":4,"messages":["リクエストがタイムアウトしました (POST /login)","リクエストがタイムアウトしました (POST /register)"]}$ sudo systemctl disable --now isu-ruby
Removed /etc/systemd/system/multi-user.target.wants/isu-ruby.service.
$ sudo systemctl enable --now isu-go
Created symlink /etc/systemd/system/multi-user.target.wants/isu-go.service → /etc/systemd/system/isu-go.service.$ ~/private_isu.git/benchmarker/bin/benchmarker -u ~/private_isu.git/benchmarker/userdata -t http://172.31.20.1
{"pass":true,"score":2441,"success":2344,"fail":0,"messages":[]}# Query 1: 23.30 QPS, 6.06x concurrency, ID 0x624863D30DAC59FA16849282195BE09F at byte 5743247
# This item is included in the report because it matches --limit.
# Scores: V/M = 0.02
# Time range: 2024-05-11T02:48:24 to 2024-05-11T02:49:44
# Attribute pct total min max avg 95% stddev median
# ============ === ======= ======= ======= ======= ======= ======= =======
# Count 4 1864
# Exec time 68 485s 51ms 404ms 260ms 323ms 74ms 279ms
# Lock time 15 4ms 0 115us 2us 2us 4us 1us
# Rows sent 0 4.99k 0 3 2.74 2.90 0.82 2.90
# Rows examine 45 177.78M 97.66k 97.67k 97.66k 97.04k 0 97.04k
# Query size 2 149.47k 79 83 82.11 80.10 0.12 80.10
# String:
# Databases isuconp
# Hosts localhost
# Users isuconp
# Query_time distribution
# 1us
# 10us
# 100us
# 1ms
# 10ms ######
# 100ms ################################################################
# 1s
# 10s+
# Tables
# SHOW TABLE STATUS FROM `isuconp` LIKE 'comments'\G
# SHOW CREATE TABLE `isuconp`.`comments`\G
# EXPLAIN /*!50100 PARTITIONS*/
SELECT * FROM `comments` WHERE `post_id` = 9985 ORDER BY `created_at` DESC LIMIT 3\Gmysql> explain SELECT * FROM `comments` WHERE `post_id` = 9985 ORDER BY `created_at` DESC
LIMIT 3\G
*************************** 1. row ***************************
id: 1
select_type: SIMPLE
table: comments
partitions: NULL
type: ALL
possible_keys: NULL
key: NULL
key_len: NULL
ref: NULL
rows: 100139
filtered: 10.00
Extra: Using where; Using filesort
1 row in set, 1 warning (0.00 sec)
Note (Code 1003): /* select#1 */ select `isuconp`.`comments`.`id` AS `id`,`isuconp`.`comments`.`post_id` AS `post_id`,`isuconp`.`comments`.`user_id` AS `user_id`,`isuconp`.`comments`.`comment` AS `comment`,`isuconp`.`comments`.`created_at` AS `created_at` from `isuconp`.`comments` where (`isuconp`.`comments`.`post_id` = 9985) order by `isuconp`.`comments`.`created_at` desc limit 3
mysql> ALTER TABLE comments ADD INDEX (post_id, created_at DESC);
Query OK, 0 rows affected (0.46 sec)
Records: 0 Duplicates: 0 Warnings: 0
mysql> explain SELECT * FROM `comments` WHERE `post_id` = 9985 ORDER BY `created_at` DESC
LIMIT 3\G
*************************** 1. row ***************************
id: 1
select_type: SIMPLE
table: comments
partitions: NULL
type: ref
possible_keys: post_id
key: post_id
key_len: 4
ref: const
rows: 10
filtered: 100.00
Extra: NULL
1 row in set, 1 warning (0.00 sec)
Note (Code 1003): /* select#1 */ select `isuconp`.`comments`.`id` AS `id`,`isuconp`.`comments`.`post_id` AS `post_id`,`isuconp`.`comments`.`user_id` AS `user_id`,`isuconp`.`comments`.`comment` AS `comment`,`isuconp`.`comments`.`created_at` AS `created_at` from `isuconp`.`comments` where (`isuconp`.`comments`.`post_id` = 9985) order by `isuconp`.`comments`.`created_at` desc limit 3{"pass":true,"score":24656,"success":23183,"fail":0,"messages":[]}slow queryで気付いた
SELECT `id`, `user_id`, `body`, `mime`, `created_at` FROM `posts` ORDER BY `created_at` DESC\G6178d545f33ed73d756f553adbabe8bd8d8c0caf
{"pass":true,"score":31882,"success":30101,"fail":0,"messages":[]}
pinkumohikan
commented
6 months ago pinkumohikan
commented
6 months ago https://github.com/tkuchiki/alp?tab=readme-ov-file#uri-matching-groups
$ mkdir -p bin
$ curl -sSfL https://github.com/tkuchiki/alp/releases/download/v1.0.21/alp_linux_arm64.tar.gz | tar zx
$ mv alp ~/bin/
$ alp --version
1.0.21$ sudo cat /var/log/nginx/access.log | alp json --sort sum --reverse --matching-groups="/image/[0-9]+.(png|jpg|gif)","/@[\w]+","/posts/[\d]+" | head -n 20
+-------+-----+-------+-----+-----+-----+--------+-----------------------------+-------+-------+---------+-------+-------+-------+-------+--------+-----------+-------------+----------------+------------+
| COUNT | 1XX | 2XX | 3XX | 4XX | 5XX | METHOD | URI | MIN | MAX | SUM | AVG | P90 | P95 | P99 | STDDEV | MIN(BODY) | MAX(BODY) | SUM(BODY) | AVG(BODY) |
+-------+-----+-------+-----+-----+-----+--------+-----------------------------+-------+-------+---------+-------+-------+-------+-------+--------+-----------+-------------+----------------+------------+
| 1106 | 0 | 1106 | 0 | 0 | 0 | GET | / | 0.028 | 0.748 | 260.419 | 0.235 | 0.312 | 0.348 | 0.400 | 0.059 | 2638.000 | 6047.000 | 3462988.000 | 3131.092 |
| 18994 | 0 | 18994 | 0 | 0 | 0 | GET | /image/[0-9]+.(png|jpg|gif) | 0.000 | 0.204 | 121.648 | 0.006 | 0.012 | 0.016 | 0.036 | 0.010 | 35065.000 | 1134095.000 | 6078783623.000 | 320037.044 |
| 210 | 0 | 210 | 0 | 0 | 0 | GET | /posts | 0.048 | 1.004 | 90.215 | 0.430 | 0.520 | 0.548 | 0.604 | 0.107 | 5011.000 | 5819.000 | 1123883.000 | 5351.824 |
| 219 | 0 | 219 | 0 | 0 | 0 | GET | /@[\w]+ | 0.044 | 0.832 | 65.105 | 0.297 | 0.388 | 0.436 | 0.504 | 0.083 | 1600.000 | 5475.000 | 718079.000 | 3278.900 |
| 1470 | 0 | 1470 | 0 | 0 | 0 | GET | /posts/[\d]+ | 0.004 | 0.232 | 53.437 | 0.036 | 0.060 | 0.072 | 0.100 | 0.021 | 714.000 | 1968.000 | 1900893.000 | 1293.124 |
| 807 | 0 | 0 | 807 | 0 | 0 | POST | /login | 0.004 | 0.184 | 28.107 | 0.035 | 0.064 | 0.076 | 0.096 | 0.023 | 0.000 | 0.000 | 0.000 | 0.000 |
| 106 | 0 | 0 | 106 | 0 | 0 | POST | /register | 0.008 | 0.104 | 4.792 | 0.045 | 0.064 | 0.072 | 0.096 | 0.017 | 0.000 | 0.000 | 0.000 | 0.000 |
| 192 | 0 | 0 | 96 | 96 | 0 | POST | / | 0.004 | 0.128 | 3.840 | 0.020 | 0.056 | 0.076 | 0.116 | 0.024 | 0.000 | 0.000 | 0.000 | 0.000 |
| 2010 | 0 | 2010 | 0 | 0 | 0 | GET | /favicon.ico | 0.000 | 0.160 | 1.984 | 0.001 | 0.004 | 0.004 | 0.008 | 0.004 | 43.000 | 43.000 | 86430.000 | 43.000 |
| 2010 | 0 | 2010 | 0 | 0 | 0 | GET | /js/timeago.min.js | 0.000 | 0.024 | 1.624 | 0.001 | 0.004 | 0.004 | 0.008 | 0.002 | 1915.000 | 1915.000 | 3849150.000 | 1915.000 |
| 2010 | 0 | 2010 | 0 | 0 | 0 | GET | /css/style.css | 0.004 | 0.020 | 1.536 | 0.001 | 0.004 | 0.004 | 0.008 | 0.002 | 1549.000 | 1549.000 | 3113490.000 | 1549.000 |
| 2010 | 0 | 2010 | 0 | 0 | 0 | GET | /js/main.js | 0.000 | 0.016 | 1.320 | 0.001 | 0.004 | 0.004 | 0.008 | 0.002 | 1824.000 | 1824.000 | 3666240.000 | 1824.000 |
| 95 | 0 | 0 | 95 | 0 | 0 | POST | /comment | 0.004 | 0.048 | 0.976 | 0.010 | 0.020 | 0.024 | 0.048 | 0.008 | 0.000 | 0.000 | 0.000 | 0.000 |
| 106 | 0 | 0 | 0 | 106 | 0 | GET | /admin/banned | 0.008 | 0.036 | 0.636 | 0.006 | 0.012 | 0.016 | 0.028 | 0.006 | 0.000 | 0.000 | 0.000 | 0.000 |
| 276 | 0 | 276 | 0 | 0 | 0 | GET | /login | 0.004 | 0.016 | 0.464 | 0.002 | 0.004 | 0.004 | 0.008 | 0.002 | 615.000 | 615.000 | 169740.000 | 615.000 |
| 138 | 0 | 0 | 138 | 0 | 0 | GET | /logout | 0.000 | 0.016 | 0.228 | 0.002 | 0.004 | 0.008 | 0.016 | 0.003 | 24.000 | 24.000 | 3312.000 | 24.000 |
| 1 | 0 | 1 | 0 | 0 | 0 | GET | /initialize | 0.020 | 0.020 | 0.020 | 0.020 | 0.020 | 0.020 | 0.020 | 0.000 | 0.000 | 0.000 | 0.000 | 0.000 |([ -e /tmp/alp-dump.yaml ] && sudo cp /tmp/alp-dump.yaml /tmp/alp-dump.old.yaml) || touch /tmp/alp-dump.old.yaml
sudo cat /var/log/nginx/access.log | alp json --sort sum --reverse --matching-groups="/image/[0-9]+.(png|jpg|gif)","/@[\w]+","/posts/[\d]+" --dump /tmp/alp-dump.yaml >/dev/null
alp diff /tmp/alp-dump.old.yaml /tmp/alp-dump.yaml | head -n 20
+-------------+-----+-------------+----------+---------+-----+--------+-----------------------------+----------------+----------------+------------------+----------------+----------------+----------------+----------------+----------------+-----------------------+--------------------------+--------------------------------+-------------------------+
| COUNT | 1XX | 2XX | 3XX | 4XX | 5XX | METHOD | URI | MIN | MAX | SUM | AVG | P90 | P95 | P99 | STDDEV | MIN(BODY) | MAX(BODY) | SUM(BODY) | AVG(BODY) |
+-------------+-----+-------------+----------+---------+-----+--------+-----------------------------+----------------+----------------+------------------+----------------+----------------+----------------+----------------+----------------+-----------------------+--------------------------+--------------------------------+-------------------------+
| 1 | 0 | 1 | 0 | 0 | 0 | GET | /initialize | 0.088 (-0.044) | 0.088 (-0.044) | 0.088 (-0.044) | 0.088 (-0.044) | 0.088 (-0.044) | 0.088 (-0.044) | 0.088 (-0.044) | 0.000 | 0.000 | 0.000 | 0.000 | 0.000 |
| 94 (+3) | 0 | 0 | 94 (+3) | 0 | 0 | POST | /comment | 0.004 | 0.040 (-0.004) | 0.884 (+0.044) | 0.009 | 0.020 | 0.028 | 0.040 (-0.004) | 0.008 | 0.000 | 0.000 | 0.000 | 0.000 |
| 100 | 0 | 0 | 100 | 0 | 0 | POST | /register | 0.008 (-0.004) | 0.100 (-0.008) | 4.520 (+0.076) | 0.045 (+0.001) | 0.076 (+0.004) | 0.084 (+0.004) | 0.096 (-0.012) | 0.020 (-0.001) | 0.000 | 0.000 | 0.000 | 0.000 |
| 100 | 0 | 0 | 0 | 100 | 0 | GET | /admin/banned | 0.004 (+0.004) | 0.060 (+0.032) | 0.648 (+0.080) | 0.006 (+0.001) | 0.012 | 0.016 (+0.004) | 0.036 (+0.020) | 0.008 (+0.004) | 0.000 | 0.000 | 0.000 | 0.000 |
| 130 (-2) | 0 | 0 | 130 (-2) | 0 | 0 | GET | /logout | 0.000 | 0.016 (+0.004) | 0.292 (+0.084) | 0.002 (+0.001) | 0.004 | 0.008 (+0.004) | 0.008 | 0.003 | 24.000 | 24.000 | 3120.000 (-48.000) | 24.000 |
| 186 (+6) | 0 | 0 | 93 (+3) | 93 (+3) | 0 | POST | / | 0.004 | 0.132 (-0.120) | 4.008 (-0.217) | 0.022 (-0.002) | 0.060 | 0.076 (-0.004) | 0.116 (-0.085) | 0.024 (-0.008) | 0.000 | 0.000 | 0.000 | 0.000 |
| 200 | 0 | 200 | 0 | 0 | 0 | GET | /posts | 0.068 (+0.016) | 0.600 (-0.569) | 90.160 (-1.476) | 0.451 (-0.007) | 0.524 (-0.012) | 0.556 (-0.004) | 0.580 (-0.388) | 0.074 (-0.040) | 5011.000 (+51.000) | 5751.000 (-34.000) | 1068152.000 (-774.000) | 5340.760 (-3.870) |
| 224 (+2) | 0 | 224 (+2) | 0 | 0 | 0 | GET | /@[\w]+ | 0.044 (+0.008) | 0.508 (-0.581) | 67.324 (-1.217) | 0.301 (-0.008) | 0.396 (-0.016) | 0.420 (-0.056) | 0.488 (-0.164) | 0.072 (-0.030) | 1821.000 (+85.000) | 5051.000 (-483.000) | 735992.000 (+13596.000) | 3285.679 (+31.643) |
| 260 (-4) | 0 | 260 (-4) | 0 | 0 | 0 | GET | /login | 0.000 | 0.024 (-0.004) | 0.516 (-0.024) | 0.002 (-0.000) | 0.004 | 0.004 (-0.004) | 0.012 (-0.004) | 0.003 (-0.000) | 615.000 | 615.000 | 159900.000 (-2460.000) | 615.000 |
| 770 (+3) | 0 | 0 | 770 (+3) | 0 | 0 | POST | /login | 0.004 | 0.120 (-0.016) | 28.173 (+1.957) | 0.037 (+0.002) | 0.064 | 0.072 | 0.100 (+0.008) | 0.022 (+0.001) | 0.000 | 0.000 | 0.000 | 0.000 |
| 1050 (+5) | 0 | 1050 (+5) | 0 | 0 | 0 | GET | / | 0.032 (+0.004) | 0.489 (-0.320) | 259.115 (-4.435) | 0.247 (-0.005) | 0.324 (-0.016) | 0.361 (-0.027) | 0.404 (-0.056) | 0.059 (-0.012) | 2663.000 (-17.000) | 6041.000 (-2.000) | 3339316.000 (-4101.000) | 3180.301 (-19.141) |
| 1511 (+6) | 0 | 1511 (+6) | 0 | 0 | 0 | GET | /posts/[\d]+ | 0.004 | 0.184 (-0.181) | 58.597 (+1.653) | 0.039 (+0.001) | 0.068 (+0.004) | 0.076 | 0.096 (-0.008) | 0.021 (-0.002) | 698.000 (-16.000) | 1954.000 (+60.000) | 1955864.000 (+7161.000) | 1294.417 (-0.402) |
| 2024 (-5) | 0 | 2024 (-5) | 0 | 0 | 0 | GET | /favicon.ico | 0.008 (+0.008) | 0.020 (+0.004) | 1.844 (+0.096) | 0.001 | 0.004 | 0.004 | 0.008 | 0.002 | 43.000 | 43.000 | 87032.000 (-215.000) | 43.000 |
| 2024 (-5) | 0 | 2024 (-5) | 0 | 0 | 0 | GET | /js/timeago.min.js | 0.000 | 0.020 (+0.004) | 1.816 (+0.316) | 0.001 | 0.004 | 0.004 | 0.008 | 0.002 | 1915.000 | 1915.000 | 3875960.000 (-9575.000) | 1915.000 |
| 2024 (-5) | 0 | 2024 (-5) | 0 | 0 | 0 | GET | /js/main.js | 0.000 | 0.020 | 1.577 (+0.085) | 0.001 | 0.004 | 0.004 | 0.008 | 0.002 | 1824.000 | 1824.000 | 3691776.000 (-9120.000) | 1824.000 |
| 2024 (-5) | 0 | 2024 (-5) | 0 | 0 | 0 | GET | /css/style.css | 0.000 | 0.024 (+0.008) | 1.608 (+0.248) | 0.001 | 0.004 | 0.004 | 0.008 | 0.002 | 1549.000 | 1549.000 | 3135176.000 (-7745.000) | 1549.000 |
| 18141 (-77) | 0 | 18141 (-77) | 0 | 0 | 0 | GET | /image/[0-9]+.(png|jpg|gif) | 0.004 (+0.004) | 0.148 (-0.116) | 116.694 (+3.965) | 0.006 | 0.016 (+0.004) | 0.020 (+0.004) | 0.032 | 0.007 (-0.002) | 32342.000 (-2097.000) | 1266561.000 (+13539.000) | 6320652376.000 | 348418.079 (+11781.615) |GET /
ここが一番重いので見ていく
pinkumohikan
commented
6 months ago (pprof) list getIndex
Total: 1894.89s
ROUTINE ======================== main.getIndex in /home/isucon/isucon-practice-20240511-private-isu-solo/webapp/golang/app.go
0 209.12s (flat, cum) 11.04% of Total
. . 381:
. . 382: http.Redirect(w, r, "/", http.StatusFound)
. . 383:}
. . 384:
. . 385:func getIndex(w http.ResponseWriter, r *http.Request) {
. 3.04s 386: me := getSessionUser(r)
. . 387:
. . 388: results := []Post{}
. . 389:
. 28.76s 390: err := db.Select(&results, "SELECT `id`, `user_id`, `body`, `mime`, `created_at` FROM `posts` ORDER BY `created_at` DESC LIMIT 30") // 投稿削除に対する考慮として50%多めに取る
. . 391: if err != nil {
. . 392: log.Print(err)
. . 393: return
. . 394: }
. . 395:
. 176.75s 396: posts, err := makePosts(results, getCSRFToken(r), false)
. . 397: if err != nil {
. . 398: log.Print(err)
. . 399: return
. . 400: }
. . 401:
. . 402: fmap := template.FuncMap{
. . 403: "imageURL": imageURL,
. . 404: }
. . 405:
. 131.31ms 406: template.Must(template.New("layout.html").Funcs(fmap).ParseFiles(
. . 407: getTemplPath("layout.html"),
. . 408: getTemplPath("index.html"),
. . 409: getTemplPath("posts.html"),
. . 410: getTemplPath("post.html"),
. 444.44ms 411: )).Execute(w, struct {
. . 412: Posts []Post
. . 413: Me User
. . 414: CSRFToken string
. . 415: Flash string
. . 416: }{posts, me, getCSRFToken(r), getFlash(w, r, "notice")})(pprof) list makePosts
Total: 1894.89s
ROUTINE ======================== main.makePosts in /home/isucon/isucon-practice-20240511-private-isu-solo/webapp/golang/app.go
0 314.28s (flat, cum) 16.59% of Total
. . 174:
. . 175:func makePosts(results []Post, csrfToken string, allComments bool) ([]Post, error) {
. . 176: var posts []Post
. . 177:
. . 178: for _, p := range results {
. 79.52s 179: err := db.Get(&p.CommentCount, "SELECT COUNT(*) AS `count` FROM `comments` WHERE `post_id` = ?", p.ID)
. . 180: if err != nil {
. . 181: return nil, err
. . 182: }
. . 183:
. . 184: query := "SELECT * FROM `comments` WHERE `post_id` = ? ORDER BY `created_at` DESC"
. . 185: if !allComments {
. . 186: query += " LIMIT 3"
. . 187: }
. . 188: var comments []Comment
. 78.12s 189: err = db.Select(&comments, query, p.ID)
. . 190: if err != nil {
. . 191: return nil, err
. . 192: }
. . 193:
. . 194: for i := 0; i < len(comments); i++ {
. 82.89s 195: err := db.Get(&comments[i].User, "SELECT * FROM `users` WHERE `id` = ?", comments[i].UserID)
. . 196: if err != nil {
. . 197: return nil, err
. . 198: }
. . 199: }
. . 200:
. . 201: // reverse
. . 202: for i, j := 0, len(comments)-1; i < j; i, j = i+1, j-1 {
. . 203: comments[i], comments[j] = comments[j], comments[i]
. . 204: }
. . 205:
. . 206: p.Comments = comments
. . 207:
. 73.75s 208: err = db.Get(&p.User, "SELECT * FROM `users` WHERE `id` = ?", p.UserID)
. . 209: if err != nil {
. . 210: return nil, err
. . 211: }
. . 212:
. . 213: p.CSRFToken = csrfToken
. . 214:
. . 215: if p.User.DelFlg == 0 {
. 10.10ms 216: posts = append(posts, p)
. . 217: }
. . 218: if len(posts) >= postsPerPage {
. . 219: break
. . 220: }
. . 221: }N+1問題がいくつかあったので改善 7a8472991cbc972fe2fd258b77910e374773402f 975aa4ee6c11eac95e1ca4459160ca75b4d84301 8c37aab9c90a3f968de4ea68cedb8153e1053d54
スコア約 38k
pinkumohikan
commented
6 months ago $ make alp
([ -e /tmp/alp-dump.yaml ] && sudo cp /tmp/alp-dump.yaml /tmp/alp-dump.old.yaml) || touch /tmp/alp-dump.old.yaml
sudo cat /var/log/nginx/access.log | alp json --matching-groups="/image/[0-9]+.(png|jpg|gif)","/@[\w]+","/posts/[\d]+" --dump /tmp/alp-dump.yaml >/dev/null
alp diff --sort sum --reverse /tmp/alp-dump.old.yaml /tmp/alp-dump.yaml --format=markdown -o count,sum,avg,stddev,min,p99,max,2xx,3xx,4xx,5xx,method,uri | head -n 20
| COUNT | SUM | AVG | STDDEV | MIN | P99 | MAX | 2XX | 3XX | 4XX | 5XX | METHOD | URI |
|--------------|-------------------|----------------|----------------|----------------|----------------|----------------|--------------|-------------|-----------|-----|--------|-----------------------------|
| 19294 (-577) | 218.595 (+27.234) | 0.011 (+0.002) | 0.012 (+0.002) | 0.000 (-0.004) | 0.048 (+0.004) | 0.220 (+0.124) | 19294 (-577) | 0 | 0 | 0 | GET | /image/[0-9]+.(png|jpg|gif) |
| 1555 (+295) | 110.304 (-67.917) | 0.071 (-0.071) | 0.029 (-0.010) | 0.012 | 0.172 (-0.072) | 0.264 (-0.032) | 1555 (+295) | 0 | 0 | 0 | GET | / |
| 117 (-83) | 92.195 (+10.646) | 0.788 (+0.380) | 0.184 (+0.074) | 0.216 (+0.120) | 1.168 (+0.508) | 1.168 (+0.492) | 117 (-83) | 0 | 0 | 0 | GET | /posts |
| 1131 (+211) | 62.837 (+14.096) | 0.056 (+0.003) | 0.031 (+0.002) | 0.036 (+0.020) | 0.136 (+0.012) | 0.240 (+0.084) | 0 | 1131 (+211) | 0 | 0 | POST | /login |
| 337 (+16) | 57.817 (-4.804) | 0.172 (-0.024) | 0.049 (-0.005) | 0.036 (-0.004) | 0.320 (-0.012) | 0.364 (-0.028) | 337 (+16) | 0 | 0 | 0 | GET | /@[\w]+ |
| 2005 (-77) | 43.411 (+5.254) | 0.022 (+0.003) | 0.016 (+0.002) | 0.016 (+0.012) | 0.076 (+0.008) | 0.160 (+0.044) | 2005 (-77) | 0 | 0 | 0 | GET | /posts/[\d]+ |
| 202 (+62) | 15.788 (+5.892) | 0.078 (+0.007) | 0.034 (+0.008) | 0.012 | 0.204 (+0.076) | 0.236 (+0.100) | 0 | 202 (+62) | 0 | 0 | POST | /register |
| 308 (+70) | 10.249 (+3.597) | 0.033 (+0.005) | 0.034 (+0.004) | 0.004 | 0.144 (+0.008) | 0.164 (+0.024) | 0 | 154 (+35) | 154 (+35) | 0 | POST | / |
| 2518 (-97) | 4.728 (+0.315) | 0.002 | 0.004 | 0.000 | 0.016 | 0.044 (+0.008) | 2518 (-97) | 0 | 0 | 0 | GET | /favicon.ico |
| 2518 (-97) | 3.968 (+0.172) | 0.002 | 0.003 (-0.000) | 0.000 (-0.008) | 0.016 | 0.036 (-0.012) | 2518 (-97) | 0 | 0 | 0 | GET | /js/timeago.min.js |
| 2518 (-97) | 3.360 (+0.188) | 0.001 | 0.003 | 0.000 | 0.016 (+0.004) | 0.032 (+0.004) | 2518 (-97) | 0 | 0 | 0 | GET | /css/style.css |
| 2518 (-97) | 3.268 (-0.128) | 0.001 (-0.000) | 0.003 (-0.000) | 0.004 | 0.012 | 0.036 (-0.028) | 2518 (-97) | 0 | 0 | 0 | GET | /js/main.js |
| 171 (+34) | 3.224 (+0.964) | 0.019 (+0.002) | 0.014 (+0.003) | 0.004 | 0.060 (+0.004) | 0.060 (+0.004) | 0 | 171 (+34) | 0 | 0 | POST | /comment |
| 202 (+62) | 2.276 (+0.860) | 0.011 (+0.001) | 0.009 (-0.002) | 0.004 | 0.036 (-0.028) | 0.044 (-0.020) | 0 | 0 | 202 (+62) | 0 | GET | /admin/banned |
| 300 (+30) | 0.936 (+0.148) | 0.003 | 0.005 | 0.000 (-0.008) | 0.020 | 0.044 (+0.016) | 300 (+30) | 0 | 0 | 0 | GET | /login |
| 150 (+15) | 0.408 (+0.028) | 0.003 (-0.000) | 0.003 (-0.000) | 0.000 (-0.004) | 0.016 | 0.016 | 0 | 150 (+15) | 0 | 0 | GET | /logout |
| 1 | 0.004 (-0.100) | 0.004 (-0.100) | 0.000 | 0.004 (-0.100) | 0.004 (-0.100) | 0.004 (-0.100) | 1 | 0 | 0 | 0 | GET | /initialize |# Query 1: 25.49 QPS, 0.93x concurrency, ID 0x12B99825AF0ABD243835AB7BAC7CEF8C at byte 98044714
# Scores: V/M = 0.01
# Time range: 2024-05-11T07:26:03 to 2024-05-11T07:27:04
# Attribute pct total min max avg 95% stddev median
# ============ === ======= ======= ======= ======= ======= ======= =======
# Count 1 1555
# Exec time 25 57s 7ms 236ms 37ms 75ms 23ms 31ms
# Lock time 1 2ms 0 31us 1us 1us 1us 1us
# Rows sent 1 45.56k 30 30 30 30 0 30
# Rows examine 19 14.99M 9.79k 9.95k 9.87k 9.80k 48.20 9.80k
# Query size 0 153.37k 101 101 101 101 0 101
# String:
# Databases isuconp
# Hosts localhost
# Users isuconp
# Query_time distribution
# 1us
# 10us
# 100us
# 1ms ##
# 10ms ################################################################
# 100ms #
# 1s
# 10s+
# Tables
# SHOW TABLE STATUS FROM `isuconp` LIKE 'posts'\G
# SHOW CREATE TABLE `isuconp`.`posts`\G
# EXPLAIN /*!50100 PARTITIONS*/
SELECT `id`, `user_id`, `body`, `mime`, `created_at` FROM `posts` ORDER BY `created_at` DESC LIMIT 30\Gmysql> desc posts;
+------------+-------------+------+-----+-------------------+-------------------+
| Field | Type | Null | Key | Default | Extra |
+------------+-------------+------+-----+-------------------+-------------------+
| id | int | NO | PRI | NULL | auto_increment |
| user_id | int | NO | | NULL | |
| mime | varchar(64) | NO | | NULL | |
| imgdata | mediumblob | NO | | NULL | |
| body | text | NO | | NULL | |
| created_at | timestamp | NO | | CURRENT_TIMESTAMP | DEFAULT_GENERATED |
+------------+-------------+------+-----+-------------------+-------------------+
6 rows in set (0.00 sec)画像データをdbが持っているせいで高負荷になっていそう。alpでも画像取得エンドポイントが1位だし、静的コンテンツとして吐き出してアプリを経由せずに読み出せるようにする。
pinkumohikan
commented
6 months ago aefe06e
スコア 92k
pinkumohikan
commented
6 months ago アプリ側で基本読み書きしなくて良くなったはずなので、select時に imgdata を返さないようにINVISIBLE COLUMNにする。
mysql> ALTER TABLE posts MODIFY COLUMN imgdata mediumblob NOT NULL INVISIBLE;
Query OK, 0 rows affected (0.00 sec)
Records: 0 Duplicates: 0 Warnings: 0
mysql> desc posts;
+------------+-------------+------+-----+-------------------+-------------------+
| Field | Type | Null | Key | Default | Extra |
+------------+-------------+------+-----+-------------------+-------------------+
| id | int | NO | PRI | NULL | auto_increment |
| user_id | int | NO | | NULL | |
| mime | varchar(64) | NO | | NULL | |
| imgdata | mediumblob | NO | | NULL | INVISIBLE |
| body | text | NO | | NULL | |
| created_at | timestamp | NO | | CURRENT_TIMESTAMP | DEFAULT_GENERATED |
+------------+-------------+------+-----+-------------------+-------------------+
6 rows in set (0.00 sec)スコア
{"pass":true,"score":95589,"success":91599,"fail":0,"messages":[]}
pinkumohikan
commented
6 months ago $ alp diff --sort sum --reverse /tmp/alp-dump.old.yaml /tmp/alp-dump.yaml --format=markdown -o count,sum,avg,stddev,min,p99,max,2xx,3xx,4xx,5xx,method,uri | head -n 20
| COUNT | SUM | AVG | STDDEV | MIN | P99 | MAX | 2XX | 3XX | 4XX | 5XX | METHOD | URI |
|-------|---------|-------|--------|-------|-------|-------|------|-------|-----|-----|--------|-----------------------------|
| 3409 | 260.553 | 0.076 | 0.026 | 0.008 | 0.148 | 0.296 | 3409 | 0 | 0 | 0 | GET | / |
| 102 | 120.556 | 1.182 | 0.356 | 0.204 | 1.632 | 1.676 | 102 | 0 | 0 | 0 | GET | /posts |
| 466 | 101.655 | 0.218 | 0.046 | 0.028 | 0.324 | 0.356 | 466 | 0 | 0 | 0 | GET | /@[\w]+ |
| 2151 | 73.010 | 0.034 | 0.022 | 0.004 | 0.092 | 0.116 | 0 | 2151 | 0 | 0 | POST | /login |
| 3435 | 50.971 | 0.015 | 0.015 | 0.000 | 0.068 | 0.132 | 3435 | 0 | 0 | 0 | GET | /posts/[\d]+ |
| 235 | 12.177 | 0.052 | 0.024 | 0.012 | 0.128 | 0.144 | 0 | 235 | 0 | 0 | POST | /register |
| 360 | 11.692 | 0.032 | 0.039 | 0.004 | 0.156 | 0.172 | 0 | 180 | 180 | 0 | POST | / |
| 164 | 2.512 | 0.015 | 0.017 | 0.000 | 0.080 | 0.088 | 0 | 164 | 0 | 0 | POST | /comment |
| 235 | 1.892 | 0.008 | 0.008 | 0.004 | 0.040 | 0.044 | 0 | 0 | 235 | 0 | GET | /admin/banned |
| 928 | 1.468 | 0.002 | 0.003 | 0.004 | 0.012 | 0.024 | 928 | 0 | 0 | 0 | GET | /login |
| 464 | 1.088 | 0.002 | 0.004 | 0.000 | 0.016 | 0.020 | 0 | 464 | 0 | 0 | GET | /logout |
| 1 | 0.140 | 0.140 | 0.000 | 0.140 | 0.140 | 0.140 | 1 | 0 | 0 | 0 | GET | /initialize |
| 56702 | 0.059 | 0.000 | 0.000 | 0.000 | 0.000 | 0.007 | 2992 | 53710 | 0 | 0 | GET | /image/[0-9]+.(png|jpg|gif) |
| 5808 | 0.000 | 0.000 | 0.000 | 0.000 | 0.000 | 0.000 | 1 | 5807 | 0 | 0 | GET | /favicon.ico |
| 5808 | 0.000 | 0.000 | 0.000 | 0.000 | 0.000 | 0.000 | 1 | 5807 | 0 | 0 | GET | /js/timeago.min.js |
| 5808 | 0.000 | 0.000 | 0.000 | 0.000 | 0.000 | 0.000 | 1 | 5807 | 0 | 0 | GET | /js/main.js |
| 5808 | 0.000 | 0.000 | 0.000 | 0.000 | 0.000 | 0.000 | 1 | 5807 | 0 | 0 | GET | /css/style.css |
# 6.5s user time, 80ms system time, 127.89M rss, 392.39G vsz
# Current date: Sat May 11 17:55:07 2024
# Hostname: salmon.local
# Files: mysql-slow.log
# Overall: 87.87k total, 34 unique, 1.42k QPS, 6.22x concurrency _________
# Time range: 2024-05-11T08:53:13 to 2024-05-11T08:54:15
# Attribute total min max avg 95% stddev median
# ============ ======= ======= ======= ======= ======= ======= =======
# Exec time 385s 1us 971ms 4ms 19ms 29ms 84us
# Lock time 141ms 0 8ms 1us 1us 58us 0
# Rows sent 2.11M 0 9.77k 25.13 13.83 460.88 0
# Rows examine 108.07M 0 97.82k 1.26k 9.80k 8.65k 0
# Query size 114.13M 17 1.33M 1.33k 284.79 32.32k 31.70
# Profile
# Rank Query ID Response time Calls R/Call V/M
# ==== =================================== ============== ===== ====== ===
# 1 0x12B99825AF0ABD243835AB7BAC7CEF8C 159.0156 41.3% 3409 0.0466 0.01 SELECT posts
# 2 0x8D047E7B2F83CC44448F61705E9EE675 78.2127 20.3% 7412 0.0106 0.59 SELECT comments
# 3 0xCDEB1AFF2AE2BE51B2ED5CF03D4E749F 52.3945 13.6% 466 0.1124 0.01 SELECT comments
# 4 0x9B36FBB6889AD40E391C181F37DD0542 37.8588 9.8% 7412 0.0051 0.26 SELECT comments
# 5 0x7A12D0C8F433684C3027353C36CAB572 14.0263 3.6% 102 0.1375 0.02 SELECT posts
# 6 0xE83DA93257C7B787C67B1B05D2469241 12.8546 3.3% 466 0.0276 0.01 SELECT posts
# 7 0xDA556F9115773A1A99AA0165670CE848 12.2247 3.2% 26616 0.0005 0.01 ADMIN PREPARE
# MISC 0xMISC 18.8756 4.9% 41986 0.0004 0.0 <27 ITEMS>
# Query 1: 56.82 QPS, 2.65x concurrency, ID 0x12B99825AF0ABD243835AB7BAC7CEF8C at byte 53254999
# Scores: V/M = 0.01
# Time range: 2024-05-11T08:53:14 to 2024-05-11T08:54:14
# Attribute pct total min max avg 95% stddev median
# ============ === ======= ======= ======= ======= ======= ======= =======
# Count 3 3409
# Exec time 41 159s 7ms 148ms 47ms 82ms 21ms 44ms
# Lock time 9 13ms 0 2ms 3us 2us 51us 1us
# Rows sent 4 99.87k 30 30 30 30 0 30
# Rows examine 30 32.90M 9.79k 9.97k 9.88k 9.80k 39.94 9.80k
# Query size 0 336.24k 101 101 101 101 0 101
# String:
# Databases isuconp
# Hosts localhost
# Users isuconp
# Query_time distribution
# 1us
# 10us
# 100us
# 1ms #
# 10ms ################################################################
# 100ms #
# 1s
# 10s+
# Tables
# SHOW TABLE STATUS FROM `isuconp` LIKE 'posts'\G
# SHOW CREATE TABLE `isuconp`.`posts`\G
# EXPLAIN /*!50100 PARTITIONS*/
SELECT `id`, `user_id`, `body`, `mime`, `created_at` FROM `posts` ORDER BY `created_at` DESC LIMIT 30\G
# Query 2: 121.51 QPS, 1.28x concurrency, ID 0x8D047E7B2F83CC44448F61705E9EE675 at byte 112466915
# Scores: V/M = 0.59
# Time range: 2024-05-11T08:53:14 to 2024-05-11T08:54:15
# Attribute pct total min max avg 95% stddev median
# ============ === ======= ======= ======= ======= ======= ======= =======
# Count 8 7412
# Exec time 20 78s 69us 971ms 11ms 8ms 79ms 490us
# Lock time 22 32ms 0 7ms 4us 2us 95us 1us
# Rows sent 1 35.41k 0 23 4.89 13.83 5.00 2.90
# Rows examine 9 9.90M 0 97.82k 1.37k 174.84 11.30k 6.98
# Query size 6 6.97M 85 57.53k 985.49 284.79 6.54k 143.84
# String:
# Databases isuconp
# Hosts localhost
# Users isuconp
# Query_time distribution
# 1us
# 10us #
# 100us ################################################################
# 1ms ###########################
# 10ms ##
# 100ms #
# 1s
# 10s+
# Tables
# SHOW TABLE STATUS FROM `isuconp` LIKE 'comments'\G
# SHOW CREATE TABLE `isuconp`.`comments`\G
# EXPLAIN /*!50100 PARTITIONS*/
SELECT * FROM `comments` WHERE `post_id` IN (9908, 9907, 9906, 9905, 9904, 9903, 9902, 9901, 9900, 9899, 9898, 9897, 9896, 9895, 9894, 9893, 9892, 9891, 9890, 9889/*... omitted 9888 items ...*/) ORDER BY `created_at` DESC LIMIT 3\G
# Query 3: 7.77 QPS, 0.87x concurrency, ID 0xCDEB1AFF2AE2BE51B2ED5CF03D4E749F at byte 107085132
# Scores: V/M = 0.01
# Time range: 2024-05-11T08:53:14 to 2024-05-11T08:54:14
# Attribute pct total min max avg 95% stddev median
# ============ === ======= ======= ======= ======= ======= ======= =======
# Count 0 466
# Exec time 13 52s 18ms 200ms 112ms 171ms 37ms 110ms
# Lock time 2 3ms 0 2ms 6us 2us 71us 1us
# Rows sent 0 466 1 1 1 1 0 1
# Rows examine 41 44.48M 97.66k 97.82k 97.74k 97.04k 0 97.04k
# Query size 0 28.17k 61 62 61.91 59.77 0 59.77
# String:
# Databases isuconp
# Hosts localhost
# Users isuconp
# Query_time distribution
# 1us
# 10us
# 100us
# 1ms
# 10ms ##############################
# 100ms ################################################################
# 1s
# 10s+
# Tables
# SHOW TABLE STATUS FROM `isuconp` LIKE 'comments'\G
# SHOW CREATE TABLE `isuconp`.`comments`\G
# EXPLAIN /*!50100 PARTITIONS*/
SELECT COUNT(*) AS count FROM `comments` WHERE `user_id` = 294\G
# Query 4: 121.51 QPS, 0.62x concurrency, ID 0x9B36FBB6889AD40E391C181F37DD0542 at byte 101596075
# Scores: V/M = 0.26
# Time range: 2024-05-11T08:53:14 to 2024-05-11T08:54:15
# Attribute pct total min max avg 95% stddev median
# ============ === ======= ======= ======= ======= ======= ======= =======
# Count 8 7412
# Exec time 9 38s 69us 574ms 5ms 6ms 37ms 287us
# Lock time 37 53ms 0 8ms 7us 2us 156us 1us
# Rows sent 46 1003.51k 0 9.75k 138.64 16.81 1.09k 0.99
# Rows examine 9 9.81M 0 97.66k 1.35k 166.51 10.97k 6.98
# Query size 6 7.05M 95 57.54k 997.10 299.03 6.53k 151.03
# String:
# Databases isuconp
# Hosts localhost
# Users isuconp
# Query_time distribution
# 1us
# 10us ###
# 100us ################################################################
# 1ms ##############
# 10ms #
# 100ms #
# 1s
# 10s+
# Tables
# SHOW TABLE STATUS FROM `isuconp` LIKE 'comments'\G
# SHOW CREATE TABLE `isuconp`.`comments`\G
# EXPLAIN /*!50100 PARTITIONS*/
SELECT `post_id`, COUNT(*) AS `count` FROM `comments` WHERE `post_id` IN (9963, 9962, 9961, 9960, 9959, 9958, 9957, 9956, 9955, 9954, 9953, 9952, 9951, 9950, 9949, 9948, 9947, 9946, 9945, 9944/*... omitted 9943 items ...*/) GROUP BY `post_id`\G
# Query 5: 1.67 QPS, 0.23x concurrency, ID 0x7A12D0C8F433684C3027353C36CAB572 at byte 46841830
# Scores: V/M = 0.02
# Time range: 2024-05-11T08:53:14 to 2024-05-11T08:54:15
# Attribute pct total min max avg 95% stddev median
# ============ === ======= ======= ======= ======= ======= ======= =======
# Count 0 102
# Exec time 3 14s 20ms 243ms 138ms 198ms 51ms 141ms
# Lock time 0 569us 0 339us 5us 2us 32us 1us
# Rows sent 45 987.05k 9.57k 9.75k 9.68k 9.33k 0 9.33k
# Rows examine 1 1.95M 19.40k 19.68k 19.54k 19.40k 0 19.40k
# Query size 0 14.14k 142 142 142 142 0 142
# String:
# Databases isuconp
# Hosts localhost
# Users isuconp
# Query_time distribution
# 1us
# 10us
# 100us
# 1ms
# 10ms ###############
# 100ms ################################################################
# 1s
# 10s+
# Tables
# SHOW TABLE STATUS FROM `isuconp` LIKE 'posts'\G
# SHOW CREATE TABLE `isuconp`.`posts`\G
# EXPLAIN /*!50100 PARTITIONS*/
SELECT `id`, `user_id`, `body`, `mime`, `created_at` FROM `posts` WHERE `created_at` <= '2016-01-02T11:44:26+09:00' ORDER BY `created_at` DESC\G
# Query 6: 7.77 QPS, 0.21x concurrency, ID 0xE83DA93257C7B787C67B1B05D2469241 at byte 80272238
# Scores: V/M = 0.01
# Time range: 2024-05-11T08:53:14 to 2024-05-11T08:54:14
# Attribute pct total min max avg 95% stddev median
# ============ === ======= ======= ======= ======= ======= ======= =======
# Count 0 466
# Exec time 3 13s 5ms 103ms 28ms 56ms 16ms 24ms
# Lock time 0 798us 0 45us 1us 1us 2us 1us
# Rows sent 0 4.72k 2 21 10.37 15.25 3.14 9.83
# Rows examine 4 4.49M 9.77k 9.95k 9.86k 9.80k 92 9.80k
# Query size 0 51.84k 113 114 113.91 112.70 0 112.70
# String:
# Databases isuconp
# Hosts localhost
# Users isuconp
# Query_time distribution
# 1us
# 10us
# 100us
# 1ms #######
# 10ms ################################################################
# 100ms #
# 1s
# 10s+
# Tables
# SHOW TABLE STATUS FROM `isuconp` LIKE 'posts'\G
# SHOW CREATE TABLE `isuconp`.`posts`\G
# EXPLAIN /*!50100 PARTITIONS*/
SELECT `id`, `user_id`, `body`, `mime`, `created_at` FROM `posts` WHERE `user_id` = 196 ORDER BY `created_at` DESC\G
# Query 7: 436.33 QPS, 0.20x concurrency, ID 0xDA556F9115773A1A99AA0165670CE848 at byte 20466989
# Scores: V/M = 0.01
# Time range: 2024-05-11T08:53:14 to 2024-05-11T08:54:15
# Attribute pct total min max avg 95% stddev median
# ============ === ======= ======= ======= ======= ======= ======= =======
# Count 30 26616
# Exec time 3 12s 25us 173ms 459us 2ms 2ms 93us
# Lock time 0 0 0 0 0 0 0 0
# Rows sent 0 0 0 0 0 0 0 0
# Rows examine 0 0 0 0 0 0 0 0
# Query size 0 779.77k 30 30 30 30 0 30
# String:
# Databases isuconp
# Hosts localhost
# Users isuconp
# Query_time distribution
# 1us
# 10us ################################################################
# 100us ##############################################
# 1ms #######
# 10ms #
# 100ms #
# 1s
# 10s+
administrator command: Prepare\G
mysql> explain SELECT `id`, `user_id`, `body`, `mime`, `created_at` FROM `posts` ORDER BY `created_at` DESC LIMIT 30\G
*************************** 1. row ***************************
id: 1
select_type: SIMPLE
table: posts
partitions: NULL
type: ALL
possible_keys: NULL
key: NULL
key_len: NULL
ref: NULL
rows: 9464
filtered: 100.00
Extra: Using filesort
1 row in set, 1 warning (0.00 sec)
Note (Code 1003): /* select#1 */ select `isuconp`.`posts`.`id` AS `id`,`isuconp`.`posts`.`user_id` AS `user_id`,`isuconp`.`posts`.`body` AS `body`,`isuconp`.`posts`.`mime` AS `mime`,`isuconp`.`posts`.`created_at` AS `created_at` from `isuconp`.`posts` order by `isuconp`.`posts`.`created_at` desc limit 30
mysql> ALTER TABLE posts ADD INDEX (created_at DESC);
Query OK, 0 rows affected (0.02 sec)
Records: 0 Duplicates: 0 Warnings: 0
mysql> explain SELECT `id`, `user_id`, `body`, `mime`, `created_at` FROM `posts` ORDER BY `created_at` DESC LIMIT 30\G
*************************** 1. row ***************************
id: 1
select_type: SIMPLE
table: posts
partitions: NULL
type: index
possible_keys: NULL
key: created_at
key_len: 4
ref: NULL
rows: 30
filtered: 100.00
Extra: NULL
1 row in set, 1 warning (0.00 sec)
Note (Code 1003): /* select#1 */ select `isuconp`.`posts`.`id` AS `id`,`isuconp`.`posts`.`user_id` AS `user_id`,`isuconp`.`posts`.`body` AS `body`,`isuconp`.`posts`.`mime` AS `mime`,`isuconp`.`posts`.`created_at` AS `created_at` from `isuconp`.`posts` order by `isuconp`.`posts`.`created_at` desc limit 30{"pass":true,"score":154798,"success":150702,"fail":0,"messages":[]}
pinkumohikan
commented
6 months ago | COUNT | SUM | AVG | STDDEV | MIN | P99 | MAX | 2XX | 3XX | 4XX | 5XX | METHOD | URI | ||
|---|---|---|---|---|---|---|---|---|---|---|---|---|---|---|
| 5854 (+2445) | 169.180 (-91.373) | 0.029 (-0.048) | 0.020 (-0.006) | 0.004 (-0.004) | 0.084 (-0.064) | 0.320 (+0.024) | 5854 (+2445) | 0 | 0 | 0 | GET | / | ||
| 2237 (+86) | 139.001 (+65.991) | 0.062 (+0.028) | 0.037 (+0.016) | 0.004 | 0.156 (+0.064) | 0.276 (+0.160) | 0 | 2237 (+86) | 0 | 0 | POST | /login | ||
| 180 (+78) | 122.356 (+1.800) | 0.680 (-0.502) | 0.176 (-0.180) | 0.176 (-0.028) | 1.020 (-0.612) | 1.108 (-0.568) | 180 (+78) | 0 | 0 | 0 | GET | /posts | ||
| 3030 (-405) | 78.680 (+27.709) | 0.026 (+0.011) | 0.019 (+0.005) | 0.004 (+0.004) | 0.084 (+0.016) | 0.280 (+0.148) | 3030 (-405) | 0 | 0 | 0 | GET | /posts/[\d]+ | ||
| 433 (-33) | 76.114 (-25.541) | 0.176 (-0.042) | 0.045 (-0.002) | 0.032 (+0.004) | 0.276 (-0.048) | 0.568 (+0.212) | 433 (-33) | 0 | 0 | 0 | GET | /@[\w]+ | ||
| 245 (+10) | 22.437 (+10.260) | 0.092 (+0.040) | 0.029 (+0.006) | 0.016 (+0.004) | 0.156 (+0.028) | 0.184 (+0.040) | 0 | 245 (+10) | 0 | 0 | POST | /register | ||
| 360 | 12.585 (+0.893) | 0.035 (+0.002) | 0.036 (-0.003) | 0.004 | 0.152 (-0.004) | 0.172 | 0 | 180 | 180 | 0 | POST | / | ||
| 245 (+10) | 3.348 (+1.456) | 0.014 (+0.006) | 0.013 (+0.005) | 0.004 | 0.068 (+0.028) | 0.072 (+0.028) | 0 | 0 | 245 (+10) | 0 | GET | /admin/banned | ||
| 174 (+10) | 3.264 (+0.752) | 0.019 (+0.003) | 0.014 (-0.002) | 0.004 (+0.004) | 0.068 (-0.012) | 0.084 (-0.004) | 0 | 174 (+10) | 0 | 0 | POST | /comment | ||
| 972 (+44) | 3.204 (+1.736) | 0.003 (+0.002) | 0.010 (+0.007) | 0.004 | 0.020 (+0.008) | 0.224 (+0.200) | 972 (+44) | 0 | 0 | 0 | GET | /login | ||
| 486 (+22) | 1.928 (+0.840) | 0.004 (+0.002) | 0.005 (+0.002) | 0.000 | 0.024 (+0.008) | 0.032 (+0.012) | 0 | 486 (+22) | 0 | 0 | GET | /logout | ||
| 1 | 0.100 (-0.040) | 0.100 (-0.040) | 0.000 | 0.100 (-0.040) | 0.100 (-0.040) | 0.100 (-0.040) | 1 | 0 | 0 | 0 | GET | /initialize | ||
| 105732 (+49030) | 0.062 (+0.003) | 0.000 (-0.000) | 0.000 (-0.000) | 0.000 | 0.000 | 0.004 (-0.003) | 2638 (-354) | 103094 (+49384) | 0 | 0 | GET | /image/[0-9]+.(png | jpg | gif) |
| 7765 (+1957) | 0.000 | 0.000 | 0.000 | 0.000 | 0.000 | 0.000 | 1 | 7764 (+1957) | 0 | 0 | GET | /favicon.ico | ||
| 7765 (+1957) | 0.000 | 0.000 | 0.000 | 0.000 | 0.000 | 0.000 | 1 | 7764 (+1957) | 0 | 0 | GET | /js/timeago.min.js | ||
| 7765 (+1957) | 0.000 | 0.000 | 0.000 | 0.000 | 0.000 | 0.000 | 1 | 7764 (+1957) | 0 | 0 | GET | /js/main.js | ||
| 7765 (+1957) | 0.000 | 0.000 | 0.000 | 0.000 | 0.000 | 0.000 | 1 | 7764 (+1957) | 0 | 0 | GET | /css/style.css |
pinkumohikan
commented
6 months ago # Query 3: 7.22 QPS, 0.55x concurrency, ID 0xCDEB1AFF2AE2BE51B2ED5CF03D4E749F at byte 47563716
# Scores: V/M = 0.01
# Time range: 2024-05-11T08:59:14 to 2024-05-11T09:00:14
# Attribute pct total min max avg 95% stddev median
# ============ === ======= ======= ======= ======= ======= ======= =======
# Count 0 433
# Exec time 17 33s 19ms 174ms 76ms 122ms 26ms 71ms
# Lock time 0 1ms 0 219us 2us 2us 11us 1us
# Rows sent 0 433 1 1 1 1 0 1
# Rows examine 47 41.33M 97.66k 97.83k 97.74k 97.04k 0 97.04k
# Query size 0 26.17k 61 62 61.90 59.77 0.00 59.77
# String:
# Databases isuconp
# Hosts localhost
# Users isuconp
# Query_time distribution
# 1us
# 10us
# 100us
# 1ms
# 10ms ################################################################
# 100ms #################
# 1s
# 10s+
# Tables
# SHOW TABLE STATUS FROM `isuconp` LIKE 'comments'\G
# SHOW CREATE TABLE `isuconp`.`comments`\G
# EXPLAIN /*!50100 PARTITIONS*/
SELECT COUNT(*) AS count FROM `comments` WHERE `user_id` = 545\Gmysql> ALTER TABLE comments ADD INDEX (user_id);
Query OK, 0 rows affected (0.30 sec)
Records: 0 Duplicates: 0 Warnings: 0
問題
後で消す