ISUCON6で屈辱的に負けてきた

はじめに

去る2016年9月18日(日)に、ISUCON6の予選に参加しました。
結果は最高スコア12023で屈辱的に敗退しました・・・
その一部始終をまとめておきたいと思います。

ISUCONとは？

お題となるWebサービスを決められたレギュレーションの中で限界まで高速化を図るチューニングバトル、それがISUCON

予選当日までにやってきたこと

主に下記のことを行ってきました。

1. チームメンバーとISUCON4(2014年開催)の過去問で復習をしてきました。
kitakitabauer.hatenablog.com
kitakitabauer.hatenablog.com
kitakitabauer.hatenablog.com
kitakitabauer.hatenablog.com
2. 今回予選で利用するサーバはMicrosoft Azureなので、アカウントを用意した後、リーダーがリソースグループ作成と、サブスクリプションへのメンバーID登録をしてくれました。
3. bitbucketに作成された共有リポジトリに、作業端末の公開鍵を入れたauthorized_keysなどをコミットしていました。作成されたインスタンスにこれらを突っ込む予定です。
4. ローカルにNode, Goの最新バージョンをインストールしました。言語選定の理由は後述します。
5. アンチョコとして、my.cnfとnginx.confを用意しておきました。
6. 予選会場は自社の会議室を間借りさせてもらうことになったので、その手配と人数分のモニターの確保をしてもらいました。

チームメンバー

Aragamiというチーム名で参加しました。(なぜか自社の障害チケット管理システムの名前を拝借)
構成メンバーは、自社でカジュアルソーシャルコーディングという、カジュアルな勉強会を4年以上続けてきたチームメンバーで参加しました。

id:nakimura：チームリーダー。主夫。アプリ担当。
@wataru420：HipHopper。ミドルウェア周りのチューニング担当。
id:kitakitabauer：私。モグリエンジニア。アプリ担当。

という作業割り振りで行こうと決まりました。
見づらくなるので、誰が何をやったとかは基本的に省略して書いていきます。

言語選定ですが、

高速化対象のソフトウェアとして主催者から Perl, Ruby, Python, PHP, Node.js, Go, Scala によるWebアプリケーションが与えられる。ただし各々の性能が一致することを主催者は保証しない。どれをベースに用いてもよいし、独自で実装したものを用いてもよい。

ということで、メンバー中2人が Node.js での実務経験が豊富だったことから、
Node > Go >>>>>>>>> Python >>>>>>>>>>>>>>>>> PHP
の順で、当日に実装内容を見てから決めようということになりました。
*1

いきなりはまった

10:00
予選が開始し、運営から事前に共有されていたポータルサイトが参照・ログイン可能となりました。
と同時に予選用イメージURLが閲覧可能となったので、Azureのリソースグループにインスタンス起動・公開鍵登録後、そこに表示されたPublic IP addressに対してSSHログインしようとしたら…
「SSHログインできない・・・！」
もう出だしから一人つまづいて死にたいと思っていたけど、死ぬのをやめて生きて原因を探しました。
こんな感じの~/.ssh/configで、自分はいつもユーザ名を指定せずに"ssh XX.XX.XX.XXX"していたのですが、

user kitakitabauer
…
Host XX.XX.XX.XXX
 User isucon
 IdentityFile ~/.ssh/id_rsa_github

userをHost毎に上書きしてくれている(つまり、Host XX.XX.XX.XXXではisuconユーザでsshしてくれる)と勘違いしていたため、ログインできなかったという恥ずかしいオチでまた死にたくなりました。
生きてユーザ指定して、無事sshできました。

Webアプリの構成を確認

11:00
ベンチマークサイトは、簡易的な辞書ページのようなものでした。
ベンチマークはキューイング方式で、それぞれのチームがベンチマークのキューに登録して実行を待つという感じです。

Node.jsの構成はざっくりこんな感じでした。

./js
├── bin
│   ├── isuda   # isudaプロセス起動
│   ├── isutar   # isutarプロセス起動
│   …
│   └── www
├── route
│   ├── isuda.js   # ルーティングされたリクエストパスの処理詳細／isudaデータベースへのセットアップなど
│   └── isutar.js   # ルーティングされたリクエストパスの処理詳細／isutarデータベースへのセットアップなど
├── views   # テンプレートエンジンによる画面描画
│   …
│   └── index.ejs
├── .gitignore
├── isuda.js   # isudaプロセスのセットアップ／リクエストのルーティング等
├── isutar.js   # isutarプロセスのセットアップ／リクエストのルーティング等
├── npm-shrinkwrap.json
└── package.json

Node実装の確認

