⚙️

BEENOS社内ISUCONハンズオンマニュアル

Aki (Takaaki Mikami)

2022/08/09に公開

ISUCON

tech

本記事はBEENOSで開催したISUCONハンズオンマニュアルを、公開向けに手順部分を抜粋したものです。
ハンズオンを開催したレポートはBEENOS社内でISUCONハンズオンを開催したレポートをご参照ください。

0. 事前準備

ハンズオン参加者の方々は、下記事前準備を実施ください。

0.1. GitHubアカウントに公開鍵の登録

もうお済みな気もしますが、GitHubアカウントに公開鍵の登録をしてください。
登録済みであれば不要です。

cf. Adding a new SSH key to your GitHub account

なお、下記の様なURLにアクセスすることで、鍵が登録されているか確認することが出来ます。

https://github.com/[username].keys

0.2. GitHubアカウントをここに記載

サーバーを建てたタイミングで鍵の格納に利用するので、参加者の方々はgithubのアカウント名を記載してください。

お名前: githubアカウント名

1. ハンズオン時の注意点

1.1. サーバーの台数について

実際のISUCONではサーバー3台が与えられ、それを自由に活用できますが、本日は簡略化のため1台のみで行います。
また、ベンチマークについても本来はwebフロントからキューイングし、ベンチマーカー自体も上記3台とは別のインスタンスが担いますが、同じく簡略化のため1台のサーバーでアプリケーションの提供とベンチマーカーの役割を同時に担います。

2. 進め方

チーム分け
- ブレイクアウトルームで1チーム3~4名に分けます 👨‍👩‍👧‍👦
- チームメンバーはお互いの進捗に責任を持ちます、相互に進捗を確認しながら足並みを揃えて進めてください。
- わからん問題に直面したときはイベント開催者に知らせてください 🤔
- なお本日のハンズオンではチームは競争関係にあるわけではないです。ですが、用意した手順をこなした後は好きに改善を進めて頂いて構わないので、是非そちらもチャレンジしてみてください 💪
ハンズオンの進め方
- ハンズオン参加者一人一人にインスタンスを一台ずつ払い出します。その上で各自に作業手順に従って進めていってもらいます。
- 当日の準備 だけハンズオン参加者全員で一緒に行います。
- それ以降は、 当日、各チームでやっていく内容 を順次進めて頂きます。

3. 当日の準備

3.1. 各自にEC2インスタンス立ち上げ、払い出し

ここにインスタンスIPのリストを貼り付け

3.2. ssh接続

ssh isucon@[IP address]

（呪文）後の作業がやりやすいように isucon ユーザーを adm グループに追加

sudo usermod -aG adm isucon

groupの追加を適用するために、セッションを立ち上げ直してください。
（ssh切断して接続し直すので良いです。）

3.3. 各種ツールのインストール

今日使用するツールを導入しておきましょう。

3.3.1. alp

curl -OL https://github.com/tkuchiki/alp/releases/download/v1.0.5/alp_linux_amd64.zip
unzip alp_linux_amd64.zip
sudo mv alp /usr/local/bin/alp

3.3.2. pt-query-digest

wget https://downloads.percona.com/downloads/percona-toolkit/3.3.1/binary/debian/bionic/x86_64/percona-toolkit_3.3.1-1.bionic_amd64.deb
sudo apt-get install -y libdbd-mysql-perl libdbi-perl libio-socket-ssl-perl libnet-ssleay-perl libterm-readkey-perl
sudo dpkg -i percona-toolkit_3.3.1-1.bionic_amd64.deb

3.4. ベンチの実行

初期スコアを出してみましょう。
下記コマンドを実行してください。

cd bench
./bench -all-addresses 127.0.0.11 -target 127.0.0.11:443 -tls -jia-service-url http://127.0.0.1:4999

1〜2分待つとこんな感じのスコアが出るはず（いくらかブレは出ます）

10:49:43.316723 score: 1455(1490 - 35) : pass
10:49:43.316731 deduction: 0 / timeout: 350

4. 当日、各チームでやっていく内容

以降は、各チームに分けれ適宜この資料を参考にしてもらい、進めて頂きます。

4.1. slow query logからの改善

4.1.1. slow queryのlogging、サマリの分析 🔬

/etc/mysql/my.cnf にslow logに関する設定を追記（末尾に書き足してください）

[mysqld]
slow_query_log=1
slow_query_log_file=/var/log/mysql/mysql-slow.log
long_query_time=0

mysqlをrestart

sudo systemctl restart mysql

ベンチを実行してみる

./bench -all-addresses 127.0.0.11 -target 127.0.0.11:443 -tls -jia-service-url http://127.0.0.1:4999

