何が書いてあるか

こんにちは、U-NEXTでAndroidエンジニアをしているakiragoです。会社の方でアドベントカレンダー書きませんかという招待を頂き、タイミングも良かったのでISUCONの記事を書かせて頂くことになりました。
U-NEXT Advent Calendarでは11日目を担当させていただきます。アドベントカレンダーのタイトルには「ISUCON（いい感じにスピードアップコンテスト）での優勝賞金100万の使い道(仮)」と強気なタイトルを書きましたが、最終スコアは奇しくも0点で優勝を逃してしまった為、存在しない100万円の使い道を書くことは出来ません。よって本記事はISUCONの概要、当日までの準備、当日の活動内容、感想についてお話しさせて下さい。

ISUCONとは

ISUCONは、LINEヤフー株式会社が運営するパフォーマンス改善コンテストです。与えられたWebサービスをできる限り高速化することが目的で、10時から18時までの8時間内で最適化を図ります。

競技では「ベンチマーカー」と呼ばれるツールが用意されており、ベンチマーカーが出力するスコアで順位が決まります。使用できるサーバーは3台で、例えば2台をアプリサーバー、1台をDBサーバーにするなど自由に構成できます。1チームあたり1〜3人で参加可能で、インフラ、アプリ、データベースの設定など多岐にわたる作業が求められます。そのため、事前準備が重要です。

当日までの準備

過去のISUCONでは初動が遅く、セットアップなどに3時間以上、3台編成まで含めると4〜5時間かかっていました。そのため、昨年のISUCONが終わった後に考えていた来年はこうやりたいを実現するために、プロファイリングツールの導入やアプリのビルドデプロイをAnsibleやShellScriptで実行するだけで完了するようにしました。データベースをdumpしてローカルで実行できるようにしたり、3台編成のやり方をドキュメントにまとめたりしました。この仕込みで2時間弱で3台設定できるようになったはずです。

プロファイリングツールの自動インストール

SQLパフォーマンス測定: slow queryとpt-query-digest
アクセスログの測定: alp
アプリの分析: fgprof

必要なファイルはAnsibleを使ってダウンロードできるようにし、設定ファイルも準備しました。

プロファイリング結果のSlack通知

プロファイリング結果はaccess.logやmysql-slow.logに出力されるのですが、shell scriptで解析結果をSlackに通知し、logファイルを初期化するようにしました。

当日やったこと

10:00~11:00 環境構築、アプリの仕様の理解

CloudFormationを実行したものの、エラーが出てやり直し、リバートも含めて15分ほどかかりました。どんな設定になってたっけって確認できるようにEC2のインスタンスを残しておいてしまったのがおそらく原因、前日の夜にはEC2のインスタンスをすべて破棄しておかないとダメでしたね。少し手間取りましたが、その他の初動は想定通りスムーズに進みました。今年はデータベースも一つでいけそうだったので、一旦APPとDB2台編成に設定しました。

11:00~13:00 Indexを貼る、2台編成に問題発生、原因調査

Indexを一通り貼り終わり、ownerGetChairsのSQLに手を入れたあたりに2台編成でエラーが出るようになってしまったのですが、また原因もよく分からなかった。また1台編成の場合には発生しないエラーの為原因が分からず、2台編成の場合にのみ発生するということに気付くことにも時間がかかっていた。

13:00~14:30 アプリの改善点

この辺りで2台編成の場合にエラーが発生してしまう原因を調査する人、User、Chairに通知をする方法をポーリングからServer Sent Event(SSE, 一度クライアントとサーバー間の接続を確立するとサーバーからクライアントにテキストデータを送信できる(らしい、が自分はアプリケーションの仕様書を見た時に初めて存在を知ったのでよく分からず使っていた)) に変更する人、ride_statusをDBからRedisで管理できるようにする人に分かれた。

下記のalpで集計したアクセスログを見た感じでは通知周りへのアクセス回数が多く合計時間もかなり取られていた為、SSEに変えられるかどうかで大きくスコアも変わりそうだなと思い、生成AIが参考実装を出してくれた為、まずはここから本腰を入れました。(後から会社のもう一つのチームの人に聞いたら、SSEは参考実装がなかったのでやらなかったという話を聞いて、そこに時間をかけるべきか検討するべきだったな、少なくとも1時間で目処が立たなかったら止めるという判断をするべきだったなと反省中)

+--------+--------+------------------------------------------+-------+-------+-------+-----------+
| COUNT  | METHOD |                   URI                    |  MIN  |  AVG  |  MAX  |    SUM    |
+--------+--------+------------------------------------------+-------+-------+-------+-----------+
| 140697 | GET    | /api/chair/notification                  | 0.003 | 0.081 | 0.575 | 11359.776 |
|  28207 | GET    | /api/app/notification                    | 0.006 | 0.221 | 0.874 |  6224.227 |
|  32260 | POST   | /api/chair/coordinate                    | 0.020 | 0.145 | 0.501 |  4665.150 |
|    504 | GET    | /api/app/nearby-chairs                   | 0.367 | 3.175 | 6.163 |  1599.995 |

