2021/08/25

ISUCON 11 にfujiwara組で出場して予選突破しました

こんにちは! 本日はほとんどISUCONのことしか書いてないブログへお越しいただきありがとうございます! だって全然旅行できる気配がないんだもの…。

さて、ISUCONの季節ということで今年もfujiwara組で出場しています。メンツも昨年と同じ 組長(fujiwara)、れもん(acidlemon)、まこぴー(macopy) の3人です。昨年は予選通過ラインに2チーム分届かずに予選落ちでしたが、今年はバシッと全体4位のスコアが出たので無事予選通過しております。では、さっそくやったことなど書いていきますね。

3人の分担は特に決まってないですが自然とこんな感じです。普段の仕事と同じ感じ。

• 組長: インフラ設定、デプロイまわり
• れもん: 仮説立てて策を考える、ちょろちょろコードを書く、大技をかける(そして不発)
• まこぴー: バリバリとコードを書く

デプロイ、レビュー、パフォーマンス分析とかは3人ともそれぞれやります。各自が同じ各種ログを見ながらあれこれ話して次の策を決めてそれぞれ取りかかるみたいな感じですね。

はじまるまで

前日までの動きとして、CloudFormationで事前のサーバ構築試験とかいい感じのitamae準備は例年通り組長がやってくれていたので、私は「そろそろリポジトリがほしいです!」と主張するくらいの事しかしていません。昨年に引き続き会社の会議室をとったくらいか。

昨年は競技開始が2時間くらい遅れましたが今年はなんか時間通り始まりそうな波動を感じていたので、会社に9時過ぎに着いて自席から会議室にディスプレイやキーボードなどの機材を運んだりしていたらもう9:30すぎでした。お昼ご飯を確保してなかったのでそこから急いでお昼を買いにいって、戻って来たらちょうど9:45くらいでいい感じに着席してライブ配信を眺めます。

トリプルディスプレイしようとおもったんだけど4Kディスプレイ2枚使った時点で3枚目の外部ディスプレイは出力されなかったんですが、よく考えたらMacBook Proって外部ディスプレイ2枚まで+内蔵ディスプレイで合計3枚はいけるけど、リッドクローズした状態からの外部ディスプレイ3枚ってできないんですかね〜。

そんなことを思いつつ、いつもの謎のオープニングを眺めて「あーIoT系か〜」などと言いながら10時を待ちました。

はじまったぞ

最初にレギュレーションをよんで、スコア伸ばすポイントをざっくり把握。レギュレーションとアプリケーションマニュアル読んだ感想としては…

• グラフの加点がすごい。1時間あたり最低N個のデータポイントをちゃんと保持できてればX点
  • Goodだと60点(当日)とか150点(当日以外)とか、明らかに破格の点数
• 認証系が外に出てるんだな〜 OpenID Connect的なやつか〜
• ISU管理サービスも外に出てるんだなあ〜
• ISUの登録APIから呼び出す外部APIの POST /api/activate に渡すターゲットホストをバラしてコントロールすることでリクエストのロードバランスができそう
  • できそうだな〜とおもってたけど結局そこまで手が回らなくてやらなかった
• 外に出てるサービスのモックがあるのはありがたい、けど、この手のフルスクラッチ向けのテストバイナリを使ったことがないんだよなオレたち

という感じです。

やったこと

実際にやったことは既にマージされたPRベースで組長のブログに書いてあるのでざっくりとししたやつはそちらを読む、でよいのですが、解法上考えたこととかそういうのにフォーカスして書いていきます。

明らかに必要なindexを張る

レギュレーションとアプリケーションマニュアルが難解すぎて2回目読み始めてる間にまこぴーが jia_isu_uuid と timestamp にINDEXを張ってくれてた。この時点でもう11時くらいだったんだけど、リーダーボードはでは1万点こえたチームどころか2万3万とみんなスコアを伸ばしてたのでちょっと出遅れ感あったけど我々もこのINDEX張るだけで1万点超えたので「これはもしかして最終的に50万とか100万点とかいくやつか…」と戦慄していた。

INDEXはこの他にも isu の character を引くヤツとかも追加しています。

Goのmysqlドライバにパラメータ追加

pt-query-digest を見た組長が PREPARE してますね、と言ってたのでサクッとオプション追加。毎年やるやつ。ちなみにれもんは mysqldumpslow 派です。いや、pt-query-digest も使えるんだけど、DBの負荷が強いときはクエリごとのQueryTimeの合計しか見ないので、そういう意味では mysqldumpslow を流し読みするほうが慣れておりまして…

debugをオフ、アクセスログもオフ

