ISUCON7予選を2日目3位で突破した

2017/10/23

ISUCON7予選を2日目3位で突破した

秋も深まりISUCONの季節ですね〜。今年はどういうチームで出ようかなと思ってたのですが、8月に同僚の @fujiwara が学生向けのISUCON夏期講習をやるということで資料を眺めていたところ…

fujiwara組ヒストリー

ぎゃーーISUCON4の3位が最低成績だなんてーーーオレ歴代fujiwara組最弱じゃないか… となったので、今年はこのチームを再結成してもうちょっと良い成績を取ってリベンジしようというのがぼくの密かな野望でした。ちなみにISUCON4の決勝で3位に伸び悩んだのはCache-Controlっていうヘッダを付けるという解法がわからなかったみたいな話なのですが、その辺は当時の公式の解説と講評を読んでもらえばいいでしょう。一応Cache-Controlつけてない組の中では1位だったんですけどね、そういうのを負け惜しみっていうんですけどね…。

ISUCON7予選のお題は…

さて、そんなわけで始まりましたISUCON7予選。始まる時間がいつもよりも遅くて、朝弱い自分としてはわりと助かったというところもないわけではないですが、さすがに13時スタートで21時までやるのはしんどかったです。でも出題側に回ったことあるので運営がこの何倍もつらいことはよく知ってるので今回出題のKLabさん本当におつかれさまでした。

予選のお題はIsubataというどこかで聞いたことのあるような感じのチャットサービスでした。あと、今回は予選から複数台構成という大変意欲的…というか本戦慣れしている人には差が付けやすくてありがたい構成になっておりましたが、スペックがな! CPU1コア! メモリ1GB! ディスク16GB+4GBスワップ(これはまぁ十分)! みたいな感じでした。ディスクがHDDかSSDかでも結構攻め方変わる可能性あるのでhdparmしておきましたがちょうどキレイに 100MB/sec くらいでしたので、まぁたぶん帯域制限されたSSDだろうということでディスクについては不自由しなさそうだなという感じです。後から分かることですが、運営はswapされることも想定していたとのことでしたので、SSDでよかったです。

さて、ここからはやったことをつらつらと書いていきます。言語は、Goです。いやぼく最近Go書いてないのでえーみたいな感じだったんですが、それ以上に最近Perlも書いてなかったのと、1日目のトップ通過チームが社内の別チームで、彼らはおそらくGoだろうねということでこれはGoで良さそうだねという感じでGoにしました。

GET /icons/:file_name について

最初に1台目と2台目にチェックボックつけてベンチかけてみるとInternal側のネットワークがサチりつつDB詰まりという見え方になっていることが分かります。で、原因は明白で、imageというテーブルに画像が入ってるからでした。しかもアイコンのわりにめっちゃでけーし。ということで、まずこれをなんとかしないことにはどうしようもないということで、INDEXを張ったりする前にまずここから手をつけました。

@handlename に初期データをDBから吸い出してファイルに落とすのをお願いして、こちらはファイルがアップロードされたら(ひとまずDBにも書く処理は残しつつ)ローカルのnginxが配信できそうなディレクトリ(あらかじめ静的配信ディレクトリにiconsディレクトリがあって運営の優しさを感じました)に保存するように変更します。最終的にはnginxのtry_fileを使う予定でしたが、ひとまず最初はアプリ側で画像がローカルにあったらそれを返すようにしてDBの負荷を下げます。これにより、1台でしか動かせなくなりますが、どうせ詰まってるのDBなので前に2台置いてもムダってことでしばらくベンチ対象は1台で高速化を進めました。

初期データ的にはimageには1000画像入ってましたが、吸い出してみると67ファイルしかできず、なんだこれどうなってるんだと思ってしらべてみると、distinct nameしたら67と返ってきてなるほど〜〜となりました。ということは getIcon のクエリで LIMIT 1 付けるだけでも効果ありそうだねってことでそれでスコアが上昇するのと確認してからローカルファイル保存を投入してようやくスコアが団子ゾーンから抜け出しました。

