ISUCON の競技の流れ

ISUCON とは、お題となる Web サービスを決められたレギュレーションの中で限界まで高速化を図るチューニングバトルです。

ISUCON には高速化対象のアプリケーションとは別に、アプリケーションに対してアクセスを行いスコアを算出するベンチマーカーというものがあります。
競技者は

アプリケーションを高速化する

ベンチマーカーを実行しスコアを確認する

という行動を繰り返し行い、高スコアを目指します。
ベンチマーカーが持っている採点基準は問題によって違うため、その問題のマニュアルを読みましょう。

問題構成の確認

ここからはISUCON 11の予選問題を解いていきます。
実際にこの手順で問題を解いてみた際のコードはGitHub のレポジトリにあります。

問題環境に ssh 接続したら、まずはディレクトリ構成を確認しましょう。
ICUCON11 予選では、次のような構成になっていました。

ディレクトリ	内容
/home/isucon/env.sh	アプリに渡す環境変数
/home/isucon/webapp/	アプリのディレクトリ
/home/isucon/webapp/言語名	go, nodejs, perl, php, python, ruby, rust のそれぞれの言語での実装
/home/isucon/webapp/public	静的コンテンツ
/home/isucon/webapp/sql	sql の初期化回りのファイル

DB は以下のコマンドで確認できる通り、MariaDB 10.3 でした。

$ mysqld --version

mysqld  Ver 10.3.31-MariaDB-0ubuntu0.20.04.1 for debian-linux-gnu on x86_64 (Ubuntu 20.04)

当日マニュアルに記載の通り、各言語実装は systemd で管理されているため、systemd に関する知識があると良いと思います。特に、アプリケーションを編集しビルドした後、 systemctl restart isucondition.go.service を実行しないと編集が反映されないことに注意しましょう。

他にも例えば、isucondition がどのように環境変数を読み込んでいるかを調べるには以下のような手順で行えます。

当日マニュアルの参考実装の項目を読み、サービス名が isucondition.go.service であることを確認する

sudo systemctl status isucondition.go.service を実行し、systemd の設定ファイルが /etc/systemd/system/isucondition.go.service にあることを確認する

/etc/systemd/system/isucondition.go.service の中身を確認し、EnvironmentFile=/home/isucon/env.sh の記述を見つける

/home/isucon/env.sh を見て、読み込まれている環境変数を確認する

env.sh のことを知っていると、複数台構成にする際に悩むことが少なくなると思います。
この記事では解説しませんが、得点が上がってきて LimitNOFILE や LimitNPROC を設定する際にも .service ファイルを編集することになります。

なお、ISUCON11 では競技中のインターネット検索は認められています。これ分からないなと思ったらその場で検索しましょう。ボトルネックは分かっているけれど直し方が分からないという状況なら、ISUCON の過去問ブログを漁るのもありです。

計測

まずはベンチマーカーを実行し、基準となるスコアを取りましょう。その後、2回目のベンチマーカー実行時に各種計測を行います。

計測に使えるツールは色々とありますが

top や htop, dstat といったシステム解析ツール

alp や kataribe といったアクセスログ解析ツール

slow-query-log といった mysql の解析ツール

Ruby の stackprof や Go の pprof といったアプリの解析ツール

あたりが ISUCON では良く使われます。
また、 NewRelic や Splunk といった高機能な解析ツールを用いるのも良いでしょう。
各ツールの使い方はここでは紹介しないのでそれぞれ検索してください。

この記事では以下のコマンドを使います。

top

alp (commit: alp 用の設定)

slow query log + mysqldumpslow (commit: slow query log の設定)

pprof (commit: alp 用の設定 pprof の設定を追加)

例えば今回の問題では、初期状態で top コマンドを使うと以下のようなデータが取れます。

    PID USER      PR  NI    VIRT    RES    SHR S  %CPU  %MEM     TIME+ COMMAND

   1053 mysql     20   0 1717616 249016  19004 S 112.3   6.6   0:33.25 mysqld

    666 isucon    20   0 1451896  24156   7544 S  45.2   0.6   0:15.22 isucondition

    162 root      19  -1  149888  98072  97000 R  15.0   2.6   0:03.93 systemd-journal

    397 www-data  20   0   13016   9536   4980 S  12.3   0.3   0:04.19 nginx

    396 www-data  20   0   11820   8460   4980 R   8.0   0.2   0:02.46 nginx

    384 syslog    20   0  224508   5500   3920 S   6.0   0.1   0:02.14 rsyslogd

    123 root      20   0       0      0      0 S   0.7   0.0   0:00.16 jbd2/nvme0n1p1-

