初めてのISUCONにチーム「らんちぅ」で参加しました #ISUCON10予選

TL;DR

Rustの参考実装は早い
New Relicに圧倒的感謝。

ISUCON10予選お疲れ様でした

最終スコアは722(参考値)でした。
isuumo、面白い問題だったなと思います。
当日までの準備を進めながら数々の対応をしてくれた運営さん、一緒に戦ったメンバー、ありがとう！お疲れ様でした！

らんちぅ

同じ大学のM1の先輩2人(Masapyon, koba)とB3の僕(Hiroya_W)の学生3人チームです。
当時、ISUCON10予選参加枠が一気に埋まりそうだ、という情報を聞き、急いでソロで参加登録。
その後、メンバー募集をされていたので、入れてもらえることになりました！

「ISUCON 夏期講習2020 座学＆もくもく会」に参加して初めてISUCONを知り、座学ともくもく会の両方参加するからには、実際にも参加しよう！と思っていました。
当初、もくもく会は、各自もくもくと問題を解くのかと思っていました。

しかし、実際に参加してみたら、全て用意されていて、なおかつ全員で足並み揃えて手取り足取り教えて頂ける会となっていました。
「過去、ISUCONに参加したことがない方のみが対象」とされていただけに、とても良い講習会だったと思っています。

事前準備

たまたま別件でGoを使う予定だったのとGoで参加している人が多いことから、Goで参加する予定でした。
そこで、まずは「A Tour of Go」をとりあえず触りました。
そこからは、GoのWebフレームワークのチュートリアルを触ってみようかな、と思いましたが、結局触っていません。

これは、New Relicが開催した「せっかく無料なのでISUCONでNew Relicをスッと使う方法」というウェビナーに参加したからです。
GoにNew RelicのAgentを導入する場合、

• 計測のために、各自でミドルウェアを書く必要がある
• それに伴い、メソッドを別のものに置き換えるので、最後はまたメソッドを元に戻す必要がある

ということを知り、まずここで詰まりそうだという印象を受けました。
それに比べ、PythonやRubyはアプリにパッケージとしてインストールするだけでほとんどの場合、自分で記述する必要がありません。
それなら、Pythonでも全員自信を持って読めるので、New Reilcを確実に使っていきたい！という方針に切り替えました。

そこから本番までひたすらISUCON9予選だけ¹を使って必要な知識をつけていきました。
ISUCON9 オンライン予選 関連エントリまとめを片っ端から読み漁り、個人で練習する時は、VagrantでISUCON環境を作り、メンバーで集まって練習する時はGCPにISUCON環境を作って練習しました。

やったことは、esa.ioに記事として試したことをひたすら書きなぐり、最後はGitHubのリポジトリのWikiに項目を分けて整理しておきました。
New Relicのライセンスキーが平文で書いてあるので公開出来ないのは申し訳ない²。

Makefile³、New Relicなどのログのとり方、秘伝のタレ、DBまわりのINDEXの張り方など基本的なところが中心になったと思います。
トラブルシューティングする時に、参考になりそうなところの記事まとめみたいな感じにも使えるようにまとめておきました。

当日

先輩方は研究室に集まり、僕は自宅からオンラインで参戦しました。
チーム全員の作業画面を見れるようにしたい、ということからwherebyというサービスを利用しましたが、使いやすくてとても良かったです⁴。

開始が12:20にずれ込んだこともあり、11:30頃に集合することにし、それまでに軽く腹ごしらえをしておきました。

午前中は運営がリアルISUCONしてる…って見守ることしか出来ませんでした。
問題の用意は大変だったと思いますが、改めて、本当にお疲れ様でした。

後は、ISUCON10はRust実装があるの面白いな〜早そうやなぁって話してました。これは伏線です。

役割分担

予定では、

• Hiroya_W: App
• koba: DB
• Masapyon: Infra

でしたが、僕が当日までにインフラ周りの勉強が出来たおかげで、本番の役割分担は、

• Hiroya_W: App Infra
• koba: DB
• Masapyon: App Infra

という感じに、僕も少しインフラの面倒を見る形になり、その間にMasapyonにAppを手伝ってもらうという形になりました。

ここからは、当日僕がやったことと、覚えている範囲でメンバーがやっていたことを書いてみます。

12:20 ~ 13:11

