From f87381972c100d49204d2ec59e0d5d9c36da2470 Mon Sep 17 00:00:00 2001 From: Andrew Rosa Date: Thu, 5 May 2022 10:20:54 -0300 Subject: [PATCH] Tweak telemetry events on batch middleware With a similar rationale from [this PR][1], tweak the telemetry events from batch middleware. The existing event contract stays the same, but move to run from inside the Task used for batch execution. There is a small semantic difference of when the :stop event fires - this patch sends the event at the end of the task, while the current form may have a delay/sync caused by Task await. A complementary event is added as well to announce when the Resolver continuation - the post batch - happens. Given that piece is part of the resolver, the resolution struct is included as part of the metadata. [1]: https://github.com/absinthe-graphql/absinthe/pull/1169 --- guides/telemetry.md | 2 + lib/absinthe/middleware/batch.ex | 74 ++++++++++--------------- test/absinthe/middleware/batch_test.exs | 42 ++++++++++++-- 3 files changed, 70 insertions(+), 48 deletions(-) diff --git a/guides/telemetry.md b/guides/telemetry.md index 8eacb8bcb5..7859fe3cc1 100644 --- a/guides/telemetry.md +++ b/guides/telemetry.md @@ -13,6 +13,8 @@ handler function to any of the following event names: - `[: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 +- `[:absinthe, :middleware, :batch, :post, :start]` when the post batch resolution starts +- `[:absinthe, :middleware, :batch, :post, :stop]` when the post batch resolution finishes Telemetry handlers are called with `measurements` and `metadata`. For details on what is passed, checkout `Absinthe.Phase.Telemetry`, `Absinthe.Middleware.Telemetry`, diff --git a/lib/absinthe/middleware/batch.ex b/lib/absinthe/middleware/batch.ex index 8e1f2add83..3aa78fc8e5 100644 --- a/lib/absinthe/middleware/batch.ex +++ b/lib/absinthe/middleware/batch.ex @@ -120,8 +120,23 @@ defmodule Absinthe.Middleware.Batch do |> Map.fetch!(:output) |> Map.fetch!(batch_key) + result = + :telemetry.span( + [:absinthe, :middleware, :batch, :post], + %{ + resolution: res, + post_batch_fun: post_batch_fun, + batch_key: batch_key, + batch_results: batch_data_for_fun + }, + fn -> + result = post_batch_fun.(batch_data_for_fun) + {result, %{result: result}} + end + ) + res - |> Absinthe.Resolution.put_result(post_batch_fun.(batch_data_for_fun)) + |> Absinthe.Resolution.put_result(result) end def after_resolution(exec) do @@ -133,59 +148,30 @@ defmodule Absinthe.Middleware.Batch do input |> Enum.group_by(&elem(&1, 0), &elem(&1, 1)) |> Enum.map(fn {{batch_fun, batch_opts}, batch_data} -> - system_time = System.system_time() - start_time_mono = System.monotonic_time() - task = Task.async(fn -> - {batch_fun, call_batch_fun(batch_fun, batch_data)} + start_metadata = %{ + id: :erlang.unique_integer(), + batch_fun: batch_fun, + batch_opts: batch_opts, + batch_data: batch_data + } + + :telemetry.span([:absinthe, :middleware, :batch], start_metadata, fn -> + result = call_batch_fun(batch_fun, batch_data) + {{batch_fun, result}, Map.merge(start_metadata, %{result: result})} + end) end) - metadata = emit_start_event(system_time, batch_fun, batch_opts, batch_data) - - {batch_opts, task, start_time_mono, metadata} + {batch_opts, task} end) - |> Map.new(fn {batch_opts, task, start_time_mono, metadata} -> + |> Map.new(fn {batch_opts, task} -> timeout = Keyword.get(batch_opts, :timeout, 5_000) - result = Task.await(task, timeout) - duration = System.monotonic_time() - start_time_mono - emit_stop_event(duration, metadata, result) - - result + Task.await(task, timeout) end) end - @batch_start [:absinthe, :middleware, :batch, :start] - @batch_stop [:absinthe, :middleware, :batch, :stop] - defp emit_start_event(system_time, batch_fun, batch_opts, batch_data) do - id = :erlang.unique_integer() - - metadata = %{ - id: id, - telemetry_span_context: id, - batch_fun: batch_fun, - batch_opts: batch_opts, - batch_data: batch_data - } - - :telemetry.execute( - @batch_start, - %{system_time: system_time}, - metadata - ) - - metadata - end - - defp emit_stop_event(duration, metadata, result) do - :telemetry.execute( - @batch_stop, - %{duration: duration}, - Map.put(metadata, :result, result) - ) - end - defp call_batch_fun({module, fun}, batch_data) do call_batch_fun({module, fun, []}, batch_data) end diff --git a/test/absinthe/middleware/batch_test.exs b/test/absinthe/middleware/batch_test.exs index d099055649..9b38bfa302 100644 --- a/test/absinthe/middleware/batch_test.exs +++ b/test/absinthe/middleware/batch_test.exs @@ -106,15 +106,20 @@ defmodule Absinthe.Middleware.BatchTest do "organization" => %{"id" => 1} } + # events may run on separate processes + pid = self() + :ok = :telemetry.attach_many( "#{test}", [ [:absinthe, :middleware, :batch, :start], - [:absinthe, :middleware, :batch, :stop] + [:absinthe, :middleware, :batch, :stop], + [:absinthe, :middleware, :batch, :post, :start], + [:absinthe, :middleware, :batch, :post, :stop] ], fn name, measurements, metadata, _ -> - send(self(), {:telemetry_event, name, measurements, metadata}) + send(pid, {:telemetry_event, name, measurements, metadata}) end, nil ) @@ -123,9 +128,38 @@ defmodule Absinthe.Middleware.BatchTest do assert expected_data == data assert_receive {:telemetry_event, [:absinthe, :middleware, :batch, :start], %{system_time: _}, - %{id: _, batch_fun: _, batch_opts: _, batch_data: _}} + %{ + id: _, + telemetry_span_context: _, + batch_fun: _, + batch_opts: _, + batch_data: _ + }} assert_receive {:telemetry_event, [:absinthe, :middleware, :batch, :stop], %{duration: _}, - %{id: _, batch_fun: _, batch_opts: _, batch_data: _, result: _}} + %{ + id: _, + telemetry_span_context: _, + batch_fun: _, + batch_opts: _, + batch_data: _, + result: _ + }} + + assert_receive {:telemetry_event, [:absinthe, :middleware, :batch, :post, :start], + %{system_time: _}, + %{ + telemetry_span_context: _, + post_batch_fun: _, + batch_key: _, + batch_results: _ + }} + + assert_receive {:telemetry_event, [:absinthe, :middleware, :batch, :post, :stop], + %{duration: _}, + %{ + telemetry_span_context: _, + result: _ + }} end end