pinkumohikan / isucon-practice-20240824-private-isu

2024/08/24 (Sat) ISUCON練習会 (ソロ, private-isu)

0 stars 0 forks source link

ISUCON練習会 (ソロ, private-isu) #1

Closed pinkumohikan closed 1 month ago

pinkumohikan commented 2 months ago

ISUCON練習会

2024/08/24 (Sat)
ソロ
private-isu
- https://github.com/catatsuy/private-isu
10:45くらいから

pinkumohikan commented 2 months ago

初期スコア

$ /home/isucon/private_isu.git/benchmarker/bin/benchmarker -u /home/isucon/private_isu.git/benchmarker/userdata -t http://172.31.29.227
{"pass":true,"score":966,"success":843,"fail":0,"messages":[]}

pinkumohikan commented 2 months ago

インフラ構成

スペック

OS: "Ubuntu 24.04 LTS"
vCPU: 2

メモリ

               total        used        free      shared  buff/cache   available
Mem:           3.7Gi       1.0Gi       2.2Gi       2.9Mi       722Mi       2.7Gi
Swap:             0B          0B          0B

ミドルウェア

MySQL: /usr/sbin/mysqld Ver 8.0.36-2ubuntu3 for Linux on x86_64 ((Ubuntu))
Nginx: nginx version: nginx/1.24.0 (Ubuntu)
Go: go version go1.22.3 linux/amd64

開いているポート