Nodeの実装を確認してびっくり！過去問から見る例年のものと比べて想像以上にしっかり実装されていました。
Webフレームワークはkoa。
しかもES7のAsync Awaitで書かれている。これはまずい。koaやAsync Awaitは勉強不足だ…。
それでもGoよりかはましということで、systemctrlで、実行言語をNodeに変更しました。

ベンチマーク初回実行

とりあえずベンチマークが動くことを確認したかったので、キューに入れていざ実行したところ、0点。
スコア計算ですが、エラーよりも、レスポンス遅延のほうが大きく減点されるようで、
実行後のメッセージ欄にはそれほどFailが確認できなかったことから、レスポンス遅延による減点が大きいのかもと推測。

マシンリソースやアプリ以外のボトルネックを確認

その後、アプリをじっくり確認する前に行ったことです。

現時点のwebappをバックアップとしてbitbucketにpush
restart.shを作って、slackにWebhook設定することで、restartを1オペでかつslack上からも再起動を確認できるように
CPUコアは2コア(これはAzureポータルからも確認できた)やメモリは7GBで潤沢なことを確認
余計なミドルウェアやツールが起動してリソースを逼迫していないか確認
ベンチマークを流したあと、データ登録後のMySQLの容量が肥大化しすぎていないか確認
アンチョコのmy.cnfを置いて、MySQLのslowqueryをONにしてスロークエリを確認

特段おかしなところはなさそう。
これはまさか、今回アプリをどれだけ改修できるかが勝負となる・・？

kataribeでボトルネック調査

13:00
kataribeを入れて時間がかかっているHTTPリクエストをサマリすることでボトルネックを確認したところ、静的ファイルのリクエストに時間がかかっていると出ていたので、nginxでキャッシングして返す・クライアントでもキャッシュできるならするようにしました。

すると、"/"、"/keyword"、"/login"へのアクセスが異様に遅いことが明白になっていきました。

君の名は。

