search

pinkumohikan / isucon-practice-20241005-isucon11q

2024/10/05 (Sat) ISUCON練習会 (pinkumohikan x fingerEase, ISUCON 11予選 問題)
https://github.com/matsuu/aws-isucon/tree/main/isucon11-qualify
0 stars 0 forks source link

first challenge #1

Open pinkumohikan opened 1 month ago

pinkumohikan commented 1 month ago

ISUCON 11 予選

documents

pinkumohikan commented 1 month ago

インフラ構成

スペック

メモリ

              total        used        free      shared  buff/cache   available
Mem:          3.6Gi       176Mi       3.0Gi       0.0Ki       483Mi       3.2Gi
Swap:            0B          0B          0B

ミドルウェア

開いているポート

COMMAND PID     USER   FD   TYPE DEVICE SIZE/OFF NODE NAME
nginx   482     root    6u  IPv4  20453      0t0  TCP *:https (LISTEN)
nginx   483 www-data    6u  IPv4  20453      0t0  TCP *:https (LISTEN)
nginx   484 www-data    6u  IPv4  20453      0t0  TCP *:https (LISTEN)
mysqld  545    mysql   21u  IPv4  22330      0t0  TCP localhost:mysql (LISTEN)

起動中のサービス

  UNIT                                 LOAD   ACTIVE SUB     DESCRIPTION
  accounts-daemon.service              loaded active running Accounts Service
  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
  atd.service                          loaded active running Deferred execution scheduler
  blk-availability.service             loaded active exited  Availability of block devices
  cloud-config.service                 loaded active exited  Apply the settings specified in cloud-config
  cloud-final.service                  loaded active exited  Execute cloud user/final scripts
  cloud-init-local.service             loaded active exited  Initial cloud-init job (pre-networking)
  cloud-init.service                   loaded active exited  Initial cloud-init job (metadata service crawler)
  console-setup.service                loaded active exited  Set console font and keymap
  cron.service                         loaded active running Regular background program processing daemon
  dbus.service                         loaded active running D-Bus System Message Bus
  finalrd.service                      loaded active exited  Create final runtime dir for shutdown pivot root
  getty@tty1.service                   loaded active running Getty on tty1
  irqbalance.service                   loaded active running irqbalance daemon
  isucondition.go.service              loaded active running isucondition.go
  jiaapi-mock.service                  loaded active running jiaapi-mock
  keyboard-setup.service               loaded active exited  Set the console keyboard layout
  kmod-static-nodes.service            loaded active exited  Create list of static device nodes for the current kernel
  lvm2-monitor.service                 loaded active exited  Monitoring of LVM2 mirrors, snapshots etc. using dmeventd or progress polling
  mariadb.service                      loaded active running MariaDB 10.3.34 database server
  ModemManager.service                 loaded active running Modem Manager
  multipathd.service                   loaded active running Device-Mapper Multipath Device Controller
  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
  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
  ssh.service                          loaded active running OpenBSD Secure Shell server
  systemd-fsck-root.service            loaded active exited  File System Check on Root Device
  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 Login Service
  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 Service
  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-timesyncd.service            loaded active running Network Time Synchronization
  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-settle.service          loaded active exited  udev Wait for Complete Device Initialization
  systemd-udev-trigger.service         loaded active exited  udev Coldplug all Devices
  systemd-udevd.service                loaded active running udev Kernel Device Manager
  systemd-update-utmp.service          loaded active exited  Update UTMP about System Boot/Shutdown
  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-runtime-dir@1100.service        loaded active exited  User Runtime Directory /run/user/1100
  user@1000.service                    loaded active running User Manager for UID 1000
  user@1100.service                    loaded active running User Manager for UID 1100

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.

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

PATH (バックアップ)

/home/isucon/.cargo/bin:/home/isucon/.cargo/bin:/home/isucon/local/ruby/bin:/home/isucon/local/python/bin:/home/isucon/local/php/bin:/home/isucon/local/perl/bin:/home/isucon/local/node/bin:/home/isucon/local/go/bin:/home/isucon/go/bin:/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin:/usr/games:/usr/local/games:/snap/bin

pinkumohikan commented 1 month ago

初期スコア: 1,500ちょい

pinkumohikan commented 1 month ago

kataribe

$ make kataribe
mkdir -p ~/kataribe-logs
sudo cp /var/log/nginx/access.log /tmp/last-access.log && sudo chmod 0666 /tmp/last-access.log
cat /tmp/last-access.log | kataribe -conf kataribe.toml > ~/kataribe-logs/$timestamp.log
cat ~/kataribe-logs/$timestamp.log | grep --after-context 20 "Top 20 Sort By Total"
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
28610  2862.031  0.1000  0.0055  0.003  0.100  0.101  0.101  0.103  0.118  242    0  28368    0          28          0          0         14  POST /api/condition/([a-z0-9-]+)
  685   293.378  0.4283  0.4765  0.003  0.063  1.001  1.001  1.001  1.006  391    0    294    0    39994893          0      58386     743417  GET /\?jwt=(.+)
  162   118.718  0.7328  0.3913  0.003  1.000  1.001  1.001  1.003  1.008   47    0    115    0        5714          0         35        136  POST /api/isu HTTP/2.0
   68    37.476  0.5511  0.4773  0.003  1.000  1.001  1.001  1.002  1.002   16    0     52    0         184          0          2         19  POST /api/auth HTTP/2.0
  128    24.376  0.1904  0.2418  0.003  0.106  0.658  0.718  0.915  0.979  108    0     20    0     1513008         14      11820     135259  GET /api/isu([a-z0-9-]+)
   16     3.419  0.2137  0.3206  0.004  0.086  1.000  1.000  1.000  1.000   15    0      1    0      291255          0      18203      33236  GET /api/isu([a-z0-9-]+)/icon
   15     0.561  0.0374  0.0852  0.003  0.004  0.231  0.276  0.276  0.276   12    0      3    0       20814          2       1387       5229  GET /api/condition/([a-z0-9-]+)
    7     0.433  0.0619  0.1228  0.003  0.003  0.359  0.359  0.359  0.359    3    0      4    0          84          0         12         21  POST /api/signout HTTP/2.0
    1     0.303  0.3030  0.0000  0.303  0.303  0.303  0.303  0.303  0.303    1    0      0    0          18         18         18         18  POST /initialize HTTP/2.0
pinkumohikan commented 1 month ago

php実装に切り替え

11:48:27.747763 score: 959(1000 - 41) : pass 11:48:27.747775 deduction: 0 / timeout: 415

finger-ease commented 1 month ago

mysql slow query log

MariaDB [isucondition]> show variables like 'slow_query%';
+---------------------+-------------------------+
| Variable_name       | Value                   |
+---------------------+-------------------------+
| slow_query_log      | ON                      |
| slow_query_log_file | /var/log/mysql/slow.log |
+---------------------+-------------------------+
2 rows in set (0.001 sec)

MariaDB [isucondition]> show variables like 'long_query%';
+-----------------+----------+
| Variable_name   | Value    |
+-----------------+----------+
| long_query_time | 0.000000 |
+-----------------+----------+
1 row in set (0.000 sec)
pinkumohikan commented 1 month ago

ベンチ中のtop

image
pinkumohikan commented 1 month ago

このあとやること

finger-ease commented 1 month ago

slow query log 設定後

12:02:45.874341 score: 959(1000 - 41) : pass
12:02:45.874351 deduction: 0 / timeout: 418
finger-ease commented 1 month ago

スロークエリログ解析


