From 14f6102484a0e5e3f115d7bb0f5e3b6026204ec5 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Jos=C3=A9=20Valim?= Date: Sat, 14 Sep 2019 09:06:19 +0200 Subject: [PATCH 1/2] Use Telemetry start/stop convention This is the same convention used in Phoenix. --- guides/telemetry.md | 12 ++++++------ lib/absinthe/middleware/telemetry.ex | 4 ++-- lib/absinthe/phase/subscription/subscribe_self.ex | 2 +- lib/absinthe/phase/telemetry.ex | 12 ++++++------ lib/absinthe/pipeline.ex | 2 +- lib/absinthe/subscription/local.ex | 2 +- test/absinthe/execution/subscription_test.exs | 8 ++++---- .../integration/execution/telemetry_test.exs | 12 ++++++------ 8 files changed, 27 insertions(+), 27 deletions(-) diff --git a/guides/telemetry.md b/guides/telemetry.md index a76dfe6576..44066ce378 100644 --- a/guides/telemetry.md +++ b/guides/telemetry.md @@ -5,11 +5,11 @@ Call `:telemetry.attach/4` or `:telemetry.attach_many/4` to attach your handler function to any of the following event names: - `[:absinthe, :execute, :operation, :start]` when the operation starts -- `[:absinthe, :execute, :operation]` when the operation finishes +- `[:absinthe, :execute, :operation, :stop]` when the operation finishes - `[:absinthe, :subscription, :publish, :start]` when a subscription starts -- `[:absinthe, :subscription, :publish]` when a subscription finishes +- `[:absinthe, :subscription, :publish, :stop]` when a subscription finishes - `[:absinthe, :resolve, :field, :start]` when field resolution starts -- `[:absinthe, :resolve, :field]` when field resolution finishes +- `[:absinthe, :resolve, :field, :stop]` when field resolution finishes By default, only fields with a resolver get measured. You can override this by setting `absinthe_telemetry` in its metadata to `true` or `false` with @@ -27,7 +27,7 @@ Absinthe passes the following measurements in the second argument to your handler function: - `start_time` with event names ending with `:start` -- `duration` with event names not ending with `:start` +- `duration` with event names ending with `:stop` ## Metadata @@ -49,7 +49,7 @@ your `iex -S mix phx.server` prompt. Paste in: ```elixir :telemetry.attach_many( :demo, - [[:absinthe, :execute, :operation], [:absinthe, :resolve, :field]], + [[:absinthe, :execute, :operation, :stop], [:absinthe, :resolve, :field, :stop, :stop]], fn event_name, measurements, metadata, _config -> %{ event_name: event_name, @@ -83,7 +83,7 @@ Shortly after the log line for `POST /api/`, you'll see something like: ```elixir telemetry: %{ - event_name: [:absinthe, :execute, :operation], + event_name: [:absinthe, :execute, :operation, :stop], measurements: %{duration: 158516000}, metadata: %{ blueprint: :..., diff --git a/lib/absinthe/middleware/telemetry.ex b/lib/absinthe/middleware/telemetry.ex index dc2eafe694..8a8f644c9d 100644 --- a/lib/absinthe/middleware/telemetry.ex +++ b/lib/absinthe/middleware/telemetry.ex @@ -3,7 +3,7 @@ defmodule Absinthe.Middleware.Telemetry do Gather and report telemetry about an individual field resolution """ @field_start [:absinthe, :resolve, :field, :start] - @field [:absinthe, :resolve, :field] + @field_stop [:absinthe, :resolve, :field, :stop] @behaviour Absinthe.Middleware @@ -43,7 +43,7 @@ defmodule Absinthe.Middleware.Telemetry do end_time_mono = System.monotonic_time() :telemetry.execute( - @field, + @field_stop, %{duration: end_time_mono - start_time_mono}, %{ id: id, diff --git a/lib/absinthe/phase/subscription/subscribe_self.ex b/lib/absinthe/phase/subscription/subscribe_self.ex index a634b800aa..d15ff80245 100644 --- a/lib/absinthe/phase/subscription/subscribe_self.ex +++ b/lib/absinthe/phase/subscription/subscribe_self.ex @@ -31,7 +31,7 @@ defmodule Absinthe.Phase.Subscription.SubscribeSelf do {:replace, blueprint, [ {Phase.Subscription.Result, topic: subscription_id}, - {Phase.Telemetry, [:execute, :operation, options]} + {Phase.Telemetry, [:execute, :operation, :stop, options]} ]} else {:error, error} -> diff --git a/lib/absinthe/phase/telemetry.ex b/lib/absinthe/phase/telemetry.ex index a8345dba76..70df094a8d 100644 --- a/lib/absinthe/phase/telemetry.ex +++ b/lib/absinthe/phase/telemetry.ex @@ -3,10 +3,10 @@ defmodule Absinthe.Phase.Telemetry do Gather and report telemetry about an operation. """ @operation_start [:absinthe, :execute, :operation, :start] - @operation [:absinthe, :execute, :operation] + @operation_stop [:absinthe, :execute, :operation, :stop] @subscription_start [:absinthe, :subscription, :publish, :start] - @subscription [:absinthe, :subscription, :publish] + @subscription_stop [:absinthe, :subscription, :publish, :stop] use Absinthe.Phase @@ -47,13 +47,13 @@ defmodule Absinthe.Phase.Telemetry do }} end - def run(blueprint, [:subscription, :publish]) do + def run(blueprint, [:subscription, :publish, :stop]) do end_time_mono = System.monotonic_time() with %{id: id, start_time: start_time, start_time_mono: start_time_mono} <- blueprint.telemetry do :telemetry.execute( - @subscription, + @subscription_stop, %{duration: end_time_mono - start_time_mono}, %{ id: id, @@ -66,13 +66,13 @@ defmodule Absinthe.Phase.Telemetry do {:ok, blueprint} end - def run(blueprint, [:execute, :operation, options]) do + def run(blueprint, [:execute, :operation, :stop, options]) do end_time_mono = System.monotonic_time() with %{id: id, start_time: start_time, start_time_mono: start_time_mono} <- blueprint.telemetry do :telemetry.execute( - @operation, + @operation_stop, %{duration: end_time_mono - start_time_mono}, %{ id: id, diff --git a/lib/absinthe/pipeline.ex b/lib/absinthe/pipeline.ex index d3a72937c3..e9821c85fa 100644 --- a/lib/absinthe/pipeline.ex +++ b/lib/absinthe/pipeline.ex @@ -107,7 +107,7 @@ defmodule Absinthe.Pipeline do {Phase.Document.Execution.Resolution, options}, # Format Result Phase.Document.Result, - {Phase.Telemetry, [:execute, :operation, options]} + {Phase.Telemetry, [:execute, :operation, :stop, options]} ] end diff --git a/lib/absinthe/subscription/local.ex b/lib/absinthe/subscription/local.ex index 545cfe3559..23faf89d97 100644 --- a/lib/absinthe/subscription/local.ex +++ b/lib/absinthe/subscription/local.ex @@ -54,7 +54,7 @@ defmodule Absinthe.Subscription.Local do pipeline, [ Absinthe.Phase.Document.Result, - {Absinthe.Phase.Telemetry, [:subscription, :publish]} + {Absinthe.Phase.Telemetry, [:subscription, :publish, :stop]} ] ] diff --git a/test/absinthe/execution/subscription_test.exs b/test/absinthe/execution/subscription_test.exs index ecec29645f..a924697e25 100644 --- a/test/absinthe/execution/subscription_test.exs +++ b/test/absinthe/execution/subscription_test.exs @@ -569,9 +569,9 @@ defmodule Absinthe.Execution.SubscriptionTest do context.test, [ [:absinthe, :execute, :operation, :start], - [:absinthe, :execute, :operation], + [:absinthe, :execute, :operation, :stop], [:absinthe, :subscription, :publish, :start], - [:absinthe, :subscription, :publish] + [:absinthe, :subscription, :publish, :stop] ], fn event, measurements, metadata, config -> send(self(), {event, measurements, metadata, config}) @@ -588,7 +588,7 @@ defmodule Absinthe.Execution.SubscriptionTest do ) assert_receive {[:absinthe, :execute, :operation, :start], _, %{id: id} = _meta, _config} - assert_receive {[:absinthe, :execute, :operation], _, %{id: ^id} = _meta, _config} + assert_receive {[:absinthe, :execute, :operation, :stop], _, %{id: ^id} = _meta, _config} Absinthe.Subscription.publish(PubSub, "foo", thing: client_id) assert_receive({:broadcast, msg}) @@ -600,7 +600,7 @@ defmodule Absinthe.Execution.SubscriptionTest do } == msg assert_receive {[:absinthe, :subscription, :publish, :start], _, %{id: id} = _meta, _config} - assert_receive {[:absinthe, :subscription, :publish], _, %{id: ^id} = _meta, _config} + assert_receive {[:absinthe, :subscription, :publish, :stop], _, %{id: ^id} = _meta, _config} :telemetry.detach(context.test) end diff --git a/test/absinthe/integration/execution/telemetry_test.exs b/test/absinthe/integration/execution/telemetry_test.exs index 9a22357508..0dc47d271a 100644 --- a/test/absinthe/integration/execution/telemetry_test.exs +++ b/test/absinthe/integration/execution/telemetry_test.exs @@ -6,9 +6,9 @@ defmodule Elixir.Absinthe.Integration.Execution.TelemetryTest do context.test, [ [:absinthe, :resolve, :field, :start], - [:absinthe, :resolve, :field], + [:absinthe, :resolve, :field, :stop], [:absinthe, :execute, :operation, :start], - [:absinthe, :execute, :operation] + [:absinthe, :execute, :operation, :stop] ], &__MODULE__.handle_event/4, %{} @@ -60,7 +60,7 @@ defmodule Elixir.Absinthe.Integration.Execution.TelemetryTest do assert %{"asyncThing" => "ASYNC", "objectThing" => %{"name" => "Foo"}} == data assert_receive {[:absinthe, :execute, :operation, :start], _, %{id: id}, _config} - assert_receive {[:absinthe, :execute, :operation], measurements, %{id: ^id} = meta, _config} + assert_receive {[:absinthe, :execute, :operation, :stop], measurements, %{id: ^id} = meta, _config} assert is_number(measurements[:duration]) assert System.convert_time_unit(meta[:start_time], :native, :millisecond) @@ -68,15 +68,15 @@ defmodule Elixir.Absinthe.Integration.Execution.TelemetryTest do assert meta[:options][:schema] == TestSchema assert_receive {[:absinthe, :resolve, :field, :start], _, %{id: id}, _} - assert_receive {[:absinthe, :resolve, :field], measurements, %{id: ^id} = meta, _} + assert_receive {[:absinthe, :resolve, :field, :stop], measurements, %{id: ^id} = meta, _} assert is_number(measurements[:duration]) assert System.convert_time_unit(meta[:start_time], :native, :millisecond) assert %Absinthe.Resolution{} = meta[:resolution] assert is_list(meta[:middleware]) - assert_receive {[:absinthe, :resolve, :field], _, _, _} + assert_receive {[:absinthe, :resolve, :field, :stop], _, _, _} # Don't execute for resolvers that don't call a resolver function (ie: default `Map.get`) - refute_receive {[:absinthe, :resolve, :field], _, _, _} + refute_receive {[:absinthe, :resolve, :field, :stop], _, _, _} end end From 68826a89cb04ea01edfbda49b444bd3f414ac3c8 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Jos=C3=A9=20Valim?= Date: Sat, 14 Sep 2019 11:10:29 +0200 Subject: [PATCH 2/2] Run the formatter --- test/absinthe/integration/execution/telemetry_test.exs | 4 +++- test/support/fixtures/arguments_schema.ex | 4 ++-- 2 files changed, 5 insertions(+), 3 deletions(-) diff --git a/test/absinthe/integration/execution/telemetry_test.exs b/test/absinthe/integration/execution/telemetry_test.exs index 0dc47d271a..47ce3883fe 100644 --- a/test/absinthe/integration/execution/telemetry_test.exs +++ b/test/absinthe/integration/execution/telemetry_test.exs @@ -60,7 +60,9 @@ defmodule Elixir.Absinthe.Integration.Execution.TelemetryTest do assert %{"asyncThing" => "ASYNC", "objectThing" => %{"name" => "Foo"}} == data assert_receive {[:absinthe, :execute, :operation, :start], _, %{id: id}, _config} - assert_receive {[:absinthe, :execute, :operation, :stop], measurements, %{id: ^id} = meta, _config} + + assert_receive {[:absinthe, :execute, :operation, :stop], measurements, %{id: ^id} = meta, + _config} assert is_number(measurements[:duration]) assert System.convert_time_unit(meta[:start_time], :native, :millisecond) diff --git a/test/support/fixtures/arguments_schema.ex b/test/support/fixtures/arguments_schema.ex index d3e223ea52..af6e2c36b5 100644 --- a/test/support/fixtures/arguments_schema.ex +++ b/test/support/fixtures/arguments_schema.ex @@ -2,8 +2,8 @@ defmodule Absinthe.Fixtures.ArgumentsSchema do use Absinthe.Schema @res %{ - true => "YES", - false => "NO" + true: "YES", + false: "NO" } scalar :input_name do