Stretcher をご利用中のかたに大切なお知らせ (S3 Signature V2廃止の件)

拙作の pull 型デプロイツール Stretcher をご利用中のかたに大切なお知らせです。

Amazon S3のAWS署名バーション2が、2019年6月24日をもって廃止されます

dev.classmethod.jp

Stretcher v0.x は Amazon S3 からのファイル取得に AdRoll/goamz を利用しており、このライブラリは Signature V2 を使用しているため、2019年6月24日以降 S3 からのファイル取得に失敗するようになります。

現状でも Signature V4のみサポートしているリージョン (us-east-2など) に対して実行すると、以下のようなエラーメッセージで失敗することが確認されています。

Load manifest failed: cannot detect valid credentials or region

ということで、この機に公式 SDK aws-sdk-go に実装を切り替えた v1.0.0 をリリースします。

現在 rc1 を提供していますので、ご利用中のかたは検証の上バージョンアップをお願いします。

(2019-03-17 追記) v1.0.0 をリリースしました。 github.com

基本的に互換性は保っていますが、credential の読みこみを自前のコードから SDK に変更した関係で一部非互換がある可能性があります。 現時点で確認されている非互換としては以下のものがあります。

  • $HOME が設定されていない状態で ~/.aws/credentials の認証情報を読み取れない
    • ホームディレクトリが解決できないため
    • 実行時に適切な $HOME を設定すれば解消します
    • 古い版では mitchellh/go-homedir で自前で解決していたので公式 SDK になって挙動が変わりました

他に何か問題がありましたら https://github.com/fujiwara/stretcher/ まで issue か、Twitter で @fujiwara までお知らせください。

github.com 報告していただいた varusan さん、ありがとうございました!

YAPC::Tokyo 2019でAWS X-Rayによる分散トレーシングの発表をしました

2019年1月26日に開催された YAPC::Tokyo 2019 にて、「Perlでも分散トレーシングしたい! - AWS::XRayによる解析とその実装」というタイトルの最後で発表してきました。

yapcjapan.org

発表資料はこちらです。

speakerdeck.com

ほとんどのクラウドベンダーやマネージドサービスで Perl SDK が提供されていない昨今ですが、AWS X-RayPerl で使いたいがために AWS::XRay を書いたよ、例として ISUCON 8 本選問題を解析してみたよ、という話です。

X-Ray は分散システムでなくても (従来型の RDBMS を使うだけの Web アプリケーションでも) パフォーマンス解析に有用で、使い始めるのに手間もないので興味を持ってもらえた人がいたら幸いです。

会場で挙手してもらった感じでも分散トレーシング自体それほど広く認知されてないようで、そのへんもあってちょっと集客がうまくいかなかったな… というのが反省点ですね。タイトルや内容の工夫の使用がもうちょっとできた気がします。


今回の YAPC でもう7回目の発表で、自分にとっての故郷的な感が強いカンファレンスです。

アクティブな CPAN Author が年々減っていたりと、今後開発のメイン言語として Perl が採用されることはどんどん減っていく流れは明白で寂しい限りなんですが、それでも400人近い人が集まって、Perl入学式などで入門してくる若者もいて、活気があって楽しかったですね。Songmuさんの男泣きにはぐっと来るものがありました。

次回、京都であるかも知れないということなので、楽しみにしています!

graceful restart できない daemon の再起動時のダウンタイムを HAProxy でリトライして救う

とあるネットワーク(Web)サーバがありまして。

  • graceful restart できない
  • graceful stop はできる
    • 処理中のものは全て処理し終わってから終了する
  • 再起動は数秒で完了する

という性質のものを、稼働中に再起動するとダウンタイムがでてしまうのをなんとか誤魔化したかったのです。

最初は nginx から proxy しているところで、繋がらなかったら何秒かおいて何回までリトライ、みたいな設定ができないか探したんですが見つからず、HAProxy を調べたら以下のような設定でできたのでメモ。

frontend absorber
    mode tcp
    default_backend upstream
    bind *:9999

backend upstream
    mode tcp
    server localhost localhost:8888 weight 1
    retries 10

retries 10 で、接続できなかった場合には 1秒間隔(1秒以下のtimeout connect が指定されていればその間隔) で10回までリトライする、という挙動になります。これで10秒以内に再起動できれば救済可能です。

適当に ab でリクエストを流し続けながら再起動してみてもエラーはでなかったので、大丈夫でしょう。