SSHしてサーバーにアクセス出来たので、MasapyonがGitHubにpushしてくれました。
また、構成も調べてくれて、Nginx、MySQLだったのでISUCON9予選と一緒だな〜ってちょっと安心しました。

その間にHiroya_Wとkobaはマニュアルを読み、大事そうなところをwikiにまとめつつ、実際にアプリを触ります。

しかし、ポートフォワーディングしてブラウザにアプリを表示させるところで苦戦しました…。
マニュアルにコマンドの使い方が書いてあったんですが、そんな使い方をしたことがなかったので、それだけでは引数をどうやって与えれば良いのか分からず悩みました。

Google先生に聞いたら、SSHポートフォワーディングを知った話を見つけました。
なるほど。立っている3つのインスタンス間は通信出来ることが分かったので、サーバ2にSSHしてそこからサーバ1の指定したポートへ流すと出来るのでは？？？と理解して、

$ ssh -L localhost:8080:10.162.41.101:80 isucon-server2 

ってやって繋がって喜びました。13:11頃です。終了後、サーバ1にSSHしてサーバ1から見たlocalhost:80に対してポートフォワードすればいいと別チームの人に教えてもらった。これで確かに繋がる。

$ ssh -L localhost:8080:localhost:80 isucon-server1

SSHまわりは、ISUCONを通して本当に勉強になりました⁵。

13:11 ~ 13:30

アプリをなんとなく触り、過去のISUCONとは違い、手で触る程度だったらisuumoがそんなに重たくない、目に見えて遅いみたいな状況が無くてすぐに遅いところは判断出来ませんでした。
なので、ベンチ回して、ログ取ってみないことには進まないねって言いながらも、まずは確認がてらログ取らずにPythonでベンチを数回回します。

ベンチ中はhtopを眺めてたんだけど、CPU1コア、RAM2GBでとかでマジ？？？？とか言ってた。
練習した環境はマシンスペックがある程度あったのでパラメータチューニングも見直す必要がありそうだなと感じ始めてました。

また、2台構成の練習を誰も出来ていなかったこと、再起動試験で落ちるのが怖くて、今回は1台でチューニングする予定で進んでいました。
が、このスペックを見て、少なくとも2台構成にしないと話が進まないなと思って、Hiroya_Wが対応することをひっそりと決意しました。

13:30 ~ 15:00

何はともあれログです。ログの出力と集計、Slackで共有まではHiroya_Wが担当します。
まずはNew Relicではなく、Python向けのラインプロファイラであるwsgi_lineprofを導入しました⁶。(後で分かりますが、結果的には何故かログが出力されませんでした)

が、たしかここら当たりでベンチの不具合によりベンチマークを実行することが出来ず、ログが手に入りません。

その時間を使って、ローカルに開発環境を整えることにしました。
が、ローカルでアプリを実行して、http://localhost:1323にアクセスしても404が返ってくる。
FlaskがGunicornに乗っていないし、Flaskでrender_templateを返していないのでアレ？ってなってきてる。

nginx.confを読んで、/www/data/に置かれている静的ファイルをNginxが返していることを確認しました。
ベンチもAPIに対して行われるようだったので、あー…じゃあローカルではcurlでPOSTしたりGETしたりして確認しようってことになりました。
動作確認はgitでbranch切って、適宜サーバーでpullして試す、といった感じ。

15:00 ~ 15:40

ベンチマーカーが復活したらしいです。早速、wsgi_lineprofでログを出力しようとしましたが、上手く出力されず。
とりあえず、同時に出力させていたMySQLのスロークエリをpt-query-digest集計してSlackで共有。
DB周りをkobaとMasapyonに見てもらっている間に、原因究明をするまでもなく、すぐにNew Relicを試す方向へ切り替えました。

そうして15:40にようやく、New Relicにログが見え始め、MySQLのクエリもが全部上がってきました。
New Relic凄いです、全部見える。

この時点でのスコアは353ですね。ようやくISUCONスタートラインに立った気がします。

15:40 ~ 16:50

ここからは、AppとDBの二台構成に挑戦します。

ISUCON9予選のエントリを読んで書いていたメモを頼りに

• 環境変数の MYSQL_HOST を立てたインスタンスの IP アドレスに設定する
• MySQL の bind-address オプションをコメントアウトする
• MySQL を外部接続できるようにするを見ながら、isuconユーザに権限を付加する