ここから次のようなことがわかります

初期状態では CPU 利用率が高い

nginx、アプリケーション、DB のいずれもが CPU を使っている

初期状態での一番 CPU 使用率が高いプロセスは DB

また、alp を見ると

API 単位だと POST /api/condition/:jia_isu_uuid がボトルネックになっている

pprof を見ると

Go 実装の場合、アプリの CPU 負荷は DB 周りが支配的で、ロジック単体で重い部分は少ない

ということも分かります。

改善を入れるとボトルネックは変化することが多いです。そのため、改善後には毎回ベンチマーカーを実行し、そのたびに計測結果は取り直すようにしましょう。

検索やソートが遅い問題を改善

見つけるための計測結果の見方

計測結果を見ます。top から DB が重いことがわかったので、まずは slow query log をみましょう。
初期状態では以下のようなクエリがボトルネックになっています。

SELECT * FROM `isu_condition` WHERE `jia_isu_uuid` = S ORDER BY `timestamp` DESC LIMIT N

SELECT * FROM `isu_condition` WHERE `jia_isu_uuid` = S ORDER BY timestamp DESC

SELECT * FROM `isu_condition` WHERE `jia_isu_uuid` = S AND `timestamp` < S ORDER BY `timestamp` DESC

SQL にはソートや検索を高速に行うためのインデックスという仕組みがあります。EXPLAIN ステートメントを使い、上のクエリにインデックスが効いているかを確認します。MariaDB に接続する際のユーザーやパスワードは、~/env.sh に記述があるものを使用します。

mysql -h localhost -P 3306 -u isucon -pisucon isucondition

MariaDB [isucondition]> EXPLAIN SELECT * FROM `isu_condition` WHERE `jia_isu_uuid` = "XXX" 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 | 71569 | Using where; Using filesort |

+------+-------------+---------------+------+---------------+------+---------+------+-------+-----------------------------+

1 row in set (0.000 sec)

type が ALL であり、key が NULL になっているため、インデックスが使用されていないことが分かります。

修正の方法

isu_condition テーブルにインデックスを張り、検索負荷を改善しましょう。
ただし、POST /initialize 時に DROP TABLE が実行されているため、SQL のコマンドを直接叩いても効果がないことに注意してください。POST /initialize が叩かれたときは ~/webapp/sql/init.sh が実行されます。 ~/webapp/sql/init.sh では、同フォルダの 0_Schema.sql と 1_InitData.sql を実行しています。1_InitData.sql は 初期データの挿入、 0_Schema.sql はテーブルを一度 DROP してから作り直す作業をしています。

インデックスを張る操作は、0_Schema.sql に記述しましょう。カラムの削除や追加など、初期データが入った後に行いたい操作は 2_patch.sql のようなファイルを作り、 1_InitData.sql の後に 2_patch.sql を追加で実行するように init.sh を編集すると良いでしょう。

WHERE の jia_isu_uuid に対して index を張っても良いですが、ORDER BY まで含めて次のような複合 index を張ると良いです。
jia_isu_uuid は = でしか比較していないので、ASC, ASC で構いません。なお、MariaDBでは DESC の指定は意味がありません。

ALTER TABLE isu_condition ADD INDEX isu_uuid_index (`jia_isu_uuid` DESC, `timestamp` DESC); 

アプリケーションマニュアルに記載がある通り、同一の ISU について、コンディションの timestamp が重複することはありません。そのため更に良い方法として予選問題担当で考えていたのは、使っていない id カラムをPKから外し、 (`jia_isu_uuid`, `timestamp`) を複合 Primary Key にすることでした。今回は 1_initData.sql を変更せずに済む簡単な方法として 0_Schema.sql の CREATE TABLE `isu_condition` の部分を、下記のように編集します。

CREATE TABLE `isu_condition` (

  `id` bigint DEFAULT 0,

  `jia_isu_uuid` CHAR(36) NOT NULL,

  `timestamp` DATETIME NOT NULL,

  ...

  PRIMARY KEY(`jia_isu_uuid`, `timestamp`)

) ENGINE=InnoDB DEFAULT CHARACTER SET=utf8mb4;

