ISUCON

2018年09月18日

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 に切り替えたときに完全に不要になっていたはず…ぐぬぬ。

訂正: read committed になっていたのは mapk0y が MySQL に入れ替えるときに my.cnf に誤混入しただけで、初期実装は repeatable read だったようです。あのJOINを使ったずっと横スクロールしないと読めない長い一行SELECT文の中に無意味な for update が混じっていたのは、特に必要な理由がない純粋な罠だったのかもしれません。。。

反省点

最大の書換であるところの reservation オンメモリ化を自分でしてしまいましたが、これは makki_d に任せて、自分はもっと調査系に専念するべきでした。手を付けたときに makki_d が他の作業に取り掛かっていたのと、事前練習不足で makki_d が「オンメモリ化」をスラスラ書けるか解らなかったのと、何より「自分が何もできないまま敗北する恐怖」に負けてしまいました。

大きな改修+それを利用した大規模な高速化が終わってトップグループになったのが16時で、そこからは「競技終了までに何をするか/しないか」に頭が切り替わってしまったので、落ち着いて全体を注意深く調査することができませんでした。

他にも、次のような要因があったと思います。

  • 過去問では report 系APIは整合性検証のためだけに使われることが多かったのでほとんど見てなかった
  • 通過ラインがわからない恐怖から、遅くなる原因追求よりも調子のいいときのスコアアップを優先してしまった

本戦では1位を取るためにスコアアップ優先になるのはある程度しかたありませんが、予選ではトップスコアを取っても通過できなければ意味がありません。来年はもう少し落ち着いて、仕事で負荷対策の調査をするときのようにマズイ点を潰していきたいと思います。

感想

アプリのコードの規模、DBのスキーマの規模ともにISUCONに適したボリュームに抑えつつも、完全オンメモリ化(SELECTを削除し、DBへの書き込みをロック外に追い出しても整合性が担保できる)が難しい複雑なSQLが散りばめられているバランスが素晴らしかったです。いろんなチームがそれぞれの得意なやり方で勝ちを狙えたはずで、本戦にしないのがもったいない、これ以上ないくらいの良問でした。

また、去年の予選でやらかしてしまった原因の「予選で複数台構成」を今年も継承してきたことにも驚きました。参加者視点で見たら、万が一設定をミスってSSHできなくなるような事態になっても試合終了にならない安心感は良いですね。

その複数台構成の活用方法も、去年に比べてずっと自由度が高いのが良かったです。

本当にこれまでで最高のISUCONだったと思います。ありがとうございました。 これが予選なら本戦はどうなるのか、参加できないのが悔しくて仕方ありません。

songofacandy at 11:04|この記事のURLComments(0)
2017年12月18日

更新頻度の多いデータのキャッシュ

はてなブックマークに登録

@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参加前と参加後に最も多くのものを持ち帰った人こそが勝者と言えるでしょう。" (引用元) ということですが、参加チームの方にこの「まとめて処理」を「待つ」パターンを持ち帰って将来何かに役立ててもらえたら幸いです。

songofacandy at 21:12|この記事のURLComments(0)
2016年10月24日

ISUCON6 で優勝しました

はてなブックマークに登録

@methane です。タイトルの通り、 ISUCON でとうとう優勝してきました。

チームメンバーは、(予選と同じく) @kizkoh (インフラ担当), @mecha_g3 (アプリ担当) でした。

私は予選のときはガッツリとアプリを書いていたのですが、本戦では netstat -tn (←老害), top, dstat -ai, sudo perf top などをみつつ指示をだしたり、方針を決めたり、完全に未経験だった node.js & react.js 対策をしたりが主な仕事で、あとは序盤のインフラのタスクが大量にあるときに MySQL を docker から外して基本的なチューニングを入れたり Go を100行程度書いただけです。

結果的には優勝できましたが、メンバーの2人がよく準備し本番でも実力を発揮してくれたのに対して 僕の戦略ミスで中盤から全くスコアを上げられなかったので、最後までヒヤヒヤしていました。

ということで、 nginx や Go でやったことはメンバーの二人が別に記事を書いてくれると思うので、 私の目線で考えたこと、自分でやったことや方針を決めて指示したこと、その考察を書いていきたいと思います。

お題と初期構成について

お題は、リアルタイムに他人の書いた線が他のユーザーに見えるようなお絵かき掲示板でした。

