Closed okashoi closed 2 months ago
isucon@ip-192-168-0-11:~$ cat /etc/systemd/system/multi-user.target.wants/isuports.service
[Unit]
Description=isucon12 qualify webapp
After=network.target
[Install]
WantedBy=multi-user.target
[Service]
Type=simple
User=isucon
Group=isucon
WorkingDirectory=/home/isucon/webapp
ExecStart=docker compose -f docker-compose-go.yml up --build
ExecStop=docker compose -f docker-compose-go.yml down
Restart=always
dockerで動いてる
Top 20 Sort By Total
Count Total Mean Stddev Min P50.0 P90.0 P95.0 P99.0 Max 2xx 3xx 4xx 5xx TotalBytes MinBytes MeanBytes MaxBytes Request
667 871.822 1.3071 1.5344 0.001 0.420 3.566 3.889 4.157 7.299 652 0 15 0 672631 0 1008 2468 GET /api/player/player/[a-z0-9]+
839 841.483 1.0030 1.6515 0.001 0.032 3.770 3.959 7.316 7.730 808 0 31 0 7779189 0 9271 14740 GET /api/player/competition/[a-z0-9]+/ranking
11 111.497 10.1361 3.0133 3.658 10.969 12.851 13.505 13.505 13.505 9 0 2 0 13641 0 1240 1565 GET /api/admin/tenants/billing?before=<num> HTTP/2.0
66 88.005 1.3334 1.3184 0.001 1.009 3.549 3.757 7.102 7.102 59 0 7 0 3371 0 51 62 POST /api/organizer/competition/[a-z0-9]+/score
26 40.399 1.5538 5.9289 0.002 0.032 0.299 8.740 30.001 30.001 25 0 1 0 50323 0 1935 5802 GET /api/organizer/billing HTTP/2.0
6 13.016 2.1693 0.6697 1.483 2.741 2.997 2.997 2.997 2.997 6 0 0 0 110123 12150 18353 25820 POST /api/organizer/players/add HTTP/2.0
135 3.879 0.0287 0.1420 0.001 0.014 0.035 0.050 0.065 1.665 121 0 14 0 162538 39 1203 2792 GET /api/player/competitions HTTP/2.0
1 2.900 2.9000 0.0000 2.900 2.900 2.900 2.900 2.900 2.900 1 0 0 0 55 55 55 55 POST /initialize HTTP/2.0
1 2.588 2.5880 0.0000 2.588 2.588 2.588 2.588 2.588 2.588 1 0 0 0 1597 1597 1597 1597 GET /api/admin/tenants/billing HTTP/2.0
47 0.812 0.0173 0.0091 0.002 0.014 0.028 0.034 0.052 0.052 46 0 1 0 7725 39 164 189 POST /api/organizer/competitions/add HTTP/2.0
43 0.763 0.0177 0.0099 0.001 0.014 0.032 0.035 0.049 0.049 42 0 1 0 921 21 21 39 POST /api/organizer/competition/[a-z0-9]+/finish
11 0.548 0.0498 0.0444 0.001 0.052 0.102 0.123 0.123 0.123 6 0 5 0 1366 39 124 208 POST /api/admin/tenants/add HTTP/2.0
30 0.323 0.0108 0.0121 0.002 0.006 0.028 0.048 0.050 0.050 30 0 0 0 542001 2942 18066 46093 GET /api/organizer/players HTTP/2.0
16 0.200 0.0125 0.0045 0.005 0.013 0.018 0.019 0.019 0.019 15 0 1 0 2409 39 150 165 POST /api/organizer/player/[a-z0-9]+/disqualified
1 0.001 0.0010 0.0000 0.001 0.001 0.001 0.001 0.001 0.001 1 0 0 0 177 177 177 177 GET /api/organizer/competitions HTTP/2.0
1 0.000 0.0000 0.0000 0.000 0.000 0.000 0.000 0.000 0.000 0 0 1 0 134 134 134 134 GET /stream?streams=btcusdt@depth HTTP/1.1
1 0.000 0.0000 0.0000 0.000 0.000 0.000 0.000 0.000 0.000 1 0 0 0 4868 4868 4868 4868 GET /css/app.83b4c321.css HTTP/2.0
1 0.000 0.0000 0.0000 0.000 0.000 0.000 0.000 0.000 0.000 1 0 0 0 479 479 479 479 GET /index.html HTTP/2.0
1 0.000 0.0000 0.0000 0.000 0.000 0.000 0.000 0.000 0.000 1 0 0 0 33294 33294 33294 33294 GET /js/app.3a4ec98c.js HTTP/2.0
インフラ構成
total used free shared buff/cache available
Mem: 3.6Gi 1.1Gi 102Mi 0.0Ki 2.4Gi 2.2Gi
Swap: 0B 0B 0B
COMMAND PID USER FD TYPE DEVICE SIZE/OFF NODE NAME
main 55593 isucon 41u IPv4 181560 0t0 TCP localhost:49598->localhost:mysql (ESTABLISHED)
main 55593 isucon 117u IPv4 181053 0t0 TCP localhost:49734->localhost:mysql (ESTABLISHED)
mysqld 56361 mysql 23u IPv4 174368 0t0 TCP localhost:mysql (LISTEN)
mysqld 56361 mysql 35u IPv4 180953 0t0 TCP localhost:mysql->localhost:49598 (ESTABLISHED)
mysqld 56361 mysql 38u IPv4 181700 0t0 TCP localhost:mysql->localhost:49734 (ESTABLISHED)
nginx 56441 root 6u IPv4 174519 0t0 TCP *:https (LISTEN)
nginx 56442 www-data 6u IPv4 174519 0t0 TCP *:https (LISTEN)
nginx 56443 www-data 6u IPv4 174519 0t0 TCP *:https (LISTEN)
UNIT LOAD ACTIVE SUB DESCRIPTION
acpid.service loaded active running ACPI event daemon
apparmor.service loaded active exited Load AppArmor profiles
apport.service loaded active exited LSB: automatic crash report generation
blackauth.service loaded active running isucon12 qualify auth server
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
containerd.service loaded active running containerd container runtime
cron.service loaded active running Regular background program processing daemon
dbus.service loaded active running D-Bus System Message Bus
docker.service loaded active running Docker Application Container Engine
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
isuports.service loaded active running isucon12 qualify webapp
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
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
packagekit.service loaded active running PackageKit Daemon
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
redis-server.service loaded active running Advanced key-value store
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-machine-id-commit.service loaded active exited Commit a transient machine-id on disk
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
ubuntu-fan.service loaded active exited Ubuntu FAN network setup
ufw.service loaded active exited Uncomplicated firewall
unattended-upgrades.service loaded active running Unattended Upgrades Shutdown
user-runtime-dir@1001.service loaded active exited User Runtime Directory /run/user/1001
user@1001.service loaded active running User Manager for UID 1001
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.
66 loaded units listed.
To show all installed unit files use 'systemctl list-unit-files'.
/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin:/usr/games:/usr/local/games:/snap/bin
-- before
mysql> explain SELECT player_id, MIN(created_at) AS min_created_at FROM visit_history WHERE tenant_id = 36 AND competition_id = '155bc48ec' GROUP BY player_id;
+----+-------------+---------------+------------+------+---------------+---------------+---------+-------+-------+----------+------------------------------+
| id | select_type | table | partitions | type | possible_keys | key | key_len | ref | rows | filtered | Extra |
+----+-------------+---------------+------------+------+---------------+---------------+---------+-------+-------+----------+------------------------------+
| 1 | SIMPLE | visit_history | NULL | ref | tenant_id_idx | tenant_id_idx | 8 | const | 84748 | 10.00 | Using where; Using temporary |
+----+-------------+---------------+------------+------+---------------+---------------+---------+-------+-------+----------+------------------------------+
-- add inex
mysql> ALTER TABLE visit_history ADD INDEX (tenant_id, competition_id, player_id, created_at);
-- after
mysql> explain SELECT player_id, MIN(created_at) AS min_created_at FROM visit_history WHERE tenant_id = 36 AND competition_id = '155bc48ec' GROUP BY player_id;
+----+-------------+---------------+------------+------+-------------------------+-----------+---------+-------------+------+----------+-------------+
| id | select_type | table | partitions | type | possible_keys | key | key_len | ref | rows | filtered | Extra |
+----+-------------+---------------+------------+------+-------------------------+-----------+---------+-------------+------+----------+-------------+
| 1 | SIMPLE | visit_history | NULL | ref | tenant_id_idx,tenant_id | tenant_id | 1030 | const,const | 3025 | 100.00 | Using index |
+----+-------------+---------------+------------+------+-------------------------+-----------+---------+-------------+------+----------+-------------+
https://isunarabe.org/teams/682/benchmark_jobs/10670 02:28:19.114746 SCORE: 4981 (+4981 0(0%))
OBJECT_NAME | COUNT_FETCH | COUNT_INSERT | COUNT_UPDATE | COUNT_DELETE |
---|---|---|---|---|
visit_history | 10756622 | 1308 | 0 | 1217 |
id_generator | 16250 | 16249 | 16250 | 0 |
tenant | 8240 | 8 | 0 | 7 |
TABLE_NAME | TABLE_ROWS | total_storage_mb | avg_storage_b | total_data_mb | total_index_mb |
---|---|---|---|---|---|
visit_history | 2969004 | 266 | 94 | 209 | 56 |
id_generator | 1 | 0 | 32768 | 0 | 0 |
tenant | 107 | 0 | 306 | 0 | 0 |
微減したのでマージは一旦見送り
02:44:29.283843 ERROR[0] load: load-validation: Get "https://isucon.t.isucon.pw/api/player/player/224605ea1": context deadline exceeded (Client.Timeout exceeded while awaiting headers) tenant:isucon role:player playerID:63c385ad1 playerID:224605ea1
02:44:29.284131 Error 1 (Critical:0)
02:44:29.284180 PASSED: true
02:44:29.284189 SCORE: 4718 (+4765 -47(1%))
02:51:37.104645 ERROR[0] load: load-validation: Get "https://jbj-wq-8.t.isucon.pw/api/organizer/billing": context deadline exceeded (Client.Timeout exceeded while awaiting headers) tenant:jbj-wq-8 role:organizer playerID:organizer
02:51:37.104931 Error 1 (Critical:0)
02:51:37.104938 PASSED: true
02:51:37.104941 SCORE: 4518 (+4563 -45(1%))
使われているGo
isucon@ip-192-168-0-11:~/webapp (pprof)
$ docker compose -f docker-compose-go.yml run webapp bash
isucon@ip-192-168-0-11:~/webapp/go$ go version
go version go1.18.4 linux/amd64
Top 20 Sort By Total
Count Total Mean Stddev Min P50.0 P90.0 P95.0 P99.0 Max 2xx 3xx 4xx 5xx TotalBytes MinBytes MeanBytes MaxBytes Request
1310 1846.814 1.4098 2.5022 0.001 0.038 3.764 4.922 12.761 20.290 1265 0 45 0 13034872 0 9950 14737 GET /api/player/competition/[a-z0-9]+/ranking
1168 1532.024 1.3117 2.5188 0.001 0.150 3.274 3.666 11.956 28.594 1104 0 63 1 958398 0 820 2263 GET /api/player/player/[a-z0-9]+
80 148.412 1.8551 2.0667 0.001 1.181 3.817 5.170 12.677 12.677 73 0 7 0 4134 0 51 62 POST /api/organizer/competition/[a-z0-9]+/score
35 80.090 2.2883 3.4360 0.001 1.451 2.868 11.755 17.938 17.938 34 0 1 0 49790 0 1422 1552 GET /api/admin/tenants/billing?before=<num> HTTP/2.0
36 22.037 0.6121 2.9069 0.002 0.030 0.278 1.567 17.701 17.701 35 0 1 0 65612 0 1822 4928 GET /api/organizer/billing HTTP/2.0
10 18.896 1.8896 0.6023 0.890 2.171 2.698 2.698 2.698 2.698 10 0 0 0 178011 12150 17801 23580 POST /api/organizer/players/add HTTP/2.0
1 3.972 3.9720 0.0000 3.972 3.972 3.972 3.972 3.972 3.972 1 0 0 0 55 55 55 55 POST /initialize HTTP/2.0
201 3.382 0.0168 0.0124 0.001 0.014 0.035 0.041 0.051 0.054 188 0 13 0 213493 39 1062 2663 GET /api/player/competitions HTTP/2.0
12 1.917 0.1598 0.2009 0.001 0.086 0.439 0.629 0.629 0.629 7 0 5 0 1517 39 126 196 POST /api/admin/tenants/add HTTP/2.0
2 1.477 0.7385 0.3075 0.431 1.046 1.046 1.046 1.046 1.046 2 0 0 0 3155 1568 1577 1587 GET /api/admin/tenants/billing HTTP/2.0
62 1.303 0.0210 0.0380 0.007 0.015 0.025 0.027 0.312 0.312 61 0 1 0 10000 39 161 185 POST /api/organizer/competitions/add HTTP/2.0
57 1.249 0.0219 0.0435 0.002 0.014 0.025 0.046 0.342 0.342 56 0 1 0 1215 21 21 39 POST /api/organizer/competition/[a-z0-9]+/finish
45 0.344 0.0076 0.0072 0.002 0.005 0.017 0.018 0.043 0.043 45 0 0 0 1498478 2942 33299 602067 GET /api/organizer/players HTTP/2.0
15 0.188 0.0125 0.0040 0.002 0.012 0.018 0.019 0.019 0.019 14 0 1 0 2249 39 149 165 POST /api/organizer/player/[a-z0-9]+/disqualified
1 0.001 0.0010 0.0000 0.001 0.001 0.001 0.001 0.001 0.001 1 0 0 0 177 177 177 177 GET /api/organizer/competitions HTTP/2.0
1 0.000 0.0000 0.0000 0.000 0.000 0.000 0.000 0.000 0.000 1 0 0 0 33294 33294 33294 33294 GET /js/app.3a4ec98c.js HTTP/2.0
1 0.000 0.0000 0.0000 0.000 0.000 0.000 0.000 0.000 0.000 1 0 0 0 479 479 479 479 GET /index.html HTTP/2.0
1 0.000 0.0000 0.0000 0.000 0.000 0.000 0.000 0.000 0.000 1 0 0 0 4868 4868 4868 4868 GET /css/app.83b4c321.css HTTP/2.0
03:26:38.262107 ERROR[0] load: load-validation: GET /api/player/player/5e2629d32 : expected([200]) != actual(500) tenant:hgp-yqb-25 role:player playerID:9fa53577 playerID:5e2629d32
03:26:38.262447 Error 1 (Critical:0)
03:26:38.262453 PASSED: true
03:26:38.262456 SCORE: 5109 (+5160 -51(1%))
Top 20 Sort By Total
Count Total Mean Stddev Min P50.0 P90.0 P95.0 P99.0 Max 2xx 3xx 4xx 5xx TotalBytes MinBytes MeanBytes MaxBytes Request
1324 1672.308 1.2631 2.2650 0.002 0.037 3.553 4.323 11.630 13.338 1282 0 42 0 12517111 0 9454 14739 GET /api/player/competition/[a-z0-9]+/ranking
1283 1452.590 1.1322 2.0200 0.001 0.074 3.203 3.618 11.224 13.706 1244 0 38 1 1218676 0 949 2237 GET /api/player/player/[a-z0-9]+
85 148.829 1.7509 2.0226 0.002 1.069 3.623 4.301 12.376 12.376 78 0 7 0 4399 0 51 62 POST /api/organizer/competition/[a-z0-9]+/score
36 79.454 2.2071 2.8235 0.001 1.287 4.764 8.299 15.051 15.051 34 0 2 0 49668 0 1379 1551 GET /api/admin/tenants/billing?before=<num> HTTP/2.0
37 26.732 0.7225 3.9122 0.002 0.025 0.369 0.553 24.185 24.185 36 0 1 0 73395 0 1983 5245 GET /api/organizer/billing HTTP/2.0
10 21.967 2.1967 0.9178 1.055 2.278 4.135 4.135 4.135 4.135 10 0 0 0 194811 12150 19481 25596 POST /api/organizer/players/add HTTP/2.0
1 4.946 4.9460 0.0000 4.946 4.946 4.946 4.946 4.946 4.946 1 0 0 0 55 55 55 55 POST /initialize HTTP/2.0
217 3.592 0.0166 0.0129 0.001 0.014 0.036 0.042 0.056 0.059 202 0 15 0 255430 39 1177 2708 GET /api/player/competitions HTTP/2.0
60 1.341 0.0223 0.0315 0.005 0.014 0.046 0.067 0.242 0.242 59 0 1 0 1278 21 21 39 POST /api/organizer/competition/[a-z0-9]+/finish
65 1.187 0.0183 0.0096 0.007 0.016 0.025 0.033 0.064 0.064 64 0 1 0 10611 39 163 185 POST /api/organizer/competitions/add HTTP/2.0
2 0.976 0.4880 0.0520 0.436 0.540 0.540 0.540 0.540 0.540 2 0 0 0 3170 1584 1585 1586 GET /api/admin/tenants/billing HTTP/2.0
48 0.439 0.0091 0.0105 0.002 0.005 0.021 0.036 0.057 0.057 48 0 0 0 1544903 3070 32185 602067 GET /api/organizer/players HTTP/2.0
12 0.426 0.0355 0.0316 0.000 0.041 0.091 0.094 0.094 0.094 7 0 5 0 1514 39 126 194 POST /api/admin/tenants/add HTTP/2.0
17 0.259 0.0152 0.0077 0.001 0.013 0.028 0.035 0.035 0.035 16 0 1 0 2556 39 150 165 POST /api/organizer/player/[a-z0-9]+/disqualified
1 0.001 0.0010 0.0000 0.001 0.001 0.001 0.001 0.001 0.001 1 0 0 0 177 177 177 177 GET /api/organizer/competitions HTTP/2.0
1 0.000 0.0000 0.0000 0.000 0.000 0.000 0.000 0.000 0.000 1 0 0 0 4868 4868 4868 4868 GET /css/app.83b4c321.css HTTP/2.0
1 0.000 0.0000 0.0000 0.000 0.000 0.000 0.000 0.000 0.000 1 0 0 0 479 479 479 479 GET /index.html HTTP/2.0
1 0.000 0.0000 0.0000 0.000 0.000 0.000 0.000 0.000 0.000 1 0 0 0 33294 33294 33294 33294 GET /js/app.3a4ec98c.js HTTP/2.0
つづいて GET /api/player/competition/[a-z0-9]+/ranking
をやる
03:57:45.605920 ERROR[0] load: load-validation: GET /api/player/competition/9fa52b49/ranking : expected([200]) != actual(500) tenant:i-hezmh-1721447804 role:player playerID:9fa52b08 competitionID:9fa52b49 rankAfter:
03:57:45.605936 ERROR[1] load: load-validation: GET /api/player/competition/9fa52e71/ranking : expected([200]) != actual(500) tenant:jjsjx-tdwrrx-10 role:player playerID:14f0d02e4 competitionID:9fa52e71 rankAfter:
03:57:45.605945 ERROR[2] load: load-validation: GET /api/player/competition/9fa531ff/ranking : expected([200]) != actual(500) tenant:dz-n-1721447812 role:player playerID:9fa52ff5 competitionID:9fa531ff rankAfter:
03:57:45.605949 ERROR[3] load: load-validation: GET /api/player/competition/9fa531ff/ranking : expected([200]) != actual(500) tenant:dz-n-1721447812 role:player playerID:9fa53141 competitionID:9fa531ff rankAfter:
03:57:45.605954 ERROR[4] load: load-validation: GET /api/player/competition/9fa53ad6/ranking : expected([200]) != actual(500) tenant:wvf-yom-16 role:player playerID:524577dc7 competitionID:9fa53ad6 rankAfter:
03:57:45.605958 ERROR[5] load: load-validation: GET /api/player/competition/9fa53ad6/ranking : expected([200]) != actual(500) tenant:wvf-yom-16 role:player playerID:9fa538d5 competitionID:9fa53ad6 rankAfter:
03:57:45.605961 ERROR[6] load: load-validation: GET /api/player/competition/9fa53fa5/ranking : expected([200]) != actual(500) tenant:aeja-cuzvf-1721447827 role:player playerID:9fa53f6d competitionID:9fa53fa5 rankAfter:
03:57:45.605964 ERROR[7] load: load-validation: GET /api/player/competition/9fa53fa5/ranking : expected([200]) != actual(500) tenant:aeja-cuzvf-1721447827 role:player playerID:9fa53f9f competitionID:9fa53fa5 rankAfter:
03:57:45.605968 ERROR[8] load: load-validation: GET /api/player/competition/9fa53fa5/ranking : expected([200]) != actual(500) tenant:aeja-cuzvf-1721447827 role:player playerID:9fa53b92 competitionID:9fa53fa5 rankAfter:
03:57:45.605970 ERROR[9] load: load-validation: GET /api/player/competition/9fa5446d/ranking : expected([200]) != actual(500) tenant:o-yluz-3 role:player playerID:3660b2c10 competitionID:9fa5446d rankAfter:
03:57:45.605974 ERROR[10] load: load-validation: GET /api/player/competition/4ce9b66c7/ranking : expected([200]) != actual(500) tenant:isucon role:player playerID:63c385ad1 competitionID:4ce9b66c7 rankAfter:
03:57:45.606268 Error 11 (Critical:0)
03:57:45.606275 PASSED: true
03:57:45.606278 SCORE: 5156 (+5793 -637(11%))
Top 20 Sort By Total
Count Total Mean Stddev Min P50.0 P90.0 P95.0 P99.0 Max 2xx 3xx 4xx 5xx TotalBytes MinBytes MeanBytes MaxBytes Request
1387 1374.245 0.9908 1.7980 0.001 0.026 3.842 5.480 6.488 11.312 1325 0 51 11 14284074 0 10298 14708 GET /api/player/competition/[a-z0-9]+/ranking
1943 741.221 0.3815 1.1103 0.001 0.015 1.254 3.200 5.598 6.486 1887 0 56 0 1489616 0 766 2401 GET /api/player/player/[a-z0-9]+
84 150.653 1.7935 1.5592 0.001 1.235 3.936 5.599 6.403 6.403 77 0 7 0 4344 0 51 62 POST /api/organizer/competition/[a-z0-9]+/score
35 79.450 2.2700 3.6640 0.001 1.384 4.588 9.723 21.227 21.227 34 0 1 0 49691 0 1419 1542 GET /api/admin/tenants/billing?before=<num> HTTP/2.0
14 31.268 2.2334 0.5418 0.816 2.246 2.700 3.321 3.321 3.321 13 0 1 0 253455 0 18103 26716 POST /api/organizer/players/add HTTP/2.0
32 22.519 0.7037 3.7273 0.002 0.023 0.086 0.132 21.456 21.456 31 0 1 0 60707 0 1897 4342 GET /api/organizer/billing HTTP/2.0
1 3.947 3.9470 0.0000 3.947 3.947 3.947 3.947 3.947 3.947 1 0 0 0 55 55 55 55 POST /initialize HTTP/2.0
210 3.247 0.0155 0.0159 0.001 0.013 0.029 0.046 0.095 0.106 196 0 14 0 210833 39 1003 2802 GET /api/player/competitions HTTP/2.0
55 1.198 0.0218 0.0359 0.001 0.013 0.032 0.068 0.267 0.267 54 0 1 0 1173 21 21 39 POST /api/organizer/competition/[a-z0-9]+/finish
64 1.083 0.0169 0.0067 0.008 0.014 0.029 0.031 0.038 0.038 63 0 1 0 10391 39 162 191 POST /api/organizer/competitions/add HTTP/2.0
14 0.779 0.0556 0.0974 0.001 0.040 0.061 0.398 0.398 0.398 9 0 5 0 1894 39 135 195 POST /api/admin/tenants/add HTTP/2.0
2 0.725 0.3625 0.0505 0.312 0.413 0.413 0.413 0.413 0.413 2 0 0 0 3157 1562 1578 1595 GET /api/admin/tenants/billing HTTP/2.0
46 0.422 0.0092 0.0136 0.002 0.005 0.017 0.036 0.083 0.083 46 0 0 0 1503318 3582 32680 602067 GET /api/organizer/players HTTP/2.0
17 0.261 0.0154 0.0119 0.001 0.013 0.021 0.060 0.060 0.060 16 0 1 0 2551 39 150 165 POST /api/organizer/player/[a-z0-9]+/disqualified
1 0.001 0.0010 0.0000 0.001 0.001 0.001 0.001 0.001 0.001 1 0 0 0 177 177 177 177 GET /api/organizer/competitions HTTP/2.0
1 0.000 0.0000 0.0000 0.000 0.000 0.000 0.000 0.000 0.000 1 0 0 0 33294 33294 33294 33294 GET /js/app.3a4ec98c.js HTTP/2.0
1 0.000 0.0000 0.0000 0.000 0.000 0.000 0.000 0.000 0.000 1 0 0 0 479 479 479 479 GET /index.html HTTP/2.0
1 0.000 0.0000 0.0000 0.000 0.000 0.000 0.000 0.000 0.000 1 0 0 0 4868 4868 4868 4868 GET /css/app.83b4c321.css HTTP/2.0
出ているエラー
error at /api/player/competition/:competition_id/ranking: write tcp 127.0.0.1:3000->127.0.0.1:38604: write: broken pipe
04:31:36.983951 ERROR[0] load: load-validation: GET /api/player/competition/9fa52e83/ranking : expected([200]) != actual(500) tenant:v-uiwbb-14 role:player playerID:9fa52e81 competitionID:9fa52e83 rankAfter:
04:31:36.984048 ERROR[1] load: load-validation: GET /api/player/competition/9fa53549/ranking : expected([200]) != actual(500) tenant:v-uiwbb-14 role:player playerID:28a1e8344 competitionID:9fa53549 rankAfter:
04:31:36.984361 Error 2 (Critical:0)
04:31:36.984364 PASSED: true
04:31:36.984367 SCORE: 5566 (+5679 -113(2%))
Top 20 Sort By Total
Count Total Mean Stddev Min P50.0 P90.0 P95.0 P99.0 Max 2xx 3xx 4xx 5xx TotalBytes MinBytes MeanBytes MaxBytes Request
1415 1563.934 1.1053 1.8148 0.001 0.034 3.756 3.975 7.897 11.039 1366 0 46 3 14084270 0 9953 14810 GET /api/player/competition/[a-z0-9]+/ranking
1657 1330.662 0.8031 1.3785 0.001 0.050 2.942 3.547 6.475 7.617 1597 0 60 0 1754880 0 1059 2597 GET /api/player/player/[a-z0-9]+
87 151.095 1.7367 1.5981 0.001 1.151 3.876 4.486 7.760 7.760 80 0 7 0 4498 0 51 62 POST /api/organizer/competition/[a-z0-9]+/score
35 79.843 2.2812 3.4777 0.001 1.025 5.778 11.496 17.856 17.856 33 0 2 0 48234 0 1378 1551 GET /api/admin/tenants/billing?before=<num> HTTP/2.0
38 28.180 0.7416 4.0704 0.002 0.022 0.399 0.615 25.487 25.487 37 0 1 0 79482 0 2091 6100 GET /api/organizer/billing HTTP/2.0
11 20.559 1.8690 0.8062 0.695 1.959 2.709 2.941 2.941 2.941 11 0 0 0 210103 12150 19100 25372 POST /api/organizer/players/add HTTP/2.0
225 7.324 0.0326 0.1643 0.001 0.014 0.036 0.054 0.073 1.876 210 0 15 0 278297 39 1236 2955 GET /api/player/competitions HTTP/2.0
1 2.951 2.9510 0.0000 2.951 2.951 2.951 2.951 2.951 2.951 1 0 0 0 55 55 55 55 POST /initialize HTTP/2.0
61 1.441 0.0236 0.0548 0.006 0.014 0.028 0.037 0.444 0.444 60 0 1 0 1299 21 21 39 POST /api/organizer/competition/[a-z0-9]+/finish
66 1.124 0.0170 0.0076 0.002 0.017 0.028 0.030 0.047 0.047 65 0 1 0 10675 39 161 188 POST /api/organizer/competitions/add HTTP/2.0
2 1.068 0.5340 0.1520 0.382 0.686 0.686 0.686 0.686 0.686 2 0 0 0 3164 1569 1582 1595 GET /api/admin/tenants/billing HTTP/2.0
12 0.412 0.0343 0.0404 0.000 0.040 0.046 0.153 0.153 0.153 7 0 5 0 1498 39 124 207 POST /api/admin/tenants/add HTTP/2.0
48 0.362 0.0075 0.0074 0.001 0.005 0.015 0.018 0.046 0.046 48 0 0 0 1596097 3087 33252 602067 GET /api/organizer/players HTTP/2.0
18 0.205 0.0114 0.0039 0.006 0.011 0.015 0.024 0.024 0.024 17 0 1 0 2693 39 149 163 POST /api/organizer/player/[a-z0-9]+/disqualified
1 0.001 0.0010 0.0000 0.001 0.001 0.001 0.001 0.001 0.001 1 0 0 0 177 177 177 177 GET /api/organizer/competitions HTTP/2.0
1 0.000 0.0000 0.0000 0.000 0.000 0.000 0.000 0.000 0.000 1 0 0 0 4868 4868 4868 4868 GET /css/app.83b4c321.css HTTP/2.0
1 0.000 0.0000 0.0000 0.000 0.000 0.000 0.000 0.000 0.000 1 0 0 0 479 479 479 479 GET /index.html HTTP/2.0
1 0.000 0.0000 0.0000 0.000 0.000 0.000 0.000 0.000 0.000 1 0 0 0 33294 33294 33294 33294 GET /js/app.3a4ec98c.js HTTP/2.0
mysql分離したら下がった
04:37:23.279077 PASSED: true 04:37:23.279080 SCORE: 4887 (+5491 -604(11%))
pprof.samples.1341.3f4825e6.pb.gz
(pprof) list competitionRankingHandler
Total: 1.73hrs
ROUTINE ======================== github.com/isucon/isucon12-qualify/webapp/go.competitionRankingHandler in /home/isucon/webapp/go/isuports.go
10.20ms 929.87s (flat, cum) 14.89% of Total
. . 1340:}
. . 1341:
. . 1342:// 参加者向けAPI
. . 1343:// GET /api/player/competition/:competition_id/ranking
. . 1344:// 大会ごとのランキングを取得する
10.20ms 10.20ms 1345:func competitionRankingHandler(c echo.Context) error {
. . 1346: ctx := context.Background()
. 2.35s 1347: v, err := parseViewer(c)
. . 1348: if err != nil {
. . 1349: return err
. . 1350: }
. . 1351: if v.role != RolePlayer {
. . 1352: return echo.NewHTTPError(http.StatusForbidden, "role player required")
. . 1353: }
. . 1354:
. . 1355: tenantDB, err := connectToTenantDB(v.tenantID)
. . 1356: if err != nil {
. . 1357: return err
. . 1358: }
. . 1359: defer tenantDB.Close()
. . 1360:
. 43.87s 1361: if err := authorizePlayer(ctx, tenantDB, v.playerID); err != nil {
. . 1362: return err
. . 1363: }
. . 1364:
. . 1365: competitionID := c.Param("competition_id")
. . 1366: if competitionID == "" {
. . 1367: return echo.NewHTTPError(http.StatusBadRequest, "competition_id is required")
. . 1368: }
. . 1369:
. . 1370: // 大会の存在確認
. 3.88s 1371: competition, err := retrieveCompetition(ctx, tenantDB, competitionID)
. . 1372: if err != nil {
. . 1373: if errors.Is(err, sql.ErrNoRows) {
. . 1374: return echo.NewHTTPError(http.StatusNotFound, "competition not found")
. . 1375: }
. . 1376: return fmt.Errorf("error retrieveCompetition: %w", err)
. . 1377: }
. . 1378:
. . 1379: now := time.Now().Unix()
. . 1380: var tenant TenantRow
. 1.89s 1381: if err := adminDB.GetContext(ctx, &tenant, "SELECT * FROM tenant WHERE id = ?", v.tenantID); err != nil {
. . 1382: return fmt.Errorf("error Select tenant: id=%d, %w", v.tenantID, err)
. . 1383: }
. . 1384:
. 1.39s 1385: if _, err := adminDB.ExecContext(
. . 1386: ctx,
. . 1387: "INSERT INTO visit_history (player_id, tenant_id, competition_id, created_at, updated_at) VALUES (?, ?, ?, ?, ?)",
. . 1388: v.playerID, tenant.ID, competitionID, now, now,
. . 1389: ); err != nil {
. . 1390: return fmt.Errorf(
. . 1391: "error Insert visit_history: playerID=%s, tenantID=%d, competitionID=%s, createdAt=%d, updatedAt=%d, %w",
. . 1392: v.playerID, tenant.ID, competitionID, now, now, err,
. . 1393: )
. . 1394: }
. . 1395:
. . 1396: var rankAfter int64
. . 1397: rankAfterStr := c.QueryParam("rank_after")
. . 1398: if rankAfterStr != "" {
. . 1399: if rankAfter, err = strconv.ParseInt(rankAfterStr, 10, 64); err != nil {
. . 1400: return fmt.Errorf("error strconv.ParseUint: rankAfterStr=%s, %w", rankAfterStr, err)
. . 1401: }
. . 1402: }
. . 1403:
. . 1404: // player_scoreを読んでいるときに更新が走ると不整合が起こるのでロックを取得する
. 862.39s 1405: fl, err := flockByTenantID(v.tenantID)
. . 1406: if err != nil {
. . 1407: return fmt.Errorf("error flockByTenantID: %w", err)
. . 1408: }
. . 1409: defer fl.Close()
. . 1410: pss := []PlayerScoreRow{}
. 8.76s 1411: if err := tenantDB.SelectContext(
. . 1412: ctx,
. . 1413: &pss,
. . 1414: "SELECT * FROM player_score WHERE tenant_id = ? AND competition_id = ? ORDER BY row_num DESC",
. . 1415: tenant.ID,
. . 1416: competitionID,
. . 1417: ); err != nil {
. . 1418: return fmt.Errorf("error Select player_score: tenantID=%d, competitionID=%s, %w", tenant.ID, competitionID, err)
. . 1419: }
. . 1420:
. . 1421: // Create a map for quick lookup
. . 1422: playerMap := make(map[string]PlayerRow)
. . 1423: if len(pss) != 0 {
. . 1424: // Collect all PlayerIDs
. . 1425: playerIDs := make([]string, len(pss))
. . 1426: for i, ps := range pss {
. . 1427: playerIDs[i] = ps.PlayerID
. . 1428: }
. . 1429:
. . 1430: // 参加者を取得する
. 10.20ms 1431: players := make([]PlayerRow, len(playerIDs))
. 51.02ms 1432: query, args, err := sqlx.In(
. . 1433: "SELECT * FROM player WHERE id IN (?)",
. . 1434: playerIDs,
. . 1435: )
. . 1436: if err != nil {
. . 1437: return fmt.Errorf("error building query for players: %w", err)
. . 1438: }
. . 1439: query = tenantDB.Rebind(query)
. 3.81s 1440: if err := tenantDB.SelectContext(ctx, &players, query, args...); err != nil && !errors.Is(err, sql.ErrNoRows) {
. 10.20ms 1441: return fmt.Errorf("error Select players: %w", err)
. . 1442: }
. . 1443:
. 10.20ms 1444: for _, player := range players {
. 40.82ms 1445: playerMap[player.ID] = player
. . 1446: }
. . 1447: }
. . 1448:
. . 1449: ranks := make([]CompetitionRank, 0, len(pss))
. 30.61ms 1450: scoredPlayerSet := make(map[string]struct{}, len(pss))
. . 1451: for _, ps := range pss {
. . 1452: // player_scoreが同一player_id内ではrow_numの降順でソートされているので
. . 1453: // 現れたのが2回目以降のplayer_idはより大きいrow_numでスコアが出ているとみなせる
. 30.61ms 1454: if _, ok := scoredPlayerSet[ps.PlayerID]; ok {
. . 1455: continue
. . 1456: }
. . 1457: scoredPlayerSet[ps.PlayerID] = struct{}{}
. . 1458: p, ok := playerMap[ps.PlayerID]
. . 1459: if !ok {
. . 1460: return fmt.Errorf("player not found: id=%s", ps.PlayerID)
. . 1461: }
. . 1462: ranks = append(ranks, CompetitionRank{
. . 1463: Score: ps.Score,
. . 1464: PlayerID: p.ID,
. . 1465: PlayerDisplayName: p.DisplayName,
. . 1466: RowNum: ps.RowNum,
. . 1467: })
. . 1468: }
. . 1469:
. 40.82ms 1470: sort.Slice(ranks, func(i, j int) bool {
. . 1471: if ranks[i].Score == ranks[j].Score {
. . 1472: return ranks[i].RowNum < ranks[j].RowNum
. . 1473: }
. . 1474: return ranks[i].Score > ranks[j].Score
. . 1475: })
. . 1476:
. . 1477: pagedRanks := make([]CompetitionRank, 0, 100)
. . 1478: for i, rank := range ranks {
. . 1479: if int64(i) < rankAfter {
. . 1480: continue
. . 1481: }
. . 1482: pagedRanks = append(pagedRanks, CompetitionRank{
. . 1483: Rank: int64(i + 1),
. . 1484: Score: rank.Score,
. . 1485: PlayerID: rank.PlayerID,
. . 1486: PlayerDisplayName: rank.PlayerDisplayName,
. . 1487: })
. . 1488: if len(pagedRanks) >= 100 {
. . 1489: break
. . 1490: }
. . 1491: }
. . 1492:
. . 1493: res := SuccessResult{
. . 1494: Status: true,
. . 1495: Data: CompetitionRankingHandlerResult{
. . 1496: Competition: CompetitionDetail{
. . 1497: ID: competition.ID,
. . 1498: Title: competition.Title,
. . 1499: IsFinished: competition.FinishedAt.Valid,
. . 1500: },
. . 1501: Ranks: pagedRanks,
. . 1502: },
. . 1503: }
. 1.32s 1504: return c.JSON(http.StatusOK, res)
. . 1505:}
. . 1506:
. . 1507:type CompetitionsHandlerResult struct {
. . 1508: Competitions []CompetitionDetail `json:"competitions"`
. . 1509:}
(pprof) list flockByTenantID
Total: 1.73hrs
ROUTINE ======================== github.com/isucon/isucon12-qualify/webapp/go.flockByTenantID in /home/isucon/webapp/go/isuports.go
0 1706.22s (flat, cum) 27.32% of Total
. . 433: return filepath.Join(tenantDBDir, fmt.Sprintf("%d.lock", id))
. . 434:}
. . 435:
. . 436:// 排他ロックする
. . 437:func flockByTenantID(tenantID int64) (io.Closer, error) {
. 10.20ms 438: p := lockFilePath(tenantID)
. . 439:
. . 440: fl := flock.New(p)
. 1706.21s 441: if err := fl.Lock(); err != nil {
. . 442: return nil, fmt.Errorf("error flock.Lock: path=%s, %w", p, err)
. . 443: }
. . 444: return fl, nil
. . 445:}
. . 446:
考察:
player_score
の読み書き時、テナントごとにファイルロックを取っている
player_score
の整合性のためっぽいのでtxを使って更新途中の状態を外部から見えないようにすれば良さそう
ちょいのび
05:29:17.445293 ERROR[0] load: load-validation: GET /api/player/competition/45c0c2910/ranking : expected([200]) != actual(500) tenant:isucon role:player playerID:63b36a24e competitionID:45c0c2910 rankAfter:
05:29:17.445317 ERROR[1] load: load-validation: GET /api/player/competitions : expected([200]) != actual(500) tenant:isucon role:player playerID:63c385ad1
05:29:17.445321 ERROR[2] load: load-validation: GET /api/player/competitions : expected([200]) != actual(500) tenant:isucon role:player playerID:63b0e0be4
05:29:17.445334 ERROR[3] load: load-validation: GET /api/player/competition/9fa537fd/ranking : expected([200]) != actual(500) tenant:isucon role:player playerID:617788cb9 competitionID:9fa537fd rankAfter:
05:29:17.445338 ERROR[4] load: load-validation: GET /api/player/competition/45c0c2910/ranking : expected([200]) != actual(500) tenant:isucon role:player playerID:638ff28e4 competitionID:45c0c2910 rankAfter:
05:29:17.445342 ERROR[5] load: load-validation: GET /api/player/competitions : expected([200]) != actual(500) tenant:isucon role:player playerID:638cf8d93
05:29:17.445345 ERROR[6] load: load-validation: GET /api/player/competitions : expected([200]) != actual(500) tenant:isucon role:player playerID:638b4b296
05:29:17.445348 ERROR[7] load: load-validation: GET /api/player/competition/9fa54688/ranking : expected([200]) != actual(500) tenant:isucon role:player playerID:61d799135 competitionID:9fa54688 rankAfter:
05:29:17.445351 ERROR[8] load: load-validation: GET /api/player/competition/174f069ca/ranking : expected([200]) != actual(500) tenant:isucon role:player playerID:63c11e74a competitionID:174f069ca rankAfter:
05:29:17.445660 Error 9 (Critical:0)
05:29:17.445668 PASSED: true
05:29:17.445671 SCORE: 5754 (+6323 -569(9%))
Top 20 Sort By Total
Count Total Mean Stddev Min P50.0 P90.0 P95.0 P99.0 Max 2xx 3xx 4xx 5xx TotalBytes MinBytes MeanBytes MaxBytes Request
1970 990.765 0.5029 0.8981 0.001 0.061 1.807 2.539 3.948 6.057 1920 0 50 0 1555196 0 789 2271 GET /api/player/player/[a-z0-9]+
1809 841.043 0.4649 0.9959 0.001 0.046 1.597 2.544 4.282 9.184 1760 0 44 5 15404251 0 8515 14665 GET /api/player/competition/[a-z0-9]+/ranking
83 195.647 2.3572 2.8088 0.002 1.299 5.207 8.000 14.273 14.273 76 0 7 0 4287 0 51 62 POST /api/organizer/competition/[a-z0-9]+/score
377 180.233 0.4781 1.0309 0.001 0.033 2.118 2.944 5.048 5.889 355 0 18 4 388489 0 1030 2913 GET /api/player/competitions HTTP/2.0
35 79.388 2.2682 3.7828 0.001 1.066 4.682 9.252 21.922 21.922 34 0 1 0 49934 0 1426 1551 GET /api/admin/tenants/billing?before=<num> HTTP/2.0
10 19.784 1.9784 1.0220 0.593 2.336 3.496 3.496 3.496 3.496 10 0 0 0 194363 12150 19436 26268 POST /api/organizer/players/add HTTP/2.0
2 3.145 1.5725 1.1785 0.394 2.751 2.751 2.751 2.751 2.751 2 0 0 0 3066 1532 1533 1534 GET /api/admin/tenants/billing HTTP/2.0
1 2.881 2.8810 0.0000 2.881 2.881 2.881 2.881 2.881 2.881 1 0 0 0 55 55 55 55 POST /initialize HTTP/2.0
63 1.604 0.0255 0.0455 0.004 0.014 0.037 0.061 0.350 0.350 62 0 1 0 10137 39 160 183 POST /api/organizer/competitions/add HTTP/2.0
33 1.426 0.0432 0.0468 0.002 0.026 0.111 0.127 0.209 0.209 33 0 0 0 58371 320 1768 4666 GET /api/organizer/billing HTTP/2.0
55 1.229 0.0223 0.0210 0.004 0.014 0.041 0.064 0.134 0.134 54 0 1 0 1173 21 21 39 POST /api/organizer/competition/[a-z0-9]+/finish
46 0.706 0.0153 0.0225 0.002 0.007 0.035 0.057 0.108 0.108 46 0 0 0 2706343 3088 58833 602067 GET /api/organizer/players HTTP/2.0
12 0.517 0.0431 0.0545 0.001 0.028 0.111 0.194 0.194 0.194 7 0 5 0 1462 39 121 189 POST /api/admin/tenants/add HTTP/2.0
17 0.226 0.0133 0.0091 0.001 0.012 0.026 0.043 0.043 0.043 16 0 1 0 2531 39 148 162 POST /api/organizer/player/[a-z0-9]+/disqualified
1 0.001 0.0010 0.0000 0.001 0.001 0.001 0.001 0.001 0.001 1 0 0 0 177 177 177 177 GET /api/organizer/competitions HTTP/2.0
1 0.000 0.0000 0.0000 0.000 0.000 0.000 0.000 0.000 0.000 1 0 0 0 33294 33294 33294 33294 GET /js/app.3a4ec98c.js HTTP/2.0
1 0.000 0.0000 0.0000 0.000 0.000 0.000 0.000 0.000 0.000 1 0 0 0 479 479 479 479 GET /index.html HTTP/2.0
1 0.000 0.0000 0.0000 0.000 0.000 0.000 0.000 0.000 0.000 1 0 0 0 4868 4868 4868 4868 GET /css/app.83b4c321.css HTTP/2.0
$ journalctl -xfu isuports.service | grep '"status":500'
Hint: You are currently not seeing messages from other users and the system.
Users in groups 'adm', 'systemd-journal' can see all messages.
Pass -q to turn off this notice.
Jul 20 05:29:20 ip-192-168-0-11 docker[183090]: webapp-webapp-1 | {"time":"2024-07-20T05:29:20.447149568Z","id":"","remote_ip":"127.0.0.1","host":"isucon.t.isucon.pw","method":"GET","uri":"/api/player/competition/45c0c2910/ranking","user_agent":"isucandar","status":500,"error":"error Select players: too many SQL variables","latency":6610180087,"latency_human":"6.610180087s","bytes_in":0,"bytes_out":39}
Jul 20 05:35:29 ip-192-168-0-11 docker[187192]: webapp-webapp-1 | {"time":"2024-07-20T05:35:29.909071587Z","id":"","remote_ip":"127.0.0.1","host":"isucon.t.isucon.pw","method":"GET","uri":"/api/player/competitions","user_agent":"isucandar","status":500,"error":"error retrievePlayer from viewer: error Select player: id=63c11e74a, database is locked","latency":5041518205,"latency_human":"5.041518205s","bytes_in":0,"bytes_out":39}
Jul 20 05:35:29 ip-192-168-0-11 docker[187192]: webapp-webapp-1 | {"time":"2024-07-20T05:35:29.909801761Z","id":"","remote_ip":"127.0.0.1","host":"isucon.t.isucon.pw","method":"GET","uri":"/api/player/competition/9fa53609/ranking","user_agent":"isucandar","status":500,"error":"error retrieveCompetition: error Select competition: id=9fa53609, database is locked","latency":5262585507,"latency_human":"5.262585507s","bytes_in":0,"bytes_out":39}
Jul 20 05:35:29 ip-192-168-0-11 docker[187192]: webapp-webapp-1 | {"time":"2024-07-20T05:35:29.909995946Z","id":"","remote_ip":"127.0.0.1","host":"isucon.t.isucon.pw","method":"GET","uri":"/api/player/competition/9fa53609/ranking","user_agent":"isucandar","status":500,"error":"error retrieveCompetition: error Select competition: id=9fa53609, database is locked","latency":5091302669,"latency_human":"5.091302669s","bytes_in":0,"bytes_out":39}
Jul 20 05:35:30 ip-192-168-0-11 docker[187192]: webapp-webapp-1 | {"time":"2024-07-20T05:35:30.315509762Z","id":"","remote_ip":"127.0.0.1","host":"isucon.t.isucon.pw","method":"GET","uri":"/api/player/competition/9fa53609/ranking","user_agent":"isucandar","status":500,"error":"error retrievePlayer from viewer: error Select player: id=5e7481f7f, database is locked","latency":5027939828,"latency_human":"5.027939828s","bytes_in":0,"bytes_out":39}
Jul 20 05:35:30 ip-192-168-0-11 docker[187192]: webapp-webapp-1 | {"time":"2024-07-20T05:35:30.420697282Z","id":"","remote_ip":"127.0.0.1","host":"isucon.t.isucon.pw","method":"GET","uri":"/api/player/competition/9fa53609/ranking","user_agent":"isucandar","status":500,"error":"error retrievePlayer from viewer: error Select player: id=5e67936a9, database is locked","latency":5033755501,"latency_human":"5.033755501s","bytes_in":0,"bytes_out":39}
Jul 20 05:35:43 ip-192-168-0-11 docker[187192]: webapp-webapp-1 | {"time":"2024-07-20T05:35:43.706768939Z","id":"","remote_ip":"127.0.0.1","host":"isucon.t.isucon.pw","method":"GET","uri":"/api/player/competition/597488a14/ranking","user_agent":"isucandar","status":500,"error":"error Select players: too many SQL variables","latency":5446674321,"latency_human":"5.446674321s","bytes_in":0,"bytes_out":39}
Jul 20 05:35:49 ip-192-168-0-11 docker[187192]: webapp-webapp-1 | {"time":"2024-07-20T05:35:49.03341277Z","id":"","remote_ip":"127.0.0.1","host":"isucon.t.isucon.pw","method":"GET","uri":"/api/player/competition/9fa5448f/ranking","user_agent":"isucandar","status":500,"error":"error retrievePlayer from viewer: error Select player: id=63aefae59, database is locked","latency":5945862649,"latency_human":"5.945862649s","bytes_in":0,"bytes_out":39}
Jul 20 05:35:49 ip-192-168-0-11 docker[187192]: webapp-webapp-1 | {"time":"2024-07-20T05:35:49.040701225Z","id":"","remote_ip":"127.0.0.1","host":"isucon.t.isucon.pw","method":"GET","uri":"/api/player/competitions","user_agent":"isucandar","status":500,"error":"error retrievePlayer from viewer: error Select player: id=638cf8d93, database is locked","latency":6155514236,"latency_human":"6.155514236s","bytes_in":0,"bytes_out":39}
Jul 20 05:35:50 ip-192-168-0-11 docker[187192]: webapp-webapp-1 | {"time":"2024-07-20T05:35:50.052690751Z","id":"","remote_ip":"127.0.0.1","host":"admin.t.isucon.pw","method":"GET","uri":"/api/admin/tenants/billing?before=8","user_agent":"isucandar","status":500,"error":"failed to billingReportByCompetition: error retrieveCompetition: error Select competition: id=174f069ca, database is locked","latency":12064860818,"latency_human":"12.064860818s","bytes_in":0,"bytes_out":39}
Jul 20 05:35:50 ip-192-168-0-11 docker[187192]: webapp-webapp-1 | {"time":"2024-07-20T05:35:50.448532372Z","id":"","remote_ip":"127.0.0.1","host":"isucon.t.isucon.pw","method":"GET","uri":"/api/player/competition/9fa5448f/ranking","user_agent":"isucandar","status":500,"error":"error retrievePlayer from viewer: error Select player: id=63aefae59, database is locked","latency":5023788833,"latency_human":"5.023788833s","bytes_in":0,"bytes_out":39}
Jul 20 05:35:50 ip-192-168-0-11 docker[187192]: webapp-webapp-1 | {"time":"2024-07-20T05:35:50.457978765Z","id":"","remote_ip":"127.0.0.1","host":"isucon.t.isucon.pw","method":"GET","uri":"/api/player/competition/9fa5448f/ranking","user_agent":"isucandar","status":500,"error":"error retrievePlayer from viewer: error Select player: id=62c46c835, database is locked","latency":7168029263,"latency_human":"7.168029263s","bytes_in":0,"bytes_out":39}
Jul 20 05:35:50 ip-192-168-0-11 docker[187192]: webapp-webapp-1 | {"time":"2024-07-20T05:35:50.458360104Z","id":"","remote_ip":"127.0.0.1","host":"isucon.t.isucon.pw","method":"GET","uri":"/api/player/competition/9fa5448f/ranking","user_agent":"isucandar","status":500,"error":"error retrievePlayer from viewer: error Select player: id=638b4b296, database is locked","latency":6688165746,"latency_human":"6.688165746s","bytes_in":0,"bytes_out":39}
Jul 20 05:35:50 ip-192-168-0-11 docker[187192]: webapp-webapp-1 | {"time":"2024-07-20T05:35:50.478410693Z","id":"","remote_ip":"127.0.0.1","host":"j-jpeqh-28.t.isucon.pw","method":"GET","uri":"/api/player/player/39b353f85","user_agent":"isucandar","status":500,"error":"error Select competitions: database is locked","latency":6183954944,"latency_human":"6.183954944s","bytes_in":0,"bytes_out":39}
Jul 20 05:36:04 ip-192-168-0-11 docker[187192]: webapp-webapp-1 | {"time":"2024-07-20T05:36:04.82557865Z","id":"","remote_ip":"127.0.0.1","host":"n-zcxduo-1721453720.t.isucon.pw","method":"GET","uri":"/api/player/competition/9fa53fe9/ranking?rank_after=30","user_agent":"isucandar","status":500,"error":"write tcp 127.0.0.1:3000-\u003e127.0.0.1:51584: write: broken pipe","latency":206122236,"latency_human":"206.122236ms","bytes_in":0,"bytes_out":3969}
Jul 20 05:36:04 ip-192-168-0-11 docker[187192]: webapp-webapp-1 | {"time":"2024-07-20T05:36:04.827068432Z","id":"","remote_ip":"127.0.0.1","host":"n-zcxduo-1721453720.t.isucon.pw","method":"GET","uri":"/api/player/competition/9fa54e13/ranking?rank_after=95","user_agent":"isucandar","status":500,"error":"write tcp 127.0.0.1:3000-\u003e127.0.0.1:51652: write: broken pipe","latency":151877100,"latency_human":"151.8771ms","bytes_in":0,"bytes_out":3969}
Jul 20 05:36:04 ip-192-168-0-11 docker[187192]: webapp-webapp-1 | {"time":"2024-07-20T05:36:04.86413026Z","id":"","remote_ip":"127.0.0.1","host":"n-zcxduo-1721453720.t.isucon.pw","method":"GET","uri":"/api/player/competition/9fa53c18/ranking","user_agent":"isucandar","status":500,"error":"write tcp 127.0.0.1:3000-\u003e127.0.0.1:51716: write: broken pipe","latency":146610303,"latency_human":"146.610303ms","bytes_in":0,"bytes_out":3969}
Jul 20 05:36:04 ip-192-168-0-11 docker[187192]: webapp-webapp-1 | {"time":"2024-07-20T05:36:04.879781946Z","id":"","remote_ip":"127.0.0.1","host":"n-zcxduo-1721453720.t.isucon.pw","method":"GET","uri":"/api/player/competition/9fa55869/ranking","user_agent":"isucandar","status":500,"error":"write tcp 127.0.0.1:3000-\u003e127.0.0.1:49806: write: broken pipe","latency":1671036345,"latency_human":"1.671036345s","bytes_in":0,"bytes_out":3969}
Jul 20 05:36:05 ip-192-168-0-11 docker[187192]: webapp-webapp-1 | {"time":"2024-07-20T05:36:05.40013918Z","id":"","remote_ip":"127.0.0.1","host":"isucon.t.isucon.pw","method":"GET","uri":"/api/player/competition/59cb9aad2/ranking","user_agent":"isucandar","status":500,"error":"error Select players: too many SQL variables","latency":4251024589,"latency_human":"4.251024589s","bytes_in":0,"bytes_out":39}
Jul 20 05:36:08 ip-192-168-0-11 docker[187192]: webapp-webapp-1 | {"time":"2024-07-20T05:36:08.121174483Z","id":"","remote_ip":"127.0.0.1","host":"isucon.t.isucon.pw","method":"GET","uri":"/api/player/competition/9fa55536/ranking","user_agent":"isucandar","status":500,"error":"error Select player_score: tenantID=1, competitionID=9fa55536, database is locked","latency":6333916042,"latency_human":"6.333916042s","bytes_in":0,"bytes_out":39}
Jul 20 05:36:08 ip-192-168-0-11 docker[187192]: webapp-webapp-1 | {"time":"2024-07-20T05:36:08.213766608Z","id":"","remote_ip":"127.0.0.1","host":"admin.t.isucon.pw","method":"GET","uri":"/api/admin/tenants/billing?before=8","user_agent":"isucandar","status":500,"error":"failed to billingReportByCompetition: error Select count player_score: tenantID=1, competitionID=31a456f7b, database is locked","latency":18059786552,"latency_human":"18.059786552s","bytes_in":0,"bytes_out":39}
06:19:22.888967 ERROR[0] load: load-validation: GET /api/player/competition/9fa54247/ranking : expected([200]) != actual(500) tenant:aqu-az-7 role:player playerID:9fa53e9a competitionID:9fa54247 rankAfter:
06:19:22.888981 ERROR[1] load: load-validation: GET /api/player/player/9fa52cbb : expected([200]) != actual(500) tenant:aqu-az-7 role:player playerID:9fa52dc0 playerID:9fa52cbb
06:19:22.888985 ERROR[2] load: load-validation: GET /api/player/player/9fa52cbe : expected([200]) != actual(500) tenant:aqu-az-7 role:player playerID:9fa52dc3 playerID:9fa52cbe
06:19:22.888988 ERROR[3] load: load-validation: GET /api/player/competition/9fa54247/ranking : expected([200]) != actual(500) tenant:aqu-az-7 role:player playerID:9fa52d5b competitionID:9fa54247 rankAfter:
06:19:22.889291 Error 4 (Critical:0)
06:19:22.889341 PASSED: true
06:19:22.889350 SCORE: 6176 (+6433 -257(4%))
Top 20 Sort By Total
Count Total Mean Stddev Min P50.0 P90.0 P95.0 P99.0 Max 2xx 3xx 4xx 5xx TotalBytes MinBytes MeanBytes MaxBytes Request
3872 1710.550 0.4418 0.8367 0.001 0.043 1.543 2.269 3.861 6.601 3753 0 112 7 3058318 0 789 2300 GET /api/player/player/[a-z0-9]+
3867 1551.216 0.4011 0.8783 0.001 0.033 1.517 2.382 3.695 9.189 3781 0 78 8 32535726 0 8413 14780 GET /api/player/competition/[a-z0-9]+/ranking
171 351.386 2.0549 2.5081 0.001 1.192 4.634 5.883 13.532 13.978 154 0 17 0 8682 0 50 62 POST /api/organizer/competition/[a-z0-9]+/score
724 329.109 0.4546 0.9133 0.001 0.025 1.846 2.718 3.756 5.152 689 0 33 2 750927 0 1037 2925 GET /api/player/competitions HTTP/2.0
71 153.632 2.1638 3.4231 0.000 1.175 3.101 10.496 20.512 20.512 68 0 2 1 99606 0 1402 1551 GET /api/admin/tenants/billing?before=<num> HTTP/2.0
22 47.909 2.1777 0.9986 0.636 2.398 3.449 3.647 4.153 4.153 21 0 1 0 412306 0 18741 26268 POST /api/organizer/players/add HTTP/2.0
71 27.243 0.3837 2.8571 0.002 0.023 0.092 0.189 24.283 24.283 71 0 0 0 130409 320 1836 5860 GET /api/organizer/billing HTTP/2.0
4 5.862 1.4655 1.0956 0.372 2.222 2.854 2.854 2.854 2.854 4 0 0 0 6251 1549 1562 1575 GET /api/admin/tenants/billing HTTP/2.0
2 5.822 2.9110 0.3730 2.538 3.284 3.284 3.284 3.284 3.284 2 0 0 0 110 55 55 55 POST /initialize HTTP/2.0
116 2.966 0.0256 0.0874 0.001 0.015 0.032 0.045 0.073 0.955 114 0 2 0 2472 21 21 39 POST /api/organizer/competition/[a-z0-9]+/finish
130 2.720 0.0209 0.0312 0.002 0.015 0.027 0.042 0.120 0.342 128 0 2 0 21082 39 162 189 POST /api/organizer/competitions/add HTTP/2.0
94 1.005 0.0107 0.0184 0.002 0.005 0.031 0.039 0.154 0.154 94 0 0 0 4314019 2466 45893 602067 GET /api/organizer/players HTTP/2.0
24 0.901 0.0375 0.0399 0.001 0.031 0.104 0.125 0.126 0.126 14 0 10 0 2982 39 124 201 POST /api/admin/tenants/add HTTP/2.0
35 0.541 0.0155 0.0112 0.001 0.012 0.032 0.034 0.064 0.064 33 0 2 0 5236 39 149 165 POST /api/organizer/player/[a-z0-9]+/disqualified
2 0.002 0.0010 0.0000 0.001 0.001 0.001 0.001 0.001 0.001 2 0 0 0 354 177 177 177 GET /api/organizer/competitions HTTP/2.0
2 0.000 0.0000 0.0000 0.000 0.000 0.000 0.000 0.000 0.000 2 0 0 0 66588 33294 33294 33294 GET /js/app.3a4ec98c.js HTTP/2.0
2 0.000 0.0000 0.0000 0.000 0.000 0.000 0.000 0.000 0.000 2 0 0 0 9736 4868 4868 4868 GET /css/app.83b4c321.css HTTP/2.0
2 0.000 0.0000 0.0000 0.000 0.000 0.000 0.000 0.000 0.000 2 0 0 0 958 479 479 479 GET /index.html HTTP/2.0
エラー内訳
Jul 20 06:18:57 ip-192-168-0-11 docker[221366]: webapp-webapp-1 | {"time":"2024-07-20T06:18:57.449972365Z","id":"","remote_ip":"127.0.0.1","host":"aqu-az-7.t.isucon.pw","method":"GET","uri":"/api/player/competition/9fa54247/ranking","user_agent":"isucandar","status":500,"error":"error retrievePlayer from viewer: error Select player: id=9fa53e9a, database is locked","latency":5033420961,"latency_human":"5.033420961s","bytes_in":0,"bytes_out":39}
Jul 20 06:18:57 ip-192-168-0-11 docker[221366]: webapp-webapp-1 | {"time":"2024-07-20T06:18:57.550740902Z","id":"","remote_ip":"127.0.0.1","host":"aqu-az-7.t.isucon.pw","method":"GET","uri":"/api/player/player/9fa52cbb","user_agent":"isucandar","status":500,"error":"error Select competitions: database is locked","latency":5372845321,"latency_human":"5.372845321s","bytes_in":0,"bytes_out":39}
Jul 20 06:18:59 ip-192-168-0-11 docker[221366]: webapp-webapp-1 | {"time":"2024-07-20T06:18:59.564939756Z","id":"","remote_ip":"127.0.0.1","host":"aqu-az-7.t.isucon.pw","method":"GET","uri":"/api/player/player/9fa52cbe","user_agent":"isucandar","status":500,"error":"error retrievePlayer from viewer: error Select player: id=9fa52dc3, database is locked","latency":5055564436,"latency_human":"5.055564436s","bytes_in":0,"bytes_out":39}
Jul 20 06:18:59 ip-192-168-0-11 docker[221366]: webapp-webapp-1 | {"time":"2024-07-20T06:18:59.972224975Z","id":"","remote_ip":"127.0.0.1","host":"aqu-az-7.t.isucon.pw","method":"GET","uri":"/api/player/competition/9fa54247/ranking","user_agent":"isucandar","status":500,"error":"error retrieveCompetition: error Select competition: id=9fa54247, database is locked","latency":5066155983,"latency_human":"5.066155983s","bytes_in":0,"bytes_out":39}
やっとこと
06:43:03.289076 PASSED: true
06:43:03.289080 SCORE: 11123 (+14260 -3137(22%))
バルクインサートはcompetitionScoreHandler関数のplayer_scoreをした
@pinkumohikan これ見てほしい
aptのデイリーアップデートがありCPU食ってた なくなったときのscore
06:53:36.352308 PASSED: true 06:53:36.352311 SCORE: 23600 (+24081 -481(2%))
アプリケーションが重い
やること
Top 20 Sort By Total
Count Total Mean Stddev Min P50.0 P90.0 P95.0 P99.0 Max 2xx 3xx 4xx 5xx TotalBytes MinBytes MeanBytes MaxBytes Request
10356 3191.960 0.3082 0.3607 0.003 0.210 0.600 0.885 1.761 10.219 10126 0 230 0 28647583 0 2766 14739 GET /api/player/competition/[a-z0-9]+/ranking
102 1159.340 11.3661 8.6129 0.001 12.063 22.415 23.828 28.428 30.000 69 0 33 0 3930 0 38 62 POST /api/organizer/competition/[a-z0-9]+/score
4844 760.775 0.1571 0.2332 0.002 0.085 0.341 0.532 1.257 3.040 4731 0 113 0 2106253 0 434 2291 GET /api/player/player/[a-z0-9]+
5175 640.495 0.1238 0.1684 0.002 0.074 0.264 0.389 0.846 2.412 5142 0 33 0 1777225 0 343 2774 GET /api/player/competitions HTTP/2.0
35 336.832 9.6238 5.0094 1.086 9.406 16.775 19.174 21.197 21.197 34 0 1 0 746619 0 21331 26268 POST /api/organizer/players/add HTTP/2.0
352 63.004 0.1790 0.3704 0.001 0.023 0.586 1.008 1.796 2.275 351 0 1 0 477737 0 1357 1615 GET /api/admin/tenants/billing?before=<num> HTTP/2.0
46 37.747 0.8206 3.8733 0.002 0.135 0.736 0.969 26.717 26.717 46 0 0 0 39407 323 856 5860 GET /api/organizer/billing HTTP/2.0
57 13.802 0.2421 0.3750 0.005 0.168 0.449 0.703 2.728 2.728 56 0 1 0 1215 21 21 39 POST /api/organizer/competition/[a-z0-9]+/finish
90 11.175 0.1242 0.1236 0.008 0.098 0.210 0.266 0.898 0.898 89 0 1 0 14771 39 164 199 POST /api/organizer/competitions/add HTTP/2.0
1 9.853 9.8530 0.0000 9.853 9.853 9.853 9.853 9.853 9.853 1 0 0 0 55 55 55 55 POST /initialize HTTP/2.0
82 6.574 0.0802 0.0871 0.002 0.056 0.211 0.245 0.496 0.496 82 0 0 0 2931114 4266 35745 624915 GET /api/organizer/players HTTP/2.0
28 3.660 0.1307 0.2262 0.006 0.045 0.610 0.698 0.937 0.937 28 0 0 0 44140 1525 1576 1655 GET /api/admin/tenants/billing HTTP/2.0
38 0.655 0.0172 0.0399 0.000 0.004 0.036 0.158 0.194 0.194 33 0 5 0 6376 39 167 213 POST /api/admin/tenants/add HTTP/2.0
9 0.349 0.0388 0.0385 0.001 0.015 0.106 0.106 0.106 0.106 8 0 1 0 1292 39 143 160 POST /api/organizer/player/[a-z0-9]+/disqualified
1 0.001 0.0010 0.0000 0.001 0.001 0.001 0.001 0.001 0.001 1 0 0 0 177 177 177 177 GET /api/organizer/competitions HTTP/2.0
1 0.000 0.0000 0.0000 0.000 0.000 0.000 0.000 0.000 0.000 1 0 0 0 33294 33294 33294 33294 GET /js/app.3a4ec98c.js HTTP/2.0
1 0.000 0.0000 0.0000 0.000 0.000 0.000 0.000 0.000 0.000 1 0 0 0 4868 4868 4868 4868 GET /css/app.83b4c321.css HTTP/2.0
1 0.000 0.0000 0.0000 0.000 0.000 0.000 0.000 0.000 0.000 1 0 0 0 479 479 479 479 GET /index.html HTTP/2.0
07:02:21.702099 Error 0 (Critical:0)
07:02:21.702103 PASSED: true
07:02:21.702106 SCORE: 20519 (+20519 0(0%))
Top 20 Sort By Total
Count Total Mean Stddev Min P50.0 P90.0 P95.0 P99.0 Max 2xx 3xx 4xx 5xx TotalBytes MinBytes MeanBytes MaxBytes Request
15637 5435.307 0.3476 0.4674 0.001 0.226 0.664 1.013 2.469 8.597 15389 0 248 0 70147206 0 4485 14771 GET /api/player/competition/[a-z0-9]+/ranking
12231 2361.088 0.1930 0.2902 0.001 0.117 0.382 0.575 1.343 7.210 12117 0 114 0 6227674 0 509 2468 GET /api/player/player/[a-z0-9]+
229 1581.803 6.9074 6.2045 0.001 5.617 15.641 18.039 20.903 27.553 165 0 63 1 9789 0 42 62 POST /api/organizer/competition/[a-z0-9]+/score
6614 955.353 0.1444 0.1928 0.001 0.095 0.293 0.415 0.926 4.396 6569 0 45 0 3234707 0 489 2928 GET /api/player/competitions HTTP/2.0
60 243.659 4.0610 3.7494 0.102 3.559 9.717 11.876 15.242 15.242 58 0 2 0 1198756 0 19979 26716 POST /api/organizer/players/add HTTP/2.0
471 115.909 0.2461 0.4205 0.001 0.113 0.589 0.810 1.954 5.419 469 0 2 0 638045 0 1354 1643 GET /api/admin/tenants/billing?before=<num> HTTP/2.0
113 91.501 0.8097 3.6345 0.002 0.194 0.866 1.319 27.537 27.940 113 0 0 0 114226 317 1010 6240 GET /api/organizer/billing HTTP/2.0
141 34.581 0.2453 0.3549 0.001 0.171 0.431 0.555 1.414 3.619 137 0 4 0 3033 21 21 39 POST /api/organizer/competition/[a-z0-9]+/finish
193 31.632 0.1639 0.1735 0.001 0.117 0.319 0.423 1.084 1.368 188 0 5 0 31158 0 161 188 POST /api/organizer/competitions/add HTTP/2.0
4 31.319 7.8297 0.5490 7.391 7.756 8.748 8.748 8.748 8.748 4 0 0 0 220 55 55 55 POST /initialize HTTP/2.0
169 20.589 0.1218 0.1326 0.002 0.084 0.240 0.297 0.748 1.243 168 0 1 0 6027782 0 35667 628051 GET /api/organizer/players HTTP/2.0
38 7.967 0.2097 0.2231 0.004 0.096 0.643 0.673 0.680 0.680 38 0 0 0 60004 1545 1579 1616 GET /api/admin/tenants/billing HTTP/2.0
77 2.241 0.0291 0.0611 0.000 0.004 0.095 0.168 0.338 0.338 57 0 20 0 11376 39 147 207 POST /api/admin/tenants/add HTTP/2.0
25 1.668 0.0667 0.1013 0.002 0.042 0.164 0.304 0.450 0.450 21 0 4 0 3467 39 138 165 POST /api/organizer/player/[a-z0-9]+/disqualified
2 0.002 0.0010 0.0000 0.001 0.001 0.001 0.001 0.001 0.001 2 0 0 0 354 177 177 177 GET /api/organizer/competitions HTTP/2.0
4 0.000 0.0000 0.0000 0.000 0.000 0.000 0.000 0.000 0.000 4 0 0 0 1916 479 479 479 GET /index.html HTTP/2.0
4 0.000 0.0000 0.0000 0.000 0.000 0.000 0.000 0.000 0.000 4 0 0 0 133176 33294 33294 33294 GET /js/app.3a4ec98c.js HTTP/2.0
4 0.000 0.0000 0.0000 0.000 0.000 0.000 0.000 0.000 0.000 4 0 0 0 19472 4868 4868 4868 GET /css/app.83b4c321.css HTTP/2.0
(pprof) list competitionRankingHandler
Total: 4.33hrs
ROUTINE ======================== github.com/isucon/isucon12-qualify/webapp/go.competitionRankingHandler in /home/isucon/webapp/go/isuports.go
362.50ms 2741.14s (flat, cum) 17.58% of Total
. . 1320:}
. . 1321:
. . 1322:// 参加者向けAPI
. . 1323:// GET /api/player/competition/:competition_id/ranking
. . 1324:// 大会ごとのランキングを取得する
362.50ms 362.50ms 1325:func competitionRankingHandler(c echo.Context) error {
. . 1326: ctx := context.Background()
. 833.31s 1327: v, err := parseViewer(c)
. . 1328: if err != nil {
. . 1329: return err
. . 1330: }
. . 1331: if v.role != RolePlayer {
. . 1332: return echo.NewHTTPError(http.StatusForbidden, "role player required")
. . 1333: }
. . 1334:
. 214.66s 1335: tenantDB, err := connectToTenantDB(v.tenantID)
. . 1336: if err != nil {
. . 1337: return err
. . 1338: }
. . 1339: defer tenantDB.Close()
. . 1340:
. 49.11s 1341: if err := authorizePlayer(ctx, tenantDB, v.playerID); err != nil {
. . 1342: return err
. . 1343: }
. . 1344:
. . 1345: competitionID := c.Param("competition_id")
. . 1346: if competitionID == "" {
. . 1347: return echo.NewHTTPError(http.StatusBadRequest, "competition_id is required")
. . 1348: }
. . 1349:
. . 1350: // 大会の存在確認
. 4.04s 1351: competition, err := retrieveCompetition(ctx, tenantDB, competitionID)
. . 1352: if err != nil {
. . 1353: if errors.Is(err, sql.ErrNoRows) {
. . 1354: return echo.NewHTTPError(http.StatusNotFound, "competition not found")
. . 1355: }
. . 1356: return fmt.Errorf("error retrieveCompetition: %w", err)
. . 1357: }
. . 1358:
. 25ms 1359: now := time.Now().Unix()
. . 1360: var tenant TenantRow
. 794.31s 1361: if err := adminDB.GetContext(ctx, &tenant, "SELECT * FROM tenant WHERE id = ?", v.tenantID); err != nil {
. . 1362: return fmt.Errorf("error Select tenant: id=%d, %w", v.tenantID, err)
. . 1363: }
. . 1364:
. 723.21s 1365: if _, err := adminDB.ExecContext(
. . 1366: ctx,
. . 1367: "INSERT INTO visit_history (player_id, tenant_id, competition_id, created_at, updated_at) VALUES (?, ?, ?, ?, ?)",
. 25ms 1368: v.playerID, tenant.ID, competitionID, now, now,
. . 1369: ); err != nil {
. . 1370: return fmt.Errorf(
. . 1371: "error Insert visit_history: playerID=%s, tenantID=%d, competitionID=%s, createdAt=%d, updatedAt=%d, %w",
. . 1372: v.playerID, tenant.ID, competitionID, now, now, err,
. . 1373: )
. . 1374: }
. . 1375:
. . 1376: var rankAfter int64
. . 1377: rankAfterStr := c.QueryParam("rank_after")
. . 1378: if rankAfterStr != "" {
. . 1379: if rankAfter, err = strconv.ParseInt(rankAfterStr, 10, 64); err != nil {
. . 1380: return fmt.Errorf("error strconv.ParseUint: rankAfterStr=%s, %w", rankAfterStr, err)
. . 1381: }
. . 1382: }
. . 1383:
. 1s 1384: tx, err := tenantDB.Beginx()
. . 1385: if err != nil {
. . 1386: return fmt.Errorf("error begin transaction failed: %w", err)
. . 1387: }
. . 1388:
. . 1389: pss := []PlayerScoreRow{}
. 85.55s 1390: if err := tx.SelectContext(
. . 1391: ctx,
. . 1392: &pss,
. . 1393: "SELECT * FROM player_score WHERE tenant_id = ? AND competition_id = ? ORDER BY row_num DESC",
. . 1394: tenant.ID,
. . 1395: competitionID,
. . 1396: ); err != nil {
. . 1397: _ = tx.Rollback()
. . 1398: return fmt.Errorf("error Select player_score: tenantID=%d, competitionID=%s, %w", tenant.ID, competitionID, err)
. . 1399: }
. . 1400:
. . 1401: // Create a map for quick lookup
. . 1402: playerMap := make(map[string]PlayerRow)
. . 1403: if len(pss) != 0 {
. . 1404: // Collect all PlayerIDs
. . 1405: playerIDs := make([]string, len(pss))
. . 1406: for i, ps := range pss {
. . 1407: playerIDs[i] = ps.PlayerID
. . 1408: }
. 750ms 1409: slices.Sort(playerIDs)
. 12.50ms 1410: uniquePlayerIDs := slices.Compact(playerIDs)
. . 1411:
. . 1412: // 参加者を取得する
. . 1413: players := make([]PlayerRow, len(uniquePlayerIDs))
. 125ms 1414: query, args, err := sqlx.In(
. . 1415: "SELECT * FROM player WHERE id IN (?)",
. . 1416: uniquePlayerIDs,
. . 1417: )
. . 1418: if err != nil {
. . 1419: _ = tx.Rollback()
. . 1420: return fmt.Errorf("error building query for players: %w", err)
. . 1421: }
. 25ms 1422: query = tx.Rebind(query)
. 17.93s 1423: if err := tx.SelectContext(ctx, &players, query, args...); err != nil && !errors.Is(err, sql.ErrNoRows) {
. . 1424: _ = tx.Rollback()
. . 1425: return fmt.Errorf("error Select players: %w", err)
. . 1426: }
. . 1427:
. . 1428: for _, player := range players {
. 375ms 1429: playerMap[player.ID] = player
. . 1430: }
. . 1431: }
. . 1432:
. 1.10s 1433: if err = tx.Commit(); err != nil {
. . 1434: _ = tx.Rollback()
. . 1435: return fmt.Errorf("error commit transaction failed: %w", err)
. . 1436: }
. . 1437:
. . 1438: ranks := make([]CompetitionRank, 0, len(pss))
. 50ms 1439: scoredPlayerSet := make(map[string]struct{}, len(pss))
. . 1440: for _, ps := range pss {
. . 1441: // player_scoreが同一player_id内ではrow_numの降順でソートされているので
. . 1442: // 現れたのが2回目以降のplayer_idはより大きいrow_numでスコアが出ているとみなせる
. 112.50ms 1443: if _, ok := scoredPlayerSet[ps.PlayerID]; ok {
. . 1444: continue
. . 1445: }
. 25ms 1446: scoredPlayerSet[ps.PlayerID] = struct{}{}
. 12.50ms 1447: p, ok := playerMap[ps.PlayerID]
. . 1448: if !ok {
. . 1449: return fmt.Errorf("player not found: id=%s", ps.PlayerID)
. . 1450: }
. . 1451: ranks = append(ranks, CompetitionRank{
. . 1452: Score: ps.Score,
. . 1453: PlayerID: p.ID,
. . 1454: PlayerDisplayName: p.DisplayName,
. . 1455: RowNum: ps.RowNum,
. . 1456: })
. . 1457: }
. . 1458:
. 150ms 1459: sort.Slice(ranks, func(i, j int) bool {
. . 1460: if ranks[i].Score == ranks[j].Score {
. . 1461: return ranks[i].RowNum < ranks[j].RowNum
. . 1462: }
. . 1463: return ranks[i].Score > ranks[j].Score
. . 1464: })
. . 1465:
. 25ms 1466: pagedRanks := make([]CompetitionRank, 0, 100)
. . 1467: for i, rank := range ranks {
. . 1468: if int64(i) < rankAfter {
. . 1469: continue
. . 1470: }
. . 1471: pagedRanks = append(pagedRanks, CompetitionRank{
. . 1472: Rank: int64(i + 1),
. . 1473: Score: rank.Score,
. . 1474: PlayerID: rank.PlayerID,
. . 1475: PlayerDisplayName: rank.PlayerDisplayName,
. . 1476: })
. . 1477: if len(pagedRanks) >= 100 {
. . 1478: break
. . 1479: }
. . 1480: }
. . 1481:
. . 1482: res := SuccessResult{
. . 1483: Status: true,
. 150ms 1484: Data: CompetitionRankingHandlerResult{
. . 1485: Competition: CompetitionDetail{
. . 1486: ID: competition.ID,
. . 1487: Title: competition.Title,
. . 1488: IsFinished: competition.FinishedAt.Valid,
. . 1489: },
. . 1490: Ranks: pagedRanks,
. . 1491: },
. . 1492: }
. 14.69s 1493: return c.JSON(http.StatusOK, res)
. . 1494:}
. . 1495:
. . 1496:type CompetitionsHandlerResult struct {
. . 1497: Competitions []CompetitionDetail `json:"competitions"`
. . 1498:}
tenent.name
にインデックスをはった
ALTER TABLE tenant ADD INDEX `tenant_name_idx` (`name`);
07:33:30.619694 Error 0 (Critical:0)
07:33:30.619698 PASSED: true
07:33:30.619701 SCORE: 24146 (+24146 0(0%))
今mainで起きているエラー
$ journalctl -xfu isuports.service | grep '"status":500'
Hint: You are currently not seeing messages from other users and the system.
Users in groups 'adm', 'systemd-journal' can see all messages.
Pass -q to turn off this notice.
Jul 20 07:49:20 ip-192-168-0-11 docker[318722]: webapp-webapp-1 | {"time":"2024-07-20T07:49:20.096487539Z","id":"","remote_ip":"127.0.0.1","host":"u-hnyhw-1721461742.t.isucon.pw","method":"POST","uri":"/api/organizer/players/add","user_agent":"isucandar","status":500,"error":"error dispenseID: error REPLACE INTO id_generator: Error 1213: Deadlock found when trying to get lock; try restarting transaction","latency":17637206971,"latency_human":"17.637206971s","bytes_in":5263,"bytes_out":39}
Jul 20 07:49:20 ip-192-168-0-11 docker[318722]: webapp-webapp-1 | {"time":"2024-07-20T07:49:20.098762595Z","id":"","remote_ip":"127.0.0.1","host":"ndgb-ekyf-1721461699.t.isucon.pw","method":"POST","uri":"/api/organizer/competition/9fa57f58/score","user_agent":"isucandar","status":500,"error":"error dispenseID: error REPLACE INTO id_generator: Error 1213: Deadlock found when trying to get lock; try restarting transaction","latency":18497408062,"latency_human":"18.497408062s","bytes_in":3896,"bytes_out":39}
Jul 20 07:49:20 ip-192-168-0-11 docker[318722]: webapp-webapp-1 | {"time":"2024-07-20T07:49:20.1014904Z","id":"","remote_ip":"127.0.0.1","host":"fao-ssxg-1721461732.t.isucon.pw","method":"POST","uri":"/api/organizer/competition/9fa58863/score","user_agent":"isucandar","status":500,"error":"error dispenseID: error REPLACE INTO id_generator: Error 1213: Deadlock found when trying to get lock; try restarting transaction","latency":12315799489,"latency_human":"12.315799489s","bytes_in":3609,"bytes_out":39}
Jul 20 07:49:20 ip-192-168-0-11 docker[318722]: webapp-webapp-1 | {"time":"2024-07-20T07:49:20.103552883Z","id":"","remote_ip":"127.0.0.1","host":"gyi-hrio-1721461741.t.isucon.pw","method":"POST","uri":"/api/organizer/players/add","user_agent":"isucandar","status":500,"error":"error dispenseID: error REPLACE INTO id_generator: Error 1213: Deadlock found when trying to get lock; try restarting transaction","latency":18802236707,"latency_human":"18.802236707s","bytes_in":5599,"bytes_out":39}
dokerを剥がした
08:12:20.340647 Error 0 (Critical:0)
08:12:20.340651 PASSED: true
08:12:20.340655 SCORE: 27420 (+27420 0(0%))
アプリ側でidを採番する #15 をマージ ✅ これでエラーが減ってスコアが安定するはず
Top 20 Sort By Total
Count Total Mean Stddev Min P50.0 P90.0 P95.0 P99.0 Max 2xx 3xx 4xx 5xx TotalBytes MinBytes MeanBytes MaxBytes Request
6297 10252.896 1.6282 2.0677 0.001 0.976 3.539 5.319 10.991 27.463 6073 0 224 0 83918504 0 13326 15573 GET /api/player/competition/[a-z0-9]+/ranking
11799 7478.838 0.6339 1.2794 0.002 0.248 1.434 2.342 6.540 21.518 11620 0 179 0 6891332 0 584 2342 GET /api/player/player/[a-z0-9]+
1183 559.652 0.4731 1.0826 0.001 0.198 0.972 1.447 6.280 16.962 1165 0 18 0 661800 0 559 2781 GET /api/player/competitions HTTP/2.0
158 329.463 2.0852 2.7946 0.002 1.257 4.825 6.266 14.474 23.165 145 0 13 0 138979 0 879 5856 GET /api/organizer/billing HTTP/2.0
40 185.215 4.6304 1.7735 0.455 5.019 6.718 6.995 7.000 7.000 40 0 0 0 948512 13250 23712 29334 POST /api/organizer/players/add HTTP/2.0
170 139.208 0.8189 0.9439 0.003 0.478 2.044 2.887 4.764 5.752 167 0 3 0 3546 0 20 39 POST /api/organizer/competition/[a-z0-9]+/finish
202 86.721 0.4293 0.6689 0.001 0.248 0.905 1.173 3.574 5.712 196 0 6 0 10788 0 53 62 POST /api/organizer/competition/[a-z0-9]+/score
185 75.235 0.4067 0.8376 0.001 0.165 0.879 1.767 5.025 7.156 184 0 1 0 5649344 0 30536 626667 GET /api/organizer/players HTTP/2.0
191 73.098 0.3827 0.6616 0.001 0.164 0.975 1.778 3.068 6.066 190 0 1 0 33407 39 174 203 POST /api/organizer/competitions/add HTTP/2.0
402 70.370 0.1750 0.9381 0.001 0.006 0.040 0.368 4.048 13.294 400 0 2 0 544003 0 1353 1613 GET /api/admin/tenants/billing?before=<num> HTTP/2.0
9 11.669 1.2966 3.5018 0.001 0.040 11.199 11.199 11.199 11.199 7 0 2 0 1162 0 129 168 POST /api/organizer/player/[a-z0-9]+/disqualified
1 8.070 8.0700 0.0000 8.070 8.070 8.070 8.070 8.070 8.070 1 0 0 0 55 55 55 55 POST /initialize HTTP/2.0
32 7.306 0.2283 1.2028 0.004 0.008 0.030 0.040 6.925 6.925 32 0 0 0 50754 1552 1586 1678 GET /api/admin/tenants/billing HTTP/2.0
42 0.319 0.0076 0.0300 0.000 0.002 0.006 0.019 0.197 0.197 37 0 5 0 7171 39 170 212 POST /api/admin/tenants/add HTTP/2.0
1 0.001 0.0010 0.0000 0.001 0.001 0.001 0.001 0.001 0.001 1 0 0 0 188 188 188 188 GET /api/organizer/competitions HTTP/2.0
1 0.000 0.0000 0.0000 0.000 0.000 0.000 0.000 0.000 0.000 1 0 0 0 33294 33294 33294 33294 GET /js/app.3a4ec98c.js HTTP/2.0
1 0.000 0.0000 0.0000 0.000 0.000 0.000 0.000 0.000 0.000 1 0 0 0 4868 4868 4868 4868 GET /css/app.83b4c321.css HTTP/2.0
1 0.000 0.0000 0.0000 0.000 0.000 0.000 0.000 0.000 0.000 1 0 0 0 479 479 479 479 GET /index.html HTTP/2.0
重め
(pprof) list billingReportByCompetition
Total: 12.93hrs
ROUTINE ======================== github.com/isucon/isucon12-qualify/webapp/go.billingReportByCompetition in /home/isucon/webapp/go/isuports.go
0 353.65s (flat, cum) 0.76% of Total
. . 530: MinCreatedAt int64 `db:"min_created_at"`
. . 531:}
. . 532:
. . 533:// 大会ごとの課金レポートを計算する
. . 534:func billingReportByCompetition(ctx context.Context, tenantDB dbOrTx, tenantID int64, competitonID string) (*BillingReport, error) {
. 228.92ms 535: comp, err := retrieveCompetition(ctx, tenantDB, competitonID)
. . 536: if err != nil {
. . 537: return nil, fmt.Errorf("error retrieveCompetition: %w", err)
. . 538: }
. . 539:
. . 540: // ランキングにアクセスした参加者のIDを取得する
. 12.05ms 541: vhs := []VisitHistorySummaryRow{}
. 334.16s 542: if err := adminDB.SelectContext(
. . 543: ctx,
. . 544: &vhs,
. . 545: "SELECT player_id, MIN(created_at) AS min_created_at FROM visit_history WHERE tenant_id = ? AND competition_id = ? GROUP BY player_id",
. . 546: tenantID,
. . 547: comp.ID,
. . 548: ); err != nil && err != sql.ErrNoRows {
. . 549: return nil, fmt.Errorf("error Select visit_history: tenantID=%d, competitionID=%s, %w", tenantID, comp.ID, err)
. . 550: }
. . 551: billingMap := map[string]string{}
. . 552: for _, vh := range vhs {
. . 553: // competition.finished_atよりもあとの場合は、終了後に訪問したとみなして大会開催内アクセス済みとみなさない
. . 554: if comp.FinishedAt.Valid && comp.FinishedAt.Int64 < vh.MinCreatedAt {
. . 555: continue
. . 556: }
. 96.39ms 557: billingMap[vh.PlayerID] = "visitor"
. . 558: }
. . 559:
. . 560: // スコアを登録した参加者のIDを取得する
. . 561: scoredPlayerIDs := []string{}
. 19.10s 562: if err := tenantDB.SelectContext(
. . 563: ctx,
. . 564: &scoredPlayerIDs,
. . 565: "SELECT DISTINCT(player_id) FROM player_score WHERE tenant_id = ? AND competition_id = ?",
. . 566: tenantID, comp.ID,
. . 567: ); err != nil && err != sql.ErrNoRows {
. . 568: return nil, fmt.Errorf("error Select count player_score: tenantID=%d, competitionID=%s, %w", tenantID, competitonID, err)
. . 569: }
. . 570: for _, pid := range scoredPlayerIDs {
. . 571: // スコアが登録されている参加者
. 60.24ms 572: billingMap[pid] = "player"
. . 573: }
. . 574:
. . 575: // 大会が終了している場合のみ請求金額が確定するので計算する
. . 576: var playerCount, visitorCount int64
. . 577: if comp.FinishedAt.Valid {
サーバー2とサーバー1でアプリケーションを処理するようにした
08:51:01.202484 Error 0 (Critical:0) 08:51:01.202487 PASSED: true 08:51:01.202491 SCORE: 40494 (+40494 0(0%))
09:19:59.116979 Error 0 (Critical:0)
09:19:59.116982 PASSED: true
09:19:59.116985 SCORE: 61738 (+61738 0(0%))
kataribe
Top 20 Sort By Total
Count Total Mean Stddev Min P50.0 P90.0 P95.0 P99.0 Max 2xx 3xx 4xx 5xx TotalBytes MinBytes MeanBytes MaxBytes Request
14374 14729.961 1.0248 1.4190 0.001 0.565 2.345 3.576 7.622 19.102 14010 0 364 0 33621315 0 2339 2981 GET /api/player/competition/[a-z0-9]+/ranking
31392 12856.188 0.4095 0.8405 0.001 0.154 0.936 1.557 4.450 12.288 31045 0 347 0 25312058 0 806 2026 GET /api/player/player/[a-z0-9]+
2160 633.670 0.2934 0.6971 0.001 0.108 0.659 1.088 3.031 12.691 2133 0 27 0 1439579 0 666 2015 GET /api/player/competitions HTTP/2.0
307 501.200 1.6326 2.7924 0.002 0.762 3.784 5.672 14.277 23.592 295 0 12 0 282956 0 921 2048 GET /api/organizer/billing HTTP/2.0
321 195.519 0.6091 1.1352 0.001 0.253 1.380 2.480 5.747 10.595 318 0 3 0 6717 0 20 39 POST /api/organizer/competition/[a-z0-9]+/finish
50 182.056 3.6411 1.6563 0.255 3.203 6.115 6.430 7.109 7.109 50 0 0 0 156811 1101 3136 3904 POST /api/organizer/players/add HTTP/2.0
364 111.893 0.3074 0.5731 0.001 0.157 0.554 0.856 2.988 6.452 356 0 8 0 19419 0 53 62 POST /api/organizer/competition/[a-z0-9]+/score
351 96.170 0.2740 0.6659 0.001 0.094 0.574 1.029 3.597 6.804 349 0 2 0 60951 0 173 209 POST /api/organizer/competitions/add HTTP/2.0
346 94.736 0.2738 0.7038 0.002 0.083 0.609 1.059 3.355 8.757 343 0 3 0 1286370 0 3717 87381 GET /api/organizer/players HTTP/2.0
555 85.135 0.1534 1.0841 0.001 0.005 0.027 0.119 4.331 15.372 553 0 2 0 756562 0 1363 1639 GET /api/admin/tenants/billing?before=<num> HTTP/2.0
1 4.985 4.9850 0.0000 4.985 4.985 4.985 4.985 4.985 4.985 1 0 0 0 55 55 55 55 POST /initialize HTTP/2.0
11 1.791 0.1628 0.1860 0.001 0.113 0.390 0.600 0.600 0.600 10 0 1 0 1612 39 146 168 POST /api/organizer/player/[a-z0-9]+/disqualified
42 1.262 0.0300 0.0894 0.004 0.007 0.042 0.048 0.563 0.563 42 0 0 0 65740 1534 1565 1604 GET /api/admin/tenants/billing HTTP/2.0
52 0.540 0.0104 0.0554 0.000 0.001 0.004 0.017 0.403 0.403 47 0 5 0 8922 39 171 208 POST /api/admin/tenants/add HTTP/2.0
1 0.001 0.0010 0.0000 0.001 0.001 0.001 0.001 0.001 0.001 1 0 0 0 188 188 188 188 GET /api/organizer/competitions HTTP/2.0
1 0.000 0.0000 0.0000 0.000 0.000 0.000 0.000 0.000 0.000 1 0 0 0 4868 4868 4868 4868 GET /css/app.83b4c321.css HTTP/2.0
1 0.000 0.0000 0.0000 0.000 0.000 0.000 0.000 0.000 0.000 1 0 0 0 835 835 835 835 GET /index.html HTTP/2.0
1 0.000 0.0000 0.0000 0.000 0.000 0.000 0.000 0.000 0.000 1 0 0 0 33294 33294 33294 33294 GET /js/app.3a4ec98c.js HTTP/2.0
テナントのキャッシュ #19 マージ ✅
https://isunarabe.org/teams/682/benchmark_jobs/10915 09:27:39.845202 SCORE: 75971 (+75971 0(0%))
seserver-3を使うようにした
members:
documents
サーバー構成
isucon-s1: http://18.180.92.229:19999/ isucon-s2: http://52.192.32.21:19999/ isucon-s3: http://52.196.130.41:19999/
メモ