ちなみにこれやってたときは最初の2時間くらいで、13000くらいだったんですが、この時点で4万から7万をジェットコースターのように上下してるチームがいてあいつらは何をブレイクスルーしたんだ…みたいな感じでしたが余所を気にしてるヒマがあったら自分の仕事をしっかりやろうということで続きをやっていきます。

あと、画像サイズデカすぎなのでリサイズは一応ためしましたが、画像の整合性チェックでNGになるので帯域なんとかしろってことですね。

DBの負荷軽減について

画像をローカルファイルから返すようにしてもまだDBの負荷は落ちなくて、インデックスをはるのを @handlename にやってもらい、それでもまだおちないので @fujiwara にとってもらったpt-query-digest を眺めた結果、COUNT(*)が大量に出てるのとループクエリがでてるのが分かったので、自分はCOUNT(*)撲滅、 @handlename はループクエリ撲滅で並行作業しました。

COUNT(*)は未読管理が絡む奴はすぐにどうにかできるものではないので放置して、チャンネルごとのトータルメッセージ数だけchannelテーブルにmessage_countカラムを追加して対応しましたが、これによりメッセージが来たときにmessageテーブルへのINSERTの他にchannelテーブルのUPDATEもかかるようになっちゃったんだよな〜書き込みクエリは減らしたいのにな〜と思いましたが、そんなことよりもこのCOUNT(*)のスキャンを減らすのが先決なのでエイヤーとやりました。

ループクエリ減らすところも無事終わり、DBの負荷が結構さがりました。この辺がおわって5万〜7万点くらいだったかな。

Cache-Controlについて

これでボトルネックはグローバル側の帯域に移りました。このときまだ1台構成だったので、dstatでsendが10MB/s送ってるのを確認してあーこれで外向き詰まりましたねぇという感じです。ベンチマークのログを見てみても、cssとかWebフォントのタイムアウトが原因で負荷が上昇しないみたいなメッセージが出始めたら外向きの帯域が詰まったサインです。

ということで @fujiwara がnginxでexpires max;を設定してCache-Control: max-age=...が出るようになりましたが、あんまり効いている素振りが見えません。ここのグローバル側帯域をどうにかしないことにはISUCON4決勝のときと同じ感じで手詰まって残り4時間くらいゴロゴロすることになってしまいます。さすがにISUCON4のリベンジに来てるつもりなのにまたCache-Controlで敗北したらこりゃシャレにならんぞ…と、もっかい当日レギュレーションを読み直します。

結果的にたいした材料になることは書いてなかったですが、「ただし、静的コンテンツや画像ファイルに関しては、HTTPの規則の範囲内でステータスコード200の代わりに304を返すことができます。」とはあるのでなんらかの方法で304を返す必要があるね、という感じになりました。nginxでファイル返してる時点でETagとLast-modifiedとCache-Control: max-ageはついてるので、さらになんか付けるとしたらCache-Controlで追加のプラグマを送るしかないよな〜となり、HTTPのキャッシュ関連仕様を眺めてCache-Controlに書けるプラグマのリスト眺めたらとにかくキャッシュしろって明示するのはpublicしかなかったので、 @fujiwara にpublicも追加でつけてもらいました。

それでもスコアのブレが激しくてあんまり上がった実感なかったのですが、nginxログをみるかぎりどうやら前半は画像が200で返るが後半から304で返るようになり、ベンチのログをみてみるといままでびくともしなかったLoadLevelがついに後半にあがってくるようになっていたので、これをいかに迅速に上げていくかがポイントなんだなーとなりました。

3台構成への変更について

これで複数台構成にすれば帯域が増えてLoadLevelが上がるタイミングを早くできそうだということで、複数台構成にする作業をすすめていきます。

問題はアップロードされた画像の分散配置をどうするかですが、パターンとしては2つあり、画像を1台にまとめて画像のところは全部そいつにnginxでproxy_passするというのが一つ。もう一つは画像をアップロードされてきたサーバにそのまま保存し、保存時にどのサーバにあるかわかる情報をファイル名に入れてnginxでそれを元に画像があるサーバにproxy_passするパターンです。

