この記事は Classi developers Advent Calendar 2021 の23日目の記事です。
こんにちは、プロダクト開発部の2年目の@minhquang4334です。 今年の8月に、同じ部で3年目の@henchiyb 先輩と一緒に yasuoチームを作り、ISUCON11 オンライン予選に初めて参加しました。参加するきっかけは弊社に業務委託として来てくださっている@soudaiさんからISUCONの話について聞かれて、面白そうなので、チャレンジしてみました。結果はRubyで4万点まで達成できましたが、全体のチームの100/598 位ぐらいで敗退してしまいました。
オンライン予選が終わった後、数百万点を達成したチームはどうやってそこまで出来たのかとずっと疑問でした。各チームの解説ブログを見てみましたが、目を通しただけですぐ忘れてしまい、知見を深く理解できないと思いました。それで、自分でももっと深くやってみたいという気持ちになったので、ISUCON 運営の方が準備してくれた環境を立ち上げて練習しました。再度の結果はRubyで、27万点 (11/598 位の点数相当) まで伸ばせました。
ISUCON11予選の課題の練習を通じて、Webパフォーマンスチューニングを中心に、いろいろ勉強になりました。その知見は新人エンジニアの時とISUCONに初めて参加する時に早めに知っておくと良さそうだと思ったので、この記事ではそんなエンジニアを対象にISUCON11予選課題の解説を含めて、自分なりの学んだことをまとめて共有します。
前提
- ISUCON とは「いい感じにスピードアップコンテスト」の略称で、お題となるWebサービスを、決められたレギュレーションの中で限界まで高速化を図るチューニングバトルというコンテストです。
- ISUCON11オンライン予選の課題は公式ページをご覧ください
- ISUCON 11オンライン予選の課題の環境構築
推測ではなく測定しよう
パフォーマンスチューニングするとき、どのように進めていますか。今までは、私はよくコードを見て、N+1や不要なループなどといったパフォーマンスの悪いコードを気づいたら、すぐ改善しようと思いました。しかし、ISUCONでそのように時々たくさん改善できても、システムのパフォーマンスが上がらなく、点数もほぼ変わっていません。 理由は解決した問題はシステムのパフォーマンス低下の原因ではないからです。それも、問題を特定するために、システムのメトリクスを見ておらず、自分の推測を信じたからです。 例えば、以下のAPIの実行時間フレームグラフの場合、どれほど 不要なループとN+1を改善しても、そのAPI自体における改善の効果は少ないのではないでしょうか。不要なループとN+1は良くない実装ですが、パフォーマンス低下の原因ではありません。
正しい問題を調べるのがすごく大事で、問題解決のアプローチを変更しなくてはいけません。推測の代わりに、システム運用のメトリクスを監視したり、測定したり、異常なものを問題として抽出したりすることです。そうして適切な問題を取り除き、解決してから、再度その測定・改善プロセスを回します。
ISUCON11予選練習の時に、その測定・改善プロセスを回してみると、徐々に点数が上がってきて、やりながら達成感も感じられました。
測定した例です。
- ALPを使って、リクエストごとに実行時間を測定する
+-------+--------+------------------------------+-----+------+-----+-------+-----+-------+-------+----------+-------+-------+-------+-------+--------+-----------+------------+--------------+-----------+ | COUNT | METHOD | URI | 1XX | 2XX | 3XX | 4XX | 5XX | MIN | MAX | SUM | AVG | P1 | P50 | P99 | STDDEV | MIN(BODY) | MAX(BODY) | SUM(BODY) | AVG(BODY) | +-------+--------+------------------------------+-----+------+-----+-------+-----+-------+-------+----------+-------+-------+-------+-------+--------+-----------+------------+--------------+-----------+ | 32656 | POST | /api/condition/* | 0 | 7510 | 0 | 25146 | 0 | 0.004 | 0.320 | 3067.503 | 0.094 | 0.060 | 0.100 | 0.100 | 0.018 | 0.000 | 14.000 | 28.000 | 0.001 | | 2688 | GET | /isu/* | 0 | 2561 | 0 | 127 | 0 | 0.048 | 0.956 | 549.019 | 0.204 | 0.000 | 0.472 | 0.112 | 0.198 | 0.000 | 135259.000 | 42280309.000 | 15729.282 | | 639 | GET | /api/trend | 0 | 614 | 0 | 25 | 0 | 0.024 | 1.116 | 397.817 | 0.623 | 0.068 | 0.540 | 0.700 | 0.195 | 0.000 | 4637.000 | 2749921.000 | 4303.476 | +-------+--------+------------------------------+-----+------+-----+-------+-----+-------+-------+----------+-------+-------+-------+-------+--------+-----------+------------+--------------+-----------+
- MySQL のSlow Logを有効し、遅いクエリを測定する
Count: 68432 Time=0.00s (28s) Lock=0.00s (0s) Rows_sent=46.7 (3194156), Rows_examined=397.0 (27169268), Rows_affected=0.0 (0), isucon[isucon]@localhost
SELECT * FROM `isu_condition` WHERE `jia_isu_uuid` = 'S' ORDER BY timestamp DESC
Count: 1089 Time=0.00s (2s) Lock=0.00s (0s) Rows_sent=0.0 (0), Rows_examined=0.0 (0), Rows_affected=0.0 (0), isucon[isucon]@localhost
COMMIT
Count: 1152 Time=0.00s (1s) Lock=0.00s (0s) Rows_sent=1.0 (1125), Rows_examined=2725.9 (3140278), Rows_affected=0.0 (0), isucon[isucon]@localhost
SELECT * FROM `isu_condition` WHERE `jia_isu_uuid` = 'S' ORDER BY `timestamp` DESC LIMIT N
Count: 21800 Time=0.00s (1s) Lock=0.00s (0s) Rows_sent=3.1 (68432), Rows_examined=0.4 (8204), Rows_affected=0.0 (0), isucon[isucon]@localhost
SELECT * FROM `isu` WHERE `character` = 'S'
Count: 3377 Time=0.00s (0s) Lock=0.00s (0s) Rows_sent=0.0 (0), Rows_examined=0.0 (0), Rows_affected=1.0 (3377), isucon[isucon]@localhost
INSERT INTO `isu_condition` (`jia_isu_uuid`, `timestamp`, `is_sitting`, `condition`, `message`) VALUES ('S', 'S', TRUE, 'S', 'S')
topコマンドでCPU 利用率とメモリ利用率を測定する
PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND 2244 isucon 20 0 784600 74604 12984 S 110.6 2.0 0:24.22 bundle 2077 mysql 20 0 1714832 109468 18660 S 25.9 2.9 0:29.95 mysqld 2236 www-data 20 0 13792 10416 5036 S 6.6 0.3 0:01.92 nginx 2235 www-data 20 0 11428 7992 5036 R 3.3 0.2 0:00.90 nginx
もしDatadogやNew Relicなどが活用できたら、測定がより楽になると思います。
データベースについて学んだこと
Webシステムの世界ではデータベース がパフォーマンス低下の原因となるケースは少なくないようです。それで、ソフトウェアエンジニアとして、データベースの正しい扱い方を学ぶのは損ではないと思います。
LIMIT句が大事だ
You aren't gonna need it https://ja.wikipedia.org/wiki/YAGNI
実際に必要となるまでは追加しないのがよいというプログラミング原則があります。そのような考え方でデータベースからデータを取得する時にも、必要であるデータのみを取得するのが大事です。 LIMIT 句を付けたら、 SELECT 文を実行した時に取得するデータの行数の上限を設定することができます。LIMIT 句を付けないと、無駄なデータを取得し、SQLが実行される時間のほとんどがDisk I/Oになってしまって、CPU利用率なども上がって、システムのボトルネックになるケースが多いです。 ISUCON 11で不要なデータを取得しないようにLIMIT 句を付けたら結構パフォーマンスが上がって、点数も急増できました。正に小さい変更で大きな効果です。
- LIMIT句を付ける前 MySQL Slow Log
Count: 75480 Time=0.00s (2s) Lock=0.00s (0s) Rows_sent=46.9 (3537598), Rows_examined=3.0 (228652), Rows_affected=0.0 (0), isucon[isucon]@localhost SELECT * FROM `isu_condition` WHERE `jia_isu_uuid` = 'S' ORDER BY timestamp DESC
- LIMIT句を付ける後 MySQL Slow Log
Count: 226516 Time=0.00s (8s) Lock=0.00s (1s) Rows_sent=1.0 (223303), Rows_examined=0.1 (29024), Rows_affected=0.0 (0), isucon[isucon]@localhost SELECT * FROM `isu_condition` WHERE `jia_isu_uuid` = 'S' ORDER BY timestamp DESC LIMIT N
LIMIT句を付ける後、Rows_sent と Rows_examined の数値が大きく減らすことができました。見なきゃいけないデータが限定されて、データベースの負荷も大きく減らせます。以下は実装・測定の参考となります。
- GET /api/trendのクエリにLIMIT を入れる
3584点 -> 7780点 - GET /api/isu_conditionsに LIMITを入れる
12426点 -> 16052点
Auto Increment Primary Key を使うべきか
Primary Key カラムにAUTO_INCREMENT をつけると、データを追加した時にカラムに対して現在格納されている最大の数値に 1 を追加した数値を自動で格納することができます。カラムに連続した数値を自動で格納したい場合に便利ですが、パフォーマンス的に問題ないでしょうか。MySQLの前提で考えてみましょう。
MySQLでB-treeインデックスの構造とInnoDBストレージエンジンを使われています。B-treeは以下の写真のような木のデータ構造で、テーブルのIndex (Primary Keyも一つのIndex) をテーブルのデータと別途に管理するものです。テーブルに一つのレコードを追加したら、テーブルにあるIndexのB-treeにも一つのノードが追加されます。B-treeの詳しい解説はこちらをご覧ください。
B-treeにノードが追加されるときに、どこで保存できるか既存のノードからそれぞれ比較します。それで、Primary KeyにAUTO_INCREMENTをつけたら、Indexは連続した数値なので、すぐ保存できるポジション (一番右側の下)を見つけられます。その特徴からAUTO INCREMENT Primary Keyを使ったら、Insert文が早く大量のInsert文によって負荷が高くなるシステム (write-heavyシステム) に相応しいと思っている方は多いのではないでしょうか。 しかし、InnoDBではACID特性)を守るため、AUTO_INCREMENT ロックモードがあります。それはテーブルにレコードを書き込むときに、AUTO_INCREMENTのロックをとって、他の書き込むトランザクションが待機させるという仕組みです。
上記の写真のように、同時に複数のトランザクションからAUTO INCREMENT Primary KeyがあるテーブルにInsert文が発行されたら、T1が終わるまで、T2がロックされます。T1が終わったら、T2でロックが 解放されて、T2はAUTO_INCREMENTロックを取得できて、Insert文が発行できます。そのため、大量のInsert文の負荷があるシステムなら、AUTO INCREMENT Primary Keyを使う場合、副作用が出てくる可能性があり、パフォーマンス低下の原因の一つになります。
ISUCON11でIOTシステムみたいな時系列のデータを収集するシステムなので、AUTO INCREMENT Primary Keyのテーブルに同時に大量のInsert文が発行されました。そのテーブルのPrimary KeyをCompound Keyに変更したら、結構パフォーマンスが改善できました。
- isu_conditionsにAUTO INCREMENTからCompound Primary Keyを修正する
システムアーキテクチャについて学んだこと
一個一個のAPIやリクエストやクエリなどを改善するというより、システム全体の構成に問題があるのか特定して解決できたら、ISUCONだけではなく実際にシステムのパフォーマンスを最適化するうえで大きなカギになると思います。
コンテンツ配信はNGINXに肩代わりさせる
普通のWeb システムのクライアントに静的なファイルを配信する方法は root/ フォルダーにファイルを置いておき、必要な場合はバックエンドがユーザーの認証やファイルを読み取りをしてから、Webサーバーが配信します。 Rubyの場合は、send_fileというメソッドがよく使われています。
指定したパスに存在する画像やファイルを読み込み、その内容をクライアントに送信
send_fileの動きが気になったことはありませんか。これは、ディスクからファイルを読み取る必要があることです。このファイルは、出力バッファーを通過し、Webサーバーにフラッシュされ、クライアントに配信します。大きいファイルの場合、メモリをたくさん使って、memory_limitを超えたケースもあります。ファイル全体をメモリに保存したり、削除したりするプロセスのため、バックエンドが忙しくなって、他のリクエストを処理できなくなります。
そこで、バックエンドの負荷を減らすために、X-Accel-Redirectを使って、認証のみをバックエンドで行い、コンテンツ配信はNginxに肩代わりさせることができます。X-Accel-RedirectはNginxの機能で、バックエンドから返されたヘッダによって決定される場所への内部的なリダイレクトを許可します。それでバックエンドを解放して他のリクエストを処理でき、Nginxが持つ素晴らしいコンテンツ配信の力で、高速配信を実現できます。
ISUCON11予選を練習するときに、その機能は全く知らず、解説しているブログなどをいくつも読むことで勉強になりました。以下のようにnginx設定ファイルに設定しました。
https://github.com/minhquang4334/isucon11-training/blob/master/isucondition.conf#L64-L68
location /icon { internal; alias /home/isucon/tmp; expires 86400s; }
location /iconにinternalを追加したら、X-Accel-Redirect レスポンスヘッダーを返すことでnginxから静的ファイルをクライアントに配信できます。
リバースプロキシキャッシュを用意する
キャッシングはWebパフォーマンスの最適化最適化におけるポピュラーな手法の一つです。現代のWebシステムにキャッシングシステムはなくてはならない存在になったといった印象もあります。それを用意することで、Webサーバとかデータベースなどの負荷が減らすことができます。 リバースプロキシキャッシュはキャッシングの一つのタイプであり、Webサーバのクライアントの間に置いておくサーバです。その中で、Varnishは一番よく使われているものです。
上記の図を使って、Varnishといったリバースプロキシキャッシュを簡単に説明します。
- 一度目にクライアントからリクエストを送ったら、VarnishはWebサーバにフォワードします。Webサーバはそのリクエストを処理して、データベースや外部APIと接続してから、レスポンスを生成します。そのレスポンス自体はVarnishのキャッシュに保存されて、クライアントに返します。
- 2度目以降でクライアントからリクエストを受けたら、すでにレスポンスはVarnishのキャッシュにあるので、すぐ返します。
- Varnishのキャッシュの有効期限も設定でき、有効期限を超えたら、キャッシュにあるレスポンスは無有効に設定されます。
そのフローでバックエンドコードを変更せずに、負荷が凄く減らせます。この仕組みは特に認証とリアルタイムも必要なくページやデータなどに相応しいと思います。
ISUCON11予選の課題では、ユーザーがログインせずサマリの画面をリロードする度にapi/trendが呼ばれて、かなり重いクエリが発行されてしまいます。そのページが遅くて、ユーザーがサイトに興味がなくなるというビジネスの要件もあります。そこで解説ブログを参考してみてから、Varnishをインストールして0.5sの有効キャッシュ応答をするように変更しました。
- Varnishを活用する前の該当リクエストのALP
+-------+--------+------------------------------+-----+------+------+-------+-----+-------+-------+----------+-------+-------+-------+-------+--------+-----------+------------+---------------+-----------+ | COUNT | METHOD | URI | 1XX | 2XX | 3XX | 4XX | 5XX | MIN | MAX | SUM | AVG | P1 | P50 | P99 | STDDEV | MIN(BODY) | MAX(BODY) | SUM(BODY) | AVG(BODY) | +-------+--------+------------------------------+-----+------+------+-------+-----+-------+-------+----------+-------+-------+-------+-------+--------+-----------+------------+---------------+-----------+ | 4499 | GET | /api/trend | 0 | 4482 | 0 | 17 | 0 | 0.004 | 0.180 | 542.084 | 0.120 | 0.080 | 0.116 | 0.124 | 0.015 | 0.000 | 5870.000 | 25317465.000 | 5627.354 | +-------+--------+------------------------------+-----+------+------+-------+-----+-------+-------+----------+-------+-------+-------+-------+--------+-----------+------------+---------------+-----------+
- Varnishを活用する後の該当リクエストのALP
+-------+--------+------------------------------+-----+------+------+-------+-----+-------+-------+----------+-------+-------+-------+-------+--------+-----------+------------+---------------+-----------+ | COUNT | METHOD | URI | 1XX | 2XX | 3XX | 4XX | 5XX | MIN | MAX | SUM | AVG | P1 | P50 | P99 | STDDEV | MIN(BODY) | MAX(BODY) | SUM(BODY) | AVG(BODY) | +-------+--------+------------------------------+-----+------+------+-------+-----+-------+-------+----------+-------+-------+-------+-------+--------+-----------+------------+---------------+-----------+ | 24461 | GET | /api/trend | 0 | 24454 | 0 | 7 | 0 | 0.000 | 0.020 | 6.500 | 0.000 | 0.000 | 0.000 | 0.000 | 0.001 | 0.000 | 8478.000 | 159572757.000 | 6523.558 | +-------+--------+------------------------------+-----+------+------+-------+-----+-------+-------+----------+-------+-------+-------+-------+--------+-----------+------------+---------------+-----------+
Varnishを使った後、AVG, P1, P50, P99のレスポンスタイムはほぼ0sぐらいになりました。バックエンドにほぼ手を入れずに、簡単な修正で、信じられないパフォーマンス最適化が出来て、すごく感動しました。今回、Varnishを導入するのが以下となります。
location ~ ^/api/trend$ { proxy_set_header Host $http_host; proxy_set_header Connection ""; proxy_http_version 1.1; proxy_pass http://varnish; }
sub vcl_backend_response {
# Happens after we have read the response headers from the backend.
#
# Here you clean the response headers, removing silly Set-Cookie headers
# and other mistakes your backend does.
set beresp.ttl = 0.5s;
set beresp.grace = 0.2s;
}
課題の特徴から適切な構成を設計する
ISUCON11予選の課題の特徴として、時系列のデータでありユーザーが増加することにより同時に大量のレコードをデータベースに書き込むといった特性上、どうしてもデータベースの負荷が高くなりパフォーマンスが低下してしまいます。そこで、リクエストごとにデータベースに書き込まずに、書き込むデータをキャッシューに入れ、Scheduled Jobを起動し、定期にキャッシュから取得したデータを一括データベースに書き込むように修正しました。その修正をした後、点数は136226から222174まで急増できました。以下のリンクは今回の修正と測定となります。 https://github.com/minhquang4334/isucon11-training/issues/1#issuecomment-944838242
こちらの改善はパフォーマンスの観点で一番効果が高いと感じています。解決したい課題の特徴を把握して、適切な構成を設計して、実装するのが一番大事かと勉強になりました。それは最初から書いた通りに、正しい課題を解決することだと思います。
終わりに
今回の練習を通じて、Webシステムパフォーマンスチューニングを含めて技術の課題解決についていろいろ勉強になりました。目を通しただけで忘れてしまい、実際にやってみた方がより深く理解できてきたと思っています。その知見を生かして、これからClassiでの業務にも頑張っていきたいです。それとも、今年の予選では敗退してしまいましたが、来年の予選までちゃんと練習して、本選まで挑戦していきたいと思います。💪 💪
自分自身の学んだことや理解したことをこの記事にまとめました。理解が不足している部分もあるかと思います。お気づきの際はぜひコメントしていただきたいです。
明日のClassi developers Advent Calendar 2021の担当は平田哲也さんです。お楽しみに。