# 2.4s user time, 20ms system time, 41.08M rss, 391.60G vsz
# Current date: Sat Oct  5 12:55:04 2024
# Hostname: nishinoshinoMBP.AirPort
# Files: slow.log
# Overall: 50.34k total, 97 unique, 324.75 QPS, 0.12x concurrency ________
# Time range: 2024-10-05 12:51:14 to 12:53:49
# Attribute          total     min     max     avg     95%  stddev  median
# ============     ======= ======= ======= ======= ======= ======= =======
# Exec time            19s       0    93ms   369us     3ms     1ms    23us
# Lock time          753ms       0     8ms    14us    36us    60us       0
# Rows sent         13.00k       0      72    0.26    0.99    2.59       0
# Rows examine      14.79M       0  19.59k  308.06       0   1.92k       0
# Rows affecte      19.76k       0     618    0.40    0.99    2.68       0
# Bytes sent        49.35M       0 646.78k   1.00k   88.31  11.43k   10.84
# Query size         8.73M       6 790.36k  181.77  258.32   3.58k   26.08
# Boolean:
# QC hit         6% yes,  93% no

# Profile
# Rank Query ID                            Response time Calls R/Call V/M 
# ==== =================================== ============= ===== ====== ====
#    1 0x8155B89FFD74A9D523D19AC409FD97AF   9.0966 48.9%  1405 0.0065  0.00 SELECT isu_condition
#    2 0xFFFCA4D67EA0A788813031B8BBC3B329   7.0809 38.0%  2256 0.0031  0.00 COMMIT
#    3 0xB8B32624C3268C0925657C305C0ED778   1.4485  7.8% 19450 0.0001  0.00 INSERT isu_condition
#    4 0xFFF66E9B3D962FA319C8068B5C1997CD   0.3214  1.7%   104 0.0031  0.00 ROLLBACK
# MISC 0xMISC                               0.6631  3.6% 27121 0.0000   0.0 <93 ITEMS>

# Query 1: 21.95 QPS, 0.14x concurrency, ID 0x8155B89FFD74A9D523D19AC409FD97AF at byte 19337921
# This item is included in the report because it matches --limit.
# Scores: V/M = 0.00
# Time range: 2024-10-05 12:52:45 to 12:53:49
# Attribute    pct   total     min     max     avg     95%  stddev  median
# ============ === ======= ======= ======= ======= ======= ======= =======
# Count          2    1405
# Exec time     48      9s   226us    24ms     6ms    13ms     4ms     6ms
# Lock time      8    60ms    20us     4ms    43us    66us   105us    31us
# Rows sent     10   1.37k       0       1    1.00    0.99    0.05    0.99
# Rows examine  99  14.72M     619  19.59k  10.73k  18.47k   5.00k  10.80k
# Rows affecte   0       0       0       0       0       0       0       0
# Bytes sent     2   1.02M     589     788  763.99  755.64   18.18  755.64
# Query size     1 171.51k     125     125     125     125       0     125
# String:
# Databases    isucondition
# Hosts        localhost
# Users        isucon
# Query_time distribution
#   1us
#  10us
# 100us  ##
#   1ms  ################################################################
#  10ms  ###############
# 100ms
#    1s
#  10s+
# Tables
#    SHOW TABLE STATUS FROM `isucondition` LIKE 'isu_condition'\G
#    SHOW CREATE TABLE `isucondition`.`isu_condition`\G
# EXPLAIN /*!50100 PARTITIONS*/
SELECT * FROM `isu_condition` WHERE `jia_isu_uuid` = '6aef4e86-226c-4111-9e27-599d8175b0be' ORDER BY `timestamp` DESC LIMIT 1\G

# Query 2: 35.25 QPS, 0.11x concurrency, ID 0xFFFCA4D67EA0A788813031B8BBC3B329 at byte 10861769
# This item is included in the report because it matches --limit.
# Scores: V/M = 0.00
# Time range: 2024-10-05 12:52:45 to 12:53:49
# Attribute    pct   total     min     max     avg     95%  stddev  median
# ============ === ======= ======= ======= ======= ======= ======= =======
# Count          4    2256
# Exec time     38      7s     8us    23ms     3ms     6ms     2ms     3ms
# Lock time      0       0       0       0       0       0       0       0
# Rows sent      0       0       0       0       0       0       0       0
# Rows examine   0       0       0       0       0       0       0       0
# Rows affecte   0       0       0       0       0       0       0       0
# Bytes sent     0  24.23k      11      11      11      11       0      11
# Query size     0  13.22k       6       6       6       6       0       6
# String:
# Databases    isucondition
# Hosts        localhost
# Users        isucon
# Query_time distribution
#   1us  #
#  10us  #####
# 100us  ###
#   1ms  ################################################################
#  10ms  #
# 100ms
#    1s
#  10s+
COMMIT\G

# Query 3: 318.85 QPS, 0.02x concurrency, ID 0xB8B32624C3268C0925657C305C0ED778 at byte 5159138
# This item is included in the report because it matches --limit.
# Scores: V/M = 0.00
# Time range: 2024-10-05 12:52:48 to 12:53:49
# Attribute    pct   total     min     max     avg     95%  stddev  median
# ============ === ======= ======= ======= ======= ======= ======= =======
# Count         38   19450
# Exec time      7      1s    34us    14ms    74us    98us   226us    57us
# Lock time     75   572ms    14us   816us    29us    40us    11us    26us
# Rows sent      0       0       0       0       0       0       0       0
# Rows examine   0       0       0       0       0       0       0       0
# Rows affecte  96  18.99k       1       1       1       1       0       1
# Bytes sent     0 246.92k      13      13      13      13       0      13
# Query size    54   4.77M     227     280  257.24  271.23   10.39  258.32
# String:
# Databases    isucondition
# Hosts        localhost
# Users        isucon
# Query_time distribution
#   1us
#  10us  ################################################################
# 100us  ###
#   1ms  #
#  10ms  #
# 100ms
#    1s
#  10s+
# Tables
#    SHOW TABLE STATUS FROM `isucondition` LIKE 'isu_condition'\G
#    SHOW CREATE TABLE `isucondition`.`isu_condition`\G
INSERT INTO `isu_condition` (`jia_isu_uuid`, `timestamp`, `is_sitting`, `condition`, `message`) VALUES ('af5e94a2-1915-47d0-bc89-5517fbc7bb97', '2021-08-12 22:43:22', '0', 'is_dirty=true,is_overweight=false,is_broken=false', 'キレイにして...')\G

# Query 4: 1.65 QPS, 0.01x concurrency, ID 0xFFF66E9B3D962FA319C8068B5C1997CD at byte 12778294
# This item is included in the report because it matches --limit.
# Scores: V/M = 0.00
# Time range: 2024-10-05 12:52:46 to 12:53:49
# Attribute    pct   total     min     max     avg     95%  stddev  median
# ============ === ======= ======= ======= ======= ======= ======= =======
# Count          0     104
# Exec time      1   321ms    14us    11ms     3ms     5ms     1ms     3ms
# Lock time      0       0       0       0       0       0       0       0
# Rows sent      0       0       0       0       0       0       0       0
# Rows examine   0       0       0       0       0       0       0       0
# Rows affecte   0       0       0       0       0       0       0       0
# Bytes sent     0   1.12k      11      11      11      11       0      11
# Query size     0     832       8       8       8       8       0       8
# String:
# Databases    isucondition
# Hosts        localhost
# Users        isucon
# Query_time distribution
#   1us
#  10us  #####
# 100us  #
#   1ms  ################################################################
#  10ms  #
# 100ms
#    1s
#  10s+
ROLLBACK\G
finger-ease commented 1 month ago

