2022/08/01

ISUCON12 予選の小ネタ

Twitterに書くには文字数が足りないけど公式サイトのブログに書くほどでもない小ネタを供養する記事です。うろ覚えなところもあるのでオフィシャルな記事よりはだいぶ信頼性低めです。

中身が完全に切り替わるフロントエンドSPA実装

今回の問題って完全にバックエンドはAPIしか提供してなくて、参加者がどんなサービスか知るために提供していたフロントエンドはSPAになってて最初からnginxで配信していました。例年だと静的ファイルはバックエンドが頑張って配信するみたいになってることが多いですが、そもそもベンチマーカーはHTML/CSS/JSには最初の整合性チェックフェーズでしかアクセスしないので、そこに力入れてもらう必要ないから最初からnginxで適切な状態にしてしまおう! という感じで出しました。

SPAなフロントエンドが提供されたことは過去にもありまして、大体Reactが使われていました。今年は私が実装するということで、私が一番手慣れてるVue.js(v3)でやりました。私は普段からNuxt使わずに筋力でルーティング書いちゃうことが多いので、Nuxtはつかってません。

あと、今回の問題はマルチテナントSaaSということで admin.t.isucon.dev はSaaS管理者画面、それ以外のサブドメインはテナント用の画面をだす必要があって、Vueのエントリポイントである main.ts でサブドメイン見てロードするAppのVueコンポーネントとルーター切り分けるという、だいぶパワーのある実装になっています。

if (host.split('.')[0] === 'admin') {
  createApp(AdminApp).use(adminRouter).mount("#app")
} else {
  createApp(TenantApp).use(tenantRouter).mount("#app")
}

importじゃなくてrequireで動的ロードしろよ説ありますが、まぁこれ動作確認用で提供してるだけなのでパフォーマンスとかはそこまで気にしなくていいから、エイヤーでimportしてしまいました。

「の」 が回るローディング

これは小ネタオブ小ネタですが、ISUCONのお題アプリって最初はレスポンス返ってくるまでめちゃ遅いので、いくつかのエンドポイントを呼ぶときはLoadingっぽいのを伝えるぐるぐるを入れる必要があります。

実務だとBootstrap Iconsでなんかカワイイローディングアイコンを入れてCSSアニメーションで回すことが多いのですが、今回はフロントエンドの依存モジュール増やしたくない(あまりそこに時間をかけたくない)ということで、まんまるなひらがなを1文字くるくる回すという感じでグルグルを実装しました。

SaaS管理者の画面だとひらがなの「の」が回って、テナント側の画面だとひらがなの「め」が回るようになっています。これはあとでちゃんとしたアイコンに差し替えようと思ってたのですが、出題チーム内でも「の」が回るの新しい、カワイイ、などと好評だったのでそのまま残しました。

各言語移植に存在する実装差分

最初の参考実装はGoで書いていたのですが、他の言語に移植するときにいろいろと「そのまま移植できない!」が出てきてその言語用にちょっとずつ実装方法が異なっている部分があって、それを簡単にご紹介します。

Node.js: flockはブロッキングモードを使わない

出題チームが各言語の移植者にお願いしていたこととして、SQLiteの書き込み排他制御には必ずflock(に相当するsyscall)を呼ぶというのがあります。

flockを呼ぶ際、Goではブロッキングモードで呼び出して、ロックが獲得できるまでずっと待つという仕様になっており、ほとんどの言語はブロッキングモードで実装していたのですが、Node.jsだけはシングルプロセスシングルスレッドで動く以上ブロッキングで待ってしまうと全部のリクエスト処理が止まってしまってベンチマークが完走しません。

ということで、Node.jsはflockをノンブロッキングモードで使うようにして、EAGAIN のときは10msごとにリトライして取れるまで無限にflock取るのを試す、といった実装になっています。

Java: flockをつかわない

Javaはもっと大変でした。最初はnioパッケージにあるFileChannelを利用してFileLockを取る実装を試してもらっていました。しかしJavadocにも書いてあるとおり別プロセスとの排他制御にはこれが使えるのですがJVM内のマルチスレッドにおける排他制御にはこれが使えません。実際にFileLockで実装したものはベンチが安定せず、Javaだけflockを使うのを諦めました。

