理系学生日記

おまえはいつまで学生気分なのか

はじめての ISUCON 体験記

先週の日曜日、ISUCON の予選に@kkasai さんと @hondaYoshitaka さんと参加しました。 記憶が確かなうちに書いておきたかったのですが、なかなかそういうわけにもいかなかったので、記憶とログを頼りに記載します。

当日

プロジェクトの高負荷時期と重なってしまい、ほとんど準備ができていないまま臨みました。 9:30 頃に集合し、アプリ、インフラ等、簡単な役割分担を決めました。その後、開始ギリギリのタイミングで

  1. slack 上で情報交換を行う room の作成 (今更…)
  2. github 上に private repository の作成

といったことを突貫で行ったあたりから、準備不足感が漂います。

10:00 になると、discord 上で ISUCON 運営からの開始連絡があり、 ISUCON 予選マニュアルの開示が行われました。

サーバ構築とログイン

予選が開始されると、サーバインスタンスから構築していく必要があります。このあたりは @kkasai さんに任せたほうが絶対に早いので完全におまかせし、まずは運営から連絡のあった ISUCON 予選マニュアルにざっくり目を通しました。 今回の対象アプリケーションには外部システム (PaymentService) 等が存在している、というところまでは認識できましたが、超高速な流し読みしかしなかったので、あまり良くわからんなぁというのがそのときの感想です。この「あまり良くわからんなぁ」が最後まで響いてしまうのですが。

ssh ログインが可能になった後 @hondaYoshitaka さんが .ssh/config を作成してくれて、これを皆で共有しました。

僕はというと github にソースをとりあえず PUSH しようとしていたのですが、 git push でエラーになるというゴミのような状況 (github アカウントで 2FA を有効にしていたため)。 token の設定とかやる暇も惜しかったので、結局 kkasai さんに PUSH お願いしますみたいな感じで、早くもぼくがボトルネックの様相です。

システム構成を調査する

ソースや設定ファイルを読んだ結果、1 インスタンスの中で以下のような構成になっている、という点は @hondaYoshitaka さんが早々に共有してくれました。

nginx - isucari (app) - mysql

一方で、予選マニュアル中に記述のあった外部システムについて、ソースコード中には localhost で待ち受けているように記載があります。 しかし、インスタンス上にそのようなプロセスは存在しません。

    DefaultPaymentServiceURL  = "http://localhost:5555"
    DefaultShipmentServiceURL = "http://localhost:7000"

このあたりは予選マニュアルをきちんと読めば「localhost の中の外部システムはあくまで開発用」であり、ベンチマーク実行時はインスタンス外部にリクエストが飛ぶ仕様という点は読み取れるのですが、 なぜか「localhost に外部システムのプロセスも立ち上げるのか〜〜〜」と壮大に勘違いしてしまい、この勘違いが最後まで足を引っ張った気がします。

アクセスログ解析

なにはともあれどこが遅いのかを調べなきゃということで、 nginx のログフォーマットを変更し、各アクセスの処理時間を解析します。

log_format with_time '$remote_addr - $remote_user [$time_local] '
                     '"$request" $status $body_bytes_sent '
                     '"$http_referer" "$http_user_agent" $request_time';
access_log /var/log/nginx/access.log with_time;

出力されるアクセスログを kataribe で解析すると、/users/transactions.json の遅さが目立つことは明らかでした。

$ cat /var/log/nginx/access.log | kataribe
Top 20 Sort By Count
Count    Total    Mean  Stddev    Min  P50.0  P90.0  P95.0  P99.0    Max  2xx  3xx  4xx  5xx  TotalBytes   MinBytes  MeanBytes   MaxBytes  Request
  102  293.639  2.8788  1.8089  0.044  3.337  4.995  5.128  6.474  6.579   98    0    4    0     1993936          0      19548      26976  GET /users/transactions.json HTTP/1.1
   60   15.765  0.2627  0.1365  0.082  0.248  0.456  0.513  0.607  0.607   52    0    8    0        5680         73         94        106  POST /login HTTP/1.1
   52    2.687  0.0517  0.0573  0.001  0.037  0.101  0.203  0.261  0.261   52    0    0    0      154024       2955       2962       2970  GET /settings HTTP/1.1
   46    2.031  0.0442  0.0577  0.001  0.016  0.134  0.158  0.217  0.217   31    0   15    0        1608         13         34        106  POST /sell HTTP/1.1
(snip)
TOP 37 Slow Requests
 1  7.089  POST /initialize HTTP/1.1
 2  6.579  GET /users/transactions.json HTTP/1.1
 3  6.474  GET /users/transactions.json HTTP/1.1
 4  5.765  GET /users/transactions.json HTTP/1.1
 5  5.749  GET /users/transactions.json?created_at=1565596038&item_id=20831 HTTP/1.1

/users/transactions.json の実装解析については hondaYoshitaka さんが見てくれて、Category のメモリキャッシュ化や N+1 問題対応を早々にすすめてくれており、さすが感がありました。

プロファイルを取る

ぼくはというと、/users/transactions.json のチューニングポイントを計測結果から探るため、golang でのプロファイルを取ることにしました。 go でのプロファイルはずっと net/http/pprofを使っているのですが、便利だという記事を読んだので今回は pkg/profile を使ってみました。

github.com