pt-query-digest でサマリを出力

pt-query-digest /var/log/mysql/mysql-slow.log

こんな結果が得られるはず（長いので末尾省略）

# 18.6s user time, 70ms system time, 33.67M rss, 41.19M vsz
# Current date: Sat Jul 30 10:57:42 2022
# Hostname: ip-172-31-16-233
# Files: /var/log/mysql/mysql-slow.log
# Overall: 259.63k total, 95 unique, 2.65k QPS, 6.29x concurrency ________
# Time range: 2022-07-30 10:53:21 to 10:54:59
# Attribute          total     min     max     avg     95%  stddev  median
# ============     ======= ======= ======= ======= ======= ======= =======
# Exec time           617s       0   527ms     2ms     3ms    19ms    36us
# Lock time             3s       0    50ms    11us    15us   237us       0
# Rows sent        567.77k       0   1.54k    2.24    0.99   44.85       0
# Rows examine     121.66M       0  67.25k  491.33       0   4.61k       0
# Rows affecte      65.88k       0     618    0.26    0.99    1.24       0
# Bytes sent       227.85M       0 285.61k  920.23  158.58  10.80k   12.54
# Query size        25.51M       6 790.36k  103.03  258.32   1.66k   31.70
# Boolean:
# QC hit         3% yes,  96% no

# Profile
# Rank Query ID                            Response time  Calls R/Call V/M
# ==== =================================== ============== ===== ====== ===
#    1 0x8155B89FFD74A9D523D19AC409FD97AF  389.1630 63.1%  2499 0.1557  0.05 SELECT isu_condition
#    2 0x931A992E852C61FC6D46141A39DEF4FE  109.2239 17.7%  1870 0.0584  0.09 SELECT isu_condition
#    3 0xFFFCA4D67EA0A788813031B8BBC3B329   62.1451 10.1%  7215 0.0086  0.06 COMMIT
#    4 0xDA556F9115773A1A99AA0165670CE848   24.3851  4.0% 81656 0.0003  0.00 ADMIN PREPARE
#    5 0xB8B32624C3268C0925657C305C0ED778   21.1537  3.4% 66672 0.0003  0.02 INSERT isu_condition
# MISC 0xMISC                               10.7713  1.7% 99720 0.0001   0.0 <90 ITEMS>

# Query 1: 32.88 QPS, 5.12x concurrency, ID 0x8155B89FFD74A9D523D19AC409FD97AF at byte 74854099
# Scores: V/M = 0.05
# Time range: 2022-07-30 10:53:41 to 10:54:57
# Attribute    pct   total     min     max     avg     95%  stddev  median
# ============ === ======= ======= ======= ======= ======= ======= =======
# Count          0    2499
# Exec time     63    389s   207us   479ms   156ms   308ms    88ms   155ms
# Lock time      7   237ms     6us    50ms    94us    60us     1ms    11us
# Rows sent      0   2.42k       0       1    0.99    0.99    0.10    0.99
# Rows examine  77  94.03M     619  65.66k  38.53k  62.55k  19.50k  38.40k
# Rows affecte   0       0       0       0       0       0       0       0
# Bytes sent     0   1.77M     589     789  742.75  755.64   20.65  719.66
# Query size     1 305.05k     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` = '5e4d10da-4f07-48be-a57f-2b6431153322' ORDER BY `timestamp` DESC LIMIT 1\G

# Query 2: 23.97 QPS, 1.40x concurrency, ID 0x931A992E852C61FC6D46141A39DEF4FE at byte 64855655
# Scores: V/M = 0.09
# Time range: 2022-07-30 10:53:41 to 10:54:59
# Attribute    pct   total     min     max     avg     95%  stddev  median
# ============ === ======= ======= ======= ======= ======= ======= =======
# Count          0    1870
# Exec time     17    109s     9us   462ms    58ms   219ms    73ms    26ms
# Lock time      1    53ms       0     8ms    28us    31us   217us    10us
# Rows sent     94 536.70k       0   1.54k  293.90   1.26k  442.84   69.19
# Rows examine  21  26.58M       0  67.25k  14.56k  65.68k  19.40k   6.96k
# Rows affecte   0       0       0       0       0       0       0       0
# Bytes sent    35  81.86M     589 246.82k  44.82k 201.74k  67.28k  10.80k
# Query size     0 210.01k     115     115     115     115       0     115
# Boolean:
# QC hit        23% yes,  76% no
# 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` = '26038fa4-a5f6-41a9-b359-a4cbb9ff2bda' ORDER BY timestamp DESC\G

...

4.1.2. slow queryの改善 🛠️

DDLが ~/webapp/sql/0_Schema.sql に存在しますが、見てみるとINDEXがろくに張られていない 🤯

