2021/09/21

ISUCON11 で優勝しました

シンプルで力強いタイトルをつけてしまいましたが、2021/09/18に行われたISUCON11の本選にfujiwara組で出場しまして、優勝することができました。メンバーの話とかは予選ブログのほうに書いてますので、そちらを参照ということで、早速やっていった内容を書いていきます。

今回は全然スコアが上がらなくて、とにかく細かいやつでもいいから施策を入れまくって積み上げるみたいな感じでやったので、やったことが大量にあって読むのにとても時間のかかるブログになっております。ちゃんと読もうとすると15〜30分くらいかかるとおもうので、お時間のあるときにゆっくりお読みください。

あわせて読みたい

チームメンバーのブログもあります。

はじまるまで

基本的には予選とおなじ準備をすればOKというところなのですが、久々の本選出場なのでせっかくなので優勝したいなぁ…ということで、今回はちょっと前日に本気だしまして、過去のブログなどを読みあさって「れもんが本番中にいつも忘れる細かい改善チェックポイントリスト」(通称: ISUCONとらのまき)をA4で1枚にバババッと書き出しておきました。よくあるのが、せっかく虎の巻つくったのに結局本番中に見ないみたいなのがあるのですが、今回はちゃんと開始3時間後くらいに存在を思い出したので役に立ってた感じです。

なにが書いてあったかというと、「認証のある静的ファイルはX-Accel-Redirect!」とか「JSON生成遅いのでgoccy/go-jsonを使う!」とか「Thundering Herd対策にsingleflight!」とか「PKEYが文字列(特にUUID)は遅いよ」とかそういうのです。

10:00〜11:00 はじまったぞ

予選の時はまずレギュレーションを読んでいたのですが、本戦はわりと最終的にインフラ勝負になりがちなので、レギュレーション読みをまこぴーさんに任せ、インフラセットアップは組長に任せて自分はまずインスタンスの詳細をつぶさに調べるところから始めました。

で、よくみるとCPUのモデル番号が違うことがわかり、ひとまず複数台構成にするときにはDBは2台目にしましょうかねという話をしていました。

CPUモデルが違うね

CPUモデル番号の話は本選おわった後の雑談で軽い気持ちで「c5.largeのCPUが2種ありましたよね〜」って言ったら運営の人たちがちょっと慌てていたので「あれ、余計なこと言ったかな…」みたいになりましたが、性能差的にはほぼ誤差レベルというのと、最終スコア計測時にそもそもEC2をStopするからCPUモデルは再び起動したときには変わってるという話(たしかに〜)になって特段の対応はナシとなっていました。

そういうのClarほしい! というのも後から言われるとたしかに〜と思ったんですけど、ISUCON10の本選は3台ともスペック異なったりしててそれについてのClarで「見えてるとおりです」みたいな回答だったとおもうので、まぁ今回もそういうものかな〜と思って特に何もしませんでした…。

初期ベンチのスコアは確認していて

  • isu01(8124M): 30630
  • isu02(8275CL): 32288

5%くらい違うけど、まぁ誤差といえば誤差か〜。あとはAWSのEC2なので、EBSのFirst Touch Penaltyがあるのを思い出して、11時台に dd if=/dev/nvme0n1p1 of=/dev/null bs=1M して、ひとまずそういうやつでスコアばらつく可能性があるというのをあらかじめ潰すというのはやっています(3台目だけは全然暖まってなかった)。

初期ベンチを回した & さっそくDBを別マシンに分離

ということで、初期スコアは3万点ちょい。本選開始前にアナウンスのあった特別賞のボーダーは8万点だったはずなので、「ええ、1台で3万点でるなら3台に分散するだけで9万行くのでは…?」となりました。

実際他のチームは最初の1時間すぎたところで7万点とかまであがっていたので、いつもだともうちょっと中盤に複数台構成にするところなのですが「fujiwaraさん! わたし5万円ほしいです!」と言って11時過ぎに無理いって2台目でDBが動くように整備してもらいました。

