Ensure we always get Transaction timing

examples/apps/oban_example/lib/oban_example/worker.ex

@@ -7,7 +7,7 @@ defmodule ObanExample.Worker do
   end
 
   def perform(%Oban.Job{args: _args}) do
-    Process.sleep(:rand.uniform(50))
+    Process.sleep(15 + :rand.uniform(50))
     :ok
   end
 end

examples/apps/oban_example/test/oban_example_test.exs

@@ -23,14 +23,21 @@ defmodule ObanExampleTest do
            )
 
     assert [
-             %{:name => "OtherTransaction/Oban/default/ObanExample.Worker/perform"},
+             %{
+               :name => "OtherTransaction/Oban/default/ObanExample.Worker/perform",
+               :timestamp => timestamp,
+               :duration => duration
+             },
              %{
                :"oban.worker" => "ObanExample.Worker",
                :"oban.queue" => "default",
                :"oban.job.result" => "success",
                :"oban.job.tags" => "foo,bar"
              }
            ] = event
+
+    assert timestamp |> is_number
+    assert duration >= 0.015
   end
 
   test "instruments a failed job" do

examples/apps/redix_example/test/redix_example_test.exs

@@ -60,6 +60,8 @@ defmodule RedixExampleTest do
     assert get_event[:"db.statement"] == "GET mykey"
     assert get_event[:"redix.connection"] =~ "PID"
     assert get_event[:"redix.connection_name"] == ":redix"