参考1. INDEX追加のやり方

ISUCON11予選問題では、ベンチ実施の最初期段階でDDLが実行されます。
このDDLが ~/webapp/sql/0_Schema.sql に存在しており、このファイルを編集することで、スキーマを変更することができます。
インデックスを貼るCREATE INDEXの例は下記のような形です。（index_name, table_name, column_name を変更してください。）
CREATE TABLE文の中に書き足すような形でも勿論可能です :+1:

CREATE INDEX `index_name` ON `table_name` (`column_name`);

cf. CREATE INDEX Statement

参考2. 改善EXPLAINの取り方

mysqlへの接続（接続情報はその年の課題によってまちまちですが、今回はhome dirの env.sh 内にあります。）

mysql -u'isucon' -p'isucon' isucondition

ここでは例として、三上が試したときにpt-query-digestの結果で一番↑に来ていたものを実施してみます。

MariaDB [isucondition]> EXPLAIN SELECT * FROM `isu_condition` WHERE `jia_isu_uuid` = '5e4d10da-4f07-48be-a57f-2b6431153322' ORDER BY `timestamp` DESC LIMIT 1;
+------+-------------+---------------+------+---------------+------+---------+------+-------+-----------------------------+
| id   | select_type | table         | type | possible_keys | key  | key_len | ref  | rows  | Extra                       |
+------+-------------+---------------+------+---------------+------+---------+------+-------+-----------------------------+
|    1 | SIMPLE      | isu_condition | ALL  | NULL          | NULL | NULL    | NULL | 68258 | Using where; Using filesort |
+------+-------------+---------------+------+---------------+------+---------+------+-------+-----------------------------+
1 row in set (0.000 sec)

EXPLAINの見方は適宜インターネッツをご参照ください
cf. MySQLのEXPLAINを徹底解説!! - 漢のコンピュータ道

参考3. 改善状況の確認

適宜INDEXを張ったら、再度ベンチマークを回して改善状況を確認してみましょう。
その際、各種logが前回のベンチの分も含まれていると、pt-query-digestやalpで出力するサマリにノイズが入っていますので、logをrotateしましょう。

sudo truncate --size 0 /var/log/nginx/access.log
sudo truncate --size 0 /var/log/mysql/mysql-slow.log

ではでは、再度ベンチマークを実行しましょう。
一応、どこのディレクトリにいても動くように pushd & popd で移動してbench実行し、元いたpathに戻るようにしました。
インデックス作成前からスコアの改善が見られるか確認してみてください。

pushd ~/bench
./bench -all-addresses 127.0.0.11 -target 127.0.0.11:443 -tls -jia-service-url http://127.0.0.1:4999
popd

ベンチマークが終わったら、新たなslow query logが吐かれているので、再度 pt-query-digest を使ってクエリ状況を確認してみましょう。
狙ったSELECT文の実行時間は削減できているでしょうか？

pt-query-digest /var/log/mysql/mysql-slow.log

結果の傾向が変わっていれば（実行時間が最もかかっているクエリがかわっている、あるいはそのクエリが占める時間が減っているなど）、ボトルネックが移っている/移りつつある証拠です。
ここまでで、slow query logからのチューニングの初歩に至れました、おめでとうございます!! :tada:

（ネタバレ）三上が去年のISUCON当日張ったINDEXの例

INDEX例 **※TRY!!してみた後で開いてください**

CREATE INDEX isucondition_jiaisuuuid_timestamp ON isu_condition (jia_isu_uuid, timestamp);
CREATE INDEX isu_jiauserid_jiaisuuuid ON isu (jia_user_id, jia_isu_uuid);
CREATE INDEX isuassociationconfig_name ON isu_association_config (name);
CREATE INDEX user_jiauserid ON user (jia_user_id);

4.2. access logからの改善

4.2.1. LTSV形式でのaccess logの出力、サマリの分析 🔬

/etc/nginx/nginx.conf にアクセスログに関する設定を追加

    # `ltsv` というログフォーマットを定義
    log_format ltsv "time:$time_local"
        "\thost:$remote_addr"
        "\tforwardedfor:$http_x_forwarded_for"
        "\treq:$request"
        "\tmethod:$request_method"
        "\turi:$request_uri"
        "\tstatus:$status"
        "\tsize:$body_bytes_sent"
        "\treferer:$http_referer"
        "\tua:$http_user_agent"
        "\treqtime:$request_time"
        "\truntime:$upstream_http_x_runtime"
        "\tapptime:$upstream_response_time"
        "\tcache:$upstream_http_x_cache"
        "\tvhost:$host";

    # この行は既にあると思うので、末尾が `main` となっているのを、 `ltsv` に変更
    access_log  /var/log/nginx/access.log ltsv;