SELECT isu_condition 解析

MariaDB [isucondition]> SHOW TABLE STATUS FROM `isucondition` LIKE 'isu_condition'\G
*************************** 1. row ***************************
            Name: isu_condition
          Engine: InnoDB
         Version: 10
      Row_format: Dynamic
            Rows: 20118
  Avg_row_length: 183
     Data_length: 3686400
 Max_data_length: 0
    Index_length: 0
       Data_free: 4194304
  Auto_increment: 20069
     Create_time: 2024-10-05 12:52:40
     Update_time: 2024-10-05 12:53:49
      Check_time: NULL
       Collation: utf8mb4_general_ci
        Checksum: NULL
  Create_options: 
         Comment: 
Max_index_length: 0
       Temporary: N
1 row in set (0.000 sec)

MariaDB [isucondition]> SHOW CREATE TABLE `isucondition`.`isu_condition`\G
*************************** 1. row ***************************
       Table: isu_condition
Create Table: CREATE TABLE `isu_condition` (
  `id` bigint(20) NOT NULL AUTO_INCREMENT,
  `jia_isu_uuid` char(36) NOT NULL,
  `timestamp` datetime NOT NULL,
  `is_sitting` tinyint(1) NOT NULL,
  `condition` varchar(255) NOT NULL,
  `message` varchar(255) NOT NULL,
  `created_at` datetime(6) DEFAULT current_timestamp(6),
  PRIMARY KEY (`id`)
) ENGINE=InnoDB AUTO_INCREMENT=20069 DEFAULT CHARSET=utf8mb4
1 row in set (0.000 sec)

MariaDB [isucondition]> EXPLAIN /*!50100 PARTITIONS*/
    -> SELECT * FROM `isu_condition` WHERE `jia_isu_uuid` = '6aef4e86-226c-4111-9e27-599d8175b0be' ORDER BY `timestamp` DESC LIMIT 1\G
*************************** 1. row ***************************
           id: 1
  select_type: SIMPLE
        table: isu_condition
   partitions: NULL
         type: ALL
possible_keys: NULL
          key: NULL
      key_len: NULL
          ref: NULL
         rows: 20118
        Extra: Using where; Using filesort
1 row in set (0.001 sec)
finger-ease commented 1 month ago

isu_condition に Index を追加

$ make gogo
sudo systemctl stop nginx
sudo systemctl stop isucondition.php
sudo systemctl stop mysql
sudo journalctl --vacuum-size=1K
Vacuuming done, freed 0B of archived journals from /run/log/journal.
Vacuuming done, freed 0B of archived journals from /var/log/journal/0d79a55166af4dceb22c211c29e78bf4.
Vacuuming done, freed 0B of archived journals from /var/log/journal.
sudo truncate --size 0 /var/log/nginx/access.log
sudo truncate --size 0 /var/log/nginx/error.log
sudo truncate --size 0 /var/log/mysql/slow.log
sudo truncate --size 0 /var/log/mysql/error.log
sudo systemctl start mysql
sudo systemctl start isucondition.php
sudo systemctl start nginx
ssh isucon-bench "cd bench && ./bench -all-addresses 172.31.46.68 -target 172.31.46.68:443 -tls -jia-service-url http://172.31.41.25:4999"
12:01:38.864372 ISUCON11 benchmarker 
12:01:38.864528 ===> PREPARE
12:01:38.864537 start: load initial data
12:01:38.866827 finish: load initial data
12:01:45.866616 SCORE: 00.StartBenchmark       : 0
12:01:45.866632 SCORE: 01.GraphGood            : 0
12:01:45.866637 SCORE: 02.GraphNormal          : 0
12:01:45.866692 ===> LOAD
12:01:45.866714 score: 0(0 - 0) : Score
12:01:45.866718 deduction: 0 / timeout: 0
12:01:45.866645 SCORE: 03.GraphBad             : 0
12:01:45.866649 SCORE: 04.GraphWorst           : 0
12:01:45.866653 SCORE: 05.TodayGraphGood       : 0
12:01:45.866656 SCORE: 06.TodayGraphNormal     : 0
12:01:45.866660 SCORE: 07.TodayGraphBad        : 0
12:01:45.866663 SCORE: 08.TodayGraphWorst      : 0
12:01:45.866674 SCORE: 09.ReadInfoCondition    : 0
12:01:45.866678 SCORE: 10.ReadWarningCondition : 0
12:01:45.866682 SCORE: 11.ReadCriticalCondition: 0
12:01:45.866685 SCORE: _1.IsuInitialize        : 0
12:01:45.866688 SCORE: _2.NormalUserInitialize : 0
12:01:45.866692 SCORE: _3.ViewerInitialize     : 0
12:01:45.866695 SCORE: _5.ViewerDropout        : 0
12:01:45.866699 SCORE: _6.RepairIsu            : 0
12:01:45.866701 LOAD INFO
  Language: php
  Campaign: None