今回は複数台にベンチがかかるので、後者になりました。まぁ1台にまとめちゃうとそいつに負荷が偏ることになりますしね…。ちなみに今年の新卒研修で社内ISUCONをやったときの複数台構成模範解答は、1台にまとめる戦術でやりました。そちらについては社内勉強会で喋った資料があって、実はこれも面白資料なのですが、まぁ社外に出しちゃダメな情報じゃないからパブリックに公開しちゃうか! ってことでさっきアップロードしといたので興味があったらそちらもどうぞ → KAYAC 社内ISUCON 2017、複数台構成の顛末

話を元にもどすと、複数台に画像を配置するために、画像URLにどのサーバにあるかのディレクトリを含めるようにして、userのavatar_iconには 01/{sha1}.png という感じで文字列を入れるようにして1台のままURLに画像の場所を入れる改造をしてベンチのチェックが通ることを確認しました。

これがレギュレーション・ベンチマーク的に通ったのでじゃあこれで分散だねーということでホスト名の最後の1文字が1〜3になっているのでこれを画像配信ディレクトリに掘ってそこに入れるようにして、 @fujiwara には location /icons/01〜/icons/03でそれぞれのサーバにうまいことproxy_passする設定をいれてもらいました。

これがうまく行って外向きの帯域を300Mbps使える & Cache-Control: publicでベンチマーク中盤からLoadLevelがあがるようになり、30〜40万程度出るようになりました。

GET /fetch と sleep について

Goつかってたということもあって、sleepはとくに障害になりませんでした。

これがPerlやRubyといったprefork型のやつだと、/fetchの並列度によってはworkerが/fetchに専有されるみたいなのもありえたのですが、GoとNode.jsはその辺考えなくて済むのでそこは楽でしたね。

レギュレーションでは、initializeのあとの整合性チェック+負荷走行のセットで60秒という規定があり、整合性チェックの中には /fetch が含まれていましたので、sleepはずしてしまったほうが/fetchが早く回って負荷走行に早く入れるのでちょっと点数上げれるみたいなところもあったかと思いますが、pubsubとかを入れずに/fetchをノースリープで回すとfetch自体の負荷が高くなりすぎてそこにCPU持って行かれるという問題がありました。

fetchの部分は未読管理をしつつ未読メッセージ件数を送るというやつで、チャンネルの数だけループクエリになっているので、ここはちょっとどうにかしないとならないということで、読んだ記録のあるチャンネルのループクエリはあきらめて、読んだ記録のないチャンネルの件数だけchannelテーブルに生やしたmessage_countからとるようにして、一度もみたことがないチャンネルの未読数部分だけループクエリを緩和しました。これがまぁまぁ効いてたこともありsleepを0とかにしても破滅しなくて済んだのかなと。

ただ、結局の所sleepの数字をいろいろいじりましたが有意にめっちゃ速くなったみたいなのがなかったので最終的にそのまま1としています。

あとpubsubでfetchをオンデマンドに返すかどうかについてはちょっと検討しましたが、お題のサービスの特性として特定のチャンネルにJOINするみたいなのはなくてあるチャンネル全体について全て所属しており未読数を返す対象になっていて、POST /messageの頻度は最終的に秒間数十回とかまで増えていくっぽいのでpubsubするまでもなく常に未読なメッセージ増え続けてるからpubsubする必要無いよねってことでやめました。

POST /profile について

POST /profile はプロフィール画像があがってくるところで、画像のファイル名を決めるのに画像全体のSHA1を使うようになっています。この時点でベンチマークのログを見るとタイムアウトになっているのはほとんどPOST /profile になっており、SHA1をするところが足を引っ張っている感じになってきました。

ということで、SHA1のとりかたを全体ではなく最初の1024バイトとかでとるように変更しました。しかしながら、これがなかなかうまく行きません。最初の整合性チェックも通過し、十数秒くらいノーペナルティで負荷が上昇し続けていきなり画像の整合性チェックが死ぬという感じでベンチマークがFailしてしまいました。