設定を再読み込み

sudo systemctl reload nginx

ベンチ実施

sudo truncate --size 0 /var/log/nginx/access.log
sudo truncate --size 0 /var/log/mysql/mysql-slow.log
pushd ~/bench
./bench -all-addresses 127.0.0.11 -target 127.0.0.11:443 -tls -jia-service-url http://127.0.0.1:4999
popd

alpでサマリを取ってみる

cat /var/log/nginx/access.log | alp ltsv

こんな結果が得られるはず

サマリ結果（例によって長過ぎるので一部のみ記載）

+-------+-----+------+-----+-----+-----+--------+-----------------------------------------------------+-------+-------+---------+-------+-------+-------+-------+--------+-----------+------------+--------------+------------+
| COUNT | 1XX | 2XX  | 3XX | 4XX | 5XX | METHOD |                         URI                         |  MIN  |  MAX  |   SUM   |  AVG  |  P90  |  P95  |  P99  | STDDEV | MIN(BODY) | MAX(BODY)  |  SUM(BODY)   | AVG(BODY)  |
+-------+-----+------+-----+-----+-----+--------+-----------------------------------------------------+-------+-------+---------+-------+-------+-------+-------+--------+-----------+------------+--------------+------------+
|     1 |   0 |    1 |   0 |   0 |   0 | GET    | /api/isu/a244a234-7603-41d6-b8b3-765131599fc9       | 0.064 | 0.064 |   0.064 | 0.064 | 0.064 | 0.064 | 0.064 |  0.000 |   148.000 |    148.000 |      148.000 |    148.000 |
|     1 |   0 |    1 |   0 |   0 |   0 | GET    | /api/isu/e7c1c95c-5d58-4314-a926-2913cc8a8016       | 0.008 | 0.008 |   0.008 | 0.008 | 0.008 | 0.008 | 0.008 |  0.000 |   142.000 |    142.000 |      142.000 |    142.000 |
|     1 |   0 |    1 |   0 |   0 |   0 | GET    | /api/isu/deda0258-fb57-47de-97ab-e7d6175bedc3       | 0.008 | 0.008 |   0.008 | 0.008 | 0.008 | 0.008 | 0.008 |  0.000 |   136.000 |    136.000 |      136.000 |    136.000 |
|     1 |   0 |    1 |   0 |   0 |   0 | GET    | /api/isu/fd61bfb1-9553-4291-8255-6ad43ce79770       | 0.020 | 0.020 |   0.020 | 0.020 | 0.020 | 0.020 | 0.020 |  0.000 |   130.000 |    130.000 |      130.000 |    130.000 |
|     1 |   0 |    1 |   0 |   0 |   0 | GET    | /api/isu/9f5e3349-adca-4927-8c23-955f3bd3ef13       | 0.004 | 0.004 |   0.004 | 0.004 | 0.004 | 0.004 | 0.004 |  0.000 |   133.000 |    133.000 |      133.000 |    133.000 |
|     1 |   0 |    1 |   0 |   0 |   0 | GET    | /api/isu/26da46a8-0e03-488a-aa21-f0dffe42d0ec       | 0.008 | 0.008 |   0.008 | 0.008 | 0.008 | 0.008 | 0.008 |  0.000 |   133.000 |    133.000 |      133.000 |    133.000 |
|     1 |   0 |    0 |   0 |   1 |   0 | GET    | /favicon.ico                                        | 0.264 | 0.264 |   0.264 | 0.264 | 0.264 | 0.264 | 0.264 |  0.000 |    71.000 |     71.000 |       71.000 |     71.000 |
|     1 |   0 |    1 |   0 |   0 |   0 | GET    | /api/isu/0d897006-eb3f-40bf-97f8-0e4441eb146c       | 0.024 | 0.024 |   0.024 | 0.024 | 0.024 | 0.024 | 0.024 |  0.000 |   145.000 |    145.000 |      145.000 |    145.000 |
|     1 |   0 |    1 |   0 |   0 |   0 | GET    | /api/isu/2176a6f8-c804-42f6-8d2f-29969df8bae3       | 0.032 | 0.032 |   0.032 | 0.032 | 0.032 | 0.032 | 0.032 |  0.000 |   136.000 |    136.000 |      136.000 |    136.000 |
|     1 |   0 |    1 |   0 |   0 |   0 | GET    | /api/isu/e74a014d-5e7e-4576-bd00-71470c96a08f       | 0.016 | 0.016 |   0.016 | 0.016 | 0.016 | 0.016 | 0.016 |  0.000 |   136.000 |    136.000 |      136.000 |    136.000 |
|     1 |   0 |    1 |   0 |   0 |   0 | GET    | /api/isu/662298f5-674c-4dc9-8c43-1dcd2b730fd9       | 0.036 | 0.036 |   0.036 | 0.036 | 0.036 | 0.036 | 0.036 |  0.000 |   148.000 |    148.000 |      148.000 |    148.000 |
|     1 |   0 |    1 |   0 |   0 |   0 | GET    | /api/isu/a3da32f8-da4e-471a-af7c-9c88f49320cb       | 0.272 | 0.272 |   0.272 | 0.272 | 0.272 | 0.272 | 0.272 |  0.000 |   130.000 |    130.000 |      130.000 |    130.000 |