12:01:45.866703 SCORE: _7.PostInfoCondition    : 0
12:01:45.866707 SCORE: _8.PostWarningCondition : 0
12:01:45.866710 SCORE: _9.PostCriticalCondition: 0
12:01:48.866782 score: 1000(1000 - 0) : pass
12:01:48.866809 deduction: 0 / timeout: 0
12:01:50.867633 ユーザーは増えませんでした
12:01:51.867093 score: 1000(1000 - 0) : pass
12:01:51.867107 deduction: 0 / timeout: 6
12:01:54.868083 score: 998(1000 - 2) : pass
12:01:54.868098 deduction: 0 / timeout: 29
12:01:55.868689 ユーザーは増えませんでした
12:01:57.869154 score: 995(1000 - 5) : pass
12:01:57.869168 deduction: 0 / timeout: 52
12:02:00.868658 SCORE: 00.StartBenchmark       : 1
12:02:00.868673 SCORE: 01.GraphGood            : 0
12:02:00.868677 SCORE: 02.GraphNormal          : 0
12:02:00.868680 SCORE: 03.GraphBad             : 0
12:02:00.868684 SCORE: 04.GraphWorst           : 0
12:02:00.868689 SCORE: 05.TodayGraphGood       : 0
12:02:00.868692 SCORE: 06.TodayGraphNormal     : 0
12:02:00.868696 SCORE: 07.TodayGraphBad        : 0
12:02:00.868699 SCORE: 08.TodayGraphWorst      : 0
12:02:00.868702 SCORE: 09.ReadInfoCondition    : 0
12:02:00.868706 SCORE: 10.ReadWarningCondition : 0
12:02:00.868709 SCORE: 11.ReadCriticalCondition: 0
12:02:00.868713 SCORE: _1.IsuInitialize        : 43
12:02:00.868717 SCORE: _2.NormalUserInitialize : 4
12:02:00.868720 SCORE: _3.ViewerInitialize     : 1
12:02:00.868724 SCORE: _5.ViewerDropout        : 1
12:02:00.868727 SCORE: _6.RepairIsu            : 0
12:02:00.868732 SCORE: _7.PostInfoCondition    : 224
12:02:00.868736 SCORE: _8.PostWarningCondition : 784
12:02:00.868739 SCORE: _9.PostCriticalCondition: 133
12:02:00.869939 score: 993(1000 - 7) : pass
12:02:00.869952 deduction: 0 / timeout: 75
12:02:00.870078 タイムアウト数が多いため、サービスの評判が悪くなりました。以降ユーザーは増加しません
12:02:00.870088 --- userAdder END
12:02:00.870091 defer s.loadWaitGroup.Done() userAdder
12:02:03.870853 score: 991(1000 - 9) : pass
12:02:03.870870 deduction: 0 / timeout: 98
12:02:06.871777 score: 988(1000 - 12) : pass
12:02:06.871790 deduction: 0 / timeout: 121
12:02:09.872616 score: 986(1000 - 14) : pass
12:02:09.872630 deduction: 0 / timeout: 144
12:02:12.874021 score: 984(1000 - 16) : pass
12:02:12.874034 deduction: 0 / timeout: 166
12:02:15.872321 SCORE: 00.StartBenchmark       : 1
12:02:15.872336 SCORE: 01.GraphGood            : 0
12:02:15.872340 SCORE: 02.GraphNormal          : 0
12:02:15.872343 SCORE: 03.GraphBad             : 0
12:02:15.872346 SCORE: 04.GraphWorst           : 0
12:02:15.872348 SCORE: 05.TodayGraphGood       : 0
12:02:15.872351 SCORE: 06.TodayGraphNormal     : 0
12:02:15.872354 SCORE: 07.TodayGraphBad        : 0
12:02:15.872356 SCORE: 08.TodayGraphWorst      : 0
12:02:15.872359 SCORE: 09.ReadInfoCondition    : 0
12:02:15.872362 SCORE: 10.ReadWarningCondition : 0
12:02:15.872364 SCORE: 11.ReadCriticalCondition: 0
12:02:15.872367 SCORE: _1.IsuInitialize        : 43
12:02:15.872370 SCORE: _2.NormalUserInitialize : 4
12:02:15.872372 SCORE: _3.ViewerInitialize     : 1
12:02:15.872375 SCORE: _5.ViewerDropout        : 1
12:02:15.872377 SCORE: _6.RepairIsu            : 0
12:02:15.872381 SCORE: _7.PostInfoCondition    : 224
12:02:15.872384 SCORE: _8.PostWarningCondition : 1321
12:02:15.872387 SCORE: _9.PostCriticalCondition: 1047
12:02:15.874875 score: 982(1000 - 18) : pass
12:02:15.874885 deduction: 0 / timeout: 189
12:02:18.876637 score: 979(1000 - 21) : pass
12:02:18.876654 deduction: 0 / timeout: 212
12:02:21.877478 score: 977(1000 - 23) : pass
12:02:21.877492 deduction: 0 / timeout: 235
12:02:24.878872 score: 975(1000 - 25) : pass
12:02:24.878887 deduction: 0 / timeout: 258
12:02:27.879248 score: 972(1000 - 28) : pass
12:02:27.879262 deduction: 0 / timeout: 280
12:02:30.876484 SCORE: 00.StartBenchmark       : 1
12:02:30.876499 SCORE: 01.GraphGood            : 0
12:02:30.876502 SCORE: 02.GraphNormal          : 0
12:02:30.876505 SCORE: 03.GraphBad             : 0
12:02:30.876508 SCORE: 04.GraphWorst           : 0
12:02:30.876511 SCORE: 05.TodayGraphGood       : 0
12:02:30.876514 SCORE: 06.TodayGraphNormal     : 0
12:02:30.876517 SCORE: 07.TodayGraphBad        : 0
12:02:30.876519 SCORE: 08.TodayGraphWorst      : 0
12:02:30.876522 SCORE: 09.ReadInfoCondition    : 0
12:02:30.876525 SCORE: 10.ReadWarningCondition : 0
12:02:30.876527 SCORE: 11.ReadCriticalCondition: 0
12:02:30.876530 SCORE: _1.IsuInitialize        : 43
12:02:30.876533 SCORE: _2.NormalUserInitialize : 4
12:02:30.876535 SCORE: _3.ViewerInitialize     : 1
12:02:30.876537 SCORE: _5.ViewerDropout        : 1
12:02:30.876540 SCORE: _6.RepairIsu            : 0
12:02:30.876544 SCORE: _7.PostInfoCondition    : 224
12:02:30.876546 SCORE: _8.PostWarningCondition : 1411
12:02:30.876549 SCORE: _9.PostCriticalCondition: 2418
12:02:30.880466 score: 970(1000 - 30) : pass
12:02:30.880476 deduction: 0 / timeout: 303
12:02:33.881554 score: 968(1000 - 32) : pass
12:02:33.881569 deduction: 0 / timeout: 326
12:02:36.882369 score: 966(1000 - 34) : pass
12:02:36.882382 deduction: 0 / timeout: 349
12:02:39.882916 score: 963(1000 - 37) : pass
12:02:39.882930 deduction: 0 / timeout: 372
12:02:42.883794 score: 961(1000 - 39) : pass
12:02:42.883809 deduction: 0 / timeout: 395
12:02:45.867282 LOAD WAIT
12:02:45.867308 defer s.loadWaitGroup.Done() keepPosting
12:02:45.867321 defer s.loadWaitGroup.Done() keepPosting
12:02:45.867346 defer s.loadWaitGroup.Done() keepPosting
12:02:45.867377 defer s.loadWaitGroup.Done() keepPosting
12:02:45.867432 defer s.loadWaitGroup.Done() keepPosting
12:02:45.867451 defer s.loadWaitGroup.Done() keepPosting
12:02:45.867492 defer s.loadWaitGroup.Done() keepPosting
12:02:45.867532 defer s.loadWaitGroup.Done() loadErrorCheck
12:02:45.867554 defer s.loadWaitGroup.Done() keepPosting
12:02:45.867574 defer s.loadWaitGroup.Done() keepPostingError
12:02:45.867581 defer s.loadWaitGroup.Done() keepPosting
12:02:45.867634 defer s.loadWaitGroup.Done() keepPosting
12:02:45.867648 defer s.loadWaitGroup.Done() keepPosting
12:02:45.867704 defer s.loadWaitGroup.Done() keepPosting
12:02:45.867749 defer s.loadWaitGroup.Done() AddNormalUser
12:02:45.867774 defer s.loadWaitGroup.Done() keepPosting
12:02:45.867808 defer s.loadWaitGroup.Done() keepPosting
12:02:45.867856 defer s.loadWaitGroup.Done() keepPosting
12:02:45.867907 defer s.loadWaitGroup.Done() AddNormalUser
12:02:45.868073 defer s.loadWaitGroup.Done() keepPosting
12:02:45.867948 defer s.loadWaitGroup.Done() AddNormalUser
12:02:45.867977 defer s.loadWaitGroup.Done() AddNormalUser
12:02:45.867985 defer s.loadWaitGroup.Done() keepPosting
12:02:45.868010 defer s.loadWaitGroup.Done() keepPosting
12:02:45.867944 defer s.loadWaitGroup.Done() keepPosting
12:02:45.868080 defer s.loadWaitGroup.Done() AddIsuconUser
12:02:45.868082 defer s.loadWaitGroup.Done() AddNormalUser
12:02:45.868172 defer s.loadWaitGroup.Done() keepPosting
12:02:45.868222 defer s.loadWaitGroup.Done() keepPosting
12:02:45.868241 defer s.loadWaitGroup.Done() keepPosting
12:02:45.868245 defer s.loadWaitGroup.Done() keepPosting
12:02:45.868296 defer s.loadWaitGroup.Done() keepPosting
12:02:45.868306 defer s.loadWaitGroup.Done() keepPosting
12:02:45.868328 defer s.loadWaitGroup.Done() keepPosting
12:02:45.868358 defer s.loadWaitGroup.Done() keepPosting
12:02:45.868376 defer s.loadWaitGroup.Done() AddNormalUser
12:02:45.868394 defer s.loadWaitGroup.Done() keepPosting
12:02:45.868394 defer s.loadWaitGroup.Done() keepPosting
12:02:45.868408 defer s.loadWaitGroup.Done() keepPosting
12:02:45.868421 defer s.loadWaitGroup.Done() keepPosting
12:02:45.868434 defer s.loadWaitGroup.Done() keepPosting
12:02:45.868457 defer s.loadWaitGroup.Done() keepPosting
12:02:45.868472 defer s.loadWaitGroup.Done() keepPosting
12:02:45.868490 defer s.loadWaitGroup.Done() keepPosting
12:02:45.868506 defer s.loadWaitGroup.Done() keepPosting
12:02:45.868539 defer s.loadWaitGroup.Done() keepPosting
12:02:45.868551 defer s.loadWaitGroup.Done() keepPosting
12:02:45.868597 defer s.loadWaitGroup.Done() keepPosting
12:02:45.868616 defer s.loadWaitGroup.Done() keepPosting
12:02:45.868637 defer s.loadWaitGroup.Done() keepPosting
12:02:45.868691 defer s.loadWaitGroup.Done() keepPosting
12:02:45.868732 defer s.loadWaitGroup.Done() keepPosting
12:02:45.868700 defer s.loadWaitGroup.Done() keepPosting
12:02:45.868700 defer s.loadWaitGroup.Done() keepPosting
12:02:45.868707 defer s.loadWaitGroup.Done() keepPosting
12:02:45.868758 defer s.loadWaitGroup.Done() keepPosting
12:02:45.868762 defer s.loadWaitGroup.Done() keepPosting
12:02:45.868763 defer s.loadWaitGroup.Done() keepPosting
12:02:45.868827 end s.loadWaitGroup.Wait()
12:02:45.868830 <=== LOAD END
12:02:45.868910 SCORE: 00.StartBenchmark       : 1
12:02:45.868920 SCORE: 01.GraphGood            : 0
12:02:45.868923 SCORE: 02.GraphNormal          : 0
12:02:45.868926 SCORE: 03.GraphBad             : 0
12:02:45.868929 SCORE: 04.GraphWorst           : 0
12:02:45.868933 SCORE: 05.TodayGraphGood       : 0
12:02:45.868935 SCORE: 06.TodayGraphNormal     : 0
12:02:45.868938 SCORE: 07.TodayGraphBad        : 0
12:02:45.868941 SCORE: 08.TodayGraphWorst      : 0
12:02:45.868943 SCORE: 09.ReadInfoCondition    : 0
12:02:45.868946 SCORE: 10.ReadWarningCondition : 0
12:02:45.868997 SCORE: 00.StartBenchmark       : 1
12:02:45.869001 SCORE: 01.GraphGood            : 0
12:02:45.869003 SCORE: 02.GraphNormal          : 0
12:02:45.869006 SCORE: 03.GraphBad             : 0
12:02:45.868965 SCORE: 11.ReadCriticalCondition: 0
12:02:45.868968 SCORE: _1.IsuInitialize        : 43
12:02:45.868970 SCORE: _2.NormalUserInitialize : 4
12:02:45.868973 SCORE: _3.ViewerInitialize     : 1
12:02:45.868976 SCORE: _5.ViewerDropout        : 1
12:02:45.868980 SCORE: _6.RepairIsu            : 0
12:02:45.868985 SCORE: _7.PostInfoCondition    : 224
12:02:45.868989 SCORE: _8.PostWarningCondition : 1411
12:02:45.868993 SCORE: _9.PostCriticalCondition: 3872
12:02:45.869039 SCORE: 04.GraphWorst           : 0
12:02:45.869042 SCORE: 05.TodayGraphGood       : 0
12:02:45.869045 SCORE: 06.TodayGraphNormal     : 0
12:02:45.869047 SCORE: 07.TodayGraphBad        : 0
12:02:45.869049 SCORE: 08.TodayGraphWorst      : 0
12:02:45.869051 SCORE: 09.ReadInfoCondition    : 0
12:02:45.869053 SCORE: 10.ReadWarningCondition : 0
12:02:45.869055 SCORE: 11.ReadCriticalCondition: 0
12:02:45.874341 score: 959(1000 - 41) : pass
12:02:45.874351 deduction: 0 / timeout: 418
12:02:45.874359 <=== sendResult finish