いらすと屋のpngとかは背景透過pngだから先頭の1024バイトだけだと同じになってるパターンあるかなぁ、でもPNGヘッダーは画像サイズとかも含んでるし、背景透過エリアは圧縮されててIDATが完全に一致することはそうそうないよな〜と思い、4KBとか16KBにしていけば大丈夫だとおもうんだけどなーとなりましたが、16KBでもダメなのでこのPRはrevertしました。

個人的にはこれが結構悔しいポイントで、それまで負荷走行の一番最初の数秒はどうしてもタイムアウトで負荷が上昇しなかったのですが、このPRを入れることにより一番最初から負荷がガンガンあがってくるようになっていて、これがちゃんと動いていればおそらく最低でも50万〜60万くらいは安定してでるようになってトップスコアも夢じゃなかったのかなーという感触でした。

結局画像チェックのエラーの理由はまだわからないのですが、パターンとしては2つあって普通に画像の先頭のSHA1だけだと完全一致するアップロード画像のパターンがあったというそうは問屋が卸さないぞパターンと、ベンチが快適に回りすぎて同じユーザIDからのPOST /profileが同時に発生してしまって画像検証がバグってしまったというベンチがバグってたパターンがあるかなぁという感じです。

ベンチのバグパターンはISUCON3本戦の出題で事前解答してベンチマークが激しく回るようになったときに似たようなこと(並列度上げすぎて期待する結果が2つのワーカー間で矛盾する結果になってしまうバグがあってそれを開発中に潰した)があって、結構ありがちなやつなのでその辺はベンチマークが公開されたらどういう画像チェックになってたのかは確認してみたいと思っています。

まぁ普通にSHA1じゃない方法でファイル名決めてもよかったかもですねー。ここはちょっと判断が甘かったところでした。

POST /message と GET /message について

レギュレーションのスコアリングをみるとわかりますが、GET /messageはGET自体の1点に加えて /message に含まれるメッセージのJSONの数がそのまま加点になります。LIMIT 100があるので最大100点ドーンと加点のチャンスなのでこれを効率よく回すのがポイントです。

で、alp使ってアクセスログ集計してみると POST /message と GET /messageがたまたまなのかなんなのかほぼ同数のリクエスト(たしか見たログだとPOSTが4603回でGETが4600回)なので、これはたぶん POST /message を早くしてGET /messageの回転上げるべきだねーってことで、message_countを作ったchannelテーブルへの書き込みがなくなるようにRedisに逃がそうみたいな話をしたのですが、結局手が着かず。

ちなみに感想部屋ではGET /fetchしてメッセージあったらGET /messageするみたいなパターンで動くみたいな話もあったので、POST /message と GET /message の回数がほぼ同じだったのはたまたまの可能性が高いかもしれませんw

その他細かいやつ

あとは箇条書きで…

Placeholder使うところがPrepare-Execの2パケットになってたので、go-sql-driver/mysql のinterpolateParams=true オプションを付ける
golangのechoのMiddlewareのLoggerが有効になっててリクエストごとにログ吐いてたのでコメントアウト
POST /profileで画像とニックネーム変更があるとUPDATE userのクエリが2回飛ぶので1個にまとめる
pt-query-digestでセッションが有効か確認するためのgetUserが毎度走ると重いので、クッキーストアにUserのデータをいれるようにしてPOST /profileの更新でクッキーストアを更新するようにした
ベンチを1回回すとGoのアプリが600MB以上くって2回目にはswapしはじめるのでGOGCを50に下げて調整

あと気になったけど手をつけなかったやつ。

テンプレートのマクロtAddとtRange、これテンプレートでやる必要あるかなぁと思ったけどGoのマクロは多分速いのでそのままにした

とまぁそんな感じで、20時半から再起動試験を行い、スコアガチャでひとまず48万でたのでこれで終わりにしましょうということで20:40過ぎに作業終了。天気も悪いので飲みにいくのは諦めて、コンビニでビール買ってきて社内の他のメンバーと感想会をやって帰宅しました。みなさまおつかれさまでした。では、本戦出場のみなさま来月もがんばりましょう〜

2017/10/23