id から AUTO_INCREMENT 指定が外れてしまいますが、アプリケーションのコードを見ると id は使われていないことが分かるため問題ありません。

~/webapp/sql/init.sh を実行し、上記の設定を反映後に EXPLAIN を見て、設定が意図通りに反映されているか確認します。

~/webapp$ ./sql/init.sh

~/webapp$ mysql -h localhost -P 3306 -u isucon -pisucon isucondition

MariaDB [isucondition]> EXPLAIN SELECT * FROM `isu_condition` WHERE `jia_isu_uuid` = "XXX" ORDER BY `timestamp` DESC

LIMIT 1;

+------+-------------+---------------+------+---------------+---------+---------+-------+------+-------------+

| id   | select_type | table         | type | possible_keys | key     | key_len | ref   | rows | Extra       |

+------+-------------+---------------+------+---------------+---------+---------+-------+------+-------------+

|    1 | SIMPLE      | isu_condition | ref  | PRIMARY       | PRIMARY | 144     | const |    1 | Using where |

+------+-------------+---------------+------+---------------+---------+---------+-------+------+-------------+

意図通り、 type が ref で、key が PRIMARY になっています。

具体的な実装例はコミットを見てください。複合 Primary Key の実装です。
commit: isu_condition テーブルに index を貼る

点数変化 1902 -> 20742

POST /api/condition/:jia_isu_uuid の改善

見つけるための計測結果の見方

計測結果を見ます。

alp で POST /api/condition/:jia_isu_uuid の SUM が大きい

slow query logで COMMIT が大きい。POST /api/condition/:jia_isu_uuid の中ではトランザクションを使っているため、このトランザクション由来の可能性がある

pprof で、POST /api/condition/:jia_isu_uuid の中の insert のSQLの実行部分は CPU を使っている

以上から、 POST /api/condition/:jia_isu_uuid を改善することで、 DB 側の CPU 使用率を下げること出来るのではないかと予想できます。ただし、

alp で、平均レスポンスタイムが小さい。そのため、レスポンスタイムの短縮は期待できない

pprof で、POST /api/condition/:jia_isu_uuid 内の INSERT の CPU 使用率は 6% 程度。そのため、アプリ側の CPU 使用率は大きくは下がらない

ことも分かります。

修正の方法

POST /api/condition/:jia_isu_uuidでは、INSERT を データの件数分別々に行っているので、これを纏めて 1 回にすることで効率化が出来ます。この記事用に用意した Go 実装では NamedExec を使っていますが、クエリを一本に纏めることさえできれば、 NamedExec 相当の機能である必要はありません。

具体的な実装例はコミットを見てください。
commit: POST /api/condition/:jia_isu_uuid のバルクインサート

pprof からアプリ側の INSERT の実行が軽くなっていることや、slow query log や alp から INSERT の試行回数が増えている（≒多くのリクエストを処理できている）ことが見受けられるため、負荷を下げる効果は確認できます。しかし、データ量そのものが多いため slow query log では依然 INSERT と見られる COMMIT が上位に来ています。また、ここを改善しただけでは点数の直接的な要因である GET リクエストがまだ遅いため、あまりスコアは伸びません。

ここでは紹介しませんが、POST されたコンディションをキューに詰めてそれを一定間隔で INSERT するようにすると、リクエストを跨いでデータが纏められるようになり、より速くなります。

不要な行を取得するクエリの改善 (GET /api/trend)

見つけるための計測結果の見方

計測結果を見ます。
top を見るとアプリと SQL は、ややアプリよりですが大体同じくらいの負荷です。
アプリ側は GET /api/trend の、condition を SELECT で取得する処理がボトルネックになっていそうです。このクエリは、slow query log でも上位に来ています。
アプリケーションのコードを読むとこのクエリで取得したデータのうちの1つしか使われていないことが分かります。slow query log の Rows_sent と合わせて読むと、毎回 500 行以上無駄なデータを取得していることが分かります。

Count: 7635  Time=0.00s (31s)  Lock=0.00s (0s)  Rows_sent=579.2 (4422423), Rows_examined=579.2 (4422089), Rows_affected=0.0 (0), isucon[isucon]@localhost

  SELECT * FROM `isu_condition` WHERE `jia_isu_uuid` = 'S' ORDER BY timestamp DESC

この処理を改善し、主にアプリの CPU 負荷を減らしましょう。

修正の方法