スコア変わらず。DBがボトルネックではないかも？

finger-ease commented 1 month ago

SELECT isu_condition は改善した

# 2.4s user time, 20ms system time, 44.77M rss, 391.84G vsz
# Current date: Sat Oct  5 13:45:08 2024
# Hostname: nishinoshinoMBP.AirPort
# Files: slow.log
# Overall: 51.38k total, 95 unique, 667.34 QPS, 0.14x concurrency ________
# Time range: 2024-10-05 13:39:57 to 13:41:14
# Attribute          total     min     max     avg     95%  stddev  median
# ============     ======= ======= ======= ======= ======= ======= =======
# Exec time            11s       0    97ms   205us   301us   895us    33us
# Lock time          806ms       0     6ms    15us    44us    53us       0
# Rows sent         14.33k       0      90    0.29    0.99    2.82       0
# Rows examine      10.17k       0     122    0.20       0    2.98       0
# Rows affecte      20.73k       0     618    0.41    0.99    2.66       0
# Bytes sent        45.14M       0 223.00k  921.14   62.76  10.13k   10.84
# Query size         8.57M       6 790.36k  174.95  271.23   3.54k   49.17
# Boolean:
# QC hit         6% yes,  93% no

# Profile
# Rank Query ID                            Response time Calls R/Call V/M 
# ==== =================================== ============= ===== ====== ====
#    1 0xFFFCA4D67EA0A788813031B8BBC3B329   7.6272 72.4%  2316 0.0033  0.00 COMMIT
#    2 0xB8B32624C3268C0925657C305C0ED778   1.8758 17.8% 20448 0.0001  0.00 INSERT isu_condition
#    3 0x8155B89FFD74A9D523D19AC409FD97AF   0.1879  1.8%  1144 0.0002  0.00 SELECT isu_condition
#    4 0xFFF66E9B3D962FA319C8068B5C1997CD   0.1678  1.6%    59 0.0028  0.00 ROLLBACK
#    5 0x27AA5037BCA3145593C643E21671646B   0.1011  1.0%    98 0.0010  0.00 INSERT isu
#    6 0x655E93F30F576321245A814D06B07CEB   0.0974  0.9%     1 0.0974  0.00 INSERT isu
# MISC 0xMISC                               0.4813  4.6% 27319 0.0000   0.0 <89 ITEMS>
pinkumohikan commented 1 month ago

opcache有効化

変わらず