普段だと初動の組長は1台目で一通りデプロイとかできるようなやつを最初の1時間くらいでセットアップして、そのあと明らかにスコアの足枷になるミドルウェア設定(nginxやmysql)を他の2人の知らないところで潰す業をしているところだったと思うんですが、「ちょ、ちょっとまって〜」と言われつつもサクッとやってもらって1台目がapp+nginx、2台目がDBの構成になりました。

2台構成にしてもらっている間に、まこぴーさんがサクッとinterpolateParamsの設定 #2 と、echoのLoggerを潰す #3 のをやっています。

11:00〜12:50 GetGrades でスコアに天井が設定されていることに気付く

time score
11:10 DBを2台目にする (fujiwara) 49585
11:24 nginx keepalive入れる (fujiwara) 53814
11:45 unread_announcements をINSERT SELECTにすることでINSERTループを撲滅 (macopy) #4 55077
12:04 createSubmissionsZip()archive/zip に (fujiwara) #5 65737
12:10 registrations のINSERTをBulk Insertにする (macopy) #6 バグ修正:#11 65138
12:42 submissionsのUPDATE文でusersをJOINしててロックかかるのでやめる (macopy) #7 64386

すごい! スコア伸びてる! けど自分の名前が出てこないので何もやってないようにみえる! おにぎりツイートしてたし。通常の業務においても私はおちゃめ担当なので、まぁそんな感じです。

長大JOINクエリとか、ループクエリとかがたくさんある問題なので、この時間帯は私は計測してボトルネックがどう移り変わっていくかをずっと眺める業としてpt-query-digestやalpのnginxログ集計結果とにらめっこしつつ、ソースコードを全部読みました。で、まこぴーさんにはpt-query-digestのRankを元に「いくつか改善して欲しい関数あるんだけど、この順番でやってほしい!」というオーダーをだしたりしていました。

12時すぎにソース全部読んで気になった点として洗い出したやつのメモが残ってます。

GetRegisteredCourses()
- teacherのリストがN+1クエリになっている
RegisterCourses()
- 履修するコースをループで回してSELECTを2クエリずつ実行している
- 履修情報の登録をループで回している
GetGrades()
- 二重のループクエリ(講義一覧→講義ごとに集計)
  103リクエスト中19リクエストしか成功していない、残りは84個の4xx(たぶん499)
SearchCourses() *Public API*
- 検索条件を WHEREのANDでたくさん繋いでいる
GetClasses()
- LEFT JOINがある、ORDER BYもある
SubmitAssignment()
- PDFのアップロード /api/courses/:courseID/classes/:classID/assignments
RegisterScores()
- UPDATE submissions をループで回している
createSubmissionsZip()
- Zipをコマンドベースで作っている

12:40すぎに取ったpt-query-digestを見ると、この時点であきらかにヤバイやつがいます。

Rank Query ID                     Response time  Calls  R/Call V/M   Ite
==== ============================ ============== ====== ====== ===== ===
   1 0xFFFCA4D67EA0A788813031B... 249.0170 55.8%  75581 0.0033  0.00 COMMIT
   # GPA算出
   2 0x8082220C07E2A565D306665...  87.7670 19.7%    223 0.3936  0.03 SELECT users registrations courses registrations courses classes submissions
   # totalScore算出
   3 0xA9A13C7DE4DE6522B8635F3...  19.7216  4.4%   8564 0.0023  0.00 SELECT users registrations courses classes submissions

Write Heavyな問題なのでCommitが異様に多い(読み込み系もTx使っているから…)というのをさておいても、この223 CallしかないのにTimeの20%使ってるこのヤバイクエリ、これが GetGrades にあるGPAを算出しているやつですね。初期の時点ではtotalScore算出のクエリのほうがわずかにトータルのCPU時間を食ってましたが、この時点ではデータが増えたことによりGPAのほうがかなり時間を食うようになっています。

