情報畑でつかまえてロゴ
本サイトは NTTテクノクロスが旬の IT をキーワードに
IT 部門が今知っておきたい最新テクノロジーに関する情報をお届けするサイトです

NTT Performance Tuning Challenge 2020 で優勝してきた

NTT Performance Tuning Challenge 2020の参加レポートです。

はじめに

NTTテクノクロスの中野です。

以前ここでGroovy/Grailsとかの記事を書いてたのですが、最後の記事を見るともう4年も経つのですね。 というわけで、たいへんご無沙汰しております。

記事公開が遅れてしまったためすでに2週間以上経ってしまっているのですが、2020/9/11(金)に開催された NTT Performance Tuning Challenge 2020 に、いつも一緒に仕事をしている山本とK氏の3名でチーム「新米」として参加してきました。

結果は、3位以下のチームと比較すると約10倍以上、2位のチームのだいたい2倍のスコアを獲得して、優勝を勝ち取ることができました!うれしい!ありがとうございます!

NTT Performance Tuning Challenge 2020 とは

https://nttcom.connpass.com/event/182658/ の説明を引用すると、

用意されたWebアプリケーションを、制限時間内にいかに高速化できるかを競う、チーム対抗のプログラミングコンテストです。

2019年にN-ISUCONとして初開催し、今年2月には学生向けにも開催しましたが、今回は名称を変更して、NTTグループ社員と学生向けに開催します!

ということで、要はISUCON的なアレです。

基本的にNTTグループの技術者によるクローズドなコンテストで、今回は学生枠を用意して一般公募もしてました、というあたりがポイントですね。

練習会のようす

今年は本番直前の9/2(水)〜9/9(水)の期間に、2019年の課題を使った練習環境一式が用意されていました。 後から考えると、我々が本番で優勝できたのは、この練習会でしっかりと準備できたから、と言えると思います。

具体的には、次のようなことを実施しました。

  • チームメンバ全員で丸1日時間をとって、本番と全く同じタイムスケジュールで初見の練習課題を解く。
    • 目的: 本番の雰囲気や時間配分、役割分担などを体験する。
  • 翌日以降も、練習環境が閉じられるまで、時間を見つけては何度もいろいろな手法を試す。
    • 目的: 性能向上のための勘所や効果的な対策案の引き出しを増やす。
  • ベンチマーク取得のためのヘルパスクリプトや、ミドルウェアの設定ファイルなどを手元にとっておいて、素早く本番環境に反映できるようにしておく。
    • 目的: 定形的な処理を素早く自動化して、性能改善に集中できるようにする。

これが大変効果的で、ISUCON的なコンテストにでるのはメンバ全員はじめてだったのですが、課題のフォーマット、ボトルネックの測定方法、N+1問題などの典型的な罠の配置のされ方、いつでも過去の最大スコアを安定再現できるような進め方、タイムアップ直前にバタつかない終盤の時間配分戦略などなど、実践的な知識・ノウハウをだいぶ習得できました。

結局、練習環境がクローズされるまでの間、隙を見つけてはイジリたおしていたので、たぶん、ベンチマークの実行回数は我々のチームがダントツ一位だった気がします。

1点だけ難をつけるというか愚痴を書いてしまうと、ちょっとベンチマークの挙動に怪しいところがあったことでしょうか。 本来、実測フェーズにおいて、リクエストを上手く捌けない場合にはスコアへのペナルティとして扱うルールなのですが、なぜかベンチマーク処理自体がエラーで異常終了して「スコアなし」になってしまう、という挙動がありました。 何度もベンチを実行しているとときどき最後まで実行できることもあるなど安定しない上に、エラー終了時の情報が少なすぎて何が起こっているのかがまったくわからなくて、かなり苦労しました。 いろいろな性能改善案を試したくても、安定した計測ができないと、効果があったのかなかったのか、何かを壊してしまったのかなどがわからなくて進捗につながらないので、大変苦しい時間を過ごすことになります。

幸いなことにベンチマークのソースコードが公開されていたので確認してみたところ、k6というツールが使われていて、発生している事象からベンチマークスクリプトの中でk6コマンドが0以外のリターンコードを返しているルートに入っていることがわかりました。 しかし、k6をローカルにインストールして試してみると、シナリオ上でのレスポンスが期待値と違っているとか、対象APIのポートが開いていなくてそもそも接続できない、みたいな場合でもk6コマンド自体は正常終了(リターンコード0)になりました。 ベンチマークスクリプトとしては、リターンコードを条件分岐に使っているだけで、結果として出力していなかったので、何が起こっているのかまったく状況がつかめません。

