美瑛の青い池

ISUCON11 初出場でぎりぎり予選落ちした

ISUCON11の予選に参加して敗退してきたので来年に向けて施策と所感を時系列でメモしていきます。

チームメンバーはアラジン( @hiromi_fuk)とたくりんとん( @takurinton)。


時系列ログ


9:35 集合

チームメンバーでdiscord上に集合、その後みんなでオープニング配信を観てた。

IoT系のアプリケーションであることがわかったので、時系列データをあれこれする必要がありそう…とか考えてた。

同時にisuconでは定番の?起床試験失敗したチームをみて笑ってた記憶。

緊張はしてなかった。全員でがっつり準備したわけじゃなかったし、練習の気持ちでやろうとか話してたので。


10:00 競技開始

まず全員でマニュアルを読んだ。

  • /api/condition/:jia_isu_uuid の書き込みでタイムアウトになってもスコアに影響はない
  • 1秒以内に書き込みできてればよい

などの記述を見つけて、「これ絶対bulk insertしろってことでしょ」ってつぶやいたりしてた。

condition周りの仕様はざっと流してしまったので競技中はあまり頭に残ってなかった。

最終スコアは再起動後に実施する負荷走行で決まることはしっかり把握できていた。


10:20 環境構築

秘伝のタレをみながら環境構築をしていた。

アラジンにはgit管理を、たくりんとんにはdbの状況把握を任せ、自分はプロファイラ導入や各種confのsymlink化を進めた。

ここだけは事前に練習してあったので各々スムーズに作業できていた感覚。

この時点で一回目のベンチを回し、スコアは3239だった。


11:00 役割分担

チームメンバーにはアプリケーションを主に見てもらおうと思ってたので、n+1やキャッシュできそうなところがないかを探してもらった。

自分はというと秘伝のタレの作業が終わっていなかったので、雑談しつつ手を動かしていた。


11:30 謎のスコアアップ

ここでやっとアプリケーションのプロファイリングできる環境が整ったのでtopを叩きながらベンチを回したりしていた。

するとスコアが14490まで跳ね上がった。

なんか知らんけど。

今回のベンチマーカーはブレが大きいのかなとか思ってた記憶。

mysqlが一番cpuを使っていたのでとりあえずここに目をつけた。

チームメンバーにはn+1の実装を続けてもらいつつ、自分はmysql-slow-queryとalpの用意を始めた。


12:00 小休憩

雑談しながら各自昼休憩中を取ったりしていた。

お好み焼きを食べた。

お好み焼きってたこ焼きと違って肉が入ってるなーとか当たり前のことを再認識してた。どういうこと。

やっと手を止める時間ができたので、アプリケーションコードをのぞいていた。


12:30 alp

apiのエンドポイントをひと通り把握したので、alpの準備を進めた。

path paramがuuid形式になっているものが多かったので、正規表現でまとめた。

完全一致にしようと思ってもうまくいかず、割と時間を使ってしまった。

結局後方一致の形にしたらいい感じに結果をまとめることができた。

sudo cat /var/log/nginx/access_log.tsv | alp ltsv -m '/api/condition/[0-9a-f]{8}-[0-9a-f]{4}-[0-9a-f]{4}-[0-9a-f]{4}-[0-9a-f]{12}$,/api/isu/[0-9a-f]{8}-[0-9a-f]{4}-[0-9a-f]{4}-[0-9a-f]{4}-[0-9a-f]{12}$,/api/isu/[0-9a-f]{8}-[0-9a-f]{4}-[0-9a-f]{4}-[0-9a-f]{4}-[0-9a-f]{12}/icon$,/api/isu/[0-9a-f]{8}-[0-9a-f]{4}-[0-9a-f]{4}-[0-9a-f]{4}-[0-9a-f]{12}/graph$,/isu/[0-9a-f]{8}-[0-9a-f]{4}-[0-9a-f]{4}-[0-9a-f]{4}-[0-9a-f]{12}$,/isu/[0-9a-f]{8}-[0-9a-f]{4}-[0-9a-f]{4}-[0-9a-f]{4}-[0-9a-f]{12}/condition$,/isu/[0-9a-f]{8}-[0-9a-f]{4}-[0-9a-f]{4}-[0-9a-f]{4}-[0-9a-f]{12}/graph$' --sort sum -r --format md

やっとのことでエンドポイント別のavg timeを見ると/api/trendがかなり長いことがわかった。

ちょうどチームメンバーがそこのn+1の改善を進めてくれていたので、自分はmysqlで改善できることはないか探すことにした。


13:00 slow_query_log

最強のmy.cnfを作り始めた。

今回のdbはmariadb 10.3だったのでmysql5.7用のconfを素直にコピペしても動かず、時間を消費してしまった。