で、この13時前くらいの時点で、さらに2〜3個くらいPRを積んであったのですが、ベンチの回転速度が高まった結果、最後の整合性チェック中に呼び出される GetGrades のループクエリの数が多くなりすぎて5秒タイムアウトになり、Failするという、天井に当たる現象が出始めました。とにかく GetGrades 以外の所の改善をいれても最後にコレで落ちるので、基本的にはこれをどうにかしないと、他になんの改善をしても意味がないということです。特別賞の8万点ボーダーをクリアするには、それを超えないといけないということで、「なるほど〜、8万点ボーダーの意味はそういうことか〜〜、よくできているな〜〜〜」となりました。

12:50〜14:10 GetGradesに手を入れて天井を突き破ろうとする

time score
12:50 検索API(/api/course)に max-age=60 つけて同じ検索クエリはキャッシュ (fujiwara) #8 0
13:00 goccy/go-jsonに入れ替え (fujiwara) #9 0
13:05 焼肉ジャンボチキンチームが8万点達成して特別賞を取る (おめでとうございます!)
13:25 userCodeもセッションに入れてusers引くのをやめる (fujiwara) #10 0
13:27 GPA計算をsingleflightする (acidlemon) #12 64256
13:30 IDカラムをlatin1にする (acidlemon) #13 (12時台に作ってペンディングしてたブランチ) 65378
13:35 innodb_log_writer_threads = off (fujiwara) 66168
13:38 innodb_doublewrite=0にする (fujiwara) 68692
13:50 teacher.nameをインメモリキャッシュする (fujiwara) #14 66168
14:06 参照系のトランザクションを削除 (fujiwara) #15 68588

私がGetGradesのGPAをどうにかしている間にみんなガシガシ天井にあたって0点になるPRをたくさん作ってくるものだから13時半前後のプルリクマージ渋滞がヤバいことになってました。

userCodeをセッションに入れる (fujiwara)

これは結構お決まりの、「ISUCONだとユーザ情報とるためにSELECTを1回するのはもったいない」というやつで、今回はセッションがクライアントクッキーだったのでクッキーセッションにそのままuserCodeも入れちゃえという感じになっております。

GPAをなんとかする

GPAを算出するSQLは16行くらいあって、JOINのある副相関クエリの結果にさらに4テーブルほどJOINするという、一目見ただけで正気の沙汰ではない(褒め言葉)とわかるクエリでした。

このクエリよく見るとWHERE部にはユーザのタイプしか指定されておらず、しかもそのユーザのタイプはENUMになっていてstudent固定です。どういうことかというと、GetGradesは /api/users/me/grades という認証が必要なエンドポイントであるのにも関わらず、その中に全学生のデータをスキャンして統計情報をだすクエリが埋まっているということです。数十人の学生がこの重厚なクエリを同時に叩くので、それはそれは重くなります。

で、この統計情報クエリは誰が叩いても(user_idがSQLのパラメータに入ってないため)同じ結果が返るということで、なるべくならこれはプロセス内でキャッシュしたほうがよいし、singleflightで多重実行されないように保護したほうがよいねということで、そういうコードを用意しました #12

このコード自体はISUCON10の本選でsingleflight使ったときのコードをぱぱっと持って来ただけなのでただの多重実行制御だけでなく900msのキャッシュもおまけでついているコードです。今回はレギュレーション上「1秒までなら反映が遅れてよい」といった明確にキャッシュできるポイントは明示されていないため、とりあえず900msキャッシュしてFailしたら短くしていこう…という感じで動かしてみたところ、そのまま通ってしまったのでじゃあ900msキャッシュしちゃえ〜 ということで、そのまま採用となりました。

このPRには実行効率上げるためのこだわりポイントがあります。初期実装ではGPA計算は他にも重いクエリの埋まったGetGradesの一番最後にあるため、GetGradesが数十人からほぼ同時に叩かれても履修した科目の数によってGPAのクエリが叩かれ始めるタイミングの差が出ます。なので、それを回避するためsingleflightにする時点でGPAクエリの実行を GetGrades の先頭に持って来て、同時に叩かれたらちゃんとsingleflightで漏れなく吸着する、という点です。