...

長すぎてこりゃ見る気がおきん...
ということでパスパラメーターを使っているURLをまとめてあげる必要性があります。

何もしない状態で行数を見ると344行ありました。（bench状況でブレるので、目安程度の数字です。）

isucon@ip-172-31-20-65:~$ cat /var/log/nginx/access.log | alp ltsv | wc -l
344

/api/condition/~~~ というURLへのアクセスがいっぱいあったので、 -m オプションを使ってこれをくくってみます。
232行まで減りましたね。

isucon@ip-172-31-20-65:~$ cat /var/log/nginx/access.log | alp ltsv -m '^/api/condition/[a-z0-9-]+$' | wc -l
232

1つくくっただけではまだまだ表が大きいので、正規表現を書き足していってください。

最終的な正規表現の記述例 **※TRY!!してみた後で開いてください**

cat /var/log/nginx/access.log | alp ltsv -m '^/api/condition/[a-z0-9-]+$,^/api/isu/[a-z0-9-]+$,^/api/isu/[a-z0-9-]+/icon$,^/api/isu/[a-z0-9-]+/graph$,^/isu/[a-z0-9-]+$,^/isu/[a-z0-9-]+/condition$,^/isu/[a-z0-9-]+/graph$'

上記正規表現でのサマリ結果 **※TRY!!してみた後で開いてください**