代わりにどうしたかというと、普通のJavaのお作法通り、Lockオブジェクトを作ってsynchronizedで保護する、という感じでやっています。

ちなみに「JNIでsyscallでflock(1)呼ぶ」とか「外部プロセス起動でflock(2)呼ぶ」とか「古のテクニックとしてmkdirがアトミックになるのを利用してロックをとるという20世紀の技があるんですけど…」のアイディアも出ましたが、まぁそこまではしなくていいんじゃない、ということでsynchronizedに落ち着きました。

Rust: sqliteのtracerがちょっと違う

Rustではsqlxというcrate(であってるのかな)を使っていたのですが、これはMySQLとSQLiteを両方サポートしていて、これを使ってクエリログを取るときに取れたデータにデータベースエンジンなどを区別する方法がない、ということでGoの参考実装通りの移植ができないということがわかりました。

出題チームで検討した結果、環境変数の名前をちょっと変えつつ、MySQLとSQLite両方でることは許容する、ログの形式も他の言語と揃えられないのでデフォルト設定の状態で出す、という形で落ち着きました。

ちなみにPerlのDBIx::Tracerも似たような感じでDBIのexecuteなどをフックしてコールバックを呼ぶみたいな仕組みのためMySQLとSQLiteが混ざるのですが、こちらはコールバックに$dbhが来るのでDriverの名前を調べてSQLiteのときだけ出す、が出来ています。

初期実装に含まれる、謎のNOTEコメント

テナント追加APIに、謎のコメントが残されています。

	// NOTE: 先にadminDBに書き込まれることでこのAPIの処理中に
	//       /api/admin/tenants/billingにアクセスされるとエラーになりそう
	//       ロックなどで対処したほうが良さそう

これは読んで字のごとくで、最初はベンチマークが全然回らないので顕在化しないんですが、APIの回転が良くなってくると、AdminのBilling APIのアクセスがたくさんくるようになりこれで引っかかるようになるというやつがありました。

どういうことかというと、Adminのテナント追加APIでは、テナント情報をMySQLにINSERTして、その後SQLiteのDBファイルを作るという順番で処理していました。Admin Billingを叩くワーカーはテナント追加APIとは別のワーカーとして動いており、並列にアクセスが来る可能性があるため「テナント追加APIでMySQLにINSERTした直後〜SQLiteのDBファイルを作るまでの間」というごくわずかな時間の間にAdmin Billingが叩かれるとSQLiteのファイルを開けなくて500エラーになる、ということです。

…ということで高速化すると謎の500エラーに悩まされる…という状態になることが分かったので、ひとまずコメントを入れてお知らせしていた、という話でした。どうすればよかったかというと、簡単なのはINSERTをトランザクションでちゃんと囲んでSQLiteのDBファイルを作ってからMySQLにコミットするとかですかね。もう1個の方法としては予選の解説に書いた「そもそもDBファイルを作るタイミングを変更する」という手もありました。

…さて、いかがでしたでしょうか。小ネタでした。

2021/09/21

ISUCON11 で優勝しました

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

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

あわせて読みたい

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

• ISUCON11で優勝しました by 組長

はじまるまで

基本的には予選とおなじ準備をすれば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モデル番号の話は本選おわった後の雑談で軽い気持ちで「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 INでannouncementsを取り出す
     • このとき、unreadはまだ考慮していない
  2. 学生のunread_announcementsの未読announcement IDを取り出す
  3. 1と2をwebapp側で突き合わせて必要なunreadなannouncementのリストを作って返す
• GetAnnouncementDetail()
  • JOINが2個入っているクエリを以下の2つでJOIN不要にする
  • course_nameをannoucementsに入れた
  • 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をセッションに入れる#10でgetUserInfo()の戻り値が増えた以外はなにもいじってませんでした。なぜいじらなかったというと、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があるようであれば、なんらかの形でお会いしましょう〜