ISUCON13に参加してきました
こんにちは。EurekaのRen Kanai です。
先日11/25に開催されたISUCON¹13にスポンサーチームとして初参加してきました！
結果
前回の記事でも紹介した通り、今回はTakeshi Watanabe, Yukako Ishikawa, Ren Kanaiの三名で参加し、最終結果としては19,894点で、694チーム中105位でした。
当日までの準備
過去問を使った練習・準備
9月下旬あたりから週に一回、4hほど時間をとって、チームでの練習・準備時間を確保するようにしました。過去のISUCONの問題を解きつつ、本番までに必要な作業を洗い出しました。
ツールのセットアップ
本番のモニタリングツールとしてpproteinを使用させていただきました。
練習段階ではalpやpercona toolkitなどを個別に使用していましたが、本番前日に導入したところとても使いやすく、当日にも使ってみることにしました（ Yukako Ishikawa 導入準備ありがとうございます！）
pproteinを使うとalp/slp/pprof/fgprofといったログ集計・プロファイリングを一つのダッシュボードで見ることができ、ベンチマーク実行ごとに結果を出力してくれます。集計のソートなどもGUI上で実行可能なので、忙しい競技中でも素早く分析作業ができたのがかなり便利でした。
当日の役割分担決め
本番当日の初動をなるべくスムーズにするため、各メンバーの役割を事前に決めておきました。
- Takeshi Watanabe：ER図作成・仕様まとめ -> アプリケーション改善
- Yukako Ishikawa：サーバー構築 + pprotein準備 -> インフラ改善
- Ren Kanai：デプロイスクリプト準備 -> アプリケーション改善
当日は各メンバーが担当する役割をこなしつつ、必要とあれば自分の担当外の箇所も担当したり手伝ったりする形をとり、可能な限り柔軟に動けるようにしました。
ISUCON当日
09:45 チームメンバー集合
本番当日はオフィスに集合して競技に臨みました。開始までは使用する環境を確認しつつ、本番開始後に調整可能な準備をしていました。
10:00 競技開始
このタイミングでCloudFormationが配布され競技開始です。初期ポイントは3,851点でした。
問題はライブストリーミングサービス「ISUPipe」のチューニングで、配信視聴者の課金がそのままポイントになるという仕様でした。過去問同様、ただサービスをチューニングするだけでなく「アプリケーションの体験をよくする」というところにも注目してもらえるような工夫が見られました。
詳細な仕様は下記公式ブログに掲載されています。
またシステム構成としてはEC2インスタンス3台、アプリケーションの前段にnginx、RDBMSにMySQLと、割とオードソックスな構成でした。一方で今回はアプリケーションの仕様として名前解決が必要となっており、DNSサーバーとしてPowerDNSが用意されていました。
競技開始後は配布されたCloudFormationからスタックを立ち上げつつ、仕様書の読み合わせを15分程度実施しました。
~12:30 MySQLサーバーの移動
mysqlプロセスのCPU使用率が高かったことや過去問の傾向からDBがボトルネックになることはわかっていたので、1台のEC2インスタンスをMySQL専用としました。デプロイスクリプトの修正やサーバーの立ち上げ直しに先に時間を使ったので正午を過ぎてしまいましたが、この頃にMySQLサーバーの移動が完了し、5,578点までupしました。
~14:00 ツールやミドルウェア設定のセットアップが完了
実は Ren Kanaiは競技時間の半分ほど、予め用意していたデプロイスクリプトの修正やconfファイルの設定を行なっていました。過去問から想定していたコマンドやディレクトリ構成が本番環境でことごとく噛み合わず、他の二人にアプリケーション・インフラ・pprof周りを見てもらっている間ずっと修正を行なっていました。。。
~15:00 N+1改善やindexingなど、少しずつチューニング
ツールの修正が終わってRen Kanaiもチューニングに参加できるようになり、アプリケーション周りで支配的なN+1やスロークエリを特定し、コードの修正やindexingなどを行なって行きました。少しずつスコアが上がっていき、15:00時点までで6,655点まで上げました。
~15:45 icons.user_id columnへのindexing
アイコン管理テーブル iconがユーザーに紐づいており、 user_idによる絞り込みが多いにも関わらずicons.user_id にindexが貼られていなかったので、indexを貼ったところ8,469点まで上がりました。
~17:00 image hashのキャッシュ + moderateHandlerのDELETE処理改善
その後しばらく停滞しますが、アプリケーション上でユーザーアイコン用に生成されるimage hash(sha256)の生成処理がプロファイラ上で大部分を占めており、ユーザーごとにキャッシュを追加 + アイコン更新時にキャッシュ追い出しを実装したところ9,956点まで伸びました。
さらにその後moderateHandlerと呼ばれるモデレーション処理のプロファイラ上に占める割合が大きくなりました。調べてみるとコメント削除処理が以下のように実装されていて、NGワードを含むかどうかのチェックを行うために ngwords要素をクエリ中に無理やり埋め込んでDELETEを実行していました。
// NGワードにヒットする過去の投稿も全削除する
for _, ngword := range ngwords {
// ライブコメント一覧取得
var livecomments []*LivecommentModel
if err := tx.SelectContext(ctx, &livecomments, "SELECT * FROM livecomments"); err != nil {
return echo.NewHTTPError(http.StatusInternalServerError, "failed to get livecomments: "+err.Error())
}
for _, livecomment := range livecomments {
query := `
DELETE FROM livecomments
WHERE
id = ? AND
livestream_id = ? AND
(SELECT COUNT(*)
FROM
(SELECT ? AS text) AS texts
INNER JOIN
(SELECT CONCAT('%', ?, '%') AS pattern) AS patterns
ON texts.text LIKE patterns.pattern) >= 1;
`
if _, err := tx.ExecContext(ctx, query, livecomment.ID, livestreamID, livecomment.Comment, ngword.Word); err != nil {
return echo.NewHTTPError(http.StatusInternalServerError, "failed to delete old livecomments that hit spams: "+err.Error())
}
}
}
// ...アプリケーションサーバーのCPU使用率はDBほど逼迫していなかったので、クエリ中のフィルタリング処理をアプリケーションに移しました。この変更によってさらに12,848点まで伸ばすことができました（本番で使用したコードのため、クエリ作成部分が若干雑なのは許してください。。）。
// ...
// ライブコメント一覧取得
var livecomments []*LivecommentModel
if err := tx.SelectContext(ctx, &livecomments, "SELECT * FROM livecomments WHERE `livestream_id` = ?", livestreamID); err != nil {
return echo.NewHTTPError(http.StatusInternalServerError, "failed to get livecomments: "+err.Error())
}
// NGワードにヒットする過去の投稿も全削除する
query := `DELETE FROM livecomments WHERE id IN (`
deletableLiveCommentIDs := make([]any, 0)
for _, lc := range livecomments {
for _, ngword := range ngwords {
if strings.Contains(lc.Comment, ngword.Word) {
deletableLiveCommentIDs = append(deletableLiveCommentIDs, lc.ID)
query += "?,"
break
}
}
}
if len(deletableLiveCommentIDs) > 0 {
query = query[:len(query)-1] + ")"
if _, err := tx.ExecContext(ctx, query, deletableLiveCommentIDs...); err != nil {
return echo.NewHTTPError(http.StatusInternalServerError, "failed to delete old livecomments that hit spams: "+err.Error())
}
}
// ...~17:18 getUserStatisticsHandlerのN+1改善
ISUPipe配信視聴者の統計情報を取得するgetUserStatisticsHandler処理には多くのN+1処理があったため、これらの改善をして13,856点となりました。この辺りから、競技時間終了を意識し始めます。
~17:25 fillLivestreamResponseのN+1改善
取得系レスポンス作成処理として横断的に使用されていたfillLivestreamResponseと呼ばれるメソッド内部では、配信情報に紐づくタグ取得処理をN+1で行なっていました。これを改善し、一気に18,288点まで持って行くことができました。
~18:00 最後のチャレンジ
その後インフラ側のDNSサーバーの切り替えや追加のキャッシュ対応などを入れたり切り戻したりして試行錯誤していましたが、切り戻しの時間を考慮し、残り15分を切った時点での変更を最後としました。最終的な点数として19,894点となりました²。
18:00 競技終了
ISUCONを終えて
やってて良かった点
- ツールや環境の準備
上記協賛ブログでも言及しましたが、事前にツールや環境を整えておいたおかげで、整備完了は改善サイクルをかなり高速に回せるようになりました。これは練習の際にも実感していた点なので、準備はしておいて良かったなと思いました。
2. 変更反映時の戦略を予め決めておく
今回のISUCONでは、変更を反映する際はベンチマークがfailしたり得点が下がらない限り変更を切り戻さなくて良いという戦略を採用していました。得点の変化のないチューニングでも、今はボトルネックが別の場所にあり、後ほど効いてくる可能性があったためです。また序盤の対応箇所のほとんどがN+1やi高負荷が容易に想定されるクエリだったこともあり、パフォーマンスが良くなる事はあっても悪くなることはあまりないと思っていたことも理由としてあります（後半になるにつれそうではなくなるかもしれませんが）。
逆に、ベンチマークがfailする・得点が下がるなどの副作用があった場合には、要修正箇所が判明しても担当者が一旦revertするようにしていました。これは追加修正を入れても改善しないなどドツボにはまるのを防ぎ、別の対応者が変更を入れられない or 対応を無理に入れてしまって原因の切り分けができないといった事態を防止するためでもあります。
3. 過去問の予習
事前にISUCONの過去問を予習していたのですが、この問題練習でISUCONの特性を知ることができたり、本番までに必要な作業を洗い出すことができました。
また本番直前にISUCON11の問題をやり、3-4hくらいで10万点あげることができテンションが仕上がっていたので、モチベーションUPという点でも練習をやっておいて良かったです。
業務ではあまり触れないツールのセットアップだったり、改善の所作やチューニングの勘所だったり、普通にWebアプリケーションパフォーマンスチューニングのトレーニングになる点もISUCON練習の良いところでした。
4. 最後は安全に倒す
上記でも述べたとおり、競技終了の30分前の対応を最後の変更としました。変更によってベンチマークテストが失敗する・スコアが下がるなどの事態が発生した場合、切り戻しの時間が必要と判断したためです。また切り戻しに伴う予想外の追加対応の時間を考えた時に、切り戻しきれずスコアダウンしたまま競技が終了したり、最悪失格となるリスクがあると考えたため、余裕を持って対応を終わらせました。結果的に最後の10分間は何もしていませんでしたが、これくらいが安定していて良かったのかもしれません。
一方で失格リスクを許容できるのであれば、玉砕覚悟でギリギリまで改善にチャレンジするのもありだと思います。
反省点
- スクリプトなどツール修正に時間をかけ過ぎた
今回の一番大きい反省点は、デプロイ用スクリプトの修正に時間をかけ過ぎた点でした。修正中は改善を正しく反映できなかったりしたので、環境に依存する箇所は環境変数などを利用してなるべく外部から注入しやすくし、セットアップをもっと早く実行できるよう準備しておこうと思いました。
また修正が必要な箇所に気づくのも遅かったので、ツール上の間違いに早期に気づけるようにしたいです。ツール上にテストスクリプトなどがあると実行時すぐ気付けたりできるかな、など色々考えています。いずれにせよ、このあたりはもうちょっと工夫しようかなと思いました。
2. ベンチマーカートラブル時に別の検証方法を検討すれば良かった
競技中、ベンチマーカーにトラブルが発生する事態に見舞われましたが、その間別の検証方法を検討していればより時間を有効に使えたのではと思いました。例えば新規に追加する変更がアプリケーション上で正しく動くかどうかはベンチマークテストをしなくてもアプリケーションを使用すれば動くので、スコアは分かりませんが実行時の挙動は検証できるので、変更切り戻しの判断ができます。自分はモニタリングツール上で改善できそうな別の場所を探したり、コードを眺めたりしていましたが、変更の適用によりボトルネック箇所が変わるので、有効な変更かどうかを検証した方が有益だったかもしれません。
最後に
今回が初ISUCON参加でしたが、競技中は真剣に取り組みながらも楽しくチューニングできました。ただもう少し順位を上げたいので、来年のリベンジに向けてトレーニングを続けたいと思います。
最後に、ISUCON運営の皆様、本当にお疲れ様でした&ありがとうございました！
またISUCONへの参加、およびスポンサードに関わっていただいたエウレカの皆様も本当にありがとうございました！
弊社のスポンサードについて下記記事も投稿しておりますので、こちらも読んでくださると嬉しいです！
[1] 「ISUCON」は、LINEヤフー株式会社の商標または登録商標です。https://isucon.net
[2] DNS切り替え対応時の切り戻しのタイミングでサービス再起動を実施したところ、キャッシュが削除されたのか点数が1,000ほど上昇しています。。