14:08:37.041067 score: 959(1000 - 41) : pass
14:08:37.041078 deduction: 0 / timeout: 416
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
28533  2854.763  0.1001  0.0058  0.000  0.100  0.101  0.102  0.103  0.118  210    0  28323    0          42          0          0         14  POST /api/condition/([a-z0-9-]+)
  288   271.549  0.9429  0.2146  0.003  1.000  1.001  1.001  1.004  1.005   15    0    273    0       10172          0         35       2469  GET /api/isu HTTP/2.0
  162   119.671  0.7387  0.3865  0.004  1.000  1.001  1.001  1.002  1.003   47    0    115    0        5745          0         35        136  POST /api/isu HTTP/2.0
  166    38.454  0.2317  0.2918  0.003  0.098  0.819  0.934  1.000  1.001  140    0     26    0     1704865          0      10270     135259  GET /api/isu([a-z0-9-]+)
   68    36.702  0.5397  0.4754  0.003  1.000  1.001  1.001  1.002  1.002   16    0     52    0         184          0          2         19  POST /api/auth HTTP/2.0
   10     2.726  0.2726  0.2167  0.004  0.236  0.618  0.618  0.618  0.618   10    0      0    0      248269       6787      24826      82854  GET /api/isu([a-z0-9-]+)/icon
   29     1.980  0.0683  0.2074  0.003  0.004  0.381  0.485  1.001  1.001   21    0      8    0       40886          0       1409       5420  GET /api/condition/([a-z0-9-]+)
   48     1.086  0.0226  0.0234  0.007  0.014  0.068  0.088  0.105  0.105   48    0      0    0    35684016     743417     743417     743417  GET /assets/vendor.ee7444dd.js HTTP/2.0
   48     0.963  0.0201  0.0231  0.005  0.013  0.057  0.093  0.097  0.097   48    0      0    0       28416        592        592        592  GET /assets/favicon.d0f5f504.svg HTTP/2.0
   48     0.950  0.0198  0.0221  0.005  0.012  0.067  0.076  0.096  0.096   48    0      0    0     1280016      26667      26667      26667  GET /assets/index.23dac98b.js HTTP/2.0
   48     0.847  0.0176  0.0327  0.003  0.003  0.073  0.088  0.161  0.161   48    0      0    0      157680       3285       3285       3285  GET /assets/logo_white.svg HTTP/2.0
    9     0.831  0.0923  0.0389  0.025  0.103  0.139  0.139  0.139  0.139    9    0      0    0       24208       2661       2689       2698  GET /api/trend HTTP/2.0
   48     0.816  0.0170  0.0204  0.005  0.009  0.056  0.073  0.089  0.089   48    0      0    0      915168      19066      19066      19066  GET /assets/index.144d8ca8.css HTTP/2.0
   11     0.515  0.0468  0.0350  0.004  0.054  0.094  0.096  0.096  0.096   11    0      0    0       36168       3288       3288       3288  GET /assets/logo_orange.svg HTTP/2.0
   11     0.470  0.0427  0.0350  0.003  0.048  0.086  0.108  0.108  0.108   11    0      0    0        5808        528        528        528  GET /
   12     0.309  0.0257  0.0196  0.003  0.029  0.043  0.073  0.073  0.073   10    0      2    0         361         21         30         36  GET /api/user/me HTTP/2.0
    1     0.299  0.2990  0.0000  0.299  0.299  0.299  0.299  0.299  0.299    1    0      0    0          18         18         18         18  POST /initialize HTTP/2.0
   15     0.222  0.0148  0.0190  0.003  0.009  0.034  0.079  0.079  0.079   15    0      0    0        7920        528        528        528  GET / HTTP/2.0
    6     0.084  0.0140  0.0242  0.003  0.003  0.068  0.068  0.068  0.068    2    0      4    0          84          0         14         21  POST /api/signout HTTP/2.0
pinkumohikan commented 1 month ago

ベンチ中の様子

image
finger-ease commented 1 month ago

postIsuCondition N+1 解消

31822df9c6ba07cecb6bc8c0d62acae3b9201b2a

bench

15:46:16.765162 score: 957(1000 - 43) : pass
15:46:16.765174 deduction: 1 / timeout: 424

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
28649  2869.851  0.1002  0.0049  0.003  0.100  0.101  0.101  0.102  0.112  170    0  28479    0          28          0          0         14  POST /api/condition/([a-z0-9-]+)
  236   219.577  0.9304  0.2380  0.003  1.000  1.001  1.001  1.001  1.004   15    0    221    0        9227          0         39       2222  GET /api/isu HTTP/2.0
  279   146.732  0.5259  0.4403  0.003  0.472  1.001  1.001  1.001  1.001  139    0    140    0     1730283          0       6201     135259  GET /api/isu([a-z0-9-]+)
   61    54.178  0.8882  0.3122  0.003  1.000  1.001  1.001  1.002  1.002    2    0     59    0          84          0          1         21  POST /api/signout HTTP/2.0
   67    36.705  0.5478  0.4742  0.004  1.000  1.001  1.001  1.001  1.001   16    0     51    0         184          0          2         19  POST /api/auth HTTP/2.0
   53    10.789  0.2036  0.1919  0.004  0.156  0.406  0.712  0.989  0.989   49    0      4    0        5945         15        112        139  POST /api/isu HTTP/2.0
   29     2.558  0.0882  0.2584  0.003  0.005  0.399  1.000  1.000  1.000   20    0      9    0       41243          0       1422       5420  GET /api/condition/([a-z0-9-]+)
    8     1.876  0.2345  0.2962  0.003  0.147  1.000  1.000  1.000  1.000    7    0      1    0      172413          0      21551      82854  GET /api/isu([a-z0-9-]+)/icon
   15     0.736  0.0491  0.1145  0.003  0.011  0.113  0.466  0.466  0.466   15    0      0    0        7920        528        528        528  GET / HTTP/2.0
    9     0.654  0.0727  0.0282  0.022  0.079  0.109  0.109  0.109  0.109    9    0      0    0       24201       2661       2689       2697  GET /api/trend HTTP/2.0
   11     0.351  0.0319  0.0244  0.004  0.034  0.058  0.084  0.084  0.084   11    0      0    0        5808        528        528        528  GET /
   12     0.326  0.0272  0.0298  0.003  0.022  0.038  0.118  0.118  0.118   10    0      2    0         346         21         28         36  GET /api/user/me HTTP/2.0
    1     0.306  0.3060  0.0000  0.306  0.306  0.306  0.306  0.306  0.306    1    0      0    0          18         18         18         18  POST /initialize HTTP/2.0
    3     0.012  0.0040  0.0008  0.003  0.004  0.005  0.005  0.005  0.005    3    0      0    0        1584        528        528        528  GET /isu/eb104b95-3532-4828-8550-89da717b9667/condition HTTP/2.0
    3     0.011  0.0037  0.0009  0.003  0.003  0.005  0.005  0.005  0.005    3    0      0    0        1584        528        528        528  GET /isu/b82dcff4-8fae-4773-9956-22ab354adb7e/condition HTTP/2.0
    3     0.011  0.0037  0.0009  0.003  0.003  0.005  0.005  0.005  0.005    3    0      0    0        1584        528        528        528  GET /isu/15063e10-26fc-4dac-ae3a-1f195e0c6c4a/condition HTTP/2.0
    3     0.010  0.0033  0.0005  0.003  0.003  0.004  0.004  0.004  0.004    3    0      0    0        1584        528        528        528  GET /isu/8469e6f6-0d29-4052-87cf-dd9bfde45014/condition HTTP/2.0
    3     0.010  0.0033  0.0005  0.003  0.003  0.004  0.004  0.004  0.004    3    0      0    0        1584        528        528        528  GET /register HTTP/2.0
    3     0.010  0.0033  0.0005  0.003  0.003  0.004  0.004  0.004  0.004    3    0      0    0        1584        528        528        528  GET /isu/c648b087-fe00-4ea2-a524-b2e80555893f/condition HTTP/2.0

変わらず

pinkumohikan commented 1 month ago

xdebug無効化

/home/isucon/local/php/etc/php.ini

+ [xdebug]
+ xdebug.mode=off

スコア

16:18:41.215262 score: 2614(2620 - 6) : pass
16:18:41.215272 deduction: 0 / timeout: 62
pinkumohikan commented 1 month ago

opcache有効化

/home/isucon/local/php/etc/php.ini

opcache.enable=1
opcache.enable_cli=1
opcache.max_accelerated_files=100000
opcache.validate_timestamps=1
opcache.revalidate_freq=2

スコア

