Ecto の Telemetry Events 対応

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

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

[beam-telemetry/telemetry](https://github.com/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 では[ここ](https://github.com/elixir-ecto/ecto_sql/blob/master/lib/ecto/adapters/sql.ex#L793)で実行してます。

### Step2. モジュールの実装
モジュールを実装する前に、[Ecto のドキュメント](https://hexdocs.pm/ecto/3.0.8/Ecto.Repo.html#content)を読みますと、config に `telemetry_prefix` を設定するようにとありますので、その設定を行います。

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

```elixir

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 を追加したリストを受け取るようにします。

```elixir

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 してください。

```elixir

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` を使ってこのように書くこともできます。

```elixir

: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
アプリケーションスタート時に呼び出されます。

```elixir

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` に渡しているものは下記のモジュールとします。

```elixir

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: スーパーバイザーとアプリケーション](https://dev.to/gumi/mix-otp-04-bj0)をご一読ください。

### Application.start/2 実行時

1. [ここ](https://github.com/elixir-ecto/ecto/blob/master/lib/ecto/repo/supervisor.ex#L22)で config から `:telemetry_prefix` を読み込みます
2. [ここ](https://github.com/elixir-ecto/ecto_sql/blob/master/lib/ecto/adapters/sql.ex#L457)で[:query] をリストに追加します
3. [ここ](https://github.com/elixir-ecto/ecto/blob/master/lib/ecto/repo/registry.ex#L37)で ets(Erlang Term Storage) に insert しています。

### SQL クエリ実行時
1. Application.start/2 時に ets に insert した config などの情報を[ここ](https://github.com/elixir-ecto/ecto/blob/master/lib/ecto/repo/queryable.ex#L137)で取得します。
2. 次に[これ](https://github.com/elixir-ecto/ecto_sql/blob/master/lib/ecto/adapters/sql.ex#L344)が実行されます。
3. ここで [measurements](https://github.com/elixir-ecto/ecto_sql/blob/master/lib/ecto/adapters/sql.ex#L777) と [metadata](https://github.com/elixir-ecto/ecto_sql/blob/master/lib/ecto/adapters/sql.ex#L784) にパラメータを渡します。
4. そして[ここ](https://github.com/elixir-ecto/ecto_sql/blob/master/lib/ecto/adapters/sql.ex#L793)の判定が行われ、`:telemetry.execute/3`が実行されます。

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

```elixir

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 です。

```elixir

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 だと下記のようになっております。

```elixir

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](https://aws.amazon.com/jp/xray/)でクエリをトレースするために [aws_ex_ray_ecto](https://github.com/lyokato/aws_ex_ray_ecto) を使うところから始まりました。

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

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

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

```elixir

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より](https://hexdocs.pm/ecto/3.0.8/Ecto.LogEntry.html#content)

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

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

## aws_ex_ray_ecto 対応

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

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

```elixir

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](https://qiita-image-store.s3.ap-northeast-1.amazonaws.com/0/98381/3238dd91-85d6-02f6-cb77-28cd4fc11943.png)

![AWS_X-Ray-Ecto-Trace_qiita2.png](https://qiita-image-store.s3.ap-northeast-1.amazonaws.com/0/98381/c1279cd6-c8c4-0ecb-e9a3-c304bb5d4797.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 などを渡します。