REQLY開発ブログ

プロの料理レシピ専門検索エンジンREQLY（レクリー）の開発ブログです。

初出場3人でISUCON8予選を学生枠1位(?)で通過しました

ISUCON（Iikanjini Speed Up CONtest）というWebサービスの高速化を図るコンテストにREQLYで参加してきました。全員初出場でしたが、結果は30,491点でなんと学生枠1位(?)で通過！厳密には一般枠で通過していた猛者の学生が4チームいますが、学生枠での1位は1位、嬉しいものは嬉しい！

メンバー

  • yoco: 唯一インフラが分かる人。発起人。
  • m2ku: なんとなくSQLが分かる人。筆者。
  • kenbo: マグロの研究者。試合後、病床に臥す。

事前準備

事前準備としてpixiv社内ISUCONを2回に分けて解きました。1回目はslow query解析やalp等の計測ツールの基礎を導入方法から勉強し、そのあとは静的ファイルの処理などを試しました。2回目は本番の前日の土曜日に行い、様々な記事を参考に、N+1問題の解消など点数を上げていく練習をしました。

役割分担・使用言語

インフラが分かる人がyoco以外にいなかったので、アプリケーション側をm2kuとkenboの2人で担当するフォーメーション。SQLに関しては、m2kuがインデックスとJOINを嗜む程度。使用言語はm2ku, kenboが普段書き慣れているPythonを採用しました。

本番参加記

それぞれの備忘録を貼っておきます。

m2ku編

最初の1時間

まずサーバーが3台もあったので怯える。なんとなく3番目のサーバーを選択し、 こいつは自分のものだと宣言する。事前の取り決め通り、pyenvでjupyter notebookが使えるようにpython環境を整えたりbitbucketにwebアプリのコードを上げたりした。残りの担当はmysqlのslowqueryの設定だったが、こっちのサーバーにはmysqlがたってないので何もできない。yocoにmysqlのサーバー3への移籍を優先でやるようにお願いする。その間は、webサイトをいじりつつ、たぬきうどんを食べる。sheetとseatのスペルミスについてkenboがドヤ顔をしているので殴る(10:48)。flaskのコードをみて基本的にシングルページで/api以下にアクセスすることで描画に必要なjsonをもらっていそうだ、ということが分かる。そうこうしているうちにサーバー3でmysqlがたつ。

slowqueryの設定

  • 練習では/etc/mysql/my.cnfをいじったがファイルが見つからなかったので怯える
  • 頑張ってググると(10:56)includedirみたいなことをやってどっかのディレクトリを読み込んでるみたいだった。
  • ディレクトリにあったファイルのうち[mysqld]という項目を持っていたファイルに予定通り以下の3行を追加
slow_query_log_file = /var/log/mariadb/slow.log
slow_query_log      = 1
long_query_time = 0
  • 練習で作っていた、restart.sh, check_mysql.shなどの便利スクリプトも仕込む。

初めてのベンチマーク

ベンチを回そうとなったが、サーバー1からサーバー3へのdbのアクセスがうまくいっていないらしく、手こずっていた。その間はdbのスキーマを確認しつつ、webサイトをいじり始める(with kenbo)。

  • /api/event/10を叩くと直接jsonが見れることを確認
  • eventにもpriceカラムがあって、sheetにもpriceがあることが分かる
    • 実際にwebサイトを見ると、2つの和になっていそうなことを確認
  • どのeventを選んでも、Sの席数などは変わらないことを確認。

この辺を確認したところで、yocoがmysqlの連携とkataribeの連携が終わったようで、ベンチマークを回して諸々の計測をする(11:54, 400点)。/loginと/usersと/eventsが遅いな、という空気感になる。/usersと/eventsが遅いのはクエリ的（スロークエリ、N+1）にも妥当だが、/loginが遅いのはクエリも速いし納得が行かないと主張する。誰も信じてくれないので、pythonのloggingを用いて、関数の実行時間を取得するコードを書く。実際にこの関数は数ミリ秒で終わっていることが分かる(12:30)。次回はアプリケーションの関数の速度を直に観測するツールの準備が必須だと感じる。kenboと唐揚げを買いに行く。道中/usersと/eventsは2時間くらいあれば自分が直せそうなので引き受けると主張する。/loginは全然わからないのでkenboに調査をお願いする。

get_event()改修

