見出し画像
Photo by mericanadesico

ISUCON12予選にチーム「フタしてない」で初参加して惨敗しました

クドウマサヤ | iCARE CTO

はいどうもー。株式会社iCAREでWebエンジニアをしているクドウマサヤ(@masaya_dev)です。

先日7/23、チーム「フタしてない」として、iCAREで共に働いているでんでん(@shogodenden)と遠藤くん(@hiroendore)とISUCONに初参加してきました。チーム名の由来は弊社のCREDOから。

ISUCONとは

ISUCONはIikanjini Speed Up Contestの略で、「お題となるWebサービスを決められたレギュレーションの中で限界まで高速化を図るチューニングバトル」です。LINE株式会社さんが運営しています。年1開催されていて、今回で12回目。

サーバーサイドやインフラ領域に携わっているWebエンジニアにとっての甲子園みたいなもんだと思っているので、ISUCONで結果残している方に出会うと、めっちゃすげー！！！！って思います(雑)

結果

自分もめっちゃすげー存在になりたかったところですが、先に結果だけ書くと惨敗。「環境チェックで失格/3回の再現スコア計測で85%以下のスコアしかでなかったため失格」でした。

めちゃくちゃ悔しい。Webエンジニアとしての矜持が雲散霧消しました。

環境チェックに関しては、おそらくnetdata用のportを開けっ放しにしてしまっていたのが原因。ここは自分が管理していたところなので猛省。

再現スコア計測に関しては、エラー出たり出なかったりで全然スコア安定していなかったので、単純に実力不足ですね。

ちなみに言語はRubyで、最後に申請したスコアが2002、途中のベストが3512でした。

事前準備

チームを組んだ

ISUCONは第1回目の頃から存在は知っていたのでいつか出てみたいなーと思いつつ、今までなかなか踏ん切りがつかず。でんでんと遠藤くんが出ようと思ってる的な話を聞きつけて、一緒に参加しようという流れになりました。

参加権を得た

人気すぎてそもそも出場する権利を得ることすら難しいISUCON。遠藤くんが頑張ってくれて無事に第一期の参加受付に滑り込み。1分遅れていたら定員オーバーだったっぽいのでヒヤヒヤ。GJですねえ。

事前講習会に出た

勢いで出ることにしたものの、正直ISUCONに対してほぼ何も知らん状態だったので事前講習に出ました。これ結構大変だな？ということに気づく(今更)

元々Goで出たいと考えていたんですが、この座学をみて普段から全員慣れているRubyにしようと判断。

ISUCON本を買った

通称ISUCON本と呼ばれる、「達人が教えるWebパフォーマンスチューニング　〜ISUCONから学ぶ高速化の実践」を買いました。

ここ数年0→1開発が中心で、高負荷なサービスをゴリゴリとチューニングするっていう仕事をやっていなかったので、考え方のおさらいやモダンな計測手法を学ぶのにとても良かった。

練習会をした(2回)

メンバー3人で集まってISUCON11予選の過去問説いたり、ISUCON本の3章以降を一緒に進めたりなどしました。

全員初参加なので当初はわからんことだらけでしたが、事前講習で学んだことや過去参加者のレポートを漁り、最低限必要になりそうなツールやTODOリストの準備は完了。

全く歯が立たないってことは無さそうな自身を得て、100位以内目指して頑張ろうと淡い期待を抱いていたあの頃。。

当日のログ

0次試験

無事起床どころか、緊張のせいかアラームが鳴る前に目覚めた。というわけでちょっと時間的余裕があったのでジムに寄った。

9:00〜

全員無事にオフィス集合。予選レギュレーションやTODOリストの再確認を確認。問題発表の時間が近づくにつれてみんなそわそわ。

9:55頃に問題発表。ISUPORTSというマルチテナントSaaSサービスとな?普段からマルチテナントSaaSを作っている我々にとって有利なのではないかというお気持ちを一瞬抱く(そんなことはなかった)

10:00〜

いよいよ競技開始。

自分のAWSアカウントを使うことにしたので、CloudFormationで環境構築開始。作成完了待ちつつざっとマニュアルを眺める。

10:10〜