で、このPRをマージしてスコアは 64256 ということで、案外伸びない…とおもったら、そもそもこのブランチちょっと古いところから切ってて組長とまこぴーさんの12時台の怒濤の改善が入ってなかったため、それらを入れるとスコアは 65378 まで伸びました(13:30)。

小ネタ: PKEYが文字列なのはちょっとムズムズするのでなんとかする

ISUCON11が始まるちょっと前に、MySQLでプライマリキーをUUIDにする前に知っておいて欲しいこと という話題がありまして、要約すると「ランダム生成したUUIDをPKEYにするとデータが一様に分散してしまうのでキャッシュヒット率的に遅いよ」というような話でした。

今回はULIDなのでその辺大丈夫ではありましたが、それにしたってCHAR型のPKEYはBIGINTとくらべてもバイト長がそれなりに長いので、INDEXの更新コスト(FKEYいっぱいあったし)とかを考えたらなるべくやめたい気持ちがあるよねぇ…。とはいえ、ULIDを整数に戻すには128bit必要なのでそれがサクッと入るデータ型はない(後から思ったのは、例えばDECIMALとか…?)ということで、やれることがない…。

と思ったんですが、MySQLはカラムごとにキャラクタセットを指定できるので、とりあえずutf8かutf8mb4になっているであろうこの CHAR(26) カラムを全部latin1(最大1バイトのエンコーディングならなんでもいいのでasciiとかでもOKのはず)にする、というのをやりました#13。singlegflightの後にこれをマージして 65378 → 66168 ということで、まぁはっきりいってチリツモレベルという感じではありますが、今回は本当にスコアの上がり方が渋いのでチリツモでもいいから思いついて作業コストの低いやつ全部やっとけ! みたいなノリでやりました。

14:10 ようやく足枷を1個みつけたので外す

time score
14:15 MySQLがbinlogを吐いていたので止める (fujiwara) 80193

いやー、12時台13時台に3人がかりで怒濤のPRを入れまくったけど、ちょっとずつはスコア改善してるものの7万点にもまだ乗らないし、一体なにをどうすればいいんだ…となり始めました。特別賞がでて1時間経つのにまだ特別賞ラインに載せられていないのはなかなか厳しい。

ということで、DBマシンのメトリクスを集中的に眺めることにしました。とにかくWriteが多すぎてiowaitも出てる、でもそもそも大量書き込み問題だし組長は定番のDisk Write減らすチューニングは全部やってくれているしで打つ手がないかな〜〜〜 と思ったんですが、innodb_file_per_tableになってるかどうかとかも自分は把握してなかったので、まずは現場を見た方が良いよねということで /var/lib/mysql を見に行ったらめっちゃbinlogが出ていました。

「fujiwaraさん! binlog出てます!」「あれ、なんでだろ、そうかMySQL8はデフォルトでbinlog出ちゃうんですね、使ってないことがバレるなハハハ」みたいなやりとりがありつつ、サクッと外してもらって 68588 → 80193となり、特別賞ラインに乗りました。「これか〜〜〜」「あと1時間早く気付いてれば特別賞いけたのに〜〜」みたいな会話もありましたが、singleflight GPAが終わったのが13時半なので、まぁbinlog止めるだけでは13時時点ではダメだったでしょうねw

全体ベストスコアが出たので配信を見に行く

ISUCON10本選からライブ配信が始まり、昨年は並行チームとして出てたのでライブ配信を生で見るの楽しいな〜と思いながらリラックスして解いていました。しかしさすがに今年は気が散るのでライブ配信聞きながらやるのは無理だ…と配信切ってたんですが、全体ベストスコアでたタイミングで魔が差してしまい運営の様子をみようと配信をみたら、たまたまブログピックアップコーナーで自分の予選ブログが取り上げられていておりました。

ホントにピンポイントでそこしか見てないんですが、色々褒められていたのをライブで見てしまいまして、ちょっとムズムズしておりました。取り上げていただきどうもありがとうございました。

