この記事は Akatsuki Advent Calendar 2018 の23日目の記事です。前回は id:yunon_phys さんの、エンジニア組織の責任範囲の透明性をRACI図で高めてみたでした。

はじめに

アカツキではElixirを使ってゲームのAPIサーバを開発・運用しています。ゲームのAPIサーバは、大量のリクエストを低いレイテンシで捌くことが要求されるため、Erlang VMの高いスケーラビリティが利用できるのは効果的です。加えてRubyなどを書き慣れている人にとっつきやすいElixirの文法も魅力です。

とはいえ、その性能を引き出すためには、やはりアプリケーションのパフォーマンスチューニングは不可欠です。その際、"Don't guess, measure" という言葉の通り、どこを改善すれば良いかを知るための良い計測ツールが必要になります。

これまでRuby on Railsのアプリケーションでは、計測・監視のためにNew RelicをAPM (Application Performance Monitoring) ツールとして使っていたのですが、現在New Relicでは公式にはElixirはサポートされていません。*1

そこで今回は、インフラの監視に利用していたDatadogにAPMも統合できることを期待して、Datadog APMを利用してみることにしました。

Datadog APMでは単なる集計値のみならず、タイミングの記録にも対応しており、下記のように個々のAPI内の処理内容をフレームグラフとして見ることも可能なため、性能改善には有効そうです。

f:id:NeoCat:20181215201740p:plain

対象アプリケーションの構成

今回、計測対象となるアプリケーションは以下のライブラリを利用しています。

Cowboy : Webサーバ
Ecto : データベースへのアクセス
Yacto : データベースのシャーディング対応、マイグレーション生成
Memcachex : memcachedへのアクセス

ElixirのWebフレームワークとしてはPhoenixがメジャーですが、今回はPhoenixは利用せず、Cowboyの上にAPIエンドポイントごとのハンドラを書いていくというシンプルな実装になっています。

APMへの対応

ElixirからDatadog APMを利用するのには、コミュニティで開発されている Spandex というライブラリを使用しました。 Spandexは様々なAPMに対応することを想定して開発されていますが、現在のところDatadogのみに対応しています。

導入

まずは、mix.exs に依存ライブラリとしてspandex、および関連ライブラリを加えます。

