Add telemetry events

lib/snap.ex

@@ -35,11 +35,50 @@ defmodule Snap do
     config = cluster.config()
     auth = Map.fetch!(config, :auth)
 
+    start_time = System.os_time()
+
     with {:ok, {method, path, headers, body}} <- auth.sign(config, method, path, headers, body) do
-      cluster.with_connection(fn pid ->
-        Snap.Connection.request(pid, method, path, headers, body)
-      end)
-      |> parse_response()
+      {response, queue_time, query_time} =
+        cluster.with_connection(fn pid ->
+          queue_time = System.os_time() - start_time
+          response = Snap.Connection.request(pid, method, path, headers, body)
+          query_time = System.os_time() - queue_time - start_time
+
+          {response, queue_time, query_time}
+        end)
+
+      result = parse_response(response)
+
+      decode_time = System.os_time() - query_time - queue_time - start_time
+      total_time = queue_time + query_time + decode_time
+
+      event = telemetry_prefix(cluster) ++ [:request]
+
+      measurements = %{
+        queue_time: queue_time,
+        query_time: query_time,
+        decode_time: decode_time,
+        total_time: total_time
+      }
+
+      metadata = telemetry_metadata(method, path, headers, body, result)
+
+      :telemetry.execute(event, measurements, metadata)
+
+      result
     end
   end
+
+  defp telemetry_prefix(cluster) do
+    config = cluster.config()
+
+    Map.get_lazy(config, :telemetry_prefix, fn ->
+      otp_app = cluster.otp_app()
+      [otp_app, :snap]
+    end)
+  end
+
+  defp telemetry_metadata(method, path, _headers, body, result) do
+    %{method: method, path: path, body: body, result: result}
+  end
 end

lib/snap/cluster.ex

@@ -15,6 +15,10 @@ defmodule Snap.Cluster do
         Snap.Cluster.Supervisor.config(__MODULE__)
       end
 
+      def otp_app() do
+        unquote(opts[:otp_app])
+      end
+
       def child_spec(opts) do
         %{
           id: __MODULE__,
@@ -24,9 +28,11 @@ defmodule Snap.Cluster do
       end
 
       def start_link(config \\ []) do
-        otp_app = unquote(opts[:opt_app])
+        otp_app = unquote(opts[:otp_app])
         config = Application.get_env(otp_app, __MODULE__, config)
 
+        {:ok, config} = init(config)
+
         Snap.Cluster.Supervisor.start_link(__MODULE__, otp_app, config)
       end
     end

mix.exs

@@ -28,7 +28,8 @@ defmodule Snap.MixProject do
       {:mint, "~> 1.0"},
       {:castore, "~> 0.1.0"},
       {:poolboy, "~> 1.5.1"},
-      {:jason, "~> 1.0"}
+      {:jason, "~> 1.0"},
+      {:telemetry, "~> 0.4"}
     ]
   end
 end

mix.lock

@@ -3,4 +3,5 @@
   "jason": {:hex, :jason, "1.2.2", "ba43e3f2709fd1aa1dce90aaabfd039d000469c05c56f0b8e31978e03fa39052", [:mix], [{:decimal, "~> 1.0 or ~> 2.0", [hex: :decimal, repo: "hexpm", optional: true]}], "hexpm", "18a228f5f0058ee183f29f9eae0805c6e59d61c3b006760668d8d18ff0d12179"},
   "mint": {:hex, :mint, "1.2.0", "65e9d75c60c456a5fb1b800febb88f061f56157d103d755b99fcaeaeb3e956f3", [:mix], [{:castore, "~> 0.1.0", [hex: :castore, repo: "hexpm", optional: true]}], "hexpm", "19cbb3a5be91b7df4a35377ba94b26199481a541add055cf5d1d4299b55125ab"},
   "poolboy": {:hex, :poolboy, "1.5.2", "392b007a1693a64540cead79830443abf5762f5d30cf50bc95cb2c1aaafa006b", [:rebar3], [], "hexpm", "dad79704ce5440f3d5a3681c8590b9dc25d1a561e8f5a9c995281012860901e3"},
+  "telemetry": {:hex, :telemetry, "0.4.2", "2808c992455e08d6177322f14d3bdb6b625fbcfd233a73505870d8738a2f4599", [:rebar3], [], "hexpm", "2d1419bd9dda6a206d7b5852179511722e2b18812310d304620c7bd92a13fcef"},
 }

test/support/cluster.ex

@@ -1,3 +1,16 @@
 defmodule Snap.Test.Cluster do
   use Snap.Cluster, otp_app: :snap
+
+  def init(config) do
+    fun = &Snap.Test.Cluster.handle_event/4
+
+    :telemetry.attach(__MODULE__, [:snap, :snap, :request], fun, :ok)
+
+    {:ok, config}
+  end
+
+  def handle_event(event, latency, metadata, _config) do
+    handler = Process.delete(:telemetry) || fn _, _, _ -> :ok end
+    handler.(event, latency, metadata)
+  end
 end

test/telemetry_test.exs

@@ -0,0 +1,21 @@
+defmodule Snap.TelemetryTest do
+  use ExUnit.Case
+
+  alias Snap.Test.Cluster
+
+  test "telemetry is fired with a request" do
+    log = fn event_name, measurements, metadata ->
+      assert event_name == [:snap, :snap, :request]
+      assert %{result: {:ok, _}, method: "GET", path: "/_cluster/health", body: nil} = metadata
+
+      assert measurements.total_time ==
+               measurements.query_time + measurements.decode_time + measurements.queue_time
+
+      send(self(), :logged)
+    end
+
+    Process.put(:telemetry, log)
+    _ = Snap.get(Cluster, "/_cluster/health")
+    assert_received :logged
+  end
+end