gihyo.jpサイトのロゴ

Perl Hackers Hub

第56回AWS X-Rayによる分散トレーシング―マイクロサービスのボトルネック、障害箇所の特定（3）

2019-08-21

（1）はこちら、（⁠2）はこちらから。

実際の分散Webアプリケーションの解析

（3）からは、実際の分散Webアプリケーションをトレースしてみましょう。

例として、2018年10月に開催されたISUCON8[1]本選問題を取り上げます。この問題は、運営が用意したブラックボックスとしての外部のWebサービスへのAPIアクセスが多数行われ、全体としては分散システムとして動作するものでした。

この問題をチューニングするには、外部へのAPIアクセスがどれだけ発生し、どれぐらいの時間を消費しているのかを把握することがポイントになります。

完全な問題、ベンチマーカ、ブラックボックスを含むリポジトリは、https://github.com/isucon/isucon8-finalで公開されています。本稿における改変を含めたリポジトリは、https://github.com/fujiwara/isucon8-final-wdpress111で公開しています。

単体アプリケーションへの組込み

まず競技者がチューニングを行う対象であるWebアプリケーションのPerl実装に、X-Rayを導入します。アプリケーションの実行環境でX-Ray daemonを起動し、AWS::XRayと関連モジュールの組込みを数行追加するのみで、アプリケーションのコードに手を入れる必要はありません。

X-Ray daemonを起動する

ISUCON8の初期実装はDocker Composeで提供されています。リポジトリ内のwebapp/docker-compose.yamlに、AWSが提供しているDockerイメージ[2]を利用してX-Ray daemonを起動する定義を追加します。

docker-compose.yaml
services:
  isucoin:
    environment:
      （省略）
      AWS_XRAY_DAEMON_ADDRESS: 'xray:2000'
    links:
      - mysql
      - xray
  xray:
    image: amazon/aws-xray-daemon:latest
    command:
      - --local-mode
    environment:
      AWS_REGION: ap-northeast-1
      AWS_ACCESS_KEY_ID: 123456789012
      AWS_SECRET_ACCESS_KEY: xxxxxxxxxxx

競技者がチューニングするWebアプリケーションはisucoinと呼ばれ、コンテナが定義されています。初期状態ではネットワークがブリッジモードのため、アプリケーションからxrayコンテナへ通信するためにはlinksの設定が必要です。環境変数AWS_XRAY_DAEMON_ADDRESSにX-Ray daemonが動作するアドレスとしてxray:2000を指定します。

X-Ray daemonからAWSにトレースを送信するために、xrayコンテナには環境変数AWS_REGION、AWS_ACCESS_KEY_ID、AWS_SECRET_ACCESS_KEY を設定します[3]⁠。

コードにAWS::XRayを組み込む

アプリケーションが起動するエントリポイントであるwebapp/perl/app.psgiファイルに、AWS::XRayと関連モジュールを利用する設定を追加します。やっていることはモジュールをuseして、Plackのミドルウェアをenableしているだけです。太字が追加箇所です。

app.psgi
use Isucoin::Web;
use Devel::KYTProf;
use Devel::KYTProf::Logger::XRay;
use AWS::XRay;
Devel::KYTProf->logger("Devel::KYTProf::Logger::XRay");