この処理は最新の一件のみをレスポンスに用いるため、LIMIT 1 をつけて高速化することができます。

SELECT * FROM `isu_condition` WHERE `jia_isu_uuid` = S ORDER BY timestamp DESC LIMIT 1 

具体的な実装例はコミットを見てください。
commit: クエリに limit をつける (GET /api/trend)

点数変化 22092 -> 29022

不要な行を取得するクエリの改善 (GET /api/condition/:jia_isu_uuid)

見つけるための計測結果の見方

計測結果を見ます。
top を見るとやや nginx の CPU 使用率が伸びて来ていますが、相変わらず支配的なのはアプリと DB です。
trend と同様、アプリ側は GET /api/condition/:jia_isu_uuid の、condition を SELECT で取得する処理がボトルネックになっていそうです。このクエリは、slow query log でも上位に来ています。

Count: 3326  Time=0.00s (13s)  Lock=0.00s (0s)  Rows_sent=789.2 (2625034), Rows_examined=789.2 (2625034), Rows_affected=0.0 (0), isucon[isucon]@localhost

  SELECT * FROM `isu_condition` WHERE `jia_isu_uuid` = 'S'      AND `timestamp` < 'S'   ORDER BY `timestamp` DESC

この処理を改善し、主にアプリの CPU 負荷を減らしましょう。

修正の方法

GET /api/condition/:jia_isu_uuid も LIMIT があるエンドポイントなので、GET /api/trend の場合と同様に LIMIT をつけたいところです。しかし、 filter 条件(condition_level) があるため、単純に LIMIT を取ることは出来ません。
LIMIT をつけるためには POST /api/condition/:jia_isu_uuid で insert するタイミングで condition_level を計算し、WHERE で filter をかけられるようにすると、LIMIT をかけることが出来るようになります。

具体的な実装例はコミットを見てください。

commit: isu_conditionテーブルにlevelカラムを追加

commit: POST /api/condition/:jia_isu_uuidで、levelをinsertするようにする

commit: GET /api/condition/:jia_isu_uuid で、LIMIT を取る

点数変化 29022 -> 32462

不要な行を取得するクエリの改善 (GET /api/isu/:jia_isu_uuid/graph)

見つけるための計測結果の見方

計測結果を見ます。

負荷傾向は変わらずややアプリ寄りに CPU 負荷がかかっています。pprof を見ると、 GET /api/isu/:jia_isu_uuid/graph の処理に最も時間がかかっていて、その中でも特に rows.Next と rows.StructScan に時間がかかっています。これは SQL のクエリで読み込む量が多いことが原因として考えられるので、ここで行っている condition を SELECT するクエリを改善しましょう。
なお、このクエリは slow query log に載ってはいるものの全体の 10% 未満の秒数であるため、 DB 側の CPU 使用率は大きくは下がらないことも予想できます。

修正の方法

GET /api/isu/:jia_isu_uuid/graph は、アプリケーションマニュアルやコードから 24 時間分のグラフデータを返すエンドポイントということがわかります。しかし、以下のように初期実装のクエリでは全区間のデータを取得しています。

SELECT * FROM `isu_condition` WHERE `jia_isu_uuid` = 'S' ORDER BY `timestamp` ASC

そのため、次のように WHERE に追加の条件を加えて範囲を制限することで改善ができます。

SELECT * FROM `isu_condition` WHERE `jia_isu_uuid` = ? AND ? <= `timestamp` AND `timestamp` < ? ORDER BY `timestamp` ASC

具体的な実装例はコミットを見てください。
commit: 検索条件の追加 (GET /api/isu/:jia_isu_uuid/graph)
編集自体はあまり手間では無いですが、コードの読解がやや難解です。 pprof を見れば分かるように、この箇所は支配的という程では無いため、本番では時間がかかりそうだと判断したら後回しにすることも有効でしょう。

点数変化 32462 -> 35372

アプリ側のログ出力が多すぎる問題を改善

見つけるための計測結果の見方

計測結果を見ます。
top を見ると、 systemd-journal が CPU 使用率の上位に来ています。systemd-journal はログ周りを担当しているサービスです。これはアプリケーションのログ出力が負荷になっていることを表しています。

修正の方法

各言語にあるログの出力コードを削り、ログを出力しないようにしましょう。 Go の場合はmiddleware.Loggerを削ります。
注意点として、POST /api/condition/:jia_isu_uuid において、リクエストを drop する際にもログを出力しています。
この箇所での出力もかなりの件数があるので、ここも出力しないようにしましょう。