使用フレームワークはs qlx + echo だったわけですが、昨年とかはログをオフにするの忘れてたりしたので早めにアクセスログをオフに。というのもこの時点でwebappとmysqlのCPU比率が1:1くらいになってて、 systemd-jorunald もまぁまぁCPU食ってたのでさっさとオフにしようという判断です。

このとき、ミドルウェアのログ出力設定のSeverityを(なぜか)INFOにしたのでWARNとして POST /api/condition/${uuid} で書き込みをせずに 202 Accepted を返しているログが出まくってしまい、それで初めて dropProbability の存在に気付きました。この時点でベンチ1回まわしたあとの各テーブルの行数をみるとisu_conditionに7万行くらい入っているのですが、それでも dropProbability は0.9(90%カット)だったわけで、つまり完全に高速化した状態においては60秒間に70万行くらいのINSERTを捌かないといけないことがわかり、震撼していました…。

generateIsuGraphResponse を軽くする

グラフ描くAPIに日付渡ってきてるのにクエリには使われてなくて全期間とってるのでクエリが重い。それは BETWEEN で絞れるやろってなったので、絞りました。

今回はベンチマークシナリオ的に3万倍のスピードで時間が流れるので60秒間に約21日間経つため、クエリで1日単位に絞ると負荷走行の後半だと引く行が全期間ひいてたときと比較すると1/15とか1/20になるので結構効きました。こういう問題だと後半スコアが伸びなくなるので、それを軽減するという意味合いが強いですね。

GET /api/trend は最新の1件しかみてないので、LIMIT 1する

GET /api/trend は色々いじりたくなるポイントが多いんですが、それよりも POST /api/condition/${uuid} に関係する負荷がやばいので、ひとまずtrendは引く行にLIMITかけるだけかけました。

ちなみにtrendはこのあと多重のN+1クエリをどうにかするべく以下のような手も打ったんですが、マージせずにおわりました。

• characterごとのループクエリをJOINで1クエリにする
  • JOINの条件が結構クソクエリ気味で、速くならなかった
• latestのConditionはRedisに保存してtrendではそれを読む
  • いろいろやってブランチは安定したけど、スコアは伸びず

trendどうにかしたかった話は一番最後にもう少し詳しく書いています。

POST /api/condition/${uuid} はBulkInsertする

IoTデバイスからステータスを束でもらうAPI。だいたい1回のリクエストに5〜15個くらい入ってそうなかんじで、INSERTがループクエリになってたのでこれをBulk Insertするように変更。順当にスコアがあがりましたが、思ったほどは上がらず、InsertよりもSelectをどうにかせねばなぁという感じ。

3台構成にする

1台だと早々にもうスコアあがらないかもな〜となったのと、やっぱりDBがヘビーなのが見えてきたので早速分割です。

• 01: mariadbのみ
• 02: nginx + webapp (ベンチの受け口、POST /api/isu の画像保存先)
• 03: nginx + webapp (IoTデバイスの受け口)

外向きには両方nginxを立てています。基本は02と03に均等にリバースプロキシしますが、画像の外部化の処理だけは02が専属で捌くのと、03は POST /api/condition/${uuid} のラッシュを受ける役という分担になっています。いずれにせよ01のmariadbがCPUを200%使っていてここがボトルネックになり、最後まで02と03のCPUはちょっと余っている状態でした。

ここらへんまででだいたい13時。ここからはDBに入ってるデータをカラム増やしてどうにかしたりしていきます。

画像をDBに入れない

isuのテーブルにimageが入っていて、これを引くクエリが結構重いので、初期データから画像を抜き出し & POSTされたものは02のローカルファイルで保存。最初nginxでpublicに見えるようにしてそのまま返していましたが、すると401になるはず! っていうエラーでFailしたのでwebappがStaticFileを返すようにしました。

なるほどISUの画像はプライバシー(?)的な問題で他の人には見せてはいけないのですね……。

アプリの修正でimageをINSERTすることは無くなりましたが、初期データには残ったままなので POST /initialize で UPDATE isu SET image = NULL なクエリも流して SELECT * しているところの転送量も削っています。

condition_true_count カラムを追加

この時点で一番きつかったのは GET /api/condition/${uuid} を捌くところで、ISU単体のコンディション履歴をwarningとかcriticalのseverityでフィルタしながら最大20件返す処理でした。この処理が、履歴を20件返すためにひとまずISUのconditionを全件取ってるのでrow readsがヤバいのなんのということで、ここに手をつけます。

• 「これ最大20件しか返さないからLIMITで20つけとけばよくね?」 → Fail!
• 「なんか条件満たさないやつはsliceに入れてないから、とりあえず20を2倍してLIMIT 40でどうだ!」 → Fail!

ちゃんとソースを読んだら、APIにフィルタしたいseverityが渡ってくるようになってて、ほとんどはinformationなところにwarningだけみたいな感じの条件が指定されると、どうみてもLIMIT40しても20件返ることはない…ということで、DBにseverityを持たせる方向で改修することにしました。

