feat: Add manual tracing. (#6)

At this stage we don't have a great solution for automatically tracing
SQL queries, etc, so we have added API to allow users to manually add
traces to their test analytics from within a test.

Author: jimsynz

README.md

@@ -58,6 +58,9 @@ Randomized with seed 12345
 
 If all is well, you should see the test run in the test analytics section of the Buildkite dashboard.
 
+## 🎢 Tracing
+
+Buildkite Test Analytics has support for tracing potentially slow operations within your tests (SQL queries, HTTP requests, etc).  Because ExUnit can run multiple tests simultaneously, it is difficult to achieve this without requiring code changes - we cannot simply use [telemetry](https://hex.pm/packages/telemetry) events because we cannot easily attribute the events to specific tests across process boundaries.  Instead we have provided [a simple API](https://hexdocs.pm/buildkite_test_collector/BuildkiteTestCollector.Tracing.html) to manually instrument operations within your tests.
 
 ## 🔜 Roadmap
 

lib/buildkite_test_collector/duration.ex

@@ -1,59 +1,59 @@
 defmodule BuildkiteTestCollector.Duration do
+  defstruct usec: 0
+  alias BuildkiteTestCollector.{Duration, Instant}
+
   @moduledoc """
-  The analyics API specifies start and end times in fractional seconds since the
-  beginning of the test run.
+  The difference between two instants with microsecond accuracy.
+
+  The Buildkite analytics API stores all times as decimal seconds since the
+  start of the test run.  Therefore we use `Duration` to calculate the span
+  between two `Instant` values.
+  """
 
-  It's convenient for us to store these as a duration by specifying their start
-  time and end time and then calculating the diference when serialising into
-  JSON.
+  @type t :: %Duration{usec: integer()}
 
-  Internally these times are stored as microseconds from the system's monotonic
-  clock.  See `System.monotonic_time/1` for more information.
+  @doc """
+  Create a new duration from the specified number of seconds.
   """
+  @spec from_seconds(number) :: t
+  def from_seconds(seconds) when is_integer(seconds),
+    do: %Duration{usec: seconds * 1_000_000}
 
-  defstruct [:offset, :epoch]
-  alias __MODULE__
+  def from_seconds(seconds) when is_float(seconds),
+    do: %Duration{usec: round(seconds * 1_000_000)}
 
-  @type microseconds :: integer
-  @type seconds :: float
-  @type t :: %Duration{
-          epoch: microseconds,
-          offset: microseconds
-        }
+  @doc """
+  Create a new duration directly from microseconds.
+  """
+  @spec from_microseconds(number) :: t
+  def from_microseconds(microseconds) when is_integer(microseconds),
+    do: %Duration{usec: microseconds}
+
+  def from_microseconds(microseconds) when is_float(microseconds),
+    do: %Duration{usec: round(microseconds)}
 
   @doc """
-  The current time based on a zero-microsecond epoch.
+  Return the elapsed time between two instants.
+  """
+  @spec between(Instant.t(), Instant.t()) :: t
+  def between(%Instant{usec: i0}, %Instant{usec: i1}), do: %Duration{usec: i0 - i1}
 
-  This esspentially returns a duration since the beginning of time, and is not
-  that useful until you use it to as the epoch for other durations.
+  @doc """
+  Return the absolute duration (ie make the duration unsigned).
   """
-  @spec now :: t
-  def now, do: %Duration{epoch: 0, offset: now_us()}
+  @spec abs(t) :: t
+  def abs(%Duration{usec: i}) when i < 0, do: %Duration{usec: -i}
+  def abs(%Duration{} = duration), do: duration
 
   @doc """
-  Return a new now time based on the provided epoch.
+  Returns the elapsed duration between `instant` and now.
   """
-  @spec since(t) :: t
-  def since(%Duration{} = time) do
-    new_epoch = time.epoch + time.offset
-    new_offset = now_us() - new_epoch
-    %Duration{epoch: new_epoch, offset: new_offset}
-  end
+  @spec elapsed(Instant.t()) :: t
+  def elapsed(%Instant{} = instant), do: Duration.between(Instant.now(), instant)
 
   @doc """
   The duration of the timing, in (fractional) seconds.
   """
-  @spec as_seconds(t) :: seconds
-  def as_seconds(%Duration{offset: offset}), do: offset / 1_000_000.0
-
-  defp now_us, do: System.monotonic_time(:microsecond)
-
-  defimpl Jason.Encoder do
-    @spec encode(Duration.t(), Jason.Encode.opts()) :: iodata
-    def encode(timing, _opts) do
-      timing
-      |> Duration.as_seconds()
-      |> Jason.Encode.float()
-    end
-  end
+  @spec as_seconds(t) :: number
+  def as_seconds(%Duration{usec: i}), do: i / 1_000_000.0
 end

lib/buildkite_test_collector/formatter.ex

@@ -11,27 +11,103 @@ defmodule BuildkiteTestCollector.Formatter do
 
   require Logger
 
-  alias BuildkiteTestCollector.{CiEnv, Duration, HttpTransport, Payload, TestResult}
+  alias BuildkiteTestCollector.{CiEnv, Duration, HttpTransport, Instant, Payload, TestResult}
 
+  @typedoc """
+  Unique identifier for tests.
+
+  Contains the module that the test is defined in, and the name of the test as an atom.
+  """
+  @type test_id :: {module, atom}
+
+  @typedoc false
   @type state :: %{
           payload: Payload.t(),
-          timings: %{required(test_id :: {module, atom}) => Duration.t()}
+          timings: %{required(test_id) => Duration.t()},
+          spans: %{required(test_id) => [TestResult.span()]}
         }
 
-  @type test_id :: {module, atom}
+  @typedoc """
+  The ExUnit tags, (specifically `module` and `test` tags)
+  """
+  @type tags :: %{
+          required(:module) => module,
+          required(:test) => atom,
+          optional(atom) => any
+        }
+
+  @typedoc """
+  A trace with known start and end time.
+  """
+  @type span_with_start_and_end_at :: %{
+          required(:section) => :http | :sql | :sleep | :annotation,
+          required(:start_at) => Instant.t(),
+          required(:end_at) => Instant.t(),
+          optional(:duration) => Duration.t(),
+          optional(:detail) => String.t()
+        }
+
+  @typedoc """
+  A trace with a known duration.
+  """
+  @type span_with_duration :: %{
+          required(:section) => :http | :sql | :sleep | :annotation,
+          required(:duration) => Duration.t(),
+          optional(:detail) => String.t()
+        }
+
+  @doc """
+  Manually add a trace span to the currently running test.
+
+  You can add timing information about sql queries, http requests, etc to your
+  test analytics.
+
+  It's probably better to use the helpers in the `Tracing` module.
+
+  ## Example
+
+  ```elixir
+  alias BuildkiteTestCollector.{Formatter, Instant}
+
+  test "example of instrumenting a query", tags do
+    start_at = Instant.now()
+
+    MyApp.Repo.all(my_complicated_query)
+
+    end_at = Instant.now()
+
+    Formatter.add_span(tags, %{
+      start_at: start_at,
+      end_at: end_at,
+      section: :sql,
+      detail: inspect(my_complicated_query)
+    })
+  end
+  ```
+  """
+  @spec add_span(tags | test_id, span_with_start_and_end_at() | span_with_duration()) :: :ok
+  def add_span(%{module: module, test: name} = _tags, span),
+    do: GenServer.cast(__MODULE__, {:add_span, {module, name}, span})
+
+  def add_span({module, name} = _test_id, span),
+    do: GenServer.cast(__MODULE__, {:add_span, {module, name}, span})
 
   @impl true
   @spec init(keyword) :: {:ok, state}
-  def init(_opts) do
+  def init(opts) do
     Process.flag(:trap_exit, true)
 
     case CiEnv.detect_env() do
       {:ok, env_module} ->
         state = %{
           payload: Payload.init(env_module),
-          timings: %{}
+          timings: %{},
+          spans: %{}
         }
 
+        if Keyword.get(opts, :register, true),
+          do: Process.register(self(), __MODULE__)
+
         {:ok, state}
 
       :error ->
@@ -45,7 +121,7 @@ defmodule BuildkiteTestCollector.Formatter do
   def handle_cast({:suite_started, _}, state) do
     payload =
       state.payload
-      |> Payload.set_start_time(Duration.now())
+      |> Payload.set_start_time(Instant.now())
 
     {:noreply, %{state | payload: payload}}
   end
@@ -61,17 +137,20 @@ defmodule BuildkiteTestCollector.Formatter do
   def handle_cast({:test_started, %ExUnit.Test{module: module, name: name}}, state) do
     timings =
       state.timings
-      |> Map.put({module, name}, Duration.since(state.payload.started_at))
+      |> Map.put({module, name}, Instant.now())
 
     {:noreply, %{state | timings: timings}}
   end
 
   def handle_cast({:test_finished, %ExUnit.Test{module: module, name: name} = test}, state) do
-    end_time = Duration.since(state.payload.started_at)
+    test_id = {module, name}
+    {test_spans, spans} = Map.pop(state.spans, test_id, [])
+    state = %{state | spans: spans}
 
-    case Map.pop(state.timings, {module, name}) do
-      {%Duration{} = start_time, timings} ->
-        test_result = TestResult.new(test, start_time, end_time)
+    case Map.pop(state.timings, test_id) do
+      {%Instant{} = start_time, timings} ->
+        test_result = TestResult.new(test, start_time)
+        test_result = Enum.reduce(test_spans, test_result, &TestResult.add_span(&2, &1))
 
         payload =
           state.payload
@@ -95,6 +174,20 @@ defmodule BuildkiteTestCollector.Formatter do
     end
   end
 
+  def handle_cast({:add_span, {module, name}, span}, state) do
+    case refine_span(span) do
+      {:ok, span} ->
+        spans =
+          state.spans
+          |> Map.update({module, name}, [span], &[span | &1])
+
+        {:noreply, %{state | spans: spans}}
+
+      :error ->
+        {:noreply, state}
+    end
+  end
+
   def handle_cast(_, state), do: {:noreply, state}
 
   @impl true
@@ -105,4 +198,20 @@ defmodule BuildkiteTestCollector.Formatter do
       Logger.error("Error sending test suite analytics: #{inspect(reason)}")
     end
   end
+
+  defguardp valid_section?(section) when section in [:http, :sql, :sleep, :annotation]
+
+  defp refine_span(%{duration: duration, section: section} = span)
+       when is_struct(duration, Duration) and valid_section?(section),
+       do: {:ok, span}
+
+  defp refine_span(%{start_at: start_at, end_at: end_at, section: section} = span)
+       when is_struct(start_at, Instant) and is_struct(end_at, Instant) and
+              valid_section?(section),
+       do: {:ok, Map.put(span, :duration, Duration.between(end_at, start_at))}
+
+  defp refine_span(span) do
+    Logger.warn("Invalid span: #{inspect(span)}")
+    :error
+  end
 end

lib/buildkite_test_collector/instant.ex

@@ -0,0 +1,38 @@
+defmodule BuildkiteTestCollector.Instant do
+  defstruct usec: 0
+  alias BuildkiteTestCollector.{Duration, Instant}
+
+  @moduledoc """
+  Represents a single instant with microsecond accuracy.
+
+  Wraps monotonic time to ensure that there are no unit mistakes.
+
+  ## Why not just use `DateTime` instead?
+
+  Sadly, the wall clock time can move backwards and forwards between samples
+  (for example if [NTP](https://www.ntp.org) is updating the clock, or during a
+  daylight savings transition).  The system monotonic clock always moves
+  forwards, regardless of the current wall clock time.  This means it's no good
+  for measuring the absolute time, but is perfect for measuring relative time.
+
+  See
+  [erlang:monotonic_time/0](https://www.erlang.org/doc/man/erlang.html#monotonic_time-0)
+  for more information.
+  """
+
+  @type t :: %Instant{usec: integer()}
+
+  @doc """
+  Return an instant representing "now" as understood by the system's monotonic
+  clock.
+  """
+  @spec now :: t
+  def now, do: %Instant{usec: System.monotonic_time(:microsecond)}
+
+  @doc """
+  Add a duration to an instant and return a new instant.
+  """
+  @spec add(t, Duration.t()) :: t
+  def add(%Instant{usec: instant}, %Duration{usec: duration}),
+    do: %Instant{usec: instant + duration}
+end

lib/buildkite_test_collector/payload.ex

@@ -5,12 +5,12 @@ defmodule BuildkiteTestCollector.Payload do
 
   defstruct run_env: nil, data: [], started_at: nil, data_size: 0
 
-  alias BuildkiteTestCollector.{CiEnv, Duration, Payload, TestResult}
+  alias BuildkiteTestCollector.{CiEnv, Instant, Payload, TestResult}
 
   @type t :: %Payload{
           run_env: serialised_environment,
           data: [TestResult.t()],
-          started_at: nil | Duration.t(),
+          started_at: nil | Instant.t(),
           data_size: non_neg_integer()
         }
 
@@ -48,7 +48,7 @@ defmodule BuildkiteTestCollector.Payload do
   @doc """
   Set the start time of the suite.
   """
-  @spec set_start_time(Payload.t(), Duration.t()) :: Payload.t()
+  @spec set_start_time(Payload.t(), Instant.t()) :: Payload.t()
   def set_start_time(%Payload{} = payload, started_at), do: %{payload | started_at: started_at}
 
   defp serialise_env(ci_env_mod) do
@@ -58,4 +58,32 @@ defmodule BuildkiteTestCollector.Payload do
       key, env -> Map.put(env, key, apply(ci_env_mod, key, []))
     end)
   end
+
+  @doc """
+  Convert the payload into a map ready for serialisation to JSON.
+
+  This is done as a separate step because all timings are relative to the
+  payload start time, so must be calculated.
+  """
+  @spec as_json(t) :: map
+  def as_json(%Payload{} = payload) do
+    %{
+      format: "json",
+      run_env: payload.run_env,
+      data:
+        payload.data
+        |> Enum.map(&TestResult.as_json(&1, payload.started_at))
+        |> Enum.reverse()
+    }
+  end
+
+  defimpl Jason.Encoder do
+    @doc false
+    @spec encode(Payload.t(), Jason.Encode.opts()) :: iodata
+    def encode(payload, opts) do
+      payload
+      |> Payload.as_json()
+      |> Jason.Encode.map(opts)
+    end
+  end
 end