Repository: whatyouhide/redix
Pull request #138 (2019-04-24 08:21:44)

Al/telemetry events for pipeline
\cc @binaryseed @deadtrickster @arkgil @josevalim, pinging all of you since you gave great feedback on the last PR. This PR adds tracing to commands sent to Redis.

I'm looking for feedback on:

  * the separation between the `[:redix, :pipeline]` and `[:redix, :error]` events. I did this because if we have a single event with a `success?` meta field and an elapsed time measurements, then errors like `:disconnected` are gonna screw up measurements since their elapsed time will be very short as there's no talking with the database.

  * putting the whole list of commands in the metadata. I'm doing this so users can figure out how to group them, by count or type or whatever.

Thoughts?

arkgil: > errors like :disconnected are gonna screw up measurements since their elapsed time will be very short as there's no talking with the database.

I wouldn't be worried about skewed measurements, since error events could be always filtered out, although I agree that it's not perfect. Additionally, having a single event simplifies e.g. counting how many pipelines were executed.

Maybe alternative, valid approach would be to have an event before the pipeline is executed (e.g. `[:redix, :pipeline, :start]`) which allows for easier counting, another event when the response is received successfully for measuring elapsed time, and the last one for errors. 

Patch:
diff --git a/lib/redix.ex b/lib/redix.ex
index ca01db1..1568e69 100644
--- a/lib/redix.ex
+++ b/lib/redix.ex
@@ -791,7 +791,28 @@ defmodule Redix do
   end
 
   defp pipeline_without_checks(conn, commands, opts) do
-    Redix.Connection.pipeline(conn, commands, opts[:timeout] || @default_timeout)
+    timeout = opts[:timeout] || @default_timeout
+
+    telemetry_metadata = %{
+      connection: conn,
+      commands: commands,
+      start_time: System.system_time()
+    }
+
+    start_time = System.monotonic_time()
+
+    case Redix.Connection.pipeline(conn, commands, timeout) do
+      {:ok, response} ->
+        end_time = System.monotonic_time()
+        measurements = %{elapsed_time: end_time - start_time}
+        :ok = :telemetry.execute([:redix, :pipeline], measurements, telemetry_metadata)
+        {:ok, response}
+
+      {:error, reason} ->
+        telemetry_metadata = Map.put(telemetry_metadata, :reason, reason)
+        :ok = :telemetry.execute([:redix, :pipeline, :error], %{}, telemetry_metadata)
+        {:error, reason}
+    end
   end
 
   defp assert_valid_pipeline_commands([] = _commands) do
diff --git a/pages/Telemetry.md b/pages/Telemetry.md
index 18b5e3d..4270a4f 100644
--- a/pages/Telemetry.md
+++ b/pages/Telemetry.md
@@ -38,6 +38,25 @@ Redix connections (both `Redix` and `Redix.PubSub`) execute the following Teleme
     * `:address` - the address the connection successfully reconnected to.
     * `:conn` - the PID of the Redix connection that emitted the event.
 
+`Redix` connections execute the following Telemetry events when commands or pipelines of any kind are executed.
+
+  * `[:redix, :pipeline]` - executed when a pipeline (or command, which is a pipeline with just one command) is successfully sent to the server and a reply comes from the server. Measurements are:
+
+    * `:elapsed_time` (integer) - the elapsed time that it took to send the pipeline to the server and get a reply. The elapsed time is expressed in the `:native` time unit. See `System.convert_time_unit/3`.
+
+    Metadata are:
+
+      * `:connection` - the connection that emitted the event. If the connection was registered with a name, the name is used here, otherwise the PID.
+      * `:commands` - the commands sent to the server. This is always a list of commands, so even if you do `Redix.command(conn, ["PING"])` than the list of commands will be `[["PING"]]`.
+      * `:start_time` - the system time when the pipeline was issued. This could be useful for tracing. The time unit is `:native`, see `System.convert_time_unit/3`.
+
+  * `[:redix, :pipeline, :error]` - executed when there's an error talking to the server. There are no measurements. Metadata are:
+
+      * `:connection` - the connection that emitted the event. If the connection was registered with a name, the name is used here, otherwise the PID.
+      * `:commands` - the commands sent to the server. This is always a list of commands, so even if you do `Redix.command(conn, ["PING"])` than the list of commands will be `[["PING"]]`.
+      * `:start_time` - the system time when the pipeline was issued. This could be useful for tracing. The time unit is `:native`, see `System.convert_time_unit/3`.
+      * `:reason` - the error reason.
+
 More events might be added in the future and that won't be considered a breaking change, so if you're writing a handler for Redix events be sure to ignore events that are not known. All future Redix events will start with the `:redix` atom, like the ones above.
 
 ## Default handler for logging


Test patch:
diff --git a/test/redix_test.exs b/test/redix_test.exs
index eed2bb5..7302dce 100644
--- a/test/redix_test.exs
+++ b/test/redix_test.exs
@@ -298,6 +298,60 @@ defmodule RedixTest do
         Redix.pipeline(c, ["PING"])
       end
     end
+
+    test "emits Telemetry events on successful pipelines", %{conn: c} do
+      {test_name, _arity} = __ENV__.function
+
+      parent = self()
+      ref = make_ref()
+
+      handler = fn event, measurements, meta, _config ->
+        if meta.connection == c do
+          assert event == [:redix, :pipeline]
+          assert is_integer(measurements.elapsed_time) and measurements.elapsed_time > 0
+          assert meta.commands == [["PING"]]
+          assert is_integer(meta.start_time)
+        end
+
+        send(parent, ref)
+      end
+
+      :telemetry.attach(to_string(test_name), [:redix, :pipeline], handler, :no_config)
+
+      assert {:ok, ["PONG"]} = Redix.pipeline(c, [["PING"]])
+
+      assert_receive ^ref
+
+      :telemetry.detach(to_string(test_name))
+    end
+
+    test "emits Telemetry events on error pipelines", %{conn: c} do
+      {test_name, _arity} = __ENV__.function
+
+      parent = self()
+      ref = make_ref()
+
+      handler = fn event, measurements, meta, _config ->
+        if meta.connection == c do
+          assert event == [:redix, :pipeline, :error]
+          assert measurements == %{}
+          assert meta.commands == [["PING"], ["PING"]]
+          assert is_integer(meta.start_time)
+          assert meta.reason == %ConnectionError{reason: :timeout}
+        end
+
+        send(parent, ref)
+      end
+
+      :telemetry.attach(to_string(test_name), [:redix, :pipeline, :error], handler, :no_config)
+
+      assert {:error, %ConnectionError{reason: :timeout}} =
+               Redix.pipeline(c, [~w(PING), ~w(PING)], timeout: 0)
+
+      assert_receive ^ref
+
+      :telemetry.detach(to_string(test_name))
+    end
   end
 
   describe "command!/2" do