想像ですが、ベンチマークサーバはCPUやメモリなどをかなり使うはずなので、練習会用のインスタンスだとリソース面で厳しくて想定外のエラーになっていたという可能性もあり、それならそれでまあ仕方がないかなとも思います。 感覚的には、ある程度のスコアがではじめたときに不安定になり出したような気がするので、そういうことなのかもしれません。

ちなみに、内心ドキドキしていましたが、本番ではそういうことはまったくなかったので、とても安心しました。

当日のようす

練習会でだいたい確立した役割分担に従って、スタートです。

  • 中野(筆者): アプリケーション改善担当
    • アプリケーションのソースコード(Go言語)の解析&改善
  • 山本: なんでも屋
    • DBチューニング(インデックス作成、DBの自動初期化方法のカスタマイズ等)
    • アプリケーションのソースコード(Go言語)の解析&改善
  • K氏: インフラまわり担当
    • ベンチマークを効率的に実行して、ボトルネックを測定するスクリプトの設置等
    • 1台構成→3台構成への変更

(参考) アプリケーションの最終コミット履歴

git rebase -iで再構成したり、コミット削除してgit push --forceしたりと、色々試行錯誤して改変しましたが、最終的なコミットログはこんな感じでした。

10:32:03 Initial import
10:57:35 DBの接続情報を ~/.env から読み込むようにした
10:58:10 before_bechmark.shから実行しやすいように、実行確認をコメントアウトした
11:22:58 init.shの中でindexを設定するようにした
11:43:39 REVOCATION_LIST_TARGETの定義をコメントアウトしてしまっていた問題を修正した
11:50:13 app/go/publicのシンボリックリンクを削除して、app/publicをコピーした
11:50:13 怪しそうなところにTODOコメントを追加した
11:50:13 アプリケーションコードをapp配下に移動した
11:50:14 DB初期化処理をdb.goに抽出した
11:50:14 type定義をtype.goに抽出した
11:50:14 initialize関数を抽出した
11:50:14 デフォルト画像をinitialize時にキャッシュしておくようにした
11:58:45 usersテーブルとreservationsテーブルにインデックスを追加した
12:34:47 jwtで怪しいところにTODOコメントをつけた
12:39:14 makeできるようにした
12:48:01 Makefileを調整した
13:06:30 キャンペーンモードを環境変数NPLUS_CAMPAIGN_MODEで指定できるようにした
13:22:35 dbのpoolサイズを環境変数で設定できるようにした
14:01:11 Dockerでローカル起動できるようにしてみた
14:02:22 予約時にreservationsテーブルをテーブルロックしないようにした
14:46:18 予約数の合計をDBに任せるようにした
14:55:51 JWTで毎回ローカルファイルにアクセスするところを改善した
15:23:14 ログイン時に無駄ロックを獲得するままになっていたのを修正した
15:52:53 .envからMySQLの認証情報をロードするようにした
15:56:25 ログイン/ログアウトの排他制御の粒度を細かくしてみた
16:03:50 一度アクセスした画像をメモリ上にキャッシュするようにしてみた(上限なし)

性能に関係がないのについついリファクタリングをしてしまったりしていますが、そういう性(さが)なので仕方がありません。

午前のようす

インフラ周り担当のK氏が黙々と仕込みを始める中、中野と山本はレギュレーションを読み込みます。 やってはいけないこととかスコア算出周りを重点的にチェックしつつ、アプリケーションの画面経由で仕様も把握します。

K氏のセットアップが完了したところで、早速Go版のアプリに対して初期状態のままベンチを回すと、だいたい500点ちょっとぐらいでした。 ほかのチームの最初の点数と比較すると、Go版が初期状態で一番高得点だったようです。

K氏が仕込んでくれたalpPercona-Toolkitの出力を見ながら、とりあえず大きそうなボトルネックを特定して、それぞれ並行して作業しました。

アプリケーションのソースコードをざっと眺めると、頻出のN+1問題や、毎回ファイルを読み込んでいる箇所が見つかったので、この辺かなーとTODOコメントをつけつつ、初手でリファクタリングを開始します。

ほどほどにリファクタリングを打ち切って、最初に手をつけたTODOは「対象の画像が登録されていない場合、リクエストのたびに毎回デフォルト画像をファイルからロードして返している」でした。 あまり効果がないだろうなとは思いつつ、手始めに瞬殺できそうなところで作業の流れを掴んでおきたいという目論見です。 対処内容としては、初期化リクエストを受けたときに単純にメモリ上にキャッシュしておくようにして、毎回のリクエスト時にはサクっとそれを返すようにしました。