まるでずっと配信観てたかのようにリアルタイムにTwitterで反応していますがそんなことはないんですよ、別に余裕だったとかそういうのは全然ないんです…。単にたまたま14:15に全体ベストスコアが出てしまっただけなのです(キリッ)。

14:20〜16:00 手分けして重めの改造に手をつけ始める

time score
15:30 調子に乗ってtotalScoreもsingleflightする (acidlemon) #16 89247
15:40 slowlog off / performance schema off / nginx keepalive 512 (fujiwara) 90726
15:57 slowlogオンとオフでどのぐらいスコア差が先に確認しておく、7%下がるらしい (fujiwara) 84926

ここらへんまでで、pt-query-digestを見る限り効き目があってサクッと出来そうな改造はだいぶ減ってきたということで、重めの改造に手をつけ始めます。13時過ぎからまこぴーさんにGetAnnoucementListらへんをやってくれ! とお願いしました。私は引き続きGetGradesのTotal Scoreのやつです。

ちなみに14時過ぎの時点で、Announcementに関するクエリの量が上に来ていました。

Rank Query ID                     Response time  Calls  R/Call V/M   Ite
==== ============================ ============== ====== ====== ===== ===
   1 0xFFFCA4D67EA0A788813031B... 253.4835 72.7%  46967 0.0054  0.00 COMMIT
   2 0x2BC75A9C3EB65F1EC570DFB...  17.3665  5.0%  12574 0.0014  0.00 SELECT announcements courses registrations unread_announcements
   3 0xA9A13C7DE4DE6522B8635F3...  11.1154  3.2%   8762 0.0013  0.00 SELECT users registrations courses classes submissions

Rank2のクエリは GetAnnouncementList の長いクエリです。一見6行しかないのでとてもかわいく見えますが、よく見ると後ろのほうで query += で4行くらい追加している上に、追加してるのがORDER BYだったりLIMIT OFFSETだったりして完全に裏の顔(?)みたいになっています。

GetGradesのtotalScoreをsingleflightにする

totalScoreはcourseごとに学生全員の点数の和を出すという、これまた統計クエリでした。GPAよりは1クエリの重さは軽いのですが、ベンチが回れば回るほど科目(course)の数がふえるので、totalScoreのループ回数が激しくなる…ということでなんとかしないといけません。

ここは正攻法でいくとsubmissionsにcourse_idを入れてJOINを外すとかそういう手になるのですが、それにしたって認証付きエンドポイントの中の統計クエリという時点でなんらかの同時実行制御を入れなければ話にならないだろう、と判断してsingleflightを入れました#16

totalScoreはGPAと違い、書き込んだ直後に即時反映されていることを検証する処理がベンチマークに入っていたので、キャッシュできませんでした。PRではキャッシュ生存時間が100ms以上みたいなコードになっていますが、クエリにかかる時間が100ms以上あるので実質キャッシュとしては機能しておらず、単に同時実行制御のみになっています。200ms以上のキャッシュをすると最初のチェックで叩き落とされることは確認済みです。

このPRのこだわりポイントとしては、学生のregisteredCoursesを列挙するところにちゃんと ORDER BY course_id を入れて明示的にコースIDの昇順になるようにしたところです。実際ORDER BY無い時にどんな順で帰ってきてたのかはわからないですが、例えばregistration順だったりしてregistrationがその時存在する科目にID順ではないランダムな順に受講登録していればcourse_id順にはならなそうだなと。そこを、course_id順に並べておくことでsingleflightの吸着効率を高めるみたいなのを狙っています。

ちなみに! これ終わったあとに気付いたんですが、courseのstatusがclosedになっていればそれ以上そのcourseにはsubmissionが来ないはずなので、その条件をチェックして無限キャッシュできたはずなんですよね。

60秒の負荷走行中のDBのCPU負荷傾向として最初160%くらいでスタートしてtotalScoreを計算するcoursesが増える後半になると200%まで上がるみたいなのがあって、終わった科目のtotalScoreのキャッシュをやっとけばその後半のCPU負荷の高まりを抑えることができたはずなので、そこまでいければDBの負荷よりwebappの負荷勝負になってきてた感じでした。