+-------+-----+-------+-----+------+-----+--------+------------------------------+-------+-------+---------+-------+-------+-------+-------+--------+-----------+------------+--------------+------------+
| COUNT | 1XX |  2XX  | 3XX | 4XX  | 5XX | METHOD |             URI              |  MIN  |  MAX  |   SUM   |  AVG  |  P90  |  P95  |  P99  | STDDEV | MIN(BODY) | MAX(BODY)  |  SUM(BODY)   | AVG(BODY)  |
+-------+-----+-------+-----+------+-----+--------+------------------------------+-------+-------+---------+-------+-------+-------+-------+--------+-----------+------------+--------------+------------+
|     1 |   0 |     1 |   0 |    0 |   0 | POST   | /initialize                  | 0.356 | 0.356 |   0.356 | 0.356 | 0.356 | 0.356 | 0.356 |  0.000 |    23.000 |     23.000 |       23.000 |     23.000 |
|     3 |   0 |     1 |   2 |    0 |   0 | GET    | /register                    | 0.000 | 0.004 |   0.004 | 0.001 | 0.004 | 0.004 | 0.004 |  0.002 |     0.000 |    528.000 |      528.000 |    176.000 |
|     6 |   0 |     6 |   0 |    0 |   0 | GET    | ^/isu/[a-z0-9-]+/graph$      | 0.000 | 0.000 |   0.000 | 0.000 | 0.000 | 0.000 | 0.000 |  0.000 |   528.000 |    528.000 |     3168.000 |    528.000 |
|     6 |   0 |     6 |   0 |    0 |   0 | GET    | ^/isu/[a-z0-9-]+$            | 0.000 | 0.000 |   0.000 | 0.000 | 0.000 | 0.000 | 0.000 |  0.000 |   528.000 |    528.000 |     3168.000 |    528.000 |
|    18 |   0 |     6 |  12 |    0 |   0 | GET    | ^/isu/[a-z0-9-]+/condition$  | 0.000 | 0.004 |   0.004 | 0.000 | 0.000 | 0.004 | 0.004 |  0.001 |     0.000 |    528.000 |     3168.000 |    176.000 |
|    55 |   0 |    51 |   0 |    4 |   0 | POST   | /api/isu                     | 0.004 | 0.168 |   4.608 | 0.084 | 0.112 | 0.128 | 0.168 |  0.031 |    15.000 |    151.000 |     7137.000 |    129.764 |
|    77 |   0 |     9 |   0 |   68 |   0 | GET    | /api/trend                   | 0.020 | 1.008 |  69.800 | 0.906 | 1.004 | 1.008 | 1.008 |  0.263 |     0.000 |   4566.000 |    40379.000 |    524.403 |
|    79 |   0 |    79 |   0 |    0 |   0 | GET    | /assets/logo_orange.svg      | 0.004 | 0.028 |   0.376 | 0.005 | 0.016 | 0.020 | 0.028 |  0.006 |  3288.000 |   3288.000 |   259752.000 |   3288.000 |
|    86 |   0 |    49 |   0 |   37 |   0 | POST   | /api/signout                 | 0.000 | 1.028 |   4.128 | 0.048 | 0.076 | 0.172 | 1.028 |  0.145 |    21.000 |     21.000 |      735.000 |      8.547 |
|   137 |   0 |    57 |   0 |   80 |   0 | GET    | /api/user/me                 | 0.000 | 0.116 |   1.728 | 0.013 | 0.040 | 0.048 | 0.092 |  0.019 |    21.000 |     42.000 |     3756.000 |     27.416 |
|   147 |   0 |    80 |  67 |    0 |   0 | GET    | /assets/vendor.ee7444dd.js   | 0.004 | 0.044 |   0.588 | 0.004 | 0.012 | 0.016 | 0.020 |  0.006 |     0.000 | 743417.000 | 59473360.000 | 404580.680 |
|   147 |   0 |    80 |  67 |    0 |   0 | GET    | /assets/index.144d8ca8.css   | 0.004 | 0.020 |   0.328 | 0.002 | 0.008 | 0.008 | 0.020 |  0.004 |     0.000 |  19066.000 |  1525280.000 |  10376.054 |
|   147 |   0 |    80 |  67 |    0 |   0 | GET    | /assets/index.23dac98b.js    | 0.004 | 0.020 |   0.416 | 0.003 | 0.008 | 0.012 | 0.016 |  0.004 |     0.000 |  26667.000 |  2133360.000 |  14512.653 |
|   147 |   0 |    80 |  67 |    0 |   0 | GET    | /assets/logo_white.svg       | 0.004 | 0.040 |   0.396 | 0.003 | 0.008 | 0.012 | 0.020 |  0.005 |     0.000 |   3285.000 |   262800.000 |   1787.755 |
|   147 |   0 |    80 |  67 |    0 |   0 | GET    | /assets/favicon.d0f5f504.svg | 0.004 | 0.020 |   0.420 | 0.003 | 0.008 | 0.012 | 0.020 |  0.004 |     0.000 |    592.000 |    47360.000 |    322.177 |
|   172 |   0 |   137 |  35 |    0 |   0 | GET    | /                            | 0.000 | 0.024 |   0.520 | 0.003 | 0.008 | 0.012 | 0.016 |  0.004 |     0.000 |    528.000 |    72336.000 |    420.558 |
|   345 |   0 |   296 |   0 |   49 |   0 | GET    | /api/isu                     | 0.000 | 1.408 |  51.808 | 0.150 | 0.252 | 0.568 | 1.284 |  0.228 |     3.000 |   4649.000 |   851661.000 |   2468.583 |
|   411 |   0 |   311 |   0 |  100 |   0 | GET    | ^/api/isu/[a-z0-9-]+$        | 0.072 | 1.004 |  25.128 | 0.061 | 0.148 | 0.200 | 0.324 |  0.082 |    14.000 |    151.000 |    44803.000 |    109.010 |
|   420 |   0 |   155 |   0 |  265 |   0 | POST   | /api/auth                    | 0.004 | 2.996 |  11.592 | 0.028 | 0.052 | 0.080 | 0.132 |  0.148 |     0.000 |     19.000 |     3036.000 |      7.229 |
|   675 |   0 |   509 |   0 |  166 |   0 | GET    | ^/api/isu/[a-z0-9-]+/graph$  | 0.004 | 0.968 |  57.116 | 0.085 | 0.168 | 0.216 | 0.408 |  0.083 |     0.000 |   8391.000 |  2478079.000 |   3671.228 |
|  2050 |   0 |  1810 |   0 |  240 |   0 | GET    | ^/api/condition/[a-z0-9-]+$  | 0.004 | 1.188 | 231.604 | 0.113 | 0.220 | 0.288 | 0.408 |  0.096 |     0.000 |   7303.000 | 10675169.000 |   5207.400 |
|  2106 |   0 |  2003 |   0 |  103 |   0 | GET    | ^/api/isu/[a-z0-9-]+/icon$   | 0.004 | 1.088 | 170.616 | 0.081 | 0.168 | 0.232 | 0.364 |  0.087 |    14.000 | 135259.000 | 51308515.000 |  24363.018 |
| 69746 |   0 | 66109 |   0 | 3637 |   0 | POST   | ^/api/condition/[a-z0-9-]+$  | 0.016 | 1.028 | 838.452 | 0.012 | 0.036 | 0.084 | 0.104 |  0.032 |     0.000 |     14.000 |       28.000 |      0.000 |
+-------+-----+-------+-----+------+-----+--------+------------------------------+-------+-------+---------+-------+-------+-------+-------+--------+-----------+------------+--------------+------------+

