この記事はNTTコミュニケーションズ Advent Calendar 2019の7日目の記事です。
昨日は @jkr4869 さんの記事でした。

はじめに

今年9月に社内で開催されたN-ISUCONで優勝した際にやったことなどを書きたいと思います。N−ISUCONの詳細やそもそもISUCONとはといったことはこちらに載っています。
普段はSkyWayというサービスを開発しており、今回はSkyWayというチーム名で同じ開発チーム内のメンバー3人で出場しました。
使用言語はチームメンバー全員が慣れているJavaScriptでした。

まとめ

計測/改善を繰り返して影響の多い所から改善できた
ラスト約1時間を再起動テストに費やすことができた
事前に最初にやることを決めていて開始直後の時間から有効活用できた

やったこと

前日

当日の動きを決定
- VSCodeのRemote Developmentを使う
- ssh鍵を投入する
- 誰がどのファイルをバックアップするか
- 誰がどこの設定を投入するか
- 終了1時間前で再起動試験したりスロークエリ設定削除したり
- 等

当日

序盤

OS、スペック、ミドルウェア、フレームワークなどを確認
- ApacheだったのでNginxに変更
- expressを予想していたらfastifyだったため予想が外れた
カーネルやMySQLの秘伝のタレを投入
DBのスキーマをダンプ
kataribeやpt-query-digestを導入
- nginxログのフォーマット指定やmysqlのslow query周りの設定なども追加
ブラウザでWebアプリを実際に開いてみる
- 尋常ではない重さのページが表示された
ベンチを回してみる
- 初期実装だと 10分 ほどかかると言われていた
ベンチの待ち時間にソースコードを読んでN+1になっているところや他のまずそうな所を探した
画像をDBに保存している明らかに不味いところを発見し修正
VSCodeで接続しに行っているとベンチ後にサーバのSSHが切られる現象が何回も発生したのでサーバ内vimでの実装に変更

昼頃

12:50頃昼になっても点数が伸びないため昼食のタイミングを逃していたが、N+1を潰して5000点ほどで1位になれたのでひとまず昼食には入れた
お昼を食べつつ改善をしたらベンチが10分程度から1-2分へと爆速に
- 気軽にベンチを回して改善できるようになった
14:40頃改善を積み重ねて14180で3位に

終盤

15時過ぎ 3台中1台しかサーバを使っていなかったので、3台に処理を分散
- 2台のAppサーバと1台のDBサーバに分割
- リクエストはある1台にしか来ないので、upstreamを二つ設定してリバプロ
- DBのユーザがlocalhostからしかログインできない設定だったのでAppサーバからもログインできるように変更
- initializeが追加した方のAppサーバ側に飛ぶとそちらが画像を持っていないため失敗
  - 画像ファイルが分散するのもあり、initializeと画像へのアクセスは片方のAppサーバに固定
3台構成にしてベンチを回すと 10万点 越えを達成
他チームの最大スコアが3万点ほどだったので安全を取って再起動テストに移行
再起動テストで失敗し -10万点 越え
メンバーが数十MBのJSを数十KBまで削減した
undefinedが何故かリクエストの含まれてしまっていたので、それ用の処理を追加
点数が10万点ほどに復活
残り10分未満になりデグレなどが怖かったため、以下の改善点は放置
- fastifyのログ出力をOFFにする
- アイコン画像をアプリ側ではなく静的なファイルと同様にnginxで返す
最終スコアが唯一の10万点越えで優勝

改善したことの詳細

アイコンをDBから剥がす

ブラウザでWebアプリを開いてみるとコンテンツの読み込みだけでなくアイコン画像の読み込みも明らかに遅かった。ソースコードを読むと、

const img = Buffer.from(iconRows[0]['icon'].toString('binary'), 'base64');

CREATE TABLE `icon` (
    (省略)
    `icon` mediumblob NOT NULL,
);

となっており、画像がbase64でDBに保存されていてアクセス毎に読みに行っていることが発覚した。
対処としてDBから画像の部分を抜き出してファイルに保存するスクリプトを書いて実行した。後から追加されるユーザのアイコンはその時にアイコンフォルダに画像を追加で保存するように変更した。アイコンを読み込む処理はSQL文を発行するのではなく、画像を開いてそれを返すように変更した。
ソースコードを読むと一度アイコンを設定すると 二度と変更できない! 仕様になっていたので、初期ユーザのアイコンだけを別ディレクトリに切り出した。initialize処理時にアイコンフォルダを再生成する必要があるが、アイコンフォルダを初期ユーザ用ディレクトリで置き換えることが可能になり、intialize処理の負荷はほぼ変わらなかった。

パスワードのハッシュ生成部分の変更

パスワードは流石に平文ではなくハッシュ化されて保存されているのだが、そのコードは以下のとおりである。

const cmd = 'echo -n ' + str + ' | openssl sha256';
const res = await execCommand(cmd);

わざわざOpenSSLコマンドを叩きに行っており、更にストレッチングもしっかりしているのでハッシュ生成がかなり重い処理になっていた。
代わりにcrypto.createHashを使うことで外部コマンドの呼び出しが無くなり高速化できた。

アイテム一覧取得のN+1問題の解決

アイテム一覧は表示が遅く、計測結果からも重いことが分かっていたので改善を試みた。ソースコードを読むと、以下のような処理になっていた。
1. アイテム一覧を取得
2. ソート順がlike順ならlikeの多い順に、そうでないなら新しい順にアプリケーション側でソート
3. 各アイテム毎にアイテムを作成したユーザのユーザ名を取得

条件によってorder byを変え、joinによってユーザ名を一緒にとってしまえば1回のクエリで完了するように思えたが、実際にはlike周りの実装によってそのままでは実現できないようになっていた。

itemsテーブルにはlikesという不穏な名前を持つカラムが存在している。これはSQLアンチパターンに載っているジェイウォークの形をしていて、likeをしたユーザ名が例えばAlice,Bob,Charlieのように格納されている。SQLではここに何人のユーザが格納されているか分からないので、アプリケーション側で文字列を分解して人数を取得しなければならなくなっている。
他のlikeを取得したり、追加したり、削除したりする部分でも同様に文字列と配列の変換をして最後に戻すという処理を行っていた。

対処としてはitemsテーブルにlikeの数を持っておくlike_countのカラムを追加した。likeの数が変動する度にこのカラムの値も更新するようにしたことで上の処理1-3を当初の目的どおり1回のクエリで実行できるようになった。
これを改善したことでベンチマークの待ち時間が劇的に減少し、スコアも伸びて1位になり昼食を取ることができた。

感想

懇親会で解説されていた改善点はおおよそ直していたのですが、計測した結果から基本的に改善していったため、コメントのテーブルにcomment_001からcomment_100までのカラムが用意されているという改善点にはコンテスト中全く気付きませんでした。
しかし、改善点を全部直そうとせず計測によって効果的に実装していったのがスコアを伸ばすのに良かったのかなと思います。
また終了前の約1時間をしっかり再起動試験に使ったことで、スコア計測時の失格を防げたのも大きいと思います。
これらが実現できたのは同じチームのメンバーで出場したことで意思疎通がとても取りやすかったのもあると思います。
来年も参加や運営で関われたらなと思います。

明日は @mtskhs さんの記事です。

社内ISUCONで優勝した時にやったこと