16:00〜16:55 まこぴーブランチ炸裂

slowlogオフで9万出ることを確認した後、またslowlogオンでしばらくチューニング作業。

time score
16:15 course.statusをオンメモリキャッシュ (fujiwara) #18 85942
16:30 announcements関連のエンドポイント3つをゴリッと改修 (macopy) #17 85901
16:40 ためしにFKやめてみる (fujiwara) #19 86153
16:50 GetGradesの中にあるclassごとのループクエリをなくす (acidlemon) #20 93729
Annoucement周りのテーブルとクエリを変更 (macopy)

GetAnnouncementList はスコアに直結するエンドポイントなので、GetGradesに比べると作業の重要度が高いです。ということで、3時間半くらいかけてAnnouncement関連のエンドポイント3つに手を入れてなるべくJOINを外してクエリの負荷を下げてもらいました#17

このPRはデバッグに小一時間くらいかかり、その間ずっとベンチは0点だったくらいでして、「ゴリッと書き換えてますよ」とまこぴーが言うとおり中身がモリモリなのですが、要約するとこんな感じです。

  • AddAnnouncement()
    • announcementsを取ってくるときに科目名(courses.course_name)を取るためにJOINしてるのを避けるために、announcementsテーブルにcourse_nameを追加
  • GetAnnouncementList()
    1. 学生の registrationsに基づいて取得が必要なannouncementのIDを別のクエリで求めてWHERE INannouncementsを取り出す
      • このとき、unreadはまだ考慮していない
    2. 学生のunread_announcementsの未読announcement IDを取り出す
    3. 1と2をwebapp側で突き合わせて必要なunreadなannouncementのリストを作って返す
  • GetAnnouncementDetail()
    • JOINが2個入っているクエリを以下の2つでJOIN不要にする
    • course_nameannoucementsに入れた
    • unreadかどうかのフラグは先に UPDATE unread_announcements SET is_deleted = true を実行してRowsAffectedが1か0をみれば分かるので、JOINするのをやめる
    • 地味にこの関数はトランザクションをしないようにしている

最後のunreadのフラグをUPDATEの結果みて設定するのはまこぴーさんマジで賢いな〜と思いました。

まこぴーさんは、このあとunreadのRedis化に向かって突進していきました。

ためしにFKはずしてみる (fujiwara) #19

「さすがに意味も無く貼ってるってことはないだろうし、全部外したら制約側でバリデーションしてたINSERTとかが失敗するんじゃないですか〜?」と思ってたんですが、普通に通ってしまった。そんなことあるんかと思いましたが、本選問題解説で「趣味でFK」って言ってたのであとでなるほど〜 となりました。この業界だと貼る人あんまりみかけないですが、ぼくもFKはるの好きです。

GetGrades のループクエリを外す #20

これ結構効いてたみたいですね。GetGradesがタイムアウトになるならないで学生が10秒サボるかどうかが決まるので、すこしでもサボる可能性下げる手を打っといたのはよかったなぁというところでした。あとはこの時点でpt-query-digestみてもループで回るSELECT submissions2つが上位5つ以内に両方入ってたのでやるべきやつでした。

16:55 圧を強める

time score
16:55 SetMaxOpenConns(20)にする 97012
16:59 slowlogオフ、SetMaxOpenConns(40)にする 111754
17:00 スコアボード凍結

GetGradesのループクエリを削った時点でDBマシンのCPU idleが出始めたので、何とかしてもうちょっとベンチマーク側から高い負荷をかけて欲しかったのですが、とはいえGetGradesはsingleflightしててもやっぱりラッシュがくるとタイムアウトしてしまって学生が10秒サボってしまう…。

ということで、あといじってないパラメータといえばSetMaxOpenConns()のコネクション数だったので、これを初期値の10から20にしてみたところ93000→97000と伸びました。そこで「もっとDBに負荷(圧)かけてよさそうですね」となり、各種分析用のログを全部外してさらに40にして回したところ11万を超えるスコアが出て、結果的にスコアボードにも圧がかかりました。組長も優勝者インタビューで言ってましたが、良い感じの見せ場が作れていたのではないでしょうか。