4.2.2. 遅いエンドポイントの改善 🛠️

↑の alp による解析結果で、 SUM （全リクエスト横断して、そのエンドポイントでかかっている時間）が他リクエストの数倍かかっているエンドポイントがあります。
今回はこのエンドポイントの改善を行ってみましょう。
（この時、どのエンドポイントの改善に取り掛かるかの基準は SUM だけではないです。例えば AVG が高いエンドポイントも改善対象っぽいですよね、この辺は後日勉強してみてください 🙏）

POST ^/api/condition/[a-z0-9-]+$

サーバーを実行しているのはgo実装の場合、 ~/webapp/go/main.go というソースコードです。
そして、該当エンドポイントの処理を担当しているのは postIsuCondition というfunctionで、その内容は↓な感じです。

`postIsuCondition` のソースコード

func postIsuCondition(c echo.Context) error {
	// TODO: 一定割合リクエストを落としてしのぐようにしたが、本来は全量さばけるようにすべき
	dropProbability := 0.9
	if rand.Float64() <= dropProbability {
		c.Logger().Warnf("drop post isu condition request")
		return c.NoContent(http.StatusAccepted)
	}

	jiaIsuUUID := c.Param("jia_isu_uuid")
	if jiaIsuUUID == "" {
		return c.String(http.StatusBadRequest, "missing: jia_isu_uuid")
	}

	req := []PostIsuConditionRequest{}
	err := c.Bind(&req)
	if err != nil {
		return c.String(http.StatusBadRequest, "bad request body")
	} else if len(req) == 0 {
		return c.String(http.StatusBadRequest, "bad request body")
	}

	tx, err := db.Beginx()
	if err != nil {
		c.Logger().Errorf("db error: %v", err)
		return c.NoContent(http.StatusInternalServerError)
	}
	defer tx.Rollback()

	var count int
	err = tx.Get(&count, "SELECT COUNT(*) FROM `isu` WHERE `jia_isu_uuid` = ?", jiaIsuUUID)
	if err != nil {
		c.Logger().Errorf("db error: %v", err)
		return c.NoContent(http.StatusInternalServerError)
	}
	if count == 0 {
		return c.String(http.StatusNotFound, "not found: isu")
	}

	for _, cond := range req {
		timestamp := time.Unix(cond.Timestamp, 0)

		if !isValidConditionFormat(cond.Condition) {
			return c.String(http.StatusBadRequest, "bad request body")
		}

		_, err = tx.Exec(
			"INSERT INTO `isu_condition`"+
				"	(`jia_isu_uuid`, `timestamp`, `is_sitting`, `condition`, `message`)"+
				"	VALUES (?, ?, ?, ?, ?)",
			jiaIsuUUID, timestamp, cond.IsSitting, cond.Condition, cond.Message)
		if err != nil {
			c.Logger().Errorf("db error: %v", err)
			return c.NoContent(http.StatusInternalServerError)
		}

	}

	err = tx.Commit()
	if err != nil {
		c.Logger().Errorf("db error: %v", err)
		return c.NoContent(http.StatusInternalServerError)
	}

	return c.NoContent(http.StatusAccepted)
}

複数のISUのconditionが、1つのPOSTリクエストで投げられているのですが、それをループで回して毎回INSERTクエリを発行している状況です。
もし何十回ものINSERTを個別に発行しているとしたら、とっても非効率です。（INSERTクエリ毎に発生するのはネットワークコストなども含んでいることにご注意ください）
これを一度のINSERTクエリで済むように変更してみましょう、所謂BULK INSERTというやつです。

改善例としてはこんな感じ。

--- a/go/main.go
+++ b/go/main.go
@@ -105,6 +105,14 @@ type IsuCondition struct {
    CreatedAt  time.Time `db:"created_at"`
 }