を試します。Server001からServer002へ接続したかったのに、Server002からServer001への接続が出来るようになってた事件がありましたが、なんとか二台構成をやり遂げます。
ここで、435にスコアが微増します。

16:50 ~ 18:33(koba, Masapyon)

ここから、kobaとMasapyonがやってくれた修正を適用していきます。
でも、ベンチ結果を見てみると分かるけど、本当に何をしても上がらない。何回か回してみても、良くならない。

kobaが張ってくれたINDEXのコミットがこんな感じ(後で分かるけど、実はこれだけではINDEX張るのが実行されてなかった)

isuumo/webapp/mysql/db/3_IndexEstate.sql

CREATE INDEX idx_door_height ON isuumo.estate(door_height);
CREATE INDEX idx_door_width ON isuumo.estate(door_width); 

isuumo/webapp/mysql/db/init.sh

- cat 0_Schema.sql 1_DummyEstateData.sql 2_DummyChairData.sql | mysql --defaults-file=/dev/null -h $MYSQL_HOST -P $MYSQL_PORT -u $MYSQL_USER $MYSQL_DBNAME
+ cat 0_Schema.sql 1_DummyEstateData.sql 2_DummyChairData.sql 3_IndexEstate.sql | mysql --defaults-file=/dev/null -h $MYSQL_HOST -P $MYSQL_PORT -u $MYSQL_USER $MYSQL_DBNAME

Masapyonが実装してくれたBotの通信に503 Service Unavailableを返す機能⁷がこんな感じ。

app.py

bot_user_agent = re.compile(
    r'ISUCONbot(-Mobile)?|ISUCONbot-Image\/|Mediapartners-ISUCON|ISUCONCoffee|ISUCONFeedSeeker(Beta)?|crawler \(https:\/\/isucon\.invalid\/(support\/faq\/|help\/jp\/)|isubot|Isupider|Isupider(-image)?\+|(bot|crawler|spider)(?:[-_ .\/;@()]|$)/i')

app.py

def block_bot(request):
    user_agent = request.headers.get('User-Agent')
    if user_agent:
        if bot_user_agent.match(user_agent):
            return True
    return False

app.py

    # 各エンドポイントで最初に実行するようにする
    if block_bot(request):
        return jsonify({'message': 'Service Unavailable'}), 503

が、スコアは伸びません…。

curlで試してちゃんと502を返すのを確認してくれていたが、ベンチ中には502を返したログが取れなかったので不思議に思ってたけど、負荷が弱すぎてボットのアクセスが無かったのでは、とお話を聞いた。

他にも、kobaがCOUNT(*)をCOUNT(id)に変更してくれたり、

app.py

-    query = f"SELECT COUNT(*) as count FROM chair WHERE {search_condition}"
+    query = f"SELECT COUNT(id) as count FROM chair WHERE {search_condition}"
-    query = f"SELECT COUNT(*) as count FROM estate WHERE {search_condition}"
+    query = f"SELECT COUNT(id) as count FROM estate WHERE {search_condition}"

Masapyonが椅子をドアに通るかチェックするところを工夫してくれたり、

app.py

     w, h, d = chair["width"], chair["height"], chair["depth"]
     query = (
         "SELECT * FROM estate"
         " WHERE (door_width >= %s AND door_height >= %s)"
         "    OR (door_width >= %s AND door_height >= %s)"
         "    OR (door_width >= %s AND door_height >= %s)"
-        "    OR (door_width >= %s AND door_height >= %s)"
-        "    OR (door_width >= %s AND door_height >= %s)"
-        "    OR (door_width >= %s AND door_height >= %s)"
         " ORDER BY popularity DESC, id ASC"
         " LIMIT %s"
     )
-    estates = select_all(query, (w, h, w, d, h, w, h, d, d, w, d, h, LIMIT))
+    estates = select_all(query, (w, min(h, d), h, min(w, d), d, min(w, h), LIMIT))

/api/estate/searchと/api/chair/searchでSQLでcountするんじゃなくて、Pythonでcountするようにしたり、

app.py

    # これはestateの部分
    search_condition = " AND ".join(conditions)

    query = f"SELECT * FROM estate WHERE {search_condition} ORDER BY popularity DESC, id ASC"
    chairs = select_all(query, params)
    count = len(chairs)
    chairs = chairs[per_page * page:per_page * page + per_page]

    return {"count": count, "estates": camelize(chairs)}