def deps do
  [{:spandex, "~> 2.1.0"},
   {:spandex_datadog, "~> 0.1.0"},  # Datadogアダプタ
   {:spandex_ecto, "~> 0.1.0"},     # Ectoを計測
   {:decorator, "~> 1.2"},
   ...

そして、必要な設定を config/config.exs に追記します。 DATADOG_HOST 環境変数は、別途インストールしたDatadog Agentの接続先を指すようにしておきます。通常はlocalhostで良いのですが、コンテナ等で導入した場合はそのコンテナ名とします。加えて、Agentにも DD_APM_ENABLED=true を渡してTracingのメッセージ(MessagePack形式)を受け取れるようにしておきます。

config :spandex,
  service: :sample,
  adapter: SpandexDatadog.Adapter,
  disabled?: {:system, "DD_APM_DISABLED", false},
  env: Mix.env()

config :spandex_datadog,
  host: {:system, "DATADOG_HOST", "localhost"},
  port: 8126,
  batch_size: 10,
  sync_threshold: 100,
  http: HTTPoison

config :spandex_ecto, SpandexEcto.EctoLogger,
  service: :ecto,
  tracer: SampleApp.Tracer,
  otp_app: :sample

spandex_ecto は性能計測値をログから取り出しているため、Ectoのログ出力先を追加しておきます。

  config :sample_app, MyApp.Repo,
    adapter: Ecto.Adapters.MySQL,
    loggers: [{Ecto.LogEntry, :log, [:debug]}, {SpandexEcto.EctoLogger, :trace, ["db_name"]}],
    ...

最後に、自分のアプリケーションにトレース用のモジュールを作り、アプリケーション起動時に初期化するようにします。

defmodule SampleApp.Tracer do
  use Spandex.Tracer, otp_app: :sample_app

  defmodule Error do
    defexception [:message]
  end

  def start() do
    Config.fetch!(:spandex)
    |> configure()
  end

  # Mixタスク等でAPI外からアプリケーションを利用する場合、これを最初に呼んでトレースを無効化しておく
  def disable() do
    Config.fetch!(:spandex)
    |> Keyword.merge(disabled?: true)
    |> configure()
  end

  # APIでエラーが発生した際は、これを呼び出すことでエラーだったことやそのメッセージを記録する
  def report_error(payload) do
    update_top_span(error: [exception: %Error{message: inspect(payload)}])
  end
end

defmodule SampleApp.Application do
  use Application

  def start(_type, _args) do
    ...
    SampleApp.Tracer.start()
    ...

以上で SampleApp.Tracer モジュールを通してAPMの計測が行えるようになりました。

各APIの計測の開始と終了

APIの処理の開始時と終了時に、それぞれ SampleApp.Tracer.start_trace(), SampleApp.Tracer.finish_trace() を呼び出します。 type > service > resourceという階層を持つキーワードをつけることで、Datadog APMのWeb UI上でトレースを分類して統計を取ることが可能になります。

加えて、これらの間に SampleApp.Tracer.start_span(), SampleApp.Tracer.finish_span() を呼び出すことで、その中で行われた個々の処理タイミングを記録することができます。この記録をspanと呼びます。

各spanはトレース画面でタイミングや所要時間を見られるほか、個々の集計も行われます。例えばEctoの発行しているクエリのうち、累計で最も時間を消費しているのはどれか？それはどのAPIから呼ばれているか？といった情報を知ることができます。他にも下記の http など、メタデータを記録させることもできます。*2

ここではCowboyのミドルウェアとしてこれらの関数を呼び出すことにします。また、他のミドルウェアでユーザ認証などを行なっているため、その所要時間がわかるよう、 "middleware" というspanを作っておくことにしました。

defmodule SampleApp.Middleware.Tracer do
  alias SampleApp.Tracer
  @behaviour :cowboy_middleware

  def execute(req, env) do
    # APIのトレースを開始するとともに、 middleware の span を作る
    meta = [url: req.path, method: req.method]
    Tracer.start_trace("request", service: :sample, type: :web, resource: req.path, http: meta)
    Tracer.start_span("middleware", service: :middleware, type: :middleware)
    {:ok, req, env}
  end
end

defmodule SampleApp.Middleware.Tracer.Start do
  alias SampleApp.Tracer
  @behaviour :cowboy_middleware

  def execute(req, env) do
    # middleware の span を閉じる
    Tracer.finish_span()
    {:ok, req, env}
  end
end

defmodule SampleApp.Middleware.Tracer.Finish do
  alias SampleApp.Tracer
  @behaviour :cowboy_middleware

  def execute(req, env) do
    # APIのトレースを終了する
    Tracer.finish_trace()
    {:ok, req, env}
  end
end

これらがをミドルウェアとして呼び出されるようにCowboyに登録します。

  :cowboy.start_clear(
    :sample,
    [...],
    %{middlewares: [
        SampleApp.Middleware.Tracer,
        :cowboy_router,
        SampleApp.Middleware.Authorize,  # 各種ミドルウェアが間に入る
        ...
        SampleApp.Middleware.Tracer.Start,
        :cowboy_handler,                 # ここでAPIのハンドラが呼び出される
        SampleApp.Middleware.Tracer.Finish
      ]
    }
  )

以上でアプリケーションの各APIがトレースできるようになりました！

計測対象の追加

Ectoの計測は追加済みですが、他にmemcachedや外部サービスの呼び出しなどをトレースしたい場合、それらの箇所にもspanを追加していきます。トレース対象の前後で start_span(), finish_span() を呼び出してもいいのですが、

  SampleApp.Tracer.span("name", service: :sample, ...) do
      ...
  end

のようにdoブロックで計測対象の処理を書くこともできます。spandex 2.4.0以降であれば、関数を丸ごとトレースする際はデコレータを使って

  @decorate trace(service: :external_service, type: :custom, resource: ...)
  def trace_me() do
    ...
  end

のように、さらに簡単にトレース対象に加えることができます。

トレースの無効化

計測によるオーバーヘッドは、やはり多少なりともあります。そこで、必要ない時には簡単にトレースを無効化できるよう、環境変数 DD_APM_DISABLED=true を渡せるようにしてあります。これを使って一部のホストだけでトレースを取るといった運用も可能です。

余談ですが、Spandex 2.0.0でトレースを無効化しようとすると例外が発生するというバグがありました。これを修正するPull Requestを送ったところ、すぐにマージしてもらえ、2.1.0では修正されました。些細ではありますがコントリビューションができて良かったです。

結果

集計結果はDatadog APMのWebページ上で閲覧します。サービス全体や個々のAPIについて、呼び出し頻度やレイテンシの分布、消費時間に占めるDBや外部サービスの割合などがひと目でわかります。

f:id:NeoCat:20181215213222p:plain

さらに下部にある個々のAPI呼び出しをクリックすれば、フレームグラフ形式でspanを見られ、さらにそこからspanにつけたメタデータの閲覧へと、細かくドリルダウンしていくことができます。

f:id:NeoCat:20181215201740p:plain

加えて、そのホストのメトリクスも同じ画面内で参照できるため、例えば特定のトレースが遅い時、CPU負荷は高かったのか？といった情報も簡単に得られるようになりました。これはインフラ監視とAPMを統合することのメリットと言えます。

終わりに

この記事では、ElixirのWebアプリケーションのAPIの性能をDatadog APMで計測する方法として、Spandexライブラリの使用方法を紹介しました。

実際に、APMを仕掛けた状態で開発中のアプリケーションのストレステストを行ったところ、N+1クエリなどの非効率な処理がいろいろと見つかり、中でも頻度が高いところを集中的に改善することができました。

それだけに留まらず、DatadogのメトリクスとしてAPMの集計値を利用できるため、個々のAPIの性能に対してアラームを設定したり、Watchdog機能を使って急激に呼び出し頻度が増えたAPIやクエリを自動検出することも可能になり、サービスの運用中にも便利に活用できそうです。

*1:コミュニティによるライブラリは開発されていますが、Phoenixを前提としているものが多いようです。後述の通り、今回の対象アプリケーションはPhoenixを使用していないため、採用は見送りました。

*2:メタデータとして渡せる構造には制限があるようです。SpandexのREADME.mdを参照してください。

Akatsuki Hackers Lab | 株式会社アカツキ（Akatsuki Inc.)

Akatsuki Hackers Labは株式会社アカツキが運営しています。

ElixirのサーバアプリケーションをDatadog APMでトレースする