ですが、きちんと仕様を把握しないまま使ってしまったので、正しいプロファイル結果を取得できていません。これは帰ってから気づいた。これだったら net/htt/pprof 使ったほうが良かった。 以下の画像が、当日取得したプロファイル結果の一部です。

f:id:kiririmode:20190915083503p:plain
誤解を生みかねない Profile 結果

取りたかった結果ではないにせよ、blowfish の負荷が目立っていたので、これパスワードの暗号化でしょ、もういっそのこと平文にしてやったら良いじゃん!! という話を冗談っぽくしてましたが…。 (御存知の通り平文保存はルール違反なので、本気で取り組まなくて良かった…)

負荷を見る

各プロセスの負荷を top や iostat あたりで見てみたのですが、おおよそ以下のような状況でした。

  • isucari (app) については 1 プロセスあたり 30-40 % の CPU 負荷
  • nginx の負荷は無視してよさそうなレベル
  • MySQL については I/O よりも CPU Bound (CPU 利用が 140% 超える)

MySQL

MySQL については slow query を取るとともに、完全に CPU bound に見えたのも鑑みて、以下を並行ですすめることにしました。

  • slow query の取得と解析
  • 他サーバへの MySQL の外だし

slow query に関しては正直経験不足できちんとした解析まで至らず。怪しそうなクエリに対してはヤマカンで index 張っても見ましたがほぼほぼ効果なく。きっと pt-query-digest とか使っていればよかったんだよね。すっかり忘れたわ。

CPU Bound な理由についても、私の経験上は bind 変数が使われていない (都度 parse が走る) といったことくらいしか思い浮かばず、仮説自体が立てられなかったので早々に諦めました。

MySQL 用のサーバ構築とバッファキャッシュ周りの(MySQL だと言い方違うのかな?)のチューニングを @kkasai さんにお願いし、アプリは @hondaYoshitaka さんにお願いしたので、ぼくは構成をスケールアウトさせる方針で動くようにしました。後の祭りですがここは後悔ポイントで、もっとアプリケーションの動作等を把握しておくべきだったなと反省しています。

スケールアウト

isucari のアプリケーションの session 管理は cookie ベースで実施しているようでした。あまり大きな手術をするのも怖かったので、sticky session でロードバランスすればスケールアウトできるだろうと考えました。 isucari アプリケーション自体の CPU 負荷は高くなかったため、1 サーバあたり 2-3 インスタンスくらい立ち上げれば CPU を使い切れるだろうという算段です。

nginx で sticky session は(無償版だと)できないというのが私の理解なので、nginx を apache の mod_proxy_balancer で置き換える方針で動いてみました。正直ここは、運営側が nginx ではないミドルウェアへの切り替えを意図して出題しているんだろうなと曲解していたので、振り返ると恥ずかしい限りです。

私自身の apache の version の認識誤りにより、中間証明書まわりの設定で結構時間が取られてしまったのですが、とりあえず apache への入れ替えには成功。ベンチマークを回してみましたが、ほぼスコアがあがりません。 一方で、httpd プロセスの CPU 負荷が 30-40 % 前後と nginx に比べて高騰し、う〜〜〜〜ん、となったのを覚えています。 このあたりで、「あー、アプリ直さないとスケールアウトしても意味ないなぁ」と思いました(ISUCON なのだから当たり前)

instance チェックに失敗することに気づく

インスタンスが運営の指示どおりになっているかを確認する instance checker のスクリプトが提供されていまして、これで NG になると(おそらく)予選敗退になります。 @kkasai さんが予選終了直前でこの事実に気づいてくれ、スクリプトを流してくれたのですが、結果はなんと NG。 慌ててインスタンスの再構築をしていたのですが、これが間に合わず、最終的にはスコア 0 で FINISH しました。

スペックチェックしてくれるツールがあったのですが、最初に流すのを忘れ直前で思い出し、実行した結果NGが出たため、インスタンスを作り直しました。 作り直した後、ベンチを実行したのですが、Failedなってしまい最終スコア0でした。

ISUCON9 予選参加しました - Qiita

ぼくは instance checker の存在すら認識してなかったゴミであるので、真に申し訳ない限りです。。。

反省点と感想

サマると以下のような反省があります。

  • ルールや仕様、ドキュメントをしっかり把握すべきだった。限られた時間ではあるが、外部サービス仕様やキャンペーンといった記述から読み取れるヒントはたくさんあったはず。
    • 即NGとなるポイントについては序盤でチェックしておくべきだった。
  • アーキテクチャ変更やミドルウェアのチューニングではなくアプリケーションとしての動作を理解し修正すべきだったのに、結局スケールアウト、チューニングに逃げてしまった。特に今回の問題のシステムはかなりシンプルだったので、悪い意味で逃げやすかった。

アプリケーションの全体像とボトルネックをきちんと理解しないままチューニングを進めても意味のないアプリチューニングで終わってしまう、というのは理屈ではわかっていました。わかっていたつもりでした。 それでも、限られた時間の中でそれを実行しようとするには強い判断力が必要です。今回は完全に「作業に逃げた」形になってしまい、きちんと「考える」ことができなかったのがとても悔しいです。

それでも、皆でチューニングに取り組めたのはとっても楽しかったですし、高スコアを出した方のエントリを読んだ結果どういう観点での分析が自分には不足しているのか、どういう技術が弱いのかが認識できる点もすごく良かった。 本当に参加してよかったです。