環境構築完了。ここで言語設定も切り替えをし、サーバー3台それぞれでベンチを回す。1台目はエラーで0点、2台目は991点、3台目は789点。

でんでんには各サーバーへgitの導入、遠藤くんにはマニュアルの読み込みをやってもらっていた。

10:25〜

ブラウザでアプリケーションの動作確認を開始。アプリケーションマニュアルも読みつつ、ドメイン知識やページの導線について理解。

10:45〜

この時間帯のTODOリストの進捗を確認。特に問題無さそうだったので、システム構成の調査に入る。

管理者用のDBがMySQLで、テナント用のDBがSQLiteなことに気づきなんか複雑そうだな…と嫌な予感。それぞれのDBにどんなデータが存在するか追う。

そしてアプリケーションとNginxとそれぞれのDBがどんな役割を持っているか、ホワイトボードにざっくりと図を書いていた。サーバー3台とも動いているものは一緒と知る。

この裏側で他メンバーにはalp、pt-query-digest、netdataとか分析ツールをインストールしてもらっていた。

11:40〜

でんでんがベンチ回しても落ちると詰まっている様子だったので、自分も調査に加わる。

10:30頃にEC2のセキュリティグループ確認したんだけど、そこで作業ミスして必要なポートが開放されていなかった。

それでベンチ回らなくなっていたので、スライディング土下座。すいませんでした。。。

12:05〜

全員作業的にキリ良いタイミングだったので、休憩がてらオフィス近くのセブンイレブンで食料調達。暑かったのでスイカバーを買った。

12:20〜

食べつつ作業再開。分析しやすくしたかったので、rack-mini-profilerのインストールを試みる。

app.rbとGemfile書き換えてbundle installすればと思ったが、Gemfile.lockと合わんと怒られた。ローカル環境でGemfile.lockの更新ファイル作ってコミットしたらうまくいった。

だがしかし、設定は間違っていないはずなんだけどprofilerが画面に出てこないという謎。小一時間試したけど原因突き止められなかったので利用をあきらめる。

正直rack-mini-profilerはあると便利だけど無くてもどうにかなるというツールなので、導入したいの欲求ありきで作業を進めてしまったのが反省点。

非常にもったいない時間の使い方をしてしまった。。。

13:30〜

メンバーはalpやpt-query-digestを追ってボトルネックの調査を進めてくれていたので、自分はベンチ回した時に起きたり起きなかったりするAPI(/api/organizer/competition/xxxxx/score)の500エラーについて調査を進めることに。

アプリケーションのログ追っているとなんかjwtの検証エラー結構出てるからその辺関係ある？という仮説で調査。

これも小一時間調査したんだけど、結局再現性特定できず。

15:00〜

競技開始から、5時間。残りはあと3時間。全くスコア上がっていないのでちょっと焦り始める。

気休めにnginxのworker_connectionsを768から1024に変え、worker_rlimit_nofileを4096にしてみる。スコア変わらず。今思えばこの段階ではアプリケーション側がボトルネックで、そもそもnginxの負荷が高まっていないのでそれはそう。

ISUCON本で学んだ「推測するな、計測せよ」の教えを全然守れていない。

15:06〜

アプリケーションの動作確認したときにテナントのmypageで大量のフォントファイル読み込まれているのが気になっていて、軽く調査。

フロント側で行われていることだしリクエスト先もGoogleフォントだし、スコアへの影響はないだろうと思いつつ、なんか怪しいという好奇心を抑えきれなかった。。。

15:18〜

メンバーはSQLiteのチューニングやAPIのエラー調査を進めていたので、自分はMySQLのチューニングに着手。

alpの結果とかソースコードみつつ、visit_historyにindex貼ったら結構効きそうと判断。tennant_idとcompetition_idにそれぞれindexを追加。ちょっとスコア伸びたからこれでいいかと終えてしまった。ベストアンサーは複合indexなので、知識不足が露骨に出ている。

15:44〜

SQLiteのロックが原因でエラーが出ているケースが多かったので、connect_to_tennant_dbのbusy_timeoutを5000→30000に変更。スコアの伸びは無いが、3回ベンチを回してもエラーが出なくなった。おそらく良い手ではない。