my $root_dir = File::Basename::dirname(__FILE__);
my $app = Isucoin::Web->psgi($root_dir);
builder {
  enable 'XRay',
    name => 'isucoin';

モジュールのインストールを行うために、cpanfileにrequiresを追加します。

cpanfile
requires 'Devel::KYTProf', '0.9992';
requires 'AWS::XRay', '0.08';
requires 'Plack::Middleware::XRay', '0.06';
requires 'Devel::KYTProf::Logger::XRay', '0.04';

これでAWS::XRayの組込みと、トレースの送信準備ができました。

競技アプリケーションを起動し、ブラウザからアクセスして、isucoinアプリケーションが表示されるのを確認してください。しばらくすると、docker-composeコマンドを実行しているコンソールに、daemonがAWSにトレースを送信しているログが出力されます[4]⁠。

docker-composeのログ出力
xray_1     | 2019-04-16T15:16:58Z [Info] Initializing AWS
X-Ray daemon 3.0.0
xray_1     | 2019-04-16T15:18:24Z [Info] Successfully sent
batch of 7 segments (1.432 seconds)

実際の競技時におけるアプリケーションのパフォーマンスを解析するために、リポジトリのREADMEにしたがってベンチマークを実行してみましょう[5]⁠。

X-Ray console による解析

ベンチマークを実行後にX-Ray consoleを見ると、サービスマップが表示されます（図1⁠）⁠。

図1　サービスマップ
図1　サービスマップ

この画面にはX-Ray daemonが送信したトレースが可視化されています。個々の丸いノードがセグメントで、isucoinからDBI、DBI::st、Furl::HTTPに矢印が伸び、呼び出されているのが見て取れます。

処理の絞り込み

isucoinをクリックすると、そのセグメントの処理に要した時間（レイテンシ）が分布図になって表示されます（図2⁠）⁠。

図2　isucoinサービスのレイテンシ
図2　isucoinサービスのレイテンシ

ここでレイテンシが3秒以上の遅い処理を選択して「トレースの表示」をクリックすると、条件に該当するトレースの一覧が表示されます。上の欄には3秒以上かかった処理がフィルタリングされ、URLでグループ化されて表示されます。平均レイテンシが3.4秒の/info?cursor=0を選択し（図3⁠）⁠、そのうちの1つのトレースを開いてみましょう。

図3　処理に3秒以上かかったURLの一覧
図3　処理に3秒以上かかったURLの一覧

セグメントの詳細を確認する

トレースの詳細画面では、そのトレースに含まれるすべてのセグメントが時系列に沿って並んでいます（図4⁠）⁠。全体の処理に要した3.5秒のうち、ひときわ大きく見える最初のDBI::st（DBIモジュールによるデータベースへのクエリ発行処理）のセグメントをクリックすると、セグメントの詳細が開きます（図5⁠）⁠。

図4　/info?cursor=0のトレース詳細
図4　/infocurso
図5　DBI:stセグメント詳細
図5　DBI:stセグメント詳細

セグメントが持っている情報として、自身のID、親のID、開始時刻と終了時刻のほかにも各種タブが並んでいます。SQLのタブでは発行されたクエリが、メタデータのタブではクエリに付随する情報が閲覧できます（図6⁠）⁠。

図6　発行されたSQL
図6　発行されたSQL

メタデータのrowsは、クエリによってデータベースから返却された行数です。図7では、23万行以上を読み取っていることがわかります。しかし、このクエリを発行しているアプリケーションのソースコード[6]をよく読むと、実はこのクエリ結果は最初の1行しか使われていないことがわかります。

図7　メタデータ
図7　メタデータ

つまり、大量の行を読み取っているのは単に無駄な処理です。最初の1行のみが必要ならば、クエリの最後にLIMIT 1を追加するだけでアプリケーションの仕様を変えずにパフォーマンスを向上できるのではないか、と予想がつきます。

パフォーマンスの改善

実際にクエリの最後にLIMIT 1を追加して、再度ベンチマークを実行したあとのURL別集計を図8に示します。初期状態では平均レイテンシが3.4秒だった/info?cursor=0が、平均1.0秒まで改善しました。

図8　レイテンシが1.0秒に改善
図8　レイテンシが1.0秒に改善

分散アプリケーションへの組込み

ここまでは、スタンドアローンのアプリケーションから発行されたデータベースへのクエリを可視化して解析しました。実際に競技でチューニングするアプリケーションは、外部へのHTTPS APIの呼び出しを多数行う分散アプリケーションです。

ISUCON8での競技中は、isucoinアプリケーションからHTTPを受信するアプリケーションは、運営が提供するサーバで動作するブラックボックスで改変は不可能でした。しかし、ここでは分散アプリケーションの可視化の例として、ブラックボックス側にもトレースを組込みます。

外部へのHTTPリクエストにトレースIDを送信する

外部APIに対するHTTPリクエストヘッダに呼び出しもとのID を設定するため、webapp/perl/lib/Isubank.pmに手を入れて、X-Amzn-Trace-Idに$seg->trace_headerの値を渡します。差分を次に示します。

Isubank.pm
sub _request {
  my ($self, $p, $v) = @_;
  my $body = encode_json $v;
  my $res;
  capture "Isubank::_request", sub {
    my $seg = shift;
    try {
      $res = $self->client->post(
        $self->endpoint . $p,
        [
          "Content-Type" => "application/json",
          "Authorization" => "Bearer ".$self->app_id,
          "X-Amzn-Trace-Id" => $seg->trace_header,
        ],
        $body,
      );
    } catch {
（省略）
  };

誌面の都合で詳しくは説明しませんが、外部APIのブラックボックス側にも競技アプリケーション同様X-Ray daemonを起動する設定を行い、SDKを組込みます。

分散アプリケーションの解析

ブラックボックス側にもトレースを組込み、アプリケーションからトレースIDを送信した状態でベンチマークを実行すると、X-Ray consoleのサービスマップは図9のようになりました。

図9　サービスマップ
図9　サービスマップ

isucoinからブラックボックス側のisubank、isuloggerノードに矢印が伸びて、呼び出しが伝わっていることがわかります。

図10のトレースの詳細では、別々のプロセスで動作しネットワークで通信しているisucoin、isubank、isuloggerの各アプリケーションが、一連の処理を行っている状況が時系列で把握できます。

図10　複数アプリケーションのトレースが統合されて見える
図10　複数アプリケーションのトレースが統合されて見える

まとめ

本稿では、分散トレーシングを活用して、多数のコンポーネントが連携して処理を行う分散アプリケーションの障害解析やパフォーマンスチューニングを容易にする方法を紹介しました。

AWS X-Rayのほかにも多数の事業者やOSSが製品を提供しています。みなさんの環境に合ったトレーシングシステムを組み込んで、よりよいシステム運用を行うきっかけになったら幸いです。

さて、次回の執筆者は門松宏明さんで、テーマは「自作ツールによる日常業務効率化」です。お楽しみに。

WEB+DB PRESS

本誌最新号をチェック！
WEB+DB PRESS Vol.130

2022年8月24日発売
B5判／168ページ
定価1,628円
（本体1,480円＋税10%）
ISBN978-4-297-13000-8

  • 特集1
    イミュータブルデータモデルで始める
    実践データモデリング
    業務の複雑さをシンプルに表現！
  • 特集2
    いまはじめるFlutter
    iOS/Android両対応アプリを開発してみよう
  • 特集3
    作って学ぶWeb3
    ブロックチェーン、スマートコントラクト、NFT

おすすめ記事

記事・ニュース一覧