ISUCON8 の本選問題は、競技者がコントロールできない外部 API 呼び出しを多数含んだ出題内容でした。
講評では、
サービスの特性を適切に分析した上で、まとめるところはまとめたり、遅延させるところは遅延させるなど
……とさらっと書かれていますが、実際そんなことを短時間で分析することは可能なのかよ！という話題が競技後の懇親会でもあったので、それ AWS X-Ray でできるよ、というエントリをまとめておきたいと思います。
今回の解析は Perl 版の初期実装に対して行ったものですが、なぜ Perl かというと AWS の公式 SDK にない X-Ray 関連の CPAN モジュールを自分が書いているので、その宣伝も兼ねています。(blogエントリ書いてなかった)
Go, Java, Node.JS, Ruby, .NET については、公式 SDK が提供されています。正直うらやましい。
どのように解析するのか
X-Ray のトレーシングをするためにソースコードに多少の手を加えてからベンチマークを実行すると、AWS console の X-Ray の画面で GUI で可視化ができます。
これは文章で説明するのが大変なので、画面キャプチャを貼りながら進めていきます。X-Ray へアプリケーションからどのようにしてデータ(トレース) を送信するかは最後にまとめます。また、競技時の初期実装では静的ファイルをアプリケーションが処理していてノイズが多いので、静的ファイルは nginx が配信するように変更した状態からはじめます。
まず、X-Ray へトレースを送信してしばらくすると、このようにサービス (丸いやつ) がグラフになった画面が出てきます。
Clients から、isucoin というサービスに矢印が伸び、そこから Isubank, Isulogger, Isucoin::Model, DBI, DBI::st, Furl::HTTP というサービスが呼び出されているのが可視化されています。
isucoin サービスをクリックすると、このサービスのレスポンスタイムがヒストグラムになって出てきます。 そのまま「トレースの表示」をクリックすると…
URLごとに平均レスポンスタイム、呼び出し回数などがサマライズされています。
ここで平均 1.6 sec といういかにもヤバそうな http://isucoin:5000/info?cursor=0 をクリックすると、その URL のみでフィルタリングされたトレースのリストが下に表示されます。
一番上の 1.3 sec 掛かっているものを開くと…
レスポンスタイム 1.3 sec のうち、どのような処理にどれぐらいの時間が掛かったのかがタイムラインとして表示されます。 495msec 掛かっている DB へのクエリ (DBI::st) があるので詳細を見てみましょう。
SELECT * FROM trade ORDER BY id DESC でテーブル全件23万行を読み取っている、問題のクエリが出てきます。これは結果的に1行しか使われないので、LIMIT 1 を付けるべきやつですね。
このクエリの親 (ひとつ上のサブセグメント) の詳細を見ると、Isucoin::Model の get_latest_trade メソッドから呼ばれていることが分かります。
ということで、当該メソッドのコードを修正し、LIMIT 1 を付けて再度ベンチを実行したあとに X-Ray を見ると
レスポンスタイムの分布が最初とは変わりました。1秒ぐらいにかけて盛り上がっていた山が消えています。
先ほどと同様に http://isucoin:5000/info?cursor=0 を選択してひとつのトレースを見てみると、
最初のクエリは 9.2 msec になっていました。
LIMIT 1 したことにより、23万行読み取っていたのが1行になっているのが確認できます。
外部 API 呼び出しの解析
ここまでは外部ではなく DB へのクエリの解析だったので、X-Ray によらずとも slow query log の解析でも把握できるものでした。
次に、外部 API のうちのひとつ、ISUBANK への API 呼び出しを解析してみましょう。
Isubank サービスを選択すると、そのサービスのみのレスポンスタイムの分布が表示されます。 100ms 以下のものが大半ですが、300ms 前後にも山があるのが観測できます。
300ms付近を選択してズーム
トレースを表示すると…
service("Isubank") { responsetime >= 0.215 AND responsetime <= 0.561 } という条件で抽出されたトレースのみが表示されています。
300ms前後の時間が掛かる Isubank の呼び出しは POST /orders からしか実行されていないことも分かります。
このトレースはいろいろ突っ込み所が多いのですが、今は 300ms 前後の Isubank 呼び出しを目的にしているのでそれを見ると…
commit であることが分かります。 このようにしていくつかのトレースを見ていくと、bank で 300ms かかるやつは commit だけだな…ということも見えてくるはずです。
丸見えですね。
アプリケーションへの組み込み
これまで見てきたようなトレース情報は、アプリケーションから直接 AWS の X-Ray API へ送信されているわけではありません。
アプリケーションからは UDP で X-Ray daemon というプロセスへトレース情報を送信し、X-Ray daemon が適宜バッファリングして AWS API に送信する、という作りになっています。UDP で送信するため、X-Ray daemon になにか問題が発生しても、アプリケーションはブロックせずに動作できる仕組みです。
X-Ray daemon の用意
ということで、まず X-Ray daemon をどこかで動かす必要がありますが、今回の初期実装は docker-compose なので、そこで動作させましょう。公式の Docker image は特に用意されていないようなので、ドキュメントに従って適当に Dockerfile を用意します。
webapp/xray/Dockerfile
FROM amazonlinux RUN yum install -y unzip RUN curl -o daemon.zip https://s3.dualstack.us-east-2.amazonaws.com/aws-xray-assets.us-east-2/xray-daemon/aws-xray-daemon-linux-2.x.zip RUN unzip daemon.zip && cp xray /usr/bin/xray ENTRYPOINT ["/usr/bin/xray", "-b", "0.0.0.0:2000", "--local-mode"] EXPOSE 2000/udp
docker-compose.yml
services: isucoin: environment: # 略 AWS_XRAY_DAEMON_ADDRESS: 'xray:2000' links: - mysql - xray xray: build: xray environment: AWS_REGION: "ap-northeast-1" AWS_ACCESS_KEY_ID: "xxxxx" AWS_SECRET_ACCESS_KEY: "zzzz"
AWS 外で動かす場合は access key を使用することになりますが、ISUCON のような他者が触れる環境で使用する場合は付与する権限に細心の注意を払ってください。X-Ray への write 権限のみの IAM user を作成し、その key を使用して、必要がなくなったら速やかに無効化するのをお薦めします。
Perl 実装への AWS::XRay 組み込み
Plack の entrypoint である app.psgi で、Plack::Middleware::XRay を有効にします。また、DBI, Furl などのトレースは Devel::KYTProf を利用し、Logger を置き換える形で取得するのでその設定もします。
# app.psgi use Devel::KYTProf::Logger::XRay; use AWS::XRay; Devel::KYTProf->logger("Devel::KYTProf::Logger::XRay"); # (中略) builder { enable 'XRay', name => 'isucoin'; # (後略)
これだけ (5行追加) で、Devel::KYTProf でプロファイルが取得できるものについてはすべてトレースが取得されるようになります。
さらに今回は、Isucoin::Model, Isulogger, Isubank の各モジュールのメソッド呼び出しもトレースするため、以下のコードも app.psgi に追加します (builder の前に)。長く見えますが、やっていることは AWS::XRay->add_capture() に各 package のメソッド名を渡しているだけです。
my $captures = { Isubank => [qw/ check reserve commit cancel /], Isulogger => [qw/ send send_bulk /], "Isucoin::Model" => [qw/ init_benchmark set_setting get_setting send_log user_signup user_login get_user_by_id get_user_by_id_with_lock get_orders_by_user_id get_orders_by_user_id_and_last_trade_id get_open_order_by_id get_order_by_id get_order_by_id_with_lock get_lowest_sell_order get_highest_buy_order fetch_order_relation add_order delete_order cancel_order get_trade_by_id get_latest_trade get_candletick_data has_trade_chance_by_order reserve_order commit_reserved_order try_trade run_trade /], }; for my $package (keys %$captures) { AWS::XRay->add_capture($package, @{$captures->{$package}}); }
Class::Inspector->methods などを使ってすべてのメソッドを自動で追加することもできますが、export された encode_json など、トレースに不要なメソッドまで追加されてしまうので列挙することにしました。
この記事の前半で行った解析に必要なことはこれだけです。この状態でアプリケーションを実行すると X-Ray へトレースデータが送られ、可視化されることになります。
なお、この状態ではすべてのトレースを送信するので、料金が問題になる可能性があります。Plack::Middleware::XRay ではサンプリングレートの設定、条件付きサンプリング (結果のステータスコードやレスポンスタイムの条件を見て、一致した場合だけトレースを送信する) こともできるので、詳しくは Plack::Middleware::XRayのドキュメント を参照してください。
トレース取得に伴うオーバーヘッド
トレースの取得処理は、対象の関数を wrap して実行時間などを計測するコードを挿入するだけのため、実アプリでのオーバーヘッドは大きくありません。
実測では、1リクエストにつき100個のトレースを取得した場合でも2ms程度のCPU時間消費で収まっているため、レスポンスタイムが平均50〜100msというような実アプリケーションにおいてはほぼ気にならないと思われます。
ISUCON では極限性能を求めるのに邪魔になる可能性は高いですが、その場合はチューニングが進んで不要になったらさっくり削除すればいいわけですし。
AWS へのトレースの送信しすぎによる課金増には、各自お気を付けください。条件サンプリングの不等号の向きを逆に書いてしまった結果、 1%だけ取得するつもりが99%取得してしまった事故がありました…
まとめ
ISUCONのレギュレーションでは競技中の外部リソースの使用は禁じられていますが、監視やモニタリングについての利用は認められています。 また、本番稼働中のアプリケーションについても常時トレースしておくことで、問題発生時の切り分けが容易になるでしょう。
AWS::XRay では Devel::KYTProf という既存の素晴らしいプロファイラを利用することにより、HTTP や DB 呼び出しについてのトレースを取得するだけであれば、既存アプリケーションに数行の追加で実装できます。どうぞご利用ください。