feat: Log db performance (query / query time) (#2954)

* feat: Log db performance (query / query time)

---------

Co-authored-by: Kayla Firestack <firestack@users.noreply.github.com>

lib/skate/application.ex

@@ -16,6 +16,8 @@ defmodule Skate.Application do
 
     start_data_processes? = Application.get_env(:skate, :start_data_processes)
 
+    Skate.Telemetry.setup_telemetry()
+
     # List all child processes to be supervised
     children =
       [{Skate.Repo, []}] ++

lib/skate/telemetry.ex

@@ -0,0 +1,33 @@
+defmodule Skate.Telemetry do
+  @moduledoc """
+  Telemetry listeners for Skate business logic.
+  """
+  require Logger
+
+  def setup_telemetry do
+    :telemetry.attach(
+      "skate",
+      [:skate, :repo, :query],
+      &Skate.Telemetry.repo_query_telemetry/4,
+      %{}
+    )
+  end
+
+  def repo_query_telemetry(
+        [:skate, :repo, :query],
+        %{decode_time: decode_time, query_time: query_time, total_time: total_time},
+        %{
+          source: source,
+          result: {:ok, %{connection_id: connection_id, num_rows: num_rows}},
+          query: query
+        },
+        _config
+      )
+      when source in ["detours"] do
+    Logger.info(fn ->
+      "Telemetry for db query, source=#{source} connection_id=#{connection_id} num_rows=#{num_rows} decode_time=#{decode_time} query_time=#{query_time} total_time=#{total_time} query='#{query}'"
+    end)
+  end
+
+  def repo_query_telemetry(_event, _measurements, _metadata, _config), do: nil
+end

mix.exs

@@ -97,6 +97,7 @@ defmodule Skate.MixProject do
       {:sobelow, "~> 0.13", only: [:dev, :test], runtime: false},
       {:ssl_verify_fun, "~> 1.1"},
       {:stream_data, "~> 1.1.1", only: :test},
+      {:telemetry, "~> 1.3"},
       {:timex, "~> 3.7.5"},
       {:typed_ecto_schema, "~> 0.4.1"},
       {:ueberauth, "~> 0.10.5"},

mix.lock

@@ -77,7 +77,7 @@
   "sobelow": {:hex, :sobelow, "0.13.0", "218afe9075904793f5c64b8837cc356e493d88fddde126a463839351870b8d1e", [:mix], [{:jason, "~> 1.0", [hex: :jason, repo: "hexpm", optional: false]}], "hexpm", "cd6e9026b85fc35d7529da14f95e85a078d9dd1907a9097b3ba6ac7ebbe34a0d"},
   "ssl_verify_fun": {:hex, :ssl_verify_fun, "1.1.7", "354c321cf377240c7b8716899e182ce4890c5938111a1296add3ec74cf1715df", [:make, :mix, :rebar3], [], "hexpm", "fe4c190e8f37401d30167c8c405eda19469f34577987c76dde613e838bbc67f8"},
   "stream_data": {:hex, :stream_data, "1.1.1", "fd515ca95619cca83ba08b20f5e814aaf1e5ebff114659dc9731f966c9226246", [:mix], [], "hexpm", "45d0cd46bd06738463fd53f22b70042dbb58c384bb99ef4e7576e7bb7d3b8c8c"},
-  "telemetry": {:hex, :telemetry, "1.2.1", "68fdfe8d8f05a8428483a97d7aab2f268aaff24b49e0f599faa091f1d4e7f61c", [:rebar3], [], "hexpm", "dad9ce9d8effc621708f99eac538ef1cbe05d6a874dd741de2e689c47feafed5"},
+  "telemetry": {:hex, :telemetry, "1.3.0", "fedebbae410d715cf8e7062c96a1ef32ec22e764197f70cda73d82778d61e7a2", [:rebar3], [], "hexpm", "7015fc8919dbe63764f4b4b87a95b7c0996bd539e0d499be6ec9d7f3875b79e6"},
   "telemetry_registry": {:hex, :telemetry_registry, "0.3.1", "14a3319a7d9027bdbff7ebcacf1a438f5f5c903057b93aee484cca26f05bdcba", [:mix, :rebar3], [{:telemetry, "~> 1.0", [hex: :telemetry, repo: "hexpm", optional: false]}], "hexpm", "6d0ca77b691cf854ed074b459a93b87f4c7f5512f8f7743c635ca83da81f939e"},
   "timex": {:hex, :timex, "3.7.11", "bb95cb4eb1d06e27346325de506bcc6c30f9c6dea40d1ebe390b262fad1862d1", [:mix], [{:combine, "~> 0.10", [hex: :combine, repo: "hexpm", optional: false]}, {:gettext, "~> 0.20", [hex: :gettext, repo: "hexpm", optional: false]}, {:tzdata, "~> 1.1", [hex: :tzdata, repo: "hexpm", optional: false]}], "hexpm", "8b9024f7efbabaf9bd7aa04f65cf8dcd7c9818ca5737677c7b76acbc6a94d1aa"},
   "typed_ecto_schema": {:hex, :typed_ecto_schema, "0.4.1", "a373ca6f693f4de84cde474a67467a9cb9051a8a7f3f615f1e23dc74b75237fa", [:mix], [{:ecto, "~> 3.5", [hex: :ecto, repo: "hexpm", optional: false]}], "hexpm", "85c6962f79d35bf543dd5659c6adc340fd2480cacc6f25d2cc2933ea6e8fcb3b"},

test/skate/telemetry_test.exs

@@ -0,0 +1,44 @@
+defmodule Skate.TelemetryTest do
+  @moduledoc false
+  use Skate.DataCase
+  import Skate.Factory
+  import ExUnit.CaptureLog, only: [capture_log: 2]
+  import Test.Support.Helpers, only: [set_log_level: 1]
+
+  alias Skate.Detours.Detours
+
+  setup tags do
+    if events = tags[:telemetry_listen] do
+      ref = :telemetry_test.attach_event_handlers(self(), events)
+
+      on_exit(fn -> :telemetry.detach(ref) end)
+
+      %{telemetry_ref: ref}
+    end
+  end
+
+  defp detour_fixture do
+    insert(:detour)
+  end
+
+  @tag telemetry_listen: [[:skate, :repo, :query]]
+  test "logs exception info" do
+    set_log_level(:info)
+    detour = detour_fixture()
+
+    log =
+      capture_log([level: :info], fn ->
+        assert Skate.Repo.preload(Detours.list_detours(), :author) == [detour]
+      end)
+
+    assert_receive {[:skate, :repo, :query], _ref,
+                    %{decode_time: _, query_time: _, total_time: _},
+                    %{
+                      query: _,
+                      result: {:ok, %{connection_id: _, num_rows: _}},
+                      source: "detours"
+                    }}
+
+    assert log =~ "Telemetry for db query, source=detours"
+  end
+end