してくれていたことがcommitログから分かりました。
僕は、この改善の議論に参加できていなかったのですが、色々試してくれていてありがたいなぁとエントリを書きながら改めて感じています。

スコアの改善が見られないのが非常に辛かったです。

18:33 ~ ??

INDEXが張れてないことに気がつきます。気がつけて良かった…。

New Relicでログを確認しても変わってる雰囲気が無かったので、本当にINDEX張られてる？みたいな雰囲気になってきてました。
MySQLから、コマンドでINDEX張ってあるか確認しようかって言ってたら、

MasapyonがINDEX張る部分が実行されてないことを見つけてくれた。

app.py

@app.route("/initialize", methods=["POST"])
def post_initialize():
    sql_dir = "../mysql/db"
    sql_files = [
        "0_Schema.sql",
        "1_DummyEstateData.sql",
        "2_DummyChairData.sql",
    ]

sql_filesってやつがあるんか…。ISUCON9予選では、initializeで

subprocess.call(["../sql/init.sh"])

が実行されていたので、そうゆうもんなんだろうと思いこんで、

koba> INDEX張るのってinit.shに書くんでいいんやんな〜？
Hiroya_W, Masapyon> 合ってると思う〜

って会話してたのを覚えてる。張れてないじゃん…。

そしたら、初めてスコアが微増した。これまで340~380を行ったり来たりしていたので、400近くなって喜びました。

もうこの時点で、18:30とかでようやく来た！嬉しい嬉しい！って言ってました。
今まで張ったINDEXがちゃんと貼れてなくてちゃんとスコアを調べられていなかったので、もう一度INDEXを張ってベンチを回して計測したりしてた。

16:50 ~ ??(Hiroya_W)

時間軸は少し戻り、kobaとMasapyonが修正を取り込んでベンチを回している間、Hiroya_WはMySQL5.7からMySQL8へのアップグレードを試していました。
これは、単純に「MySQL8にすると早い」という超大雑把な情報を得たからです。MySQL8にある機能がISUCON10で使えるなんて知る由もありません。

また、App,DB,DBにしろ、App,App,DBにしろ、3台構成にする方法を僕らのチームは誰も勉強出来ていません。なので、1台余らせてしまっているので、壊しても良いという思いで挑戦させてくれました。

MySQL8にアップグレードし、ベンチを回した結果ですが、こんな感じになりました。

0でFinishしているのは、アプリケーションの整合性チェックに引っかかっています。
かと思えば、その直後に実行したベンチは、スコアが付きかけ、結局Cancelledされてしまいます。

他にも、スコアがついたとしても100台とMySQL5.7より良くなっている気配がしません。
ちゃんと理解出来ていない上、アプリケーション整合性チェックが何故通らないのかも分からず、ベンチが不安定で運営の追試でFailするのも嫌なのでMySQL8へのアップグレードは諦めました。

これは、本番中に問い合わせてみても良かったかもしれないなと書きながら思ってます。
MySQL8に関しても、ちゃんと復習しておきたいなと思うポイントですね。

?? ~ 20:20

僕は用意したMySQLとNginxの秘伝のタレを投入。

kobaがINDEXを更に張り、

3_IndexEstate.sql

  CREATE INDEX idx_door_height ON isuumo.estate(door_height);
- CREATE INDEX idx_door_width ON isuumo.estate(door_width); 
+ CREATE INDEX idx_door_width ON isuumo.estate(door_width);
+ CREATE INDEX idx_latitude ON isuumo.estate(latitude);
+ CREATE INDEX idx_longitude ON isuumo.estate(longitude);
+ CREATE INDEX idx_rent ON isuumo.estate(rent);
+ CREATE INDEX idx_popularity ON isuumo.estate(popularity); 

4_IndexChair.sql

CREATE INDEX idx_popularity ON isuumo.chair(popularity);
CREATE INDEX idx_price ON isuumo.chair(price);
CREATE INDEX idx_color ON isuumo.chair(color);
CREATE INDEX idx_height ON isuumo.chair(height);
CREATE INDEX idx_width ON isuumo.chair(width);
CREATE INDEX idx_kind ON isuumo.chair(kind);
CREATE INDEX idx_stock ON isuumo.chair(stock);
CREATE INDEX idx_features ON isuumo.chair(features); 

Masapyonが変更を適用してベンチを回してくれていました。
数ある変更をmasterへマージしていってベンチを回していき、chairにINDEXを張る変更によって590スコアを記録します。
回すたびにスコアが伸びていって凄い凄い言ってたと思います。

