From 5354c91d516cb4f8556178bd13c6db5224baedf9 Mon Sep 17 00:00:00 2001 From: Andrew Rosa Date: Tue, 24 May 2022 22:16:32 -0300 Subject: [PATCH] Split telemetry into parse, validate and execution This get a bit closer to what we see in other implementations, like the javascript one, where we have explicit phases for parse and validation. This way, we can instrument Absinthe in a similar fashion, and break down how much work is done inside the framework (by parse/validation) and by the execution engine itself (and resolvers). Example of those phases in [Apollo Federation + JS impl][1]. [1]: https://www.apollographql.com/docs/federation/opentelemetry/#graphql-specific-spans --- .../phase/document/validation/init.ex | 27 +++++++++++++++++++ .../phase/document/validation/result.ex | 10 +++++++ lib/absinthe/phase/init.ex | 2 +- lib/absinthe/phase/parse.ex | 27 +++++++++++-------- lib/absinthe/phase/telemetry.ex | 3 +-- lib/absinthe/pipeline.ex | 7 ++--- test/absinthe/pipeline_test.exs | 2 +- 7 files changed, 60 insertions(+), 18 deletions(-) create mode 100644 lib/absinthe/phase/document/validation/init.ex diff --git a/lib/absinthe/phase/document/validation/init.ex b/lib/absinthe/phase/document/validation/init.ex new file mode 100644 index 0000000000..0da230df77 --- /dev/null +++ b/lib/absinthe/phase/document/validation/init.ex @@ -0,0 +1,27 @@ +defmodule Absinthe.Phase.Document.Validation.Init do + @moduledoc false + + # Init validation + + alias Absinthe.{Blueprint, Phase} + + use Absinthe.Phase + + @doc """ + Run the validation. + """ + @spec run(Blueprint.t(), Keyword.t()) :: Phase.result_t() + def run(blueprint, _options \\ []) do + id = :erlang.unique_integer() + system_time = System.system_time() + start_time_mono = System.monotonic_time() + + :telemetry.execute( + [:absinthe, :validate, :start], + %{system_time: system_time}, + %{telemetry_span_context: id, blueprint: blueprint} + ) + + {:ok, %{blueprint | telemetry: %{id: id, start_time_mono: start_time_mono}}} + end +end diff --git a/lib/absinthe/phase/document/validation/result.ex b/lib/absinthe/phase/document/validation/result.ex index 1d0dc34f81..cc4fb60f6a 100644 --- a/lib/absinthe/phase/document/validation/result.ex +++ b/lib/absinthe/phase/document/validation/result.ex @@ -22,6 +22,16 @@ defmodule Absinthe.Phase.Document.Validation.Result do errors = :lists.reverse(errors) result = put_in(input.execution.validation_errors, errors) + with %{id: id, start_time_mono: start_time_mono} <- result.telemetry do + end_time_mono = System.monotonic_time() + + :telemetry.execute( + [:absinthe, :validate, :stop], + %{duration: end_time_mono - start_time_mono}, + %{telemetry_span_context: id, blueprint: result} + ) + end + case {errors, jump} do {[], _} -> {:ok, result} diff --git a/lib/absinthe/phase/init.ex b/lib/absinthe/phase/init.ex index 4e628d289b..2781a1f262 100644 --- a/lib/absinthe/phase/init.ex +++ b/lib/absinthe/phase/init.ex @@ -9,7 +9,7 @@ defmodule Absinthe.Phase.Init do def run(input, _options \\ []) do {:record_phases, make_blueprint(input), fn bp, phases -> - %{bp | initial_phases: phases} + %{bp | initial_phases: phases, source: bp.input} end} end diff --git a/lib/absinthe/phase/parse.ex b/lib/absinthe/phase/parse.ex index 7b04faf130..57c2185ce7 100644 --- a/lib/absinthe/phase/parse.ex +++ b/lib/absinthe/phase/parse.ex @@ -12,17 +12,22 @@ defmodule Absinthe.Phase.Parse do def run(input, options \\ []) def run(%Absinthe.Blueprint{} = blueprint, options) do - options = Map.new(options) - - case parse(blueprint.input) do - {:ok, value} -> - {:ok, %{blueprint | input: value}} - - {:error, error} -> - blueprint - |> add_validation_error(error) - |> handle_error(options) - end + :telemetry.span([:absinthe, :parse], %{}, fn -> + options = Map.new(options) + + result = + case parse(blueprint.input) do + {:ok, value} -> + {:ok, %{blueprint | input: value}} + + {:error, error} -> + blueprint + |> add_validation_error(error) + |> handle_error(options) + end + + {result, %{}} + end) end def run(input, options) do diff --git a/lib/absinthe/phase/telemetry.ex b/lib/absinthe/phase/telemetry.ex index 797da6d8ce..7486e86b9f 100644 --- a/lib/absinthe/phase/telemetry.ex +++ b/lib/absinthe/phase/telemetry.ex @@ -29,8 +29,7 @@ defmodule Absinthe.Phase.Telemetry do {:ok, %{ blueprint - | source: blueprint.input, - telemetry: %{id: id, start_time_mono: start_time_mono} + | telemetry: %{id: id, start_time_mono: start_time_mono} }} end diff --git a/lib/absinthe/pipeline.ex b/lib/absinthe/pipeline.ex index 6c931ec460..181ac99e92 100644 --- a/lib/absinthe/pipeline.ex +++ b/lib/absinthe/pipeline.ex @@ -52,7 +52,6 @@ defmodule Absinthe.Pipeline do [ Phase.Init, - {Phase.Telemetry, Keyword.put(options, :event, [:execute, :operation, :start])}, # Parse Document {Phase.Parse, options}, # Convert to Blueprint @@ -63,6 +62,7 @@ defmodule Absinthe.Pipeline do # Mark Fragment/Variable Usage Phase.Document.Uses, # Validate Document Structure + Phase.Document.Validation.Init, {Phase.Document.Validation.NoFragmentCycles, options}, Phase.Document.Validation.LoneAnonymousOperation, {Phase.Document.Validation.SelectedCurrentOperation, options}, @@ -105,6 +105,7 @@ defmodule Absinthe.Pipeline do # Check Validation {Phase.Document.Validation.Result, options}, # Prepare for Execution + {Phase.Telemetry, Keyword.put(options, :event, [:execute, :operation, :start])}, Phase.Document.Arguments.Data, # Apply Directives Phase.Document.Directives, @@ -114,9 +115,9 @@ defmodule Absinthe.Pipeline do # Execution {Phase.Subscription.SubscribeSelf, options}, {Phase.Document.Execution.Resolution, options}, + {Phase.Telemetry, Keyword.put(options, :event, [:execute, :operation, :stop])}, # Format Result - Phase.Document.Result, - {Phase.Telemetry, Keyword.put(options, :event, [:execute, :operation, :stop])} + Phase.Document.Result ] end diff --git a/test/absinthe/pipeline_test.exs b/test/absinthe/pipeline_test.exs index c4ac6e78d4..e8a652588c 100644 --- a/test/absinthe/pipeline_test.exs +++ b/test/absinthe/pipeline_test.exs @@ -21,7 +21,7 @@ defmodule Absinthe.PipelineTest do Pipeline.for_document(Schema) |> Pipeline.upto(Phase.Blueprint) - assert {:ok, %Blueprint{}, [Phase.Blueprint, Phase.Parse, Phase.Telemetry, Phase.Init]} = + assert {:ok, %Blueprint{}, [Phase.Blueprint, Phase.Parse, Phase.Init]} = Pipeline.run(@query, pipeline) end end