通知のAPIの実装を変更する上で下記のステップで進めようと考えました。

ポーリングを辞めSSEの形式にする
UserやChairなどの情報をメモリキャッシュで持つ
ride_statusをkey-valueのMapで管理する

14:30~16:00 ポーリングを辞めSSEの形式にする

SSEの実装は終わったもののスコアは少し下がっただけ。ログで通知を送信出来ているか確認はしたがおそらく送れてるかもという感じだった。SSEは一方向通信の為クライアントが受け取れているかどうかの確認は出来なかった事とこの通知を送ったことによってクライアントがどう処理して次の行動に移るか理解出来ていなかった為、DBへのアクセス回数が増え過ぎてしまった結果スコアが下がっているのだろうと解釈してメモリキャッシュの実装を進めた。（クライアント側の実装がisucon14のrepositoryに出てきたので動かしてみる）

16:00~17:00 メモリキャッシュを行いDBへのアクセス回数を減らす

UserやChairなどの情報を持つのはすぐ出来たがride_statusをMapで管理する方は上手く行きませんでした。MATCHINGの通知をChairに送った後、ENROUTEにして下さい、というリクエストがChairから送られて来ず、詰まってしまった。クライアント側の実装が分からないのが辛すぎる…

17:00~17:50 UserとChairのマッチングロジック改善

ride_statusのapp_sent_at, chair_sent_atの項目がどのような役割を果たしているかを調べている時にUserとChairをマッチングするロジックを発見し、MEMOでランダムにマッチングしているが絶対もっといいやり方があるので改善したい、みたいなことが書かれていて絶対もっと早くここやるべきだったけどもう全然時間ないじゃんと思いつつ手を出しはじめてしまった。本来ならツールの除去、不要サービスの停止、一番パフォーマンスの良いアプリへの切り替え、再起動テストをやり始める時間だったのだが…

17:50~18:00 プロファイリングツールの除去、不要サービスの停止、一番パフォーマンスの良いアプリの選定

1時間前にはプロファイリングツールの除去、不要サービスの停止、一番パフォーマンスの良いアプリの選定を行う、というルールは去年まではしっかりやっていた気がするのだが(3台編成にギリギリで滑り込むみたいなことをやっていた気もする)、今回何もできておらず熱くなってしまい直前まで何かしら成果を上げたいという気持ちでもうちょっと、もうちょっとだけをやってしまった。他のメンバー二人がプロファイリングツールの除去、不要サービスの停止などを行なってくれた為コンテスト中の一番いいスコアに近い数値で終われました。再起動テストで失敗した為失格0点となりましたが。不要なツールを手動で削除するのは正直面倒なのと消しすぎて壊れるみたいなこともありそうなのである程度Ansibleでアンインストール出来るようにしておこうかな。

感想

よかった事

Ansibleでほぼ自動化出来ていた、人の手で3台の設定やるのは無理
Goのビルド自動デプロイコマンドで動作確認のスピードが爆速になった
AIに知りたいことを聞けた

来年できるようになりたいこと

アプリの仕様を理解した上でどうやってスコアを上げるのか考えた上で、改善に取り組む(アクセスログを見て、上位の関数を見てとりあえず改善出来そうな所に手をつけるをやってしまった)
実際の作業を始める前にGoのコードを一通り眺めておく
クライアント側の実装も全体を知るためにみる
綺麗に終わる為のAnsibleを作る

まとめ

今年もなんも出来んかったなあという悲しい気持ち。なんも出来ていないことはないのだがスコアに直結するイカした改善が出来ていないのがむず痒い。
悔しいっ••••••!　悔しいっ••••••!　悔しいっ••••••!　し•••••••••しかし••••
しかし••••••••••••　これでいいっ••••••••!　これでこそISUCON••••ISUCONだっ••••••••!
ISUCON5年目で色々できるようになったものの、結局本番出来ることは練習で出来たことで、練習で出来なかった事が本番で急に出来ることもなく、仕様を理解して本質的な改善に取り組む為の練習時間が足りず順当に勝てなかったのかなあと思いました。
今年は信じられない速さでISUCON14のrepositoryをあげて頂いて、しかもポータルからベンチも叩けるようになっているので早速延長戦をしています。ISUCONは至れり尽くせりで本当にありがたい。

U-NEXT Advent Calendar 2024 にはU-NEXTの社員の趣味や仕事のガチだったりゆるーい話が色々載っているので是非時間があればご覧になって下さい。
明日12月12日の記事は Miao Jiang さんの Chinese hotpot in Tokyo になります。
是非、そちらもご覧ください！