久しぶりのBlogです。9/8にISUCON9予選が開催され 同僚とともに むし,うさぎ,いぬ というわかりづらいチームで参加してきました。私はうさぎです。個人としては3回目、このメンバーでは2回目の参加でした。
isucon.net
9650点のチームまでが予選通過でしたので、あと10点あれば…とおもうと悔しかったですが、これまでで一番いい成績だったので来年こそはと思えました。
事前準備
会社がPythonメインなので、Pythonでいくことにしました。ISUCONではプロファイリングが重要であるため、どの言語でもラインプロファイラーを使うチームが多いと思います。Pythonでは wsgi_lineprof が使いやすいと思います。
これをつかうと、アクセス毎にそのリクエストが通過したPythonのコードに対するプロファイル結果が指定した出力先(ファイル or 標準出力)に書き出されます。この結果をサマライズするための自作のツール wsgi_lineprof_reporter で加工して、ボトルネックを特定しています。
しかし、 wsgi_lineprof を2年前のISUCONから試していたのですが実はうまく使えていませんでした。というのも、昨今のISUCONのベンチマーカの処理が以下のようになっており、事前走行部分でタイムアウトしてしまうからです。
- 初期化処理
- アプリケーションの整合性チェックのための事前走行
- スコアに関わる負荷走狗
ISUCONで与えられるインスタンスは弱いことも多く、また初期実装ではベンチマークがぎりぎり通る程度に遅いことが多いです。そのような状況で、プロファイラをいれてしまうと、そのオーバーヘッドでスコア測定まで進めなくなってしまっていました。
そこで、今回は(予選2日前に) wsgi_lineprof をForkして初回N回のアクセスはプロファイルしないオプションを追加し、当日はそちらを使い初回200アクセスをスキップする運用にしました。
結局、今回与えられたインスタンスはそこそこ強かったので、初回アクセススキップは不要だったかもしれませんがまぁまぁうごいたので良しとします。 (ほんとにありあわせの修正で突如思い出したものなので、本家にPRを出せていませんが折を見てPRを上げてみたいと思います。
当日の作業のやりかた
インフラが得意ないぬは縦横無尽に各サーバの/etc/を直接書き換えてもらい、アプリケーションを見るむしとうさぎはそれぞれサーバ1/2を専有し、sshfsでリモートのファイルをローカルにマウントしてPyCharmやSublime等、使い慣れたエディタで書き換えていました。
sshfsはSSHさえできればローカルにマウントできるので便利ですが、パフォーマンス的には結構きつく、また複数のユーザが同じファイルを編集すると競合しやすいので各々別サーバを使う方式としました。
やったこと
他の記事や講評もすでにでていますので、内容はかぶるところが多いと思いますが軽くまとめておきます。
get_transactions のN+1排除
プロファイラで確認したところ、get_transactions が重くなっており絵に書いたようなN+1が発生していました。 item テーブルを取得後に transaction_evidences と shippings それぞれにクエリが飛んでいたので、先に外部結合を使ったクエリを行いN+1を回避しました。
API呼び出しの削減
get_transactions 解消後は、外部APIでshipment statusを取得する箇所が遅いことに気が付きました。この関数は複数の箇所から呼び出されていたため、状況を正確に把握するため、呼び出し元ごとに別の関数として定義し、プロファイラーを使用しました。これは去年の予選が極端な汎化関数での失敗という問題があったので、それを疑ったためですがとくに有効な情報生えられませんでした。しかたないので、APIの仕様書と実際にアプリを動かして挙動を確認したところ、配送手配中と配送中以外は、API問い合わせをする必要がないことがわかりましたので、shipmentsテーブルの結果次第ではAPIを呼び出さないことにしました。
その他、カテゴリやユーザ情報取得等の小さな部分に雑にlru_cacheをいれたりして、この時点で5400点に到達しました。12時過ぎの時点で2位でしたので、ここが我々のピークだったかもしれません。
右往左往の時期
ここからはなんの成果も得られませんでしたタイムです。
この時点でボトルネックはbcryptによるログイン処理が支配的であることがわかっていましたが、いまいち手が打てないままでした。とりあえず新規ユーザ作成時の強度を下げるくらいは考えましたが、ベンチマーク中は新規ユーザが増えないため意味はなく、同じパスワードでのログイン可否結果だけキャッシュして少しでも負荷を下げようとしましたが99%は異なるユーザでのログインでしたので意味はなかったです。
このあたりからレギュレーションにあった以下の部分へのアプローチを行いました。
新着一覧については、上記の制限を満たした上でよりユーザにあわせた商品の一覧を返すことで、購入の機会を増やすことができます。
どうやらユーザの好みを考慮した順序で戻したりすると、売上が増えるらしい？ 実際に現時点での購入状況を確認すると、殆どの購入リクエストがすでに売れてしまっているものに集中しており、きっとうまくこれを散らせるとめっちゃ売り上げ伸びるんだな？と思いパフォーマンスの改善ではなくベンチマーカの気持ちになる方向に舵を切りました。
まず、既存の売上などを確認すると購入される商品がユーザごとにカテゴリが偏っていることがわかりました。そこで、ユーザごとに購入履歴にあるものと同じカテゴリの商品を表示させてみました。が、効果はありませんでした。
次に、そもそも売り切れの商品に突っ込んできてたので、売り切れの商品を新着から表示除外しました。が、効果はありませんでした。
さすがに、ログインIDとかでランダムに新着を切り替えてみたら散るだろうとしてみました。が、効果はありませんでした。
なるほど、我々はユーザ(ベンチマーカ)の気持ち分かってないな？とおもったので基本に立ち返り、ユーザの挙動を確認しました。ユーザに提示された新着itemの一覧とその後にユーザーが開いたitemページ、購入を試みたitemページをロギングしユーザの状況を目視で可視化したところ驚きの事実が発覚しました。あるitemに集中して購入を試みるユーザは、新着item一覧にないitemの購入を試みているし、itemの詳細すら開いていなかったのです。なるほど、こいつらは買いたい商品へのPOSTリクエストをブックマークして連打している悪意にみちたユーザに騙されていたという結論になりました。ここはもしかしたらキャンペーンの値を4にしたりすると挙動が変わるのかもしれませんが、我々はその域に達せませんでした。
さらなる迷走
すでに迷走していますが、bcryptのことを忘れ去った我々(主に自分)はさらに迷走を始めます。集中購入を行うユーザの大半の挙動が意味不明なら、こいつらにとりあえず別の商品を買わせてしまえばいいのではという天啓を得ました。そこで、すでに売り切れの商品へのリクエストはitemのIDをインクリメントして変える前で再リクエストする悪魔の実装を追加しました。これにより、すべてのユーザは商品が売り切れで変えないということはなく、本人が望んでいないかもしれないがとりあえず椅子が買える状態になりました。
で、ベンチマーカを動かしたら当然事前走行での整合性チェックで死にました。ですよねー。
今思えば、何という無駄な時間だったのでしょうか。
3台構成への対応と時間切れ
この時点で16時くらいでした。そろそろ構成を3台にしておこうということでその作業を進めました。今回の課題ではファイルのアップロードもあったので、椅子画像のアップロードと配信はすべて1号機で行い、MySQLも1号機で動かした関係で2.3号機のウェイトをあげてバランシングさせるようにしました。
途中でファイルディスクリプタ不足でnginxが500を返す事故を喰らいました(Appは500を返してないので戸惑いました)が対応し、そのまま9600点前後まではいきました。一通り安定させた時点で残り20分ちょっととなり、大きな修正をいれる勇気がなかったのでnginxのバランシングをいじる程度の修正をしながらベンチマーカを回して終了時間を迎えました。
悔い
予選通過の方の情報をみていると、/loginを一部のサーバに寄せる構成が丸かったようで、それに気がつけなかったのは悔しいです。しかし何より、普段であれば必ずやっているgunicornからuwsgiへの差し替え等、少なくともあと10点、うまくいけば300点くらいは伸びたであろう変更をできなかったのが本当に悔しいです。
来年は規定の作業は初手でちゃんとやろうと思います。
といっても、2年前からの結果は再起動試験落ちで順位なし -> 再起動試験落ちで順位なし -> 33位なのでこのペースでいけば来年は優勝なのできっと大丈夫です。