16:06〜

2時間を切ったが2000前後とほぼ伸びていない。とりあえずスコアをパッとあげられそうなことはないか？と探す。ベンチ回しながらtopを眺めていて、CPU使用率に余裕があることに気づく。

そこでpumaのworkerとthreadを調整することに。
workerを2→3、threadを1→8:32へ。worker:4も試したがAPIのエラーが増えるので減らした。

ちなみに解説だと、worker32まであげられたっぽいので、やっぱそもそものアプリケーション側のボトルネック潰す前にやっても良い効果得づらいんだよなと感じる。あと結局数値調整も勘になっちゃっているので、まだまだ見識が浅い。。。

16:30〜

/api/admin/tenants/billingであきらかにN+1が生じているので直せないか調査。が、なかなか大変そうなことに気づく。

とりあえずMySQLの設定ファイル(/etc/mysql/my.cnf)でよくあるチューニングしてみるかと方向転換。

[mysqld]
innodb_buffer_pool_size=1GB
innodb_flush_log_at_trx_commit=2
innodb_flush_method=O_DIRECT

これ追加したら、瞬間最高スコア3512を記録してちょっと沸く。

17:10〜

引き続きMySQLのチューニングをしようと思っていたが、「Mysql2::Error::ConnectionError - Lost connection to MySQL server during query」というエラーが突如発生するようになり焦る。出たり出なかったりで結局最後まで再現性を特定できなかった。

この辺からベンチの結果も全く安定しなくなる。おそらくworkerとthreadの数を増やした結果によってtimeoutが出るAPIが生じてその減点が大きかった。

17:50〜

とりあえずもう何をやっても間に合うわけないのでスコアガチャ。1000切ったり2000超えたり全く安定していないのでまじのガチャ。2002でフィニッシュ。

18:00〜

競技終了、中継の解説みんなでみて悔しさ抱えつつ解散
(あまりの悔しさに自分は朝までやけ酒してしまったのはここだけの話)

総括

はい、以上のように見事に惨敗でした。

敗因は山のようにあるんですが、そもそもの戦略ミスが大きかったかなと思います。SQLite出るなんて思わなくて、誰も触ったこと無いやばいみたいなところで、序盤から完全に進め方が崩れてしまっていた気がする。

あれも気になる、これも気になるという情報が無数にある中で、どこから潰していくかというロードマップを描かずに、なんかとりあえずスコア上がりそうなことやる、となってしまったのが最大の反省。

どの層にボトルネックがあるかをしっかり認識し、計測から仮説を立て改善をするというサイクルを全然回しきれていなかった。

おそらくここを焦らずやっていれば、今の全員の知識レベルでも10000点は目指せたんじゃないかなというお気持ち。

Webエンジニアになって12年ちょっと。ここまで悔しい思いをしたのは初めてだったので来年必ずリベンジしたいと思います。

謝辞

これ書いてても未だに悔しさで爆発しそうですが、めちゃくちゃ楽しかったのも事実！ここまで緊迫した状況でアプリケーションのパフォーマンスチューニングをするという経験もなかなか出来るものではないので、エンジニア脳をフル回転させられて面白かったです。

一緒に闘ってくれたでんでん&遠藤くんには本当に感謝！悔しさをバネに、この経験を活かしてCarelyをいい感じにスピードアップ出来るように頑張っていきましょう。

また、弊社技術顧問の馬場さん(@netmarkjp)もSlackで色々アドバイスいただいたり、勉強会で著者直々にISUCON本の解説やっていただいたりとありがとうございました！予選2位で通過は本当にお流石です。。。

そして練習会のときに、日曜にも関わらずわざわざ美味しいプリンを差し入れしてくれた弊社テックリードのうっちーさん(@MushromSamba)にも感謝！そういう素敵な気遣いが出来る人に自分もなりたい。。

我々が開発している健康管理システムのCarelyも、お陰様で利用ユーザー数も順調に伸びており、気持ちよくサービスを使っていただくためにパフォーマンスチューニングしたい部分が増えています！

ちょっとでも興味があればラフにお話しましょう！気軽にDMください〜

ではでは！

Everything's gonna be alright!