具体的な実装例はコミットを見てください。
commit: アプリ側のログ出力を止める

点数変化 35372 -> 39405

CPU リソースが足りない問題を複数台を使うことで改善

見つけるための計測結果の見方

以上まででいくつかの改善を入れてきましたが、top を見ると一台だと CPU が詰まりっぱなしであることがわかります。計算リソース自体を増やすため、複数台のサーバーを使いましょう。

修正の方法

今回は 3 台のサーバーの内、アプリケーションを 1 台目 DB を 2 台目に配置する 2 台構成を行います。

DB の分割は

DB 用サーバーの設定を変更し、localhost 以外からの接続を受け入れるようにする

アプリサーバーの設定を変更し、DB の接続先を localhost からDB サーバーに変更する

の 2 ステップで行います。

DB 用サーバーの設定を変更し、localhost 以外からの接続を受け入れるようにするには、 DB 用サーバー（2 台目）内で次のような操作を行います。
まず、 /etc/mysql/mariadb.conf.d/50-server.cnf にある、 bind-address を 0.0.0.0 に設定し、 sudo systemctl restart mysql.service で設定を反映します。
次に、 mysql -uisucon -pisucon 等で mysql の CUI に入り、次のコマンドを実行します。

CREATE USER `isucon`@`192.168.%` IDENTIFIED BY 'isucon'; 

GRANT ALL PRIVILEGES ON `isucondition`.* TO `isucon`@`192.168.%`;

これにより、アドレスが 192.168. で始まるサーバーから、 isucon ユーザーを用いて、 isucondition データベースへのアクセスが可能になります。ISUCON 11予選問題では 3 台のサーバーは全て同じ192.168のプライベートネットワークに属しているため、アドレス制限は192.168.%を指定しています。設定の詳細な意味についてはここでは解説しないため、各自検索してください。

アプリサーバーの設定を変更し、DB の接続先を localhost から DB サーバーに変更する作業は、アプリケーションサーバー（1 台目）内で行います。
アプリケーションは、main.go 内での接続確立処理 と、~/webapp/sql/init.sh の二か所で DB と接続しています。この二か所とも、 ~/env.sh の値を元に接続を行っているため、 ~/env.sh を編集し、2 台目の 192.168. で始まるアドレスを指定するだけで良いです。アドレスはip addr showコマンドで調べることが出来ます。sudo systemctl restart isucondition.go.service で設定を反映するのを忘れないようにしましょう。

具体的な実装例はコミットを見てください。

commit: localhost以外からの接続を受け入れるようにする

commit: DBの接続先をDBサーバーに変更する（指定するアドレスは各自の環境に合わせる必要があります）

上記までの変更で、負荷が満遍なくかかるようになっているため、この変更で大きくスコアが伸びます。
なお、 DB が 2 台目に移動しているため、 slow query log が 2 台目に出力されることに気を付けてください。

点数変化 39405 -> 53272

CPU リソースが余る問題を改善

見つけるための計測結果の見方

計測結果を見ます。
top を見ると、 CPU 負荷に余裕があることが分かります。ここで、dropProbability を思い出しましょう。
ISUCON11 予選問題では、初期の負荷を下げるために指定の割合で ISU から送られてくるデータをドロップするためのパラメーター（dropProbability）があり、初期状態では 90% のデータが捨てられていました。しかし、ここまでの改善を加え top を見ると、 CPU 負荷に余裕があることが分かります。そのため、 dropProbability を下げても十分に処理が行えると予想できます。

修正の方法

dropProbability を下げるだけですが、今回は0に設定したときが一番点が高かったため、コード自体を削除する実装にしました。

具体的な実装例はコミットを見てください。

commit: dropProbabilityを下げる

点数変化 53272 -> 152271

ISUCON 11 予選の 16 位相当のスコアを取ることが出来ました。

終わりに

ここで紹介した測定を行い、ボトルネックを探し、そこを改善する、という一連の流れはどの年の問題にも通じる考え方だと思います。例えばこの問題では無かったアプリケーションロジックが重いような問題でも、top を見てアプリケーション比率が高ければ、pprof を見て場所を特定し、改善する、といった流れで点を上げることが出来るはずです。

この問題の更なる改善については、解説と講評にもう少しだけ書いてあります。そちらもどうぞ。