このあと、17:05くらいまでSetMaxOpenConns(60)とかも試したりしましたが、そんなにスコアは伸びなかったのでひとまず現時点であれば40で十分ということになりました。

17:00〜18:00 さらにラストスパート

time score
17:10 unread_announcements のINDEX減らす (acidlemon) #18 121153
17:20 unread_announcements をRedisに逃がす (macopy) #23, 初期化修正: #24 120215
17:30 zipファイルをX-Accel-Redirectで配る (fujiwara) #22 126520
17:40 redis-serverを3台目にする (fujiwara) 130650
17:45 再起動試験 132092
unread_announcementsのINDEX減らす

予選に引き続き今回も書き込みヘビーだったわけですが、INSERTとかUPDATEのうちどうしてもBulk Insertできないやつとして、1件だけ unread_announcements を更新する GetAnnouncementDetail というやつがありました。

レギュレーション読む限り、ベンチマークで実装されてたユーザのシナリオは「おしらせリストをみる(1点)」→「おしらせ詳細をよむ」→「レポートを提出する(3点)」とかなので、お知らせ詳細を読むGetAnnouncementDetailのスループット上げるのは大事、ということで unread_announcementsテーブルの書き込み負荷を下げることを検討しました。

で、まこぴーさんにはRedisに逃がすのをやってもらいつつ、この時間からのRedisはさすがにうまく行かない確率の方が高いだろう、ということで次善の策として私は PRIMARY KEY (announcement_id, user_id) になっているのを入れ替えて PRIMARY KEY (user_id, announcement_id) にして(FK外したときに追加した)INDEX (user_id) を消す、というのをやりました。

このあとまこぴーさんのRedisブランチが無事完成したんですが、この次善の策が入ったブランチとさほどパフォーマンスが変わらなかったのは、よかったのか悪かったのか… というところです。この時点で実は1台目のwebapp+nginxと2台目のmysqlがどちらもほぼ100%CPUを使い切っている状態になっていて、これ以上はwebapp側を2台にするのをやらないと厳しいというのが見えてはじめていました。あと、Redis入れた時点でSetMaxOpenConns(60)を試してみてもよかったかもしれない。

X-Accel-Redirect でzipファイルを返す、redis-serverを3台目へ (fujiwara)

ということで、1台目のwebapp側の負荷をちょっとでも減らしましょうということで、ファイル返すのをgoからnginxに変えたり、1台目にあったredis-serverを全く使ってなかった3台目に逃がしたりして作業終了。

17:50の時点で再起動試験後に3回ベンチマークして全部Passしたので、もうやることないねということでそのまま作業終了しました。

まとめ

ということで長々と書いてきましたが、やったこととしてはこんな感じです。最終的にはギリギリDBよりもwebapp側のほうがCPU詰まり気味の状態まできてたので、やれることは全部やれたかな〜というところでした。

totalScoreのsingleflightのところにちょっと書きましたが、fujiwara組の最終形の状態からさらに何か延ばすとしたら、courseがcloseされてたら無限キャッシュする、が次の手になるのですが、CPU負荷の割合からすると次はwebapp側を2台にしないとスコアが伸びなくなるので、そこまで構成変えてスコア安定させるのは時間が足りなかったかな〜というところでした(nginxのlocationを組長にたくさん書いてもらう必要があった)。

course closeの無限キャッシュはだいぶ効くとおもうので、結果発表でもし13万点オーバーのチームが出てきて負けちゃったら、たぶんそれやられたとかなんだろうな〜と土曜寝る前に考えながら寝ました(ただ、totalScoreのsingleflightやらずに無限キャッシュだけだとThundering herdに耐えられなくてダメだったと思います)。

あとは、なんか聞かれそうなことを書いときます!

Q. 課題の提出のPOST SubmitAssignment() は手をつけてないんですか?

