iTranslated by AI
Performance Tuning ISUCON11 Qualifiers on a Local Environment: Reaching 20,000 Points (4x the Initial Score)
The environment setup part is above.
Since I've managed to build the ISUCON11 preliminary problem in a local environment, I'd like to practice some tuning. This time, instead of solving it entirely on my own, I will work through it while referring to the explanations from the following sources:
- ISUCON11 Preliminary Problem Commentary and Evaluation : ISUCON Official Blog
- Participated in ISUCON11 Preliminaries as Team "Woo Baba Ee 2" and Qualified for the Finals - G-Minor Oriented
However, to enhance the learning effect, I won't simply follow them blindly. I'll focus on performing measurements as much as possible and gaining an intuitive understanding of "why did they focus on that point?"
Environment
- M1 Macbook Air
- Ubuntu instance configured with 4GB RAM
Initial Benchmark (Score: 5416)
First, I run the benchmark in the initial state (strictly speaking, I've already installed some tools).
./bench -all-addresses 127.0.0.11 -target 127.0.0.11:443 -tls -jia-service-url http://127.0.0.1:4999
If you want to check the application logs during the benchmark, run the following command in another terminal.
journalctl -f -xe -u isucondition.ruby.service
The score was as follows:
14:57:50.995556 score: 5416(5416 - 0) : pass
Based on reading various participation blogs, the initial score often seems to be around 2000–3000, so 5416 feels a bit high. To be rigorous, it might be better to prepare an AWS EC2 instance with specs equivalent to the actual competition.
I will proceed as is in this article.
Prepare a script to restart/clear various things and run the benchmark
Creating the shell script
Since there are many steps when modifying code and re-running the benchmark, I created a shell script like the one below to consolidate the processing.
cd ~/bench
touch my-bench.sh
chmod +x my-bench.sh
The file content is as follows:
#!/bin/bash
# Restart services
sudo systemctl restart nginx
sudo systemctl restart mysqld
sudo systemctl restart isucondition.ruby.service
# Clear logs
sudo truncate /var/lib/mysql/my-slow.log --size 0
sudo truncate /var/log/nginx/access.log --size 0
# benchmark
./bench -all-addresses 127.0.0.11 -target 127.0.0.11:443 -tls -jia-service-url http://127.0.0.1:4999 > /tmp/my-bench.txt
# Output alp log analysis results
# Raw alp output
sudo cat /var/log/nginx/access.log | alp ltsv > /tmp/alp.txt
# alp output grouped by regular expressions
# Sorted by sum descending
sudo cat /var/log/nginx/access.log | alp ltsv -m '/api/condition/.*,/api/isu/.*/graph,/api/isu/.*/icon,/api/isu/.*,/isu/.*/graph,/isu/.*/condition,/isu/.*' --sort sum -r > /tmp/alp-grouped-sum.txt
# Sorted by avg descending
sudo cat /var/log/nginx/access.log | alp ltsv -m '/api/condition/.*,/api/isu/.*/graph,/api/isu/.*/icon,/api/isu/.*,/isu/.*/graph,/isu/.*/condition,/isu/.*' --sort avg -r > /tmp/alp-grouped-avg.txt
# Output slow query analysis results
sudo pt-query-digest /var/lib/mysql/my-slow.log > /tmp/pt-query-digest.txt
Usage
cd ~/bench
./my-bench.sh
Start Tuning
Adjusting drop probability (Score: 11394)
First, I'll try changing the drop probability from 0.9 to 0.
post '/api/condition/:jia_isu_uuid' do
# TODO: We managed to get by by dropping a certain percentage of requests, but originally we should be able to handle the full volume.
- drop_probability = 0.9
+ drop_probability = 0
Run ./my-bench and check the score.
16:00:45.121200 score: 11394(11396 - 2) : pass
The score increased with just this. However, whether doing this as a first step actually improves things likely depends a lot on the environment's specs.
Adding an index to the isu_condition table (Score: 11740)
I immediately ran ./my-bench.sh and checked the slow query log.
# Profile
# Rank Query ID Response time Calls R/Call V/M Ite
# ==== ============================== ============= ===== ====== ===== ===
# 1 0x9C6C682008AE0D08F3E2A0049... 59.9978 37.1% 1941 0.0309 0.01 SELECT isu_condition
# 2 0x931A992E852C61FC6D46141A3... 56.3146 34.8% 2828 0.0199 0.01 SELECT isu_condition
# 3 0x8155B89FFD74A9D523D19AC40... 17.3326 10.7% 778 0.0223 0.01 SELECT isu_condition
# 4 0xFFFCA4D67EA0A788813031B8B... 16.7064 10.3% 5115 0.0033 0.00 COMMIT
# 5 0x5F580A12ADA1633C9634298BE... 8.7383 5.4% 258 0.0339 0.01 SELECT isu_condition
# MISC 0xMISC 2.6468 1.6% 490 0.0054 0.0 <26 ITEMS>
First, I focus on the Rank 1 query. Looking further into the output, the specific query seems to be something like:
SELECT * FROM `isu_condition` WHERE `jia_isu_uuid` = '485d9ef0-eab4-4a27-adbe-ea17f49a3373' AND `timestamp` < '2021-08-28 08:38:30' ORDER BY `timestamp` DESC
So, I will add an index to speed up this SELECT.
CREATE TABLE `isu_condition` (
`id` bigint 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`)
+ PRIMARY KEY(`id`),
+ INDEX `jia_isu_uuid_index` (`jia_isu_uuid`,`timestamp`)
) ENGINE=InnoDB DEFAULT CHARACTER SET=utf8mb4;
Then I ran ./my-bench and checked the score:
16:14:34.367554 score: 11740(11742 - 2) : pass
It didn't seem to increase as much as I expected.
However, looking at the pt-query-digest results:
# Profile
# Rank Query ID Response time Calls R/Call V/M Ite
# ==== ============================== ============= ===== ====== ===== ===
# 1 0xFFFCA4D67EA0A788813031B8B... 7.2662 57.0% 2763 0.0026 0.01 COMMIT
# 2 0x931A992E852C61FC6D46141A3... 3.4482 27.0% 1895 0.0018 0.00 SELECT isu_condition
# 3 0x9C6C682008AE0D08F3E2A0049... 1.1181 8.8% 610 0.0018 0.00 SELECT isu_condition
# 4 0x5F580A12ADA1633C9634298BE... 0.5169 4.1% 262 0.0020 0.00 SELECT isu_condition
# MISC 0xMISC 0.4025 3.2% 118 0.0034 0.0 <17 ITEMS>
The Response time is clearly shorter.
Moving on for now.
Improving POST /api/condition (Score: 13314)
+-------+-----+------+-----+-------+-----+--------+------------------------------+-------+-------+----------+-------+-------+-------+-------+--------+-----------+------------+--------------+------------+
| COUNT | 1XX | 2XX | 3XX | 4XX | 5XX | METHOD | URI | MIN | MAX | SUM | AVG | P90 | P95 | P99 | STDDEV | MIN(BODY) | MAX(BODY) | SUM(BODY) | AVG(BODY) |
+-------+-----+------+-----+-------+-----+--------+------------------------------+-------+-------+----------+-------+-------+-------+-------+--------+-----------+------------+--------------+------------+
| 32374 | 0 | 7450 | 0 | 24924 | 0 | POST | /api/condition/.* | 0.004 | 0.116 | 3123.523 | 0.096 | 0.104 | 0.104 | 0.108 | 0.012 | 0.000 | 14.000 | 126.000 | 0.004 |
| 2016 | 0 | 1912 | 0 | 104 | 0 | GET | /api/condition/.* | 0.016 | 0.908 | 291.053 | 0.144 | 0.192 | 0.428 | 0.832 | 0.138 | 0.000 | 6221.000 | 9825484.000 | 4873.752 |
| 1114 | 0 | 1072 | 0 | 42 | 0 | GET | /api/isu/.*/icon | 0.004 | 0.836 | 147.013 | 0.132 | 0.200 | 0.492 | 0.660 | 0.124 | 14.000 | 135228.000 | 28854161.000 | 25901.401 |
Looking at the alp analysis results (descending order of sum), POST /api/condition.* stands out.
Therefore, I'll apply the following tuning to the code for this endpoint:
- Change the insert process from a loop of individual inserts to a bulk insert.
- Since
countonly needs to determine if at least one record exists, addLIMIT 1to the query. - Prioritize speed over consistency and remove the transaction.
- db_transaction do
- count = db.xquery('SELECT COUNT(*) AS `cnt` FROM `isu` WHERE `jia_isu_uuid` = ?', jia_isu_uuid).first
+ count = db.xquery('SELECT COUNT(*) AS `cnt` FROM `isu` WHERE `jia_isu_uuid` = ? LIMIT 1', jia_isu_uuid).first
halt_error 404, 'not found: isu' if count.fetch(:cnt).zero?
+ q = "INSERT INTO `isu_condition` (`jia_isu_uuid`, `timestamp`, `is_sitting`, `condition`, `message`) VALUES "
+ values = []
+ binds = []
json_params.each do |cond|
timestamp = Time.at(cond.fetch(:timestamp))
halt_error 400, 'bad request body' unless valid_condition_format?(cond.fetch(:condition))
- db.xquery(
- 'INSERT INTO `isu_condition` (`jia_isu_uuid`, `timestamp`, `is_sitting`, `condition`, `message`) VALUES (?, ?, ?, ?, ?)',
- jia_isu_uuid,
- timestamp,
- cond.fetch(:is_sitting),
- cond.fetch(:condition),
- cond.fetch(:message),
- )
+ values << "(?, ?, ?, ?, ?)"
+ binds << jia_isu_uuid
+ binds << timestamp
+ binds << cond.fetch(:is_sitting)
+ binds << cond.fetch(:condition)
+ binds << cond.fetch(:message)
end
+ db.xquery(q << values.join(','), binds)
- end
As a result, I got the following score:
16:53:51.843345 score: 13314(13316 - 2) : pass
I was also able to confirm improvements in the alp analysis results:
- Increased COUNT
- Reduced AVG
+-------+-----+-------+-----+-------+-----+--------+------------------------------+-------+-------+----------+-------+-------+-------+-------+--------+-----------+------------+--------------+------------+
| COUNT | 1XX | 2XX | 3XX | 4XX | 5XX | METHOD | URI | MIN | MAX | SUM | AVG | P90 | P95 | P99 | STDDEV | MIN(BODY) | MAX(BODY) | SUM(BODY) | AVG(BODY) |
+-------+-----+-------+-----+-------+-----+--------+------------------------------+-------+-------+----------+-------+-------+-------+-------+--------+-----------+------------+--------------+------------+
| 34725 | 0 | 16075 | 0 | 18650 | 0 | POST | /api/condition/.* | 0.004 | 0.116 | 3023.877 | 0.087 | 0.104 | 0.104 | 0.108 | 0.020 | 0.000 | 14.000 | 112.000 | 0.003 |
Adding LIMIT 1 to GET /api/trend Query (Score: 18352)
This time, looking at the alp analysis results (descending order of avg):
+-------+-----+-------+-----+-------+-----+--------+------------------------------+-------+-------+----------+-------+-------+-------+-------+--------+-----------+------------+--------------+------------+
| COUNT | 1XX | 2XX | 3XX | 4XX | 5XX | METHOD | URI | MIN | MAX | SUM | AVG | P90 | P95 | P99 | STDDEV | MIN(BODY) | MAX(BODY) | SUM(BODY) | AVG(BODY) |
+-------+-----+-------+-----+-------+-----+--------+------------------------------+-------+-------+----------+-------+-------+-------+-------+--------+-----------+------------+--------------+------------+
| 162 | 0 | 117 | 0 | 45 | 0 | GET | /api/trend | 0.008 | 1.008 | 130.952 | 0.808 | 1.000 | 1.004 | 1.008 | 0.238 | 0.000 | 4636.000 | 514928.000 | 3178.568 |
| 433 | 0 | 356 | 0 | 77 | 0 | GET | /api/isu/.*/graph | 0.040 | 0.864 | 60.752 | 0.140 | 0.212 | 0.248 | 0.648 | 0.097 | 0.000 | 9900.000 | 1429425.000 | 3301.212 |
| 2345 | 0 | 2236 | 0 | 109 | 0 | GET | /api/condition/.* | 0.004 | 0.944 | 306.180 | 0.131 | 0.196 | 0.264 | 0.756 | 0.114 | 0.000 | 6281.000 | 11575158.000 | 4936.101 |
GET /api/trend stands out.
Looking at the code for this endpoint, there is a part that issues the query 'SELECT * FROM isu_conditionWHEREjia_isu_uuid = ? ORDER BY timestamp DESC'. Since the subsequent code isu_last_condition = conditions.first only uses the first record, we can speed it up by adding LIMIT 1 to the query.
isu_list.each do |isu|
- conditions = db.xquery('SELECT * FROM `isu_condition` WHERE `jia_isu_uuid` = ? ORDER BY timestamp DESC', isu.fetch(:jia_isu_uuid)).to_a
+ conditions = db.xquery('SELECT * FROM `isu_condition` WHERE `jia_isu_uuid` = ? ORDER BY timestamp DESC LIMIT 1', isu.fetch(:jia_isu_uuid)).to_a
Running ./my-bench.sh after this change:
17:10:40.378087 score: 18352(18352 - 0) : pass
I confirmed an improvement in the score.
Let's check the alp results as well.
+-------+-----+------+------+-------+-----+--------+------------------------------+-------+-------+----------+-------+-------+-------+-------+--------+-----------+------------+--------------+-----------+
| COUNT | 1XX | 2XX | 3XX | 4XX | 5XX | METHOD | URI | MIN | MAX | SUM | AVG | P90 | P95 | P99 | STDDEV | MIN(BODY) | MAX(BODY) | SUM(BODY) | AVG(BODY) |
+-------+-----+------+------+-------+-----+--------+------------------------------+-------+-------+----------+-------+-------+-------+-------+--------+-----------+------------+--------------+-----------+
| 3525 | 0 | 3511 | 0 | 14 | 0 | GET | /api/trend | 0.008 | 0.368 | 642.029 | 0.182 | 0.236 | 0.264 | 0.316 | 0.045 | 0.000 | 5985.000 | 19714297.000 | 5592.708 |
GET /api/trend has improved significantly. Not only has the AVG become faster, but the COUNT has increased substantially from 162 to 3525.
Building a Caching Mechanism for GET /api/trend (Score: 19587)
Furthermore, I'll attempt to cache the same endpoint. I'll add a cache table like the following:
+CREATE TABLE `cache` (
+ `name` VARCHAR(255) PRIMARY KEY,
+ `value` TEXT NOT NULL
+) ENGINE=InnoDB DEFAULT CHARACTER SET=utf8mb4;
By the way, for caching, options like:
- Installing a KVS like Redis
- Installing Varnish
- Using MariaDB's JSON column type
also seemed possible, but this time I chose to store the JSON string as-is in a TEXT-type value column. I'd like to try the other methods if I have more time.
The application code was changed as follows:
# Latest condition information for each ISU character
get '/api/trend' do
+ cache_probability = 0.7
+ if rand <= cache_probability
+ cached_trend = db.query("SELECT `value` FROM `cache` WHERE `name` = 'trend'").first
+ if !cached_trend.nil?
+ content_type :json
+ return cached_trend.fetch(:value)
+ end
+ end
character_list = db.query('SELECT `character` FROM `isu` GROUP BY `character`')
+ res_json = res.to_json
+ db.xquery("INSERT INTO `cache` (`name`, `value`) values ('trend', ?) ON DUPLICATE KEY UPDATE `name` = 'trend'", res_json)
content_type :json
- res.to_json
+ res_json
end
Borrowing the idea of drop_probability already present in the same app, I made it return the cache with a certain probability (set to 0.7 for now). Also, if it doesn't return the cache, it updates the trend after recalculating.
Running the benchmark:
21:21:16.743787 score: 19587(19608 - 21) : pass
That was the score.
However, looking at alp:
+-------+-----+-------+-----+-------+-----+--------+------------------------------+-------+-------+----------+-------+-------+-------+-------+--------+-----------+------------+--------------+------------+
| COUNT | 1XX | 2XX | 3XX | 4XX | 5XX | METHOD | URI | MIN | MAX | SUM | AVG | P90 | P95 | P99 | STDDEV | MIN(BODY) | MAX(BODY) | SUM(BODY) | AVG(BODY) |
+-------+-----+-------+-----+-------+-----+--------+------------------------------+-------+-------+----------+-------+-------+-------+-------+--------+-----------+------------+--------------+------------+
| 326 | 0 | 220 | 0 | 106 | 0 | GET | /api/isu/.*/graph | 0.032 | 0.260 | 38.512 | 0.118 | 0.192 | 0.208 | 0.232 | 0.056 | 0.000 | 10574.000 | 1564022.000 | 4797.613 |
| 3327 | 0 | 3181 | 0 | 146 | 0 | GET | /api/condition/.* | 0.004 | 0.316 | 348.633 | 0.105 | 0.160 | 0.184 | 0.244 | 0.044 | 0.000 | 6281.000 | 16572049.000 | 4981.079 |
| 1 | 0 | 1 | 0 | 0 | 0 | POST | /initialize | 0.104 | 0.104 | 0.104 | 0.104 | 0.104 | 0.104 | 0.104 | 0.000 | 19.000 | 19.000 | 19.000 | 19.000 |
| 260 | 0 | 92 | 0 | 168 | 0 | POST | /api/auth | 0.004 | 0.180 | 21.852 | 0.084 | 0.144 | 0.164 | 0.180 | 0.043 | 0.000 | 19.000 | 1932.000 | 7.431 |
| 36653 | 0 | 24251 | 0 | 12402 | 0 | POST | /api/condition/.* | 0.000 | 0.120 | 3020.953 | 0.082 | 0.104 | 0.104 | 0.108 | 0.020 | 0.000 | 14.000 | 112.000 | 0.003 |
| 115 | 0 | 115 | 0 | 0 | 0 | GET | /api/trend | 0.004 | 0.184 | 9.340 | 0.081 | 0.136 | 0.148 | 0.176 | 0.039 | 2661.000 | 4534.000 | 381165.000 | 3314.478 |
- AVG was reduced.
- But COUNT decreased.
This result showed up. Man, it's difficult.
Slightly increasing the drop probability value
I'm just a little bit away from a clean 20,000 points. While searching for some simple task to raise the score,
# Receive condition from ISU
post '/api/condition/:jia_isu_uuid' do
# TODO: We managed to get by by dropping a certain percentage of requests, but originally we should be able to handle the full volume.
- drop_probability = 0
+ drop_probability = 0.6
By changing the drop_probability value again as shown above:
21:46:12.921205 score: 21207(21228 - 21) : pass
It exceeded 20,000 points.
Honestly, I can't explain the "Why" for this. It was just a feeling of trying it out while referring to descriptions like these:
ISUCON11 Preliminary Problem Commentary and Evaluation : ISUCON Official Blog
Depending on the situation, reducing the update frequency of trend or increasing the dropProbability to throttle the load and speed up response times was also important for earning points.
While unable to think of what to do, when I tried returning the dropProbability—which I had lowered to 0.6—back to 0.9 at 13:39, it improved significantly. Why? I'm not really sure.
I feel like I just tried it out with these as references. While some uncertainty remains, I'll save a deeper dive for another day. Things like this probably happen in the actual finals too.
References
- How to use alp (Basic Edition)
- ISUCON11 Preliminary Problem Commentary and Evaluation : ISUCON Official Blog
- Participated in ISUCON11 Preliminaries as Team "Woo Baba Ee 2" and Qualified for the Finals - G-Minor Oriented
- Parsing JSON in Ruby - Qiita
- Conveniently executing record insertion/update with MySQL's INSERT ... ON DUPLICATE KEY UPDATE - Qiita
Discussion