Repository: keathley/finch (elixir)

Issue:
First Use Time & Idle Time Tracking
This will help in configuring pool size & count.

We can record System.monotonic_time on init and handle_checkin and subtract it from System.monotonic_time on handle_checkout.

Since init doesn't connect, maybe "first_use_time" makes sense as the name for that measurement. 

Pull request description:
Emit :handle_checkout events with idle_time measurements
Closes #27 

The issue mentions possibly tracking "first_use_time" separately, but I think this measurement alone should suit our needs for now.

Patch:
diff --git a/lib/finch/conn.ex b/lib/finch/conn.ex
index 95dd3e8..cf70de6 100644
--- a/lib/finch/conn.ex
+++ b/lib/finch/conn.ex
@@ -12,6 +12,7 @@ defmodule Finch.Conn do
       port: port,
       opts: opts.conn_opts,
       parent: parent,
+      last_checkin: System.monotonic_time(),
       mint: nil
     }
   end
diff --git a/lib/finch/pool.ex b/lib/finch/pool.ex
index 774bf31..616dde8 100644
--- a/lib/finch/pool.ex
+++ b/lib/finch/pool.ex
@@ -34,8 +34,8 @@ defmodule Finch.Pool do
       NimblePool.checkout!(
         pool,
         :checkout,
-        fn from, conn ->
-          Telemetry.stop(:queue, start_time, metadata)
+        fn from, {conn, idle_time} ->
+          Telemetry.stop(:queue, start_time, metadata, %{idle_time: idle_time})
 
           with {:ok, conn} <- Conn.connect(conn),
                {:ok, conn, response} <- Conn.request(conn, req, receive_timeout) do
@@ -67,13 +67,16 @@ defmodule Finch.Pool do
 
   @impl NimblePool
   def handle_checkout(:checkout, _, %{mint: nil} = conn) do
-    {:ok, conn, conn}
+    idle_time = System.monotonic_time() - conn.last_checkin
+    {:ok, {conn, idle_time}, conn}
   end
 
   def handle_checkout(:checkout, {pid, _}, conn) do
+    idle_time = System.monotonic_time() - conn.last_checkin
+
     with {:ok, conn} <- Conn.set_mode(conn, :passive),
          :ok <- Conn.transfer(conn, pid) do
-      {:ok, conn, conn}
+      {:ok, {conn, idle_time}, conn}
     else
       {:error, _error} ->
         {:remove, :closed}
@@ -84,7 +87,7 @@ defmodule Finch.Pool do
   def handle_checkin(state, _from, conn) do
     with :prechecked <- state,
          {:ok, conn} <- Conn.set_mode(conn, :active) do
-      {:ok, conn}
+      {:ok, %{conn | last_checkin: System.monotonic_time()}}
     else
       _ ->
         {:remove, :closed}
diff --git a/lib/finch/telemetry.ex b/lib/finch/telemetry.ex
index dd04ca4..8cc0354 100644
--- a/lib/finch/telemetry.ex
+++ b/lib/finch/telemetry.ex
@@ -23,6 +23,7 @@ defmodule Finch.Telemetry do
     #### Measurements
 
     * `:duration` - Duration to check out a pool connection.
+    * `:idle_time` - Elapsed time since the connection was last checked in or initialized.
 
     #### Metadata
 
@@ -123,12 +124,12 @@ defmodule Finch.Telemetry do
 
   @doc false
   # emits a `start` telemetry event and returns the the start time
-  def start(event, meta \\ %{}) do
+  def start(event, meta \\ %{}, extra_measurements \\ %{}) do
     start_time = System.monotonic_time()
 
     :telemetry.execute(
       [:finch, event, :start],
-      %{system_time: System.system_time()},
+      Map.merge(extra_measurements, %{system_time: System.system_time()}),
       meta
     )
 
@@ -137,9 +138,9 @@ defmodule Finch.Telemetry do
 
   @doc false
   # Emits a stop event.
-  def stop(event, start_time, meta \\ %{}) do
+  def stop(event, start_time, meta \\ %{}, extra_measurements \\ %{}) do
     end_time = System.monotonic_time()
-    measurements = %{duration: end_time - start_time}
+    measurements = Map.merge(extra_measurements, %{duration: end_time - start_time})
 
     :telemetry.execute(
       [:finch, event, :stop],
@@ -149,9 +150,9 @@ defmodule Finch.Telemetry do
   end
 
   @doc false
-  def exception(event, start_time, kind, reason, stack, meta \\ %{}) do
+  def exception(event, start_time, kind, reason, stack, meta \\ %{}, extra_measurements \\ %{}) do
     end_time = System.monotonic_time()
-    measurements = %{duration: end_time - start_time}
+    measurements = Map.merge(extra_measurements, %{duration: end_time - start_time})
 
     meta =
       meta


Test patch:
diff --git a/test/finch_test.exs b/test/finch_test.exs
index 56ee50c..5d6c37c 100644
--- a/test/finch_test.exs
+++ b/test/finch_test.exs
@@ -319,6 +319,7 @@ defmodule FinchTest do
 
           [:finch, :queue, :stop] ->
             assert is_integer(measurements.duration)
+            assert is_integer(measurements.idle_time)
             assert is_pid(meta.pool)
             assert is_atom(meta.scheme)
             assert is_integer(meta.port)