ISUCON13に参加してきました

初期点 (3950)

初期点は 3950 でした。

Nginx / MySQL 構成であること、Go 言語で立っていること、sysmtectl | grep isu、neofetch などお決まりの環境チェックをして、例年の構成と同じだと判断しました。

用意していた Makefile を置いたり、 alp や pt-query-digest 、 discorder などのツールを落としてきました。

各種ログセットアップ (3119)

今回はそのままいつものように nginx のアクセスログと mysql のスロークエリログと pprof を取得しました。

各種ログセットアップは 3119 でした。

DNSのTTLを設定 (3255)

@a01sa01toが DNS キャッシュの TTL が 0 になっていることに気づき、TTL を 3600 に設定しました。

livestream_tags へINDEX貼る (2958)

ベンチマークを走らせてみると、やはりスロークエリが多いようでした。

pt を見ると上位に Rows examine (avg) 10.88k に対して Rows sent (avg) 3.69 というトンデモクエリがあったので、これに対してインデックスを貼りました。

SELECT * FROM livestream_tags WHERE livestream_id = 7494\G

NOTE
※ 実は貼ったつもりでしたが、貼り方を間違えていて点数が上がらず地獄でした。
同じサークルから別チームで出ていて、練習会で一回も負けたことない maximum-baby と maximum.mum が初っ端から6000点とか出してて「俺ら今回負けるんじゃね！？」なんて話してた記憶があります

以降、DB負荷が下がらないまま 3~5000 点付近5時間ほどうろうろすることになります

fillLivestreamResponse の tags に関するN+1を解消 (3141)

@sor4chiが fillLivestreamResponse 内の tags に関する N+1 を解消しました。ほとんど誤差な気がします。

themes をキャッシュ (3650)

@sor4chiが themes テーブルへのクエリが SELECT と INSERT しかないことに気づき、 SELECT した結果をキャッシュするようにしました。

user icon の hash をキャッシュ (3543)

ユーザーのアイコンのハッシュをキャッシュすることで、DB の負荷を下げました。
この時同時に If-None-Match を使って、キャッシュが有効な場合は 304 Not Modified を返すようにしたつもりだったのですが、実際はリクエストの If-None-Match ヘッダはダブルクォーテーションで囲まれていたため、その Hash 文字列と素の Hash が一致しないためキャッシュが効いていませんでした。
(これは最後まで気づきませんでした)

それから、キャッシュヒットせずにハッシュを生成したあと、ETag ヘッダに入れないといけないことを知らず、フロントエンドエンジニアとしてとても恥ずかしいことをしました。
(これも気づかなかったのでほとんど意味なかったのかなと思ってます)

サーバー分割 (4504)

@a01sa01toがサーバー分割を行いました。
ついでにベンチ開始後の DNS 追加設定にも TTL を設定するようにここで変更してくれたようです。

のようにすることで、水責めの負荷が App や App DB に影響しないようにしました。この分割の判断はかなり早かったと思います。
さらに、DNS DB にも Lookup 負荷がかかることに気づき、INDEX を貼っていくれたそうです。

@a01sa01toが表現してくれたフローがこちら。わかりやすい。

ベンチ -[global]-> DNS (s1) -[local]-> DB (s1)
ベンチ -[global]-> nginx (s2) -[local]-> App (s2) -[private]-> DB (s3)

DNS 何もわからんなのでとても助かりました。

moderateHandler のN+1解消 (4763)

@sor4chiが moderateHandler の N+1 を解消しました。

getUserStatisticsHandler のN+1解消 (6409)

@Ryoga_exeが getUserStatisticsHandler の N+1 を解消しました。

INDEXを正しく貼る (22687)

開始から 5 時間経って、t@a01sa01to がやっぱり INDEX が効いてないんじゃないかと言い出して、実際に MySQL にログインして EXPLAIN してみると、 livestream_tags に livestream_id に対する INDEX が貼られていないことに気づきました。

じゃあもうわからんから 10_schema.sql に書くのやめようということで Index Already Exists にならないようにアプリ側でキャッチしながら CREATE INDEX するようにしました。

ついでに pt-query-digest 上位だった SELECT の Rows examine / sent 比が高いクエリ全てに INDEX を貼りました。

ここで点数が 22687 と一気に 4 倍近くまで上がりました。

t@sor4chi「本当にごめん、あとで土下座させていただきます」

getReactionsHandler の N+1 解消 (28638)

@Ryoga_exeが getReactionsHandler の N+1 を解消しました。

(リーダーボード凍結)

最後の 1 時間はリーダーボードが凍結します。凍結直前の時点で 23 位だったので、「30 位圏内には入れそうだねー」という話をしていました。

user icon の hash の余分な計算を削減 (38578)

キャッシュヒットした後でもに DB に image を取りにいくような実装になっていることに気づき、t@a01sa01to がキャッシュヒットした後は DB にいかないようにしました。

fillLivestreamResponse の N+1 解消 (45116)

@sor4chiが fillLivestreamResponse の N+1 を解消しました。

fillUserResponse の N+1 解消 (52872)

@sor4chiが fillUserResponse の N+1 を解消しました。

整合性エラー (0)

最後の 9 分で整合性エラーが出てしまいました。その時ちょうど systemctl disable 作業をしていたので、一度 systemctl enable して戻したのですが治らず…。
全員で急いで確認したところ、isupipe-go.service がおそらく前のベンチマークの負荷で途中で異常終了していたことが原因でした。
仕方ないですが、最終チェックでエラーにならないことを祈りつつ systemctl enable してベンチマークを再開しました。

ログ閉じ (58960)

最後の 2 分で Logger Middleware を消したり、Access Log と Slow Query Log、pprof を閉じて最後のベンチマークを走らせました。

以上、とりあえず影響がありそうだったやつをピックアップして時系列で紹介してみました。他にも色々やってるのでこれが全てではないです！