ISUCON3 予選参加報告
結果
暫定14位で本戦出場できることになったので、前回よりは進歩したかと思います。
既に @__kan さんと @bonnu さんがエントリをあげていますので、ポイントよりも推移に関してログを抜粋して行こうかと。
前日まで
チャンネルを作り、ざっくりと「個別の環境を作って、自分がやっている改善施策を共有しつつ3並列で違う事を試していく」という方針を決めた。
[13/09/30 11:47:18] まいんだー: まいんだー がタイトルを "ISUCON対策会議室" に設定しました [13/09/30 11:48:19] Satoshi Ohkubo: 当日集まってやりたいっすね [13/10/03 16:26:10] まいんだー: 土曜日の飲酒を禁止といたします！ [13/10/03 16:27:01] Satoshi Ohkubo: そっすねー。体調整えてきましょう。 [13/10/03 16:28:50] ふしはらかん: 我々の作業の流れとしては、口頭とこのチャンネルでやりとりしつつ [13/10/03 16:29:07] ふしはらかん: 全員で↑のインスタンスにSSHで入って作業する、みたいな感じになるですかね? [13/10/03 16:32:44] まいんだー: 個別にAMI起動してもいいですけどね。 [13/10/03 16:49:31] ふしはらかん: そういえば、これちょっと気になってたのだった http://twitter.com/fujiwara/status/385672841355468800 [13/10/03 16:49:41] ふしはらかん: が、そもそもそこまで最適化できるのかがまず壁かw [13/10/03 16:50:01] まいんだー: failしないことですね。 [13/10/03 16:50:08] まいんだー: 我々前回死んでるから。 [13/10/03 16:50:08] Satoshi Ohkubo: いかにシングルでパフォーマンスを上げるかw [13/10/03 16:50:19] まいんだー: 同じアプローチを取らないように [13/10/03 16:50:24] まいんだー: 3並列でいろんな事をためす [13/10/03 16:50:42] ふしはらかん: 完走して負けるのは仕方ないけど、不戦敗はしない、をとりあえず目標に [13/10/03 16:50:50] Satoshi Ohkubo: はい。 [13/10/03 16:50:59] ふしはらかん: そうですね、何やるかは示し合わせつつやってきましょう
1日目
何か情報が出てこないものかとタイムラインをちょいちょい見ていました。
この時点では当然ながら情報が何も出てこないので、目指すべき数値みたいなのを共有するにとどまっている。
[13/10/05 17:30:07] まいんだー: ISUCON情報が全然出てこない。 [13/10/05 17:31:05] ふしはらかん: まあ、当落と順位以外しゃべっちゃ駄目って言われてますしねえw [13/10/05 18:18:29] まいんだー: 1位 : 33830.4点 5位 : 19412.5点 10位 : 9061.7点 [13/10/05 18:18:30] まいんだー: うーむ [13/10/05 18:20:56] まいんだー: 当落スコアとしては2万を最低ラインと考えて、まずはそこを目指しましょう。 [13/10/05 18:22:04] ふしはらかん: うい [13/10/05 18:22:33] まいんだー: デフォで1000〜3000くらいみたいな話だったので [13/10/05 18:22:52] まいんだー: やはり前回同様かなと。 [13/10/05 18:29:16] ふしはらかん: 予選だし、ある意味前回の復習的な感じなのかも [13/10/05 18:30:59] ふしはらかん: お、walf443のpixivチーム勝ち抜いとる [13/10/05 21:32:50] まいんだー: 勝たねば。 [13/10/05 21:36:41] まいんだー: 山形組強いな。
2日目午前
開始時点ではこんな状況、当日にカード登録を変えたのでインスタンスが起動できないというしょうもない事態が発生し、隣の @Yuryu に助けてもらってインスタンスは無事作ることができた。
インスタンスの起動まで確認できていたから、登録を変えるみたいなことをする必要はなかった、余計なことはしない方がいい。。
[13/10/06 8:35:33] Satoshi Ohkubo: おはようございます。 体調もよく、これからスタジオに向かいます。 [13/10/06 9:56:53] ふしはらかん: すみません、まさかの現時刻起床です…… [13/10/06 9:58:11] Satoshi Ohkubo: おお [13/10/06 9:58:49] ふしはらかん: えっと、作業等考えると、このまま自宅からリモートよりも会社向かったほうが良いですかね?この時間なら [13/10/06 10:03:25] Satoshi Ohkubo: たぶん最終的には効率がよいと思いますー [13/10/06 10:03:52] ふしはらかん: 了解です。とりあえず向かいます
ということでアプリケーションを読んだりサーバの状態をちょこちょこ調査開始
[13/10/06 10:47:18] まいんだー: my $memos = $self->dbh->select_all(
sprintf("SELECT * FROM memos WHERE is_private=0 ORDER BY created_at DESC, id DESC LIMIT 100 OFFSET %d", $page * 100)
);
if ( @$memos == 0 ) {
[13/10/06 10:47:22] まいんだー: これは遅い。
[13/10/06 10:59:17] まいんだー: 我々はひとまずdiffとか貼ってく方向で。
[13/10/06 11:00:07] Satoshi Ohkubo: ok です
[13/10/06 11:04:29] まいんだー: どこからも呼ばれてなさそうなupdate文消した。
[13/10/06 11:04:38] まいんだー: last_accessだったか。この時点でのベンチ結果はこんな感じ
[13/10/06 11:07:23] まいんだー: [isucon@ip-10-121-12-154 ~]$ sudo isucon3 benchmark Result: SUCCESS RawScore: 1242.0 Fails: 1 Score: 1242.0 [OK] 結果を管理サーバに送信しました
このあと --init で DB の中身を事前に変えるなどをやり始め、1387までスコア改善
[13/10/06 11:44:15] まいんだー: [isucon@ip-10-121-12-154 ~]$ sudo isucon3 benchmark --init /home/isucon/initialize.sh Result: SUCCESS RawScore: 1387.8 Fails: 0 Score: 1387.8 [OK] 結果を管理サーバに送信しました [13/10/06 11:44:17] まいんだー: もう一歩 [13/10/06 11:44:28] まいんだー: [isucon@ip-10-121-12-154 ~]$ cat initialize.sh #!/bin/bash mysql -uisucon isucon -e 'select * from memos' > /dev/null; mysql -uisucon isucon -e 'select * from users' > /dev/null; mysql -uisucon isucon -e 'alter table memos add index id_and_is_private_idx(is_private)' > /dev/null; [13/10/06 11:44:30] まいんだー: こんな感じ。 [13/10/06 11:45:25] ふしはらかん: あー、一応あっためてるんですかね>mysql
でも暖め自体には意味がない感はいまになって振り返るとあるなぁ...
そして @bonnu さんが nginx 化
[13/10/06 11:52:19] Satoshi Ohkubo: nginx にしたもの [isucon@ip-10-121-28-177 ~]$ sudo isucon3 test Result: SUCCESS RawScore: 2683.8 Fails: 0 Score: 2683.8
ここから、 @kan さんが markdown の所、自分がキャッシュを活用するような改善施策に取り組み始める。
[13/10/06 11:53:26] ふしはらかん: markdownのとこ弄ってみようとしてます [13/10/06 12:14:08] まいんだー: index貼ったら改善。 [13/10/06 12:17:26] まいんだー: keyで引いてるところをmemd化するのやります。
そして、ここまでの施策をぜんぶまとめて @bonnu さんが適用した結果、2742まで進捗。
[13/10/06 12:20:48] Satoshi Ohkubo: 微妙ですけど Result: SUCCESS RawScore: 2742.5 Fails: 0 Score: 2742.5
そして次の手として @bonnu さんがプロファイリングを取り始め、自分は Starman 以外に差替えて試すなどをやってみた。
結論からいうと Starman を変える必要はなかった。
[13/10/06 12:21:37] Satoshi Ohkubo: まだその程度です。このあと nytprof & starlet 試してみます [13/10/06 12:26:05] ふしはらかん: むう、いかにも遅いかと思ってmarkdown化の処理をText::Markdown::Discountにしたものの、大してベンチ変わらず [13/10/06 12:26:18] ふしはらかん: そもそも、ここは結果をいかにキャッシュしないと、みたいな話ですね [13/10/06 12:27:31] まいんだー: starletizeしてベンチ中。 [13/10/06 12:27:40] ふしはらかん: Text::Markdown::Discount を cpanfileに書いて carton install して [13/10/06 12:28:11] ふしはらかん: Isucon3::Web の sub markdown を削除して、use Text::Markdown::Discount 'markdown' でいけまする [13/10/06 12:28:37] まいんだー: starlet化してもさしてかわらず。 [13/10/06 12:30:17] まいんだー: monocerosも入れてみた。 [13/10/06 12:30:27] まいんだー: 裏でkanさんの施策取り込んでみます。 [13/10/06 12:30:34] まいんだー: の裏で更にmemd化を進めてみる。 [13/10/06 12:30:55] ふしはらかん: おっす。自分もうちょいコード読んでポイント探します [13/10/06 12:32:00] まいんだー: starmanが一番スコア良さそう。 [13/10/06 12:32:22] Satoshi Ohkubo: かなり誤差っぽいっすね。。 [13/10/06 12:32:30] Satoshi Ohkubo: starman <-> starlet [13/10/06 12:32:39] まいんだー: 差替えの意味はなさそうです。 [13/10/06 12:32:43] まいんだー: やはりセオリーというか歴史に学んでいくしかない。 [13/10/06 12:34:20] まいんだー: 「アプリに処理させたら負け」
この辺の時間で「できるだけキャッシュさせ、必要なら暖める」みたいな方針が見え始める。
まだ時間に余裕はあるからと、キャッシュ化を考えながら、ミドルウェアでもいろいろ出来ないかというところも併せてやっていた。
[13/10/06 12:41:19] まいんだー: location ~ ^/(images|js|css)/ {
rewrite_by_lua 'ngx.sleep(2.5)';
root ../../../staticfiles;
}
[13/10/06 12:41:25] まいんだー: これをnginxの設定にいれてtestしてみます。
[13/10/06 12:45:39] まいんだー: kazeburoさんの http://blog.nomadscafe.jp/2012/11/isucon2-5.html にあったやつ。
[13/10/06 12:53:10] まいんだー: その前にちょっと OpenRestyで静的ファイル返すのにdelay仕込むkazeburoメソッドを試してます。
[13/10/06 12:53:13] まいんだー: インストールして起動するだけなので。
[13/10/06 12:58:01] まいんだー: うーん
[13/10/06 12:58:08] まいんだー: 画像とかjsそんなに遅くない予感。
[13/10/06 12:58:11] ふしはらかん: nrhd
[13/10/06 12:58:16] まいんだー: openrestyでベンチ中。
[13/10/06 12:58:19] まいんだー: ウヒーダメポ
[13/10/06 12:58:21] まいんだー: 意味なし。
[13/10/06 12:58:26] まいんだー: ということでmemd引き続き。
[13/10/06 12:58:36] ふしはらかん: ういというのをやってみたものの sleep を入れたらむしろダメだったので、この案は早々に廃止して元に戻した。
このタイミングで、会場にいた全員でランチを取り、状況やらを軽く共有しつつ歓談。Pariya のお弁当は大変おいしゅうございます。
2日目午後
ボトルネックになるリクエストをちゃんと絞り込んでなかったので、改めて「遅いリクエスト」に絞り込んで行く作業を開始。
[13/10/06 13:37:02] まいんだー: /memo/41246 HTTP/1.1" 200 0.103 [13/10/06 13:37:12] まいんだー: /memo /recent に絞るべき。 [13/10/06 13:37:18] まいんだー: 50ms or die.と戦おう。 [13/10/06 13:37:29] ふしはらかん: おっすおっす
そして粛々とプロファイリングしていた @bonnu さんの共有が上がってくる。
[13/10/06 13:41:21] Satoshi Ohkubo: 本日の nytprof 情報です（ほぼデフォルトコード） [13/10/06 13:41:22] Satoshi Ohkubo: http://bonnu:8080/isucon/html/index.html [13/10/06 13:41:34] ふしはらかん: bonnu++ [13/10/06 13:41:37] ふしはらかん: あざす!
ここいらで、方針が一本化されつつあったので、git化して全体で足並みを揃えて進めることに。
[13/10/06 14:40:51] ふしはらかん: なんか、手元であんまり結果が変わらんのですが、超ざっくりrecentキャッシュ版をpushします [13/10/06 14:41:00] Satoshi Ohkubo: ++ [13/10/06 14:41:11] まいんだー: ああ [13/10/06 14:41:15] まいんだー: まだキャッシュしてなかったんですね [13/10/06 14:41:20] ふしはらかん: done [13/10/06 14:42:04] まいんだー: 見ました [13/10/06 14:42:09] まいんだー: 完全に手法が一致。 [13/10/06 14:42:13] ふしはらかん: www [13/10/06 14:43:28] まいんだー: 50ms or die.的にはまだ厳しいですな〜 [13/10/06 14:43:48] まいんだー: $ sudo isucon3 benchmark --init /home/isucon/initialize.sh Result: SUCCESS RawScore: 3376.8 Fails: 0 Score: 3376.8 [OK] 結果を管理サーバに送信しました
ここからスコア6000くらいまでは、じわじわとキャッシュ策並びにプロファイリング結果からのコード修正を行っていった。
更に warm up するような施策を入れたのもこの辺。
[13/10/06 16:30:11] まいんだー: [isucon@ip-10-121-12-154 perl]$ sudo isucon3 benchmark --init /home/isucon/webapp/perl/initialize.sh Result: SUCCESS RawScore: 6018.3 Fails: 0 Score: 6018.3 [OK] 結果を管理サーバに送信しました [13/10/06 16:33:27] まいんだー: /memo は lognest request で 36ms [13/10/06 16:33:42] まいんだー: /recent が [13/10/06 16:33:44] まいんだー: 0.319 "GET /recent/110 HTTP/1.1 [13/10/06 16:33:46] まいんだー: やはりツライ。
この時、warm upしているのに遅いリクエストがあってなんでだろうと思って調べ始めた。
[13/10/06 16:37:12] ふしはらかん: ぐぬ、何故かwarmup適用後のほうがスコア下がった……>手元 [13/10/06 16:43:09] まいんだー: memcachedからキャッシュが溢れてる疑惑があるので [13/10/06 16:43:20] まいんだー: 64mだと足りないだろ。。。 [13/10/06 16:43:48] ふしはらかん: うひ [13/10/06 16:43:52] まいんだー: 8000mまで上げてみました。 [13/10/06 16:44:15] Satoshi Ohkubo: CACHESIZE="8000" [13/10/06 16:44:18] Satoshi Ohkubo: ですか [13/10/06 16:44:24] Satoshi Ohkubo: /etc/sysconfig/memcached [13/10/06 16:45:04] まいんだー: よっしゃ100ms over目立たなくなってる！ [13/10/06 16:45:08] ふしはらかん: ooo [13/10/06 16:45:26] まいんだー: これは期待。 [13/10/06 16:45:31] ふしはらかん: dkdk [13/10/06 16:45:48] まいんだー: [isucon@ip-10-121-12-154 perl]$ sudo isucon3 benchmark --init /home/isucon/webapp/perl/initialize.sh Result: SUCCESS RawScore: 7891.3 Fails: 0 Score: 7891.3 [OK] 結果を管理サーバに送信しました [13/10/06 16:45:49] まいんだー: きたー [13/10/06 16:45:54] ふしはらかん: YATTa!! [13/10/06 16:45:57] Satoshi Ohkubo: ooo! [13/10/06 16:46:30] まいんだー: evicted_unfetched evictions [13/10/06 16:46:32] まいんだー: が出てて [13/10/06 16:46:34] まいんだー: もしかして？ [13/10/06 16:46:36] まいんだー: と思った。 [13/10/06 16:51:09] ふしはらかん: ここから、もうひとのびさせたいすね
この後の「ひとのび」は @bonnu さんが地道にプロファイリング結果を解析していった所が大きく、特に uri_for あたりのコストを削減したことが大きい。
最終的には遅くなりそうなところをぼちぼち潰して行って、じわじわとスコアをupさせ、10787.2でフィニッシュ。
[13/10/06 17:39:41] Satoshi Ohkubo: 10745 [13/10/06 17:39:42] まいんだー: ++ [13/10/06 17:45:39] まいんだー: nihenさんとかこの時間に革命的な事が起こったとか言ってるしまだいける。 [13/10/06 17:47:51] Satoshi Ohkubo: Result: SUCCESS RawScore: 10774.9 Fails: 0 Score: 10774.9 [OK] 結果を管理サーバに送信しました [13/10/06 17:48:05] Satoshi Ohkubo: びみょうーに 10774.9 [13/10/06 17:48:09] Satoshi Ohkubo: あげてます [13/10/06 17:48:16] ふしはらかん: bonnu++ [13/10/06 17:48:23] まいんだー: さすが夜にさしかかってきたから [13/10/06 17:48:27] まいんだー: bonnu++ [13/10/06 17:48:44] ふしはらかん: 18:00-4:00とかのスケジュールなら圧勝だったか…… [13/10/06 17:55:22] Satoshi Ohkubo: 2013/10/06 17:55:14 done benchmark Result: SUCCESS RawScore: 10787.2 Fails: 0 Score: 10787.2 [OK] 結果を管理サーバに送信しました
最初のアプリ構成から大きく変えていないので、workloadを最適な値にしてスコアが出せれば、この状態でももっと伸びただろうと考えられる。
ちょっともったいないことをした。。。
17時頃までスコアが伸び悩んでいた原因は、ログや計測まわりの流れを作るのが遅れたことだと考えられる。
まだ本戦が残っているので、この辺の反省を踏まえて効率よく進めたい。
引き続きよろしくお願いいたします。