16:16:20.299619 score: 3676(3678 - 2) : pass
16:16:20.299627 deduction: 0 / timeout: 21
nishino-satoshi commented 1 month ago

isu_condition index 付与

16:28:02.913336 score: 3047(3050 - 3) : pass
16:28:02.913345 deduction: 0 / timeout: 32

(mainでやっても変わらず)

=> @pinkumohikan に計測してもらったら改善していた

nishino-satoshi commented 1 month ago

perf: isu_conditionテーブルにindexを追加

https://github.com/pinkumohikan/isucon-practice-20241005-isucon11q/pull/3

before

16:38:10.532318 score: 3693(3698 - 5) : pass
16:38:10.532328 deduction: 0 / timeout: 57

after

16:40:00.396328 score: 4137(4146 - 9) : pass
16:40:00.396337 deduction: 0 / timeout: 94
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
30023  3002.585  0.1000  0.0053  0.002  0.100  0.101  0.101  0.102  0.118   683    0  29340    0          14          0          0         14  POST /api/condition/([a-z0-9-]+)
 1204   423.361  0.3516  0.2637  0.002  0.266  0.694  0.980  1.000  1.346  1079    0    125    0    17864222          0      14837     135259  GET /api/isu([a-z0-9-]+)
  501   125.842  0.2512  0.2020  0.002  0.179  0.551  0.685  1.000  1.001   442    0     59    0     2087778          0       4167       6221  GET /api/condition/([a-z0-9-]+)
  139    64.105  0.4612  0.3448  0.002  0.367  1.000  1.000  1.001  1.002   117    0     22    0      282229          0       2030       3761  GET /api/isu HTTP/2.0
   66    42.746  0.6477  0.3343  0.022  0.737  1.000  1.001  1.001  1.001    52    0     14    0      217597          0       3296       4536  GET /api/trend HTTP/2.0
  106    39.610  0.3737  0.2761  0.002  0.258  0.769  0.998  1.000  1.001    99    0      7    0     2308926          0      21782     135259  GET /api/isu([a-z0-9-]+)/icon
   79    33.081  0.4187  0.3131  0.001  0.458  0.848  0.982  0.997  0.997    77    0      2    0       40656          0        514        528  GET / HTTP/2.0
  115    32.487  0.2825  0.2390  0.002  0.185  0.594  0.613  0.865  1.000    50    0     65    0         736          0          6         19  POST /api/auth HTTP/2.0
   53    17.185  0.3242  0.2854  0.001  0.207  0.801  0.888  1.001  1.001    26    0     27    0        1322          0         24         37  GET /api/user/me HTTP/2.0
   32    10.562  0.3301  0.3090  0.002  0.196  0.836  0.972  1.001  1.001    19    0     13    0         252          0          7         21  POST /api/signout HTTP/2.0
   29     7.392  0.2549  0.2754  0.001  0.165  0.777  0.839  0.940  0.940    28    0      1    0       14784          0        509        528  GET /
   55     7.255  0.1319  0.0606  0.002  0.134  0.197  0.232  0.255  0.255    51    0      4    0        6101         15        110        142  POST /api/isu HTTP/2.0
    1     0.267  0.2670  0.0000  0.267  0.267  0.267  0.267  0.267  0.267     1    0      0    0          18         18         18         18  POST /initialize HTTP/2.0
   18     0.031  0.0017  0.0004  0.001  0.002  0.002  0.002  0.002  0.002    18    0      0    0        9504        528        528        528  GET /isu/([a-z0-9-]+)/condition
   39     0.015  0.0004  0.0009  0.000  0.000  0.001  0.001  0.005  0.005    39    0      0    0    28993263     743417     743417     743417  GET /assets/vendor.ee7444dd.js HTTP/2.0
    3     0.006  0.0020  0.0000  0.002  0.002  0.002  0.002  0.002  0.002     3    0      0    0        1584        528        528        528  GET /register HTTP/2.0
   39     0.005  0.0001  0.0003  0.000  0.000  0.001  0.001  0.001  0.001    39    0      0    0     1040013      26667      26667      26667  GET /assets/index.23dac98b.js HTTP/2.0
    1     0.003  0.0030  0.0000  0.003  0.003  0.003  0.003  0.003  0.003     1    0      0    0         528        528        528        528  GET /isu/b82dcff4-8fae-4773-9956-22ab354adb7e HTTP/2.0
   39     0.003  0.0001  0.0003  0.000  0.000  0.000  0.001  0.001  0.001    39    0      0    0       23088        592        592        592  GET /assets/favicon.d0f5f504.svg HTTP/2.0
pinkumohikan commented 1 month ago

slow query

# Query 1: 18.98 QPS, 0.05x concurrency, ID 0x931A992E852C61FC6D46141A39DEF4FE at byte 142186342
# Scores: V/M = 0.00
# Time range: 2024-10-05 15:57:28 to 16:40:00
# Attribute    pct   total     min     max     avg     95%  stddev  median
# ============ === ======= ======= ======= ======= ======= ======= =======
# Count          6   48432
# Exec time     50    134s     4us    47ms     3ms    10ms     4ms     1ms
# Lock time     17      1s       0     8ms    27us    52us    65us    22us
# Rows sent     84   5.34M       0     760  115.60  420.77  134.10   69.19
# Rows examine  71 273.05M       0  30.09k   5.77k  21.38k   6.87k   3.35k
# Rows affecte   0       0       0       0       0       0       0       0
# Bytes sent    35 977.28M     589 139.25k  20.66k  76.03k  23.69k  12.50k
# Query size     4   5.31M     115     115     115     115       0     115
# Boolean:
# QC hit        10% yes,  89% no
# String:
# Databases    isucondition
# Hosts        ip-172-31-46-68.ap-northeast-1.compute.inter...
# Users        isucon
# Query_time distribution
#   1us  #####
#  10us  ######
# 100us  ######################################
#   1ms  ################################################################
#  10ms  ######
# 100ms
#    1s
#  10s+
# Tables
#    SHOW TABLE STATUS FROM `isucondition` LIKE 'isu_condition'\G
#    SHOW CREATE TABLE `isucondition`.`isu_condition`\G
# EXPLAIN /*!50100 PARTITIONS*/
SELECT * FROM `isu_condition` WHERE `jia_isu_uuid` = '48b8339b-9123-4a75-b801-59b3079458d1' ORDER BY timestamp DESC\G

# Query 2: 11.33 QPS, 0.03x concurrency, ID 0xFFFCA4D67EA0A788813031B8BBC3B329 at byte 327259528
# Scores: V/M = 0.00
# Time range: 2024-10-05 15:57:28 to 16:40:00
# Attribute    pct   total     min     max     avg     95%  stddev  median
# ============ === ======= ======= ======= ======= ======= ======= =======
# Count          3   28924
# Exec time     24     65s     3us    36ms     2ms     3ms     1ms     2ms
# Lock time      0       0       0       0       0       0       0       0
# Rows sent      0       0       0       0       0       0       0       0
# Rows examine   0       0       0       0       0       0       0       0
# Rows affecte   0       0       0       0       0       0       0       0
# Bytes sent     0 310.71k      11      11      11      11       0      11
# Query size     0 169.48k       6       6       6       6       0       6
# String:
# Databases    isucondition
# Hosts        ip-172-31-46-68.ap-northeast-1.compute.inter...
# Users        isucon
# Query_time distribution
#   1us  #
#  10us  ######
# 100us  #
#   1ms  ################################################################
#  10ms  #
# 100ms
#    1s
#  10s+
COMMIT\G

