Qiita Teams that are logged in
You are not logged in to any team

Log in to Qiita Team
Community
OrganizationEventAdvent CalendarQiitadon (β)
Service
Qiita JobsQiita ZineQiita Blog
4
Help us understand the problem. What are the problem?

More than 1 year has passed since last update.

posted at

updated at

Organization

Ecto の Telemetry Events 対応

Telemetry Events を触り、ハマったり疑問に思ったことがあったのでまとめてみました。

Telemetry Events

Telemetry Events は Elixir アプリケーションで Metrics を追跡する一般的な方法として登場したライブラリです。

beam-telemetry/telemetry

使い方(簡潔バージョン)

Telemetry Events はドキュメントに記述されている通り、次の順番で実装します。

  1. :telemetry.execute/3 を実行する。
  2. イベント発生時に呼び出されるモジュールを実装する。
  3. :telemetry.attach/4(もしくは :telemetry.attach_many/4) で、2で実装したモジュールを attach する。

使い方(実例)

では具体的な例をあげて使い方の順番を追っていきたいと思います。
今回は SQL クエリをトレースしたかったため、Ecto の Telemetry Events を使ってみました。

Step1. :telemetry.execute/3 の実行

これは使用するアプリケーションが実行してくれます。
Ecto ではここで実行してます。

Step2. モジュールの実装

モジュールを実装する前に、Ecto のドキュメントを読みますと、config に telemetry_prefix を設定するようにとありますので、その設定を行います。

config

config は、イベントをキャッチしたい repo ごとに :telemetry_prefix(atom のリスト) を設定します。
省略した場合は repo を Module.split/1 した結果が :telemetry_prefix (下記の例でいうと、[:my_app, :repo, :repo1]や[:my_app, :repo, :repo2])となります。


config :myapp, MyApp.Repo.Repo1,
  database: "sample_db1",
  username: "sample_user",
  ...
  telemetry_prefix: [:myapp, :repo1]

config: myapp, MyApp.Repo.Repo2,
  database: "sample_db2",
  username: "sample_user",
  ...
  telemetry_prefix: [:myapp, :repo2]

モジュール

モジュール名、関数名は自由です。みなさんのコーディングルールに従って命名してください。
関数は config で設定した telemetry_prefix に :query を追加したリストを受け取るようにします。


defmodule MyApp.Sample.Handler do
  require Logger

  def handle_event([:myapp, _, :query], measurements, meta, config) do
    Logger.info("total_time: #{measurements.total_time}, log: #{inspect meta}")
  end
end

repo ごとに計測したい内容が異なる場合は、第二引数を _ にしないで :repo1, :repo2 と明記して、関数をそれぞれ用意してあげてください。

Step3. モジュールを attach する

Application の start/2 で、Step2で実装した関数を attach します。
repo ごとに :telemetry_prefix を変えた場合はその分 attach してください。


def start(_, _) do
  :ok = :telemetry.attach("repo1-log", [:myapp, :repo1, :query], &MyApp.Sample.Handler.handle_event/4, nil)

  :ok = :telemetry.attach("repo2-log", [:myapp, :repo2, :query], &MyApp.Sample.Handler.handle_event/4, nil)
end

:telemetry.attach_many/4 を使ってこのように書くこともできます。


:ok = :telemetry.attach_many("repo-log", [[:myapp, :repo1, :query], [:myapp, :repo2, :query]], &MyApp.Sample.Handler.handle_event/4, nil)

:telemetry.attach/4 の第一引数にはイベント名(他と被らないように)を、第二引数には config の :telemetry_prefix ++ [:query] を渡します。

以上で SQL クエリが実行された際に Ecto の Telemetry Events をキャッチして log を取ることができるようになります。

ハマったこと

  • :telemetry.execute/3 をどこで実行したらいいのか
  • config の :telemetry_prefix には一体なにを設定したらいいのか
  • :telemetry.attach/4 の記述方法

これらにハマってたので、自分のハマりポイントのまとめは以上になります。

疑問点

ひとまず Metrics は取れたのですが、次の疑問が湧き上がってきました。

  • config で設定した :telemetry_prefix の内容はどうやって Ecto で利用されるのか
  • 関数の引数や attach で渡す :query とはどこから出てきたのか
  • :telemetry.execute/3 はどのように実行されるのか
  • Ecto の場合、measurements と metadata にはどのような情報が入るのか

ということで、Ecto のコードを順に追っていくことにしました。
Ecto のコードをつらつらと書き並べるのは読みにくいと思ったので、該当コードのリンクを貼っていきたいと思います。

Application.start/2

アプリケーションスタート時に呼び出されます。


defmodule SampleApp do
  use Application

  def start(_type, _args) do
    repo_children = [Sample.Repo.Repo1, Sample.Repo.Repo2]
    children =
      [
        # Start the endpoint when the application starts
        SampleApp.Endpoint
      ] ++ repo_children
    opts = [strategy: :one_for_one, name: SampleApp.Supervisor]
    Supervisor.start_link(children, opts)
  end
end

repo_children に渡しているものは下記のモジュールとします。