A. userCodeをセッションに入れる#10getUserInfo()の戻り値が増えた以外はなにもいじってませんでした。なぜいじらなかったというと、17時半くらいまではDBのCPUが詰まっていたので、という感じです。pprofとかをみるとなんかwebapp側のボトルネックっぽかったんでしょうかね? 今回もpprof見れてなかったのでその辺わかっておりません…。

ただ、トランザクションの内側にWriteFileがあるのはINSERT INTO submissionsをネクストキーロックしててスループット伸びないみたいなのはありそうなので、外に出したほうがよかったかも。

Q. GetGradesってGETで集計じゃなくてPOSTで集計結果作っておくとかは考えなかったんですか?

脳がsingleflightしてたので(そしてそれでベンチ通ってたので)考えなかったですねぇ。Write Heavyな感じなので、POST起点でキャッシュ的なものを作ってもすぐにinvalidationが必要になってキャッシュ生存時間短そうというのもありました。まぁでもDBにテーブル作ってやらせればよかったのかなぁ。

今回のGetGradesは、どんだけ高速にしても1点のスコアにもならないお邪魔エンドポイントなので、基本的に考えていたこととしては「DBで利用できるCPU時間をいかにGetGradesに使わせないか」ってことでした。結果としてThundering HerdなクエリラッシュをsingleflightすることでGetGradesのためにDBのCPU使ってる割合をさげてやれば、今回はベンチの並列数が相当高いので残りのworkerが GetAnnouncementList()GetAnnouncementDetail()SubmitAssignment() ループを回してくれるだろう、と思っておりました。

今回は並列数が自動で調整されるというよりは、ドカッと並列にぶんなげてくるけどサーバがつらそうならタイムアウト応答にあわせてSleepするみたいな仕組みだったので、この戦略が上手くはまったのだと思います。


最後に、ISUCON11運営のみなさま、今年もいい問題をありがとうございました! 優勝できたのでチョーキモチイイーのはもちろんそうなのですが、それを差し引いてもベンチマークも快適だし問題も(読み物はちょっと長かったけど)スコアリングが明確になっていて、なおかつスコアがばらつきにくくする工夫が入ってることを感じられて良い問題だな〜と思いました。

わたしはISUCON2の年に北海道から関東に出てきてSIerからWeb業界に転職してきた人間なので、ちょうど今年が10年目。節目の年にISUCON優勝できてとても嬉しいです。ちなみに、全然覚えてなかったんですけどISUCON2に出たときのブログみたら、当時も新卒だったまこぴーさん(+けんじおじさん)と組んでISUCONに出てたみたいですよ! 10年経って優勝できるなんて感慨深いですね!

それではまた来年ISUCONがあるようであれば、なんらかの形でお会いしましょう〜

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_uuidtimestamp にINDEXを張ってくれてた。この時点でもう11時くらいだったんだけど、リーダーボードはでは1万点こえたチームどころか2万3万とみんなスコアを伸ばしてたのでちょっと出遅れ感あったけど我々もこのINDEX張るだけで1万点超えたので「これはもしかして最終的に50万とか100万点とかいくやつか…」と戦慄していた。

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

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 /initializeUPDATE 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_countWHERE 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_uuidtimestamp だけが必要なクエリでもIndex Condition Pushdown で後者のINDEXは一応効きます。ということで、ここまでWrite HeavyであればINDEXの更新負荷を下げるべきという判断をして、前者のINDEXを消しましょう! という話をしました。

で、よくよくみていくと

  • isu_conditionのPKEYである id (auto_increment)はユーザに返してないので別になくてもいい
  • PKEY自体をidじゃなくて jia_isu_uuidtimestamp の複合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な問題が好きなので、個人的には相性の良い問題だったな〜と思いました。

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

うされもん @acidlemonについて

|'-')/ acidlemonです。鎌倉市在住で、鎌倉で働く普通のITエンジニアです。

30年弱住んだ北海道を離れ、鎌倉でまったりぽわぽわしています。

外部サイト情報

  • twitter
  • github
  • facebook
  • instagram
  • work on kayac