仕事を始める(12:54)。/usersの方はスロークエリの上位に入っていたのでindexを貼れば簡単に治りそうだと思い先に着手する。SQLのIFNULLとかGROUP BY HAVINGとか初めて見て怯える。コードを読んでいくと、途中でget_event()を複数回呼んでいることに気づき、 /events も合わせてこれが諸悪の根源であることに気付く。方針転換して、get_event()のN+1を最初に直すのが良さそうだと考える。jupyter notebookでget_event()をリニューアルすることを始める（13:46）。最初はDBとの接続に苦労したが、yocoに聞いたら「flaskを捨てろ」といって華麗に解決してくれる。新しくsheet情報を一括で取得するクエリを作成し、結果を元のget_event()と返り値が同じになるように整える。jupyter上で%%timeで計測したら、4倍くらい早くなっていたので、良さそうだと感じる。deployされて点数が伸びる(15:00, 10000点)。ドヤ顔をして30分休憩する。totalの席数やランクごとの値段の加算がeventによって変わらないということをあらかじめ知っていたので、コードを単純化できたのも良かった。

def get_event(event_id, login_user_id=None):
    cur = dbh().cursor()
    cur.execute("SELECT * FROM events WHERE id = %s", [event_id])
    event = cur.fetchone()
    if not event: return None

    query = '''
    SELECT *
    FROM sheets
    LEFT JOIN (
        SELECT
            sheet_id,
            user_id,
            reserved_at
        FROM reservations
        WHERE event_id = {}
        AND canceled_at IS NULL
        ORDER BY sheet_id
    ) AS sub
    ON sheets.id = sub.sheet_id;
    '''.format(event_id)

    cur.execute(query)
    sheets = cur.fetchall()

    event["total"] = 1000
    event["remains"] = 0

    event["sheets"] = {}
    event["sheets"]["S"] = {"total": 50,    "remains": 0, "detail":[], "price": event["price"] + 5000}
    event["sheets"]["A"] = {"total": 150, "remains": 0, "detail":[], "price": event["price"] + 3000}
    event["sheets"]["B"] = {"total": 300, "remains": 0, "detail":[], "price": event["price"] + 1000}
    event["sheets"]["C"] = {"total": 500, "remains": 0, "detail":[], "price": event["price"] + 0}

    for sheet in sheets:
        if sheet["reserved_at"] is None:
            event["remains"] += 1
            event["sheets"][sheet["rank"]]["remains"] += 1
        else:
            sheet["reserved"] = True
            sheet["reserved_at"] = int(sheet['reserved_at'].replace(tzinfo=timezone.utc).timestamp())
            if sheet["user_id"] == login_user_id:
                sheet["mine"] = True

        event["sheets"][sheet["rank"]]["detail"].append(sheet)
        del sheet['id']
        del sheet['price']
        del sheet['rank']
        del sheet['sheet_id']
        del sheet['user_id']

    event['public'] = True if event['public_fg'] else False
    event['closed'] = True if event['closed_fg'] else False
    del event['public_fg']
    del event['closed_fg']
    return event

残り2.5h

残りの2.5hで何をするか話し合う。/usersと/adminの2つがネックになっているという話になる。/usersの方を取り、/adminを2人に任せる。

  • /eventsでは自分以外のsheet情報がいらないのでget_event()を呼ばずに専用の小さいクエリでアクセスするようにする
  • user_idでindexを貼る

などの細かい修正をしたが、ベンチマークがしばらく走らなくなってしまっていたこともあり、改善がどれくらいあったのかは分からない。ここに関してはmaster一本開発より、各々featureブランチを切っても良かったかもと思った。あと、indexを手動で貼っても、schemaに書いておかないと再起動後には失われてしまうということに気付いていなかったため、重いクエリを読み間違えたりしていたのが勿体無かった。また、サブクエリ内で使われると思っていたINDEXが、実際にEXPLAINで確認すると使われてなかったりして、本戦までにはSQL力を上げておきたい。reserved_atと主keyの順番は同じであると仮定して、ORDER BYしなくても良い説をなども唱えたが、これはどうなんだろうか。そもそもカラムがすでにsortされているかを確認するSQL文を知らないので、調べておく。

yoco編

最初の2時間

h2oに対してalpを仕込もうとしたが、alpはltsv形式での出力を要求している。nginxの設定ファイルをみながら、h2oのログの出力をalpがパースできる形に変換しようと考えたが、うまくいかない。そこでいろいろ調べてみると、kataribeというロギングツールがあることがわかったので、kataribeを導入することにした。kataribeは、h2oのもとのログフォーマットに、request_timeを追加するだけであったので、容易に導入することができた。