long_query_timeを徐々に小さくしていったが、思ったほど問題のqueryが浮かび上がらなかったのを覚えている。

この傾向から、mysqlのcpu負荷よりもioの方が問題になっていそうと考えた。

「ここまでioが遅いならどこかで競合起きてそう。やっぱりRDBがこのアプリケーションに向いてない気がするな、、」という感覚になったので、時系列データベースに乗り換えるべく調査を始めた。

が、使ったことがないので移行するのはリスキーすぎると考え、まずはmysqlを専用インスタンスに分離する施策から始めた。


14:30 dbを専用サーバーに

mysqlのlocalhost以外からのアクセスを許可するのに少しはまったが、無事インスタンスをわけることに成功した。

ベンチを回すと、スコアは26,114まであがった。

みんな喜んでた。嬉しい。


15:00 ポイ捨てされたbulk insert

dbの作業が落ち着いたので、一旦UIを触ってみたり、マニュアルを読み直し始めた。

ここでbulk insertで改善できそうな関数があったのを思い出し、実装を進めた。

実装自体はすぐに終わったがスコアは伸びず、頭にはてなが浮かんでいた。

今思うと相当焦っていた。

もっと落ち着いていればスコアが伸びない理由を把握できたように思う。

インフラを練習したのは自分だけだったので、「アプリケーションに気を取られてはいけない、何しろアラジンとたくりんとんに任せてある」と思い、bulk insertはさくっと捨ててしまった。もったいない。


16:30 忘れられていたINDEX

mysqlとnginxまだまだチューニングやることあるやん、と頭を切り替えた。

ふとINDEXのことを思い出し、whereとorder byを洗い出した。

isuテーブル・isu_conditionテーブルにINDEXを張ると34,798までスコアは伸びた。

INDEXすごーい。


17:00 アプリケーションサーバーを2台に

INDEXのおかげでmysqlのcpu負荷が下がり、アプリケーションのスループットも高くなっていることを確認した。

ここで、アプリケーションのサーバーを2台に増やす決断をした。

このタイミングになったのは、メンバーがaとcそれぞれで進めていた開発の効率を落としたくなかったため。

ローカル環境を構築すればよかったのかもしれないけど、過去回の練習ではすっと構築できなかったので今回は避けてた。

分け方は/api/condition以下のリクエストをすべて別サーバーに流すというもの。

このあたりからログが残っていないけど、45,000くらいはいってた気がする。


17:15 再起動試験しよう。ん?。ポータルサイト落ちてる?

再起動試験した矢先にベンチマークを回せなくなってしまった。

仕方がないので動くと信じて他に打てる施策を探して回った。

n+1の改善が難しいと聞いてたので自分も実装に手を出した。

が、sliceのsliceをsqlxがいい感じにメモリ割り当てしてくれる自信がなく、動作確認も手間がかかるので諦めた。

完全な実力不足。


17:45? 競技時間伸びるらしいよ

競技時間が伸びるのがほぼ確定したので、最後のあがきの準備を始めた。

メンバーにはログを吐いてる部分を潰してもらったりした。

自分はINDEXの張り忘れを修正したり、不要なserviceを停止したり。

ここで焦らず、ベンチマーカーが復活して動作確認取れてからPRをマージするという認識合わせができたのは非常に大きかったと思ってる。


18:15 え、学生1位?

用意してあったPRを動作確認しながらマージしていった。

最終的に再起動試験を実施して59000くらいのスコアが出た。

フリーズ前のスコアではあるけど他の学生枠チームを上回って1位だったので、もしかしたら本戦出場あるぞ!!!ってなってた。

もともと練習のつもりだったが、ここに来て期待がかなりふくらんだ。


18:30 もう何も触らない

この時点で変更を加えて動かなくなるリスクを捨てて、振り返りを始めた。

メンバーはインフラ・DB周りの施策を把握してなかったはずので、どういうことをやったとか、なんで速くなるのとかを説明した。


19:00 クロージング

各々クロージング配信みてた。

疲れた。。。


結果発表

翌日、結果発表があった。

名前は、、、、、、、、、、、なかった、、、、、、

最終スコアは58,449で、学生枠だと6位?だった。あと2000点。。。。。。。。


感想

結構悔しいです。

特にアプリケーションは手を出して無理だーってなる流れが2回あったので復習しておこうと思います。

今回ここまで戦えたのはちゅうこさんとそーだいさんとの素振りのおかげな部分が大きいです。ありがとうございました!

フロントが得意な同期もサーバー側に少しは興味を持ってくれてそうだったのでそれもよかったです。

学生枠で本戦出るチーム、頑張ってください!!

来年こそ!!!!!

Takizawa Tetsu
Takizawa Tetsu

音のVRの研究をしながらWebの技術を勉強しています。