COMMAND  PID     USER   FD   TYPE DEVICE SIZE/OFF NODE NAME
ruby     682   isucon    7u  IPv4   8321      0t0  TCP *:http-alt (LISTEN)
nginx    744     root    5u  IPv4   6603      0t0  TCP *:http (LISTEN)
nginx    745 www-data    5u  IPv4   6603      0t0  TCP *:http (LISTEN)
nginx    746 www-data    5u  IPv4   6603      0t0  TCP *:http (LISTEN)
mysqld  1116    mysql   34u  IPv4   8358      0t0  TCP localhost:mysql (LISTEN)
ruby    1119   isucon    7u  IPv4   8321      0t0  TCP *:http-alt (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  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
  fwupd.service                                  loaded active running Firmware update daemon
  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
  ModemManager.service                           loaded active running Modem Manager
  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
  sysstat.service                                loaded active exited  Resets System Activity Logs
  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-BOOT.service loaded active exited  File System Check on /dev/disk/by-label/BOOT
  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 OS 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-tmpfiles-setup-dev-early.service       loaded active exited  Create Static Device Nodes in /dev gracefully
  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
  udisks2.service                                loaded active running Disk Manager
  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

Legend: 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.

65 loaded units listed.
To show all installed unit files use 'systemctl list-unit-files'.

PATH (バックアップ)

/home/isucon/.local/go/bin:/home/isucon/.local/node/bin:/home/isucon/.local/ruby/bin:/usr/local/bin:/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin:/usr/games:/usr/local/games:/snap/bin

pinkumohikan commented 2 months ago

Ruby実装からGo実装へ切り替え

$ 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.

$ /home/isucon/private_isu.git/benchmarker/bin/benchmarker -u /home/isucon/private_isu.git/benchmarker/userdata -t http://172.31.29.227
{"pass":true,"score":4187,"success":4028,"fail":0,"messages":[]}

pinkumohikan commented 2 months ago

slow query

pt-query-digest結果

# A software update is available:

# 2.6s user time, 140ms system time, 73.38M rss, 392.17G vsz
# Current date: Sat Aug 24 11:23:11 2024
# Hostname: salmon.local
# Files: mysql-slow.log
# Overall: 71.48k total, 27 unique, 850.98 QPS, 7.42x concurrency ________
# Time range: 2024-08-24T02:21:30 to 2024-08-24T02:22:54
# Attribute          total     min     max     avg     95%  stddev  median
# ============     ======= ======= ======= ======= ======= ======= =======
# Exec time           624s     1us   306ms     9ms    59ms    29ms    31us
# Lock time           32ms       0     7ms       0     1us    28us       0
# Rows sent          1.32M       0   9.77k   19.32    0.99  414.76       0
# Rows examine     666.05M       0  97.68k   9.54k  97.04k  28.75k       0
# Query size         7.99M      17   1.15M  117.23   72.65   8.57k   31.70

# Profile
# Rank Query ID                            Response time  Calls R/Call V/M
# ==== =================================== ============== ===== ====== ===
#    1 0x624863D30DAC59FA16849282195BE09F  396.0856 63.5%  3207 0.1235  0.01 SELECT comments
#    2 0x422390B42D4DD86C7539A5F45EB76A80  163.0011 26.1%  3443 0.0473  0.00 SELECT comments
#    3 0x100EC8B5C400F34381F9D7F7FA80A53D   32.4159  5.2%   236 0.1374  0.00 SELECT comments
#    4 0x19759A5557089FD5B718D440CBBB5C55   18.2332  2.9%  2520 0.0072  0.12 SELECT posts
# MISC 0xMISC                               13.8612  2.2% 62076 0.0002   0.0 <23 ITEMS>

# Query 1: 38.18 QPS, 4.72x concurrency, ID 0x624863D30DAC59FA16849282195BE09F at byte 6405454
# This item is included in the report because it matches --limit.
# Scores: V/M = 0.01
# Time range: 2024-08-24T02:21:30 to 2024-08-24T02:22:54
# Attribute    pct   total     min     max     avg     95%  stddev  median
# ============ === ======= ======= ======= ======= ======= ======= =======
# Count          4    3207
# Exec time     63    396s    26ms   204ms   124ms   148ms    33ms   128ms
# Lock time      9     3ms       0   438us       0     1us     7us     1us
# Rows sent      0   8.01k       0       3    2.56    2.90    1.03    2.90
# Rows examine  45 305.87M  97.66k  97.67k  97.66k  97.04k       0  97.04k
# Query size     3 257.35k      80      83   82.17   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` = 6857 ORDER BY `created_at` DESC LIMIT 3\G

# Query 2: 40.99 QPS, 1.94x concurrency, ID 0x422390B42D4DD86C7539A5F45EB76A80 at byte 12132827
# This item is included in the report because it matches --limit.
# Scores: V/M = 0.00
# Time range: 2024-08-24T02:21:30 to 2024-08-24T02:22:54
# Attribute    pct   total     min     max     avg     95%  stddev  median
# ============ === ======= ======= ======= ======= ======= ======= =======
# Count          4    3443
# Exec time     26    163s    10ms    91ms    47ms    61ms    13ms    48ms
# Lock time      7     3ms       0    16us       0     1us       0     1us
# Rows sent      0   3.36k       1       1       1       1       0       1
# Rows examine  49 328.37M  97.66k  97.67k  97.66k  97.04k       0  97.04k
# Query size     2 219.08k      63      66   65.16   65.89    1.19   62.76
# 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 `post_id` = 8908\G

# Query 3: 3.52 QPS, 0.48x concurrency, ID 0x100EC8B5C400F34381F9D7F7FA80A53D at byte 12086969
# This item is included in the report because it matches --limit.
# Scores: V/M = 0.00
# Time range: 2024-08-24T02:21:31 to 2024-08-24T02:22:38
# Attribute    pct   total     min     max     avg     95%  stddev  median
# ============ === ======= ======= ======= ======= ======= ======= =======
# Count          0     236
# Exec time      5     32s    27ms   190ms   137ms   155ms    17ms   134ms
# Lock time      0   193us       0     2us       0     1us       0     1us
# Rows sent      0   2.19k       0      20    9.52   14.52    3.59    8.91
# Rows examine   3  22.51M  97.66k  97.68k  97.67k  97.04k       0  97.04k
# Query size     0  17.04k      72      75   73.95   72.65    0.22   72.65
# 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` = 205 ORDER BY `created_at` DESC\G

# Query 4: 34.52 QPS, 0.25x concurrency, ID 0x19759A5557089FD5B718D440CBBB5C55 at byte 2288990
# This item is included in the report because it matches --limit.
# Scores: V/M = 0.12
# Time range: 2024-08-24T02:21:31 to 2024-08-24T02:22:44
# Attribute    pct   total     min     max     avg     95%  stddev  median
# ============ === ======= ======= ======= ======= ======= ======= =======
# Count          3    2520
# Exec time      2     18s    60us   306ms     7ms    75ms    29ms   113us
# Lock time      7     2ms       0   170us       0     1us     3us     1us
# Rows sent      0   2.46k       1       1       1       1       0       1
# Rows examine   0   2.46k       1       1       1       1       0       1
# Query size     1  96.29k      37      40   39.13   38.53    0.27   38.53
# 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 * FROM `posts` WHERE `id` = 7209\G

index tuning

mysql> explain SELECT * FROM `comments` WHERE `post_id` = 6857 ORDER BY `created_at` DESC LIMIT 3;
+----+-------------+----------+------------+------+---------------+------+---------+------+-------+----------+-----------------------------+
| id | select_type | table    | partitions | type | possible_keys | key  | key_len | ref  | rows  | filtered | Extra                       |
+----+-------------+----------+------------+------+---------------+------+---------+------+-------+----------+-----------------------------+
|  1 | SIMPLE      | comments | NULL       | ALL  | NULL          | NULL | NULL    | NULL | 99674 |    10.00 | Using where; Using filesort |
+----+-------------+----------+------------+------+---------------+------+---------+------+-------+----------+-----------------------------+
1 row in set, 1 warning (0.00 sec)
mysql> ALTER TABLE comments ADD INDEX (post_id, created_at DESC);
Query OK, 0 rows affected (0.14 sec)
Records: 0  Duplicates: 0  Warnings: 0
mysql> explain SELECT * FROM `comments` WHERE `post_id` = 6857 ORDER BY `created_at` DESC LIMIT 3;
+----+-------------+----------+------------+------+---------------+---------+---------+-------+------+----------+-------+
| id | select_type | table    | partitions | type | possible_keys | key     | key_len | ref   | rows | filtered | Extra |
+----+-------------+----------+------------+------+---------------+---------+---------+-------+------+----------+-------+
|  1 | SIMPLE      | comments | NULL       | ref  | post_id       | post_id | 4       | const |   10 |   100.00 | NULL  |
+----+-------------+----------+------------+------+---------------+---------+---------+-------+------+----------+-------+
1 row in set, 1 warning (0.00 sec)

スコア

$ /home/isucon/private_isu.git/benchmarker/bin/benchmarker -u /home/isucon/private_isu.git/benchmarker/userdata -t http://172.31.29.227
{"pass":true,"score":34788,"success":32613,"fail":0,"messages":[]}

pinkumohikan commented 2 months ago

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
 1266  227.148  0.1794  0.0375  0.030  0.176  0.229  0.244  0.278  0.328   1266    0    0    0     3932113       2639       3105       6045  GET / HTTP/1.1
19602  163.539  0.0083  0.0123  0.000  0.005  0.016  0.022  0.044  0.327  19602    0    0    0  6313515243      34642     322085    1057912  GET /image/$image
  240   72.038  0.3002  0.0464  0.064  0.300  0.353  0.365  0.409  0.432    240    0    0    0     1281443       5032       5339       5773  GET /posts?max_created_at=(.*)
 1470   50.410  0.0343  0.0204  0.002  0.030  0.059  0.070  0.101  0.215   1470    0    0    0     1892691        712       1287       1981  GET /posts/\d+
  247   47.725  0.1932  0.0493  0.030  0.191  0.257  0.271  0.319  0.339    247    0    0    0      822301       1590       3329       5380  GET /@[a-zA-Z0-9]+
  930   25.879  0.0278  0.0140  0.000  0.027  0.046  0.051  0.062  0.096      0  930    0    0           0          0          0          0  POST /login HTTP/1.1
  244    5.002  0.0205  0.0192  0.001  0.011  0.049  0.057  0.082  0.086      0  122  122    0           0          0          0          0  POST / HTTP/1.1
  141    4.809  0.0341  0.0127  0.010  0.032  0.051  0.057  0.081  0.082      0  141    0    0           0          0          0          0  POST /register HTTP/1.1
 1951    4.147  0.0021  0.0028  0.000  0.001  0.005  0.007  0.014  0.029   1951    0    0    0       83893         43         43         43  GET /favicon.ico HTTP/1.1
 1951    4.042  0.0021  0.0030  0.000  0.001  0.005  0.007  0.015  0.030   1951    0    0    0     3736165       1915       1915       1915  GET /js/timeago.min.js HTTP/1.1
 1951    3.707  0.0019  0.0025  0.000  0.001  0.004  0.006  0.013  0.023   1951    0    0    0     3022099       1549       1549       1549  GET /css/style.css HTTP/1.1
 1951    3.689  0.0019  0.0029  0.000  0.001  0.004  0.007  0.015  0.035   1951    0    0    0     3558624       1824       1824       1824  GET /js/main.js HTTP/1.1
  128    1.351  0.0106  0.0084  0.001  0.008  0.020  0.028  0.047  0.049      0  128    0    0           0          0          0          0  POST /comment HTTP/1.1
  278    1.281  0.0046  0.0052  0.000  0.003  0.011  0.016  0.028  0.038    278    0    0    0      170970        615        615        615  GET /login HTTP/1.1
  141    0.997  0.0071  0.0065  0.000  0.005  0.016  0.019  0.035  0.041      0    0  141    0           0          0          0          0  GET /admin/banned HTTP/1.1
  139    0.504  0.0036  0.0035  0.000  0.003  0.008  0.010  0.018  0.026      0  139    0    0        3336         24         24         24  GET /logout HTTP/1.1
    1    0.056  0.0560  0.0000  0.056  0.056  0.056  0.056  0.056  0.056      1    0    0    0           0          0          0          0  GET /initialize HTTP/1.1

pinkumohikan commented 2 months ago

リソース利用状況

MySQLが一番頑張っている

pinkumohikan commented 2 months ago

kataribe 2位 `GET /image/$image`

https://github.com/pinkumohikan/isucon-practice-20240824-private-isu/blob/6d198714cfdc46730a4637c785080e066015610b/webapp/golang/app.go#L673-L703

posts テーブルの img_data カラムに画像が載っているデータをファイルに落とし、Nginxから直接返せるようにしていく

pinkumohikan commented 1 month ago

続きからやっていき

pinkumohikan commented 1 month ago

現時点のスコア

{"pass":true,"score":35575,"success":33419,"fail":0,"messages":[]}

pinkumohikan commented 1 month ago

ベンチ中にハングしたのでAWS Consoleから強制停止 & 起動させて、Swap 2GB追加 💀

pinkumohikan commented 1 month ago

{"pass":true,"score":57371,"success":54852,"fail":0,"messages":[]}

pinkumohikan commented 1 month ago

ついでにinvisible化

mysql> ALTER TABLE posts MODIFY COLUMN `imgdata` mediumblob NOT NULL
INVISIBLE;
Query OK, 0 rows affected (0.01 sec)
Records: 0  Duplicates: 0  Warnings: 0

{"pass":true,"score":58891,"success":56339,"fail":0,"messages":[]}

pinkumohikan commented 1 month ago

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
 1833  339.612  0.1853  0.0345  0.031  0.184  0.229  0.245  0.271  0.299  1833      0    0    0     5594720       2653       3052       6038  GET / HTTP/1.1
  360  111.834  0.3107  0.0647  0.037  0.320  0.375  0.386  0.410  0.422   360      0    0    0     1928370       4962       5356       5878  GET /posts?max_created_at=(.*)
 2322   76.137  0.0328  0.0196  0.001  0.028  0.060  0.070  0.087  0.133  2322      0    0    0     3008011        713       1295       1908  GET /posts/\d+
  334   67.728  0.2028  0.0492  0.028  0.201  0.264  0.282  0.323  0.331   334      0    0    0     1083597       1567       3244       5053  GET /@[a-zA-Z0-9]+
 1294   33.550  0.0259  0.0151  0.000  0.025  0.046  0.053  0.068  0.087     0   1294    0    0           0          0          0          0  POST /login HTTP/1.1
  137    4.747  0.0346  0.0163  0.010  0.031  0.054  0.060  0.097  0.111     0    137    0    0           0          0          0          0  POST /register HTTP/1.1
  248    3.438  0.0139  0.0134  0.001  0.010  0.030  0.039  0.055  0.112     0    124  124    0           0          0          0          0  POST / HTTP/1.1
  520    2.086  0.0040  0.0048  0.000  0.002  0.010  0.015  0.022  0.035   520      0    0    0      319800        615        615        615  GET /login HTTP/1.1
  129    1.236  0.0096  0.0106  0.001  0.006  0.023  0.036  0.046  0.056     0    129    0    0           0          0          0          0  POST /comment HTTP/1.1
  260    1.215  0.0047  0.0059  0.000  0.002  0.013  0.017  0.030  0.035     0    260    0    0        6240         24         24         24  GET /logout HTTP/1.1
  137    0.799  0.0058  0.0076  0.000  0.003  0.013  0.022  0.038  0.052     0      0  137    0           0          0          0          0  GET /admin/banned HTTP/1.1
35102    0.464  0.0000  0.0011  0.000  0.000  0.000  0.000  0.000  0.182  2191  32911    0    0   325390406          0       9269    1089626  GET /image/$image
    1    0.228  0.2280  0.0000  0.228  0.228  0.228  0.228  0.228  0.228     1      0    0    0       22374      22374      22374      22374  GET / HTTP/1.0
    1    0.012  0.0120  0.0000  0.012  0.012  0.012  0.012  0.012  0.012     1      0    0    0           0          0          0          0  GET /initialize HTTP/1.1
 3455    0.000  0.0000  0.0000  0.000  0.000  0.000  0.000  0.000  0.000     1   3454    0    0        1824          0          0       1824  GET /js/main.js HTTP/1.1
 3455    0.000  0.0000  0.0000  0.000  0.000  0.000  0.000  0.000  0.000     1   3454    0    0        1549          0          0       1549  GET /css/style.css HTTP/1.1
 3455    0.000  0.0000  0.0000  0.000  0.000  0.000  0.000  0.000  0.000     1   3454    0    0          43          0          0         43  GET /favicon.ico HTTP/1.1
 3455    0.000  0.0000  0.0000  0.000  0.000  0.000  0.000  0.000  0.000     1   3454    0    0        1915          0          0       1915  GET /js/timeago.min.js HTTP/1.1

pinkumohikan commented 1 month ago

indexチューニング

mysql> explain SELECT `id`, `user_id`, `body`, `mime`, `created_at` FROM `posts` WHERE `created_at` <= '2016-01-02T11:46:03+09:00' ORDER BY `created_at` DESC;
+----+-------------+-------+------------+------+---------------+------+---------+------+-------+----------+-----------------------------+
| id | select_type | table | partitions | type | possible_keys | key  | key_len | ref  | rows  | filtered | Extra                       |
+----+-------------+-------+------------+------+---------------+------+---------+------+-------+----------+-----------------------------+
|  1 | SIMPLE      | posts | NULL       | ALL  | NULL          | NULL | NULL    | NULL | 10214 |    33.33 | Using where; Using filesort |
+----+-------------+-------+------------+------+---------------+------+---------+------+-------+----------+-----------------------------+
1 row in set, 1 warning (0.00 sec)

mysql> ALTER TABLE posts ADD INDEX (created_at);
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` WHERE `created_at` <= '2016-01-02T11:46:03+09:00' ORDER BY `created_at` DESC;
+----+-------------+-------+------------+-------+---------------+------------+---------+------+------+----------+-------------------------------------------------------+
| id | select_type | table | partitions | type  | possible_keys | key        | key_len | ref  | rows | filtered | Extra                                                 |
+----+-------------+-------+------------+-------+---------------+------------+---------+------+------+----------+-------------------------------------------------------+
|  1 | SIMPLE      | posts | NULL       | range | created_at    | created_at | 4       | NULL | 9963 |   100.00 | Using index condition; Backward index scan; Using MRR |
+----+-------------+-------+------------+-------+---------------+------------+---------+------+------+----------+-------------------------------------------------------+
1 row in set, 1 warning (0.00 sec)

mysql> explain SELECT COUNT(*) AS count FROM `comments` WHERE `user_id` = 433;
+----+-------------+----------+------------+------+---------------+------+---------+------+-------+----------+-------------+
| id | select_type | table    | partitions | type | possible_keys | key  | key_len | ref  | rows  | filtered | Extra       |
+----+-------------+----------+------------+------+---------------+------+---------+------+-------+----------+-------------+
|  1 | SIMPLE      | comments | NULL       | ALL  | NULL          | NULL | NULL    | NULL | 99667 |    10.00 | Using where |
+----+-------------+----------+------------+------+---------------+------+---------+------+-------+----------+-------------+
1 row in set, 1 warning (0.00 sec)

mysql> ALTER TABLE comments ADD INDEX (user_id);
Query OK, 0 rows affected (0.09 sec)
Records: 0  Duplicates: 0  Warnings: 0

mysql> explain SELECT COUNT(*) AS count FROM `comments` WHERE `user_id` = 433;
+----+-------------+----------+------------+------+---------------+---------+---------+-------+------+----------+-------------+
| id | select_type | table    | partitions | type | possible_keys | key     | key_len | ref   | rows | filtered | Extra       |
+----+-------------+----------+------------+------+---------------+---------+---------+-------+------+----------+-------------+
|  1 | SIMPLE      | comments | NULL       | ref  | user_id       | user_id | 4       | const |   96 |   100.00 | Using index |
+----+-------------+----------+------------+------+---------------+---------+---------+-------+------+----------+-------------+
1 row in set, 1 warning (0.00 sec)

{"pass":true,"score":60042,"success":57444,"fail":0,"messages":[]}

pinkumohikan commented 1 month ago

top-slow 1位のクエリがpostsを全件取ってそうで怪しい

# Query 1: 5.46 QPS, 0.18x concurrency, ID 0x4858CF4D8CAA743E839C127C71B69E75 at byte 758735
# Scores: V/M = 0.00
# Time range: 2024-09-16T02:17:36 to 2024-09-16T02:23:12
# Attribute    pct   total     min     max     avg     95%  stddev  median
# ============ === ======= ======= ======= ======= ======= ======= =======
# Count          0    1835
# Exec time     52     59s    11ms    65ms    32ms    48ms     9ms    31ms
# Lock time      2     4ms       0     2ms     2us     1us    45us     1us
# Rows sent     82  17.61M   9.77k   9.89k   9.83k   9.80k      62   9.80k
# Rows examine  43  35.22M  19.53k  19.77k  19.65k  19.40k       0  19.40k
# Query size     0 164.86k      92      92      92      92       0      92
# 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\G

ここっぽい https://github.com/pinkumohikan/isucon-practice-20240824-private-isu/blob/85b2d5090fba41ec8b8bac85f97323ea79d8a758/webapp/golang/app.go#L389

pinkumohikan commented 1 month ago

↑ 後続処理の makePosts() 内で、未削除20件に絞る処理があった一旦雑に、余裕を持って LIMIT 30 に設定 b308429

{"pass":true,"score":95790,"success":91478,"fail":0,"messages":[]}

pinkumohikan commented 1 month ago

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
 3144  305.764  0.0973  0.0224  0.017  0.095  0.126  0.136  0.168  0.192  3144      0    0    0     9089033       2601       2890       6046  GET / HTTP/1.1
  520  111.467  0.2144  0.0287  0.037  0.218  0.240  0.246  0.265  0.337   520      0    0    0     2778291       4985       5342       5827  GET /posts?max_created_at=(.*)
 3543   80.408  0.0227  0.0120  0.002  0.020  0.038  0.047  0.064  0.090  3543      0    0    0     4578461        696       1292       1931  GET /posts/\d+
  530   60.738  0.1146  0.0343  0.017  0.115  0.160  0.174  0.195  0.266   530      0    0    0     1713098       1485       3232       5312  GET /@[a-zA-Z0-9]+
 2171   50.185  0.0231  0.0121  0.000  0.024  0.038  0.042  0.051  0.073     0   2171    0    0           0          0          0          0  POST /login HTTP/1.1
  233    7.131  0.0306  0.0110  0.010  0.030  0.044  0.051  0.069  0.082     0    233    0    0           0          0          0          0  POST /register HTTP/1.1
  422    4.573  0.0108  0.0080  0.001  0.009  0.021  0.027  0.039  0.046     0    211  211    0           0          0          0          0  POST / HTTP/1.1
  864    2.309  0.0027  0.0029  0.000  0.002  0.005  0.008  0.016  0.026   864      0    0    0      531360        615        615        615  GET /login HTTP/1.1
  220    1.281  0.0058  0.0046  0.000  0.005  0.010  0.016  0.028  0.031     0    220    0    0           0          0          0          0  POST /comment HTTP/1.1
  432    1.078  0.0025  0.0027  0.000  0.002  0.005  0.007  0.014  0.023     0    432    0    0       10368         24         24         24  GET /logout HTTP/1.1
  233    0.981  0.0042  0.0039  0.001  0.003  0.007  0.009  0.019  0.034     0      0  233    0           0          0          0          0  GET /admin/banned HTTP/1.1
57555    0.147  0.0000  0.0001  0.000  0.000  0.000  0.000  0.000  0.008  3038  54517    0    0   462954215          0       8043    1265181  GET /image/$image
    1    0.013  0.0130  0.0000  0.013  0.013  0.013  0.013  0.013  0.013     1      0    0    0           0          0          0          0  GET /initialize HTTP/1.1
 5458    0.000  0.0000  0.0000  0.000  0.000  0.000  0.000  0.000  0.000     1   5457    0    0        1915          0          0       1915  GET /js/timeago.min.js HTTP/1.1
 5458    0.000  0.0000  0.0000  0.000  0.000  0.000  0.000  0.000  0.000     1   5457    0    0        1549          0          0       1549  GET /css/style.css HTTP/1.1
 5458    0.000  0.0000  0.0000  0.000  0.000  0.000  0.000  0.000  0.000     1   5457    0    0        1824          0          0       1824  GET /js/main.js HTTP/1.1
 5458    0.000  0.0000  0.0000  0.000  0.000  0.000  0.000  0.000  0.000     1   5457    0    0          43          0          0         43  GET /favicon.ico HTTP/1.1

pinkumohikan commented 1 month ago

top-slow (pt-query-digest)

top-slow.log

ADMIN PREPARE が上位に食い込んできたので動的プレースホルダを使うようにしていく

pinkumohikan commented 1 month ago

動的プレースホルダを使うように設定 ✅

{"pass":true,"score":114162,"success":109182,"fail":0,"messages":[]}

pinkumohikan commented 1 month ago

ついでにコネクションプーリングの設定 ✅

{"pass":true,"score":119715,"success":114429,"fail":0,"messages":[]}

pinkumohikan commented 1 month ago

ベンチ中のCPU使用率

pinkumohikan commented 1 month ago

top slow 1位のクエリも同じようにLIMIT 30

# Query 1: 2.40 QPS, 0.10x concurrency, ID 0x7A12D0C8F433684C3027353C36CAB572 at byte 162930666
# Scores: V/M = 0.00
# Time range: 2024-09-16T02:45:05 to 2024-09-16T02:53:58
# Attribute    pct   total     min     max     avg     95%  stddev  median
# ============ === ======= ======= ======= ======= ======= ======= =======
# Count          0    1280
# Exec time     32     52s    16ms    80ms    41ms    56ms     9ms    40ms
# Lock time      0     1ms       0    37us       0     1us     1us     1us
# Rows sent     91  12.08M   9.57k   9.76k   9.66k   9.33k       0   9.33k
# Rows examine  30  12.08M   9.57k   9.76k   9.66k   9.33k       0   9.33k
# Query size     0 177.50k     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:45:49+09:00' ORDER BY `created_at` DESC\G

63cc2b1

{"pass":true,"score":145909,"success":139864,"fail":0,"messages":[]}

pinkumohikan commented 1 month ago

休憩 12:20 - 14:30 あと4時間くらい

pinkumohikan commented 1 month ago

usersのfindでN+1問題

# Query 1: 4.45k QPS, 0.40x concurrency, ID 0x396201721CD58410E070DA9421CA8C8D at byte 25204635
# Scores: V/M = 0.00
# Time range: 2024-09-16T03:11:27 to 2024-09-16T03:12:28
# Attribute    pct   total     min     max     avg     95%  stddev  median
# ============ === ======= ======= ======= ======= ======= ======= =======
# Count         50  271191
# Exec time     35     25s    25us     7ms    90us   287us   154us    52us
# Lock time     49   229ms       0     3ms       0     1us    13us     1us
# Rows sent     37 264.83k       1       1       1       1       0       1
# Rows examine   1 264.83k       1       1       1       1       0       1
# Query size    33   9.80M      36      39   37.89   36.69    0.16   36.69
# 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 'users'\G
#    SHOW CREATE TABLE `isuconp`.`users`\G
# EXPLAIN /*!50100 PARTITIONS*/
SELECT * FROM `users` WHERE `id` = 729\G

レコード数は1.5kレコード程度なので、全部メモリで持つかたちにする

mysql> select count(*) from users;
+----------+
| count(*) |
+----------+
|     1340 |
+----------+
1 row in set (0.00 sec)

pinkumohikan commented 1 month ago

{"pass":true,"score":200467,"success":193708,"fail":0,"messages":[]}

pinkumohikan commented 1 month ago

ベンチ中のCPU使用率

pinkumohikan commented 1 month ago

slow query

# Query 1: 2.56k QPS, 0.35x concurrency, ID 0x624863D30DAC59FA16849282195BE09F at byte 13433422
# Scores: V/M = 0.00
# Time range: 2024-09-16T06:50:25 to 2024-09-16T06:51:25
# Attribute    pct   total     min     max     avg     95%  stddev  median
# ============ === ======= ======= ======= ======= ======= ======= =======
# Count         43  153505
# Exec time     32     21s    39us    11ms   138us   445us   203us    80us
# Lock time     41   140ms       0     2ms       0     1us    11us     1us
# Rows sent     23 151.47k       0       3    1.01    2.90    1.36       0
# Rows examine   0 151.47k       0       3    1.01    2.90    1.36       0
# Query size    48  12.10M      79      83   82.66   80.10    0.11   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` = 15228 ORDER BY `created_at` DESC LIMIT 3\G

クエリ発行回数的にN+1だが、post_idごとにLIMIT 3する上手い方法がパッと思いつかないので後回し

# Query 2: 2.71k QPS, 0.35x concurrency, ID 0x422390B42D4DD86C7539A5F45EB76A80 at byte 6804912
# Scores: V/M = 0.00
# Time range: 2024-09-16T06:50:25 to 2024-09-16T06:51:25
# Attribute    pct   total     min     max     avg     95%  stddev  median
# ============ === ======= ======= ======= ======= ======= ======= =======
# Count         45  162582
# Exec time     31     21s    38us     5ms   127us   403us   184us    76us
# Lock time     46   156ms       0     2ms       0     1us    15us     1us
# Rows sent     24 158.77k       1       1       1       1       0       1
# Rows examine   2 582.02k       0      23    3.67   12.54    5.06       0
# Query size    40  10.17M      62      66   65.62   65.89    1.51   65.89
# 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 `post_id` = 15209\G

これもN+1 パッと直せそうなので見ていく

pinkumohikan commented 1 month ago

{"pass":true,"score":233499,"success":225669,"fail":0,"messages":[]}

pinkumohikan commented 1 month ago

slow query

引き続き1位は一旦skip

# Query 2: 20.90 QPS, 0.21x concurrency, ID 0xE83DA93257C7B787C67B1B05D2469241 at byte 30132196
# Scores: V/M = 0.00
# Time range: 2024-09-16T06:54:46 to 2024-09-16T06:55:46
# Attribute    pct   total     min     max     avg     95%  stddev  median
# ============ === ======= ======= ======= ======= ======= ======= =======
# Count          0    1254
# Exec time     23     13s     3ms    24ms    10ms    16ms     4ms     9ms
# Lock time      0     1ms       0   278us     1us     1us     9us     1us
# Rows sent      1  12.53k       2      21   10.23   14.52    2.92    9.83
# Rows examine  46  12.20M   9.77k  10.14k   9.96k   9.80k  109.66   9.80k
# Query size     0 139.50k     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` = 641 ORDER BY `created_at` DESC\G

index張れそう

mysql> explain SELECT `id`, `user_id`, `body`, `mime`, `created_at` FROM `posts` WHERE `user_id` = 641 ORDER BY `created_at` DESC;
+----+-------------+-------+------------+------+---------------+------+---------+------+-------+----------+-----------------------------+
| id | select_type | table | partitions | type | possible_keys | key  | key_len | ref  | rows  | filtered | Extra                       |
+----+-------------+-------+------------+------+---------------+------+---------+------+-------+----------+-----------------------------+
|  1 | SIMPLE      | posts | NULL       | ALL  | NULL          | NULL | NULL    | NULL | 10315 |    10.00 | Using where; Using filesort |
+----+-------------+-------+------------+------+---------------+------+---------+------+-------+----------+-----------------------------+
1 row in set, 1 warning (0.00 sec)

mysql> ALTER TABLE posts ADD INDEX (user_id, 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` WHERE `user_id` = 641 ORDER BY `created_at` DESC;
+----+-------------+-------+------------+------+---------------+---------+---------+-------+------+----------+-------+
| id | select_type | table | partitions | type | possible_keys | key     | key_len | ref   | rows | filtered | Extra |
+----+-------------+-------+------------+------+---------------+---------+---------+-------+------+----------+-------+
|  1 | SIMPLE      | posts | NULL       | ref  | user_id       | user_id | 4       | const |   11 |   100.00 | NULL  |
+----+-------------+-------+------------+------+---------------+---------+---------+-------+------+----------+-------+
1 row in set, 1 warning (0.00 sec)

{"pass":true,"score":244925,"success":236644,"fail":0,"messages":[]}

pinkumohikan commented 1 month ago

申し訳程度 4536f163ca1df04615644fa03de0ae1898281d67

{"pass":true,"score":248304,"success":240071,"fail":0,"messages":[]}

pinkumohikan commented 1 month ago

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
  6764  226.622  0.0335  0.0085  0.004  0.033  0.045  0.048  0.056  0.074  6764       0    0    0    19319055       2552       2856       6049  GET / HTTP/1.1
  4106   95.422  0.0232  0.0118  0.000  0.025  0.038  0.040  0.046  0.078     0    4106    0    0           0          0          0          0  POST /login HTTP/1.1
  2320   90.017  0.0388  0.0092  0.003  0.038  0.050  0.054  0.063  0.092  2320       0    0    0    12419660       4965       5353       5852  GET /posts?max_created_at=(.*)
  9917   69.076  0.0070  0.0037  0.001  0.006  0.012  0.014  0.019  0.030  9917       0    0    0    12868655        693       1297       2104  GET /posts/\d+
  1471   40.109  0.0273  0.0090  0.007  0.026  0.039  0.043  0.052  0.074  1471       0    0    0     4749940       1423       3229       5538  GET /@[a-zA-Z0-9]+
   472   13.533  0.0287  0.0083  0.009  0.029  0.039  0.042  0.051  0.061     0     472    0    0           0          0          0          0  POST /register HTTP/1.1
   768    8.336  0.0109  0.0080  0.000  0.009  0.022  0.025  0.035  0.054     0     384  384    0           0          0          0          0  POST / HTTP/1.1
  1522    5.300  0.0035  0.0025  0.000  0.003  0.007  0.009  0.012  0.019  1522       0    0    0      936030        615        615        615  GET /login HTTP/1.1
   761    2.894  0.0038  0.0030  0.000  0.003  0.008  0.010  0.015  0.023     0     761    0    0       18264         24         24         24  GET /logout HTTP/1.1
   583    2.300  0.0039  0.0027  0.000  0.003  0.007  0.009  0.013  0.021     0     583    0    0           0          0          0          0  POST /comment HTTP/1.1
   472    1.107  0.0023  0.0021  0.000  0.002  0.005  0.006  0.011  0.013     0       0  472    0           0          0          0          0  GET /admin/banned HTTP/1.1
154064    0.322  0.0000  0.0001  0.000  0.000  0.000  0.000  0.000  0.005  6331  147733    0    0   943677578          0       6125    1265181  GET /image/$image
     1    0.016  0.0160  0.0000  0.016  0.016  0.016  0.016  0.016  0.016     1       0    0    0           0          0          0          0  GET /initialize HTTP/1.1
 14307    0.000  0.0000  0.0000  0.000  0.000  0.000  0.000  0.000  0.000     1   14306    0    0        1915          0          0       1915  GET /js/timeago.min.js HTTP/1.1
 14307    0.000  0.0000  0.0000  0.000  0.000  0.000  0.000  0.000  0.000     1   14306    0    0        1824          0          0       1824  GET /js/main.js HTTP/1.1
 14307    0.000  0.0000  0.0000  0.000  0.000  0.000  0.000  0.000  0.000     1   14306    0    0        1549          0          0       1549  GET /css/style.css HTTP/1.1
 14307    0.000  0.0000  0.0000  0.000  0.000  0.000  0.000  0.000  0.000     1   14306    0    0          43          0          0         43  GET /favicon.ico HTTP/1.1

pinkumohikan commented 1 month ago

slow query

# Query 1: 3.30k QPS, 0.45x concurrency, ID 0x624863D30DAC59FA16849282195BE09F at byte 38574882
# Scores: V/M = 0.00
# Time range: 2024-09-16T07:14:08 to 2024-09-16T07:15:08
# Attribute    pct   total     min     max     avg     95%  stddev  median
# ============ === ======= ======= ======= ======= ======= ======= =======
# Count         75  198075
# Exec time     67     27s    39us     6ms   136us   424us   191us    80us
# Lock time     72   196ms       0     2ms       0     1us    14us     1us
# Rows sent     27 196.29k       0       3    1.01    2.90    1.36       0
# Rows examine  10 196.29k       0       3    1.01    2.90    1.36       0
# Query size    69  15.61M      79      83   82.66   80.10    0.10   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` = 9918 ORDER BY `created_at` DESC LIMIT 3\G

サブクエリでwindow関数を使ってrownumを振り、元クエリでrownumが3以下のものだけを取るようにすれば欲しいものが取れる

{"pass":true,"score":321739,"success":312564,"fail":0,"messages":[]}

pinkumohikan commented 1 month ago

MySQLチューニング

slow query見た感じ、もうクエリ的にはチューニングの余地無さそうなのでDBは一旦終わりの設定に

{"pass":true,"score":329460,"success":320070,"fail":0,"messages":[]}

pinkumohikan commented 1 month ago

profile

(pprof) list getIndex
Total: 1881.62s
ROUTINE ======================== main.getIndex in /home/isucon/isucon-practice-20240824-private-isu/webapp/golang/app.go
         0     82.61s (flat, cum)  4.39% of Total
         .          .    427:
         .          .    428:   http.Redirect(w, r, "/", http.StatusFound)
         .          .    429:}
         .          .    430:
         .          .    431:func getIndex(w http.ResponseWriter, r *http.Request) {
         .      5.71s    432:   me := getSessionUser(r)
         .          .    433:
         .          .    434:   results := []Post{}
         .          .    435:
         .     23.14s    436:   err := db.Select(&results, "SELECT `id`, `user_id`, `body`, `mime`, `created_at` FROM `posts` ORDER BY `created_at` DESC LIMIT 30")
         .          .    437:   if err != nil {
         .          .    438:       log.Print(err)
         .          .    439:       return
         .          .    440:   }
         .          .    441:
         .     46.25s    442:   posts, err := makePosts(results, getCSRFToken(r), false)
         .          .    443:   if err != nil {
         .          .    444:       log.Print(err)
         .          .    445:       return
         .          .    446:   }
         .          .    447:
         .          .    448:   fmap := template.FuncMap{
         .          .    449:       "imageURL": imageURL,
         .          .    450:   }
         .          .    451:
         .      1.56s    452:   template.Must(template.New("layout.html").Funcs(fmap).ParseFiles(
         .    10.10ms    453:       getTemplPath("layout.html"),
         .          .    454:       getTemplPath("index.html"),
         .          .    455:       getTemplPath("posts.html"),
         .          .    456:       getTemplPath("post.html"),
         .      5.93s    457:   )).Execute(w, struct {
         .          .    458:       Posts     []Post
         .          .    459:       Me        User
         .          .    460:       CSRFToken string
         .          .    461:       Flash     string
         .    10.10ms    462:   }{posts, me, getCSRFToken(r), getFlash(w, r, "notice")})
         .          .    463:}
         .          .    464:
         .          .    465:func getAccountName(w http.ResponseWriter, r *http.Request) {
         .          .    466:   accountName := r.PathValue("accountName")
         .          .    467:   user := User{}

(pprof) list getSessionUser
Total: 1881.62s
ROUTINE ======================== main.getSessionUser in /home/isucon/isucon-practice-20240824-private-isu/webapp/golang/app.go
         0     10.42s (flat, cum)  0.55% of Total
         .          .    144:
         .          .    145:   return session
         .          .    146:}
         .          .    147:
         .          .    148:func getSessionUser(r *http.Request) User {
         .      9.16s    149:   session := getSession(r)
         .          .    150:   uid, ok := session.Values["user_id"]
         .          .    151:   if !ok || uid == nil {
         .          .    152:       return User{}
         .          .    153:   }
         .          .    154:
         .          .    155:   id := 0
         .          .    156:   switch value := uid.(type) {
         .          .    157:   case int:
         .          .    158:       id = value
         .          .    159:   case int64:
         .          .    160:       id = int(value)
         .          .    161:   }
         .      1.26s    162:   u, err := findUser(id)
         .          .    163:   if err != nil {
         .          .    164:       return User{}
         .          .    165:   }
         .          .    166:
         .          .    167:   return u

session storeにmemcacheを使っているっぽい cookie storeに変えてみる

{"pass":true,"score":317982,"success":308171,"fail":1,"messages":["静的ファイルが正しくありません (GET /image/18743.png)"]}

スコア下がったのでやめ

pinkumohikan commented 1 month ago

profile 2

(pprof) list postLogin
Total: 1881.62s
ROUTINE ======================== main.postLogin in /home/isucon/isucon-practice-20240824-private-isu/webapp/golang/app.go
         0    104.17s (flat, cum)  5.54% of Total
         .          .    328:       Flash string
         .          .    329:   }{me, getFlash(w, r, "notice")})
         .          .    330:}
         .          .    331:
         .          .    332:func postLogin(w http.ResponseWriter, r *http.Request) {
         .    10.10ms    333:   if isLogin(getSessionUser(r)) {
         .          .    334:       http.Redirect(w, r, "/", http.StatusFound)
         .          .    335:       return
         .          .    336:   }
         .          .    337:
         .     97.21s    338:   u := tryLogin(r.FormValue("account_name"), r.FormValue("password"))
         .          .    339:
         .          .    340:   if u != nil {
         .          .    341:       session := getSession(r)
         .          .    342:       session.Values["user_id"] = u.ID
         .          .    343:       session.Values["csrf_token"] = secureRandomStr(16)
         .      4.39s    344:       session.Save(r, w)
         .          .    345:
         .          .    346:       http.Redirect(w, r, "/", http.StatusFound)
         .          .    347:   } else {
         .          .    348:       session := getSession(r)
         .          .    349:       session.Values["notice"] = "アカウント名かパスワードが間違っています"
         .      2.56s    350:       session.Save(r, w)
         .          .    351:
         .          .    352:       http.Redirect(w, r, "/login", http.StatusFound)
         .          .    353:   }
         .          .    354:}
         .          .    355:

