Merge pull request #901 from binaryseed/telemetry-spec

Adapt to telemetry span convention
absinthe-graphql · Apr 2, 2020 · 2c17917 · 2c17917
2 parents 392426b + 033635e
commit 2c17917
Show file tree

Hide file tree

Showing 6 changed files with 39 additions and 61 deletions.
diff --git a/CHANGELOG.md b/CHANGELOG.md
@@ -5,6 +5,7 @@ For changes pre-v1.5 see the [v1.4](https://github.com/absinthe-graphql/absinthe
 ## v1.5.0 (Rc)
 
 - Feature (Experimental): `:persistent_term` based schema backend
+- Breaking Change: `telemetry` event keys [changed](https://github.com/absinthe-graphql/absinthe/pull/901) since the beta release.
 
 ## v1.5.0 (Beta)
 - Feature: SDL directives, other improvements

diff --git a/lib/absinthe/middleware/telemetry.ex b/lib/absinthe/middleware/telemetry.ex
@@ -10,16 +10,13 @@ defmodule Absinthe.Middleware.Telemetry do
   @impl Absinthe.Middleware
   def call(resolution, _) do
     id = :erlang.unique_integer()
-    start_time = System.system_time()
+    system_time = System.system_time()
     start_time_mono = System.monotonic_time()
 
     :telemetry.execute(
       @field_start,
-      %{start_time: start_time},
-      %{
-        id: id,
-        resolution: resolution
-      }
+      %{system_time: system_time},
+      %{id: id, resolution: resolution}
     )
 
     %{
@@ -30,7 +27,6 @@ defmodule Absinthe.Middleware.Telemetry do
               {{__MODULE__, :on_complete},
                %{
                  id: id,
-                 start_time: start_time,
                  start_time_mono: start_time_mono,
                  middleware: resolution.middleware
                }}
@@ -42,7 +38,6 @@ defmodule Absinthe.Middleware.Telemetry do
         %{state: :resolved} = resolution,
         %{
           id: id,
-          start_time: start_time,
           start_time_mono: start_time_mono,
           middleware: middleware
         }
@@ -54,7 +49,6 @@ defmodule Absinthe.Middleware.Telemetry do
       %{duration: end_time_mono - start_time_mono},
       %{
         id: id,
-        start_time: start_time,
         middleware: middleware,
         resolution: resolution
       }

diff --git a/lib/absinthe/phase/telemetry.ex b/lib/absinthe/phase/telemetry.ex
@@ -17,63 +17,49 @@ defmodule Absinthe.Phase.Telemetry do
 
   defp do_run(blueprint, [:execute, :operation, :start], options) do
     id = :erlang.unique_integer()
-    start_time = System.system_time()
+    system_time = System.system_time()
     start_time_mono = System.monotonic_time()
 
-    :telemetry.execute(@operation_start, %{start_time: start_time}, %{
-      id: id,
-      blueprint: blueprint,
-      options: options
-    })
+    :telemetry.execute(
+      @operation_start,
+      %{system_time: system_time},
+      %{id: id, blueprint: blueprint, options: options}
+    )
 
     {:ok,
      %{
        blueprint
        | source: blueprint.input,
-         telemetry: %{
-           id: id,
-           start_time: start_time,
-           start_time_mono: start_time_mono
-         }
+         telemetry: %{id: id, start_time_mono: start_time_mono}
      }}
   end
 
   defp do_run(blueprint, [:subscription, :publish, :start], options) do
     id = :erlang.unique_integer()
-    start_time = System.system_time()
+    system_time = System.system_time()
     start_time_mono = System.monotonic_time()
 
-    :telemetry.execute(@subscription_start, %{start_time: start_time}, %{
-      id: id,
-      blueprint: blueprint,
-      options: options
-    })
+    :telemetry.execute(
+      @subscription_start,
+      %{system_time: system_time},
+      %{id: id, blueprint: blueprint, options: options}
+    )
 
     {:ok,
      %{
        blueprint
-       | telemetry: %{
-           id: id,
-           start_time: start_time,
-           start_time_mono: start_time_mono
-         }
+       | telemetry: %{id: id, start_time_mono: start_time_mono}
      }}
   end
 
   defp do_run(blueprint, [:subscription, :publish, :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
+    with %{id: id, start_time_mono: start_time_mono} <- blueprint.telemetry do
       :telemetry.execute(
         @subscription_stop,
         %{duration: end_time_mono - start_time_mono},
-        %{
-          id: id,
-          start_time: start_time,
-          blueprint: blueprint,
-          options: options
-        }
+        %{id: id, blueprint: blueprint, options: options}
       )
     end
 
@@ -83,17 +69,11 @@ defmodule Absinthe.Phase.Telemetry do
   defp do_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
+    with %{id: id, start_time_mono: start_time_mono} <- blueprint.telemetry do
       :telemetry.execute(
         @operation_stop,
         %{duration: end_time_mono - start_time_mono},
-        %{
-          id: id,
-          start_time: start_time,
-          blueprint: blueprint,
-          options: options
-        }
+        %{id: id, blueprint: blueprint, options: options}
       )
     end
 

diff --git a/test/absinthe/execution/subscription_test.exs b/test/absinthe/execution/subscription_test.exs
@@ -587,8 +587,10 @@ defmodule Absinthe.Execution.SubscriptionTest do
                context: %{pubsub: PubSub}
              )
 
-    assert_receive {[:absinthe, :execute, :operation, :start], _, %{id: id} = _meta, _config}
-    assert_receive {[:absinthe, :execute, :operation, :stop], _, %{id: ^id} = _meta, _config}
+    assert_receive {[:absinthe, :execute, :operation, :start], measurements, %{id: id}, _config}
+    assert System.convert_time_unit(measurements[:system_time], :native, :millisecond)
+
+    assert_receive {[:absinthe, :execute, :operation, :stop], _, %{id: ^id}, _config}
 
     Absinthe.Subscription.publish(PubSub, "foo", thing: client_id)
     assert_receive({:broadcast, msg})
@@ -599,8 +601,9 @@ defmodule Absinthe.Execution.SubscriptionTest do
              topic: topic
            } == msg
 
-    assert_receive {[:absinthe, :subscription, :publish, :start], _, %{id: id} = _meta, _config}
-    assert_receive {[:absinthe, :subscription, :publish, :stop], _, %{id: ^id} = _meta, _config}
+    # Subscription events
+    assert_receive {[:absinthe, :subscription, :publish, :start], _, %{id: id}, _config}
+    assert_receive {[:absinthe, :subscription, :publish, :stop], _, %{id: ^id}, _config}
 
     :telemetry.detach(context.test)
   end

diff --git a/test/absinthe/integration/execution/telemetry_test.exs b/test/absinthe/integration/execution/telemetry_test.exs
@@ -59,21 +59,23 @@ defmodule Elixir.Absinthe.Integration.Execution.TelemetryTest do
     {:ok, %{data: data}} = Absinthe.run(query, TestSchema, variables: %{"echo" => "ASYNC"})
     assert %{"asyncThing" => "ASYNC", "objectThing" => %{"name" => "Foo"}} == data
 
-    assert_receive {[:absinthe, :execute, :operation, :start], _, %{id: id}, _config}
+    # Operation events
+    assert_receive {[:absinthe, :execute, :operation, :start], measurements, %{id: id}, _config}
+    assert System.convert_time_unit(measurements[:system_time], :native, :millisecond)
 
     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, :stop], measurements, %{id: ^id} = meta, _}
+    # Field events
+    assert_receive {[:absinthe, :resolve, :field, :start], measurements, %{id: id}, _}
+    assert System.convert_time_unit(measurements[:system_time], :native, :millisecond)
 
+    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])
 

diff --git a/test/absinthe/schema/notation/experimental/import_sdl_test.exs b/test/absinthe/schema/notation/experimental/import_sdl_test.exs
@@ -581,15 +581,13 @@ defmodule Absinthe.Schema.Notation.Experimental.ImportSdlTest do
                Absinthe.run(@query, Definition)
 
       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}, _config}
 
       assert_receive {[:absinthe, :resolve, :field, :start], measurements,
-                      %{resolution: %{definition: %{name: "posts"}}} = meta, config}
+                      %{resolution: %{definition: %{name: "posts"}}}, config}
 
       assert_receive {[:absinthe, :resolve, :field, :stop], measurements,
-                      %{resolution: %{definition: %{name: "posts"}}} = meta, config}
+                      %{resolution: %{definition: %{name: "posts"}}}, config}
     end
   end
 end