山本によるMySQLのインデックスの追加もできていたので、合わせて本番環境に反映してからベンチマークを実行すると、スコアは1000点ちょっとぐらいにあがりました。 とりあえずは、リファクタリング&軽微な改善でエラーにならずに普通に動いたので、ひとまずそれでよしとします。

午後のようす

ローカルで動作確認まで実行できると作業が捗るので、Docker/Docker Composeで起動できるように頑張ってみましたが、DBの初期化処理まわりの仕込みに手こずって、30分くらいかけた段階で諦めました。無念です。 Makefileを修正してコンパイルはできるようにしておいたので、とりあえずコンパイルが通ったら、あとは直接本番環境で実行して試す、ということで妥協しました。

次のTODOに着手する前に、キャンペーンモードを変えてみるとスコアはどうなるのかを試してみました。 今回のお題では、キャンペーンモードという概念があって、ベンチマークからの初期化リクエストに対して1〜3の数字を返すことで、ベンチマーカが送信してくるリクエスト数を調整できます。 1が一番リクエスト数が少なくて、3が一番多い、という感じです。

最初はキャンペーンモード1がハードコードされていたので、アプリ起動時の環境変数で指定できるように改造してから、いきなりキャンペーンモード3で起動してベンチマークをとってみます。 実質的にはまだほぼ初期状態という感じですが、CPUがぜんぶ I/O wait で持っていかれて、結果的にスコアは激減しました。確か100点以下だった気がします。

というわけで、I/Oに効きそうなあたりに集中してアプリケーションコードの改善を開始します。

まずは、「JWTの失効リスト管理」問題でした。 JWTをセッション管理に使っていてログアウト時にトークンを失効状態にさせる必要がある、という仕様なのですが、巨大な失効トークンリストをリクエストごとに毎回ファイルから読み込んでいるのでI/O負荷が高い、という問題です。 とりあえず初期化時にロードしてメモリ上にキャッシュしておくことで、すべてのリクエストでファイルアクセスすることを抑止しました。 永続化は確実にしておきたいので、ログアウト時はオンメモリの失効リストにもトークンを追加しつつ、ファイルにも書き出しておきます。

並行して進んでいた、山本による「大きすぎるテーブルロックを必要最小限の行ロックにする」も反映して、ベンチマークを実行すると3000点ぐらいになりました。

この辺で、スコアボードがクローズされて、他のチームの様子が見えなくなりました。

この後、いろいろ試行錯誤をしてスコアが落ちたりベンチが失敗したりというツライ時間がやってきます。

K氏によって「3台構成(Web+App+DB)で実行できるようにする」対処の仕込みができたので、ベンチマークを実行してみると、残念ながらエラーで終了してしまいました。

エラーの原因を探しているときに、ログインリクエストのエラー件数が多少多いのが気になったので、これがエラーの原因かどうかはわかりませんが、ログアウト絡みでリクエストが素早く実行された場合でも厳密にリジェクトできるように排他制御を実装して改善しました。 ファイルへの書き出しで律速されて、リクエストごとのロック獲得待ちにならないように、オンメモリの失効リスト用のMutexとファイル書き出し用のMutexは別に用意するように配慮しておきます。

そのあと色々あって、なんとか安定して実行できるようになったのですが、スコア的には結局変わらず3000点後半あたりでウロウロしていました。

計測結果を見るとまだまだI/Oが高いので、先送りしていた「DBに格納された画像データ」問題に着手することにします。 割と大きめの画像ファイルが文字列にエンコードされてMySQLに格納してあり、一覧画面を表示するためにたくさんの画像データをDB→アプリ→WebサーバとバケツリレーをすることによってCPUとI/Oの負荷が高くなってしまう、という問題です。 DBから画像データをファイルにダンプして、Webサーバで直接静的ファイルとして配信する、という対処が王道ですが、MySQLが不慣れなのと、画像アップロード時の差し替えをどうするか、などの課題があったので、ちょっと雑な対処ですが、JWTの失効リストと同じくオンメモリでキャッシュするようにしました。 とりあえずまだメモリに余裕があるようにみえたので、上限や揮発する仕組み作りなどは先送りして、どんどん画像データをキャッシュしていく富豪的プログラミングで進めます。 デフォルトでは、起動スクリプトでアプリのメモリ量が制限されていたので、設定を変更してガツンと割り当てます。

しかし、スコア的には3000点後半から動きません。