(pprof) list tryLogin
Total: 1881.62s
ROUTINE ======================== main.tryLogin in /home/isucon/isucon-practice-20240824-private-isu/webapp/golang/app.go
         0     97.16s (flat, cum)  5.16% of Total
         .          .     94:   }
         .          .     95:}
         .          .     96:
         .          .     97:func tryLogin(accountName, password string) *User {
         .          .     98:   u := User{}
         .      9.98s     99:   err := db.Get(&u, "SELECT * FROM users WHERE account_name = ? AND del_flg = 0", accountName)
         .          .    100:   if err != nil {
         .          .    101:       return nil
         .          .    102:   }
         .          .    103:
         .     87.18s    104:   if calculatePasshash(u.AccountName, password) == u.Passhash {
         .          .    105:       return &u
         .          .    106:   } else {
         .          .    107:       return nil
         .          .    108:   }
         .          .    109:}

(pprof) list calculatePasshash
Total: 1881.62s
ROUTINE ======================== main.calculatePasshash in /home/isucon/isucon-practice-20240824-private-isu/webapp/golang/app.go
         0    100.12s (flat, cum)  5.32% of Total
         .          .    134:func calculateSalt(accountName string) string {
         .          .    135:   return digest(accountName)
         .          .    136:}
         .          .    137:
         .          .    138:func calculatePasshash(accountName, password string) string {
         .    100.12s    139:   return digest(password + ":" + calculateSalt(accountName))
         .          .    140:}
         .          .    141:
         .          .    142:func getSession(r *http.Request) *sessions.Session {
         .          .    143:   session, _ := store.Get(r, "isuconp-go.session")
         .          .    144:

(pprof) list digest
Total: 1881.62s
ROUTINE ======================== crypto/sha256.(*digest).Write in /home/isucon/.local/go/src/crypto/sha256/sha256.go
   10.10ms    10.10ms (flat, cum) 0.00054% of Total
         .          .    174:   return Size224
         .          .    175:}
         .          .    176:
         .          .    177:func (d *digest) BlockSize() int { return BlockSize }
         .          .    178:
   10.10ms    10.10ms    179:func (d *digest) Write(p []byte) (nn int, err error) {
         .          .    180:   boring.Unreachable()
         .          .    181:   nn = len(p)
         .          .    182:   d.len += uint64(nn)
         .          .    183:   if d.nx > 0 {
         .          .    184:       n := copy(d.x[d.nx:], p)
ROUTINE ======================== main.digest in /home/isucon/isucon-practice-20240824-private-isu/webapp/golang/app.go
         0    100.11s (flat, cum)  5.32% of Total
         .          .    120:   return "'" + strings.Replace(arg, "'", "'\\''", -1) + "'"
         .          .    121:}
         .          .    122:
         .          .    123:func digest(src string) string {
         .          .    124:   // opensslのバージョンによっては (stdin)= というのがつくので取る
         .    100.11s    125:   out, err := exec.Command("/bin/bash", "-c", `printf "%s" `+escapeshellarg(src)+` | openssl dgst -sha512 | sed 's/^.*= //'`).Output()
         .          .    126:   if err != nil {
         .          .    127:       log.Print(err)
         .          .    128:       return ""
         .          .    129:   }
         .          .    130:

digest計算で外部コマンドを呼び出しているのをGoのlibraryでなんとかしたい

pinkumohikan commented 1 month ago

{"pass":true,"score":508788,"success":486772,"fail":0,"messages":[]}

pinkumohikan commented 1 month ago

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
 17864  152.115  0.0085  0.0037  0.001  0.008  0.013  0.015  0.020  0.033  17864       0     0    0    48835181       2460       2733       6040  GET / HTTP/1.1
 12706   81.592  0.0064  0.0033  0.000  0.006  0.011  0.013  0.016  0.038  12706       0     0    0    15867346        706       1248       1989  GET /posts/\d+
  5190   62.934  0.0121  0.0043  0.002  0.012  0.017  0.019  0.023  0.100   5190       0     0    0    27710273       4947       5339       5826  GET /posts?max_created_at=(.*)
 10902   40.167  0.0037  0.0025  0.000  0.003  0.007  0.009  0.012  0.021      0   10902     0    0           0          0          0          0  POST /login HTTP/1.1
  2435   34.346  0.0141  0.0055  0.002  0.014  0.021  0.024  0.028  0.063   2435       0     0    0     8022475       1339       3294       5569  GET /@[a-zA-Z0-9]+
  2110   18.530  0.0088  0.0079  0.000  0.006  0.019  0.022  0.045  0.062      0    1055  1055    0           0          0          0          0  POST / HTTP/1.1
  3664   12.375  0.0034  0.0022  0.000  0.003  0.006  0.008  0.011  0.015   3664       0     0    0     2253360        615        615        615  GET /login HTTP/1.1
  1825    8.192  0.0045  0.0029  0.000  0.004  0.008  0.010  0.014  0.020      0    1825     0    0           0          0          0          0  POST /register HTTP/1.1
  1832    6.454  0.0035  0.0025  0.000  0.003  0.007  0.008  0.011  0.016      0    1832     0    0       43968         24         24         24  GET /logout HTTP/1.1
  1471    5.422  0.0037  0.0025  0.000  0.003  0.007  0.009  0.012  0.018      0    1471     0    0           0          0          0          0  POST /comment HTTP/1.1
  1825    4.237  0.0023  0.0019  0.000  0.002  0.005  0.006  0.010  0.012      0       0  1825    0           0          0          0          0  GET /admin/banned HTTP/1.1
337875    1.006  0.0000  0.0001  0.000  0.000  0.000  0.000  0.000  0.012   7692  330183     0    0  1502091683          0       4445    1265181  GET /image/$image
     1    0.093  0.0930  0.0000  0.093  0.093  0.093  0.093  0.093  0.093      1       0     0    0           0          0          0          0  GET /initialize HTTP/1.1
 21777    0.000  0.0000  0.0000  0.000  0.000  0.000  0.000  0.000  0.000      1   21776     0    0          43          0          0         43  GET /favicon.ico HTTP/1.1
 21777    0.000  0.0000  0.0000  0.000  0.000  0.000  0.000  0.000  0.000      1   21776     0    0        1915          0          0       1915  GET /js/timeago.min.js HTTP/1.1
 21777    0.000  0.0000  0.0000  0.000  0.000  0.000  0.000  0.000  0.000      1   21776     0    0        1549          0          0       1549  GET /css/style.css HTTP/1.1
 21777    0.000  0.0000  0.0000  0.000  0.000  0.000  0.000  0.000  0.000      1   21776     0    0        1824          0          0       1824  GET /js/main.js HTTP/1.1

pinkumohikan commented 1 month ago

ベンチ中のCPU使用率

pinkumohikan commented 1 month ago

Nginxチューニング

Nginxの負荷が目立ってきた定番のチューニングを設定

{"pass":true,"score":542672,"success":518633,"fail":0,"messages":[]}

アプリがCPU食えば食うほどスコア上がる状態っぽいので、gzip off

{"pass":true,"score":591929,"success":567434,"fail":0,"messages":[]}

pinkumohikan / isucon-practice-20240824-private-isu

ISUCON練習会 (ソロ, private-isu) #1

ISUCON練習会

初期スコア

インフラ構成

スペック

メモリ

ミドルウェア

開いているポート

起動中のサービス

PATH (バックアップ)

Ruby実装からGo実装へ切り替え

slow query

pt-query-digest結果

index tuning

スコア

kataribe

リソース利用状況

kataribe 2位 GET /image/$image

続きからやっていき

kataribe

indexチューニング

kataribe

top-slow (pt-query-digest)

ベンチ中のCPU使用率

top slow 1位のクエリも同じようにLIMIT 30

usersのfindでN+1問題

ベンチ中のCPU使用率

slow query

slow query

kataribe

slow query

MySQLチューニング

profile

profile 2

kataribe

ベンチ中のCPU使用率

Nginxチューニング

kataribe 2位 `GET /image/$image`