ISUCON
ISUCON 8 予選で惨敗しました（リュウグウ）
@methane です。とうとうISUCON予選敗退を経験してしまいました。 めちゃんこ悔しいです。
16:20には6万点台を出し、そこからはトップ争いを続けて17:47には10万点台を叩き出したものの、その後は2万点台しか出なくなり終了してしまいました。
それまでは調子の悪いときでも数回ベンチをしていれば少なくとも4万点台にはなっていたので、ずっと2万点台しか出なかったのは不運もあったのですが、そもそもスコアが安定しない原因を潰しておけば確実に予選突破できていたはずなのでこれも実力です。
やったこと
役割分担は、僕が全体を見る＆アプリの実装もやる、 makki_d がアプリ、 mapk0y がインフラでした。選択言語はGoです。
最初の方はダッシュボードを作るのに必要な作業を2人にお願いしつつ、自分でもインフラ、アプリのコード両方を見て回りました。
ダッシュボードができてからは getEvent がネックなのが明らかになりました。一方レギュレーションでは予約とキャンセルのスコアが高く、ISUCON2との類似性からもその部分もキーになると判断しました。
getEvent も 予約もキャンセルも、全部 registration テーブルがキーになっています。とくに予約処理は見るからにまずいトランザクションになっているので、 registration テーブルのオンメモリ化に取り掛かりました。
といっても完全なオンメモリ化は諦めていて、ちゃんとDBに書き込んだ上で最新の情報をメモリ上にも載せておくだけです。また、メモリに乗せるのはキャンセルされていない予約だけです。
最初は予約処理とキャンセル処理でメモリ上のデータを正確に更新するところを作りきりました。これができたのがすでに15時ごろでした。(diff)
これができると、次は getEvent でループで registration テーブルを SELECT してるところをメモリ上のデータを使うように書き換えます。 (diff) これが 15:30 頃で、4万点台でやっとトップグループの仲間入りをし、ほっと一息。
次に、さっきの getEvent のループ内で RegisteredAt を求めるためだけに registration を配列から線形探索でやっていたのがネックになっていたので、ループの前に先に sheet id と registered at を対応付ける map を作って置くことで高速化 (16:10ごろ) (diff)
この時点で6万点台は出るようになっていたものの、スコアの乱高下に翻弄され始めます。インフラの設定変更を試してみても大幅にスコアが下がって、設定変更のせいなのかどうか分からなくて迷走してしまいます。 (TIMED_WAIT が多いから nginx -> Go を unix socket に切り替えたものの、スコアが上がらなくなって TCP に戻すなど)
17:00 を過ぎた当たりで、 makki_d が挑戦していたイベント全体のオンメモリ化のバグが取り切れなかったので、 getEvents で event テーブル全体を引いたあとに getEvent で event テーブルを1行ずつ引くという同じテーブルに対する N+1 を潰し (diff)、17:30 には7万7千点。
そこから再起動試験で一度失敗し、2度めの再起動試験で幻の10万点台を 17:47 に出します。
ここで止めておけば良いものの、この一度のハイスコアで「再起動したらスコアがよくなる、なんか遅くなるのは繰り返して実行してるからかもしれない」と誤認してしまいます。 このときに nginx のアクセスログが切れてなかったので、アクセスログを切ってもう一度やろうと指示を出し、結果競技終了までずっと2万点台、最後の1回は1万点台で終了しました。
敗因(技術的問題点)
終了後にメンバーと話し合って、多分これだという問題点を見つけました。
予約とキャンセル処理では、registration のオンメモリキャッシュの一貫性を保護する mutex の中でDBへの更新をしていました。それがつまり気味なのはなんとなく把握していましたが、原因や、ひどいときにどれくらい詰まるのかまでは把握してませんでした。
一方、DBの方でもなにかデッドロックのログが発生していることは気づいていたものの、 admin 系で複雑なクエリがあるので、 admin 系のAPI通しで競合する事があるのかなとあまり気にしていませんでした。
そして、その admin 系の複雑な長いSELECTクエリに、 "for update" が混ざっているものがあることも気づいていて無視していました。
これを総合して考えると、 admin 系の重い SELECT クエリが for update で registration テーブルを盛大に（全体を？）ロックし、予約か削除がロックを握ったままそれを待ち、 getEvent を利用しているすべてのAPIが引きずられて詰まりタイムアウトを発生させる、というシナリオに思い当たります。ベンチマーカーが公開されたら検証してみたいと思います。
実は、mapk0y が作業中に「MariaDBからMySQLに入れ替えます。」「トランザクション分離レベルを read committed から repeatable readに切り替えます」という報告はしてくれていました。SELECTクエリの中で for update が出てくるの、ダーティーリードを避けるためにロックを掛けていたとすれば、 repeatable read に切り替えたときに完全に不要になっていたはず…ぐぬぬ。
反省点
最大の書換であるところの reservation オンメモリ化を自分でしてしまいましたが、これは makki_d に任せて、自分はもっと調査系に専念するべきでした。手を付けたときに makki_d が他の作業に取り掛かっていたのと、事前練習不足で makki_d が「オンメモリ化」をスラスラ書けるか解らなかったのと、何より「自分が何もできないまま敗北する恐怖」に負けてしまいました。
大きな改修＋それを利用した大規模な高速化が終わってトップグループになったのが16時で、そこからは「競技終了までに何をするか／しないか」に頭が切り替わってしまったので、落ち着いて全体を注意深く調査することができませんでした。
他にも、次のような要因があったと思います。
- 過去問では report 系APIは整合性検証のためだけに使われることが多かったのでほとんど見てなかった
- 通過ラインがわからない恐怖から、遅くなる原因追求よりも調子のいいときのスコアアップを優先してしまった
本戦では1位を取るためにスコアアップ優先になるのはある程度しかたありませんが、予選ではトップスコアを取っても通過できなければ意味がありません。来年はもう少し落ち着いて、仕事で負荷対策の調査をするときのようにマズイ点を潰していきたいと思います。
感想
アプリのコードの規模、DBのスキーマの規模ともにISUCONに適したボリュームに抑えつつも、完全オンメモリ化（SELECTを削除し、DBへの書き込みをロック外に追い出しても整合性が担保できる）が難しい複雑なSQLが散りばめられているバランスが素晴らしかったです。いろんなチームがそれぞれの得意なやり方で勝ちを狙えたはずで、本戦にしないのがもったいない、これ以上ないくらいの良問でした。
また、去年の予選でやらかしてしまった原因の「予選で複数台構成」を今年も継承してきたことにも驚きました。参加者視点で見たら、万が一設定をミスってSSHできなくなるような事態になっても試合終了にならない安心感は良いですね。
その複数台構成の活用方法も、去年に比べてずっと自由度が高いのが良かったです。
本当にこれまでで最高のISUCONだったと思います。ありがとうございました。 これが予選なら本戦はどうなるのか、参加できないのが悔しくて仕方ありません。
更新頻度の多いデータのキャッシュ
@methane です。
ISUCON 7 本戦で最大のスコアアップできたポイントが、 status と呼ばれる重い計算の結果となるJSONのキャッシュでした。
近年のISUCONによくある、「更新が成功したら以降のレスポンスにはその更新が反映される必要がある」（以降は「即時反映」と呼びます）タイプの問題だったのですが、今回のように更新頻度の高くかつ即時反映が求められるデータをキャッシュする方法について、より一般的に解説しておきたいと思います。
即時反映が不要な場合
まずは基本として、即時反映が不要な場合のキャッシュ方法からおさらいします。この場合、一番良く使われるのは参照時に計算した結果を Memcached などにキャッシュし、時間で expire する方法です。
このタイプのキャッシュには、参照元が分散している場合（Webサーバーが複数台あるなど）に Thundering Herd という問題がつきものです。参照頻度が非常に高く、かつ並列して行われる場合に、キャッシュが無効化した瞬間に（キャッシュで回避しているはずの）重い処理が並列で実行されてしまうという問題です。
Thundering Herd を避ける方法としては、memcached や MySQL を使って排他制御をするとか、 expire 時間が到達する前にランダムな時間をずらして投機的に再計算するという方法があります。
また、少しサーバー構成を複雑にしていいのであれば、Webサーバー以外でバックグラウンドに処理を実行して、そこで定期的にキャッシュを更新するという方法もあります。
最初のISUCONはブログがお題で、最新のブログコメントの一覧がサイドバーとしていろんなページに表示されていました。このサイドバーを作るケースなどにはバックグラウンド処理が非常に有効なはずです。
即時反映が必要＆更新頻度が低い場合
即時反映が求められる場合は、更新処理の最後（例えばPOSTリクエストに対する処理のうち、MySQLにコミットした後、HTTPレスポンスを返す前）にキャッシュの無効化か更新をしてしまうという手があります。
無効化と更新のどちらがいいかは参照頻度で決まります。参照頻度が更新に比べて十分に高い場合、キャッシュを更新することで Thudering Herd を回避する事ができます。一方で参照頻度が十分高くない場合、一度も参照されないキャッシュを計算するのに時間とメモリを使ってしまう危険もあります。
即時反映が必要＆更新頻度が高い場合
さて、本題です。結果をキャッシュしたい計算の重さに対して、参照頻度も更新頻度も非常に高い場合はどうすれば良いでしょうか？
もちろん、計算回数が更新回数よりも少なくなるようにしなければなりません。更新のたびにキャッシュを無効化したり再計算するのはダメです。
即時反映が不要な場合の方法を振り返ってみると、参照時に（Thundering Herdを避けつつ）計算する方法でも、バックグラウンドで非同期にキャッシュを更新する方法でも、計算頻度は更新頻度に影響されませんでした。キャッシュの再計算が1秒おきなら、その1秒の間に何千回の更新処理が走っていても関係ありません。なので、あとは即時反映の要求を満たすようになにか工夫するだけです。
たとえば、更新のたびに単調増加するバージョン番号のようなもの（MySQLのAUTO INCREMENTなIDなど ）を用意します。参照時に計算をするなら、まず現在のバージョン (v0) を取得してからロックを取得し、ロックを取得できた時点で得られたキャッシュについているバージョンが v0 より新しければそのまま利用する、古ければ再度バージョン (v1) を取得し直して計算し、結果に v1 を付けてキャッシュするという手がとれます。
バックグラウンドで計算するなら、 redis の pubsub などを使って新しいバージョンのキャッシュが作られるのを待つという手も利用できるでしょう。
今回のISUCONでは、同じ status を共有するクライアントを同じプロセスに誘導できるようになっていたので、 Redis や MySQL を使わずにもっと楽に実装することができたはずです。
「まとめて処理」を「待つ」パターン
複数の更新処理に対して1度にまとめて重い処理を実行するという考えかたは、キャッシュに限らず広く有効なものです。例えば「日次バッチ」などと呼ばれる処理は大抵そうでしょう。最近のMySQLは複数のトランザクションのコミットを一度のディスクへの sync でまとめて実行すること（グループコミット） ができます。Fluentdが高いスループットを出せるのも、ある程度の量のイベントをバッファに貯めて一括で転送する設計が寄与していると思います。
そしてこの「まとめて処理」パターンには待ち時間がつきものです。日次バッチならそのバッチが終わるまで結果は見えませんし、トランザクションのコミットはグループコミットを待たされます。 「即時反映が必要でかつ更新頻度が高い」問題でのキャッシュが難しいのは、他のケースのキャッシュではこの「待ち時間」が必要ない、あるいは意識することがないからだと思います。
@tagomoris さんいわく "ISUCON参加前と参加後に最も多くのものを持ち帰った人こそが勝者と言えるでしょう。" (引用元) ということですが、参加チームの方にこの「まとめて処理」を「待つ」パターンを持ち帰って将来何かに役立ててもらえたら幸いです。
ISUCON6 で優勝しました
@methane です。タイトルの通り、 ISUCON でとうとう優勝してきました。
チームメンバーは、(予選と同じく) @kizkoh (インフラ担当), @mecha_g3 (アプリ担当) でした。
私は予選のときはガッツリとアプリを書いていたのですが、本戦では netstat -tn (←老害), top,
dstat -ai, sudo perf top などをみつつ指示をだしたり、方針を決めたり、完全に未経験だった
node.js & react.js 対策をしたりが主な仕事で、あとは序盤のインフラのタスクが大量にあるときに
MySQL を docker から外して基本的なチューニングを入れたり Go を100行程度書いただけです。
結果的には優勝できましたが、メンバーの2人がよく準備し本番でも実力を発揮してくれたのに対して 僕の戦略ミスで中盤から全くスコアを上げられなかったので、最後までヒヤヒヤしていました。
今年の #isucon 予選でisupam触らなくてもスコア伸びたのが、本戦でraactのサーバーサイドレンダリングを真面目に対策しないとスコア伸びない事のフェイントになっていて、見事にハメられた。
— INADA Naoki (@methane) 2016年10月22日
今年の優勝は出題者チームだと思う。
ということで、 nginx や Go でやったことはメンバーの二人が別に記事を書いてくれると思うので、 私の目線で考えたこと、自分でやったことや方針を決めて指示したこと、その考察を書いていきたいと思います。
- インフラ担当の @kizkoh の記事: ISUCON6 にインフラエンジニアとして参加して優勝した!!
- アプリ担当の @mecha_g3 の記事: ISUCON6 優勝しました
お題と初期構成について
お題は、リアルタイムに他人の書いた線が他のユーザーに見えるようなお絵かき掲示板でした。
構成が特徴的で、
- フロントにいるのが通常の Web サーバーではなくて、 react.js を使ったアプリを含む node.js サーバー (以下react)
- そこからリバースプロキシされる形でアプリが存在し、それには各言語の実装がある (以下app)
- app のバックエンドとしては MySQL がいる
- react, app, MySQL がすべて docker になっていて、 docker-compose で動いている
というものでした。
ベンチマーカーは react の Web アプリを想定しているようで、 bundle.js というファイル（react を
全く知りませんが、たぶんサーバーサイドとクライアントサイドで共通なファイル）が1バイトでも変化したら
FAIL していたので、かなり厳密にチェックしていたのだと思います。
Docker は @kizkoh が判るということでしたが、 node.js & react が全く分からないのがとにかくつらい。
「react が判らないと勝てない問題なら多言語用意する意味ないし、きっと簡単にここはボトルネックじゃなくなって、 1本線を引いたらそれを何百人に転送して何百点もバーンと入るような問題だ。それならGoは得意だし、 ネットワークで協力プレイするサーバーをGoで開発してる僕らも得意だ。実力出せば勝てる」と メンバーと自分に言い聞かせてスタートしました。
序盤戦 (~14:00 くらい)
初回ベンチを終え、 @kizkoh が nginx の準備、 @mecha_g3 がアプリ開発＆チューニングの準備を
しているあいだに、フロントの react の server.jsx というファイルと Go アプリのルーティング部分を見て、
フロントに追加する nginx のリバースプロキシ設定 (/api/ は直接 app にリバースプロキシして、それ以外は
react にリバースプロキスするなど) をまとめたり、 @mecha_g3 に room のオンメモリ化を始めるように指示したりしました。
このときはまだ react がボトルネックでなくなるという楽観的な前提だったので、まずは @mecha_g3 に線を書くところとそれを
SSEで配信するところでオンメモリ化を進めてもらいつつ、 react を docker から引きずり出したり、共有していた開発環境に
MySQL をセットアップしてインフラ再構築中でも app の動作確認ができる状況を用意してから、腹をくくって react の
server.jsx というファイルを読み始めました。 (server.jsxのソースコード)
そうすると、下の方で renderString() しているところは、ここからHTMLはブラウザで見たソースがどうやって生成されるのか
全くわからない上に、HTMLの方にはたぶんクライアントとサーバーの整合性を確認するためのものと思われるチェックサムがあって、
何をしたら fail するのか分からないできるだけ触りたくない部分に見えた一方、上の方にはいかにもここをチューニングしてくれ
という雰囲気で /img/:id というパスの処理をしているコードが目に止まりました。ここもどうやってXMLができるのか全くわからない
ものの、レスポンスヘッダを設定しているところから生の svg を生成していることが一目瞭然でした。
/img/:id: の部分は renderString() ではなくて renderToStaticMarkup() という関数を使っていたので、この関数のリファレンスを
探して見てみます。
https://facebook.github.io/react/docs/react-dom-server.html#rendertostaticmarkup
Similar to renderToString, except this doesn't create extra DOM attributes such as data-reactid, that React uses internally. This is useful if you want to use React as a simple static page generator, as stripping away the extra attributes can save lots of bytes.
要するに react の魔術がかかってないプレーンなデータを作るための関数のようです。これは出題者からのヒントだろう。XML生成とか いかにも重そうだし、ここをキャッシュするとか 304 not modified を返せば一気に react は問題にならなくなるんだろう、という希望的予測を立てました。
なお、競技終了後にちょっとディレクトリツリーに目を通してみたら、すぐに components/ というディレクトリ配下にコンポーネント（テンプレート+コード）があって
xml を生成している Canvas というコンポーネントも判りました。このディレクトリを見ていればその後の戦略ももっと変わったかもしれません。
ちょっと検索すれば、同じディレクトリにある Room というコンポーネントで同じ Canvas コンポーネントを利用してるのが判るので、 /img/:id だけ
高速化しても react 全体が軽くはならないだろう、 /room/:id も対策が必要だという前提で進められていたはずです。
緊張状態では知らない技術は10倍怖いし、ベンチマーカーが何をチェックしてるかわからないのも10倍怖くて、計100倍の怖さだもんね。仕方ないね。
中盤戦 (~16:30 くらい)
react から ssl を外してフロントを nginx にするとか docker 外しとか一通り終わったので、 @kizkoh には「やりたいことが残ってるならやってていいけど、
無いならムリに何かしようと頑張るより終盤に向けて休憩取っておいて」という指示を出し、 app が返す json とそれを react が変換してブラウザに返す svg を見比べながら、
その svg を Go の内部のデータ構造から直接生成するような fmt.Printf の塊を作ります。 (ソースコード)
@mecha_g3 のオンメモリ化が終わってからつなぎ込み、svgはあっさりベンチをパス。ただGoに持っていってもsvg生成は結構重い（想定内）ので、 @mecha_g3 にキャッシュを依頼。
その時ちょっと面白がって、 stroke が書かれたときのキャッシュの更新でひと工夫。 svg の更新は stroke の追記オンリーなので、全部再生成するのではなくて、単に追加された
stroke を最後の </svg> タグの手前に挿入するだけにしてもらいました。スコアにどれくらい影響があったのかはわかりませんが、これが簡単にできたのはGoらしい部分でした。
とはいえ、この工夫が強かったのかと言うと、試してみないとわからないものの、svgを静的ファイルに吐き出してnginxで返すことで参照性能上げたほうが、更新性能を上げるよりスコア上がった可能性が大きいと思います。
さらに、可能性としては、react側の /room/:id を弄ることができれば、 react から静的ファイルを読み込んで埋め込むのは簡単だったはずです。
静的ファイルを使う場合分散構成がネックになりますが、同じ部屋へのアクセスが同じサーバーに分散されるような nginx の設定は @kizkoh ならすぐにやってくれたはずです。
終盤戦
序盤に考えていたことは実現できたものの、そのときに妄想していたレベルの性能は全然出ていません。
インフラ側でも問題が色々でていましたし、なにより react のCPU使用率が支配的で app の性能を全く活かせていません。
今から react を調べてハマらずにチューニングするのはバクチ過ぎて、暫定ダントツトップの状態から挑戦するのはナシです。 ここまで1台で動かしてきたのを、MySQL を isu2 に (これは僕の指示でしたが、データセットが初期状態にもどって軽くなる以外は無意味でした…)、 react を isu3-5 で動かす分散構成に移行します。
他にも too many open files とか TIME_WAIT とかが問題になっていたので、 nofiles や tcp_tw_reuse などを設定するように指示しつつ、 react が HTTP keep-alive を頑なに拒否していたのを直していきます。
まず、 nginx -> react のリバースプロキシ部分で全く keep-alive されないのは、 express.js 部分でレスポンスヘッダーを追加するAPIを調べて res.append('Connection', 'keep-alive') を追加したら直りました。
一方 react -> app の方が問題で、ライブラリの依存関係を潜っていった結果、 bitinn/node-fetch の中の次のようなコードを削除するというちょっと強引な方法で解消しました。
// https://github.com/bitinn/node-fetch/blob/master/index.js#L79-L81
if (!headers.has('connection') && !options.agent) {
headers.set('connection', 'close');
}
こういった修正を、再起動試験の合間を縫ってやっていたのですが、終盤はタイムリミットが近づくにつれ何もしなくてもどんどんスコアが下がる状況に陥っていて、 ベストスコアの 85k 点は最後の修正が入ってない状態でした。
考察
終盤にスコアが伸び悩んだ（むしろ落ちた）のが帯域がネックだと予想している点について補足しておきます。 今回使ったインスタンスは2コアの D2v2 で、ベンチマーカーがアクセスするインスタンスは1台のみ、次のグラフは終盤のベンチにおけるその1台の帯域 (bytes/sec) です。
2コアのインスタンスで100MB/secを超えてるのはすごいですね。グラフがガタガタなのは、多分ベンチマーカーが波状攻撃をしかけてきたからだと思います。
次は、各パスへのアクセス数です。集計しているのはベンチマーカーからのアクセスのみで、 react -> app へのアクセスが含まれていません。(これも重要な情報なので、 直接アクセスさせていたのは僕の判断ミスでした)
Request by count 11106 GET /img/* 178 GET / 112 GET /bundle.js 112 GET /css/rc-color-picker.css 112 GET /css/sanitize.css 49 GET /rooms/* 46 POST /api/strokes/rooms/* 41 GET /api/rooms 20 GET /api/stream/rooms/* 3 POST /api/rooms 2 GET //admin/config.php 1 GET /api/rooms/1088
次は、同じくベンチマーカーに返していたレスポンスの、各パスごとの合計／平均バイト数です。
Request by out bytes 2511686449 14110598 GET / 272792736 6653481 GET /api/rooms 266967906 24038 GET /img/* 36283072 323956 GET /bundle.js 9725553 198480 GET /rooms/* 764377 38218 GET /api/stream/rooms/* 340144 3037 GET /css/sanitize.css 303520 2710 GET /css/rc-color-picker.css 184982 4021 POST /api/strokes/rooms/* 75910 75910 GET /api/rooms/1088 1017 339 POST /api/rooms 490 245 GET //admin/config.php
一番帯域を使っている / ですが、これは react から外せていないパスで、この大きいレスポンスが react (別サーバー) -> nginx -> ベンチマーカーに流れているので、 nginx を置いてるマシンの in と out の帯域が同じくらいになっています。
2番めの /api/rooms ですが、これは直接クライアントから呼ばれるのが41回、（多分）/rooms/* を処理している react からアクセスされるのが他に 49 回あるので、
実際に使っている帯域はこの倍以上あったはずで、ここが帯域に引きずられてタイムアウトしやすくなったのがスコアが安定しなかった理由だと思います。
まだ見れてないですが、 / に帯域を減らせるような仕込みがあったのかもしれません。また、それを攻略できなかったとしても、 nginx で全体に ratelimit をかけて
帯域を食うパスを遅くする代わりにそれ以外のパスでタイムアウトになる数を減らすことで、もっとクライアントの並列度を稼いでスコアを取れたかもしれません。
せっかくこれだけの情報を取れていながら、終盤はテンパっていて全然考察できていませんでした。再起動試験中に冷静に最後のもうひと稼ぎを考えないといけませんね。
感想
例年は自分が一番アプリを書ける、かつインフラのチューニングも一番判るという状態で、新卒メンバー2人にタスクを振るという戦い方をしていました。
今年は、 @mecha_g3 を自分と同じくらいアプリが書けると信頼して大まかな方針だけ共有するだけで済んだし、 @kizkoh も僕が全然キャッチアップできていない 近年のミドルウェアを予習してきてくれておまかせできた上に、アプリチューニングが入る前からインフラだけでスコアを伸ばしてくれたおかげで、 手を動かさずに目と頭を使う戦い方ができました。
まだまだ僕の力不足で出題側の想定解法にはたどり着けませんでしたが、3人で強いチームがISUCONで強いチームだということを強く実感でき、 スポコンマンガの登場人物になったかのような快感・達成感を得ることができました。 このチームであと10回くらい勝って賞金で新車のWRXを買いたいです。
終わりになりますが、運営・協賛の各位、特に毎年増え続ける参加者をあたたかみのある運用で運営してくださっている櫛井さんと、 毎年上がり続ける出題レベルのプレッシャーに見事に応える良問と安定ベンチマークシステムを作ってくださった出題チームに感謝いたします。
ISUCON6予選をトップ通過しました
@methane です。「この技術部には問題がある！」というチーム名で @kizkoh (インフラ担当), @mecha_g3 (アプリ担当) とともに ISUCON 6 に参戦し、予選をトップスコアで通過しました。 恒例のふりかえり記事を書きます。
ふりかえり
残念ながらスコアは記録してないのですが、時系列順にやったことをまとめます。 アプリのコードは methane/isu6q-app で公開しているので、興味がある方はコードを確認してください。
strings.Replacer を使う
使用言語は最初から Go と決めていたのですが、Goの初期実装は遅すぎてタイムアウトで最初からスコア無しでした。 top でアプリのCPUが支配的なのはすぐ判りましたし、コードを読めばなにが遅いのかも一発で判りました。そんなに長くないので関数全体を張ります。
func htmlify(w http.ResponseWriter, r *http.Request, content string) string {
if content == "" {
return ""
}
rows, err := db.Query(`
SELECT * FROM entry ORDER BY CHARACTER_LENGTH(keyword) DESC
`)
panicIf(err)
entries := make([]*Entry, 0, 500)
for rows.Next() {
e := Entry{}
err := rows.Scan(&e.ID, &e.AuthorID, &e.Keyword, &e.Description, &e.UpdatedAt, &e.CreatedAt)
panicIf(err)
entries = append(entries, &e)
}
rows.Close()
keywords := make([]string, 0, 500)
for _, entry := range entries {
keywords = append(keywords, regexp.QuoteMeta(entry.Keyword))
}
re := regexp.MustCompile("("+strings.Join(keywords, "|")+")")
kw2sha := make(map[string]string)
content = re.ReplaceAllStringFunc(content, func(kw string) string {
kw2sha[kw] = "isuda_" + fmt.Sprintf("%x", sha1.Sum([]byte(kw)))
return kw2sha[kw]
})
content = html.EscapeString(content)
for kw, hash := range kw2sha {
u, err := r.URL.Parse(baseUrl.String()+"/keyword/" + pathURIEscape(kw))
panicIf(err)
link := fmt.Sprintf("<a href=\"%s\">%s</a>", u, html.EscapeString(kw))
content = strings.Replace(content, hash, link, -1)
}
return strings.Replace(content, "\n", "<br />\n", -1)
}
今回の問題ははてなキーワード＋はてなスターのようなサービスで、この関数はキーワードの紹介記事に対して他のキーワードへのリンクを生成しつつHTMLエスケープするものです。キーワードは文字数順でソートしているので、最長一致でリンクになります。
キーワードからリンクへの変換が一発でされていないのは、先に変換するとHTMLエスケープで <a> タグまでエスケープされてしまうし、逆に先にHTMLエスケープをするとキーワードを見つけられなくなるからです。（一度これに気づかず一気に変換するようにしてハマりました）
正規表現のビルドと置換のどちらがどれくらいの割合で重いのかまではまだプロファイルを始めてなかったのでわかりませんが、初手からGoらしい最適化を始めてみます。
まずGoの正規表現は遅いので strings.Replacer を使ってキーワードからリンクへの変換をします。 Replacer を構築するのにも時間がかかるので、 htmlify() という関数で毎回構築するのではなく、起動時と、キーワードの追加削除時に再構築をするようにします。（実際にはすでに存在するキーワードの記事に対する修正のケースを見逃していて無駄に再構築していました。これに気づいていたらもっとスコア上がったはず…）
var (
mKwControl sync.Mutex
kwdList KeywordArray
mKwReplacer sync.RWMutex
kwReplacer1st, kwReplacer2nd *strings.Replacer
)
func updateReplacer() {
reps1 := make([]string, 0, len(kwdList)*2)
reps2 := make([]string, 0, len(kwdList)*2)
for i, k := range kwdList {
if k.holder == "" {
k.holder = fmt.Sprintf("isuda_%x", sha1.Sum([]byte(k.Key)))
kwdList[i].holder = k.holder
}
reps1 = append(reps1, k.Key)
reps1 = append(reps1, k.holder)
reps2 = append(reps2, k.holder)
reps2 = append(reps2, k.Link)
}
r1 := strings.NewReplacer(reps1...)
r2 := strings.NewReplacer(reps2...)
mKwReplacer.Lock()
kwReplacer1st = r1
kwReplacer2nd = r2
mKwReplacer.Unlock()
}
func AddKeyword(key, link string) {
k := Keyword{Key: key, Link: link}
mKwControl.Lock()
kwdList = append(kwdList, k)
sort.Sort(kwdList)
updateReplacer()
mKwControl.Unlock()
}
func ReplaceKeyword(c string) string {
mKwReplacer.RLock()
r1 := kwReplacer1st
r2 := kwReplacer2nd
mKwReplacer.RUnlock()
x := r1.Replace(c)
x = html.EscapeString(x)
return r2.Replace(x)
}
AddKeyword はキーワードをポストしたときに、 ReplaceKeyword は htmlify から呼ばれます。これで NewReplacer を呼び出す回数を大幅に削減することができました。
この変更を投入するタイミングで、 MySQL に接続するときに '127.0.0.1' からの接続が許可されていないというエラーがでるようになって（何もしてないのに壊れた追記: 秘伝のタレでskip-name-resolveが入ったのが原因の模様） Unix Domain Socket を使うようにしました。
@kizkoh による nginx や MySQL の設定 (静的ファイルを nginx で返す等) や、初期実装にあったバグを潰したりして、14:00すぎに12万点を出しました。
isutar を isuda にマージ
これは @mecha_g3 に任せた部分です。 isutar と isuda がお互いにJSON APIを使ってやり取りをしている部分があって、2つのアプリとMySQLが1台のマシンに乗っている以上完全に無駄なので全部1つにまとめました。スコアを記録してないのですが順当に性能アップしたはずです。
これを投入してベンチをかけるときにハマったのが、DBコネクションのデッドロックです。もともと2コアの1台のマシンなので、DBへの接続は4本も要らないだろうと思いつつ、念のために8本にしていました。ところが、次のようなコードが原因で8本あっても足りなくなってしまいました。
rows, err := db.Query(fmt.Sprintf(
"SELECT * FROM entry ORDER BY updated_at DESC LIMIT %d OFFSET %d",
perPage, perPage*(page-1),
))
if err != nil && err != sql.ErrNoRows {
panicIf(err)
}
entries := make([]*Entry, 0, 10)
for rows.Next() {
e := Entry{}
err := rows.Scan(&e.ID, &e.AuthorID, &e.Keyword, &e.Description, &e.UpdatedAt, &e.CreatedAt)
panicIf(err)
e.Html = htmlify(w, r, e.Description)
e.Stars = loadStars(e.Keyword)
entries = append(entries, &e)
}
rows.Close()
このコードはトップページのハンドラーの一部です。 for rows.Next() ループが終了して rows.Close() が呼ばれるまでDBの接続を握るのですが、このループ中の loadStars(e.Keyword) の部分が中でさらにSQLを呼び出しています。
この状態で、 top ページに8個並列でアクセスが来てループの外側のクエリを実行すると、8本の接続を使い切った状態になり、どの goroutine も内側の loadStars() でDB接続を無限に待ってしまうことになります。
落ち着いて考えればすごく当たり前のことなのですが、最初は rows.Close() を呼んでない場所がどこかにあるんじゃないかと探し回ったり、この形のネストがまずいことに気づいたときも「でも1goroutineあたりのDB接続数が2倍になるだけだから、その程度の余裕は見込んで8本にしたんだけどなあ。」と考えてしまったりしてしまいました。
結果、この問題の対策もちゃんとネストを潰すのではなく、単にコネクションプールの数を倍の16に増やしただけです。ベンチマーカーがどんどん並列度上げてくるタイプだったらこれでも死んでました。
教訓として、 rows.Next() ループ内でネストしてクエリを実行するのは単に必要な接続数が倍になる以上の凶悪さを持っているので、 rows.Close() までの処理は単純にクエリ結果のフェッチだけにしましょう。
Replacer の構築を zero time cache 化
プロファイルを取ってみたところまだ Replacer の構築が重いので、個人的に zero time cache と呼んでいるイディオムを使って安全にキャッシュをしてみます。次のコードを見てください。
var (
mKwControl sync.Mutex
kwdList KeywordArray
mUpdateReplacer sync.Mutex
repLastUpdated time.Time
)
func AddKeyword(key, link string) {
k := Keyword{Key: key, Link: link}
mKwControl.Lock()
kwdList = append(kwdList, k)
mKwControl.Unlock()
updateReplacer()
}
func updateReplacer() {
now := time.Now()
mUpdateReplacer.Lock()
defer mUpdateReplacer.Unlock()
if repLastUpdated.After(now) {
return
}
repLastUpdated = time.Now()
reps1 := make([]string, 0, len(kwdList)*2)
reps2 := make([]string, 0, len(kwdList)*2)
mKwControl.Lock()
kws := kwdList[:]
mKwControl.Unlock()
sort.Sort(kws)
// ... 以降 Replacer の構築処理
}
mUpdateReplacer と repLastUpdated が追加した変数で、 updateReplacer() の repLastUpdated = time.Now() までがイディオムになっています。
例えば、キーワードA, B, C がほぼ同時に追加されたとします。
- まずAが最初にロックを取得して、
repLastUpdated = time.Now()を実行して Replacer の構築を始めます。 - 続いてキーワードBとCがともに
mUpdateReplacer.Lock()で停止します。ロック直前に取得したnowは (1) で更新したrepLastUpdatedよりも未来の時間になります。 - キーワードAの Replacer 更新が終了し、
mUpdateReplacerが開放されます。キーワードBを処理していた goroutine がそのロックを取得します。 - ロック取得前に取得した
nowがrepLastUpdatedよりも新しいので、if repLastUpdated.After(now)が真になりません。なので Replacer を再構築します。キーワードAを更新したときのkwdListにキーワードBは入っていなかった（厳密にはタイミング依存で入っていた可能性もある）ので、これは必要な処理です。 - さらにキーワードBの Replacer 更新が終わり、キーワードCが
mUpdateReplacerのロックを取得します。今度はif repLastUpdated.After(now)が真になるので、 Replacer の再構築はスキップされます。 (4) で Replacer を再構築したときには確実にキーワードCもkwdListに入っていたので、スキップしても安全です。
この説明を一度読んだだけでは理解できないかもしれませんが、ぜひじっくりとコードと見比べて理解してみてください。 このイディオムはISUCONだけではなく、実際にGoで高性能なサーバーを書くときに大変便利です。
また、例えば MySQL が複数のトランザクションを一度の fsync でコミットするグループコミットなど、「同時に実行される重い処理をバッチ化する」というのは並列処理のデザインパターンと呼んでも良いくらい汎用的だと思うのですが、どなたかこのパターンの名前をご存知でしたら @methane 宛の Tweet などで教えてください。
仕上げ
まだ top ページのハンドラーが重かったので、再び zero time cache パターンを使ってさらにトップページの内容の取得を効率化します。
ただしこのときは効率より実装の手早さを優先して、 zero time cache パターンをトップページのハンドラ内に直接実装してしまいました。着実には性能向上しましたが、これもキーワードの更新側に処理を持っていけばもっと劇的な性能向上が見込めたはずです。
最後に、アプリの環境変数で GOGC=400 を設定し、プロファイルやモニタリングやnginxのアクセスログを切り、ベストスコアを出すまで enqueue を数回実行して終了しました。
考察
POST /keyword のアクセスがキーワードの追加だけではなく更新にも使われていることを見逃していて、一番重い Replacer の再構築を必要以上に実行してしまっていたのが悔やまれます。
また、上に書いたようにトップページの内容の更新も、 GET / ではなく POST /keyword で行えばもっと劇的なスコアアップができたでしょう。
さらに、非ログインユーザーのトップページを静的ファイルに書き出してしまって nginx に直接返させるのも、ISUCONで頻出の攻略法で事前に判っていたはずで、実装する時間もあったはずなのにやるタイミングを逸してしまいました。
これらを全部できていれば、ベンチマーカーの実装次第ですが、倍の50万点の可能性もあったかもしれません。
感想
今までは毎年予選は一人で戦って勝ち抜いてきたのですが、去年の予選のボリュームが本戦と同じくらいあってキツかったので、今年は予選からチームで戦うことにしました。
「直したはずのバグがこっちのブランチでは直ってなかった」「プロファイルが違う場所のバイナリ／ソースを参照してたかもしれなくてくてアテにならない」系のトラブルはあったものの、自分がアプリを書くときに心配事を忘れて集中できたり、逆に実装を任せてる間に自分は休憩したり落ち着いて見直しをしたりできて、精神的な負荷が大幅に減り、余裕を持って優雅に戦えたと思います。
一方で、Azureに慣れていなかったことや、14時過ぎに取った初めての0点以外のスコアがその時点の断トツトップで、そこからもほぼずっと2位のダブルスコアをキープしていたこともあって、保守的になりすぎて全力を出し切れたとは言い難いです。
本戦では全力を出せるように、もう少しチームワーク練習や環境構築の練習を重ねて行きます。
それでは、決勝進出者のみなさん、決勝でお会いしましょう。 運営・出題者のみなさんはお疲れ様でした。決勝も引き続きお願いいたします。
pixiv private isucon 2016 Python 版実装を用意しました
今年の ISUCON でも Python 実装が提供されることが 発表されました。
Python での練習は過去の予選問題でも可能ですが、今年の出題チームが準備した問題で 練習できるように Python 版の実装を用意しました。とりあえずベンチマーカーが完走する ところまでは確認してあります。
用意したのはアプリの実装だけなので、これを使って練習する際は
pixiv さんが公開されている AMI
の webapp ディレクトリ配下に python という名前で git clone し、
systemd などの設定は練習の一環として自前で行ってください。
また時間があるときに自分でチューニングしてみて、ミドルウェアの選定や ツール・テクニックなどを公開したいと思います。
@methane
pixiv private isucon 2016 攻略 (5/5)
攻略記事一覧:
ボトルネック探し
前回は一番重かったトップページにページキャッシュを導入して劇的に高速化したものの、CPU以外がボトルネックになって大した高速化はできませんでした。 こういう場合は dstat が役に立つことが多いです。
----total-cpu-usage---- -dsk/total- -net/total- ---paging-- ---system-- usr sys idl wai hiq siq| read writ| recv send| in out | int csw 2 0 98 0 0 0| 596k 271k| 0 0 | 0 0 | 606 755 1 0 100 0 0 0| 0 0 | 192B 1190B| 0 0 | 119 177 0 0 100 0 0 0| 0 0 | 66B 350B| 0 0 | 103 158 1 0 98 1 0 0| 512k 0 | 537B 783B| 0 0 | 962 1035 48 7 38 3 0 5| 16M 728k|4590k 60M| 0 0 | 24k 20k 44 7 36 5 0 8| 11M 376k|6568k 71M| 0 0 | 34k 26k 44 11 35 4 0 7| 18M 312k|6190k 71M| 0 0 | 33k 27k 48 8 33 3 0 8| 14M 272k|7784k 71M| 0 0 | 31k 24k 41 7 42 4 0 6| 17M 352k|8097k 72M| 0 0 | 31k 23k 44 9 38 4 1 5| 14M 256k|8019k 71M| 0 0 | 33k 25k 44 10 35 3 0 8| 10M 448k|7705k 71M| 0 0 | 32k 25k 36 9 46 3 0 6| 14M 224k|7196k 71M| 0 0 | 32k 22k 38 10 39 6 0 7| 16M 18M|7812k 71M| 0 0 | 31k 22k 47 9 28 11 0 4| 20M 47M|6683k 72M| 0 0 | 29k 19k 45 7 39 3 0 6| 10M 696k|6113k 71M| 0 0 | 33k 24k 42 7 39 4 0 8| 12M 672k|3825k 71M| 0 0 | 33k 24k 51 8 31 3 0 6| 13M 512k|6750k 71M| 0 0 | 31k 22k 44 9 39 2 0 5|5496k 648k|8045k 71M| 0 0 | 32k 24k 53 9 28 3 0 6| 20M 544k|5832k 71M| 0 0 | 29k 20k 41 7 42 3 0 7| 14M 616k|7459k 71M| 0 0 | 35k 24k 48 9 31 4 0 8| 17M 608k|5869k 71M| 0 0 | 30k 23k 38 11 40 3 0 8| 14M 752k|8956k 71M| 0 0 | 32k 24k 44 11 36 4 0 5| 13M 576k|7181k 71M| 0 0 | 33k 25k 47 7 35 7 0 5| 14M 62M|5753k 65M| 0 0 | 30k 22k ...
net の send が 71M で張り付いてるのが目につきますね。アプリサーバーは c4.large なのでこんなもんでしょう。
ですが、 pixiv さんの Blog 記事 のスクリーンショットを見ると、多くのチームが 40k 点を超えていて、トップチームは180k点に到達しています。こっちは40k点の手前で帯域の壁にぶつかってるのに、変だぞ？ (Twitter で pixiv の @catatsuy さんに、ポータルのスコアとコマンドラインによるベンチマーカーのスコアが同一であることを確認しました。)
さて、2つ目の記事で、次のように言っていましたね。
帯域は /image/ が支配的。帯域ネックになるようだったら、画像は再圧縮しにくいので、ヘッダーを適切に設定すればクライアントに "304 Not Modified" を返せるようになって大きなブレークスルーがあるかもしれない。
試しにクライアントのキャッシュ実装に影響を与えそうなヘッダーを追加してみましょう。 "nginx 静的ファイル キャッシュ" でググってそれっぽいのを探します
upstream app {
server 127.0.0.1:8080;
keepalive 64;
}
server {
listen 80;
client_max_body_size 10m;
root /home/isucon/private_isu/webapp/public/;
location / {
try_files $uri @app;
}
location ~* \.(?:ico|css|js|gif|jpe?g|png)$ {
try_files $uri @app;
expires max;
add_header Pragma public;
add_header Cache-Control "public, must-revalidate, proxy-revalidate";
etag off;
}
location @app {
proxy_set_header Host $host;
proxy_set_header X-Real-IP $remote_addr;
proxy_set_header X-Forwarded-For $proxy_add_x_forwarded_for;
proxy_pass http://app;
}
}
計測してみます。
スコア:
{"pass":true,"score":182435,"success":174747,"fail":0,"messages":[]}
pixiv 社内 isucon のトップと同じくらいのスコアがでました。(これはプロファイルを取ったりいろいろしながらのスコアなので、仕上げしたらもう少し伸びるはずです)
top, dstat:
Tasks: 81 total, 3 running, 78 sleeping, 0 stopped, 0 zombie %Cpu(s): 80.7 us, 11.5 sy, 0.0 ni, 3.0 id, 0.5 wa, 0.0 hi, 4.2 si, 0.0 st KiB Mem: 1022972 total, 954144 used, 68828 free, 25432 buffers KiB Swap: 0 total, 0 used, 0 free. 557948 cached Mem PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND 1397 isucon 20 0 377096 97572 8880 S 100.5 9.5 0:27.35 app.dc4a3eaa 731 mysql 20 0 1059292 183956 10552 S 65.9 18.0 2:26.08 mysqld 1396 www-data 20 0 92088 5304 3144 R 18.6 0.5 0:04.99 nginx 1069 isucon 20 0 33140 10476 2636 S 5.7 1.0 0:12.10 tmux 308 memcache 20 0 334624 9744 2228 S 0.7 1.0 0:01.38 memcached 110 root 20 0 0 0 0 S 0.3 0.0 0:00.08 jbd2/xvda2-8 1034 root 20 0 0 0 0 S 0.3 0.0 0:02.89 kworker/1:0
----total-cpu-usage---- -dsk/total- -net/total- ---paging-- ---system-- usr sys idl wai hiq siq| read writ| recv send| in out | int csw 0 0 100 0 0 0| 0 0 | 0 0 | 0 0 | 45 76 21 5 71 2 0 1| 11M 0 |1987k 12M| 0 0 |8731 9184 73 15 5 2 0 5| 17M 904k|4574k 25M| 0 0 | 19k 20k 78 13 3 1 0 6| 20M 272k|3815k 18M| 0 0 | 15k 17k 80 9 6 2 0 4| 25M 272k|7221k 20M| 0 0 | 16k 17k 81 11 4 1 0 4| 18M 272k|5953k 20M| 0 0 | 15k 16k 81 10 4 0 0 5| 24M 256k|5363k 24M| 0 0 | 15k 17k 76 13 6 2 0 4| 20M 272k|8293k 18M| 0 0 | 16k 17k 82 11 2 1 0 5| 15M 552k|2665k 18M| 0 0 | 16k 16k 80 14 3 1 0 4| 14M 408k|2870k 15M| 0 0 | 15k 16k 79 12 5 1 0 4| 16M 360k|5475k 19M| 0 0 | 17k 18k 79 11 5 2 0 3| 16M 65M|5456k 21M| 0 0 | 15k 16k 77 12 6 1 0 4| 19M 760k|6763k 23M| 0 0 | 19k 20k 79 12 4 2 0 4| 23M 592k|6824k 19M| 0 0 | 16k 17k 79 12 5 2 0 3| 11M 632k|5994k 20M| 0 0 | 16k 18k 82 11 3 1 0 4| 11M 680k|3447k 16M| 0 0 | 15k 17k 83 11 2 0 0 4| 13M 792k|5076k 18M| 0 0 | 16k 18k ...
CPUを使い切るようになったのが判ります。
access.log 集計:
Request by count 117444 GET /image/* 7987 GET / 6394 GET /js/jquery-2.2.0.js 6394 GET /css/style.css 6394 GET /js/jquery.timeago.ja.js 6394 GET /favicon.ico 6394 GET /js/jquery.timeago.js 6394 GET /js/main.js 4028 POST /login 1459 GET /login 1176 GET /posts/* 959 POST /register 958 GET /admin/banned 873 GET /@user 731 GET /logout 609 POST / 330 GET /posts?max_created_at= 268 POST /comment 1 GET /initialize Request by total time 98.996 0.299987878788 GET /posts?max_created_at= 84.66 0.0105997245524 GET / 84.077 0.0963081328751 GET /@user 52.172 0.0129523336643 POST /login 39.666 0.0337295918367 GET /posts/* 33.621 0.0552068965517 POST / 19.801 0.0738843283582 POST /comment 17.144 0.0117505140507 GET /login ... Request by out bytes 894159053 7613 GET /image/* 185613643 23239 GET / 16456443 18850 GET /@user 11202870 33948 GET /posts?max_created_at= 4098331 3484 GET /posts/* ...
image の転送量が大幅に減ったことが確認できます。また、集計せずに access.log を見ると、狙い通り 304 を返せていることが判ります。
(余談) 壁の超え方
2つ目の記事で 304 Not Modified を返せることを予想していたのは、エスパーでもなんでもありません。一昨年 (2014年) の決勝であったんです。その時はこの壁を超えられず悔しい思いをしました。
その時、壁を超えたチームが2チームありました。準優勝チームは静的ファイルを返すための nginx の設定のテンプレ（いわゆる「秘伝のタレ」）を使ったらいきなりスコアが上がったけど何が起こったのか設定した本人にも分からなかった、そして優勝チームは順優勝チームのスコアを見て「必ず壁を超える方法があるはずだ」と試行錯誤した結果壁を超えたと記憶しています。（興味がある方は当時の blog 記事を探してみてください）
「秘伝のタレ」が偶然ハマる、という壁の超え方は準備の賜物です。 個人的にはチューニングするときはパラメーターを1つ1ついじって効果確認したいところですが、それだと時間がもったいないし、ベンチマーカーの挙動についての予想が当てられないと壁が超えられないので、やはり「秘伝のタレ」は強力な武器になります。
一方、ベンチマーカーの動作を予想し試行錯誤するやり方は、問題作成側の心理を読む ISUCON 力、可能性のある試行錯誤をするための引き出し(今回でいえば HTTP ヘッダーとキャッシュに関する知識)、精神力などが求められます。 過去に決勝で優勝したチームはどれもこの能力が特に優れていたチームだと思います。難しいですが優勝を目指して勉強と鍛錬をしましょう。
雑巾絞り
CPUネックになったことですし、CPUプロファイルを見てみましょう。
(pprof) top30 -cum
7.63s of 29.87s total (25.54%)
Dropped 601 nodes (cum <= 0.15s)
Showing top 30 nodes out of 296 (cum >= 4.36s)
flat flat% sum% cum cum%
0 0% 0% 28.68s 96.02% runtime.goexit
0 0% 0% 24.58s 82.29% net/http.(*conn).serve
0 0% 0% 23.35s 78.17% net/http.(*ServeMux).ServeHTTP
0 0% 0% 23.35s 78.17% net/http.serverHandler.ServeHTTP
0 0% 0% 23.32s 78.07% github.com/zenazn/goji/web.(*Mux).ServeHTTP
0 0% 0% 23.30s 78.00% github.com/zenazn/goji/web.(*cStack).ServeHTTP
0 0% 0% 23.30s 78.00% github.com/zenazn/goji/web/middleware.RequestID.func1
0 0% 0% 23.30s 78.00% net/http.HandlerFunc.ServeHTTP
0 0% 0% 23.25s 77.84% github.com/zenazn/goji/web/middleware.Logger.func1
0 0% 0% 22.71s 76.03% github.com/zenazn/goji/web.(*mStack).newStack.func1
0.01s 0.033% 0.033% 22.71s 76.03% github.com/zenazn/goji/web.(*router).route
0 0% 0.033% 22.71s 76.03% github.com/zenazn/goji/web/middleware.AutomaticOptions.func1
0 0% 0.033% 22.71s 76.03% github.com/zenazn/goji/web/middleware.Recoverer.func1
0.01s 0.033% 0.067% 18.11s 60.63% github.com/zenazn/goji/web.netHTTPHandlerFuncWrap.ServeHTTPC
0 0% 0.067% 12.85s 43.02% main.getPosts
0 0% 0.067% 12.46s 41.71% github.com/jmoiron/sqlx.(*DB).Select
0 0% 0.067% 12.46s 41.71% github.com/jmoiron/sqlx.Select
0.07s 0.23% 0.3% 11.69s 39.14% github.com/jmoiron/sqlx.scanAll
1.72s 5.76% 6.06% 9.78s 32.74% runtime.mallocgc
0.16s 0.54% 6.60% 8.62s 28.86% runtime.systemstack
5.02s 16.81% 23.40% 7.29s 24.41% runtime.scanobject
0.15s 0.5% 23.90% 5.91s 19.79% runtime.newobject
0 0% 23.90% 5.33s 17.84% runtime.gcAssistAlloc
0 0% 23.90% 5.33s 17.84% runtime.gcAssistAlloc.func1
0.04s 0.13% 24.04% 5.33s 17.84% runtime.gcDrainN
0.04s 0.13% 24.17% 5.22s 17.48% database/sql.(*Rows).Next
0.03s 0.1% 24.27% 5.04s 16.87% github.com/go-sql-driver/mysql.(*textRows).Next
0.34s 1.14% 25.41% 5.01s 16.77% github.com/go-sql-driver/mysql.(*textRows).readRow
0 0% 25.41% 4.55s 15.23% github.com/zenazn/goji/web.handlerFuncWrap.ServeHTTPC
0.04s 0.13% 25.54% 4.36s 14.60% main.makePosts
(pprof) list getPosts
Total: 29.87s
ROUTINE ======================== main.getPosts in /home/isucon/private_isu/webapp/golang/app.go
0 12.85s (flat, cum) 43.02% of Total
. . 593: fmt.Println(terr)
. . 594: return
. . 595: }
. . 596:
. . 597: results := []Post{}
. 11.19s 598: rerr := db.Select(&results, "SELECT `id`, `user_id`, `body`, `mime`, `created_at` FROM `posts` WHERE `created_at` <= ? ORDER BY `created_at` DESC", t.Format(ISO8601_FORMAT
))
. . 599: if rerr != nil {
. . 600: fmt.Println(rerr)
. . 601: return
. . 602: }
. . 603:
. 1.03s 604: posts, merr := makePosts(results, getCSRFToken(r), false)
. . 605: if merr != nil {
. . 606: fmt.Println(merr)
. . 607: return
. . 608: }
. . 609:
. . 610: if len(posts) == 0 {
. . 611: w.WriteHeader(http.StatusNotFound)
. . 612: return
. . 613: }
. . 614:
. . 615: fmap := template.FuncMap{
. . 616: "imageURL": imageURL,
. . 617: }
. . 618:
. . 619: template.Must(template.New("posts.html").Funcs(fmap).ParseFiles(
. 10ms 620: getTemplPath("posts.html"),
. . 621: getTemplPath("post.html"),
. 620ms 622: )).Execute(w, posts)
. . 623:}
. . 624:
. . 625:func getPostsID(c web.C, w http.ResponseWriter, r *http.Request) {
. . 626: pid, err := strconv.Atoi(c.URLParams["id"])
. . 627: if err != nil {
(pprof) list makePosts
Total: 29.87s
ROUTINE ======================== main.makePosts in /home/isucon/private_isu/webapp/golang/app.go
40ms 4.36s (flat, cum) 14.60% of Total
. . 188:}
. . 189:
. . 190:func makePosts(results []Post, CSRFToken string, allComments bool) ([]Post, error) {
. . 191: var posts []Post
. . 192:
. 20ms 193: for _, p := range results {
. 720ms 194: err := db.Get(&p.CommentCount, "SELECT COUNT(*) AS `count` FROM `comments` WHERE `post_id` = ?", p.ID)
. . 195: if err != nil {
. . 196: return nil, err
. . 197: }
. . 198:
. . 199: query := "SELECT * FROM `comments` WHERE `post_id` = ? ORDER BY `created_at` DESC"
. . 200: if !allComments {
. . 201: query += " LIMIT 3"
. . 202: }
. . 203: var comments []Comment
. 920ms 204: cerr := db.Select(&comments, query, p.ID)
. . 205: if cerr != nil {
. . 206: return nil, cerr
. . 207: }
. . 208:
. . 209: for i := 0; i < len(comments); i++ {
20ms 1.89s 210: uerr := db.Get(&comments[i].User, "SELECT * FROM `users` WHERE `id` = ?", comments[i].UserID)
. . 211: if uerr != nil {
. . 212: return nil, uerr
. . 213: }
. . 214: }
. . 215:
. . 216: // reverse
. . 217: for i, j := 0, len(comments)-1; i < j; i, j = i+1, j-1 {
. . 218: comments[i], comments[j] = comments[j], comments[i]
. . 219: }
. . 220:
. . 221: p.Comments = comments
. . 222:
20ms 780ms 223: perr := db.Get(&p.User, "SELECT * FROM `users` WHERE `id` = ?", p.UserID)
. . 224: if perr != nil {
. . 225: return nil, perr
. . 226: }
. . 227:
. . 228: p.CSRFToken = CSRFToken
. . 229:
. . 230: if p.User.DelFlg == 0 {
. 30ms 231: posts = append(posts, p)
. . 232: }
. . 233: if len(posts) >= postsPerPage {
. . 234: break
. . 235: }
. . 236: }
getPosts が重いのは、前に getIndex が重いのを直した時と同じく、 LIMIT すれば良さそうですね。
makePosts もクエリを投げすぎているので、 Post の取得とその User の取得は INNER JOIN で一気にする、コメント一覧はメモリ上にキャッシュしてしまうことにします。
あとテンプレートのコンパイルも事前にするようにしていきます。 Go アプリ側で出力しているログも tmux や ssh の CPU を食ってるのでそろそろ止めてしまいましょう。 (nginx のログを止めるのは一番最後です)
diff --git a/app.go b/app.go
index f246ad6..eca8413 100644
--- a/app.go
+++ b/app.go
@@ -187,54 +184,78 @@ func getFlash(w http.ResponseWriter, r *http.Request, key string) string {
}
}
-func makePosts(results []Post, CSRFToken string, allComments bool) ([]Post, error) {
- var posts []Post
+var (
+ commentM sync.Mutex
+ commentStore map[int][]Comment = make(map[int][]Comment)
+)
- for _, p := range results {
- err := db.Get(&p.CommentCount, "SELECT COUNT(*) AS `count` FROM `comments` WHERE `post_id` = ?", p.ID)
+func getCommentsLocked(postID int) []Comment {
+ if cs, ok := commentStore[postID]; ok {
+ return cs
+ }
+
+ var cs []Comment
+ query := ("SELECT comments.id, comments.comment, comments.created_at, users.id, users.account_name " +
+ " FROM `comments` INNER JOIN users ON comments.user_id = users.id " +
+ " WHERE `post_id` = ? ORDER BY comments.`created_at`")
+
+ rows, err := db.Query(query, postID)
+ if err != nil {
+ log.Println(err)
+ return cs
+ }
+ for rows.Next() {
+ var c Comment
+ err := rows.Scan(&c.ID, &c.Comment, &c.CreatedAt, &c.User.ID, &c.User.AccountName)
if err != nil {
- return nil, err
+ log.Println(err)
+ continue
}
+ cs = append(cs, c)
+ }
+ rows.Close()
- query := "SELECT * FROM `comments` WHERE `post_id` = ? ORDER BY `created_at` DESC"
- if !allComments {
- query += " LIMIT 3"
- }
- var comments []Comment
- cerr := db.Select(&comments, query, p.ID)
- if cerr != nil {
- return nil, cerr
- }
+ commentStore[postID] = cs
+ return cs
+}
- for i := 0; i < len(comments); i++ {
- uerr := db.Get(&comments[i].User, "SELECT * FROM `users` WHERE `id` = ?", comments[i].UserID)
- if uerr != nil {
- return nil, uerr
- }
- }
+func getComments(postID int) []Comment {
+ commentM.Lock()
+ defer commentM.Unlock()
+ return getCommentsLocked(postID)
+}
- // reverse
- for i, j := 0, len(comments)-1; i < j; i, j = i+1, j-1 {
- comments[i], comments[j] = comments[j], comments[i]
- }
+func appendComent(c Comment) {
+ commentM.Lock()
+ cs := getCommentsLocked(c.PostID)
+ commentStore[c.PostID] = append(cs, c)
+ commentM.Unlock()
+}
+
+func makePosts(results []Post, CSRFToken string, allComments bool) ([]Post, error) {
+ var posts []Post
+ for _, p := range results {
+ comments := getComments(p.ID)
+ if !allComments && len(comments) > 3 {
+ comments = comments[len(comments)-3:]
+ }
p.Comments = comments
+ p.CSRFToken = CSRFToken
perr := db.Get(&p.User, "SELECT * FROM `users` WHERE `id` = ?", p.UserID)
if perr != nil {
return nil, perr
}
- p.CSRFToken = CSRFToken
-
- if p.User.DelFlg == 0 {
- posts = append(posts, p)
+ if p.User.DelFlg != 0 {
+ continue
}
+ posts = append(posts, p)
if len(posts) >= postsPerPage {
break
}
}
-
return posts, nil
}
@@ -411,8 +432,9 @@ func getLogout(w http.ResponseWriter, r *http.Request) {
}
var (
- indexTemplate *template.Template
- postsTemplate *template.Template
+ indexTemplate *template.Template
+ postsTemplate *template.Template
+ accountNameTempalte *template.Template
indexPostsM sync.Mutex
indexPostsT time.Time
@@ -434,6 +456,13 @@ func init() {
getTemplPath("posts.html"),
getTemplPath("post.html"),
))
+
+ accountNameTempalte = template.Must(template.New("layout.html").Funcs(fmap).ParseFiles(
+ getTemplPath("layout.html"),
+ getTemplPath("user.html"),
+ getTemplPath("posts.html"),
+ getTemplPath("post.html"),
+ ))
}
func renderIndexPosts() {
@@ -506,7 +535,6 @@ func getAccountName(c web.C, w http.ResponseWriter, r *http.Request) {
}
results := []Post{}
-
rerr := db.Select(&results, "SELECT `id`, `user_id`, `body`, `mime`, `created_at` FROM `posts` WHERE `user_id` = ? ORDER BY `created_at` DESC", user.ID)
if rerr != nil {
fmt.Println(rerr)
@@ -527,12 +555,10 @@ func getAccountName(c web.C, w http.ResponseWriter, r *http.Request) {
}
postIDs := []int{}
- perr := db.Select(&postIDs, "SELECT `id` FROM `posts` WHERE `user_id` = ?", user.ID)
- if perr != nil {
- fmt.Println(perr)
- return
+ for _, r := range results {
+ postIDs = append(postIDs, r.ID)
}
- postCount := len(postIDs)
+ postCount := len(results)
commentedCount := 0
if postCount > 0 {
@@ -557,16 +583,7 @@ func getAccountName(c web.C, w http.ResponseWriter, r *http.Request) {
me := getSessionUser(r)
- fmap := template.FuncMap{
- "imageURL": imageURL,
- }
-
- template.Must(template.New("layout.html").Funcs(fmap).ParseFiles(
- getTemplPath("layout.html"),
- getTemplPath("user.html"),
- getTemplPath("posts.html"),
- getTemplPath("post.html"),
- )).Execute(w, struct {
+ accountNameTempalte.Execute(w, struct {
Posts []Post
User User
PostCount int
@@ -595,7 +612,7 @@ func getPosts(w http.ResponseWriter, r *http.Request) {
}
results := []Post{}
- rerr := db.Select(&results, "SELECT `id`, `user_id`, `body`, `mime`, `created_at` FROM `posts` WHERE `created_at` <= ? ORDER BY `created_at` DESC", t.Format(ISO8601_FORMAT))
+ rerr := db.Select(&results, "SELECT posts.`id`, `user_id`, `body`, `mime`, posts.`created_at` FROM `posts` INNER JOIN `users` ON posts.user_id=users.id WHERE users.del_flg = 0 AND posts.`created_at` <= ? ORDER BY `created_at` DESC LIMIT 20", t.Format(ISO8601_FORMAT))
if rerr != nil {
fmt.Println(rerr)
return
@@ -806,9 +823,24 @@ func postComment(w http.ResponseWriter, r *http.Request) {
return
}
- query := "INSERT INTO `comments` (`post_id`, `user_id`, `comment`) VALUES (?,?,?)"
- db.Exec(query, postID, me.ID, r.FormValue("comment"))
-
+ now := time.Now()
+ commentStr := r.FormValue("comment")
+ query := "INSERT INTO `comments` (`post_id`, `user_id`, `comment`, `created_at`) VALUES (?,?,?,?)"
+ res, err := db.Exec(query, postID, me.ID, commentStr, now)
+ if err != nil {
+ log.Println(err)
+ return
+ }
+ lid, _ := res.LastInsertId()
+ c := Comment{
+ ID: int(lid),
+ PostID: postID,
+ UserID: me.ID,
+ Comment: commentStr,
+ CreatedAt: now,
+ User: me,
+ }
+ appendComent(c)
renderIndexPosts()
http.Redirect(w, r, fmt.Sprintf("/posts/%d", postID), http.StatusFound)
}
@@ -921,6 +953,7 @@ func main() {
go http.ListenAndServe(":3000", nil)
+ goji.DefaultMux = web.New()
goji.Get("/initialize", getInitialize)
goji.Get("/login", getLogin)
goji.Post("/login", postLogin)
計測
スコア:
{"pass":true,"score":271542,"success":256436,"fail":0,"messages":[]}
pixiv 社内 isucon の優勝チームのスコアを超えることができたと思います。
top:
ks: 82 total, 4 running, 78 sleeping, 0 stopped, 0 zombie
%Cpu(s): 57.1 us, 13.8 sy, 0.0 ni, 16.5 id, 5.1 wa, 0.0 hi, 7.3 si, 0.2 st
KiB Mem: 1022972 total, 926504 used, 96468 free, 27152 buffers
KiB Swap: 0 total, 0 used, 0 free. 432620 cached Mem
PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND 1494 isucon 20 0 544796 191292 8940 S 81.5 18.7 0:29.06 app.7f063c1
731 mysql 20 0 1125024 182444 10552 S 44.9 17.8 3:04.05 mysqld
1524 www-data 20 0 92056 5276 3140 R 27.6 0.5 0:09.65 nginx
308 memcache 20 0 336672 11756 2228 S 1.7 1.1 0:02.25 memcached
31 root 20 0 0 0 0 S 0.7 0.0 0:00.40 kswapd0
89 root 0 -20 0 0 0 S 0.3 0.0 0:00.73 kworker/0:1H
1 root 20 0 28636 4736 3100 S 0.0 0.5 0:01.31 systemd
ちょっと idle が出てきたかな。
dstat:
----total-cpu-usage---- -dsk/total- -net/total- ---paging-- ---system-- usr sys idl wai hiq siq| read writ| recv send| in out | int csw 0 0 100 0 0 0| 0 0 | 0 0 | 0 0 | 82 283 11 3 82 2 0 2| 12M 0 |1684k 15M| 0 0 |7607 5952 55 13 17 9 0 7| 49M 864k| 11M 44M| 0 0 | 27k 20k 58 15 14 8 0 6| 48M 416k| 13M 43M| 0 0 | 28k 20k 48 14 21 12 0 5| 43M 63M| 12M 40M| 0 0 | 25k 19k 55 17 14 7 0 7| 48M 528k| 14M 42M| 0 0 | 25k 18k 55 12 19 8 0 6| 45M 488k| 12M 42M| 0 0 | 27k 20k 52 17 16 6 0 8| 35M 592k| 14M 38M| 0 0 | 27k 19k 50 12 19 14 0 6| 34M 59M| 11M 38M| 0 0 | 25k 17k 56 12 18 6 0 7| 42M 720k| 11M 45M| 0 0 | 28k 20k 51 15 18 9 0 8| 45M 704k| 14M 39M| 0 0 | 26k 19k 52 17 17 7 0 7| 39M 3936k| 14M 45M| 0 0 | 27k 19k 47 17 18 13 0 5| 41M 56M| 12M 39M| 0 0 | 24k 17k 53 13 19 9 0 6| 45M 848k| 13M 41M| 0 0 | 27k 20k 57 15 16 6 0 6| 38M 776k| 13M 42M| 0 0 | 27k 19k 53 14 20 9 0 4| 28M 58M| 11M 29M| 0 0 | 24k 16k 53 13 19 6 0 8| 44M 672k| 13M 38M| 0 0 | 26k 18k 57 13 16 9 0 6| 46M 872k| 10M 38M| 0 0 | 25k 18k 53 12 22 7 0 6| 44M 776k| 12M 41M| 0 0 | 28k 20k 54 16 16 8 0 6| 33M 57M|9049k 33M| 0 0 | 24k 18k 51 16 21 5 0 7| 32M 888k| 12M 38M| 0 0 | 27k 19k 54 13 19 7 0 7| 49M 2264k| 11M 46M| 0 0 | 26k 18k 54 14 19 6 0 7| 36M 680k| 12M 42M| 0 0 | 28k 19k 48 16 19 10 0 7| 33M 52M| 14M 31M| 0 0 | 23k 16k 55 15 15 7 0 7| 42M 720k| 12M 34M| 0 0 | 26k 20k 59 14 17 5 0 6| 33M 744k| 12M 35M| 0 0 | 25k 18k 47 15 25 7 0 6| 34M 736k|9604k 43M| 0 0 | 28k 19k 47 11 27 8 0 6| 31M 51M| 12M 39M| 0 0 | 25k 17k 54 18 17 5 0 7| 34M 816k| 12M 33M| 0 0 | 27k 20k 55 16 16 6 0 6| 35M 888k| 14M 34M| 0 0 | 27k 19k 57 13 18 6 0 6| 34M 720k| 11M 37M| 0 0 | 27k 19k 52 12 18 12 0 6| 36M 53M| 11M 34M| 0 0 | 23k 17k 62 12 15 4 0 7| 26M 720k|9309k 29M| 0 0 | 25k 19k 46 20 19 5 0 9| 30M 560k| 16M 35M| 0 0 | 28k 20k 59 12 20 5 0 5| 23M 544k| 10M 36M| 0 0 | 25k 17k 53 13 21 8 0 5| 25M 47M| 11M 31M| 0 0 | 23k 16k 54 14 18 6 0 9| 38M 584k| 14M 35M| 0 0 | 27k 21k ...
帯域は半分強使っていますね。大きい js があるので、 `nginx の gzip_static モジュールを使うなどでもう少し帯域を開けられると思います。
pprof:
(pprof) top30 -cum
6.95s of 22.25s total (31.24%)
Dropped 621 nodes (cum <= 0.11s)
Showing top 30 nodes out of 321 (cum >= 2.44s)
flat flat% sum% cum cum%
0 0% 0% 20.30s 91.24% runtime.goexit
0.02s 0.09% 0.09% 17.03s 76.54% net/http.(*conn).serve
0 0% 0.09% 14.60s 65.62% net/http.(*ServeMux).ServeHTTP
0 0% 0.09% 14.60s 65.62% net/http.serverHandler.ServeHTTP
0 0% 0.09% 14.58s 65.53% github.com/zenazn/goji/web.(*Mux).ServeHTTP
0 0% 0.09% 14.57s 65.48% github.com/zenazn/goji/web.(*cStack).ServeHTTP
0 0% 0.09% 14.57s 65.48% github.com/zenazn/goji/web.(*mStack).newStack.func1
0 0% 0.09% 14.57s 65.48% github.com/zenazn/goji/web.(*router).route
0 0% 0.09% 14.57s 65.48% net/http.HandlerFunc.ServeHTTP
0 0% 0.09% 10.03s 45.08% github.com/zenazn/goji/web.netHTTPHandlerFuncWrap.ServeHTTPC
0.01s 0.045% 0.13% 6.12s 27.51% html/template.(*Template).Execute
0 0% 0.13% 5.58s 25.08% text/template.(*Template).Execute
0.12s 0.54% 0.67% 5.57s 25.03% text/template.(*state).walk
0.01s 0.045% 0.72% 5.20s 23.37% text/template.(*state).walkTemplate
0.04s 0.18% 0.9% 4.68s 21.03% text/template.(*state).walkRange
0.01s 0.045% 0.94% 4.65s 20.90% text/template.(*state).walkRange.func1
0.97s 4.36% 5.30% 4.60s 20.67% runtime.mallocgc
0 0% 5.30% 4.46s 20.04% github.com/zenazn/goji/web.handlerFuncWrap.ServeHTTPC
0.23s 1.03% 6.34% 4.38s 19.69% runtime.systemstack
0.04s 0.18% 6.52% 4.07s 18.29% text/template.(*state).evalPipeline
0.08s 0.36% 6.88% 4.03s 18.11% text/template.(*state).evalCommand
2.54s 11.42% 18.29% 3.71s 16.67% runtime.scanobject
0.10s 0.45% 18.74% 3.09s 13.89% text/template.(*state).evalCall
0.03s 0.13% 18.88% 3.07s 13.80% text/template.(*state).evalFunction
0 0% 18.88% 2.99s 13.44% main.getAccountName
2.48s 11.15% 30.02% 2.70s 12.13% syscall.Syscall
0 0% 30.02% 2.62s 11.78% main.getPosts
0.01s 0.045% 30.07% 2.56s 11.51% reflect.Value.Call
0.26s 1.17% 31.24% 2.52s 11.33% reflect.Value.call
0 0% 31.24% 2.44s 10.97% github.com/jmoiron/sqlx.(*DB).Get
テンプレートの実行とが重いのと、あとGCが重いですね。
テンプレートが重いのは、ページキャッシュだとトップページ以外はどれくらいキャッシュヒット率が見込めるかわかりません。 valyala/quicktemplate などの、リフレクションを多用しない高速なテンプレートエンジンに乗り換えるほうが早いかもしれません。
GCの方は、クエリ実行回数をさらに削っていけば、一時オブジェクトがを削減するのが有効そう。どこでアロケートが多発しているのかを確認したい場合は pprof -alloc_objects を使ってみてください。
まとめ
スコア: 4745 (初期状態) -> 39743 (前回) -> 182435 (Not Modified) -> 271542 (最終版)
壁を超えた効果で、いままで伸び悩んでいたスコアが一気にジャンプしました。
攻略記はここまでにしますが、できればさらにチューニングを続けてみてください。練習で実際に手を動かしていないことは、本番ではほぼ確実にできません。 私の場合は、次のようなチューニングで500k点を超えましたが、これでもまだ帯域を使い切っていないし nginx よりも app と MySQL が使用するCPUの方が大きいのでさらに上を狙えるはずです。
- gzip_static を使う (スコアは上がりませんでしたが、帯域に余裕を作りました)
- テンプレートが重い posts の部分で valyala/quicktemplate を使ってみる
- ユーザーをオンメモリキャッシュし、強引なJOINをやめる
- セッションストアを memcached からオンメモリに切り替える
- nginx と app の間を unix domain socket に切り替える
- nginx が重くなってきていたので worker_processes を 2 にする
- 更新系のリクエストであえて
time.Sleep()で待たせて、スコアへの影響が大きいシナリオの処理にリソースを向ける - アクセスログを切る (最初は静的ファイルだけ、最後は全部のアクセスログを消す)
ここまでのコミットログは methane/pixiv-private-isucon-2016 に置いてあります。 ですが、できるだけ自力で 500k 点超えを目指してみてください。
最後に、ISUCON の練習にとても良い題材を提供して頂いた pixiv さんに感謝します。
@methane
pixiv private isucon 2016 攻略 (4/5)
攻略記事一覧:
ここから、いよいよ ISUCON らしくなってきますよ。
現状確認
access.log の集計はこんな感じです。
Request by count 12317 GET /image/* 2797 GET / 1983 POST /login 1218 GET /posts/* 1029 GET /js/jquery-2.2.0.js 1029 GET /favicon.ico 1029 GET /js/jquery.timeago.js 1028 GET /css/style.css 1028 GET /js/jquery.timeago.ja.js 1028 GET /js/main.js 930 GET /@user 655 POST /register 654 GET /admin/banned 579 POST /comment 579 POST / 112 GET /login 83 GET /posts?max_created_at= 56 GET /logout 1 GET /initialize Request by total time 72.877 0.0260554165177 GET / 34.018 0.0365784946237 GET /@user 18.444 0.22221686747 GET /posts?max_created_at= 15.705 0.0271243523316 POST / 12.566 0.0103169129721 GET /posts/* 8.439 0.000685150604855 GET /image/* 5.644 0.00284619263742 POST /login 1.825 0.00278625954198 POST /register 1.661 0.00286873920553 POST /comment 1.648 0.00251987767584 GET /admin/banned 0.475 0.00424107142857 GET /login 0.45 0.00803571428571 GET /logout 0.026 0.026 GET /initialize
top はこんな感じ
Tasks: 73 total, 1 running, 72 sleeping, 0 stopped, 0 zombie %Cpu(s): 55.4 us, 10.8 sy, 0.0 ni, 23.5 id, 3.1 wa, 0.0 hi, 6.7 si, 0.5 st KiB Mem: 1022972 total, 617428 used, 405544 free, 18260 buffers KiB Swap: 0 total, 0 used, 0 free. 314552 cached Mem PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND 1122 isucon 20 0 403944 68064 8328 S 76.3 6.7 0:16.87 app.f9aa6c7 731 mysql 20 0 993756 159744 10756 S 62.6 15.6 0:15.46 mysqld 1033 www-data 20 0 92024 5136 3056 S 7.0 0.5 0:01.63 nginx 1069 isucon 20 0 28796 6136 2636 S 2.7 0.6 0:00.80 tmux 308 memcache 20 0 330528 6060 2228 S 0.7 0.6 0:00.14 memcached
そろそろリクエスト数が増えてきたのと、まだ少し idle が残っているので、念の為ベンチマーク直後の netstat を確認しておきます。
$ netstat -tn ... tcp6 0 0 127.0.0.1:8080 127.0.0.1:63462 TIME_WAIT tcp6 0 0 127.0.0.1:8080 127.0.0.1:64494 TIME_WAIT tcp6 0 0 127.0.0.1:8080 127.0.0.1:63477 TIME_WAIT tcp6 0 0 127.0.0.1:8080 127.0.0.1:63563 TIME_WAIT tcp6 0 0 127.0.0.1:8080 127.0.0.1:63877 TIME_WAIT tcp6 0 0 127.0.0.1:8080 127.0.0.1:64234 TIME_WAIT tcp6 0 0 127.0.0.1:8080 127.0.0.1:63565 TIME_WAIT tcp6 0 0 127.0.0.1:8080 127.0.0.1:64008 TIME_WAIT tcp6 0 0 127.0.0.1:8080 127.0.0.1:63594 TIME_WAIT tcp6 0 0 127.0.0.1:8080 127.0.0.1:64065 TIME_WAIT $ netstat -tn | grep -c TIME_WAIT 1981
まだ詰まるほどじゃないけど一応 /etc/nginx/sites-enabled/isucon.conf で upstream の keepalive を 64 に増やしておきます。
ページキャッシュ
プロファイルを見てみます。
(pprof) top30 -cum
5.66s of 23.80s total (23.78%)
Dropped 584 nodes (cum <= 0.12s)
Showing top 30 nodes out of 326 (cum >= 3.55s)
flat flat% sum% cum cum%
0 0% 0% 22.30s 93.70% runtime.goexit
0 0% 0% 19.44s 81.68% net/http.(*conn).serve
0.01s 0.042% 0.042% 18.79s 78.95% net/http.serverHandler.ServeHTTP
0 0% 0.042% 18.78s 78.91% net/http.(*ServeMux).ServeHTTP
0 0% 0.042% 18.76s 78.82% github.com/zenazn/goji/web.(*Mux).ServeHTTP
0 0% 0.042% 18.72s 78.66% github.com/zenazn/goji/web.(*cStack).ServeHTTP
0 0% 0.042% 18.72s 78.66% github.com/zenazn/goji/web/middleware.RequestID.func1
0 0% 0.042% 18.72s 78.66% net/http.HandlerFunc.ServeHTTP
0.01s 0.042% 0.084% 18.69s 78.53% github.com/zenazn/goji/web/middleware.Logger.func1
0 0% 0.084% 18.27s 76.76% github.com/zenazn/goji/web/middleware.Recoverer.func1
0 0% 0.084% 18.21s 76.51% github.com/zenazn/goji/web.(*mStack).newStack.func1
0 0% 0.084% 18.21s 76.51% github.com/zenazn/goji/web.(*router).route
0 0% 0.084% 18.21s 76.51% github.com/zenazn/goji/web/middleware.AutomaticOptions.func1
0.01s 0.042% 0.13% 14.43s 60.63% github.com/zenazn/goji/web.netHTTPHandlerFuncWrap.ServeHTTPC
0 0% 0.13% 12.63s 53.07% main.getIndex
0.07s 0.29% 0.42% 9.88s 41.51% main.makePosts
0.01s 0.042% 0.46% 6.89s 28.95% github.com/jmoiron/sqlx.(*DB).Get
0.01s 0.042% 0.5% 6.88s 28.91% github.com/jmoiron/sqlx.Get
0.03s 0.13% 0.63% 6.80s 28.57% database/sql.(*DB).Query
0.02s 0.084% 0.71% 6.77s 28.45% database/sql.(*DB).query
0.03s 0.13% 0.84% 6.43s 27.02% database/sql.(*DB).queryConn
0.06s 0.25% 1.09% 6.02s 25.29% github.com/go-sql-driver/mysql.(*mysqlConn).Query
0.02s 0.084% 1.18% 4.65s 19.54% github.com/jmoiron/sqlx.(*DB).QueryRowx
4.06s 17.06% 18.24% 4.38s 18.40% syscall.Syscall
1.17s 4.92% 23.15% 4.08s 17.14% runtime.mallocgc
0 0% 23.15% 3.83s 16.09% github.com/jmoiron/sqlx.(*DB).Select
0.01s 0.042% 23.19% 3.83s 16.09% github.com/jmoiron/sqlx.Select
0 0% 23.19% 3.72s 15.63% github.com/zenazn/goji/web.handlerFuncWrap.ServeHTTPC
0.12s 0.5% 23.70% 3.58s 15.04% runtime.systemstack
0.02s 0.084% 23.78% 3.55s 14.92% syscall.Write
(pprof) list getIndex
Total: 23.80s
ROUTINE ======================== main.getIndex in /home/isucon/private_isu/webapp/golang/app.go
0 12.63s (flat, cum) 53.07% of Total
. . 413:
. . 414: http.Redirect(w, r, "/", http.StatusFound)
. . 415:}
. . 416:
. . 417:func getIndex(w http.ResponseWriter, r *http.Request) {
. 330ms 418: me := getSessionUser(r)
. . 419:
. . 420: results := []Post{}
. . 421:
. 600ms 422: err := db.Select(&results, "SELECT posts.`id`, `user_id`, `body`, `mime`, posts.`created_at` FROM `posts` INNER JOIN `users` ON posts.user_id=users.id WHERE users.del_flg = 0 ORDER BY `created_at` DESC LIMIT 20")
. . 423: if err != nil {
. . 424: fmt.Println(err)
. . 425: return
. . 426: }
. . 427:
. 8.43s 428: posts, merr := makePosts(results, getCSRFToken(r), false)
. . 429: if merr != nil {
. . 430: fmt.Println(merr)
. . 431: return
. . 432: }
. . 433:
. . 434: fmap := template.FuncMap{
. . 435: "imageURL": imageURL,
. . 436: }
. . 437:
. 40ms 438: template.Must(template.New("layout.html").Funcs(fmap).ParseFiles(
. 10ms 439: getTemplPath("layout.html"),
. 10ms 440: getTemplPath("index.html"),
. . 441: getTemplPath("posts.html"),
. . 442: getTemplPath("post.html"),
. 1.20s 443: )).Execute(w, struct {
. . 444: Posts []Post
. . 445: Me User
. . 446: CSRFToken string
. . 447: Flash string
. 2.01s 448: }{posts, me, getCSRFToken(r), getFlash(w, r, "notice")})
. . 449:}
. . 450:
. . 451:func getAccountName(c web.C, w http.ResponseWriter, r *http.Request) {
. . 452: user := User{}
. . 453: uerr := db.Get(&user, "SELECT * FROM `users` WHERE `account_name` = ? AND `del_flg` = 0", c.URLParams["accountName"])
テンプレートに渡すための []Post を用意する makePosts 関数が一番重いものの、最初に Post 一覧を取得する select が 600ms, テンプレートのコンパイルと実行を足して 3.2sec ありますね。
テンプレートのコンパイルは起動時に一度やればいい処理なので 1.2sec は無駄です。
また、トップページに表示される内容はユーザーにかかわらず一定なので、レンダリング結果をまるごとページキャッシュできれば、 makePosts の 8.4sec とテンプレートのレンダリングの 2sec の合わせて 10sec をほぼ消し去ることができます。
ページキャッシュが実現できそうかテンプレートの中身を確認してみると、ユーザーごとに異なる内容は、 (1) ヘッダー部分, (2) 全フォームにある csrf token, でした。レンダリングが重いのはポスト一覧の部分でしょうから、ヘッダーはページキャッシュの対象外にして、ポスト一覧部分だけをキャッシュすれば (1) は問題ありません。問題は (2) ですが、レンダリング時に固定のキーワードを入れてレンダリングしておき、ユーザーに返すときに本当の csrf token に文字列置換することにします。
ページキャッシュを作るタイミングですが、 getIndex() が呼ばれた時にするよりも、トップページに何か変更があったとき (画像が投稿された、コメントされた、ユーザーが削除されたなど) にレンダリングするほうが効率的です。
さらに、性能が上がってくるとトップページに変更があるリクエストが並列で来る可能性があるので、レンダリングを Mutex で排他したうえで、 Mutex を待ってる goroutine が同時に複数存在した場合はそのうちの1つだけがレンダリングする方式を採用しました。
この方式は GoCon 2016 Spring で zero time cache パターンとして紹介したもので、全ての POST リクエストがレンダリングを待ってからレスポンスを返すので、キャッシュによる更新が反映されるまでの遅延が存在しません。
diff --git a/app.go b/app.go
index b5a8fac..f246ad6 100644
--- a/app.go
+++ b/app.go
@@ -1,6 +1,7 @@
package main
import (
+ "bytes"
crand "crypto/rand"
"crypto/sha512"
"encoding/hex"
@@ -109,6 +110,8 @@ func dbInitialize() {
for _, sql := range sqls {
db.Exec(sql)
}
+
+ renderIndexPosts()
}
func tryLogin(accountName, password string) *User {
@@ -414,38 +410,85 @@ func getLogout(w http.ResponseWriter, r *http.Request) {
http.Redirect(w, r, "/", http.StatusFound)
}
-func getIndex(w http.ResponseWriter, r *http.Request) {
- me := getSessionUser(r)
+var (
+ indexTemplate *template.Template
+ postsTemplate *template.Template
- results := []Post{}
+ indexPostsM sync.Mutex
+ indexPostsT time.Time
+ indexPostsRenderedM sync.RWMutex
+ indexPostsRendered []byte
+)
+
+func init() {
+ fmap := template.FuncMap{
+ "imageURL": imageURL,
+ }
+ indexTemplate = template.Must(template.New("layout.html").Funcs(fmap).ParseFiles(
+ getTemplPath("layout.html"),
+ getTemplPath("index.html"),
+ ))
+
+ postsTemplate = template.Must(template.New("posts.html").Funcs(fmap).ParseFiles(
+ getTemplPath("posts.html"),
+ getTemplPath("post.html"),
+ ))
+}
+
+func renderIndexPosts() {
+ now := time.Now()
+ indexPostsM.Lock()
+ defer indexPostsM.Unlock()
+ if indexPostsT.After(now) {
+ return
+ }
+ now = time.Now()
+
+ results := []Post{}
err := db.Select(&results, "SELECT posts.`id`, `user_id`, `body`, `mime`, posts.`created_at` FROM `posts` INNER JOIN `users` ON posts.user_id=users.id WHERE users.del_flg = 0 ORDER BY `created_at` DESC LIMIT 20")
if err != nil {
- fmt.Println(err)
+ log.Println(err)
return
}
- posts, merr := makePosts(results, getCSRFToken(r), false)
+ posts, merr := makePosts(results, "[[[CSRFTOKEN]]]", false)
if merr != nil {
- fmt.Println(merr)
+ log.Println(merr)
return
}
- fmap := template.FuncMap{
- "imageURL": imageURL,
+ var b bytes.Buffer
+ if err := postsTemplate.Execute(&b, posts); err != nil {
+ log.Println(err)
+ return
}
- template.Must(template.New("layout.html").Funcs(fmap).ParseFiles(
- getTemplPath("layout.html"),
- getTemplPath("index.html"),
- getTemplPath("posts.html"),
- getTemplPath("post.html"),
- )).Execute(w, struct {
- Posts []Post
- Me User
- CSRFToken string
- Flash string
- }{posts, me, getCSRFToken(r), getFlash(w, r, "notice")})
+ indexPostsT = now
+ indexPostsRenderedM.Lock()
+ indexPostsRendered = b.Bytes()
+ indexPostsRenderedM.Unlock()
+}
+
+func getIndexPosts(csrf string) template.HTML {
+ indexPostsRenderedM.RLock()
+ t := bytes.Replace(indexPostsRendered, []byte("[[[CSRFTOKEN]]]"), []byte(csrf), -1)
+ indexPostsRenderedM.RUnlock()
+ return template.HTML(string(t))
+}
+
+func getIndex(w http.ResponseWriter, r *http.Request) {
+ me := getSessionUser(r)
+ csrf := getCSRFToken(r)
+ posts := getIndexPosts(csrf)
+
+ indexTemplate.Execute(w,
+ map[string]interface{}{
+ "Me": me,
+ "CSRFToken": csrf,
+ "Flash": getFlash(w, r, "notice"),
+ "Posts": posts},
+ )
}
func getAccountName(c web.C, w http.ResponseWriter, r *http.Request) {
@@ -708,8 +751,9 @@ func postIndex(w http.ResponseWriter, r *http.Request) {
}
tf.Close()
copyImage(int(pid), tf.Name(), mime)
+
+ renderIndexPosts()
http.Redirect(w, r, "/posts/"+strconv.FormatInt(pid, 10), http.StatusFound)
- return
}
func getImage(c web.C, w http.ResponseWriter, r *http.Request) {
@@ -765,6 +809,7 @@ func postComment(w http.ResponseWriter, r *http.Request) {
query := "INSERT INTO `comments` (`post_id`, `user_id`, `comment`) VALUES (?,?,?)"
db.Exec(query, postID, me.ID, r.FormValue("comment"))
+ renderIndexPosts()
http.Redirect(w, r, fmt.Sprintf("/posts/%d", postID), http.StatusFound)
}
@@ -821,6 +866,7 @@ func postAdminBanned(w http.ResponseWriter, r *http.Request) {
db.Exec(query, 1, id)
}
+ renderIndexPosts()
http.Redirect(w, r, "/admin/banned", http.StatusFound)
}
@@ -864,6 +910,15 @@ func main() {
db.SetMaxIdleConns(8)
defer db.Close()
+ for {
+ if db.Ping() == nil {
+ break
+ }
+ log.Println("waiting db...")
+ }
+
+ renderIndexPosts()
+
go http.ListenAndServe(":3000", nil)
goji.Get("/initialize", getInitialize)
diff --git a/templates/index.html b/templates/index.html
index 22ff9c2..8c2b639 100644
--- a/templates/index.html
+++ b/templates/index.html
@@ -19,7 +19,7 @@
</form>
</div>
-{{ template "posts.html" .Posts }}
+{{ .Posts }}
<div id="isu-post-more">
<button id="isu-post-more-btn">もっと見る</button>
計測
スコア:
{"pass":true,"score":39743,"success":32254,"fail":0,"messages":[]}
top:
Tasks: 77 total, 1 running, 76 sleeping, 0 stopped, 0 zombie
%Cpu(s): 44.7 us, 8.3 sy, 0.0 ni, 35.3 id, 5.1 wa, 0.0 hi, 6.0 si, 0.5 st
KiB Mem: 1022972 total, 961900 used, 61072 free, 23704 buffers
KiB Swap: 0 total, 0 used, 0 free. 604328 cached Mem
PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND
1337 isucon 20 0 207476 68192 8880 S 63.6 6.7 0:13.73 app.dc4a3eaa
731 mysql 20 0 1059292 181996 10552 S 45.6 17.8 1:49.68 mysqld
1033 www-data 20 0 92008 5092 3056 S 8.0 0.5 0:11.70 nginx
1069 isucon 20 0 32140 9332 2636 S 4.0 0.9 0:07.71 tmux
3 root 20 0 0 0 0 S 0.3 0.0 0:15.56 ksoftirqd/0
13 root 20 0 0 0 0 S 0.3 0.0 0:29.07 ksoftirqd/1
43 root 20 0 0 0 0 S 0.3 0.0 0:00.15 kworker/u30:1
308 memcache 20 0 332576 7896 2228 S 0.3 0.8 0:00.89 memcached
968 isucon 20 0 80656 3496 2656 S 0.3 0.3 0:00.28 sshd
CPU がだいぶ遊んできましたね。どこか別のところにあるボトルネックを見つけないといけません。
myprofiler:
34 SELECT * FROM `users` WHERE `id` = N 30 SELECT `id`, `user_id`, `body`, `mime`, `created_at` FROM `posts` WHERE `created_at` <= S ORDER BY `created_at` DESC 23 SELECT * FROM `posts` WHERE `id` = N 19 SELECT `id`, `user_id`, `body`, `mime`, `created_at` FROM `posts` WHERE `user_id` = N ORDER BY `created_at` DESC 11 SELECT COUNT(*) AS `count` FROM `comments` WHERE `post_id` = N 10 SELECT * FROM `comments` WHERE `post_id` = N ORDER BY `created_at` DESC LIMIT N 8 SELECT `id` FROM `posts` WHERE `user_id` = N 2 INSERT INTO `users` (`account_name`, `passhash`) VALUES (S,S) 1 SELECT * FROM `comments` WHERE `post_id` = N ORDER BY `created_at` DESC 1 SELECT COUNT(*) AS count FROM `comments` WHERE `post_id` IN (...N)
user を PK で取得する部分が重いみたいです。
access.log:
Request by count 12394 GET /image/* 4149 GET / 2791 POST /login 1395 GET /posts/* 1207 POST /register 1207 GET /admin/banned 1049 GET /@user 1021 GET /js/jquery-2.2.0.js 1021 GET /css/style.css 1021 GET /js/jquery.timeago.ja.js 1021 GET /favicon.ico 1021 GET /js/jquery.timeago.js 1021 GET /js/main.js 704 POST /comment 698 POST / 120 GET /login 77 GET /posts?max_created_at= 61 GET /logout 1 GET /initialize Request by total time 30.646 0.0292144899905 GET /@user 24.051 0.0344570200573 POST / 14.411 0.187155844156 GET /posts?max_created_at= 12.099 0.00867311827957 GET /posts/* 11.879 0.0168735795455 POST /comment 9.296 0.00224053988913 GET / 6.612 0.00236904335364 POST /login 3.355 0.00277961888981 POST /register 2.882 0.00023253187026 GET /image/* 2.21 0.00183098591549 GET /admin/banned 0.448 0.00373333333333 GET /login 0.443 0.00726229508197 GET /logout 0.038 0.038 GET /initialize Request by out bytes 3847419944 310426 GET /image/* 264074503 258643 GET /js/jquery-2.2.0.js 99628388 24012 GET / ...
GET / が 2.2msec まで速くなりました。まだ速く出来る余地はあるけど、先に GET /@user などの高速化が先でしょうね。
まとめ
スコア: 4745 (初期状態) -> 32771 (前回) -> 39743 (トップページのページキャッシュ)
ボトルネックがCPU以外に移っているので、スコアが期待したほど伸びませんでした。次回はそのボトルネックを調査・解決します。
ページキャッシュに利用した zero time cache パターンは Go だから簡単に実現できるものなので、 prefork 型のアプリサーバーを使う他の言語ではちょっと難しいです。 (node.js なら、2コアマシンならシングルプロセスで頑張れるかも知れません)
他の言語では、普通に getIndex でページキャッシュしてベンチが完走するようにキャッシュの生存期間を調整するとか、バックグラウンドで動くデーモンが定期的にページキャッシュを生成するようにしてベンチが通るようにその生成間隔を調整するといったやり方がISUCONでは一般的だと思います。
しかし、今回の pixiv private isucon ではルールに POST が返ってからその内容が別の GET リクエストに反映されるまでの猶予が明記されていないので、調整のために複数回ベンチを走らせる必要があるかもしれません。 (Go 推し)
@methane
pixiv private isucon 2016 攻略 (3/5)
攻略記事一覧:
現状確認
access.log をもう一度見直しましょう。
Request by total time 74.113 0.0307140489018 GET / 70.007 0.00532696697611 GET /image/* 43.428 0.0575205298013 GET /@user 24.058 0.283035294118 GET /posts?max_created_at= 23.976 0.0522352941176 POST / 12.767 0.012987792472 GET /posts/* 6.642 0.00390476190476 POST /login ...
CPU を一番使っているのはトップページですが、レスポンスタイムに占める時間で言えば /image/* がほとんど並びました。
そろそろ /image/* をリバースプロキシするのは止めないといけません。
Go を使う場合は nginx を使うのをやめるのも候補になるのですが、静的ファイル配信は nginx に任せたほうがてっとり早いので、 nginx を外さない方針で行きましょう。
nginx の設定
僕も ISUCON 前以外は nginx の設定に詳しくないので、とりあえずこんな感じで設定しました。
root /home/isucon/private_isu/webapp/public/;
location / {
try_files $uri @app;
}
location @app {
proxy_set_header Host $host;
proxy_set_header X-Real-IP $remote_addr;
proxy_set_header X-Forwarded-For $proxy_add_x_forwarded_for;
proxy_pass http://app;
}
public ディレクトリは css とか js も入ってるので、その中に mkdir image しておき、 try_files ディレクティブでファイルが有ればそれを返す、なければリバースプロキシの設定を書いた @app location を使う設定にしています。
アプリ側は、 /image/* にアクセスがあったときに画像を返すついでにファイルに書き出すのと、画像がアップロードされたときにファイルに書いてDBには書かないように修正します。DBに書かないのは Disk IO 負荷低減のためです。
--- a/app.go
+++ b/app.go
@@ -78,6 +78,29 @@ func init() {
store = gsm.NewMemcacheStore(memcacheClient, "isucogram_", []byte("sendagaya"))
}
+func writeImage(id int, mime string, data []byte) {
+ var ext string
+ switch mime {
+ case "image/jpeg":
+ ext = ".jpg"
+ case "image/png":
+ ext = ".png"
+ case "image/gif":
+ ext = ".gif"
+ default:
+ fmt.Println("Failed to write file: ", id, mime)
+ return
+ }
+
+ fn := fmt.Sprintf("../public/image/%d%s", id, ext)
+ f, err := os.OpenFile(fn, os.O_WRONLY|os.O_CREATE, 0666)
+ if err != nil {
+ panic(err)
+ }
+ f.Write(data)
+ f.Close()
+}
+
func dbInitialize() {
sqls := []string{
"DELETE FROM users WHERE id > 1000",
@@ -652,7 +675,7 @@ func postIndex(w http.ResponseWriter, r *http.Request) {
query,
me.ID,
mime,
- filedata,
+ []byte(""),
r.FormValue("body"),
)
if eerr != nil {
@@ -665,7 +688,7 @@ func postIndex(w http.ResponseWriter, r *http.Request) {
fmt.Println(lerr.Error())
return
}
-
+ writeImage(int(pid), mime, filedata)
http.Redirect(w, r, "/posts/"+strconv.FormatInt(pid, 10), http.StatusFound)
return
}
@@ -695,6 +718,7 @@ func getImage(c web.C, w http.ResponseWriter, r *http.Request) {
if err != nil {
fmt.Println(err.Error())
}
+ writeImage(pid, post.Mime, post.Imgdata)
return
}
メモリが足りない！！
ここで問題にぶつかりました。メモリが足りなくてベンチが完走しません。 静的ファイル配信を nginx に任せることでメモリ使用量が減らせると思っていたのに！
多分、性能が向上したためにメモリアロケートのペースが早くなって問題が顕在化したのでしょう。プロファイラーで、ベンチマーク中 (メモリ使用量が増えてきたけどメモリ不足で落ちるよりは前) のメモリ使用量を調査してみます。
$ go tool pprof -inuse_space app.e27b8a http://localhost:3000/debug/pprof/heap
Fetching profile from http://localhost:3000/debug/pprof/heap
Saved profile in /home/isucon/pprof/pprof.app.e27b8a.localhost:3000.inuse_objects.inuse_space.002.pb.gz
Entering interactive mode (type "help" for commands)
(pprof) top40 -cum
319.72MB of 338.26MB total (94.52%)
Dropped 338 nodes (cum <= 1.69MB)
Showing top 40 nodes out of 52 (cum >= 8.34MB)
flat flat% sum% cum cum%
0 0% 0% 337.76MB 99.85% runtime.goexit
0 0% 0% 336.72MB 99.54% net/http.(*conn).serve
0 0% 0% 322.22MB 95.26% github.com/zenazn/goji/web.(*mStack).newStack.func1
0 0% 0% 322.22MB 95.26% github.com/zenazn/goji/web.(*router).route
0 0% 0% 322.22MB 95.26% github.com/zenazn/goji/web/middleware.AutomaticOptions.func1
0 0% 0% 322.22MB 95.26% github.com/zenazn/goji/web/middleware.Logger.func1
0 0% 0% 322.22MB 95.26% github.com/zenazn/goji/web/middleware.Recoverer.func1
0 0% 0% 322.22MB 95.26% github.com/zenazn/goji/web/middleware.RequestID.func1
0 0% 0% 322.22MB 95.26% net/http.HandlerFunc.ServeHTTP
0 0% 0% 321.72MB 95.11% github.com/zenazn/goji/web.(*Mux).ServeHTTP
0 0% 0% 321.72MB 95.11% github.com/zenazn/goji/web.(*cStack).ServeHTTP
0 0% 0% 321.72MB 95.11% net/http.(*ServeMux).ServeHTTP
0 0% 0% 321.72MB 95.11% net/http.serverHandler.ServeHTTP
0 0% 0% 309.80MB 91.59% github.com/zenazn/goji/web.netHTTPHandlerFuncWrap.ServeHTTPC
0 0% 0% 301.29MB 89.07% net/http.(*Request).FormValue
0 0% 0% 301.29MB 89.07% net/http.(*Request).ParseMultipartForm
0 0% 0% 299.29MB 88.48% main.postIndex
0.50MB 0.15% 0.15% 298.79MB 88.33% mime/multipart.(*Reader).ReadForm
0 0% 0.15% 298.29MB 88.18% bytes.(*Buffer).ReadFrom
298.29MB 88.18% 88.33% 298.29MB 88.18% bytes.makeSlice
0 0% 88.33% 298.29MB 88.18% io.Copy
0 0% 88.33% 298.29MB 88.18% io.CopyN
0 0% 88.33% 298.29MB 88.18% io.copyBuffer
0 0% 88.33% 15MB 4.44% net/http.(*conn).readRequest
1MB 0.3% 88.63% 15MB 4.44% net/http.readRequest
0 0% 88.63% 12.42MB 3.67% github.com/zenazn/goji/web.handlerFuncWrap.ServeHTTPC
10.50MB 3.11% 91.73% 11MB 3.25% net/textproto.(*Reader).ReadMIMEHeader
0 0% 91.73% 10.50MB 3.10% github.com/bradleypeabody/gorilla-sessions-memcache.(*MemcacheStore).Get
0 0% 91.73% 10.50MB 3.10% main.getSession
0 0% 91.73% 9.42MB 2.78% database/sql.(*Rows).Next
9.42MB 2.78% 94.52% 9.42MB 2.78% github.com/go-sql-driver/mysql.(*buffer).fill
0 0% 94.52% 9.42MB 2.78% github.com/go-sql-driver/mysql.(*buffer).readNext
0 0% 94.52% 9.42MB 2.78% github.com/go-sql-driver/mysql.(*mysqlConn).readPacket
0 0% 94.52% 9.42MB 2.78% github.com/go-sql-driver/mysql.(*textRows).Next
0 0% 94.52% 9.42MB 2.78% github.com/go-sql-driver/mysql.(*textRows).readRow
0 0% 94.52% 8.34MB 2.47% github.com/jmoiron/sqlx.(*DB).Get
0 0% 94.52% 8.34MB 2.47% github.com/jmoiron/sqlx.(*Row).Scan
0 0% 94.52% 8.34MB 2.47% github.com/jmoiron/sqlx.(*Row).scanAny
0 0% 94.52% 8.34MB 2.47% github.com/jmoiron/sqlx.Get
0 0% 94.52% 8.34MB 2.47% main.getImage
(pprof) list ReadForm
Total: 338.26MB
ROUTINE ======================== mime/multipart.(*Reader).ReadForm in /home/isucon/.local/go/src/mime/multipart/formdata.go
512.02kB 298.79MB (flat, cum) 88.33% of Total
. . 19:// ReadForm parses an entire multipart message whose parts have
. . 20:// a Content-Disposition of "form-data".
. . 21:// It stores up to maxMemory bytes of the file parts in memory
. . 22:// and the remainder on disk in temporary files.
. . 23:func (r *Reader) ReadForm(maxMemory int64) (f *Form, err error) {
512.02kB 512.02kB 24: form := &Form{make(map[string][]string), make(map[string][]*FileHeader)}
. . 25: defer func() {
. . 26: if err != nil {
. . 27: form.RemoveAll()
. . 28: }
. . 29: }()
. . 30:
. . 31: maxValueBytes := int64(10 << 20) // 10 MB is a lot of text.
. . 32: for {
. . 33: p, err := r.NextPart()
. . 34: if err == io.EOF {
. . 35: break
. . 36: }
. . 37: if err != nil {
. . 38: return nil, err
. . 39: }
. . 40:
. . 41: name := p.FormName()
. . 42: if name == "" {
. . 43: continue
. . 44: }
. . 45: filename := p.FileName()
. . 46:
. . 47: var b bytes.Buffer
. . 48:
. . 49: if filename == "" {
. . 50: // value, store as string in memory
. . 51: n, err := io.CopyN(&b, p, maxValueBytes)
. . 52: if err != nil && err != io.EOF {
. . 53: return nil, err
. . 54: }
. . 55: maxValueBytes -= n
. . 56: if maxValueBytes == 0 {
. . 57: return nil, errors.New("multipart: message too large")
. . 58: }
. . 59: form.Value[name] = append(form.Value[name], b.String())
. . 60: continue
. . 61: }
. . 62:
. . 63: // file, store in memory or on disk
. . 64: fh := &FileHeader{
. . 65: Filename: filename,
. . 66: Header: p.Header,
. . 67: }
. 298.29MB 68: n, err := io.CopyN(&b, p, maxMemory+1)
. . 69: if err != nil && err != io.EOF {
. . 70: return nil, err
. . 71: }
. . 72: if n > maxMemory {
. . 73: // too big, write to disk and flush buffer
(pprof) list postIndex
Total: 338.26MB
ROUTINE ======================== main.postIndex in /home/isucon/private_isu/webapp/golang/app.go
0 299.29MB (flat, cum) 88.48% of Total
. . 612: Me User
. . 613: }{p, me})
. . 614:}
. . 615:
. . 616:func postIndex(w http.ResponseWriter, r *http.Request) {
. 512.17kB 617: me := getSessionUser(r)
. . 618: if !isLogin(me) {
. . 619: http.Redirect(w, r, "/login", http.StatusFound)
. . 620: return
. . 621: }
. . 622:
. 298.79MB 623: if r.FormValue("csrf_token") != getCSRFToken(r) {
. . 624: w.WriteHeader(StatusUnprocessableEntity)
. . 625: return
. . 626: }
メモリーを使ってる箇所はわかりましたが、どう見てもリークではないです。
ファイルアップロードの効率化
ググったり、multipart の ReadForm 周辺のソースコードを読んで、原因を調べ、対策を考えます。
原因:
postIndexで最初にRequest.FormValueを呼んだときにフォームを解析する処理が実行されていて、そこでアップロードされたファイルを読み込んでいる。- アップロードされたファイルは、ある程度 (デフォルト32MB) までは
bytes.Bufferに読み込まれ、それを超える場合はテンポラリファイルに書き出される。 bytes.Bufferは小さいサイズからどんどんリアロケートして拡大していくので、短時間に大量のアロケートが発生する。アプリの性能が上がるのに連動してファイルのアップロードの頻度が増え、アロケートのペースが速すぎてGCが追いつかなくなったようだ。
対策:
- multipart を解析するときに明示的に
ParseMultipartFormを呼び出し、32MBよりももっと早めにテンポラリファイルを使うようにする。 - 並列にファイルアップロードの解析が走らないように Mutex で保護する。
--- a/app.go
+++ b/app.go
@@ -17,6 +17,7 @@ import (
"regexp"
"strconv"
"strings"
+ "sync"
"time"
"github.com/bradfitz/gomemcache/memcache"
@@ -613,6 +614,8 @@ func getPostsID(c web.C, w http.ResponseWriter, r *http.Request) {
}{p, me})
}
+var uploadM sync.Mutex
+
func postIndex(w http.ResponseWriter, r *http.Request) {
me := getSessionUser(r)
if !isLogin(me) {
@@ -620,6 +623,9 @@ func postIndex(w http.ResponseWriter, r *http.Request) {
return
}
+ uploadM.Lock()
+ defer uploadM.Unlock()
+ r.ParseMultipartForm(1 << 10)
if r.FormValue("csrf_token") != getCSRFToken(r) {
w.WriteHeader(StatusUnprocessableEntity)
return
これでもまだ足りませんでした。なので、一旦メモリに置いてからファイルに書き出すのを止め、一時ファイルにコピーして、それを image/ ディレクトリ配下にリネームするように改修しました。
--- a/app.go
+++ b/app.go
@@ -80,26 +80,21 @@ func init() {
}
func writeImage(id int, mime string, data []byte) {
- var ext string
- switch mime {
- case "image/jpeg":
- ext = ".jpg"
- case "image/png":
- ext = ".png"
- case "image/gif":
- ext = ".gif"
- default:
- fmt.Println("Failed to write file: ", id, mime)
- return
+ fn := imagePath(id, mime)
+ err := ioutil.WriteFile(fn, data, 0666)
+ if err != nil {
+ log.Println("failed to write file; path=%q, err=%v", fn, err)
}
+}
- fn := fmt.Sprintf("../public/image/%d%s", id, ext)
- f, err := os.OpenFile(fn, os.O_WRONLY|os.O_CREATE, 0666)
- if err != nil {
- panic(err)
+func copyImage(id int, src, mime string) {
+ dst := imagePath(id, mime)
+ if err := os.Chmod(src, 0666); err != nil {
+ log.Println("failed to chmod: path=%v, %v", src, err)
+ }
+ if err := os.Rename(src, dst); err != nil {
+ log.Println("failed to rename; src=%q, dst=%q; %v", src, dst, err)
}
- f.Write(data)
- f.Close()
}
func dbInitialize() {
@@ -260,6 +255,19 @@ func imageURL(p Post) string {
return "/image/" + strconv.Itoa(p.ID) + ext
}
+func imagePath(id int, mime string) string {
+ var ext string
+ switch mime {
+ case "image/jpeg":
+ ext = ".jpg"
+ case "image/png":
+ ext = ".png"
+ case "image/gif":
+ ext = ".gif"
+ }
+ return fmt.Sprintf("../public/image/%d%s", id, ext)
+}
+
func isLogin(u User) bool {
return u.ID != 0
}
@@ -662,16 +670,20 @@ func postIndex(w http.ResponseWriter, r *http.Request) {
}
}
- filedata, rerr := ioutil.ReadAll(file)
- if rerr != nil {
- fmt.Println(rerr.Error())
+ tf, err := ioutil.TempFile("../upload", "img-")
+ if err != nil {
+ log.Panicf("failed to create image: %v", err)
}
-
- if len(filedata) > UploadLimit {
+ written, err := io.CopyN(tf, file, UploadLimit+1)
+ if err != nil && err != io.EOF {
+ log.Panicf("failed to write to temporary file: %v", err)
+ }
+ if written > UploadLimit {
+ os.Remove(tf.Name())
+ tf.Close()
session := getSession(r)
session.Values["notice"] = "ファイルサイズが大きすぎます"
session.Save(r, w)
-
http.Redirect(w, r, "/", http.StatusFound)
return
}
@@ -694,7 +706,8 @@ func postIndex(w http.ResponseWriter, r *http.Request) {
fmt.Println(lerr.Error())
return
}
- writeImage(int(pid), mime, filedata)
+ tf.Close()
+ copyImage(int(pid), tf.Name(), mime)
http.Redirect(w, r, "/posts/"+strconv.FormatInt(pid, 10), http.StatusFound)
return
}
これでメモリ不足は落ち着き、とりあえず静的ファイルと投稿画像を nginx から返す設定でベンチが完走しました。
{"pass":true,"score":32771,"success":27352,"fail":0,"messages":[]}
本当は、 http.Request の Form 解析によって作られる一時ファイルからアプリケーションの一時ファイルへのコピーが無駄なので、 Request の Form 系のAPIを使わず直接 Body を解析するともっと効率が良くなります。（難しそうに聞こえるかもしれませんが、ほぼ Request.ParseMultipartFormのコピペで行けるはずです）
ただし、この時点でメモリ不足は収まったので、これ以上はディスク書き込みがネックになってどうしようもなくなるまで置いておいて、本来やりたかったチューニングにもどりましょう。
まとめ
スコア: 4745 (初期状態) -> 30076 (前回) -> 32771 (nginxで画像配信)
思っていたより性能向上が少ないです。これは次回に持ち越しです。
今回はファイルアップロードによるメモリ不足に悩まされましたが、(2010年代も後半になって)1GBメモリのマシンで、すごい大量にアップロードされる画像を裁くのは ISUCON だとありがちです。ちゃんと効率のいいファイルアップロードのやり方を調べておきましょう。
また、自分が使う予定の言語でメモリ不足を調査する方法も調べておきましょう。(例えば Python なら標準ライブラリの tracemalloc が使えると思います。)
@methane
pixiv private isucon 2016 攻略 (2/5)
攻略記事一覧:
アプリを読む
ソースコードを読みながらだいたいの構成を把握していきます。
- フレームワークは goji を使っている。 goji のサイトを見ると同じ名前で新しいフレームワークを作り直したみたいだけど、これは古い方を使ってるみたいです。
- セッションは Gorilla のライブラリに memcached store を組み合わせている
- テンプレートをレンダリングのたびにコンパイルしてるのが重そう。
- コメントのユーザーをいちいちユーザーテーブルから引っ張ってるのも JOIN かキャッシュが効きそう。
- 画像データを MySQL に突っ込んでるのは、ファイルに出す必要がありそう。(ファイルなら数十KBずつ読んでは返せるけれど、DBだと簡単な方法だと一度に全体をメモリに読んでしまうので、並列にアクセスが来たときにメモリが足りなくなります。）
読んでいると改善したいポイントがたくさん出てくるものの、いきなりあちこち改造しだすとバグったときに困ります。はじめは基礎的な設定とボトルネックに絞ったチューニングです。
最初にDBのコネクションプール設定できてないので設定しておきましょう。2コアなんでそんなにたくさんコネクションあっても仕方ないハズ。とりあえずちょい多めの8にしておきます。
+ db.SetMaxOpenConns(8)
+ db.SetMaxIdleConns(8)
defer db.Close()
アクセスログを読む
事前に用意しておいたアクセスログ集計ツール（自作してもいいですし、過去のいろいろな方のISUCONの記事を探してみれば良いツールが紹介されているはずです）を、アクセスログやアプリのURLルーティングの設定を参考にカスタマイズしましょう。
僕の場合は自作スクリプトで、次のような集計をしました。
Request by count 8028 GET /image/* 644 GET / 551 GET /js/jquery-2.2.0.js 551 GET /css/style.css 551 GET /js/jquery.timeago.ja.js 551 GET /favicon.ico 551 GET /js/jquery.timeago.js 551 GET /js/main.js 450 POST /login 299 GET /posts/* 235 GET /@user 130 POST / 98 GET /login 90 POST /comment 79 POST /register 78 GET /admin/banned 56 GET /posts?max_created_at= 50 GET /logout 1 GET /initialize Request by total time (total avg [sec]) 198.379 0.308041925466 GET / 168.858 0.021033632287 GET /image/* 47.605 0.202574468085 GET /@user 34.491 0.0766466666667 POST /login 30.444 0.543642857143 GET /posts?max_created_at= 15.095 0.0504849498328 GET /posts/* 7.068 0.0894683544304 POST /register 6.7 0.0515384615385 POST / 6.51 0.0118148820327 GET /favicon.ico 6.483 0.0117658802178 GET /js/jquery-2.2.0.js 5.784 0.010497277677 GET /js/jquery.timeago.js 5.213 0.0094609800363 GET /js/jquery.timeago.ja.js 5.095 0.00924682395644 GET /css/style.css 4.997 0.00906896551724 GET /js/main.js 2.478 0.0275333333333 POST /comment 2.257 0.0230306122449 GET /login 1.314 0.0168461538462 GET /admin/banned 1.131 0.02262 GET /logout 0.061 0.061 GET /initialize Request by out bytes (total avg) 2485959550 309661 GET /image/* 142499069 258619 GET /js/jquery-2.2.0.js 12206011 18953 GET / 4287247 18243 GET /@user 4105501 7451 GET /js/jquery.timeago.js 1912146 34145 GET /posts?max_created_at= 1108574 3707 GET /posts/* 980229 1779 GET /css/style.css 487635 885 GET /js/main.js 357048 648 GET /js/jquery.timeago.ja.js 195356 434 POST /login 177772 1814 GET /login 149872 272 GET /favicon.ico 34286 434 POST /register 23530 181 POST / 22200 444 GET /logout 16833 187 POST /comment 13104 168 GET /admin/banned 161 161 GET /initialize
これで考えるのは、主に次の2点です。
- トップページと
/image/に掛かる時間が一番重い。特にトップページを最初にチューニングするのが良さそう。 - 帯域は
/image/が支配的。帯域ネックになるようだったら、画像は再圧縮しにくいので、ヘッダーを適切に設定すればクライアントに "304 Not Modified" を返せるようになって大きなブレークスルーがあるかもしれない。
pprof
とりあえず app の CPU が重いので、CPUプロファイルから始めましょう。 pprof の基本的な使い方は、以前に Blog を書いたのでそれを参照してください。
diff --git a/app.go b/app.go
index 861ff03..eb52f47 100644
--- a/app.go
+++ b/app.go
@@ -9,6 +9,7 @@ import (
"io/ioutil"
"log"
"net/http"
+ _ "net/http/pprof"
"net/url"
"os"
"os/exec"
@@ -826,6 +827,8 @@ func main() {
+
+ db.SetMaxOpenConns(8)
+ db.SetMaxIdleConns(8)
defer db.Close()
+ go http.ListenAndServe(":3000", nil)
+
goji.Get("/initialize", getInitialize)
goji.Get("/login", getLogin)
goji.Post("/login", postLogin)
$ go tool pprof app http://localhost:3000/debug/pprof/profile
Fetching profile from http://localhost:3000/debug/pprof/profile
Please wait... (30s)
Saved profile in /home/isucon/pprof/pprof.localhost:3000.samples.cpu.001.pb.gz
Entering interactive mode (type "help" for commands)
(pprof) top 10
14440ms of 29650ms total (48.70%)
Dropped 546 nodes (cum <= 148.25ms)
Showing top 10 nodes out of 214 (cum >= 7370ms)
flat flat% sum% cum cum%
2270ms 7.66% 7.66% 8650ms 29.17% runtime.mallocgc
2220ms 7.49% 15.14% 2220ms 7.49% runtime.memclr
2150ms 7.25% 22.39% 2840ms 9.58% runtime.scanobject
1930ms 6.51% 28.90% 2060ms 6.95% syscall.Syscall
1280ms 4.32% 33.22% 1280ms 4.32% runtime.heapBitsSetType
1240ms 4.18% 37.40% 1270ms 4.28% runtime.(*mspan).sweep.func1
1000ms 3.37% 40.78% 1000ms 3.37% runtime.memmove
930ms 3.14% 43.91% 5070ms 17.10% database/sql.convertAssign
750ms 2.53% 46.44% 2240ms 7.55% time.parse
670ms 2.26% 48.70% 7370ms 24.86% github.com/go-sql-driver/mysql.(*textRows).readRow
メモリ管理が重いですね。あと MySQL から受け取った結果をパースしてる部分が重い。
メモリ管理が重い場合、メモリのアロケートしてる部分を見つけて潰していく方法もありますが、もっと高いレイヤーでのアプリのチューニングの方が先です。この場合 -cum オプションを使ってトップダウンにプロファイルを見ます。
(pprof) top -cum 40
10.25s of 29.65s total (34.57%)
Dropped 546 nodes (cum <= 0.15s)
Showing top 40 nodes out of 214 (cum >= 2.22s)
flat flat% sum% cum cum%
0 0% 0% 28.99s 97.77% runtime.goexit
0 0% 0% 25.69s 86.64% net/http.(*conn).serve
0 0% 0% 25.40s 85.67% net/http.(*ServeMux).ServeHTTP
...
0 0% 0% 25.08s 84.59% github.com/zenazn/goji/web/middleware.Recoverer.func1
0 0% 0% 22.42s 75.62% github.com/zenazn/goji/web.netHTTPHandlerFuncWrap.ServeHTTPC
0 0% 0% 20.61s 69.51% main.getIndex
0 0% 0% 20.26s 68.33% github.com/jmoiron/sqlx.(*DB).Select
0 0% 0% 20.26s 68.33% github.com/jmoiron/sqlx.Select
...
上位にいるリクエストハンドラーは getIndex だけです。ここに集中しましょう。
ソースコードの行単位のプロファイルを見るにはデバッグ情報が必要なので、 pprof 起動時にアプリのバイナリを指定しておく必要があります。
バイナリを指定し忘れて URL だけでプロファイルを取ってしまった場合も、起動したときの "Saved profile in ..." に表示されているパスにプロファイル結果が保存されているので、再度プロファイリングしなくても
go tool pprof app <プロファイル結果のパス> で大丈夫です。
isucon:~/private_isu/webapp/golang$ go tool pprof app /home/isucon/pprof/pprof.localhost:3000.samples.cpu.001.pb.gz
Entering interactive mode (type "help" for commands)
(pprof) list main.getIndex
Total: 29.65s
ROUTINE ======================== main.getIndex in /home/isucon/private_isu/webapp/golang/app.go
0 20.61s (flat, cum) 69.51% of Total
. . 388:
. . 389: http.Redirect(w, r, "/", http.StatusFound)
. . 390:}
. . 391:
. . 392:func getIndex(w http.ResponseWriter, r *http.Request) {
. 120ms 393: me := getSessionUser(r)
. . 394:
. . 395: results := []Post{}
. . 396:
. 18.39s 397: err := db.Select(&results, "SELECT `id`, `user_id`, `body`, `mime`, `created_at` FROM `posts` ORDER BY `created_at` DESC")
. . 398: if err != nil {
. . 399: fmt.Println(err)
. . 400: return
. . 401: }
. . 402:
. 1.34s 403: posts, merr := makePosts(results, getCSRFToken(r), false)
. . 404: if merr != nil {
. . 405: fmt.Println(merr)
. . 406: return
. . 407: }
. . 408:
. . 409: fmap := template.FuncMap{
. . 410: "imageURL": imageURL,
. . 411: }
. . 412:
. . 413: template.Must(template.New("layout.html").Funcs(fmap).ParseFiles(
. . 414: getTemplPath("layout.html"),
. . 415: getTemplPath("index.html"),
. . 416: getTemplPath("posts.html"),
. . 417: getTemplPath("post.html"),
. 70ms 418: )).Execute(w, struct {
. . 419: Posts []Post
. . 420: Me User
. . 421: CSRFToken string
. . 422: Flash string
. 690ms 423: }{posts, me, getCSRFToken(r), getFlash(w, r, "notice")})
. . 424:}
. . 425:
. . 426:func getAccountName(c web.C, w http.ResponseWriter, r *http.Request) {
. . 427: user := User{}
. . 428: uerr := db.Get(&user, "SELECT * FROM `users` WHERE `account_name` = ? AND `del_flg` = 0", c.URLParams["accountName"])
前回の記事の最後で myprofiler で見つけた、 posts からの LIMIT なしクエリが重い問題ですね。MySQL 側だけでなく、その大量の結果を全件取得してパースしてる app 側でも一番重くなっているようです。
このクエリの結果を利用している makePosts() の中を見てみると、ループの終端にこんな if 文があります。
if len(posts) >= postsPerPage {
break
}
この手前に continue 文もないので、このまま postsPerPage で LIMIT しましょう。 (注: これが確認不足で後でハマります)
diff --git a/app.go b/app.go
index eb52f47..3dd9804 100644
--- a/app.go
+++ b/app.go
@@ -394,7 +394,7 @@ func getIndex(w http.ResponseWriter, r *http.Request) {
results := []Post{}
- err := db.Select(&results, "SELECT `id`, `user_id`, `body`, `mime`, `created_at` FROM `posts` ORDER BY `created_at` DESC")
+ err := db.Select(&results, "SELECT `id`, `user_id`, `body`, `mime`, `created_at` FROM `posts` ORDER BY `created_at` DESC LIMIT 20")
if err != nil {
fmt.Println(err)
return
さて、計測です。本当は計測とプロファイルは別にした方がいいですが、時間が勿体無いのでプロファイルしながら計測です。
スコア:
{"pass":true,"score":12848,"success":22272,"fail":1201,"messages":["1ページに表示される画像の数が足りません (GET /)","リダイレクト先URLが正しくありません: expected '^/$', got '/login' (GET /login)"]}
あらら。エラーがでてきました。アプリのログを見ると、
fork/exec /bin/bash: cannot allocate memory
メモリが足りなくて fork に失敗してました。
top:
PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND 11931 isucon 20 0 406248 183372 9052 S 74.8 17.9 0:19.55 app 720 mysql 20 0 1226416 215076 10404 S 65.5 21.0 3:24.11 mysqld
CPU 使用率は app と mysql がだいたい一緒ですね。足しても200にだいぶ届かないので、CPU以外の部分がネックにりはじめていそうです。
myprofiler:
17 SELECT * FROM `posts` WHERE `id` = N 12 SELECT `id`, `user_id`, `body`, `mime`, `created_at` FROM `posts` WHERE `created_at` <= S ORDER BY `created_at` DESC 4 SELECT * FROM `users` WHERE `id` = N 3 SELECT * FROM `users` WHERE `id` = ?
posts から id 指定で1レコード取得が重くなりました。 N+1 かな？
外部プロセス呼び出しをやめる
fork に失敗するのは、多分（スワップがないせいで？）オーバーコミットがオフになっていて、fork した瞬間に app と同じだけのメモリを持ってるもう1プロセスを作れないからだと思います。
CPU使用率が2コアなのに200%に全然届かないのも fork のせい (Go のランタイムの都合上 fork するためには全 goroutine を一旦止めないといけなくて待ち時間が発生する) かもしれないので、メモリ使用量削減のために画像ファイルをDBから切り出すよりも外部プロセス呼び出しをやめる方を優先しましょう。
外部プロセスを読んでるところを見ると、 openssl dgst -sha512 コマンドで sha512 ダイジェストを計算しているようです。 Go で sha512 を計算する方法を調べて、同じ出力をするプログラムを書いてみます。
$ cat t.go < app.go
package main
import (
"crypto/sha512"
"fmt"
"io/ioutil"
"os"
)
func main() {
data, _ := ioutil.ReadAll(os.Stdin)
fmt.Printf("%x\n", sha512.Sum512(data))
}
isucon@ip-10-0-1-202:~/private_isu/webapp/golang$ go run t.go < t.go
b252b55576a4f4e321d5761b6dc980b8ee41fd9767765c785861a73b736f6a59aa7f40f7ba0d92c508dea32a20bc800e0198056c3dc8b33d5ac445f27b163d17
isucon@ip-10-0-1-202:~/private_isu/webapp/golang$ openssl dgst -sha512 < t.go
(stdin)= b252b55576a4f4e321d5761b6dc980b8ee41fd9767765c785861a73b736f6a59aa7f40f7ba0d92c508dea32a20bc800e0198056c3dc8b33d5ac445f27b163d17
これを参考に app.go を書き換えます。
@@ -125,14 +125,7 @@ func escapeshellarg(arg string) string {
}
func digest(src string) string {
- // opensslのバージョンによっては (stdin)= というのがつくので取る
- out, err := exec.Command("/bin/bash", "-c", `printf "%s" `+escapeshellarg(src)+` | openssl dgst -sha512 | sed 's/^.*= //'`).Output()
- if err != nil {
- fmt.Println(err)
- return ""
- }
-
- return strings.TrimSuffix(string(out), "\n")
+ return fmt.Sprintf("%x", sha512.Sum512([]byte(src)))
}
さて、プロファイル＆計測です。アプリのログには fork エラーが消えました。
スコア:
{"pass":true,"score":26755,"success":24050,"fail":119,"messages":["1ページに表示される画像の数が足りません (GET /)"]}
うーん、まだエラー出てますね。これは LIMIT 足したのがマズいかな？
top:
Tasks: 84 total, 1 running, 83 sleeping, 0 stopped, 0 zombie %Cpu(s): 54.2 us, 20.7 sy, 0.0 ni, 15.0 id, 1.4 wa, 0.0 hi, 8.3 si, 0.4 st KiB Mem: 1022972 total, 958404 used, 64568 free, 18292 buffers KiB Swap: 0 total, 0 used, 0 free. 425600 cached Mem PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND 720 mysql 20 0 1357488 210336 4476 S 78.6 20.6 5:19.05 mysqld 763 isucon 20 0 619612 198632 9120 S 70.2 19.4 0:13.54 app 2904 www-data 20 0 92028 4088 1928 S 11.3 0.4 0:29.40 nginx 2572 isucon 20 0 34344 11148 2160 S 7.3 1.1 0:28.48 tmux
idle が 15% まで下がってます。狙い通り。 あと、 tmux が 7% まで来ました。 Goji のログがリッチすぎるので、最後には切らないといけませんね。
myprofiler:
## 2016-05-25 20:18:44.06 +0900 13 SELECT * FROM `posts` WHERE `id` = N 9 SELECT `id`, `user_id`, `body`, `mime`, `created_at` FROM `posts` WHERE `created_at` <= S ORDER BY `created_at` DESC 9 SELECT * FROM `comments` WHERE `post_id` = N ORDER BY `created_at` DESC LIMIT N 6 SELECT * FROM `users` WHERE `id` = ? 6 SELECT `id` FROM `posts` WHERE `user_id` = N 4 SELECT * FROM `users` WHERE `id` = N 4 SELECT COUNT(*) AS `count` FROM `comments` WHERE `post_id` = ? 2 SELECT COUNT(*) AS `count` FROM `comments` WHERE `post_id` = N 2 SELECT * FROM `comments` WHERE `post_id` = ? ORDER BY `created_at` DESC LIMIT N 2 SELECT `id`, `user_id`, `body`, `mime`, `created_at` FROM `posts` WHERE `user_id` = N ORDER BY `created_at` DESC
バグ修正
makePosts() を見直してみると、投稿したユーザーが論理削除されていたら配列への追加をしないようなコードになっていました。
(Go だと early return (continue) イディオムを使うことが多いのでこの部分を見逃していました)
if p.User.DelFlg == 0 {
posts = append(posts, p)
}
SELECT の段階で強引に JOIN してこの論理削除のフィルタリングを実行してしまいます。
@@ -394,7 +387,7 @@ func getIndex(w http.ResponseWriter, r *http.Request) {
results := []Post{}
- err := db.Select(&results, "SELECT `id`, `user_id`, `body`, `mime`, `created_at` FROM `posts` ORDER BY `created_at` DESC LIMIT 20")
+ err := db.Select(&results, "SELECT posts.`id`, `user_id`, `body`, `mime`, posts.`created_at` FROM `posts` INNER JOIN `users` ON posts.user_id=users.id WHERE users.del_flg = 0 ORDER BY `created_at` DESC LIMIT 20")
if err != nil {
fmt.Println(err)
return
スコア:
{"pass":true,"score":27399,"success":23615,"fail":0,"messages":[]}
今度はちゃんと通りました。
top:
Tasks: 83 total, 4 running, 79 sleeping, 0 stopped, 0 zombie %Cpu(s): 53.9 us, 23.6 sy, 0.0 ni, 9.8 id, 4.2 wa, 0.0 hi, 8.2 si, 0.2 st KiB Mem: 1022972 total, 948340 used, 74632 free, 12604 buffers KiB Swap: 0 total, 0 used, 0 free. 486056 cached Mem PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND 720 mysql 20 0 1359224 209144 4576 S 85.9 20.4 6:06.96 mysqld 910 isucon 20 0 487224 139892 8884 S 67.9 13.7 0:09.58 app 2904 www-data 20 0 91852 2828 844 R 10.7 0.3 0:35.40 nginx 2572 isucon 20 0 34472 10100 928 S 6.7 1.0 0:33.64 tmux
ちょっと mysql が重いですね。
myprofiler:
15 SELECT * FROM `posts` WHERE `id` = N 7 SELECT `id`, `user_id`, `body`, `mime`, `created_at` FROM `posts` WHERE `created_at` <= S ORDER BY `created_at` DESC 6 SELECT * FROM `comments` WHERE `post_id` = N ORDER BY `created_at` DESC LIMIT N 5 SELECT * FROM `users` WHERE `id` = ? 5 INSERT INTO `comments` (`post_id`, `user_id`, `comment`) VALUES (?,?,?) 5 SELECT COUNT(*) AS `count` FROM `comments` WHERE `post_id` = N 5 SELECT `id`, `user_id`, `body`, `mime`, `created_at` FROM `posts` WHERE `user_id` = N ORDER BY `created_at` DESC 4 INSERT INTO `posts` (`user_id`, `mime`, `imgdata`, `body`) VALUES (?,?,?,?) 4 INSERT INTO `users` (`account_name`, `passhash`) VALUES (?,?) 3 SELECT * FROM `users` WHERE `id` = N
JOIN を足したけど、それでもまだ post を id で引くのが重いみたいです。
pprof top40 -cum:
...
0 0% 0.38% 13.88s 76.18% github.com/zenazn/goji/web/middleware.AutomaticOptions.func1
0.01s 0.055% 0.44% 8.85s 48.57% github.com/zenazn/goji/web.netHTTPHandlerFuncWrap.ServeHTTPC
0 0% 0.44% 6.11s 33.53% main.getIndex
0.02s 0.11% 0.55% 4.92s 27.00% github.com/jmoiron/sqlx.(*DB).Get
0.01s 0.055% 0.6% 4.90s 26.89% github.com/jmoiron/sqlx.Get
0 0% 0.6% 4.78s 26.23% github.com/zenazn/goji/web.handlerFuncWrap.ServeHTTPC
0.02s 0.11% 0.71% 4.65s 25.52% main.makePosts
3.82s 20.97% 21.68% 4.06s 22.28% syscall.Syscall
...
pprof list makePosts:
ROUTINE ======================== main.makePosts in /home/isucon/private_isu/webapp/golang/app.go
20ms 4.65s (flat, cum) 25.52% of Total
. . 173:}
. . 174:
. . 175:func makePosts(results []Post, CSRFToken string, allComments bool) ([]Post, error) {
. . 176: var posts []Post
. . 177:
10ms 10ms 178: for _, p := range results {
. 1.05s 179: err := db.Get(&p.CommentCount, "SELECT COUNT(*) AS `count` FROM `comments` WHERE `post_id` = ?", p.ID)
. . 180: if err != nil {
. . 181: return nil, err
. . 182: }
. . 183:
. . 184: query := "SELECT * FROM `comments` WHERE `post_id` = ? ORDER BY `created_at` DESC"
. . 185: if !allComments {
. 20ms 186: query += " LIMIT 3"
. . 187: }
. . 188: var comments []Comment
. 1.38s 189: cerr := db.Select(&comments, query, p.ID)
. . 190: if cerr != nil {
. . 191: return nil, cerr
. . 192: }
. . 193:
. . 194: for i := 0; i < len(comments); i++ {
. 770ms 195: uerr := db.Get(&comments[i].User, "SELECT * FROM `users` WHERE `id` = ?", comments[i].UserID)
. . 196: if uerr != nil {
. . 197: return nil, uerr
. . 198: }
. . 199: }
. . 200:
. . 201: // reverse
. . 202: for i, j := 0, len(comments)-1; i < j; i, j = i+1, j-1 {
. . 203: comments[i], comments[j] = comments[j], comments[i]
. . 204: }
. . 205:
10ms 10ms 206: p.Comments = comments
. . 207:
. 1.35s 208: perr := db.Get(&p.User, "SELECT * FROM `users` WHERE `id` = ?", p.UserID)
. . 209: if perr != nil {
. . 210: return nil, perr
. . 211: }
. . 212:
. . 213: p.CSRFToken = CSRFToken
. . 214:
. . 215: if p.User.DelFlg == 0 {
. 60ms 216: posts = append(posts, p)
. . 217: }
. . 218: if len(posts) >= postsPerPage {
. . 219: break
. . 220: }
. . 221: }
時間のかかってるクエリがコメント取得を除いて1レコード取得するだけのクエリなので、簡単なクエリを大量に投げてるのが問題で重いのでしょう。
プレースホルダがあるクエリは、デフォルトでは prepared statement を使い捨てにしている (prepare, execute, close の3コマンド) ので、明示的に prepared statement を再利用するコードを書くか、 prepared statement を使わないようにするのがいいです。
最高性能を目指すなら再利用の方がいいですが、改修が簡単なのは prepared statement を使わない方です。 dsn に interpolateParams=true を足すだけ！ (僕が実装した機能です。 参考)
diff:
@@ -805,7 +805,7 @@ func main() {
}
dsn := fmt.Sprintf(
- "%s:%s@tcp(%s:%s)/%s?charset=utf8mb4&parseTime=true&loc=Local",
+ "%s:%s@tcp(%s:%s)/%s?charset=utf8mb4&parseTime=true&loc=Local&interpolateParams=true",
user,
password,
host,
スコア:
{"pass":true,"score":30076,"success":25687,"fail":0,"messages":[]}
30k 点に到達。
top:
Tasks: 83 total, 5 running, 78 sleeping, 0 stopped, 0 zombie %Cpu(s): 63.1 us, 17.4 sy, 0.0 ni, 8.5 id, 3.4 wa, 0.0 hi, 7.4 si, 0.2 st KiB Mem: 1022972 total, 960140 used, 62832 free, 13192 buffers KiB Swap: 0 total, 0 used, 0 free. 472760 cached Mem PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND 720 mysql 20 0 1359224 209132 4128 S 79.7 20.4 6:56.71 mysqld 1010 isucon 20 0 514368 157192 8888 S 66.8 15.4 0:08.93 app 2904 www-data 20 0 91876 2824 844 R 11.3 0.3 0:41.86 nginx 1015 isucon 20 0 21176 18648 3444 R 8.3 1.8 0:01.31 myprofiler 2572 isucon 20 0 34920 10472 916 S 7.3 1.0 0:38.28 tmux
myprofiler:
18 SELECT * FROM `posts` WHERE `id` = N 11 INSERT INTO `posts` (`user_id`, `mime`, `imgdata`, `body`) VALUES (N,S,_binaryS,S) 9 SELECT * FROM `users` WHERE `id` = N 7 SELECT * FROM `comments` WHERE `post_id` = N ORDER BY `created_at` DESC LIMIT N 6 SELECT `id`, `user_id`, `body`, `mime`, `created_at` FROM `posts` WHERE `user_id` = N ORDER BY `created_at` DESC 5 SELECT `id`, `user_id`, `body`, `mime`, `created_at` FROM `posts` WHERE `created_at` <= S ORDER BY `created_at` DESC 4 SELECT COUNT(*) AS `count` FROM `comments` WHERE `post_id` = N 2 INSERT INTO `users` (`account_name`, `passhash`) VALUES (S,S) 1 SELECT * FROM `users` WHERE `account_name` = S AND `del_flg` = N 1 INSERT INTO `comments` (`post_id`, `user_id`, `comment`) VALUES (N,N,S)
pprof:
(pprof) top40 -cum
4.23s of 18.58s total (22.77%)
Dropped 583 nodes (cum <= 0.09s)
Showing top 40 nodes out of 317 (cum >= 2.07s)
flat flat% sum% cum cum%
0 0% 0% 17.10s 92.03% runtime.goexit
...
0 0% 0.22% 8.84s 47.58% github.com/zenazn/goji/web.netHTTPHandlerFuncWrap.ServeHTTPC
0 0% 0.22% 5.66s 30.46% main.getIndex
0 0% 0.22% 4.90s 26.37% github.com/zenazn/goji/web.handlerFuncWrap.ServeHTTPC
0 0% 0.22% 4.04s 21.74% github.com/jmoiron/sqlx.(*DB).Get
0.04s 0.22% 0.43% 4.04s 21.74% github.com/jmoiron/sqlx.Get
0 0% 0.43% 3.73s 20.08% html/template.(*Template).Execute
0.03s 0.16% 0.59% 3.50s 18.84% main.makePosts
0 0% 0.59% 3.32s 17.87% github.com/jmoiron/sqlx.(*DB).Select
0 0% 0.59% 3.32s 17.87% github.com/jmoiron/sqlx.Select
0.93s 5.01% 5.60% 3.23s 17.38% runtime.mallocgc
0 0% 5.60% 3.12s 16.79% text/template.(*Template).Execute
0.08s 0.43% 6.03% 3.12s 16.79% text/template.(*state).walk
0.01s 0.054% 6.08% 3.07s 16.52% text/template.(*state).walkTemplate
0 0% 6.08% 3.02s 16.25% text/template.(*state).walkRange
0 0% 6.08% 3.02s 16.25% text/template.(*state).walkRange.func1
0.13s 0.7% 6.78% 2.96s 15.93% runtime.systemstack
そろそろテンプレートの重さが上位に見え始めましたが、まだDBの方が重い。
まとめ
スコア: 4745 (初期状態) -> 14208 (前回) -> 30076 (今回)
さて、そろそろプロファイルで重いところを潰すチューニングは、乾いた雑巾絞りに近づいてきました。 次回はもっとドラスティックなチューニングに移っていきたいと思います。
今回は pprof や myprofiler を使ったチューニングの紹介の意図があったのでちょっとやりすぎてしまいました。 実際にはもっと早めに大改造を必要とするようなチューニングを考えて実行しないと、後半に時間が足りなくてジリ貧になってしまうので気をつけましょう。
@methane
pixiv private isucon 2016 攻略 (1/5)
攻略記事一覧:
pixiv さんが社内で開催したプライベート ISUCON の AMI を公開してくれたので、手順を残しながら攻略していきます。
この記事の対象読者は途中で何をすればいいかわからなくなってしまう ISUCON 初心者です。 Go を利用して攻略していきますが、他の言語で参加する場合でも考え方などは参考になると思います。
最低限の初期設定
ssh の公開鍵を入れたり、エディターや git などのツール類をインストール・設定します。
このあたりは事前に自分用のチートシートやスクリプトを作って、手早くできるようにしておきましょう。
マシン調査
スペック
とりあえず CPU とメモリくらいはちゃんと把握しておきましょう。
$ grep processor /proc/cpuinfo
processor : 0
processor : 1
$ free -m
total used free shared buffers cached
Mem: 998 906 92 12 25 335
-/+ buffers/cache: 545 453
Swap: 0 0 0
CPUは2コアですね。メモリはトータル1GBでスワップなし。要注意です。
ps aux
何が動いているか確認します。 メールサーバーとか、AppArmor のような、競技に明らかに不要そうなデーモンは、ベンチマークスコアを安定させるためとメモリの節約のために落としておいたほうが良いです。
今回は特に何もする必要はありませんでした。
アプリの仕様把握
初期状態に復元する手順を確認してから、実際にアプリをブラウザからさわってみましょう。
初期状態への復元は、 tar でアーカイブしてローカルに持ってきておいたり、 mysqldump を取ったりしておくと良いです。
ただし今回の場合はAMIからやり直せるので、 /initialize というパスで初期化されると言うことだけアプリのコードで確認し、バックアップは手抜きしました。
ISUCON 本番では初期状態を復元するのに必要なデータをオペミスで失うと即死する恐れがあるので注意しましょう。
ブラウザのデバッグ機能でどういう通信をしているのか見たり、アプリのコードのURLルーティング部分を中心に軽く目を通したり、 mysqldump --no-data isuconp で取得したスキーマを参考に、ざっくりと全体像を把握していきます。
nginx の基礎設定
アクセスログを事前に用意しておいたフォーマットに変更して、 upstream への keepalive を付ける。
コア数少ないので worker_processes を 1 にして、 keepalive の効率を上げる。
静的ファイルを nginx から返す設定は、アプリの動作を把握してからでも遅くない。 Go 以外を使う人は、完全に静的なファイルが分かった段階ですぐに、Go を使う人はある程度チューニングが進んで nginx を外すかどうかを判断するタイミングで nginx から返すようにしよう。
/etc/nginx/nginx.conf:
worker_processes 1;
...
##
# Logging Settings
##
log_format isucon '$time_local $msec\t$status\treqtime:$request_time\t'
'in:$request_length\tout:$bytes_sent\trequest:$request\t'
'acceptencoding:$http_accept_encoding\treferer:$http_referer\t'
'ua:$http_user_agent';
access_log /var/log/nginx/access.log isucon;
/etc/nginx/sites-enabled/isucon.conf:
upstream app {
server 127.0.0.1:8080;
keepalive 32;
}
server {
listen 80;
client_max_body_size 10m;
root /home/isucon/private_isu/webapp/public/;
location / {
proxy_set_header Host $host;
proxy_set_header X-Real-IP $remote_addr;
proxy_set_header X-Forwarded-For $proxy_add_x_forwarded_for;
proxy_pass http://app;
}
}
あと、今回は Go を使うので ruby と php のサービスも止めてしまいます。 Go のサービスは開発中はコマンドラインで起動したいのでここでは設定しません。
$ sudo systemctl stop isu-ruby $ sudo systemctl disable isu-ruby $ sudo systemctl stop php7.0-fpm $ sudo systemctl disable php7.0-fpm
MySQL の基礎設定
/etc/mysql/my.cnf を見てみます。ほぼディストリのデフォルトで使っているようなので、メモリ使用量削減とIO待ち削減のために次の設定だけ追加しておきます。
innodb_flush_method = O_DIRECT innodb_flush_log_at_trx_commit = 2
重いクエリを手早く見つけるためのツールを用意する。僕の場合は myprofiler を使う。
$ wget https://github.com/KLab/myprofiler/releases/download/0.1/myprofiler.linux_amd64.tar.gz $ tar xf myprofiler.linux_amd64.tar.gz $ sudo mv myprofiler /usr/local/bin/
myprofiler の使い方は、 myprofiler -user=root です。クエリが減ってきたら myprofiler -user=root -interval=0.2 くらいにサンプリング間隔を短くすると良いでしょう。それ以外のオプションは myprofiler -h で確認してください。
ベンチマークの実行とざっくり状況把握
スコア:
{"pass":true,"score":4745,"success":4408,"fail":0,"messages":[]}
top:
Tasks: 81 total, 1 running, 80 sleeping, 0 stopped, 0 zombie %Cpu(s): 94.1 us, 4.2 sy, 0.0 ni, 0.3 id, 0.0 wa, 0.0 hi, 1.3 si, 0.0 st KiB Mem: 1022972 total, 701036 used, 321936 free, 21396 buffers KiB Swap: 0 total, 0 used, 0 free. 346564 cached Mem PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND 720 mysql 20 0 1087768 140276 10724 S 142.8 13.7 0:52.09 mysqld 2908 isucon 20 0 582876 124364 8800 S 46.6 12.2 0:12.98 app 2904 www-data 20 0 91680 4800 2988 S 1.7 0.5 0:00.61 nginx
MySQL が app の3倍CPU食ってるのがわかります。
myprofiler:
198 SELECT * FROM `comments` WHERE `post_id` = N ORDER BY `created_at` DESC LIMIT N 124 SELECT COUNT(*) AS `count` FROM `comments` WHERE `post_id` = N 11 SELECT `id`, `user_id`, `body`, `mime`, `created_at` FROM `posts` ORDER BY `created_at` DESC 9 SELECT * FROM `comments` WHERE `post_id` = N ORDER BY `created_at` DESC 5 SELECT * FROM `posts` WHERE `id` = N 4 SELECT COUNT(*) AS count FROM `comments` WHERE `post_id` IN (...N) 2 SELECT * FROM `users` WHERE `id` = ? 2 SELECT `id`, `user_id`, `body`, `mime`, `created_at` FROM `posts` WHERE `created_at` <= S ORDER BY `created_at` DESC 1 SELECT * FROM users WHERE account_name = S AND del_flg = N 1 SELECT COUNT(*) AS count FROM `comments` WHERE `user_id` = N
comments の SELECT と COUNT が遅い事がわかる。その次に posts の select。
一番最初のチューニング: インデックス
上位3件のクエリについて、インデックスが有るか確認して、なければ張っておく。
mysql> show create table comments\G
*************************** 1. row ***************************
Table: comments
Create Table: CREATE TABLE `comments` (
`id` int(11) NOT NULL AUTO_INCREMENT,
`post_id` int(11) NOT NULL,
`user_id` int(11) NOT NULL,
`comment` text NOT NULL,
`created_at` timestamp NOT NULL DEFAULT CURRENT_TIMESTAMP,
PRIMARY KEY (`id`)
) ENGINE=InnoDB AUTO_INCREMENT=100049 DEFAULT CHARSET=utf8mb4
1 row in set (0.00 sec)
mysql> show create table posts\G
*************************** 1. row ***************************
Table: posts
Create Table: CREATE TABLE `posts` (
`id` int(11) NOT NULL AUTO_INCREMENT,
`user_id` int(11) NOT NULL,
`mime` varchar(64) NOT NULL,
`imgdata` mediumblob NOT NULL,
`body` text NOT NULL,
`created_at` timestamp NOT NULL DEFAULT CURRENT_TIMESTAMP,
PRIMARY KEY (`id`)
) ENGINE=InnoDB AUTO_INCREMENT=10056 DEFAULT CHARSET=utf8mb4
1 row in set (0.00 sec)
comments.post_id と posts.created_at にインデックスがない。重いクエリ上位3つがこれ。
mysql> create index post_id on comments (post_id); Query OK, 0 rows affected (0.19 sec) Records: 0 Duplicates: 0 Warnings: 0 mysql> create index created_at on posts (created_at); Query OK, 0 rows affected (0.03 sec) Records: 0 Duplicates: 0 Warnings: 0
とりあえずこれでもう一度計測しておきます。
top:
top - 18:13:32 up 2:13, 1 user, load average: 2.01, 0.84, 0.52 Tasks: 79 total, 1 running, 78 sleeping, 0 stopped, 0 zombie %Cpu(s): 74.0 us, 19.3 sy, 0.0 ni, 3.2 id, 0.2 wa, 0.0 hi, 3.4 si, 0.0 st KiB Mem: 1022972 total, 944288 used, 78684 free, 23344 buffers KiB Swap: 0 total, 0 used, 0 free. 462656 cached Mem PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND 2908 isucon 20 0 640148 174444 8800 S 109.7 17.1 0:44.93 app 720 mysql 20 0 1093212 212252 10740 S 58.5 20.7 1:56.57 mysqld
app が mysql の 2倍になり、クエリがネックじゃなくなったのがわかります。
スコア:
{"pass":true,"score":14208,"success":13157,"fail":0,"messages":[]}
myprofiler:
36 SELECT `id`, `user_id`, `body`, `mime`, `created_at` FROM `posts` ORDER BY `created_at` DESC 15 SELECT COUNT(*) AS count FROM `comments` WHERE `user_id` = N 5 SELECT * FROM `comments` WHERE `post_id` = N ORDER BY `created_at` DESC LIMIT N 4 SELECT `id`, `user_id`, `body`, `mime`, `created_at` FROM `posts` WHERE `created_at` <= S ORDER BY `created_at` DESC
上位2件を見ると
postsからの SELECT に LIMIT が無いcomments.user_idにインデックスがない
LIMIT がないのはアプリ側で修正が必要なのと、ボトルネックがアプリに移ってるので、アプリ改修に移る。
comments.user_id はついでにインデックス張っておく。（1番重いクエリじゃないのでベンチは省略）
mysql> create index user_id on comments (user_id); Query OK, 0 rows affected (0.14 sec) Records: 0 Duplicates: 0 Warnings: 0
まとめ
スコア: 4745 (初期状態) -> 14208 (インデックスチューニング)
systemd のコマンドとか nginx の設定とか MySQL の設定ファイルを見るとかインデックス張るとかいろいろ慣れて、ここまではスムーズにできるようになりましょう。
感覚値ですが、一人でやってる場合はここまでを2時間以内には終わらせられるようにしましょう。1時間を切れればスゴイです。
@methane
ISUCON5 予選通過しました (@methane編)
9/27 の ISUCON 予選2日目に参戦してきました。
KLab から参加した6チームのうち予選通過できたのは私が率いる lily white だけ、それも通過組の中で下から3位とかなり厳しい結果になってしまいました。
本格的な練習は新人が予選で ISUCON の難しさを実感してからにしようと思っていたのですが、今年は予選のレベルが想像以上に上がっていて、 お題のアプリも本戦さながらの規模、複雑さになっていて、もう完全に舐めてましたごめんなさい。出題側本気出しすぎです。本当にお疲れ様でした。
考察と感想戦はベンチマーカーが公開されてからにするとして、当日の流れを覚えているうちに振り返ってみます。 (時間とスコアをメモってなくて集計サイトもクローズしてしまったので、文中の時間とスコアはうろ覚えのものです)
準備
lily white は私以外に新卒の @gam0022, そして Twitter で見かけて誘った学生の @k2wanko さんの3人チームですが、 2人がサーバーサイドの経験が殆ど無い上に一緒に練習する時間も取れなかったので、 一応なにが必要なのかは教えたうえで個別練習してもらい、本戦も個別で挑戦することに。
私は Ubuntu 14.04 で OpenResty をビルドしておいたり、「マスタリング nginx」を読んだり、去年用意したチートシートを アップデートしたりしていました。
roマウント問題
スタート時点では余裕ぶっこいてたので、若者2人のサポートをしつつ一人で余裕で予選クリアするつもりでした。
2人にはマニュアルを読んでもらいつつ、 sysctl, nginx, my.cnf, limits.conf などを一通り設定して、
Go 実装にはバグがあるという情報があったので Ruby 実装のまま一回ベンチマークをかけつつ、
show full processlist で目につくクエリをメモったりしてた。
ここまで30分程度で、それから当日マニュアルをゆっくり読もうとしたとき、スナップショットから起動した インスタンスがおかしいと言われ、調べたら / が ro マウントされてた。
ブートプロセスに詳しくないのでちょっと時間を食ったけど、 fstab で LABEL=cloudimg-rootfs となってるデバイスを
見つけられないようだったので /dev/sda1 と書き換えてひとまず解決。
(帰ってからあとで調べたところ、何故かラベルが設定されていなかったので sudo e2label /dev/sda1 cloudimg-rootfs が
正しい解決方法だったようです。)
スタートダッシュが遅れたけど、終了直前にこの問題にぶつかったらヤバかったので結果オーライ。 スナップショットを撮り直して、マニュアルを読みなおし、やっとアプリに取り掛かれるようになりました。 (11:00ごろ)
エントリが重い
ro マウント問題を調査している間に2人には元のイメージから起動してアプリを動かしてみてもらっていて、どうやら Go 実装で普通に ベンチマークを通るらしいので、 Go に切り替えて、どんなアプリかみたり、 top や dstat を眺めたりした。最初に考えたのは、
- エントリ、コメント、足あと、チューニング対象になりそうな機能が3つも！ 出題者頑張りすぎ！
- IO Wait がネック。どうやら read らしい
- にしてはアプリの CPU も遅い。なにか無駄なことしてそう。
真っ先に確認しないといけないのはもちろん IO wait です。メモリに乗るか乗らないかは致命的な問題だからです。
/var/lib/mysql/isucon5q# ls -lah total 2.4G drwx------ 2 mysql mysql 4.0K Sep 26 06:17 . drwx------ 5 mysql mysql 4.0K Sep 27 11:15 .. -rw-rw---- 1 mysql mysql 8.6K Sep 26 06:13 comments.frm -rw-rw---- 1 mysql mysql 628M Sep 27 11:24 comments.ibd -rw-rw---- 1 mysql mysql 67 Sep 25 23:16 db.opt -rw-rw---- 1 mysql mysql 8.5K Sep 25 23:28 entries.frm -rw-rw---- 1 mysql mysql 2.3G Sep 27 11:24 entries.ibd -rw-rw---- 1 mysql mysql 8.5K Sep 25 23:19 footprints.frm -rw-rw---- 1 mysql mysql 40M Sep 27 11:24 footprints.ibd -rw-rw---- 1 mysql mysql 8.6K Sep 25 23:19 profiles.frm -rw-rw---- 1 mysql mysql 464K Sep 27 11:23 profiles.ibd -rw-rw---- 1 mysql mysql 8.5K Sep 25 23:19 relations.frm -rw-rw---- 1 mysql mysql 60M Sep 27 11:24 relations.ibd -rw-rw---- 1 mysql mysql 8.4K Sep 25 23:19 salts.frm -rw-rw---- 1 mysql mysql 256K Sep 25 23:19 salts.ibd -rw-rw---- 1 mysql mysql 8.6K Sep 25 23:19 users.frm -rw-rw---- 1 mysql mysql 9.0M Sep 25 23:19 users.ibd
指定されたインスタンスタイプの n1-highcpu-4 の搭載メモリは 3.6GB なので、2.4GBならなんとかメモリに載る。 今回の出題はアプリだけでなくデータセットも絶妙なバランスですね。
アプリのメモリは500MBもあれば十分だし、OSのバッファ／キャッシュも今回は問題にならないので、 innodb のバッファプールを ちょっと多めの 2.7GB に設定してから、次のクエリでバッファプールを温めはじめました。
mysql> select sum(length(body)) from entries;
このクエリがなかなか返ってこないので、アプリを読み始めます。 (11:40 ごろ)
テンプレート毎回コンパイルしてる問題
テンプレートをリクエストの度にファイルからコンパイルしてるのが目に止まりました。 去年の予選でも Go のアプリを重くしてる一番の原因だったので即対応開始。
普通にテンプレートを起動時にコンパイルするように書き換えただけだとコンパイルエラー。 テンプレート内から呼び出せる関数をテンプレートコンパイル時に指定するのですが、その関数にクロージャーを渡していて、 そのクロージャーが Request と ResponseWriter に依存しているために、リクエストハンドラ以外に移動すると コンパイルできなくないことが判明。
関数経由で取得していた情報をテンプレートのレンダリング時に明示的に渡すように書き換えてテンプレートをコンパイルするようにし、 ついでに友達のコメントをトップページに表示する際にコメント先のエントリが private かどうかチェックするためだけに大きい Entry の bodyを 読んでいるところを削る。
これだけでまずは1000点を超えていたはず。
entries テーブルの圧縮
タイトルを取得するためだけに大きい entry テーブルの body を select しているところがボトルネックになっているので、 title と body を分離するついでに、ウォームアップ時間を短縮するために圧縮テーブルを使うように。
この変換スクリプトは Python で書いて、 id の範囲でざっくり2分割して並列実行。それでも結構時間を食った。
myprofiler を見ながらクエリチューニング
15時を回っていたけど上位勢から大きく離されていてかなり焦りだす。 myprofiler を見て重いクエリを各個撃破していくことに。
まずは友達のチェックに時間がかかっていたので、 friends テーブルをオンメモリ化。
エントリのユーザーを指定してコメントを引っ張ってくるところのJOINを高速化するために、 comments テーブルに
entry_user_id カラムを追加。ここまでで 12000 点台。
それでもトップページでコメント1000件取得が重いので、クエリ結果をキャッシュするように改造した所、 バグって手間取る。 Go のプログラムが panic&recover をLLの例外の用に気軽に使ってる上に、そのエラーメッセージをHTMLに書くだけなので、 PHP で display_errors だけ使ってデバッグするくらいのデバッグ難易度で時間を無駄にしてしまう。
いったんリセットするも、このままでは予選突破できなさそうなので、最後の30分で最新のコメント1000件をオンメモリ化し、 14000点台に。 最後に再起動を確認したらダメだったので慌てて対策して終了。
感想
予選なら一人で余裕で突破できるだろうと思ってたけど、全く余裕が無かった。
複数台構成の組み合わせが必須になる以前の、ISUCON, ISUCON2 の流れでさらに難しくしたような問題で、 これが本戦でも全くおかしくないし、これが本戦だったらやはり10位以下で惨敗だったでしょう。
トップの fujiwara 組と比べると、8時間の競技時間中6時間半の時点のスコアは超えているので、一人にしては悪くない パフォーマンスだと思うけど、同レベルで得意分野が異なる3人チームでないと fujiwara 組に勝つのは難しい。 3人で力を合わせないと勝てないという点でも、これぞISUCONと言える予選でした。
残り2人が高負荷サイトのアプリチューニングの面でも、インフラの面でも経験値がほぼ0なので、 本戦に向けてどうチームビルディングしていくか悩ましいところです。
来年は戦力の分散を止めて、勉強組、遊び組、攻略組でチームを作ろうと思います。
最後に
インフラを提供して頂いた Google さんと、サポートしてくださった佐藤さんありがとうございました。 GCE は起動が早いし、課金単位時間も短いので、個人環境としてすごい使いやすかったです。 頂いたクーポンがいっぱい余ってるので本戦の練習でもガンガン活用します。
271組ものチームのサポート業を1人で対応されていた LINE の櫛井さんも本当にお疲れ様でした。 オンサイトの本戦はさらに大変そうですが、よろしくお願いします。
そして出題側の Treasure Data の田籠さん、上薗さん、初期実装協力者の方々、本当にお疲れ様でした。 Twitter で田籠さんの忙しい様子を見て、さすがに予選はある程度手を抜いてくるだろうとたかをくくっていたのですが、 予想を遥かに超えた、本戦レベルの出題や採点システムに完敗しました。 本戦はもっとまともに戦えるように準備してリベンジしに行きます。
