本記事では、2023年11月25日(土)の来るべきISUCON13に向け、ISUCONの練習問題に取り組んだ過程についてまとめています。書籍『達人が教えるWebパフォーマンスチューニング 〜ISUCONから学ぶ高速化の実践』を読み、private-isu（ピクシブさんが2016年に作成した社内ISUCON）に挑戦してみました。
private-isuには、Ruby/Go/PHPの3言語が用意されていますが、今回はデフォルトのRubyでやりました。
何度か謎のエラーに苛まれながらもなんとかできるところまでやり遂げたので、同じところでつまずいている方々の参考になれば幸いです。
インスタンススポットの起動×2
以下2つのEC2インスタンスを起動する必要があります。
- 競技者用インスタンス
- ベンチマーカー用インスタンス
ずっと起動していると料金が嵩張る恐れがあったので、以下を参考にインスタンススポットを2つ起動することにしました。
以下は先月分の料金ですが、赤枠で囲ったインスタンススポットのほうが起動時間は長いものの料金は安く抑えることができています。
VSCodeとインスタンスをSSH接続
普段使用しているVSCodeをインスタンススポットと接続してコードに変更を加えるためには、VSCodeの拡張機能「Remote - SSH」を利用する必要があります。以下の記事が参考になりました。
チューニングあれこれ
ベンチマーカー用インスタンスにSSH接続して以下のコマンドでベンチマークを実行できます。
cd /home/isucon/private_isu.git/benchmarker && ./bin/benchmarker -u ./userdata -t http://app-instance-ip
初期スコアはこちら
ベンチマーク実行中のtopコマンドの実行結果はこちら
commentsテーブルにインデックスを追加する
commentsテーブルのpost_idカラムに対してインデックスを追加する。
チューニング後のスコアはこちら
{"pass":true,"score":4748,"success":4093,"fail":0,"messages":[]}
ベンチマーク実行中のtopコマンドの実行結果はこちら
MySQLのCPU使用率が下がり、アプリケーションサーバー（ruby）のCPU使用率が下がりました。
unicornworkerプロセスを4にする
2コアあるCPUを有効に活用するため、アプリケーションサーバーのworkerプロセスを1から4プロセスに増やす。
チューニング後のスコアはこちら
{"pass":true,"score":13964,"success":12699,"fail":0,"messages":[]}
ベンチマーク実行中のtopコマンドの実行結果はこちら
アプリケーションサーバーのプロセス（ruby）が4プロセス起動し、均等にCPUを使うようになりました。インスタンス全体ではidleが0%になり、全てのCPUを使えている状態になりました。
次のボトルネックを探すため、アクセスログを解析ツールalp（Access Log Profiler）で解析します。
alpのインストールに際して、EC2インスタンスでのuname -mの実行結果はaarch64でした。
書籍p.122にあるログのフォーマットの$remote_portと$body_bytes_sentを勝手にダブルクォートで囲んだらフォーマットが想定と異なり、alp実行でエラーが出ます。この2つは文字列じゃなくて数値だからダブルクォートはいらないみたいです。
alpの解析結果を見ると、アップロードされた画像を配信している/image/以下へのリクエストが圧倒的に多数のようです。
静的ファイルをnginxで配信する
静的ファイルはアプリケーションサーバーではなくリバースプロキシ（Webサーバー）から配信するべき。/favicon.ico, /css/, /js/, /img/に前方一致するURLを、nginxが静的ファイルとして配信するように設定する。
チューニング後のスコアはこちら
{"pass":true,"score":16871,"success":15608,"fail":0,"messages":[]}
コード変更後のalpコマンドによる解析結果はこちら
alpでの解析結果で、静的ファイルの集計結果が上位から下位に移動しました。
ここで、/etc/nginx/nginx.confと/etc/nginx/sites-available/isucon.confと/home/isucon/private-isu/webapp/etc/nginx/conf.d/default.confとの違いについて気になりましたが、すべてnginxの設定ファイルであり、isucon.confが優先して適用されているようでした。
アップロード画像を静的ファイル化する
画像の配信時は以下のようにする。
- 最初にリクエストを受けるnginxは、ファイルがあればそのまま配信する。
- ファイルがなければ、アプリケーションサーバーへ、リバースプロキシする。
- アプリケーションサーバーはMySQLから画像を取得し、ファイルとして保存した上でレスポンスを返す。
チューニング後のスコアはこちら
{"pass":true,"score":22675,"success":21805,"fail":0,"messages":[]}
コード変更後のalpコマンドによる解析結果はこちら
静的ファイル化前は、GET /image\d+の平均レスポンスタイムは0.040秒でしたが、静的ファイル化後は、0.003秒となりました。
アプリケーションサーバの再起動後、ベンチマークを実行すると静的ファイルが正しくありません (GET /image/9997.jpg)みたいなエラーが出たので、作成時に755だったディレクトリに対してchmod 757 /home/isucon/private_isu/webapp/public/image/したら直りました。
この時点でのdefault.confとisucon.conf
default.conf：中身を空にしても問題ありませんでした。
isucon.conf：https://github.com/tatsujin-web-performance/tatsujin-web-performance/commit/a49eb2dfd307ffe7a85eb9cfbcae3912e8427f0d
こちらと同じにして動かすことができました。
次のボトルネックを探すため、MySQLが出力したスロークエリログをpt-query-digestで解析します。
Percona社が開発・配布しているユーティリティキットをインストールします。
sudo apt install percona-toolkit
スロークエリログに対してpt-query-digestを実行し、標準出力とテキストファイルの両方に結果を出力します。
cd /var/log/mysql && pt-query-digest mysql-slow.log | tee pt-query-digest_$(date +%Y%m%d%H%M).txt
pt-query-digestの解析結果を見ると、postsテーブルに対するクエリがテーブルの全行を取得しているようです。
postsとusersをJOINして必要な行数だけ取得する
ループを回るたびにusersテーブルへクエリを発行する、いわゆるN+1問題を、JOINすることで解消する。
チューニング後のスコアはこちら
{"pass":true,"score":67671,"success":65622,"fail":0,"messages":[]}
書籍では90,000超えてましたが、70,000弱までしか増えませんでした...
コード変更後のalpコマンドによる解析結果はこちら
GET /の平均レスポンスタイムが改善前の0.363秒から0.095秒まで短縮されました。
プリペアードステートメントの改善
サーバーサイドのプリペアードステートメントを使用しないようにする。
チューニング後のスコアはこちら
{"pass":true,"score":86513,"success":84018,"fail":0,"messages":[]}
コード変更後のpt-query-digestによる解析結果はこちら
bundle install してねと書籍に書いてあるけど...
そもそもrubyがインストールされていないように見えたのでインストールしました。
- sudo apt install ruby-bundler
- sudo apt install ruby-dev
- sudo bundle install
pt-query-digestの結果から、ADMIN PREPAREが消えました。
commentsテーブルへインデックスを追加する
インデックスがなくフルスキャンになってしまっているクエリに対処する。
チューニング後のスコアはこちら
{"pass":true,"score":90370,"success":87816,"fail":0,"messages":[]}
コード変更後のpt-query-digestによる解析結果はこちら
インデックス付与前のクエリ実行計画はこちら
インデックス付与後のクエリ実行計画はこちら
インデックスを付与したところ、フルスキャンではなくなりました。
postsからのN+1クエリ結果をキャッシュする
キャッシュとしてmemcachedを使用し、キャッシュがあればそれを使い、なければその場でMySQLにクエリしてmemcachedにキャッシュを作成する。
チューニング後のスコアはこちら
{"pass":true,"score":144112,"success":140492,"fail":0,"messages":[]}
コード変更後のpt-query-digestによる解析結果はこちら
10万回近く実行されていたクエリが数千回まで減ったため、上位3つのクエリがボトルネックではなくなりました。
適切なインデックスが使えないクエリを解決する
user_idで絞り込んでからcreated_atで並べ替えるための複合インデックスを作成し、強制的にこのインデックスを使うようFORCE INDEXで指定する。
チューニング後のスコアはこちら
{"pass":true,"score":154671,"success":150812,"fail":0,"messages":[]}
コード変更後のpt-query-digestによる解析結果はこちら
一番CPUを使っているプロセスが、ついにMySQLではなくなりました！
STRAIGHT_JOINとFORCE INDEXについては公式マニュアルを参照しました。
STRAIGHT_JOINは、左側のテーブルが常に右側のテーブルの前に読み取られる点を除き、JOINと同じです。これは、結合オプティマイザが最適でない順序でテーブルを処理する（少数の）場合に使用できます。
インデックスヒントは、クエリー処理中にインデックスを選択する方法に関するオプティマイザ情報を提供します。（中略）インデックスヒントとオプティマイザヒントは、別々に、または一緒に使用できます。
USE INDEXヒントは、名前付きインデックスのいずれかのみを使用してテーブル内の行を検索するように MySQL に指示します。 代替構文IGNORE INDEXは、特定のインデックスを使用しないように MySQL に指示します。 これらのヒントは、EXPLAINによって、MySQL が可能性のあるインデックスのリストから間違ったインデックスを使用していることが示された場合に役立ちます。
FORCE INDEXヒントはUSE INDEXのように機能します。
外部コマンド呼び出しをやめる
登録とログイン処理時にパスワードのハッシュ値を算出するため呼び出していた外部コマンドをライブラリに置き換える。
チューニング後のスコアはこちら
{"pass":true,"score":189185,"success":182691,"fail":0,"messages":[]}
コード変更前のalpによる解析結果はこちら
コード変更後のalpによる解析結果はこちら
平均75msec, 61msecかかっていた処理が、平均21msec, 17msecにまで短縮されました。
MySQLの設定を調整する
- コミットごとに更新データをログに書き、1秒ごとにログをフラッシュする。
- バイナリログを無効化する。
- スロークエリログを無効化する。
チューニング後のスコアはこちら
{"pass":true,"score":202761,"success":196067,"fail":0,"messages":[]}
コード変更後のpt-query-digestによる解析結果はこちら
pt-query-digestの上位からINSERTクエリがなくなり、上位のクエリは3msec未満で処理できるようになりました。
memcachedへのN+1を解消する
予め、memcachedから取得したい値のキーを配列に構築しておき、ループの前にget_multi(keys)を実行して結果をまとめて取得する。
チューニング後のスコアはこちら
{"pass":true,"score":251581,"success":243391,"fail":0,"messages":[]}
コード変更後のalpによる解析結果はこちら
全てのエンドポイントで平均レスポンスタイムが34msec、最長でも108msecになりました。
RubyのYJITを有効にする
YJITと呼ばれるJIT（just-in-time）コンパイラを有効にする。
チューニング後のスコアはこちら
{"pass":true,"score":260205,"success":251707,"fail":0,"messages":[]}
ベンチマーク実行中のtopコマンドの実行結果はこちら
チューニング完了！
まとめ
書籍では約32万点までスコアを伸ばしていましたが、自分のほうでは約26万点にまでとどまってしまいました...。各インスタンスのスペック（インスタンスタイプ, vCPU, メモリ, ネットワークパフォーマンス）は書籍と同じものにしているため、どこかでチューニング手法を間違えたのかもしれません。今後はその調査を進め、原因が分かり次第追記していきます。
Discussion