severityは3つあるフラグについて1個か2個trueならwarning、3個ならcriticalなので、それをInsert時にDBに保存すればいいという話なんですが、初期データも手当てしないとならず、ここの手間を減らすためにseverityを直接保存するのではなくてtrueの個数を保存するようにしました。initializeにこのSQLを一発書いておわりです。自分は昔からISUCONではInitialize職人なので、こういうのが大好き。

UPDATE isu_condition SET condition_true_count = ROUND((LENGTH(`condition`) - LENGTH(REPLACE(`condition`, 'true', ''))) / 4)

Bulk Insertする POST /api/condition/${uuid} と、フィルタリングして履歴を返す GET /api/condition/${uuid} もそれぞれ対応しました。

severityに対応する condition_true_count を WHERE IN で絞りながら引くことで、ぴったりLIMIT 20でエラーが出なくなり、スコアが20%〜30%くらいあがりました。

userをオンメモリにする

リクエスト返す速度が上がってきたことで総リクエスト数が多くなり、地味にセッション確認のためにuserのnameを引くクエリがだいぶ回数多くなってきたため、userをオンメモリで返せるようにしました。

POST /api/condition/${uuid} で確率的に何もしてなかったのをやめる

元のソースコードにコメントで書かれていた TODO: 一定割合リクエストを落としてしのぐようにしたが、本来は全量さばけるようにすべき というやつ、一通り高速化したしそろそろ dropProbability を調整してみるか〜ということで調整してみたところ、dropを0%にしたときが最高スコアになったため早速削除。まこぴーさんがコメントに日時を入れていて、この時点で15時半前です。

スコアの説明と、 dropProbability の挙動をあわせて確認するとわかるのですが、

• 基本的にはISUから毎時数十メトリクスくらい飛んでくる
• グラフのAPIをよんだときに、24時間分について毎時21メトリクス以上返せていれば最高点

という感じの仕様になっています。で、メトリクスの記録を90%カットしていると、確率的にいえば24時間分の24個のタイムレンジについて空っぽの時間が発生する確率が8割以上はありそうです。「1時間の間に1個のメトリクスがない」というのはグラフのスコアリング評価としてはWorstということになります。

戦略としては「Worstでいいから大量にグラフのAPIを捌けるようにする」か「リクエストのドロップ率を下げていってちゃんとBadとかNormalとかで点数を稼ぐ」になるのですが、スコアの係数からするとNormalでもWorstの10倍のスコアになることを考えると、APIを10倍捌くよりはグラフスコア係数側で稼いだ方がよさそうです(というか題意にマッチしている)。

ひとまず、9割ドロップをやめたところスコアが5倍くらい(+400%くらい)に上がったので、ここで大きなブレイクスルーその1となりました。

trendのクエリの最適化 → 失敗

上の方にも少し書きましたが、非ログインでみれる GET /api/trend が結構DBに負荷をかけているので、これの高速化に取り組みました。

characterのループ → ISUのループ → ISUの最新condition という二重ループのN+1クエリになっているので、まずはISUのループを展開して、セルフジョインで最新のコンディションをまとめてとれるクエリを書きました。

SELECT isu_condition.* FROM `isu_condition` JOIN (SELECT jia_isu_uuid, MAX(timestamp) AS recent_timestamp FROM `isu_condition` WHERE jia_isu_uuid IN (?) GROUP BY jia_isu_uuid) AS m ON isu_condition.jia_isu_uuid = m.jia_isu_uuid AND timestamp = m.recent_timestamp

JOINの条件が2条件になっているのがちょっとアレですが、explainしても意図したキーは使われてるし問題無さそう…なのですがベンチしてもスコアが向上しないため、この作戦のブランチは捨てることになりました。

とはいえここをどうにかしないとDBのCPUが空かない(webappのCPUが余っている状態を打開できない)ということで、最新のconditionを取るところをDBではなくRedisにしようということで、Redis対応をやりました。

1回Failしつつ修正したところ無事ベンチは通ったのですが、ちょうどその直前あたりの時間からベンチマークのポータルの挙動が怪しくなってきたり、そもそもサーバのslowlogがディスクを圧迫していたり(後で分かった)でスコアが満足できる水準にならず、ポータル閉鎖されてて詳細を調べることができなかったためこのブランチも捨てました。ちょっと悔しい。

押しの一手: isu_conditionのINDEX更新負荷を減らす(PKEYを変える)

17時台のポータル閉鎖中に再起動試験もおわり、気がつくと18時。結局今回は「dropProbabilityを0にしてスコアが下がらない程度に高速化出来ていれば予選通過ライン」という感じになりそうだということはわかったのですが、そのラインに達するチームが何チームくらいいるか予想つかなかったので、そのライン越えたチームの間でも出し抜かないと危ない…ということで押しの一手を考えました。

