Plugin telemetry events

guides/telemetry.md

@@ -11,9 +11,12 @@ 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, :middleware, :batch, :start]` when the batch processing starts
+- `[:absinthe, :middleware, :batch, :stop]` when the batch processing 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.Middleware.Batch`.
 
 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/batch.ex

@@ -142,17 +142,63 @@ defmodule Absinthe.Middleware.Batch do
     input
     |> Enum.group_by(&elem(&1, 0), &elem(&1, 1))
     |> Enum.map(fn {{batch_fun, batch_opts}, batch_data} ->
-      {batch_opts,
-       Task.async(fn ->
-         {batch_fun, call_batch_fun(batch_fun, batch_data)}
-       end)}
+      telemetry_data = generate_telemetry_data(batch_fun, batch_opts, batch_data)
+
+      emit_start_event(telemetry_data)
+
+      {
+        batch_opts,
+        Task.async(fn ->
+          {batch_fun, call_batch_fun(batch_fun, batch_data)}
+        end),
+        telemetry_data
+      }
     end)
-    |> Map.new(fn {batch_opts, task} ->
+    |> Map.new(fn {batch_opts, task, telemetry_data} ->
       timeout = Keyword.get(batch_opts, :timeout, 5_000)
-      Task.await(task, timeout)
+      result = Task.await(task, timeout)
+
+      emit_stop_event(telemetry_data, result)
+
+      result
     end)
   end
 
+  defp generate_telemetry_data(batch_fun, batch_opts, batch_data) do
+    %{
+      id: :erlang.unique_integer(),
+      system_time: System.system_time(),
+      start_time_mono: System.monotonic_time(),
+      batch_fun: batch_fun,
+      batch_opts: batch_opts,
+      batch_data: batch_data
+    }
+  end
+
+  defp emit_start_event(telemetry_data) do
+    :telemetry.execute(
+      [:absinthe, :middleware, :batch, :start],
+      Map.take(telemetry_data, [:system_time]),
+      Map.take(telemetry_data, [:id, :batch_fun, :batch_opts, :batch_data])
+    )
+  end
+
+  defp emit_stop_event(telemetry_data, result) do
+    metadata = %{
+      id: telemetry_data.id,
+      batch_fun: telemetry_data.batch_fun,
+      batch_opts: telemetry_data.batch_opts,
+      batch_data: telemetry_data.batch_data,
+      result: result
+    }
+
+    :telemetry.execute(
+      [:absinthe, :middleware, :batch, :stop],
+      %{duration: System.monotonic_time() - telemetry_data.start_time_mono},
+      metadata
+    )
+  end
+
   defp call_batch_fun({module, fun}, batch_data) do
     call_batch_fun({module, fun, []}, batch_data)
   end

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

test/absinthe/middleware/batch_test.exs

@@ -82,7 +82,8 @@ defmodule Absinthe.Middleware.BatchTest do
     assert expected_data == data
   end
 
-  test "can resolve batched fields cross-query that have different data requirements" do
+  test "can resolve batched fields cross-query that have different data requirements and should emit telemetry events",
+       %{test: test} do
     doc = """
     {
       users {
@@ -105,7 +106,26 @@ defmodule Absinthe.Middleware.BatchTest do
       "organization" => %{"id" => 1}
     }
 
+    :ok =
+      :telemetry.attach_many(
+        "#{test}",
+        [
+          [:absinthe, :middleware, :batch, :start],
+          [:absinthe, :middleware, :batch, :stop]
+        ],
+        fn name, measurements, metadata, _ ->
+          send(self(), {:telemetry_event, name, measurements, metadata})
+        end,
+        nil
+      )
+
     assert {:ok, %{data: data}} = Absinthe.run(doc, Schema)
     assert expected_data == data
+
+    assert_receive {:telemetry_event, [:absinthe, :middleware, :batch, :start], %{system_time: _},
+                    %{id: _, batch_fun: _, batch_opts: _, batch_data: _}}
+
+    assert_receive {:telemetry_event, [:absinthe, :middleware, :batch, :stop], %{duration: _},
+                    %{id: _, batch_fun: _, batch_opts: _, batch_data: _, result: _}}
   end
 end