Telemetry Events を触り、ハマったり疑問に思ったことがあったのでまとめてみました。
Telemetry Events
Telemetry Events は Elixir アプリケーションで Metrics を追跡する一般的な方法として登場したライブラリです。
使い方(簡潔バージョン)
Telemetry Events はドキュメントに記述されている通り、次の順番で実装します。
-
:telemetry.execute/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 実行時
-
ここで config から
:telemetry_prefixを読み込みます - ここで[:query] をリストに追加します
- ここで ets(Erlang Term Storage) に insert しています。
SQL クエリ実行時
- Application.start/2 時に ets に insert した config などの情報をここで取得します。
- 次にこれが実行されます。
- ここで measurements と metadata にパラメータを渡します。
- そしてここの判定が行われ、
: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 が 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 が渡されることを期待した実装になっております。
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 クエリや実行時間が見れるようになりました。
追記
2019年6月5日
:telemetry.execute/3 を実行するとなぜ :telemetry.attach/4 に渡した関数に metadata などが渡るのか、その仕組みが気になったので telemetry events のコードを追ったところ、ざっくり下記の手順で渡しておりましたので追記します。
-
:telemetry.attach/4を実行すると、attach()に渡した引数を ETS に保存します。 -
:telemetry.execute/3を実行すると、execute()に渡した引数を条件に ETS を検索し、関数を取得して metadata などを渡します。