# Query 3: 3.40 QPS, 0.01x concurrency, ID 0x8155B89FFD74A9D523D19AC409FD97AF at byte 215467974
# Scores: V/M = 0.00
# Time range: 2024-10-05 15:57:28 to 16:40:00
# Attribute    pct   total     min     max     avg     95%  stddev  median
# ============ === ======= ======= ======= ======= ======= ======= =======
# Count          1    8686
# Exec time      8     24s     5us    33ms     3ms     9ms     3ms     1ms
# Lock time      2   209ms       0   197us    24us    52us    16us    21us
# Rows sent      0   6.79k       0       1    0.80    0.99    0.40    0.99
# Rows examine  16  63.71M       0  30.09k   7.51k  22.45k   7.83k   4.27k
# Rows affecte   0       0       0       0       0       0       0       0
# Bytes sent     0   6.07M     589     812  732.56  755.64   75.96  755.64
# Query size     0   1.04M     125     125     125     125       0     125
# Boolean:
# QC hit        17% yes,  82% no
# String:
# Databases    isucondition
# Hosts        ip-172-31-46-68.ap-northeast-1.compute.inter...
# Users        isucon
# Query_time distribution
#   1us  ################
#  10us  ##################
# 100us  ####################
#   1ms  ################################################################
#  10ms  #####
# 100ms
#    1s
#  10s+
# Tables
#    SHOW TABLE STATUS FROM `isucondition` LIKE 'isu_condition'\G
#    SHOW CREATE TABLE `isucondition`.`isu_condition`\G
# EXPLAIN /*!50100 PARTITIONS*/
SELECT * FROM `isu_condition` WHERE `jia_isu_uuid` = '79575de6-0978-41de-a821-8f61b0435087' ORDER BY `timestamp` DESC LIMIT 1\G
nishino-satoshi commented 1 month ago

Insert を Bulk Insert にしてN+1問題を解消

benchmark

17:33:03.486308 score: 3498(3500 - 2) : pass
17:33:03.486318 deduction: 0 / timeout: 28

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
30987  3096.204  0.0999  0.0056  0.002  0.100  0.101  0.101  0.102  0.121   581    0  30406    0          14          0          0         14  POST /api/condition/([a-z0-9-]+)
 1078   423.370  0.3927  0.2464  0.001  0.408  0.716  0.752  0.863  1.001  1008    0     70    0    18056170          0      16749     135259  GET /api/isu([a-z0-9-]+)
  417   178.992  0.4292  0.2239  0.001  0.449  0.710  0.750  0.881  0.998   372    0     45    0     1691100          0       4055       6001  GET /api/condition/([a-z0-9-]+)
  174   124.502  0.7155  0.2753  0.022  0.788  1.000  1.001  1.001  1.001   150    0     24    0      658808          0       3786       4638  GET /api/trend HTTP/2.0
  184    92.832  0.5045  0.2430  0.001  0.567  0.764  0.834  0.986  0.987   184    0      0    0       97152        528        528        528  GET / HTTP/2.0
  114    43.164  0.3786  0.2431  0.002  0.394  0.723  0.782  0.874  0.928   108    0      6    0      240458          2       2109       3789  GET /api/isu HTTP/2.0
  103    38.428  0.3731  0.2346  0.002  0.396  0.687  0.741  0.856  0.863   101    0      2    0     2851932          0      27688     135259  GET /api/isu([a-z0-9-]+)/icon
   93    29.570  0.3180  0.2631  0.000  0.353  0.733  0.739  0.874  0.874    35    0     58    0         644          0          6         19  POST /api/auth HTTP/2.0
   58     8.972  0.1547  0.1220  0.002  0.126  0.268  0.509  0.686  0.686    54    0      4    0        6537         15        112        130  POST /api/isu HTTP/2.0
   27     7.879  0.2918  0.2787  0.002  0.321  0.669  0.761  0.921  0.921    16    0     11    0         714         21         26         38  GET /api/user/me HTTP/2.0
   15     4.753  0.3169  0.2767  0.002  0.291  0.634  0.745  0.745  0.745     7    0      8    0         168          0         11         21  POST /api/signout HTTP/2.0
   17     3.035  0.1785  0.2486  0.002  0.034  0.667  0.776  0.776  0.776    17    0      0    0        8976        528        528        528  GET /
    1     0.389  0.3890  0.0000  0.389  0.389  0.389  0.389  0.389  0.389     1    0      0    0      743417     743417     743417     743417  GET /assets/vendor.ee7444dd.js HTTP/1.1
    1     0.233  0.2330  0.0000  0.233  0.233  0.233  0.233  0.233  0.233     1    0      0    0          18         18         18         18  POST /initialize HTTP/2.0
   42     0.020  0.0005  0.0005  0.000  0.000  0.001  0.001  0.002  0.002    42    0      0    0    31223514     743417     743417     743417  GET /assets/vendor.ee7444dd.js HTTP/2.0
    3     0.007  0.0023  0.0005  0.002  0.002  0.003  0.003  0.003  0.003     3    0      0    0        1584        528        528        528  GET /isu/8fb74e6e-4f8d-4a33-9862-dbcdc0712c7e/condition HTTP/2.0
    3     0.006  0.0020  0.0000  0.002  0.002  0.002  0.002  0.002  0.002     3    0      0    0        1584        528        528        528  GET /isu/8469e6f6-0d29-4052-87cf-dd9bfde45014/condition HTTP/2.0
    3     0.006  0.0020  0.0000  0.002  0.002  0.002  0.002  0.002  0.002     3    0      0    0        1584        528        528        528  GET /isu/15063e10-26fc-4dac-ae3a-1f195e0c6c4a/condition HTTP/2.0
    3     0.006  0.0020  0.0000  0.002  0.002  0.002  0.002  0.002  0.002     3    0      0    0        1584        528        528        528  GET /register HTTP/2.0
nishino-satoshi commented 1 month ago

$dropProbability = 0.95

17:43:55.471490 score: 3223(3226 - 3) : pass
17:43:55.471498 deduction: 0 / timeout: 33

$dropProbability = 0.8

17:46:11.010271 score: 3405(3408 - 3) : pass
17:46:11.010279 deduction: 0 / timeout: 36
pinkumohikan commented 1 month ago 
MariaDB [isucondition]> SELECT table_name,
    ->        table_rows,
    ->        FLOOR((data_length + index_length) / 1024 / 1024) AS total_storage_mb,
    ->        FLOOR((data_length + index_length) / table_rows) AS avg_storage_b,
    ->        FLOOR((data_length) / 1024 / 1024) AS total_data_mb,
    ->        FLOOR((index_length) / 1024 / 1024) AS total_index_mb
    -> FROM information_schema.TABLES
    -> WHERE TABLE_SCHEMA NOT IN ("information_schema", "mysql", "performance_schema", "sys", "test")
    -> ORDER BY total_storage_mb DESC;
+------------------------+------------+------------------+---------------+---------------+----------------+
| table_name             | table_rows | total_storage_mb | avg_storage_b | total_data_mb | total_index_mb |
+------------------------+------------+------------------+---------------+---------------+----------------+
| isu_condition          |      30534 |                9 |           310 |             5 |              3 |
| isu                    |         72 |                3 |         51427 |             3 |              0 |
| isu_association_config |          1 |                0 |         32768 |             0 |              0 |
| user                   |         13 |                0 |          1260 |             0 |              0 |
+------------------------+------------+------------------+---------------+---------------+----------------+
4 rows in set (0.001 sec)
pinkumohikan commented 1 month ago

php-fpmのワーカー数調整

17:52:49.592267 score: 5398(5400 - 2) : pass 17:52:49.592277 deduction: 0 / timeout: 29