defmodule Sample.Repo do
  defmodule Repo1 do
    @moduledoc false
    use Ecto.Repo, otp_app: :sample_app, adapter: Ecto.Adapters.MySQL
  end

  defmodule Repo2 do
    @moduledoc false
    use Ecto.Repo, otp_app: :sample_app, adapter: Ecto.Adapters.MySQL
  end
end

Supervisor.start_link/2 については、MixとOTP 04: スーパーバイザーとアプリケーションをご一読ください。

Application.start/2 実行時

  1. ここで config から :telemetry_prefix を読み込みます
  2. ここで[:query] をリストに追加します
  3. ここで ets(Erlang Term Storage) に insert しています。

SQL クエリ実行時

  1. Application.start/2 時に ets に insert した config などの情報をここで取得します。
  2. 次にこれが実行されます。
  3. ここで measurementsmetadata にパラメータを渡します。
  4. そしてここの判定が行われ、:telemetry.execute/3が実行されます。

event_name:telemetry_prefix ++ [:query] で、その event_name を渡して :telemetry.execute/3 を実行しています。
そのため、呼び出される関数や :telemetry.attach/4:query が必要というわけです。


if event_name = Keyword.get(opts, :telemetry_event, event_name) 
  :telemetry.execute(event_name, measurements, metadata)
end

ちなみに上記のコードをみてわかるように、opts:telemetry_prefix を渡す場合は :query は必須ではありませんが(指定した場合は config の設定を使わないので注意。最初はこれにハマりました)、クエリを実行する箇所に毎回 opts を渡すのは大変なのであまり実用的ではないと思います。

補足

Ecto SQL が渡す measurements と metadata ですが、Ecto SQL のバージョンによって異なることがあるのでご注意ください。
こちらが最新版の measurements と metadata です。


measurements = %{
  total_time: query_time + queue_time + decode_time,
  query_time: query_time,
  queue_time: queue_time,
  decode_time: decode_time
}

metadata = %{
  type: :ecto_sql_query,
  repo: repo,
  result: log_result(result),
  params: params,
  query: query_string,
  source: source
}

一方、Ecto SQL v3.0.5 だと下記のようになっております。


measurements = query_time + queue_time + decode_time
metadata = %{
  decode_time: decode_time,
  query_time: query_time,
  queue_time: queue_time,
  type: :ecto_sql_query,
  repo: repo,
  result: log_result(result),
  params: params,
  query: query_string,
  source: source
}

AWS X-Ray との連携

元々は AWS X-Rayでクエリをトレースするために aws_ex_ray_ecto を使うところから始まりました。

お手軽設定と思っていたが・・・

aws_ex_ray_ecto のドキュメントを読みますと

In your config file, put AwsExRay.Ecto.Logger into Ecto's :loggers setting.


config :my_app, MyApp.EctoRepo,
  adapter: Ecto.Adapters.MySQL,
  hostname: "example.org",
  port:     "3306",
  database: "my_db",
  username: "foo",
  password: "bar",
  loggers:  [Ecto.LogEntry, AwsExRay.Ecto.Logger]

で OK のように読めたのでいざ試してみたところ

Note: Ecto.LogEntry is currently soft-deprecated and will be hard-deprecated in 3.1.x. Instead you should use “Telemetry Events” (as documented in the Ecto.Repo docs)

Ecto.LogEntryより

と、Ecto.LogEntry が deprecated のため、Telemetry Events を使うことを推奨されていました(というかコンパイルが通らなかったので一択)。

これで Telemetry Events の使い方が理解できたので、実装してみたいと思います。

aws_ex_ray_ecto 対応

aws_ex_ray_ecto 対応の場合は handle_event/4AwsExRay.Ecto.Logger.log/1 を実行します。

AwsExRay.Ecto.Logger.log/1 は metadata に caller_pid を追加した map が渡されることを期待した実装になっております。


defmodule MyApp.AwsExRay.Ecto do
  def handle_event([:myapp, _, :query], _measurements, metadata, _config) do
    entry = Map.put(metadata, :caller_pid, nil)
    AwsExRay.Ecto.Logger.log(entry)
  end
end

あとはこの関数を attach してあげれば無事 AWS X-Ray でSQL クエリや実行時間が見れるようになりました。

AWS_X-Ray_qiita1.png

AWS_X-Ray-Ecto-Trace_qiita2.png

追記

2019年6月5日

:telemetry.execute/3 を実行するとなぜ :telemetry.attach/4 に渡した関数に metadata などが渡るのか、その仕組みが気になったので telemetry events のコードを追ったところ、ざっくり下記の手順で渡しておりましたので追記します。

  1. :telemetry.attach/4 を実行すると、attach()に渡した引数を ETS に保存します。
  2. :telemetry.execute/3 を実行すると、execute()に渡した引数を条件に ETS を検索し、関数を取得して metadata などを渡します。
Why not register and get more from Qiita?
  1. We will deliver articles that match you
    By following users and tags, you can catch up information on technical fields that you are interested in as a whole
  2. you can read useful information later efficiently
    By "stocking" the articles you like, you can search right away
4
Help us understand the problem. What are the problem?