ここまででとにかくWrite HeavyなDBであることは分かっているので、少しでもその負荷を下げるのがよい、ということでスキーマを見直すと、ここまでの作業の過程で isu_condition にINDEXを2つ張ってました。

ALTER TABLE `isu_condition` ADD INDEX `jia_isu_uuid_timestamp_idx` (`jia_isu_uuid`, `timestamp`)
ALTER TABLE `isu_condition` ADD INDEX `jia_isu_uuid_condition_true_count_timestamp_idx` (`jia_isu_uuid`, `condition_true_count`, `timestamp`)

2つのINDEXの違いは2番目のカラムなのですが、jia_isu_uuid と timestamp だけが必要なクエリでもIndex Condition Pushdown で後者のINDEXは一応効きます。ということで、ここまでWrite HeavyであればINDEXの更新負荷を下げるべきという判断をして、前者のINDEXを消しましょう! という話をしました。

で、よくよくみていくと

• isu_conditionのPKEYである id (auto_increment)はユーザに返してないので別になくてもいい
• PKEY自体をidじゃなくて jia_isu_uuid と timestamp の複合PKEYにしてよさそう(マニュアルに「コンディションの時刻情報は、既に送られたコンディションの時刻情報よりも常に先の時刻となる。」とかいてあるので、同じISUにtimestampが被る事は無さそう)
• 複合PKEYにするとそもそも1個目のINDEXと同じなのでクエリパフォーマンスに影響がない
• つまりいいことしかない

ということがわかり、id のauto_incrementを外しつつPKEYを複合PKEYに変更して、INDEXを1個削ったところスコアがまた60〜80%くらい伸びて最終的には70万点となりました。正直、そんなに伸びるのか〜と3人ともびっくりしていました。一番最後にブレイクスルーその2がくるとは。

そんなこんなで18時半過ぎ。さすがに70万点出てれば予選は通過してるだろ! と安心しつつ競技を終えました。

もっとスコア伸ばせそうだったポイント

conditionのINSERT負荷

conditionのメトリクスを一切ドロップしない状態にすると60秒間に70〜80万行ほどのINSERTが走るのですが、1時間あたりに返すデータポイント数は21個あれば最高スコアです。1分おきくらいのペースでメトリクスがくると1時間に50データポイント以上INSERTされるので、ここをなんかいい感じにして21個くらいになるように、リクエストの中でINSERT量を調整するみたいなのはあるんじゃないかな〜と思いました。

trendのキャッシュ

trendは、「POST /api/condition/${uuid} の結果がtrendに反映するのが遅れてよい」とは書いてあるのですが何秒キャッシュしていいかレギュレーションに書いてなくてよくわからないので、proxy cacheするという判断をしませんでした。でも、よく考えたらそもそも最初90%ドロップしているわけだしtrendの最終更新日時が巻き戻ってないかくらいしかベンチマーカー側はそもそも遅延をチェックできないはずなので、わりと勢いよくtrendをキャッシュしちゃえばよかったな〜と終わってから思いました。ちなみにRedisブランチ作っている最中に、トレンド巻き戻り問題によるFailは経験しました(syncして回避)。

ベンチマークを回すと5秒おきに「ユーザが増えました」「ユーザが増えませんでした」とでるわけですが、これがおそらくtrendの速度とかと連動してそうな雰囲気で(題意を読む限り未ログイン状態でみれるトレンドがいい感じだと増えるという感じのはず)、だいたい1人増えるのが2〜3回あったくらいでした。これもうちょっとユーザ増えるとスコアも増えるんだろうな〜と思いました。

ちなみに、結局マージ出来なかったRedisブランチはロジックとしてはバッチリ完成していてベンチ自体は通っていました。計測する限りトレンドの生成速度がめちゃめちゃ速くなってました。それを示すかのように、そのブランチだと一番最初のユーザ増加が一気に6人とか見たことない増え方をしたのですが、ユーザが増えるとISUが増えるわけで、POST /api/condition/${uuid} がますます激しくなってしまいベンチの回転が悪くなるらしい(グラフの表示回数が1/5くらいになってた)…というような感じでスコアが伸びなかったようです。trendのリアルタイム更新性能をあげるよりもtrendをキャッシュするだけキャッシュして更新頻度を下げたほうがよかった、ということなのかな〜。

おわりに

ISUCON 11出題チームのみなさまよい問題をありがとうございました! 久々にWrite Heavyな問題だったのでとても楽しかったです! 基本的にWrite Heavyな問題が好きなので、個人的には相性の良い問題だったな〜と思いました。

それでは、本戦のブログでまたお会いしましょう〜