+    assert get_event[:timestamp] |> is_number
+    assert get_event[:duration] > 0.0
 
     [pipeline_event, _, _] =
       Enum.find(span_events, fn [ev, _, _] ->

lib/new_relic/telemetry/finch.ex

@@ -56,7 +56,7 @@ defmodule NewRelic.Telemetry.Finch do
 
   def handle_event(
         @finch_request_start,
-        %{monotonic_time: monotonic_time, system_time: system_time},
+        %{system_time: start_time},
         %{request: request},
         config
       ) do
@@ -70,8 +70,7 @@ defmodule NewRelic.Telemetry.Finch do
       Process.put(
         config.handler_id,
         %{
-          start_time_mono: monotonic_time,
-          system_time: system_time,
+          start_time: start_time,
           span: span,
           previous_span: previous_span,
           previous_span_attrs: previous_span_attrs
@@ -82,85 +81,83 @@ defmodule NewRelic.Telemetry.Finch do
 
   def handle_event(
         @finch_request_stop,
-        %{monotonic_time: end_time_mono, duration: duration},
+        %{duration: duration},
         %{name: finch_pool, request: request, result: result},
         config
       ) do
     if instrument?() do
-      %{
-        start_time_mono: start_time_mono,
-        system_time: start_time,
-        span: span,
-        previous_span: previous_span,
-        previous_span_attrs: previous_span_attrs
-      } = Process.delete(config.handler_id)
-
-      metric_name = "External/#{request.host}/Finch/#{request.method}"
-      secondary_name = "#{request.host} - Finch/#{request.method}"
-
-      duration_ms = System.convert_time_unit(duration, :native, :millisecond)
-      duration_s = duration_ms / 1000
-
-      id = span
-      parent_id = previous_span || :root
-
-      url =
-        URI.to_string(%URI{scheme: "#{request.scheme}", host: request.host, path: request.path})
-
-      result_attrs =
-        case result do
-          {:ok, %{__struct__: Finch.Response} = response} -> %{"response.status": response.status}
-          {:ok, _acc} -> %{}
-          {:error, exception} -> %{error: true, "error.message": Exception.message(exception)}
-        end
-
-      NewRelic.Transaction.Reporter.add_trace_segment(%{
-        primary_name: metric_name,
-        secondary_name: secondary_name,
-        attributes: %{},
-        pid: self(),
-        id: span,
-        parent_id: parent_id,
-        start_time: start_time,
-        start_time_mono: start_time_mono,
-        end_time_mono: end_time_mono
-      })
-
-      NewRelic.report_span(
-        timestamp_ms: System.convert_time_unit(start_time, :native, :millisecond),
-        duration_s: duration_s,
-        name: metric_name,
-        edge: [span: id, parent: parent_id],
-        category: "http",
-        attributes:
-          %{
-            "request.url": url,
-            "request.method": request.method,
-            "request.client": "Finch",
-            "finch.pool": finch_pool
-          }
-          |> Map.merge(result_attrs)
-      )
+      with %{
+             start_time: start_time,
+             span: span,
+             previous_span: previous_span,
+             previous_span_attrs: previous_span_attrs
+           } <- Process.delete(config.handler_id) do
+        metric_name = "External/#{request.host}/Finch/#{request.method}"
+        secondary_name = "#{request.host} - Finch/#{request.method}"
+
+        duration_ms = System.convert_time_unit(duration, :native, :millisecond)
+        duration_s = duration_ms / 1000
+
+        id = span
+        parent_id = previous_span || :root
+
+        url =
+          URI.to_string(%URI{scheme: "#{request.scheme}", host: request.host, path: request.path})
+
+        result_attrs =
+          case result do
+            {:ok, %{__struct__: Finch.Response} = response} -> %{"response.status": response.status}
+            {:ok, _acc} -> %{}
+            {:error, exception} -> %{error: true, "error.message": Exception.message(exception)}
+          end
+
+        NewRelic.Transaction.Reporter.add_trace_segment(%{
+          primary_name: metric_name,
+          secondary_name: secondary_name,
+          attributes: %{},
+          pid: self(),
+          id: span,
+          parent_id: parent_id,
+          start_time: start_time,
+          duration: duration
+        })
+
+        NewRelic.report_span(
+          timestamp_ms: System.convert_time_unit(start_time, :native, :millisecond),
+          duration_s: duration_s,
+          name: metric_name,
+          edge: [span: id, parent: parent_id],
+          category: "http",
+          attributes:
+            %{
+              "request.url": url,
+              "request.method": request.method,
+              "request.client": "Finch",
+              "finch.pool": finch_pool
+            }
+            |> Map.merge(result_attrs)
+        )
 
-      NewRelic.incr_attributes(
-        "external.#{request.host}.call_count": 1,
-        "external.#{request.host}.duration_ms": duration_ms
-      )
+        NewRelic.incr_attributes(
+          "external.#{request.host}.call_count": 1,
+          "external.#{request.host}.duration_ms": duration_ms
+        )
 
-      NewRelic.report_metric(
-        {:external, url, "Finch", request.method},
-        duration_s: duration_s
-      )
+        NewRelic.report_metric(
+          {:external, url, "Finch", request.method},
+          duration_s: duration_s
+        )
 
-      NewRelic.Transaction.Reporter.track_metric({
-        {:external, url, "Finch", request.method},
-        duration_s: duration_s
-      })
+        NewRelic.Transaction.Reporter.track_metric({
+          {:external, url, "Finch", request.method},
+          duration_s: duration_s
+        })
 
-      NewRelic.DistributedTrace.reset_span(
-        previous_span: previous_span,
-        previous_span_attrs: previous_span_attrs
-      )
+        NewRelic.DistributedTrace.reset_span(
+          previous_span: previous_span,
+          previous_span_attrs: previous_span_attrs
+        )
+      end
     end
   end
 
@@ -171,46 +168,45 @@ defmodule NewRelic.Telemetry.Finch do
         config
       ) do
     if instrument?() do
-      %{
-        system_time: start_time,
-        span: span,
-        previous_span: previous_span,
-        previous_span_attrs: previous_span_attrs
-      } = Process.delete(config.handler_id)
-
-      metric_name = "External/#{request.host}/Finch/#{request.method}"
-
-      duration_ms = System.convert_time_unit(duration, :native, :millisecond)
-      duration_s = duration_ms / 1000
-
-      id = span
-      parent_id = previous_span || :root
-
-      url =
-        URI.to_string(%URI{scheme: "#{request.scheme}", host: request.host, path: request.path})
-
-      error_message = NewRelic.Util.Error.format_reason(kind, reason)
-
-      NewRelic.report_span(
-        timestamp_ms: System.convert_time_unit(start_time, :native, :millisecond),
-        duration_s: duration_s,
-        name: metric_name,
-        edge: [span: id, parent: parent_id],
-        category: "http",
-        attributes: %{
-          error: true,
-          "error.message": error_message,
-          "request.url": url,
-          "request.method": request.method,
-          "request.client": "Finch",
-          "finch.pool": finch_pool
-        }
-      )
+      with %{
+             start_time: start_time,
+             span: span,
+             previous_span: previous_span,
+             previous_span_attrs: previous_span_attrs
+           } <- Process.delete(config.handler_id) do
+        metric_name = "External/#{request.host}/Finch/#{request.method}"
+
+        duration_ms = System.convert_time_unit(duration, :native, :millisecond)
+        duration_s = duration_ms / 1000
+
+        id = span
+        parent_id = previous_span || :root
+
+        url = URI.to_string(%URI{scheme: "#{request.scheme}", host: request.host, path: request.path})
+
+        error_message = NewRelic.Util.Error.format_reason(kind, reason)
+
+        NewRelic.report_span(
+          timestamp_ms: System.convert_time_unit(start_time, :native, :millisecond),
+          duration_s: duration_s,
+          name: metric_name,
+          edge: [span: id, parent: parent_id],
+          category: "http",
+          attributes: %{
+            error: true,
+            "error.message": error_message,
+            "request.url": url,
+            "request.method": request.method,
+            "request.client": "Finch",
+            "finch.pool": finch_pool
+          }
+        )
 
-      NewRelic.DistributedTrace.reset_span(
-        previous_span: previous_span,
-        previous_span_attrs: previous_span_attrs
-      )
+        NewRelic.DistributedTrace.reset_span(
+          previous_span: previous_span,
+          previous_span_attrs: previous_span_attrs
+        )
+      end
     end
   end
 

lib/new_relic/telemetry/oban.ex

@@ -61,14 +61,14 @@ defmodule NewRelic.Telemetry.Oban do
   @doc false
   def handle_event(
         @oban_start,
-        %{system_time: system_time},
+        %{system_time: start_time},
         meta,
         _config
       ) do
     Transaction.Reporter.start_transaction(:other)
     NewRelic.DistributedTrace.start(:other)
 
-    add_start_attrs(meta, system_time)
+    add_start_attrs(meta, start_time)
   end
 
   def handle_event(
@@ -99,10 +99,10 @@ defmodule NewRelic.Telemetry.Oban do
     :ignore
   end
 
-  defp add_start_attrs(meta, system_time) do
+  defp add_start_attrs(meta, start_time) do
     [
       pid: inspect(self()),
-      system_time: system_time,
+      start_time: start_time,
       other_transaction_name: "Oban/#{meta.queue}/#{meta.worker}/perform",
       "oban.worker": meta.worker,
       "oban.queue": meta.queue,

lib/new_relic/telemetry/plug.ex

@@ -140,7 +140,7 @@ defmodule NewRelic.Telemetry.Plug do
   defp add_start_attrs(meta, meas, headers, :cowboy) do
     [
       pid: inspect(self()),
-      system_time: meas[:system_time],
+      start_time: meas[:system_time],
       host: meta.req.host,
       path: meta.req.path,
       remote_ip: meta.req.peer |> elem(0) |> :inet_parse.ntoa() |> to_string(),
@@ -155,7 +155,7 @@ defmodule NewRelic.Telemetry.Plug do
   defp add_start_attrs(meta, meas, headers, :bandit) do
     [
       pid: inspect(self()),
-      system_time: meas[:system_time],
+      start_time: meas[:system_time],
       host: meta.conn.host,
       path: meta.conn.request_path,
       remote_ip: meta.conn.remote_ip |> :inet_parse.ntoa() |> to_string(),

lib/new_relic/tracer/direct.ex

@@ -66,7 +66,7 @@ defmodule NewRelic.Tracer.Direct do
           pid: self(),
           id: span,
           parent_id: previous_span || :root,
-          system_time: start_time,
+          start_time: start_time,
           duration: duration
         })