+type IsuConditionForInsert struct {
+   JIAIsuUUID string    `db:"jia_isu_uuid"`
+   Timestamp  time.Time `db:"timestamp"`
+   IsSitting  bool      `db:"is_sitting"`
+   Condition  string    `db:"condition"`
+   Message    string    `db:"message"`
+}
+
 type MySQLConnectionEnv struct {
    Host     string
    Port     string

@@ -1186,23 +1194,27 @@ func postIsuCondition(c echo.Context) error {
        return c.String(http.StatusNotFound, "not found: isu")
    }

-   for _, cond := range req {
+   conditions := make([]IsuConditionForInsert, len(req))
+   for i, cond := range req {
        timestamp := time.Unix(cond.Timestamp, 0)

        if !isValidConditionFormat(cond.Condition) {
            return c.String(http.StatusBadRequest, "bad request body")
        }

-       _, err = db.ExecContext(c.Request().Context(),
-           "INSERT INTO `isu_condition`"+
-               "   (`jia_isu_uuid`, `timestamp`, `is_sitting`, `condition`, `message`)"+
-               "   VALUES (?, ?, ?, ?, ?)",
-           jiaIsuUUID, timestamp, cond.IsSitting, cond.Condition, cond.Message)
-       if err != nil {
-           c.Logger().Errorf("db error: %v", err)
-           return c.NoContent(http.StatusInternalServerError)
+       conditions[i] = IsuConditionForInsert{
+           JIAIsuUUID: jiaIsuUUID,
+           Timestamp:  timestamp,
+           IsSitting:  cond.IsSitting,
+           Condition:  cond.Condition,
+           Message:    cond.Message,
        }
+   }

+   _, err = db.NamedExecContext(c.Request().Context(), "INSERT INTO `isu_condition` (`jia_isu_uuid`, `timestamp`, `is_sitting`, `condition`, `message`) VALUES (:jia_isu_uuid, :timestamp, :is_sitting, :condition, :message)", conditions)
+   if err != nil {
+       c.Logger().Errorf("db error: %v", err)
+       return c.NoContent(http.StatusInternalServerError)
    }

コードの変更が入ったので、buildが必要です。
下記コマンドでアプリケーションをbuildし、serviceを立ち上げ直しましょう

pushd ~/webapp/go
go build
sudo systemctl restart isucondition.go
popd

その後はベンチ実施 ⚙️
スコアが上がっているか確認してみましょう。

sudo truncate --size 0 /var/log/nginx/access.log
sudo truncate --size 0 /var/log/mysql/mysql-slow.log
pushd ~/bench
./bench -all-addresses 127.0.0.11 -target 127.0.0.11:443 -tls -jia-service-url http://127.0.0.1:4999
popd

そしてalpでのアクセスログ解析ももう一度。（↓のコマンドは三上が用意した正規表現のものです。↑の方で既に組み上げた自身の正規表現があれば、それを -m オプションに渡して実施するので問題ありません。）
改善対象であった POST ^/api/condition/[a-z0-9-]+$ のリクエストの数値はどの様に変化しているでしょうか？
改善前とで比較してみてください。

cat /var/log/nginx/access.log | alp ltsv -m '^/api/condition/[a-z0-9-]+$,^/api/isu/[a-z0-9-]+$,^/api/isu/[a-z0-9-]+/icon$,^/api/isu/[a-z0-9-]+/graph$,^/isu/[a-z0-9-]+$,^/isu/[a-z0-9-]+/condition$,^/isu/[a-z0-9-]+/graph$'

Hint: 最終的にbuildして、log rotateして、ベンチ実施、をまとめるとこんな感じになりそうです。
本番ではよくここら辺の手順をアプリケーションのdeploy含めてshell scriptとかにまとめるチームもあります。

pushd ~/webapp/go
go build
sudo systemctl restart isucondition.go
sudo truncate --size 0 /var/log/nginx/access.log
sudo truncate --size 0 /var/log/mysql/mysql-slow.log
cd ~/bench
./bench -all-addresses 127.0.0.11 -target 127.0.0.11:443 -tls -jia-service-url http://127.0.0.1:4999
popd

4.3. 無限のパフォーマンスチューニングジャーニーの始まり

お疲れさまでした!!
今回、ハンズオンのために用意した内容は以上です。
ここまでで、slow queryとaccess logを起点にした改善の基礎を学べたはずです。
ISUCON本番では、golangでいうpprofや外部サービス(New Relic, DataDog等々)を活用したprofilingなどもよく行われています。
いずれにしろ、重要となるのは計測と改善です。
制約条件の理論に則って、計測からボトルネックの特定、改善というサイクルを回し続ける必要があります。
常にOODAループを回し続けましょう 🌀

なにはともあれ、この過程で楽しさみたいなものを感じてくださっていれば幸甚です。
ISUCONの大会当日もとても楽しい催しなので、是非皆さんも わいわい の精神でご参加ください。（別に回し者ではないのですが）
まだ時間がある方は下記の通り、時間が許す限り遊んでみてください。

BEENOS Tech BlogPublication

BEENOSグループのTech Blogです。 BEENOSは越境ECを主要事業として、その他関連/新規事業を行っています。このTech Blogでは、グループ内の各事業を推進する過程で得られた技術的知見を発信していきます。