(2018-01-15 18:15 redispatch は関係なく、再試行間隔は timeout connect に依存していたので修正しました)

Mackerel と連携する外形監視エージェント maprobe でマネージドサービスのメトリック収集を自動化する

Mackerel Advent Calendar 2018 22日目の記事です。

ちょっと前に maprobe という、Mackerel のホスト情報と連携して外形監視を行うエージェントツールを作りました。

sfujiwara.hatenablog.com

maprobe は指定した Mackerel のサービス、ロールに存在しているホストに対して外形監視を行った結果をホストメトリックとして投稿するものです。定義にしたがって外から pingTCP, HTTP の疎通を確認した結果を投稿できるのですが、mackerel-agent のメトリックプラグインと互換性のある出力をするコマンドを実行する機能もあります。

今回は AWS インテグレーションで管理されているマネージドサービスのホストに、maprobe でメトリックプラグインで取得したメトリックを追加することで、運用負荷を下げる手法を紹介します。

AWS インテグレーションで管理されたホストにカスタムメトリックを投稿する方法(おさらい)

メトリックプラグインによって得られたメトリックを AWS インテグレーションで管理されているホストに送信することは、mackerel-agent でも可能です。

例として ElastiCache Redis に対してメトリック収集を行いたい場合、どこかのホストで実行されている mackerel-agent の設定に以下のような記述をします。

[plugin.metrics.redis-001]
command = [
  "mackerel-plugin-redis",
  "-host=redis-001.xxxx.apne1.cache.amazonaws.com",
  "-tempfile=/tmp/mackerel-plugin-redis-001",
  "-config-command=",
]
custom_identifier = "redis-001.xxxx.0001.apne1.cache.amazonaws.com"
  • ElastiCache では CONFIG コマンドが実行できないので、-config-command= の設定で CONFIG による値取得を無効化しています
  • -tempfile の指定は、同一 agent で複数の ElastiCahce を監視する場合に状態管理ファイルを分離するために必要です

ポイントは custom_identifier で、ここに mkr hosts --verbose で確認できる customIdentifier の値を指定します。

これによって AWS インテグレーションで認識された ElastiCache のホストに、mackerel-plugin-redis によって取得したメトリックを投稿することができます。

mackerel-agent でメトリック収集する場合の運用負荷

このように maprobe を使わずとも mackerel-agent でもメトリック収集自体は可能なのですが、運用上面倒な点があります。

  • custom_identifier を調べる必要がある
    • 何らかの方法 (mkr コマンドや API) で調べた値を、config に静的に書き込む必要があります
  • ホストが増減した時の設定更新が必要
    • AWS 上でインテグレーション対象のホストを増減した場合、config の記述もそれに合わせて増減する必要があります
    • 具体的には、設定ファイルを再生成して mackerel-agent の reload が必要になります

maprobe で解決すること

maprobe は指定したサービス、ロールのホストを Mackerel API から収集し、その時点で存在している全てのホストに対して外形監視、コマンド実行を行います。メトリック投稿には API で得られた Mackerel のホストIDを使用するので、custom_identifier を調べる必要はありません。

ホストが増減した場合には自動的に追従するため、設定ファイルの変更は必要ありません。

設定ファイルが変更されている場合には自動で再読み込みを行うため、新しい監視設定を追加しても再起動は必要ありません。

maprobe の設定例

先に記述した、ElastiCache Redis にカスタムメトリックを投稿する例は maprobe では以下のようになります。(v0.2.3で command に配列を渡せるようになりました)

probes:
  - service: production
    role: ElastiCache
    command:
      command:
        - "mackerel-plugin-redis"
        - "-host={{.Host.CustomIdentifier}}"
        - "-tempfile=/tmp/mackerel-plugin-redis-{{.Host.ID}}"
        - "-config-command="
      graph_defs: true

graph_defs: true を指定すると、プラグインから得たグラフ定義の投稿 (MACKEREL_AGENT_PLUGIN_META=1 で得られる結果) を自動的に投稿するため、Mackerel 上での見た目は mackerel-agent でメトリック収集したものと同一になります。

さらに maprobe では、ping, TCP, HTTP による外形監視 (check-{tcp,http} とほぼ同等機能) も行えるため、Redis プロトコルPING, PONG による外形監視も追加できます。

probes:
  - service: production
    role: ElastiCache
    tcp:
      host: "{{ .Host.CustomIdentifier }}"
      port: 6379
      send: "PING\n"
      expect_pattern: "PONG"
    command:
      command:
        - "mackerel-plugin-redis"
        - "-host={{.Host.CustomIdentifier}}"
        - "-tempfile=/tmp/mackerel-plugin-redis-{{.Host.ID}}"
        - "-config-command="
      graph_defs: true