構成が特徴的で、

  • フロントにいるのが通常の 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を買いたいです。

終わりになりますが、運営・協賛の各位、特に毎年増え続ける参加者をあたたかみのある運用で運営してくださっている櫛井さんと、 毎年上がり続ける出題レベルのプレッシャーに見事に応える良問と安定ベンチマークシステムを作ってくださった出題チームに感謝いたします。

songofacandy at 19:09|この記事のURLComments(0)TrackBack(0)
2016年09月20日

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 はキーワードをポストしたときに、 ReplaceKeywordhtmlify から呼ばれます。これで 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 の構築処理
}

mUpdateReplacerrepLastUpdated が追加した変数で、 updateReplacer()repLastUpdated = time.Now() までがイディオムになっています。

例えば、キーワードA, B, C がほぼ同時に追加されたとします。

  1. まずAが最初にロックを取得して、 repLastUpdated = time.Now() を実行して Replacer の構築を始めます。
  2. 続いてキーワードBとCがともに mUpdateReplacer.Lock() で停止します。ロック直前に取得した now は (1) で更新した repLastUpdated よりも未来の時間になります。
  3. キーワードAの Replacer 更新が終了し、 mUpdateReplacer が開放されます。キーワードBを処理していた goroutine がそのロックを取得します。
  4. ロック取得前に取得した nowrepLastUpdated よりも新しいので、 if repLastUpdated.After(now) が真になりません。なので Replacer を再構築します。キーワードAを更新したときの kwdList にキーワードBは入っていなかった(厳密にはタイミング依存で入っていた可能性もある)ので、これは必要な処理です。
  5. さらにキーワード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位のダブルスコアをキープしていたこともあって、保守的になりすぎて全力を出し切れたとは言い難いです。

本戦では全力を出せるように、もう少しチームワーク練習や環境構築の練習を重ねて行きます。

それでは、決勝進出者のみなさん、決勝でお会いしましょう。 運営・出題者のみなさんはお疲れ様でした。決勝も引き続きお願いいたします。

songofacandy at 16:25|この記事のURLComments(3)TrackBack(0)
2016年08月23日

pixiv private isucon 2016 Python 版実装を用意しました

はてなブックマークに登録

今年の ISUCON でも Python 実装が提供されることが 発表されました。

Python での練習は過去の予選問題でも可能ですが、今年の出題チームが準備した問題で 練習できるように Python 版の実装を用意しました。とりあえずベンチマーカーが完走する ところまでは確認してあります。

リポジトリ

用意したのはアプリの実装だけなので、これを使って練習する際は pixiv さんが公開されている AMIwebapp ディレクトリ配下に python という名前で git clone し、 systemd などの設定は練習の一環として自前で行ってください。

また時間があるときに自分でチューニングしてみて、ミドルウェアの選定や ツール・テクニックなどを公開したいと思います。


@methane
songofacandy at 20:55|この記事のURLComments(0)TrackBack(0)
2016年06月03日

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

songofacandy at 18:53|この記事のURLComments(0)TrackBack(0)
2016年06月02日

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

songofacandy at 17:51|この記事のURLComments(0)TrackBack(0)
2016年06月01日

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

songofacandy at 15:52|この記事のURLComments(0)TrackBack(0)
2016年05月31日

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

songofacandy at 11:10|この記事のURLComments(0)TrackBack(0)
2016年05月30日

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_idposts.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

songofacandy at 11:09|この記事のURLComments(0)TrackBack(0)
2015年09月28日

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 で田籠さんの忙しい様子を見て、さすがに予選はある程度手を抜いてくるだろうとたかをくくっていたのですが、 予想を遥かに超えた、本戦レベルの出題や採点システムに完敗しました。 本戦はもっとまともに戦えるように準備してリベンジしに行きます。

songofacandy at 21:41|この記事のURLComments(0)TrackBack(0)
Blog内検索
Archives
このブログについて
DSASとは、KLab が構築し運用しているコンテンツサービス用のLinuxベースのインフラです。現在5ヶ所のデータセンタにて構築し、運用していますが、我々はDSASをより使いやすく、より安全に、そしてより省力で運用できることを目指して、日々改良に勤しんでいます。
このブログでは、そんな DSAS で使っている技術の紹介や、実験してみた結果の報告、トラブルに巻き込まれた時の経験談など、広く深く、色々な話題を織りまぜて紹介していきたいと思います。
最新コメント