(書きかけ)
これまで予選3回、本戦3回と参加させていただいているISUCONですが、今回のISUCON8でようやくランクインすることができました。
うまくやれば優勝できていたと思われるだけに悔しいーー！
まだまだ精進しないと…という感じです。
感想はともかく、何をしたか、何をしていれば優勝できたか、他に何をやることがあったかまとめておきたいと思います。
メンバーはいつもの3人、 @__math @misodengaku @chibiegg。
SECCONで一緒に出てる @aki33524 は前回と同様釣りに出かけていました。
明確に決めてるわけではないのですが、役割分担としては以下のような感じです。
- @__math (まーす先生) アルゴリズム、コーディング
- @misodengaku (みそでん) データベース、エスパー
- @chibiegg 取りまとめ、インフラ、お茶汲み係、雑用
時系列順に
まずは時系列にやったこととその効果をスコアで振り返りたいと思います。
競技中はソースコード、設定ファイル全てをGitHubで管理しています。
ブランチ毎に作業をして、切り替えながらベンチマークを実行し、バグ無く実装できたものをmasterにマージする方法でやっていました。
そのため、スコアのグラフはところどころ複数の機能実装を交互にテストしているため、実装と効果の関係を誤って記載しているかもしれない点についてはご了承ください。
事前準備 (こたまご)
GitHubにプライベートリポジトリを作成し、二人を招待しておく。
SlackのチャンネルにGitHub連携を設定しておく。
10:00 開始直後 (こたまご)
2人にマニュアルとソースコードを見てもらっている間に作業効率化のための準備をしました。
簡単なAnsibleのplaybookを書いて、基本的な設定を行います。
Ansibleでやる必要もないのですが、やっておくとあとで一括作業が必要になった時に慌てずにできるので良いです。が、今回はあんまり使いませんでした。
- SSH公開鍵の登録 (authorized_keys)
- わかりやすいホスト名の設定
- sudoをパスワードなしで実行できるように
それから、初期実装や設定ファイルとうのディレクトリ (/home/isucon/isucon2018-final) にあるファイルをリポジトリに登録します。
Nginxのアクセスログをalpで解析できるようにLTSVフォーマットでファイルに出力するように設定。
とりあえず、この状態で初期スコアをベンチマークで測定しました。
この時点で把握した状況は以下の通り。
- ネットワークの帯域は余裕、ピークで数Mbpsいくぐらい
- アプリケーションとMySQLがCPUを食い合ってる
- 静的ファイルへのアクセスは多く無い
- 全体の応答時間のうち、 /info /orders へのリクエストが支配的
- スコアは500点強
11:00 DBとアプリケーションサーバを分離 (みそでん、こたまご)
MySQLとアプリケーションがCPUを食い合ってるのはよくないので分離。
サーバ01をアプリケーションに、サーバ02をMySQLに使うようにしました。
全サーバで共通のdocker-compose.ymlが利用されていましたが、これでは各サーバで動かすコンテナを変更できないので、サフィックスをつけて管理することに。
みそでんにスロークエリのログを吐いてもらうように設定して、再度ベンチマークでスコア測定。
- スコアは800強
- 2つ遅いクエリが見つかる
- SELECT * FROM trade ORDER BY id DESC
- SELECT m.t, a.price, b.price, m.h, m.l FROM (SELECT … FROM trade WHERE … GROUP BY t) m JOIN …..
11:20 明らかに遅くて不要なSQLを修正 (まーす先生)
スロークエリを出すまでも無く、遅いクエリのうちの一つが、コードを見るとLIMIT 1で良いことにまーす先生がぱっと見で気づく。LIMIT 1を適用してベンチマーク。
- スコアが10倍近い5000点強に
この時点で何チームか4000点から5000点代になっており、同様の対応をしたと想定されます。
11:50頃 /info の高速化のための下準備 (まーす先生)
まーす先生が /info を高速化すべく、いくつかのプルリクエストに分けて動作確認しつつ改修を進める。
add sec,min,hou #7
add indexes #9
ロウソク足の計算がしやすいように、tradeテーブルに秒まで、分まで、時までのカラムを追加し、インデックスを張った。
カラムを追加したのみで、利用はしていないためスコアへの影響はなし。
12:00頃 ロードバランスできるように準備 (こたまご)
データベースを使い続ける方針にしたので、使っていない残り2台もアプリケーションサーバとして利用できるように設定。
この時点でサーバ01でNginx+App、サーバ02でMySQL、サーバ03と04でApp、という構成に。
ただし、Initializeが全台に対して行われるための仕組みを作っていなかったので、いつでもロードバランスできる状態にはしておきつつ、一旦サーバ01だけで処理するようにしておきました。
また、あんまり効果はないと思われたが、精神衛生上、静的ファイルはできるだけNginxから応答されるように設定しました。
案の定スコアへの影響はなし。
13:20頃 isuloggerへの送信にバルクリクエストを採用 (こたまご)
isuloggerへのログ送信は秒間リクエスト数に制限がありました。
仕様書を見ると、バルクリクエストがあったためこちらを利用することにしました。
- ログの発生時は実際には送信せずchanに突っ込む
- バックグラウンドでchanからログを収集
- 定期的にまとめて送信
という挙動を実装しました。
実装とついでに吐いたログからわかったことは以下の通りです。
- スコアが1000程上がって、6000弱になった
- 今の所秒間リクエスト数を超えるようなログは発生していない
ログの送信がバックグラウンド処理になった影響で少しだけスコアが上昇します。
この時点では秒間リクエスト数の制限にかかるほどではなかったのであまり大きな効果になっていませんが、この実装をしておかないとこの後詰まることになります。
14:00頃 ロードバランスできるように初期化機能を実装 (まーす先生、こたまご)
初期化を全ノードに実行できる準備 #11
ロードバランスを再度有効化 #12
ベンチマーカーは実行開始前に一度だけ /initialize を実行します。
ロードバランスするとこの初期化リクエストは1つのアプリケーションプロセスにのみ届きます。
その時点で、全てのアプリケーションプロセスを初期化する必要があるため、内部APIを用意し (/internalInitialize) 全てのサーバの初期化を行うように実装しました。
また、設定をsettingテーブルから都度参照するようになっていたのをやめ、グローバル変数に持つように改修することでDBへのアクセスを減らしています。
ちゃんと動作はするようになったものの、数百程度のスコア上昇しかおきませんでした。
14:10頃 不要な行ロックを削除 (まーす先生)
コード上に怪しい SELECT * FROM user WHERE … FOR UPDATE があったので、不要じゃないかとFOR UPDATEを削除。
この時点ではスコアに大きな影響はなかったが、残していた場合この後で困っていたと思われる。
14:30頃 SNSでの拡散を開始 (こたまご)
みそでんがSNSシェアを有効にするフラグがあると発言。(さすがエスパー担当)
それを聞いた私が、もしかしてtrueにするとアクセスが増えるようにベンチマークができているのではと気づく。
ドキュメントを読み返すと同様の趣旨が書いてあった。(読んだけどなんのことかわからずその時はスルーしてしまっていたと思われる)
あまりにもtrueを返しすぎると、ユーザー増加に耐えられずタイムアウトが増えてしまうので、とりあえず1/8の確率でtrueを返すようにする。
- スコアが1万点を超える
- リクエストが増えたことでボトルネックがわかりやすくなった
このあたりで1万5000点の特別賞をチームNaruseJunが獲得。
このフラグに気づくのがあと10分早かったらーーと悔やまれます(笑)。
15:20頃 /infoのローソク足をキャッシュ (まーす先生、こたまご)
雑な /info キャッシュ #15
雑じゃないロウソク足のキャッシュ #16
- ローソク足は、直近のものは変化するが過去のものは変化しない
- ローソク足は、秒単位で更新されれば良い
という性質もと、私が雑にレスポンス丸ごとメモリにキャッシュする実装、まーす先生が丁寧にロウソク足をメモリにキャッシュする方法をそれぞれ実装しました。
私の雑なキャッシュでも特に問題はなく、一気に25000点弱に。
まーす先生の丁寧なキャッシュもバグ無く動作したため、両方をマージしました。
丁寧にロックまでしてキャッシュを管理していたものの、ロックをしない私の雑キャッシュでも問題なく動作したためロックを削除した結果、28000点ぐらいまで上昇しました。
15:50頃 約定条件のチェックが不要だった (まーす先生)
前々から処理が冗長だと気づいていた RunTrade 関数にメスを入れ始める。
初期実装では、注文があるたびにRunTrade関数を利用して約定可能なものを全て約定してから応答を返していた。
その際に、RunTrade関数を呼ぶ前に約定する可能性があるかどうかを確認するロジックがあったが、このロジックが重く不要だったため、小手始めにごっそり削除。
少しスコアが上がり、3万点弱に。
16:10頃 ユーザーの情報をメモリにキャッシュ (こたまご)
settingテーブルと同様、リクエストの度にデータベースを参照しにいくようになっていたユーザー情報をメモリにキャッシュするように修正。
ついでに吐きすぎていた不要なログを削除。
ついに3万点を超える。
16:50頃 RunTrade (約定処理) をシリアルにバックグラウンドで実行するように (まーす先生)
上記の通り、注文処理が来る度に実行されていた約定処理を、約定処理要求だけフラグにもち、実際の約定処理はバックグラウンドでシリアルに実行されるように修正。
これによりスコアが37000程度に上昇。
17:30頃 /info 内の注文価格情報をキャッシュ (まーす先生)
ache lowest/highest value (GET /info Only) #22
もっとも安い売り注文と、もっとも高い売り注文の価格の計算を求めるSQLが重く、キャッシュすることに。
これにより5万点を超える。競技中4万点を超えたチームはtakedashiだけだった。
17:30頃 再起動試験や最後の調整を行う (こたまご、みそでん)
データベースやアプリケーションがサーバ再起動時にちゃんと上がって来るように設定されているかみそでんにチェックしてもらいました。
並行して再起動試験を行い、どの程度スコアが下がるか調査。
この時点でサーバ自体を再起動する勇気がなかったのがこの後の敗因の一つとなります。
また、Nginxのアクセスログや、スロークエリを出さないように設定したことで競技中最高得点の51,834点を記録。
時系列外 (みそでん)
みそでんにはデータベース周りの細かいチューニングを行ってもらっていました。
今回はDBのダンプファイルが提供されていなかったためバックアップを取っておいてもらったり、コネクション数を調整してもらったり、バッファサイズを調整してもらったり…
試行錯誤が必要なので、githubのコミットには細かくは残っていません…
最終計測
48000点ほどのリクエストを捌いたものの、33件のリクエストを落としてしまった (400エラーを返していた) ため、減点により31939点に。
ステータスコードが400なのがちょっときになるが、OS起動後でデータベースのファイルがOSのページキャッシュに載っておらず十分なおパフォーマンスが出せなかったことが原因と思われます。
また、SNSシェア率を100%にしてたため、パフォーマンスが追いつかなくなった時にエラーが頻発してしまう問題も抱えていました。
ほんとはやるべきだったこと、まだまだあるやるべきこと
この先も書こうと思っていますが、明日はU-22プログラミング・コンテストの審査会のため続きは明日終わってから書きます。
おやすみなさい…