Mackerel 本体で提供されている外形監視は、現時点ではグローバルな HTTP(S) に対するもののみです。マネージドサービスのホストでは mackerel-agent が稼働しないため、Unreachable なアラートも上げられません。そのためダウン検知がむずかしいのですが、maprobe では外形監視によりホストのダウンを素早く検知できます。

まとめ

maprobe は Go で実装された OSS です。Mackerel API を利用して、簡単な設定で指定したサービス、ロールのホストに対する外形監視とメトリック収集、投稿を行えます。

github.com

DockerHub でイメージも公開 しているため、コンテナ環境での利用も容易です。

マネージドサービスのホストが増減しても、特に監視設定の変更を意識せずにメトリック収集、外形監視を追従できるため、運用負荷を下げることができるでしょう。

WEB+DB PRESS vol.108 に18周年記念エッセイを寄稿しました

いつもお世話になっている WEB+DB PRESS誌の vol.108 に、18周年記念エッセイを寄稿しました。2018年12月22日発売です。創刊18周年おめでとうございます。

WEB+DB PRESS Vol.108

これまで WEB+DB PRESS には Perl Hackers Hub (vol. 71) と、特集 (vol.94) で技術記事を書かせていただきましたが、まさかエモい文章を求められるとは。どういう経緯での人選なのかは知るよしもありませんが…

普段カンファレンスなどでも技術の話しかしないので、引き受けようかどうしようかちょっと迷ったのですが、(中を読んでいただければ分かるとおり) こういうお誘いには乗っておくべきだということで快諾しました。

いただいたお題が「私が限界を感じたとき」というもので、普段は「人生なるようにしかならないよ」と適当に生きているのでちょっと困りました。WEB+DB PRESS & 限界というキーワードで思い浮かんだのが20年近く前、WEB+DB PRESS の創刊当初の昔話だったため、完全におじさんの昔語りになっています。ご笑覧ください。

f:id:sfujiwara:20181220233548j:plain

「こんな仕事のしかたをしていては死ぬな」というタイトルは編集の方に提案していただいたもので、特に他にいい案も思い浮かばなかったのでじゃあそれで、と決めたものです。他の3名の方々のエッセイを読み、自分の語りがなんだかちょっと恥ずかしくなったので、今後も基本的には真面目に技術の話をしていきたいと思います…

今号の特集は、スキーマ駆動 Web API 開発 (最近はもう必須ですね)、久々の PostgreSQL 大特集 (いまは MySQL ばかりですが昔使ってて実は PostgreSQL 大好きです)、ZOZOのリプレースノウハウ大公開 (泥臭い、けど価値がある話で大好物) と大変おもしろく読ませていただきました。今号からは Kindle 版も用意されるようで、より多くの環境で読みやすくなりますね。ぜひどうぞ。

WEB+DB PRESS Vol.108

WEB+DB PRESS Vol.108

  • 作者: 大和田純,中野暁人,山本浩平,曽根壮大,ZOZOTOWNリプレースチーム,権守健嗣,茨木暢仁,松井菜穂子,新多真琴,laiso,豊田啓介,藤原俊一郎,牧大輔,向井咲人,大島一将,上川慶,末永恭正,久保田祐史,星北斗,池田拓司,竹馬光太郎,粕谷大輔,WEB+DB PRESS編集部
  • 出版社/メーカー: 技術評論社
  • 発売日: 2018/12/22
  • メディア: 単行本
  • この商品を含むブログを見る

エッセイ中にも出てくる自分にとって転機になったカンファレンス、YAPC が来年1月に東京で開催されます。

yapcjapan.org

自分も分散トレーシングと AWS X-Ray の話をするので、こちらも是非よろしくお願いします。チケットもまだ発売中です!(2019年1月6日までの予定です)

今年書いた & update したCPANモジュールたち

Perl Advent Calendar 2018 11日目のエントリです。

最近、新しく書きはじめるもので Perl を使うことはめっきり減っているのですが、それでも仕事のいくつかのプロジェクトのメイン言語が Perl だったり、リリースした CPAN モジュールでまだまだ需要があるものはメンテが必要です。

ということでちょくちょく Perl も書いているので、今年自分がリリースした CPAN モジュールと update の変更点をまとめておきたいと思います。