元々この対処は、同じファイルに対するリクエストであれば速くなるけれど、満遍なくいろいろな画像にアクセスされると利用メモリが増えるだけで性能向上はしない、というリスキーな実装なので、実際に効果があるかどうかは賭けでした。

今回、この賭けに負けてしまったということなのでしょうか。

あとから思えば、この時間帯で実施したいろいろな対処は、この時点でまだ発見できていない後述のボトルネックのため結果には現れていないものの、潜在的な性能向上には寄与していたのだと思われます。

そして、その効果が劇的に発揮されるのは、この後。

終了直前のようす

3000点後半で膠着状態になったまま迎えた終了30分前、そろそろ再起動してからベンチマークが通るかどうかの確認をして手仕舞いをしないといけないね、という時間帯になったところで、メンバ2人がアプリケーションの最大コネクション数とMySQLの最大コネクション数とのズレに気づきました。 MySQLで受け付ける最大コネクション数は1000と大きくしていたのですが、アプリケーションの方を見ると150しか許容していませんでした。なんということでしょう。

急いで値を1000に合わせた上で、残り時間もないのでダメ元でキャンペーンレベル2に設定してリクエスト数を増やしてみたところ、いきなりガツンと念願の1万点オーバーを叩き出しました。 思わず机を叩いて声を上げてしまいました。

そのあと、時間もないのに欲張ってキャンペーンレベル3も試すと、やはりというかガクンと3000点台にが下がってしまったので、あわててもう一度キャンペーンレベル2に戻して、ベンチマークの実行を開始したところでタイムアップ。 sshセッションをすべて切断して、祈りながら最後のベンチマーク結果を待つと、なんとか無事に完走はしたのですが、スコアはギリギリ1万点に届かないくらいになっていました。

結果発表のようす

最後の最後で1万点を切ってしまいましたが、順位を決めるのは運営側で再起動してから計測したスコアです。 きっと再起動すればクリーンな状態になって1万点超えるはず(してほしい)と期待しながら結果発表を待つこと数十分、無事に11637点を獲得して、優勝することができました。

ふりかえり

勝因(?)

  • 事前にインターネット上で公開されているISUCON対策記事を読み合わせた。
  • 練習会で、本番と同じタイムスケジュールに従って擬似体験した。
  • 練習環境が提供されている間、しつこくしつこくスコア改善のための努力を続けた。
  • 「推測するな、計測せよ」という先人の教えに忠実に従って、測定結果を基に対策ポイントを絞り込んで優先度付けをした。
  • 定形的な自動化スクリプトなどは練習会で確立して、手元に用意しておいた。
  • 普段の業務で一緒に作業するやり方を共有していて、チーム作業の練度が高かった。
  • 時間ギリギリで、アプリケーションの最大コネクション数とRDBMSの最大コネクション数とのズレに気づくことができた。

反省点

強いていえばこんな感じでしょうか。

  • Redis等のキャッシュサーバを速攻で用意して、アプリからのアクセスを実装できるように素振りが必要。
  • RDBMSから静的コンテンツをダンプしてWebサーバで直接返す、みたいな頻出パターンですぐに手が動くように素振りが必要。
  • アプリの修正前に、手元のローカルマシンで実行できるようにしようとDockerを使って環境を構築しようとしたけど、DBの初期化まわりで手こずって結局あきらめた。貴重な30分強を無駄にしてしまった。
  • 今回はアプリ=1プロセスにしていたので期待通り動くが、アプリを複数起動した場合はオンメモリキャッシュだと動かないので、技術的負債になっている。
    • 今回の場合だと画像データはプロセスごとのキャッシュでもなんとか大丈夫だけど、JWT失効リストは全体で共有されていないとまずい。

おわりに

K氏による測定周りの迅速な仕込みがあったおかげで、効率的に作業が進められました。 また、表彰式では山本がいい感じにインタビューで答えてくれていてさすがでした。

というわけで、このような大変楽しくてためになる素晴らしいコンテストを開催していただいた運営のみなさま、本当にありがとうございました!

連載シリーズ
テクノロジーコラム
著者プロフィール
中野 靖治
中野 靖治

Groovyスクリプトの起動時間を短縮するGroovyServや、GroovyスクリプトでのExcel操作を劇的に楽にするGExcelAPIなどのOSSを業務/プライベートで開発、 一般に公開。Groovy/Grails/GradleなどのOSSへのバグフィックスや機能パッチの提供などにも貢献している。著書に『プログラミングGroovy』(技術評論社/共著)がある。自他共に認めるビール党。