3台体制であったので、いままでの練習会で試していないパターンであって動揺するが、すぐにサーバ1とサーバ2をアプリケーションサーバ、サーバ3をdb用にすることに決めた。サーバ3にdbをつなげるのに苦労した原因は、「mysqlの初期化コード」がサーバ1に置いてあり、これは/initialize にアクセスしたときに実行されるが、その初期化コードが参照するmysqlが、デフォルトではサーバ1のものであったためである（これが俗に言う鈴木明エラーである）。このサーバがさす向きをipアドレスを直で指定してサーバ3に切り替えるという修正を行った。

お手製のpython再起動スクリプトrestart.shと、チームslackに通知するためのスクリプトslack-notifier.shを、サーバ1およびサーバ2にも導入した。これにより、private git repositoryでpythonサーバのコードを管理しておいて、アプリケーションを再起動したいときはそのコードをpullしてsystemctlでrestartする環境を整えることができた。

ここまで2時間かかってしまったことは誤算であった。

それ以後試したこと

インフラ側のチューニングを行った。今回の初期設定ではgunicornというアプリケーションサーバで、flaskのアプリはサーブされている。これは、もとの設定ではワーカ1、スレッド1で動いていたので、1コアしか利用することができなかった。

mysqlでshow connections;をしたところ、1ワーカにつき1つのコネクションしか貼らないという挙動がみえた。この挙動通りだとすると、スレッド数を増やすよりワーカの数を増やしたほうが、mysqlのスロークエリがコネクションを占有することが少ないのではないかという仮説を持った。

そこで、少し変則的であるが、スロークエリが多いことからワーカー数を増やして並列化することにした。これにより、アプリケーションサーバで1コアだけでなく、2コアを使うことが可能になり、スコアが多少増加した。

h2oはnginxに比べてほとんどチューニングする余地はない。が、負荷分散のために/admin のアクセスだけを、サーバ2に送ることにした。これは、結果的には/admin以下にある巨大なCSVを吐くエンドポイントがワーカを占有することを回避できたといえる。（mysqlのトランザクション分離レベルの問題か？）。

その後、kenboと、遅い箇所について検証した。

/loginが遅いのはクエリも速いし納得が行かないと主張する。誰も信じてくれないので、pythonのloggingを用いて、関数の実行時間を取得するコードを書く。

というところから、ロギングで実行時間として計測していない部分、今回の場合ではreturn文でjsonifyしているところが遅いのではないかと考えた。実際に/login はjsonを吐くところが律速になってたようで、python-rapidjsonを導入することで1リクエストあたりの所要時間が激減し、スローリクエスト順にソートされたログの上位からは姿を消した。

csvを吐くエンドポイント（@app.route('/admin/api/reports/sales')）のpythonコード側の改修を行い、ループの回数とソートの回数を1回ずる減らしたが、定数倍の高速化であることに加え、このエンドポイントはクエリ側がFOR UPDATEでロックをとっていたことが律速であったのでそれほど意味がなかった。

m2kuがget_eventのN+1クエリを華麗に解決したので、3万点に到達した。m2kuがクエリ修正をやっている間に、yocoとkenboではSQLをほとんど触れなかったので、それが今後の課題となる。

憶測

レギュレーションからみて、「予約or予約取り消し」のたびに10点、その他のリクエストは基本的にゴミなので、できるだけ予約を進めたいが、その他のクソリクエストにcsvを吐くとかの激重FOR UPDATEリクエストが混じっているせいで、点数の入るリクエストの実行が妨げられていたと思われる。そのため、いかにうまくそれらを捌くか、ということが重要であったように見える。

ベンチマーカの挙動として、3万点の壁を越える頃には、/loginや/ などに対するアクセスが1回につき数千アクセス発行されるようになった。これらのアクセスは、点数にはほとんど寄与しないが、全体の処理速度を遅くしてしまうという問題があった。これに対して、これ以外のエンドポイントをサーバ分けてしまうと、reservation更新/参照系のクエリに不整合が起きる（例えばサーバ1に更新クエリを送ったとき、それが処理されるまえにサーバ2で参照している？）らしいということがわかったので、色々と考えてみたが、failを完全に防ぐ切り分け方は当時は見つからなかった。（上位通過チームでも、random failに苦しんでいたようだった。）

コメント

今回の勝因は「細かい修正箇所に惑わされず、計測結果を信じて最もボトルネックとなっていたget_eventを修正したこと＋/admin以下の遅いクエリを別サーバに待避させた」という点にあると思っている。 再起動確認はビビらずにさっさとやればよかった。

おわりに

運営の皆さんありがとうございました。本選頑張ります！