いろんなリクエストから呼ばれている処理の中で、ユーザの名前を毎回DBから取得していたので、メモリにマップを持たせて初回のみ取得するように。

 const setName = async (ctx) => {
   ctx.state = {};
   const db = await dbh(ctx);
   const userId = ctx.session.userId;
   if (userId != null) {
-    const users = await db.query('SELECT name FROM user WHERE id = ?', [userId.toString()]);
-    if (users.length > 0) {
-      ctx.state.user_name = users[0].name;
+    let name = userNameMap[userId];
+    if (name === undefined) {
+        const users = await db.query('SELECT name FROM user WHERE id = ?', [userId.toString()]);
+        name = users[0] && users[0].name;
+    }
+    if (name) {
+      userNameMap[userId] = name; 
+      ctx.state.user_name = name;

スコアは0。これぐらいじゃあまだまだ。

Nodeで一つ一つのIO処理待ってる意味 is 何？

最も遅い"/"へのリクエストの中で、for文内でAsync Awaitで1つ1つ直列に処理している部分がひどいので、Promiseに詰めて並列実行できるように(リーダーが)改善しました。

-  for (let entry of entries) {
Add a comment to this line
-    entry.html = await htmlify(ctx, entry.description);
-    entry.stars = await loadStars(ctx, entry.keyword);
-  }
+
+  const tasks = entries.map(entry => {
+    return Promise.all([
+      htmlify(ctx, entry.description),
+      loadStars(ctx, entry.keyword),
+    ]).then(result => {
+      entry.html = result[0];
+      entry.stars = result[1];
+    });
+  });
+  await Promise.all(tasks);

スコアはまだ0のままうんともすんとも。

キーワード長を毎回取得するなんて

MySQLクエリ解析にかけるほどでもなく明らかだったのですが、下記は"keyword"を長さ順に全件取得しているので重いです。

SELECT * FROM entry ORDER BY CHARACTER_LENGTH(keyword) DESC

キーワード長は不変なので、キーワードをDBに登録する処理の時に、長さも合わせて保存することで、HTMLページのキーワードリンク生成処理時に毎回レングスを取ってこなくてもいいように変更。

ALTER TABLE entry ADD COLUMN `keyword_length` int(11) after `keyword`

   await db.query(
-    'INSERT INTO entry (author_id, keyword, description, created_at, updated_at) ' +
-    'VALUES (?, ?, ?, NOW(), NOW()) ' +
+    'INSERT INTO entry (author_id, keyword, keyword_length, description, created_at, updated_at) ' +
+    'VALUES (?, ?, ?, CHARACTER_LENGTH(?), NOW(), NOW()) ' +
     'ON DUPLICATE KEY UPDATE ' +
-    'author_id = ?, keyword = ?, description = ?, updated_at = NOW()',
+    'author_id = ?, keyword = ?, keyword_length = CHARACTER_LENGTH(?), description = ?, updated_at = NOW()',
     [
-      userId, keyword, description, userId, keyword, description
+      userId, keyword, keyword, description, userId, keyword, keyword, description
     ]);

うーん、いまだスコアは0のまま。

initializeでイニシアチブとってこ

HTMLページのキーワードリンクを生成するための処理の中で、for文で全ての登録キーワードをDBから毎回取得して正規表現でゴニョゴニョしている部分を、まずinitializeで一度行うように(これもリーダーが)変更して、その後新しいキーワードが登録されたときだけ、その正規表現を更新するように。
あと、entryテーブルの全フィールドをSELECTしていたのを"keyword"だけにするのも同時に。

これはかなりききそうだけど、まだスコアは0のまま。。ほんとに上がるのか・・？
(後々、他の箇所の実装で書かれたSQL構文が間違っていたことでスコアが上がらなかったことに気づきました。なので、ここだけの伸びはわかりかねますが、多分今回対応できた中ではここが一番効いたのかと！)

パスワード＝名前説

14:00
/login へのリクエストのときに、SHA-1でメッセージダイジェストを生成して、userテーブルのパスワードと比較していますが、この生成されたメッセージダイジェストを保存するようにしたら、同じユーザのログインが高速化されるかもという話が上がり、改修していきました。
すると、そもそもリクエストされたパスワードがユーザのnameと一緒だという衝撃の事実が明らかになりました。

これは、ちゃんとHTTPステータス4xxのものは弾いて、それ以外はすんなりログインさせれば、かなりの高速化が見込めそうだということで修正した結果、ようやくスコアが 0 → 約6000 まで上がりました。

こんなマイクロサービスは嫌だ

15:00
コードをじっくり読んでいくと、isudaとisutarが、互いにHTTPアクセスして、アクセス先のプロセスでisuda/isutarデータベース要求している部分が完全に無駄なので、それぞれの実装にDBアクセス設定をゴリゴリ書いてアクセスするようにしました。

これによって約6000 → 9970 まで上がりました！
もっと余裕があれば、isudaとisutarの完全統合までやりたかった。

Nodeプロセス数が微妙に多い、そう微妙に。

17:00
起動するisudaとisutarのNodeプロセス数を、CPUコア数に合わせて3→2ずつに変更
9970 → これまでのベストスコア 12023 に！

と、ここまででタイムリミット。最後の最後に1万超えは嬉しかった…

ISUCONに参加してみて

個人的な反省点は下記の通り。

最後までサーバローカルで直接ソースコードを編集していたので、同時に修正できなかった。
- 結構思い込みでコーディングしてた中でミスも多々あったので、レビューもし易いことを考えても効率は上がるはず
- 声を掛け合っていたので、デグレードが起きなかったのはせめてもの救い
次はチェックリストを作っておいて、作業の経過が見えたり、よりバッティングしないようにしたほうがいいかも
- id:foostanさんのように、GitHubのProjectsを使ってみるのもいいなぁと
Async Awaitとかkoaとか、もっとEcmaScriptやNodeの新しめの仕様を勉強しておけばよかった
ページングのために、キーワードの総数を毎回SELECT COUNTしていたけど、キーワード登録のときにメモリに回数を持って、それを使うようにすればそこそこ速くなったはず。途中まで実装していたけど間に合わず。
html生成の部分がもっとも重いことは明白だったので、トライ木の構築をしてキャッシュすればかなり速くなるということで、id:nakimuraさんが最後の最後までライブラリを検証しながらテストしてたけど結局スコアが落ちてしまい、導入を断念orz
- トライ木の構築はメモリは食うのだけど、だからこそメモリが潤沢だったと思われるだけに残念…

ISUCON、前々から興味はあったけど、自分の現在地を知るのが恐くて参加できずにいました。
そしてこんな優秀なメンバーと参加できた以上、もっと貢献できたらなぁと思う場面ばかりで、悔やまれるばかりです。

でもめっちゃ楽しかった！プライベートな時間は結構費やしたけど、とても勉強になったので、もっと周りのISUCON人口を増やして切磋琢磨したいです。

本選に出場されたチームの皆様、当日は激しい闘いを期待しています！
最後に、ISUCON運営の皆様、本当にありがとうございました！
まだ本選は控えていますが、来年も激しく楽しい大会の開催を期待しています！

*1:ちなみに、C++で独自実装したチームもいたそうです。しかも予選通過。すごすぎる…！

bauer's diary

凡人の凡人による凡人のための備忘録