@ebiebievidence と @uni745e の2人と一緒に「ここにチーム名を入れる」というチームを組んで、ISUCON11に出場しました。
結果は予選敗退、最高スコアは45180、最終スコアは40952、公開Leaderboard での順位は 105位でした*1。
この記事では、準備したこと、当日やったこと、振り返りについて述べます。
- 準備したこと
- 当日やったこと
- (10:00 ~ 10:45) マニュアル読み、アプリの動作確認
- (10:45 ~ 11:45) 諸々のセットアップ
- (11:45 ~ 12:20) ベンチマーク、ログ・メトリクスの分析、方針相談
- (12:20 ~ 13:00) アプリからエラーログが出るようにしようとする
- (13:00 ~ 13:20) index を貼る ①
- (13:20 ~ 13:45) コードリーディング
- (13:45 ~ 15:00) 500エラーの原因を追う
- (15:00 ~ 16:00) index を貼る ②
- (16:00 ~ 16:30) LIMIT 1 をつける
- (16:30 ~ 18:00) latest_isu_condition テーブルの導入
- (18:00 ~ 18:45) クロージング
- 振り返り
- 総括・所感
準備したこと
リクルーティング
ISUCON10 が終了した直後に、インフラエンジニアの @uni745e をリクルートしました。 これは、私も @ebiebievidence もミドルウェア・インフラ周りの知識がなさすぎて、まともにチューニングができなかった、という反省を受けての行動です。
@uni745e が参戦したことで、ミドルウェアのチューニングが去年に比べて高いレベルで行えたり、ミドルウェアのバージョンアップがスムーズに行ったり、構成変更をゴリゴリできたりといった良い効果がありました。
過去問演習
3人で集まって過去問を解きました。 合計で3年分ぐらいの過去問を解きました*2が、回数をこなしたことで、初動の整理・役割分担をうまくできたと思います。
特に今回は @uni745e が ISUCON 初参戦だったため、回数をこなしたのは効果的だったと思います。
役割分担
普段の仕事内容や、過去問演習の反省を踏まえ、初動・役割分担は以下のような形に落ち着きました。
- 私
- @ebiebievidence
- 初動：ソースコードを読んで、データの流れを把握しつつ、問題のありそうなコードに目星をつける
- 役割：アプリのチューニング
- @uni745e
- 初動： /etc/hosts を配ったり、各種ログを出したり
- 役割：ミドルウェアのチューニング、構成変更
なお、マニュアルの読解とアプリの動作確認は、全員で集まって画面共有をしながら、一番最初に行うことにしました。 また、アクセスログの分析についても、下回りの整備が終わったタイミングで、全員で画面共有しながら行うことにしました。
自習
@ebiebievidence はアプリのプロファイラ周りの勉強をし、@uni745e は ミドルウェアのパラメータチューニングを勉強したり構成変更の手順をまとめたりしていたようです。
私は、 pt-query-digest の使い方を思い出したり、デプロイ・ログローテーションスクリプトの雛形を作ったりしていました。
当日やったこと
私がやったことを中心に、当日の行動を時系列で述べます。
(10:00 ~ 10:45) マニュアル読み、アプリの動作確認
画面共有しながら全員で競技マニュアルを読み、その後、アプリのマニュアルを見ながらアプリの動作確認を行いました。
(10:45 ~ 11:45) 諸々のセットアップ
以下を行いました。全部合わせて1時間ぐらいかかりました。
- ソースコードをgitで管理下に置く
- デプロイスクリプトを書いて、デプロイできるようにする
- アプリが吐くログをファイルに出力するようにする
- 元は標準出力に出てたので見づらかった
- fgprof / pprofを導入する
- ログローテーションスクリプトを書いて、ログローテーションできるようにする
(11:45 ~ 12:20) ベンチマーク、ログ・メトリクスの分析、方針相談
ベンチマークを実行し、ログや各種メトリクスを読んだり、コードを読んだりして以下のことがわかりました。
- MySQLのCPU使用率が100%である
- いくつかのAPIが、クライアントのタイムアウトで切断されている(status code 499)
- postIsuCondition は9割のデータを保存せずに無視している
これを受けて、以下の方針で行くことにしました。
- 私
- 各種READ系がタイムアウトしてるのをどうにかする
- ただし、 getTrend を改善して人が増えても捌ききれないので、getTrend は直さない
- @ebiebievidence
- postIsuCondition がタイムアウトしてるのをどうにかする
- @uni745e
- 少しでもDBにCPUを使わせるため、Web と DB のホストを分ける
(12:20 ~ 13:00) アプリからエラーログが出るようにしようとする
APIリクエストと紐付いた形でエラーログが出るようにしようと頑張ったが、echo のミドルウェア周りに不慣れだったことから沼ってしまい、最終的に諦めました。
(13:00 ~ 13:20) index を貼る ①
はじめは、エンドポイントをひとつひとつ改善していこうと思っていましたが、MySQLのCPUがサチってるので任意のクエリが重くなるのは必然だと思い直し、アプリ中の重いクエリに片っ端からindexを貼ることにしました。
(13:20 ~ 13:45) コードリーディング
index を貼るためにクエリダイジェストを取ろうとしたところ、MariaDB が吐くスローログのフォーマットが思っていたものと違っており、pt-query-digest に食わせてもうまく情報が出てくれませんでした。MariaDBでいい感じにスローログを出す方法がわからなかったので、 @uni745e にお願いして MariaDB を MySQL に載せ替えてもらうことにしました。
そして、pt-query-digest が使えるようになるのを待つ間、アプリのコードを少しでも読んでおこうと思ってコードリーディングをしました。
(13:45 ~ 15:00) 500エラーの原因を追う
コードリーディングをしながらアクセスログを alp で分析していたのですが、@ebiebievidence の改修(postIsuConditionでbulk insertするやつ)が入ったあとから、 POST /isu/condition/... で大量の 500 エラーが出ていることがわかりました。
エラーの原因を調査するべく調査しましたが、原因がわからずに1時間ぐらい溶かしてしまいました。
結局このエラーは、 @ebiebievidence がデバッグをしているときに出たエラーログが、正常なアプリのログに混じっていたのが原因だとわかりました。 実際、ログを消したあとに再度ベンチマークを回したら500エラーはきれいに消えました...。
(15:00 ~ 16:00) index を貼る ②
このタイミングではまだMySQLへの載せ替えは完了していなかったので、pt-query-digest を使うのは諦めて、コードを grep 'SELECT' で検索し、出てきたすべてのクエリをさっと見て、重そうなやつにindexを貼りました。
CREATE INDEX isu_uuid_timestamp ON isu_condition (jia_isu_uuid, `timestamp`);
この index は、以下のクエリを改善します。
SELECT * FROM `isu_condition` WHERE `jia_isu_uuid` = ? ORDER BY `timestamp` DESC LIMIT 1
このクエリは、 index を貼る前は type: ALLの実行計画になる上に、getIsuList の中にあるループの中で呼ばれているという激ヤバのクエリでした。
index を貼ったことで、スコアは 8000 → 23000 に上がりました*3。
(16:00 ~ 16:30) LIMIT 1 をつける
getTrend の loop の中で、以下のようなクエリが実行されていました。
SELECT * FROM `isu_condition` WHERE `jia_isu_uuid` = ? ORDER BY timestamp DESC
しかし、このクエリの結果は、なんと最初の1件しか使われていませんでした。つまり1件しか取得する必要がないということなので、以下のように書き換えました。
SELECT * FROM `isu_condition` WHERE `jia_isu_uuid` = ? ORDER BY timestamp DESC LIMIT 1
これによって、スコアは 23000 → 29000 に上がりました。
(16:30 ~ 18:00) latest_isu_condition テーブルの導入
以下のような「ある椅子の最新の isu_condition を取得する」クエリが発行されている場所がいくつかありました。しかもこのクエリはforループの中で実行されていて、典型的なN+1クエリでした。
SELECT * FROM `isu_condition` WHERE `jia_isu_uuid` = ? ORDER BY timestamp DESC LIMIT 1
上記のクエリは、 直前に貼った isu_uuid_timestamp index によってある程度高速に実行されますが、ループの外で実行する(=N+1クエリをやめる)ためには、この構造のテーブルでは厳しいと思いました。
この問題を解決するため、 latest_isu_condition テーブルを新たに導入することにしました。
latest_isu_condition は、ある isu に関する最新の condition を保持するテーブルであり、以下のように利用されます。
- postIsuCondition の中で latest_isu_condition に UPSERT する
- 「ある椅子の最新の isu_condition を取得する」というクエリは latest_isu_condition を使って発行する
このようにすることで、PRIMRY KEY に対する検索によって一発でデータを取得でき*4、高速化につながるだろうと考えました。
そして、2時間ほどかけて諸々の実装を終え、ベンチマークを回したところ、40000 → 45000 ぐらいまでスコアが上がりました*5。
(18:00 ~ 18:45) クロージング
終了時刻が近づいてきたのでクロージング処理に移り、各種ログの出力を止め、ベンチマークガチャを行いました。 ところがここで、ベンチマークが fail し始めました。
慌てながら色々と調査した結果、前述の latest_isu_condition が原因で落ちてそうだということがわかったため、latest_isu_condition が入る前までコードを巻き戻し、なんとか一回だけベンチマークを通し、試合終了となりました。
振り返り
思いついたことをつらつらと書いていきます。
慣れない言語は難しい
今回私は、デプロイスクリプトをシェルスクリプトで書き、またGoのアプリの改修も行いましたが、どちらも不慣れな言語だったので問題がありました。
シェルスクリプトに関しては、配列の扱いに不慣れだったため、２つのホストにデプロイしているつもりで、１つのホストにしかデプロイできていなかった、という致命的な問題が終盤に発覚しました。 Goに関しては、N+1を直すべくゴリゴリ書こうとしたのですが、普段書かない言語ということもあってかなり手こずりました。
デプロイスクリプトに関してはシェルスクリプトを使うのをやめて、使い慣れた Ruby を使って Rake Task に書き直しました。 アプリに関しては、言語の選択を考えなおすことや、 @ebiebievidence との役割分担も含めて、色々と考え直したほうが良さそうな感はあります。
実装は難しい
実装は難しく、バグが出ます。難しい実装は更に難しいので、バグが更に出ます。 実装せずに早くできる手段があるならそれを選ぶべきだし、簡単な実装で済ませられるならそうするべきだと思いました。
そして、簡単な実装をするためには、そのための知識や準備が必要になるなあと思いました。
ブラウザ周り・HTTP周りの知識が足りない
お仕事でブラウザを直接触ることがないので、キャッシュ周りの知識とかが皆無だということに今回気づいた。 何らか勉強しないとまずいなと思ったので、ひとまずこのブログを頭から読んでいます。
それに加えて、いま輪読会で読んでる本が読み終わったら、そういう本を一冊ぐらい読んでおこうと思っています。 このへんとか。
古いログが混ざってしまった件
追う必要のない500 エラーで時間を溶かした回の話。
今回作ったログローテーションスクリプトは、「ログローテーション」と「ログの手元へのコピー」がワンセットになったスクリプトであり、ログのコピーが遅いためにスクリプト全体が重くなっていた。 そのため、ログローテーションを行うには長い時間がかかり、ログローテーションを行わないモチベーションが生まれていた。 その結果として、デバッグ中に出たアプリログが残ってしまい、正常なベンチマーク時のログと混ざってしまった。
この問題は、以下の2つの対策によってある程度解決できるだろうと考えています。
- ログローテーションと、ログの手元へのコピーを独立して実行できるようにする
- これにより、手軽にログローテーションを行えるようになる
- デプロイスクリプトの中でログのローテーションを行うようにしておく
- これにより、アプリをデプロイしたのであれば、ログはローテーションされている、ということを担保できます
ロールバック可能性の担保
最後の最後でFailすることに気づいたが、ロールバックをうまい単位で行えずに、ログを切るコミットも消してしまいました。 ベンチマークを通った各コミットにタグを打つなどして、サクッと撤退できるようにしておくべきだったと思います。
このことが、クロージングのバタつきの一因となったと思いました。
エンバグへの対処
コードの修正を伴う改修はエンバグ確率が高いので、ベンチマーカーが数回通ることを確認してからマージするのが良さそうです。 なぜならば、以下のような場合、エンバグは一発のベンチマークで検出されないからです。
- 確率で失敗するロジックが存在するケース
- 2回目のデプロイ以降で死ぬようになるケース
そのため、修正をマージする前にベンチマークを数回実行し、エンバグしている可能性を下げておくのが良さそうです。 ただし、index を追加するだけ、みたいなやつは1発ベンチを通してマージでも良いと思います。
再起動試験できた
去年は再起動試験をせずにフィニッシュしました。 今年は再起動試験をやって無事なことを確かめました。結果的には運営の人が書いたであろう restart=always があったので問題ありませんでしたが*6。
ISUCON10 の反省を生かせた
ISUCON10 での反省点を解消するのが、ISUCON11 における自分の隠れ目標でしたが、解消できたものとできなかったものがあります。
解消できたものはこの辺です。
- 競技開始直後にアクセスログを分析することはできたが、競技中に分析できず、アクセス傾向の変化に気づけなかった
- 作業の依存関係の整理や優先度付けが下手で、ログ分析に着手するのが遅れた
- ミドルウェアのアップグレードに失敗する、ミドルウェアの秘伝のタレを扱えないなど、インフラ面のスキル不足が露呈した
- 再起動試験に失敗したであろう構成のままフィニッシュしてしまった
- ボトルネックを見つけるのにこだわりすぎて、改修に手を出すのが遅れた
- テーブルの構造を最適化するような大きな改修を行えなかった
一方で、以下の点については今年も課題が残ったと思いました。
- 複雑な実装に手を付けてエンバグした
- 見たことのない機能が使われているのを見て脳が停止した
前者に関しては、ベンチを数回回してからマージするフローを採用することで問題を回避できそうな気はしてます。 後者は Conditional GET の話ですが、初手で「Conditional GET は誰もやったことないからやらないことにしよう」という判断をしてしまったのが駄目だったなあと思います。 時間制限がある中でも落ち着いて、新しい知識を仕入れながら使う、ということができるようになりたいものです。 またその一方で、Webエンジニアとして必要になる知識は、普段から幅広く仕入れておく必要があるとも思いました。
改修の筋道を立てられた
alpで分析したアクセスログと、マニュアルにあるスコア計算式、ベンチマーク終了後のDBの状態、そしてベンチマーカーの出力を睨みつつ、今どういうことが起きていて、それを解消するために、どのような順序で問題を解消していくべきか、という筋道を組み立てることができたのは良かったかなと思います。
具体的には以下のような感じです。
アクセスログを分析すると、以下のことがわかる 1. 椅子の状態登録APIで、多くのリクエストがタイムアウトしており、十分な数のデータを保存できていない。そして、新しいデータを保存できないと、得点に繋がらない。 2. 自分の椅子の情報を取得するほとんどのAPIで、リクエストがタイムアウトしており、得点が上昇していない。情報取得APIが直接の得点源であるため、これを改善することで得点が上昇する。 3. トップページのトレンドAPIがタイムアウトしており、新規ユーザーが増加していない。 また、ベンチマーク終了後のDBの状態を見ると、椅子やユーザーの数は少ない(数件〜数十件のオーダー)。 この人数を捌けないのであれば、トレンドAPIを改善して新規ユーザーを流入させても、得点にはつながらないだろう。 したがって、今やるべきことはトレンドAPIの改修ではなく、状態登録APIや情報取得APIの高速化である。 そして、それらのエンドポイントが十分高速化した暁には、トレンドAPIを改善して新規ユーザーを流入させることを考えるべきである。
このような筋道を最初に立てることで、やるべきことが明確になって取り組みやすくなったと思います。 一方で、これは次の項目にも関連しますが、立てた筋道の妥当性に関しては疑問が残ります。
解き方が不適切だった説
競技終了後に社内でISUCON感想戦をやりました。色々と学びはあったのですが、一番タメになったのは まずはリソースの飽和を解消すべきである ということでした。
前述の「筋道」で自分は、
トレンドAPIを改善して新規ユーザーを流入させても、得点にはつながらないだろう。 したがって、今やるべきことはトレンドAPIの改修ではなく、状態登録APIや情報取得APIの高速化である。
と書きました。これは、得点の増加という観点からは妥当だったと思います。 しかし、MySQL のCPU使用率が100%になっている状態では任意のSQLが重くなるため、得点に直結するAPIを改修しても十分な効果は得られないと考えられます。
そのため、得点に直結するAPIを直すより前に、リソースの飽和の原因となるAPI（この場合はトレンドAPIやgetIsuCondition）の改修に優先的に取り掛かるべきだったとも思えます*7。
情報の集約
今回は各人の作業状況を、こんな感じで Google drive に集約しながら進めました。 これにより、「次に自分が何をやればよいか」「他の人は今何をやっているか」をひと目で知ることができ、見通しが立てやすくなった(不安が小さくなった)と思います。
また、１時間に１回ぐらいの周期で全員が手を止め、情報を共有したり、次の方針を決めたりしていて、これも良かったです。
手早さ
行動ログを見るとわかるのですが、 12:20 ~ 15:00 あたりはかなり無をしています。タラレバですが、ここの時間が丸っと削れたとすれば、 latest_isu_condition のデバッグをすることもできたし、その上でさらにもう一つぐらい改修を入れられたと思います。
スローログがうまく取れないという状況にはありましたが、結局スローログを見なくても index は貼れています。 多少効率が悪くなったとしても、もっと早いタイミングで「実質的な効果を持つ施策」に着手するべきだったかもなあと思いました。
また、これ以上の順位を取るためにはindexを貼る程度の最適化では難しく、アプリ改修も含めた最適化に手がある必要があります。しかし、そのような最適化に手を出すためには、コードリーディングの速度やコーディングの速度が必要になってくると感じました。
総括・所感
昨年よりは多少マシになっていて、少なくともデグレはしてないと思います。しかし、一昨年→昨年の差分に比べると、昨年→今年の差分からは、自身の成長がスコア上昇に寄与している感覚が少なかったです。
一昨年→昨年は、production-ready なWeb開発の経験がないところから、業務経験をバリバリ積んで index の知識が付いたことで、成長を特に感じられたと思います。一方で、昨年→今年はそういう技術的成長がなかったとも言えるかもしれません。もちろん何かしら成長してはいるのですが、ISUCONで役立つ技能はあんまり増えてないような気はしてます。
技能が増えてないという感覚を得たことで、来年に向けて勉強したいという気持ちが去年よりも強くあります。とりあえず、今年の予選問題はハイスコアが出るまでチューニングし続けてみようと思いました。
最後に、一緒にISUCONに出てくれた @ebiebievidence と @uni745e、ありがとうございました！