上3つのベンチは、僕のOS周りのチューニングが施された結果なのですが、スコアが下がってしまったので、直ぐに元に戻して無かったことにしました。

20:20 ~ 21:00

終了1時間を切ったので、再起動試験をしようってなったのですが、その前にRustの参照実装でどれくらいスコアが出るのか気になる、ということでベンチを走らせることに。

無事最高得点を叩き出します。
チューニングを施したPython実装よりも早いじゃねーか⁸！！もう大爆笑ですね。

アプリまわりの修正がスコアに効かなかったこともあり、そのアプリの修正を全て捨ててRust実装へ切り替えることに。
DBのINDEXを張る部分と別のインスタンスのMySQLにアクセスするように修正し、20:30。

再起動後、ベンチを回して最終スコアを更に更新して722。

しっかり再起動試験App→DB、DB→Appを試して、ちゃんと動いていることを確認してFinish。

反省点

ISUCON9予選でMySQL5.7からMySQL8へのアップグレードが効果的になる話を読んでいたので、事前に試しておくべきだったなぁと感じています。そこからMySQL8にある機能をちゃんと理解しておくべきでした。
また、今回はメンバー全員のNginxやMySQLに関する知識が薄かったのが刺さったと思います。
特に今回は、DBが中心的な印象があり、Appだけでは現状から抜け出すチューニングが出来なかったな、と感じています。

感想

結果的に、Rustの初期実装とDBにINDEX張っただけになってしまいました。
それでも、そこにたどり着く過程が面白かったのでOKです。

結果はどうであれ、ログを見て、遅いところを探し、正解に近い部分を修正しようと出来ていたような気がします。
環境を整え、この段階に持っていくことがISUCONの最初の難しいところだと思うので、それが本番でちゃんと出来たのは良かったなと思います。

また、このエントリを書くにあたって、commitログから色々と試してくれていたメンバーの様子が分かり、ありがたいなぁという思いでいっぱいです。
任して良かったと思うし、逆に、僕に任して挑戦させてくれたことにもメンバーに感謝したいです。

この経験を次のISUCON11に活かして挑戦します！次も対戦よろしくお願いします！

1. 一応他の問題も手を出したが、ISUCON8予選はNew Relicを入れるとベンチが落ちる(原因はbrowser_monitoringらしい)ので諦めた。ISUCON9本戦はDockerが分からなくて諦めた。ISUCON9予選だけとは言うが、やってもやってもやること、知らないことが出てくるので、ISUCON9予選**"しか"**つかっていないの方が正しいかもしれない。 ↩

2. いつかはどこかで公開したい。 ↩

3. 直前にMake勉強会をしたので、ここぞとばかりに「ISUCON9予選1日目で最高スコアを出しました」を参考に整えた。タイムリーだった。 ↩

4. 当初はZoomを使う予定だったが、Zoomで全員の画面共有をしてみるも、自分が画面共有をしながら相手の画面を見る方法が分からず断念。ただし、wherebyでも他にしても、画面共有をしながらブラウジングしたり、VSCodeでコーディングするのは自分のPCのスペックでは限界だったらしく、作業に支障をきたす事が発覚し、途中から僕の画面共有は適宜、という形になってしまった。CPU:Core i5 4210, RAM:8GBですが、CPU使用率が張り付き、CPU温度が80℃をキープするようになったので慌ててノートPC用の冷却ファンを取り出した。 ↩

5. 事前準備で鍵の配置、権限、フィンガープリントといった問題で、ことごとく詰まってたので知見が自然と溜まっていった。 ↩

6. ISUCON9予選のPython実装ででNew Relic素振りしたら、MySQLのクエリログがset, commit, rollBack以外上がってこなくて、肝心のSELECTが一切見れてなかった。New RelicのExplorer Hubに書いて調査してもらっても良かったな。他にも、ISUCON8予選でベンチ回すとDOM構造が〜って言われてベンチが落ちる現象(原因はbrowser_monitoringらしい)になって、New Relic使うのどうしようって話にもなり、その時用に別の方法を確立させてた。 ↩

7. Pythonのアプリで実装するものだと思ってたのですが、どうやらNginxで実現できるそうですね…。知らなかった。 ↩

8. PythonでNew Relic外した時のスコアを計測していないような気がする。 ↩