defmodule Surgex.Appsignal.EctoLogger do @moduledoc """ Integration for logging Ecto queries. This is an override of `Appsignal.Ecto` - backwards compatible with the original but with additional options available in the `handle_event/4` function. """ require Logger alias Appsignal.{Transaction, TransactionRegistry} @nano_seconds :erlang.convert_time_unit(1, :nano_seconds, :native) @default_event_name "query.ecto" @query_stages [:queue, :query, :decode] @doc """ Handles Ecto event generated via Telemetry. This is an override of `Appsignal.Ecto.handle_event/4` - backwards compatible with the original but with additional options controlled via Telemetry configuration list. ## Options - `:event_name` - allows to adjust logged event name and include app name/repo name in it. The value passed may be string literal or list of event name parts which may include string literals or following special atoms: - `:app` - name of app that owns specific Ecto repo - `:repo` - name of the specific Ecto repo - `:method` - Ecto method (currently just "query") - `:query_stages` - allows to alter the default duration calc behavior in which all three Ecto stages (`:queue`, `:query` and `:decode`) are included in the event. The optimal scenario would be to track these separately but Appsignal NIF currently doesn't give an option to log multiple events backwards in time so this option allows to exclude some of these stages and/or configure multiple events for specific stages. You can set this option to list of stages that should be included or to `:all` atom which will result in generating both the `ecto` event for whole event and separate `ecto_` subevents for each stage. ## Examples Multiple repos: # lib/my_app/application.ex Telemetry.attach_many( "my-app-ecto-appsignal", [ [:my_app, :some_repo, :query], [:my_app, :other_repo, :query] ], Surgex.Appsignal.EctoLogger, :handle_event, event_name: ["ecto", :repo, :method] ) Multiple apps eg. in Umbrella: # apps/some_app/lib/some_app/application.ex Telemetry.attach( "some-app-ecto-appsignal", [:some_app, :repo, :query], Surgex.Appsignal.EctoLogger, :handle_event, event_name: ["ecto", :app, :method] ) # apps/other_app/lib/other_app/application.ex Telemetry.attach( "other-app-ecto-appsignal", [:other_app, :repo, :query], Surgex.Appsignal.EctoLogger, :handle_event, event_name: ["ecto", :app, :method] ) All stages logged together with main event: # lib/my_app/application.ex Telemetry.attach( "my-app-ecto-appsignal", [:my_app, :repo, :query], Surgex.Appsignal.EctoLogger, :handle_event, event_name: ["ecto", :method], queue_stages: :all ) Customization of the above - additional log for queue time without query and decode times: # lib/my_app/application.ex Telemetry.attach( "my-app-ecto-appsignal", [:my_app, :repo, :query], Surgex.Appsignal.EctoLogger, :handle_event, event_name: ["ecto", :method] ) Telemetry.attach( "my-app-ecto-appsignal-queue", [:my_app, :repo, :query], Surgex.Appsignal.EctoLogger, :handle_event, event_name: ["ecto_queue", :method], query_stages: [:queue] ) """ def handle_event(telemetry_event, latency, metadata, nil) do handle_event(telemetry_event, latency, metadata, []) end def handle_event(telemetry_event, _latency, metadata, config) do event_name = Keyword.get(config, :event_name, @default_event_name) query_stages = Keyword.get(config, :query_stages, @query_stages) event_name_string = get_event_name(event_name, telemetry_event) log(metadata, event_name_string, query_stages) end defp get_event_name(event_name, telemetry_event) defp get_event_name(event_name, _) when is_binary(event_name) do event_name end defp get_event_name(event_name_parts, telemetry_event) when is_list(event_name_parts) do event_name_parts |> Enum.map(&resolve_event_name_part(&1, telemetry_event)) |> Enum.reverse() |> Enum.join(".") end defp resolve_event_name_part(part, telemetry_event) defp resolve_event_name_part(part, _) when is_binary(part), do: part defp resolve_event_name_part(:app, [app, _, _]), do: app defp resolve_event_name_part(:repo, [_, repo, _]), do: repo defp resolve_event_name_part(:method, [_, _, method]), do: method @doc """ Logs the event via Ecto logger instead of Telemetry (Ecto before version 3.0). This is an override of `Appsignal.Ecto.log/1` - backwards compatible with the original but with additional control over event name and query stages that are included in event duration both of which are used by `handle_event/4`. """ def log(entry) do log(entry, @default_event_name, @query_stages) end @doc false def log(entry, event_name, query_stages) do # See if we have a transaction registered for the current process case apply(TransactionRegistry, :lookup, [self()]) do nil -> # skip :ok %{__struct__: Transaction} = transaction -> # record the event log_stages(transaction, event_name, entry, query_stages) end entry end defp log_stages(transaction, event_name, entry, query_stages) defp log_stages(transaction, event_name, entry, :all) do log_stages(transaction, event_name, entry, @query_stages) Enum.each(@query_stages, fn stage -> total_time = get_total_time(entry, [stage]) duration = trunc(total_time / @nano_seconds) event_name = event_name <> "_" <> to_string(stage) apply(Transaction, :record_event, [transaction, event_name, "", entry.query, duration, 10]) end) end defp log_stages(transaction, event_name, entry, query_stages) when is_list(query_stages) do total_time = get_total_time(entry, query_stages) duration = trunc(total_time / @nano_seconds) apply(Transaction, :record_event, [transaction, event_name, "", entry.query, duration, 1]) end defp get_total_time(entry, stages) do Enum.reduce(@query_stages, 0, &reduce_total_time_for_query_stage(entry, &1, stages, &2)) end defp reduce_total_time_for_query_stage(entry, stage, included_stages, accum) do with true <- Enum.member?(included_stages, stage), {:ok, incr} when is_number(incr) <- Map.fetch(entry, :"#{stage}_time") do accum + incr else _ -> accum end end end