@acidlemonについて
|'-')/ acidlemonです。鎌倉市在住で、鎌倉で働く普通のITエンジニアです。
30年弱住んだ北海道を離れ、鎌倉でまったりぽわぽわしています。
シンプルで力強いタイトルをつけてしまいましたが、2021/09/18に行われたISUCON11の本選にfujiwara組で出場しまして、優勝することができました。メンバーの話とかは予選ブログのほうに書いてますので、そちらを参照ということで、早速やっていった内容を書いていきます。
今回は全然スコアが上がらなくて、とにかく細かいやつでもいいから施策を入れまくって積み上げるみたいな感じでやったので、やったことが大量にあって読むのにとても時間のかかるブログになっております。ちゃんと読もうとすると15〜30分くらいかかるとおもうので、お時間のあるときにゆっくりお読みください。
チームメンバーのブログもあります。
基本的には予選とおなじ準備をすればOKというところなのですが、久々の本選出場なのでせっかくなので優勝したいなぁ…ということで、今回はちょっと前日に本気だしまして、過去のブログなどを読みあさって「れもんが本番中にいつも忘れる細かい改善チェックポイントリスト」(通称: ISUCONとらのまき)をA4で1枚にバババッと書き出しておきました。よくあるのが、せっかく虎の巻つくったのに結局本番中に見ないみたいなのがあるのですが、今回はちゃんと開始3時間後くらいに存在を思い出したので役に立ってた感じです。
なにが書いてあったかというと、「認証のある静的ファイルはX-Accel-Redirect!」とか「JSON生成遅いのでgoccy/go-jsonを使う!」とか「Thundering Herd対策にsingleflight!」とか「PKEYが文字列(特にUUID)は遅いよ」とかそういうのです。
予選の時はまずレギュレーションを読んでいたのですが、本戦はわりと最終的にインフラ勝負になりがちなので、レギュレーション読みをまこぴーさんに任せ、インフラセットアップは組長に任せて自分はまずインスタンスの詳細をつぶさに調べるところから始めました。
で、よくみるとCPUのモデル番号が違うことがわかり、ひとまず複数台構成にするときにはDBは2台目にしましょうかねという話をしていました。
CPUモデル番号の話は本選おわった後の雑談で軽い気持ちで「c5.largeのCPUが2種ありましたよね〜」って言ったら運営の人たちがちょっと慌てていたので「あれ、余計なこと言ったかな…」みたいになりましたが、性能差的にはほぼ誤差レベルというのと、最終スコア計測時にそもそもEC2をStopするからCPUモデルは再び起動したときには変わってるという話(たしかに〜)になって特段の対応はナシとなっていました。
そういうのClarほしい! というのも後から言われるとたしかに〜と思ったんですけど、ISUCON10の本選は3台ともスペック異なったりしててそれについてのClarで「見えてるとおりです」みたいな回答だったとおもうので、まぁ今回もそういうものかな〜と思って特に何もしませんでした…。
初期ベンチのスコアは確認していて
5%くらい違うけど、まぁ誤差といえば誤差か〜。あとはAWSのEC2なので、EBSのFirst Touch Penaltyがあるのを思い出して、11時台に dd if=/dev/nvme0n1p1 of=/dev/null bs=1M
して、ひとまずそういうやつでスコアばらつく可能性があるというのをあらかじめ潰すというのはやっています(3台目だけは全然暖まってなかった)。
ということで、初期スコアは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 のをやっています。
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 |
すごい! スコア伸びてる! けど自分の名前が出てこないので何もやってないようにみえる! おにぎりツイートしてたし。通常の業務においても私はおちゃめ担当なので、まぁそんな感じです。
おにぎりデプロイしまーす!! 🍙 #isucon
— Masatoshi Kawazoe (@acidlemon) September 18, 2021
長大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万点ボーダーの意味はそういうことか〜〜、よくできているな〜〜〜」となりました。
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時半前後のプルリクマージ渋滞がヤバいことになってました。
これは結構お決まりの、「ISUCONだとユーザ情報とるためにSELECTを1回するのはもったいない」というやつで、今回はセッションがクライアントクッキーだったのでクッキーセッションにそのままuserCodeも入れちゃえという感じになっております。
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)。
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 ということで、まぁはっきりいってチリツモレベルという感じではありますが、今回は本当にスコアの上がり方が渋いのでチリツモでもいいから思いついて作業コストの低いやつ全部やっとけ! みたいなノリでやりました。
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本選からライブ配信が始まり、昨年は並行チームとして出てたのでライブ配信を生で見るの楽しいな〜と思いながらリラックスして解いていました。しかしさすがに今年は気が散るのでライブ配信聞きながらやるのは無理だ…と配信切ってたんですが、全体ベストスコアでたタイミングで魔が差してしまい運営の様子をみようと配信をみたら、たまたまブログピックアップコーナーで自分の予選ブログが取り上げられていておりました。
ISUCON11 オンライン本選ライブ中継、ブログピックアップ🗒 こちら3つのブログに個人スポンサーグッズをプレゼントさせていただきます🎉 ありがとうございました!#isucon https://t.co/kymLn573JK pic.twitter.com/B9wJnvIkZ3
— ISUCON公式 (@isucon_official) September 18, 2021
ホントにピンポイントでそこしか見てないんですが、色々褒められていたのをライブで見てしまいまして、ちょっとムズムズしておりました。取り上げていただきどうもありがとうございました。
めっちゃ褒められてる… #isucon
— Masatoshi Kawazoe (@acidlemon) September 18, 2021
まるでずっと配信観てたかのようにリアルタイムにTwitterで反応していますがそんなことはないんですよ、別に余裕だったとかそういうのは全然ないんです…。単にたまたま14:15に全体ベストスコアが出てしまっただけなのです(キリッ)。
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の負荷勝負になってきてた感じでした。
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 |
GetAnnouncementList
はスコアに直結するエンドポイントなので、GetGrades
に比べると作業の重要度が高いです。ということで、3時間半くらいかけてAnnouncement関連のエンドポイント3つに手を入れてなるべくJOINを外してクエリの負荷を下げてもらいました#17。
このPRはデバッグに小一時間くらいかかり、その間ずっとベンチは0点だったくらいでして、「ゴリッと書き換えてますよ」とまこぴーが言うとおり中身がモリモリなのですが、要約するとこんな感じです。
AddAnnouncement()
announcements
を取ってくるときに科目名(courses.course_name
)を取るためにJOINしてるのを避けるために、announcements
テーブルにcourse_name
を追加GetAnnouncementList()
registrations
に基づいて取得が必要なannouncementのIDを別のクエリで求めてWHERE IN
でannouncements
を取り出す
unread_announcements
の未読announcement IDを取り出すGetAnnouncementDetail()
course_name
をannoucements
に入れたUPDATE unread_announcements SET is_deleted = true
を実行してRowsAffectedが1か0をみれば分かるので、JOINするのをやめる最後のunreadのフラグをUPDATEの結果みて設定するのはまこぴーさんマジで賢いな〜と思いました。
未読既読のマークつけると同時に未読だったかを見てる箇所で、どうせ必ずUPDATEするんだから、状態を直前にSELECTせずにUPDATEのRowAffected見たのが必殺技感あったけど、後で自分でRedisに書き換えて使わなくなった #isucon
— ホームページを作るのが得意 (@mackee_w) September 18, 2021
まこぴーさんは、このあとunreadのRedis化に向かって突進していきました。
「さすがに意味も無く貼ってるってことはないだろうし、全部外したら制約側でバリデーションしてたINSERTとかが失敗するんじゃないですか〜?」と思ってたんですが、普通に通ってしまった。そんなことあるんかと思いましたが、本選問題解説で「趣味でFK」って言ってたのであとでなるほど〜 となりました。この業界だと貼る人あんまりみかけないですが、ぼくもFKはるの好きです。
GetGrades
のループクエリを外す #20これ結構効いてたみたいですね。GetGrades
がタイムアウトになるならないで学生が10秒サボるかどうかが決まるので、すこしでもサボる可能性下げる手を打っといたのはよかったなぁというところでした。あとはこの時点でpt-query-digestみてもループで回るSELECT submissions
2つが上位5つ以内に両方入ってたのでやるべきやつでした。
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万を超えるスコアが出て、結果的にスコアボードにも圧がかかりました。組長も優勝者インタビューで言ってましたが、良い感じの見せ場が作れていたのではないでしょうか。
スコアボード凍結前に圧をかけている #isucon
— Masatoshi Kawazoe (@acidlemon) September 18, 2021
このあと、17:05くらいまでSetMaxOpenConns(60)
とかも試したりしましたが、そんなにスコアは伸びなかったのでひとまず現時点であれば40で十分ということになりました。
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に耐えられなくてダメだったと思います)。
あとは、なんか聞かれそうなことを書いときます!
SubmitAssignment()
は手をつけてないんですか?A. userCodeをセッションに入れる#10でgetUserInfo()
の戻り値が増えた以外はなにもいじってませんでした。なぜいじらなかったというと、17時半くらいまではDBのCPUが詰まっていたので、という感じです。pprofとかをみるとなんかwebapp側のボトルネックっぽかったんでしょうかね? 今回もpprof見れてなかったのでその辺わかっておりません…。
ただ、トランザクションの内側にWriteFileがあるのはINSERT INTO submissions
をネクストキーロックしててスループット伸びないみたいなのはありそうなので、外に出したほうがよかったかも。
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があるようであれば、なんらかの形でお会いしましょう〜
こんにちは! 本日はほとんど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枚ってできないんですかね〜。
ISUCON準備は完了したものの、会社MacはM1が出る直前のMacBook Pro (Intel, 2020)なのでトリプルディスプレイいけるぜ! と思ってたんだけど、4Kディスプレイを2枚つかうと3枚目にフルHDのディスプレイをつなげても出力がないということが分かって(´・ω・`)となってる
— Masatoshi Kawazoe (@acidlemon) August 21, 2021
そんなことを思いつつ、いつもの謎のオープニングを眺めて「あーIoT系か〜」などと言いながら10時を待ちました。
最初にレギュレーションをよんで、スコア伸ばすポイントをざっくり把握。レギュレーションとアプリケーションマニュアル読んだ感想としては…
POST /api/activate
に渡すターゲットホストをバラしてコントロールすることでリクエストのロードバランスができそう
という感じです。
実際にやったことは既にマージされたPRベースで組長のブログに書いてあるのでざっくりとししたやつはそちらを読む、でよいのですが、解法上考えたこととかそういうのにフォーカスして書いていきます。
レギュレーションとアプリケーションマニュアルが難解すぎて2回目読み始めてる間にまこぴーが jia_isu_uuid
と timestamp
にINDEXを張ってくれてた。この時点でもう11時くらいだったんだけど、リーダーボードはでは1万点こえたチームどころか2万3万とみんなスコアを伸ばしてたのでちょっと出遅れ感あったけど我々もこのINDEX張るだけで1万点超えたので「これはもしかして最終的に50万とか100万点とかいくやつか…」と戦慄していた。
INDEXはこの他にも isu
の character
を引くヤツとかも追加しています。
pt-query-digest
を見た組長が PREPARE
してますね、と言ってたのでサクッとオプション追加。毎年やるやつ。ちなみにれもんは mysqldumpslow
派です。いや、pt-query-digest
も使えるんだけど、DBの負荷が強いときはクエリごとのQueryTimeの合計しか見ないので、そういう意味では mysqldumpslow
を流し読みするほうが慣れておりまして…
使用フレームワークは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を捌かないといけないことがわかり、震撼していました…。
グラフ描く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クエリをどうにかするべく以下のような手も打ったんですが、マージせずにおわりました。
trendどうにかしたかった話は一番最後にもう少し詳しく書いています。
POST /api/condition/${uuid}
はBulkInsertするIoTデバイスからステータスを束でもらうAPI。だいたい1回のリクエストに5〜15個くらい入ってそうなかんじで、INSERTがループクエリになってたのでこれをBulk Insertするように変更。順当にスコアがあがりましたが、思ったほどは上がらず、InsertよりもSelectをどうにかせねばなぁという感じ。
1台だと早々にもうスコアあがらないかもな〜となったのと、やっぱりDBがヘビーなのが見えてきたので早速分割です。
POST /api/isu
の画像保存先)外向きには両方nginxを立てています。基本は02と03に均等にリバースプロキシしますが、画像の外部化の処理だけは02が専属で捌くのと、03は POST /api/condition/${uuid}
のラッシュを受ける役という分担になっています。いずれにせよ01のmariadbがCPUを200%使っていてここがボトルネックになり、最後まで02と03のCPUはちょっと余っている状態でした。
ここらへんまででだいたい13時。ここからはDBに入ってるデータをカラム増やしてどうにかしたりしていきます。
isuのテーブルにimageが入っていて、これを引くクエリが結構重いので、初期データから画像を抜き出し & POSTされたものは02のローカルファイルで保存。最初nginxでpublicに見えるようにしてそのまま返していましたが、すると401になるはず! っていうエラーでFailしたのでwebappがStaticFileを返すようにしました。
なるほどISUの画像はプライバシー(?)的な問題で他の人には見せてはいけないのですね……。
アプリの修正でimageをINSERTすることは無くなりましたが、初期データには残ったままなので POST /initialize
で UPDATE isu SET image = NULL
なクエリも流して SELECT *
しているところの転送量も削っています。
この時点で一番きつかったのは GET /api/condition/${uuid}
を捌くところで、ISU単体のコンディション履歴をwarningとかcriticalのseverityでフィルタしながら最大20件返す処理でした。この処理が、履歴を20件返すためにひとまずISUのconditionを全件取ってるのでrow readsがヤバいのなんのということで、ここに手をつけます。
ちゃんとソースを読んだら、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のnameを引くクエリがだいぶ回数多くなってきたため、userをオンメモリで返せるようにしました。
POST /api/condition/${uuid}
で確率的に何もしてなかったのをやめる元のソースコードにコメントで書かれていた TODO: 一定割合リクエストを落としてしのぐようにしたが、本来は全量さばけるようにすべき
というやつ、一通り高速化したしそろそろ dropProbability
を調整してみるか〜ということで調整してみたところ、dropを0%にしたときが最高スコアになったため早速削除。まこぴーさんがコメントに日時を入れていて、この時点で15時半前です。
スコアの説明と、 dropProbability
の挙動をあわせて確認するとわかるのですが、
という感じの仕様になっています。で、メトリクスの記録を90%カットしていると、確率的にいえば24時間分の24個のタイムレンジについて空っぽの時間が発生する確率が8割以上はありそうです。「1時間の間に1個のメトリクスがない」というのはグラフのスコアリング評価としてはWorstということになります。
戦略としては「Worstでいいから大量にグラフのAPIを捌けるようにする」か「リクエストのドロップ率を下げていってちゃんとBadとかNormalとかで点数を稼ぐ」になるのですが、スコアの係数からするとNormalでもWorstの10倍のスコアになることを考えると、APIを10倍捌くよりはグラフスコア係数側で稼いだ方がよさそうです(というか題意にマッチしている)。
ひとまず、9割ドロップをやめたところスコアが5倍くらい(+400%くらい)に上がったので、ここで大きなブレイクスルーその1となりました。
上の方にも少し書きましたが、非ログインでみれる 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がディスクを圧迫していたり(後で分かった)でスコアが満足できる水準にならず、ポータル閉鎖されてて詳細を調べることができなかったためこのブランチも捨てました。ちょっと悔しい。
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を消しましょう! という話をしました。
で、よくよくみていくと
id
(auto_increment)はユーザに返してないので別になくてもいいjia_isu_uuid
と timestamp
の複合PKEYにしてよさそう(マニュアルに「コンディションの時刻情報は、既に送られたコンディションの時刻情報よりも常に先の時刻となる。」とかいてあるので、同じISUにtimestampが被る事は無さそう)ということがわかり、id
のauto_incrementを外しつつPKEYを複合PKEYに変更して、INDEXを1個削ったところスコアがまた60〜80%くらい伸びて最終的には70万点となりました。正直、そんなに伸びるのか〜と3人ともびっくりしていました。一番最後にブレイクスルーその2がくるとは。
そんなこんなで18時半過ぎ。さすがに70万点出てれば予選は通過してるだろ! と安心しつつ競技を終えました。
conditionのメトリクスを一切ドロップしない状態にすると60秒間に70〜80万行ほどのINSERTが走るのですが、1時間あたりに返すデータポイント数は21個あれば最高スコアです。1分おきくらいのペースでメトリクスがくると1時間に50データポイント以上INSERTされるので、ここをなんかいい感じにして21個くらいになるように、リクエストの中でINSERT量を調整するみたいなのはあるんじゃないかな〜と思いました。
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な問題が好きなので、個人的には相性の良い問題だったな〜と思いました。
それでは、本戦のブログでまたお会いしましょう〜