Fluent::Logger

おなじみ Fluentd へログを送信するためのモジュール。2011年にリリース以来、継続的にメンテナンスしています。2018年の変更は、エラー時に即座にリトリライするためのオプション追加でした。

  • 0.27 2018-06-19T07:52:56Z
    • Add retry_immediately option (#28)

これは、とあるプロジェクトで AWS NLB の配下に fluentd を配置していて、NLB が 360秒間通信がないとコネクションを切断してしまうので (普通の fluentd はそういう挙動はしない)、その場合のリトライが次のログ送信時まで遅延してしまうのを救済する意図で追加したものでした。

Redis::Setlock

Redis を使って排他ロックを取得するためのモジュールです。こんなエントリも書きました。 sfujiwara.hatenablog.com

社内の Perl のプロジェクトではよく使われていて、そこでの要求からいくつかの機能追加があります。

  • 0.12 2018-07-09T08:50:57Z
    • Set expire to a wait queue. (#6)
  • 0.11 2018-05-24T05:04:58Z
    • Add blocking option to lock_guard (#5)
  • 0.10 2018-05-24T04:23:50Z
    • Change an algorithm to build key name for $WAIT_QUEUE. (#4)
  • 0.09 2018-05-23T07:33:17Z
    • Add $WAIT_QUEUE package variable. (#3) When $WAIT_QUEUE is true, wait for a lock released using BLPOP command instead of polling

このモジュールは Redis のある key を SET NX で排他取得し、必要なくなったらその key を削除することでロックを解放します。

ロックが競合した場合、あとにロックを取得しようとしたプロセスは 500ms 間隔のリトライで再度取得を試みるのが従来の実装でしたが、それでは解放待ちに時間が掛かりすぎるという課題がでました。そこで BLPOP を利用した解放待ち queue を用意して、解放時に queue へメッセージを送信することで、待たされているプロセスは速やかにロックを取得しにいく、という挙動ができるようになりました。

Katsubushi::Client

memcached protocol でアクセスできる分散ID採番機 katsubushi へのクライアントモジュールです。

  • 0.2 2018-07-25T03:10:29Z
    • fork safe (#4)

fork safe、(作者からすると)嫌な (使う側とすると)嬉しい fix ですね。

とあるプロジェクトでベンチマークをしていたところ、妙に katsubushi からのID取得に時間が掛かることが発覚しました。その原因を追及したところ、内部で使っている Cache::Memcached::Fast は fork safe ではない!ということに気づいて解決したものです。

一度接続したあと fork した場合、fork したプロセスがひとつの接続を共有してしまいます。そのため、自分が投げたリクエストの結果を誰かに横取りされてしまって、なかなかレスポンスが返ってこない、というような現象が発生するのでした。

fork safe ではないことは、Cache::Memcached::Fast のドキュメント にも、ちゃんと書いてあります。

disconnect_all

$memd->disconnect_all;

Closes all open sockets to memcached servers. Must be called after "fork" in perlfunc if the parent process has open sockets to memcacheds (as the child process inherits the socket and thus two processes end up using the same socket which leads to protocol errors.)

AWS::XRay, Plack::Middleware::XRay, Devel::KYTProf::Logger::XRay

これは今年の新作です。

AWS X-Ray という分散トレーシングのマネージドサービスに、Perl のアプリケーションからトレースデータを送信するためのものです。

公式の Perl SDK は提供されていないため、じゃあ自分で書くしかないな、ということでえいやと書きました。

f:id:sfujiwara:20181027013112p:plain

sfujiwara.hatenablog.com

ちなみに Katsubushi::Client が妙に遅い(ことがある)、というのは X-Ray の解析結果から気がついたものでした。DB へのクエリなどとは違って通常遅くなることが考えにくい部分なので、X-Ray がなかったら原因にたどり着くのに相当時間が掛かっただろうなあという実感があります。おすすめです。

X-Ray 関係のモジュールについては、来年1月に開催される YAPC::Tokyo で、 「Perlでも分散トレーシングしたい! - AWS::XRayによる解析とその実装」というタイトルで 40分の発表をする予定です。 YAPC::Tokyo 2019 - TALKS

12月16日まで チケットも発売中のようです ので、興味のあるかたは是非聞きに来てください!

まとめ

あらためて振り返ってみて気がついたのですが、実はこれらの修正はすべて、とあるプロジェクトの構築中に負荷試験で明らかになった問題を解決したり、負荷試験結果を解析するために作られたものでした。必要は発明の母ですね。

それでは、良いお年を。

AWS X-Ray による ISUCON8 本選問題の解析

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 へトレースを送信してしばらくすると、このようにサービス (丸いやつ) がグラフになった画面が出てきます。

f:id:sfujiwara:20181027005805p:plain

Clients から、isucoin というサービスに矢印が伸び、そこから Isubank, Isulogger, Isucoin::Model, DBI, DBI::st, Furl::HTTP というサービスが呼び出されているのが可視化されています。

f:id:sfujiwara:20181027010128p:plain

isucoin サービスをクリックすると、このサービスのレスポンスタイムがヒストグラムになって出てきます。 そのまま「トレースの表示」をクリックすると…

f:id:sfujiwara:20181027011110p:plain

URLごとに平均レスポンスタイム、呼び出し回数などがサマライズされています。

ここで平均 1.6 sec といういかにもヤバそうな http://isucoin:5000/info?cursor=0 をクリックすると、その URL のみでフィルタリングされたトレースのリストが下に表示されます。

f:id:sfujiwara:20181027010533p:plain

一番上の 1.3 sec 掛かっているものを開くと…

f:id:sfujiwara:20181027010848p:plain

レスポンスタイム 1.3 sec のうち、どのような処理にどれぐらいの時間が掛かったのかがタイムラインとして表示されます。 495msec 掛かっている DB へのクエリ (DBI::st) があるので詳細を見てみましょう。

f:id:sfujiwara:20181027010950p:plain f:id:sfujiwara:20181027011005p:plain f:id:sfujiwara:20181027011017p:plain

SELECT * FROM trade ORDER BY id DESC でテーブル全件23万行を読み取っている、問題のクエリが出てきます。これは結果的に1行しか使われないので、LIMIT 1 を付けるべきやつですね。

このクエリの親 (ひとつ上のサブセグメント) の詳細を見ると、Isucoin::Modelget_latest_trade メソッドから呼ばれていることが分かります。

f:id:sfujiwara:20181027011540p:plain

ということで、当該メソッドのコードを修正し、LIMIT 1 を付けて再度ベンチを実行したあとに X-Ray を見ると

f:id:sfujiwara:20181027012118p:plain

レスポンスタイムの分布が最初とは変わりました。1秒ぐらいにかけて盛り上がっていた山が消えています。

先ほどと同様に http://isucoin:5000/info?cursor=0 を選択してひとつのトレースを見てみると、

f:id:sfujiwara:20181027012405p:plain

最初のクエリは 9.2 msec になっていました。

f:id:sfujiwara:20181027012446p:plain f:id:sfujiwara:20181027012456p:plain

LIMIT 1 したことにより、23万行読み取っていたのが1行になっているのが確認できます。

外部 API 呼び出しの解析

ここまでは外部ではなく DB へのクエリの解析だったので、X-Ray によらずとも slow query log の解析でも把握できるものでした。

次に、外部 API のうちのひとつ、ISUBANK への API 呼び出しを解析してみましょう。

f:id:sfujiwara:20181027012939p:plain

Isubank サービスを選択すると、そのサービスのみのレスポンスタイムの分布が表示されます。 100ms 以下のものが大半ですが、300ms 前後にも山があるのが観測できます。

f:id:sfujiwara:20181027013103p:plain

300ms付近を選択してズーム

f:id:sfujiwara:20181027013112p:plain

トレースを表示すると…

f:id:sfujiwara:20181027013410p:plain

service("Isubank") { responsetime >= 0.215 AND responsetime <= 0.561 } という条件で抽出されたトレースのみが表示されています。 300ms前後の時間が掛かる Isubank の呼び出しは POST /orders からしか実行されていないことも分かります。

f:id:sfujiwara:20181027013553p:plain

このトレースはいろいろ突っ込み所が多いのですが、今は 300ms 前後の Isubank 呼び出しを目的にしているのでそれを見ると…

f:id:sfujiwara:20181027013804p:plain f:id:sfujiwara:20181027013841p:plain

commit であることが分かります。 このようにしていくつかのトレースを見ていくと、bank で 300ms かかるやつは commit だけだな…ということも見えてくるはずです。

丸見えですね。

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

これまで見てきたようなトレース情報は、アプリケーションから直接 AWSX-Ray API へ送信されているわけではありません。

アプリケーションからは UDPX-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 呼び出しについてのトレースを取得するだけであれば、既存アプリケーションに数行の追加で実装できます。どうぞご利用ください。