Plugin telemetry events

guides/telemetry.md

@@ -11,9 +11,14 @@ handler function to any of the following event names:
 - `[:absinthe, :subscription, :publish, :stop]` when a subscription finishes
 - `[:absinthe, :resolve, :field, :start]` when field resolution starts
 - `[:absinthe, :resolve, :field, :stop]` when field resolution finishes
+- `[:absinthe, :plugin, :before_resolution, :start]` when a plugin before_resolution callback starts
+- `[:absinthe, :plugin, :before_resolution, :stop]` when a plugin before_resolution callback finishes
+- `[:absinthe, :plugin, :after_resolution, :start]` when a plugin after_resolution callback starts
+- `[:absinthe, :plugin, :after_resolution, :stop]` when a plugin after_resolution callback finishes
 
 Telemetry handlers are called with `measurements` and `metadata`. For details on
-what is passed, checkout `Absinthe.Phase.Telemetry` and `Absinthe.Middleware.Telemetry`
+what is passed, checkout `Absinthe.Phase.Telemetry`, `Absinthe.Middleware.Telemetry`,
+and `Absinthe.Phase.Document.Execution.Resolution`.
 
 For async, batch, and dataloader fields, Absinthe sends the final event when
 it gets the results. That might be later than when the results are ready. If

lib/absinthe/middleware/dataloader.ex

@@ -3,6 +3,7 @@ if Code.ensure_loaded?(Dataloader) do
     @behaviour Absinthe.Middleware
     @behaviour Absinthe.Plugin
 
+    @impl Absinthe.Plugin
     def before_resolution(%{context: context} = exec) do
       context =
         with %{loader: loader} <- context do
@@ -12,6 +13,7 @@ if Code.ensure_loaded?(Dataloader) do
       %{exec | context: context}
     end
 
+    @impl Absinthe.Middleware
     def call(%{state: :unresolved} = resolution, {loader, callback}) do
       if !Dataloader.pending_batches?(loader) do
         resolution.context.loader
@@ -36,10 +38,12 @@ if Code.ensure_loaded?(Dataloader) do
       Absinthe.Resolution.put_result(resolution, value)
     end
 
+    @impl Absinthe.Plugin
     def after_resolution(exec) do
       exec
     end
 
+    @impl Absinthe.Plugin
     def pipeline(pipeline, exec) do
       with %{loader: loader} <- exec.context,
            true <- Dataloader.pending_batches?(loader) do

lib/absinthe/phase/document/execution/resolution.ex

@@ -46,7 +46,7 @@ defmodule Absinthe.Phase.Document.Execution.Resolution do
     plugins = bp_root.schema.plugins()
     run_callbacks? = Keyword.get(options, :plugin_callbacks, true)
 
-    exec = plugins |> run_callbacks(:before_resolution, exec, run_callbacks?)
+    exec = run_callbacks(plugins, :before_resolution, exec, run_callbacks?)
 
     common =
       Map.take(exec, [:adapter, :context, :acc, :root_value, :schema, :fragments, :fields_cache])
@@ -75,11 +75,35 @@ defmodule Absinthe.Phase.Document.Execution.Resolution do
   end
 
   defp run_callbacks(plugins, callback, acc, true) do
-    Enum.reduce(plugins, acc, &apply(&1, callback, [&2]))
+    Enum.reduce(plugins, acc, fn plugin, acc ->
+      start_time = System.monotonic_time()
+
+      emit_start_event(start_time, acc, callback, plugin)
+      acc = apply(plugin, callback, [acc])
+      emit_stop_event(start_time, acc, callback, plugin)
+
+      acc
+    end)
   end
 
   defp run_callbacks(_, _, acc, _), do: acc
 
+  defp emit_start_event(start_time, acc, callback, plugin) do
+    :telemetry.execute(
+      [:absinthe, :plugin, callback, :start],
+      %{start_time: start_time},
+      %{acc: acc, plugin: plugin}
+    )
+  end
+
+  defp emit_stop_event(start_time, acc, callback, plugin) do
+    :telemetry.execute(
+      [:absinthe, :plugin, callback, :stop],
+      %{duration: System.monotonic_time() - start_time},
+      %{acc: acc, plugin: plugin}
+    )
+  end
+
   @doc """
   This function walks through any existing results. If no results are found at a
   given node, it will call the requisite function to expand and build those results

test/absinthe/middleware/dataloader_test.exs

@@ -139,7 +139,8 @@ defmodule Absinthe.Middleware.DataloaderTest do
     end
   end
 
-  test "can resolve a field using the normal dataloader helper" do
+  test "can resolve a field using the normal dataloader helper and should emit telemetry events",
+       %{test: test} do
     doc = """
     {
       users {
@@ -158,11 +159,57 @@ defmodule Absinthe.Middleware.DataloaderTest do
       ]
     }
 
+    # Get test PID and clear mailbox
+    self = self()
+    flush_process_mailbox()
+
+    :ok =
+      :telemetry.attach_many(
+        "#{test}",
+        [
+          [:absinthe, :plugin, :before_resolution, :start],
+          [:absinthe, :plugin, :before_resolution, :stop],
+          [:absinthe, :plugin, :after_resolution, :start],
+          [:absinthe, :plugin, :after_resolution, :stop]
+        ],
+        fn name, measurements, metadata, _ ->
+          send(self, {:telemetry_event, name, measurements, metadata})
+        end,
+        nil
+      )
+
     assert {:ok, %{data: data}} = Absinthe.run(doc, DefaultSchema)
     assert expected_data == data
 
     assert_receive(:loading)
     refute_receive(:loading)
+
+    # This test emits a total of 24 events, but there we are only validating the
+    # dataloader events in this test
+    results =
+      Enum.reduce(1..24, %{dataloader_starts: 0, dataloader_stops: 0}, fn _, acc ->
+        receive do
+          {:telemetry_event, [:absinthe, :plugin, callback, :start], %{start_time: _},
+           %{plugin: Absinthe.Middleware.Dataloader, acc: %{}}}
+          when callback in ~w(before_resolution after_resolution)a ->
+            Map.update(acc, :dataloader_starts, 0, &(&1 + 1))
+
+          {:telemetry_event, [:absinthe, :plugin, callback, :stop], %{duration: _},
+           %{plugin: Absinthe.Middleware.Dataloader, acc: %{}}}
+          when callback in ~w(before_resolution after_resolution)a ->
+            Map.update(acc, :dataloader_stops, 0, &(&1 + 1))
+
+          _skip ->
+            acc
+        after
+          0 ->
+            acc
+        end
+      end)
+
+    assert results.dataloader_starts == 4
+    assert results.dataloader_stops == 4
+    assert {:message_queue_len, 0} = Process.info(self, :message_queue_len)
   end
 
   test "can resolve a field when dataloader uses 'tuples' get_policy" do
@@ -299,4 +346,14 @@ defmodule Absinthe.Middleware.DataloaderTest do
     assert_receive(:loading)
     refute_receive(:loading)
   end
+
+  defp flush_process_mailbox() do
+    receive do
+      _ ->
+        flush_process_mailbox()
+    after
+      0 ->
+        :ok
+    end
+  end
 end