Merge pull request #782 from josevalim/jv-telemetry-stop

Use Telemetry start/stop convention

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: :...,

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,

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} ->

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,

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
 

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]}
           ]
         ]
 

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

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,23 +60,25 @@ 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)
     assert %Absinthe.Blueprint{} = meta[:blueprint]
     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

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