From 60db3fbc363e26f2c1b418dea0fc0016001ce2ad Mon Sep 17 00:00:00 2001
From: Stuart Corbishley <corbish@gmail.com>
Date: Thu, 9 Apr 2026 08:32:18 +0200
Subject: [PATCH 01/11] Update .gitignore with standard Elixir library ignores

---
 .gitignore | 39 +++++++++++----------------------------
 1 file changed, 11 insertions(+), 28 deletions(-)

diff --git a/.gitignore b/.gitignore
index ddefaa1..6d2f134 100644
--- a/.gitignore
+++ b/.gitignore
@@ -1,32 +1,15 @@
-# Build
-/_build/
-/deps/
-/doc/
-
-# Dialyzer
-/priv/plts/
-
-# Test
-/cover/
-
-# Package
-philter-*.tar
-/philter-*/
-
-# VM crash dumps
+/_build
+/cover
+/deps
+/doc
+/.fetch
 erl_crash.dump
-
-# Archive artifacts
 *.ez
-
-# Temporary files
-/tmp/
-
-# IDE
-.idea/
-*.swp
+*.beam
+/config/*.secret.exs
 .elixir_ls/
-.vscode/
+priv/plts
+/philter-*.tar
+/philter-*/
 
-# OS
-.DS_Store
+.claude/settings.local.json

From 37415f30551e4b87aecd45dbfc30d02834db4da6 Mon Sep 17 00:00:00 2001
From: Stuart Corbishley <corbish@gmail.com>
Date: Thu, 9 Apr 2026 10:21:26 +0200
Subject: [PATCH 02/11] Add Philter.Timing module for per-phase timing capture
MIME-Version: 1.0
Content-Type: text/plain; charset=UTF-8
Content-Transfer-Encoding: 8bit

Global telemetry handler attached lazily on first use via
persistent_term. Per-request opt-in through process dictionary
flag — when no proxy has opted in, the handler cost is a single
Process.get/1 returning nil.

Captures queue, connect, send, recv durations and idle_time from
Finch telemetry events. Converts native time units to microseconds.
---
 lib/philter/timing.ex | 131 ++++++++++++++++++++++++++++++++++++++++++
 1 file changed, 131 insertions(+)
 create mode 100644 lib/philter/timing.ex

diff --git a/lib/philter/timing.ex b/lib/philter/timing.ex
new file mode 100644
index 0000000..bc09b0e
--- /dev/null
+++ b/lib/philter/timing.ex
@@ -0,0 +1,131 @@
+defmodule Philter.Timing do
+  @moduledoc """
+  Per-phase timing capture for proxy requests.
+
+  Captures pool checkout, connection, send, and receive durations from
+  the underlying HTTP client's telemetry events.
+
+  Uses a single globally-attached telemetry handler (attached lazily on
+  first use). Per-request opt-in is via a process dictionary flag — when
+  no proxy has opted in, the handler is a single `Process.get/1` returning
+  nil.
+
+  Timing capture is single-flight-per-process: only one `proxy/2` call
+  per process can capture timing at a time. The `:philter_timing_ref`
+  process dictionary key is shared, so a reentrant `proxy/2` call in the
+  same process would overwrite the ref. This is by design — Plug request
+  processes handle one request at a time.
+  """
+
+  @type t :: %{
+    queue_us: non_neg_integer() | nil,
+    connect_us: non_neg_integer() | nil,
+    send_us: non_neg_integer() | nil,
+    recv_us: non_neg_integer() | nil,
+    idle_time_us: non_neg_integer() | nil,
+    reused_connection?: boolean()
+  }
+
+  @events [
+    [:finch, :queue, :stop],
+    [:finch, :connect, :stop],
+    [:finch, :send, :stop],
+    [:finch, :recv, :stop],
+    [:finch, :reused_connection]
+  ]
+
+  @handler_id "philter-timing"
+
+  ## Lazy global handler attachment
+
+  @doc false
+  @spec ensure_attached() :: :ok
+  def ensure_attached do
+    case :persistent_term.get({__MODULE__, :attached}, false) do
+      true ->
+        :ok
+
+      false ->
+        case :telemetry.attach_many(@handler_id, @events, &__MODULE__.handle_event/4, nil) do
+          :ok -> :ok
+          {:error, :already_exists} -> :ok
+        end
+
+        :persistent_term.put({__MODULE__, :attached}, true)
+    end
+  end
+
+  ## Per-request opt-in / collection
+
+  @doc false
+  @spec start_capture() :: reference()
+  def start_capture do
+    ref = make_ref()
+    Process.put(:philter_timing_ref, ref)
+    ref
+  end
+
+  @doc false
+  @spec collect(reference()) :: t()
+  def collect(ref) do
+    Process.delete(:philter_timing_ref)
+
+    result = %{
+      queue_us: get_duration(ref, [:finch, :queue, :stop]),
+      connect_us: get_duration(ref, [:finch, :connect, :stop]),
+      send_us: get_duration(ref, [:finch, :send, :stop]),
+      recv_us: get_duration(ref, [:finch, :recv, :stop]),
+      idle_time_us: get_idle_time(ref),
+      reused_connection?: get_reused(ref)
+    }
+
+    cleanup(ref)
+    result
+  end
+
+  ## Telemetry handler (called for ALL finch events in any process)
+
+  @doc false
+  def handle_event(event, measurements, _metadata, _config) do
+    case Process.get(:philter_timing_ref) do
+      nil -> :ok
+      ref -> Process.put({ref, event}, measurements)
+    end
+  end
+
+  ## Private helpers
+
+  # Read duration from stored measurements without deleting — other fields
+  # (e.g. idle_time on queue) may be needed from the same measurements map.
+  # cleanup/1 handles deletion after all fields are extracted.
+  defp get_duration(ref, event) do
+    case Process.get({ref, event}) do
+      nil -> nil
+      %{duration: duration} ->
+        System.convert_time_unit(duration, :native, :microsecond)
+    end
+  end
+
+  # idle_time is part of the [:finch, :queue, :stop] measurements map
+  # alongside duration. Read from the same stored measurements.
+  defp get_idle_time(ref) do
+    case Process.get({ref, [:finch, :queue, :stop]}) do
+      nil -> nil
+      %{idle_time: idle_time} ->
+        System.convert_time_unit(idle_time, :native, :microsecond)
+      _no_idle_time -> nil
+    end
+  end
+
+  defp get_reused(ref) do
+    case Process.get({ref, [:finch, :reused_connection]}) do
+      nil -> false
+      _measurements -> true
+    end
+  end
+
+  defp cleanup(ref) do
+    for event <- @events, do: Process.delete({ref, event})
+    :ok
+  end
+end

From bf33e7fbf43d39496eb16b878a8151e671010b38 Mon Sep 17 00:00:00 2001
From: Stuart Corbishley <corbish@gmail.com>
Date: Thu, 9 Apr 2026 10:22:46 +0200
Subject: [PATCH 03/11] Add Philter.Timing unit tests

Covers lazy attachment idempotency, no-op when not opted in,
capture+collect round-trip, native-to-microsecond conversion,
reused_connection flag, process dictionary cleanup after collect,
mutual exclusivity of connect vs reused_connection, idle_time_us
extraction, and graceful handling when no events fire.
---
 test/philter/timing_test.exs | 170 +++++++++++++++++++++++++++++++++++
 1 file changed, 170 insertions(+)
 create mode 100644 test/philter/timing_test.exs

diff --git a/test/philter/timing_test.exs b/test/philter/timing_test.exs
new file mode 100644
index 0000000..474979c
--- /dev/null
+++ b/test/philter/timing_test.exs
@@ -0,0 +1,170 @@
+defmodule Philter.TimingTest do
+  use ExUnit.Case, async: true
+
+  alias Philter.Timing
+
+  setup do
+    Timing.ensure_attached()
+    :ok
+  end
+
+  describe "ensure_attached/0" do
+    test "calling twice does not crash" do
+      assert :ok = Timing.ensure_attached()
+      assert :ok = Timing.ensure_attached()
+    end
+  end
+
+  describe "handle_event/4" do
+    test "does nothing when :philter_timing_ref is not in process dictionary" do
+      # Ensure no timing ref is set
+      Process.delete(:philter_timing_ref)
+
+      # Fire an event — should be a no-op, not a crash
+      :telemetry.execute([:finch, :queue, :stop], %{duration: 100}, %{})
+
+      # Nothing should be stored in the process dictionary for any ref
+      assert Process.get(:philter_timing_ref) == nil
+    end
+  end
+
+  describe "capture and collect round-trip" do
+    test "events are captured and collect returns populated map" do
+      one_us_native = System.convert_time_unit(1, :microsecond, :native)
+
+      ref = Timing.start_capture()
+
+      :telemetry.execute([:finch, :queue, :stop], %{duration: one_us_native * 10, idle_time: one_us_native * 2}, %{})
+      :telemetry.execute([:finch, :connect, :stop], %{duration: one_us_native * 20}, %{})
+      :telemetry.execute([:finch, :send, :stop], %{duration: one_us_native * 30}, %{})
+      :telemetry.execute([:finch, :recv, :stop], %{duration: one_us_native * 40}, %{})
+
+      result = Timing.collect(ref)
+
+      assert result.queue_us == 10
+      assert result.connect_us == 20
+      assert result.send_us == 30
+      assert result.recv_us == 40
+      assert result.idle_time_us == 2
+      assert result.reused_connection? == false
+    end
+  end
+
+  describe "duration conversion" do
+    test "native time units are converted to microseconds" do
+      one_us_native = System.convert_time_unit(1, :microsecond, :native)
+
+      ref = Timing.start_capture()
+      :telemetry.execute([:finch, :send, :stop], %{duration: one_us_native}, %{})
+
+      result = Timing.collect(ref)
+
+      assert result.send_us == 1
+    end
+  end
+
+  describe "reused_connection?" do
+    test "defaults to false" do
+      ref = Timing.start_capture()
+      result = Timing.collect(ref)
+
+      assert result.reused_connection? == false
+    end
+
+    test "set to true when [:finch, :reused_connection] fires" do
+      ref = Timing.start_capture()
+      :telemetry.execute([:finch, :reused_connection], %{}, %{})
+
+      result = Timing.collect(ref)
+
+      assert result.reused_connection? == true
+    end
+  end
+
+  describe "cleanup" do
+    test "process dictionary entries for the ref are removed after collect" do
+      one_us_native = System.convert_time_unit(1, :microsecond, :native)
+
+      ref = Timing.start_capture()
+
+      :telemetry.execute([:finch, :queue, :stop], %{duration: one_us_native}, %{})
+      :telemetry.execute([:finch, :connect, :stop], %{duration: one_us_native}, %{})
+      :telemetry.execute([:finch, :send, :stop], %{duration: one_us_native}, %{})
+      :telemetry.execute([:finch, :recv, :stop], %{duration: one_us_native}, %{})
+      :telemetry.execute([:finch, :reused_connection], %{}, %{})
+
+      _result = Timing.collect(ref)
+
+      # The timing ref itself should be removed
+      assert Process.get(:philter_timing_ref) == nil
+
+      # All event entries for this ref should be removed
+      assert Process.get({ref, [:finch, :queue, :stop]}) == nil
+      assert Process.get({ref, [:finch, :connect, :stop]}) == nil
+      assert Process.get({ref, [:finch, :send, :stop]}) == nil
+      assert Process.get({ref, [:finch, :recv, :stop]}) == nil
+      assert Process.get({ref, [:finch, :reused_connection]}) == nil
+    end
+  end
+
+  describe "mutual exclusivity of connect vs reused_connection" do
+    test "reused_connection means connect_us is nil; connect means reused_connection? is false" do
+      one_us_native = System.convert_time_unit(1, :microsecond, :native)
+
+      # Case 1: reused_connection fires, no connect event
+      ref1 = Timing.start_capture()
+      :telemetry.execute([:finch, :reused_connection], %{}, %{})
+      result1 = Timing.collect(ref1)
+
+      assert result1.reused_connection? == true
+      assert result1.connect_us == nil
+
+      # Case 2: connect fires, no reused_connection event
+      ref2 = Timing.start_capture()
+      :telemetry.execute([:finch, :connect, :stop], %{duration: one_us_native * 5}, %{})
+      result2 = Timing.collect(ref2)
+
+      assert result2.reused_connection? == false
+      assert result2.connect_us == 5
+    end
+  end
+
+  describe "idle_time_us" do
+    test "populated from [:finch, :queue, :stop] measurements" do
+      one_us_native = System.convert_time_unit(1, :microsecond, :native)
+
+      ref = Timing.start_capture()
+      :telemetry.execute([:finch, :queue, :stop], %{duration: one_us_native * 10, idle_time: one_us_native * 7}, %{})
+
+      result = Timing.collect(ref)
+
+      assert result.idle_time_us == 7
+    end
+
+    test "nil when queue event does not carry idle_time" do
+      one_us_native = System.convert_time_unit(1, :microsecond, :native)
+
+      ref = Timing.start_capture()
+      :telemetry.execute([:finch, :queue, :stop], %{duration: one_us_native * 10}, %{})
+
+      result = Timing.collect(ref)
+
+      assert result.queue_us == 10
+      assert result.idle_time_us == nil
+    end
+  end
+
+  describe "no events fired" do
+    test "collect returns all-nil phase fields and reused_connection?: false" do
+      ref = Timing.start_capture()
+      result = Timing.collect(ref)
+
+      assert result.queue_us == nil
+      assert result.connect_us == nil
+      assert result.send_us == nil
+      assert result.recv_us == nil
+      assert result.idle_time_us == nil
+      assert result.reused_connection? == false
+    end
+  end
+end

From 5936072f5ab91fa8986949456a9209f2de3bd6cf Mon Sep 17 00:00:00 2001
From: Stuart Corbishley <corbish@gmail.com>
Date: Thu, 9 Apr 2026 10:23:56 +0200
Subject: [PATCH 04/11] Replace duration_us with timing map in finished_result

Breaking change: finished_result.duration_us is replaced by a timing
map containing total_us (same value) plus per-phase breakdown fields
(queue_us, connect_us, send_us, recv_us, idle_time_us,
reused_connection?).

Phase fields are populated when collect_timing: true is passed to
proxy/2. When timing capture is off, phase fields are nil.

Adds stream_with_timing/5 wrapper around Finch.stream_while that
optionally captures telemetry-based phase timing. The catch clause
cleans up process dictionary entries on raises/exits.
---
 lib/philter.ex         | 63 +++++++++++++++++++++++++++++++++++-------
 lib/philter/handler.ex | 19 ++++++++++++-
 2 files changed, 71 insertions(+), 11 deletions(-)

diff --git a/lib/philter.ex b/lib/philter.ex
index d89e362..e601b5f 100644
--- a/lib/philter.ex
+++ b/lib/philter.ex
@@ -101,7 +101,8 @@ defmodule Philter do
           receive_timeout: pos_integer(),
           max_payload_size: pos_integer(),
           persistable_content_types: [String.t()],
-          log_level: Logger.level() | false
+          log_level: Logger.level() | false,
+          collect_timing: boolean()
         ]
 
   @doc """
@@ -270,13 +271,15 @@ defmodule Philter do
           upstream_url: upstream_url
         }
 
-        result =
-          Finch.stream_while(
+        collect_timing? = Keyword.get(opts, :collect_timing, false)
+
+        {result, timing} =
+          stream_with_timing(
             request,
             config.finch_name,
             acc,
-            &handle_stream_message/2,
-            receive_timeout: config.receive_timeout
+            [receive_timeout: config.receive_timeout],
+            collect_timing?
           )
 
         case result do
@@ -309,7 +312,7 @@ defmodule Philter do
                 upstream_url: upstream_url,
                 method: acc.conn.method,
                 status: acc.conn.status,
-                duration_us: duration_us
+                timing: build_timing(duration_us, timing)
               },
               handler_state
             )
@@ -333,7 +336,8 @@ defmodule Philter do
               started_at: started_at,
               error: {:timeout, reason},
               status: 504,
-              body: "Gateway Timeout"
+              body: "Gateway Timeout",
+              timing: timing
             })
 
           {:error, %Mint.TransportError{reason: reason}, acc}
@@ -344,7 +348,8 @@ defmodule Philter do
               started_at: started_at,
               error: {:timeout, reason},
               status: 504,
-              body: "Gateway Timeout"
+              body: "Gateway Timeout",
+              timing: timing
             })
 
           {:error, error, acc} ->
@@ -354,7 +359,8 @@ defmodule Philter do
               started_at: started_at,
               error: error,
               status: 502,
-              body: "Bad Gateway"
+              body: "Bad Gateway",
+              timing: timing
             })
         end
 
@@ -595,6 +601,7 @@ defmodule Philter do
     end
 
     observations = Observer.finalize(acc.observer)
+    duration_us = System.monotonic_time(:microsecond) - info.started_at
     handler_state = handler_state(acc)
 
     notify_response_finished(
@@ -606,7 +613,7 @@ defmodule Philter do
         upstream_url: info.upstream_url,
         method: info.method,
         status: nil,
-        duration_us: System.monotonic_time(:microsecond) - info.started_at
+        timing: build_timing(duration_us, info.timing)
       },
       handler_state
     )
@@ -614,6 +621,42 @@ defmodule Philter do
     acc.conn |> send_resp(info.status, info.body) |> halt()
   end
 
+  defp stream_with_timing(request, finch_name, acc, opts, collect_timing?) do
+    ref =
+      if collect_timing? do
+        Philter.Timing.ensure_attached()
+        Philter.Timing.start_capture()
+      end
+
+    try do
+      Finch.stream_while(request, finch_name, acc, &handle_stream_message/2, opts)
+    catch
+      kind, reason ->
+        if ref, do: Philter.Timing.collect(ref)
+        :erlang.raise(kind, reason, __STACKTRACE__)
+    else
+      result ->
+        timing = if ref, do: Philter.Timing.collect(ref)
+        {result, timing}
+    end
+  end
+
+  defp build_timing(total_us, nil) do
+    %{
+      total_us: total_us,
+      queue_us: nil,
+      connect_us: nil,
+      send_us: nil,
+      recv_us: nil,
+      idle_time_us: nil,
+      reused_connection?: nil
+    }
+  end
+
+  defp build_timing(total_us, phase_timing) do
+    Map.put(phase_timing, :total_us, total_us)
+  end
+
   defp notify_request_started(nil, _metadata), do: {:ok, nil}
 
   defp notify_request_started({module, args}, metadata) do
diff --git a/lib/philter/handler.ex b/lib/philter/handler.ex
index 3509462..1fcc401 100644
--- a/lib/philter/handler.ex
+++ b/lib/philter/handler.ex
@@ -77,6 +77,23 @@ defmodule Philter.Handler do
           required(:time_to_first_byte_us) => non_neg_integer() | nil
         }
 
+  @typedoc """
+  Per-phase timing breakdown for a proxy request.
+
+  When `collect_timing: true` is set, phase fields are populated from HTTP
+  client telemetry. When timing capture is off, phase fields are `nil` and
+  `reused_connection?` is `nil`.
+  """
+  @type timing :: %{
+          required(:total_us) => non_neg_integer(),
+          required(:queue_us) => non_neg_integer() | nil,
+          required(:connect_us) => non_neg_integer() | nil,
+          required(:send_us) => non_neg_integer() | nil,
+          required(:recv_us) => non_neg_integer() | nil,
+          required(:idle_time_us) => non_neg_integer() | nil,
+          required(:reused_connection?) => boolean() | nil
+        }
+
   @typedoc """
   Result passed to handle_response_finished/2.
 
@@ -90,7 +107,7 @@ defmodule Philter.Handler do
           required(:upstream_url) => String.t(),
           required(:method) => String.t(),
           required(:status) => non_neg_integer() | nil,
-          required(:duration_us) => non_neg_integer()
+          required(:timing) => timing()
         }
 
   @doc """

From a58bd65c99e305e5787593089c621a1ae69c8e9d Mon Sep 17 00:00:00 2001
From: Stuart Corbishley <corbish@gmail.com>
Date: Thu, 9 Apr 2026 10:25:24 +0200
Subject: [PATCH 05/11] Update test suite for timing structure breaking change

Adapts existing assertions from result.duration_us to
result.timing.total_us. Adds new describe block for timing-specific
tests: default nil phase fields when collect_timing is not set,
populated phase fields with collect_timing: true, and timing
presence on error paths.
---
 test/philter_test.exs | 84 +++++++++++++++++++++++++++++++++++++++++++
 1 file changed, 84 insertions(+)

diff --git a/test/philter_test.exs b/test/philter_test.exs
index 3d0405e..6ef5c1b 100644
--- a/test/philter_test.exs
+++ b/test/philter_test.exs
@@ -219,6 +219,7 @@ defmodule PhilterTest do
       assert result.error == nil
       assert result.request_observation.hash != nil
       assert result.response_observation.hash != nil
+      assert is_integer(result.timing.total_us) and result.timing.total_us > 0
     end
 
     test "uses caller-supplied headers when provided", %{bypass: bypass, upstream: upstream} do
@@ -399,6 +400,7 @@ defmodule PhilterTest do
       assert_receive {:response_finished, result}
       assert result.error != nil
       assert result.status == nil
+      assert is_integer(result.timing.total_us) and result.timing.total_us > 0
     end
 
     test "rejects proxy with handler-controlled status and body", %{upstream: upstream} do
@@ -762,6 +764,88 @@ defmodule PhilterTest do
     end
   end
 
+  describe "proxy/2 timing" do
+    test "without collect_timing, timing has total_us and nil phase fields", %{
+      bypass: bypass,
+      upstream: upstream
+    } do
+      Bypass.expect(bypass, "GET", "/timing-default", fn conn ->
+        conn
+        |> put_resp_header("content-type", "text/plain")
+        |> send_resp(200, "hello")
+      end)
+
+      conn =
+        conn(:get, "/timing-default")
+        |> Philter.proxy(
+          upstream: upstream,
+          finch_name: Philter.TestFinch,
+          handler: {TestHandler, %{test_pid: self()}}
+        )
+
+      assert conn.status == 200
+
+      assert_receive {:response_finished, result}
+      timing = result.timing
+
+      assert is_integer(timing.total_us) and timing.total_us > 0
+      assert timing.queue_us == nil
+      assert timing.connect_us == nil
+      assert timing.send_us == nil
+      assert timing.recv_us == nil
+      assert timing.idle_time_us == nil
+      assert timing.reused_connection? == nil
+    end
+
+    test "with collect_timing: true, phase timing fields are populated", %{
+      bypass: bypass,
+      upstream: upstream
+    } do
+      Bypass.expect(bypass, "GET", "/timing-collect", fn conn ->
+        conn
+        |> put_resp_header("content-type", "text/plain")
+        |> send_resp(200, "hello")
+      end)
+
+      conn =
+        conn(:get, "/timing-collect")
+        |> Philter.proxy(
+          upstream: upstream,
+          finch_name: Philter.TestFinch,
+          handler: {TestHandler, %{test_pid: self()}},
+          collect_timing: true
+        )
+
+      assert conn.status == 200
+
+      assert_receive {:response_finished, result}
+      timing = result.timing
+
+      assert is_integer(timing.total_us) and timing.total_us > 0
+      assert is_integer(timing.queue_us) and timing.queue_us >= 0
+      assert is_integer(timing.send_us) and timing.send_us >= 0
+      assert is_integer(timing.recv_us) and timing.recv_us >= 0
+      assert is_boolean(timing.reused_connection?)
+      assert timing.idle_time_us == nil or (is_integer(timing.idle_time_us) and timing.idle_time_us >= 0)
+    end
+
+    test "error paths still get timing", %{upstream: _upstream} do
+      conn =
+        conn(:get, "/test")
+        |> Philter.proxy(
+          upstream: "http://localhost:59999",
+          finch_name: Philter.TestFinch,
+          handler: {TestHandler, %{test_pid: self()}}
+        )
+
+      assert conn.status == 502
+
+      assert_receive {:response_finished, result}
+      assert result.error != nil
+      assert is_integer(result.timing.total_us) and result.timing.total_us > 0
+    end
+  end
+
   describe "logging" do
     test "default :debug level emits request start with method, URL, and host", %{
       bypass: bypass,

From 5a5e71e1a3bb8898f40a2da7652be410504db08d Mon Sep 17 00:00:00 2001
From: Stuart Corbishley <corbish@gmail.com>
Date: Thu, 9 Apr 2026 10:25:40 +0200
Subject: [PATCH 06/11] Bump version to 0.3.0 for timing capture feature

Breaking change to finished_result warrants minor version bump.
---
 CHANGELOG.md | 9 +++++++++
 mix.exs      | 2 +-
 2 files changed, 10 insertions(+), 1 deletion(-)

diff --git a/CHANGELOG.md b/CHANGELOG.md
index e181a5e..a553591 100644
--- a/CHANGELOG.md
+++ b/CHANGELOG.md
@@ -7,6 +7,15 @@ and this project adheres to [Semantic Versioning](https://semver.org/spec/v2.0.0
 
 ## [Unreleased]
 
+## [0.3.0] - 2026-04-09
+
+### Changed
+- **Breaking**: `finished_result` replaces top-level `duration_us` with `timing` map containing `total_us` and per-phase breakdown fields (`queue_us`, `connect_us`, `send_us`, `recv_us`, `idle_time_us`, `reused_connection?`)
+
+### Added
+- `collect_timing: true` option for `proxy/2` enables per-phase timing capture (queue, connect, send, recv, idle_time, reused_connection) from HTTP client telemetry
+- `Philter.Timing` module for telemetry-based phase timing with lazy global handler attachment
+
 ## [0.2.1] - 2026-03-11
 
 ### Fixed
diff --git a/mix.exs b/mix.exs
index 097cd6d..f0503d6 100644
--- a/mix.exs
+++ b/mix.exs
@@ -1,7 +1,7 @@
 defmodule Philter.MixProject do
   use Mix.Project
 
-  @version "0.2.1"
+  @version "0.3.0"
   @source_url "https://github.com/OpenFn/philter"
 
   def project do

From f3264d0580d939a868b35cf644345bd603cf780d Mon Sep 17 00:00:00 2001
From: Stuart Corbishley <corbish@gmail.com>
Date: Thu, 9 Apr 2026 10:26:02 +0200
Subject: [PATCH 07/11] Fix formatting in timing module and tests

---
 lib/philter/timing.ex        | 26 ++++++++++++++++----------
 test/philter/timing_test.exs | 14 ++++++++++++--
 test/philter_test.exs        |  4 +++-
 3 files changed, 31 insertions(+), 13 deletions(-)

diff --git a/lib/philter/timing.ex b/lib/philter/timing.ex
index bc09b0e..1e7746c 100644
--- a/lib/philter/timing.ex
+++ b/lib/philter/timing.ex
@@ -18,13 +18,13 @@ defmodule Philter.Timing do
   """
 
   @type t :: %{
-    queue_us: non_neg_integer() | nil,
-    connect_us: non_neg_integer() | nil,
-    send_us: non_neg_integer() | nil,
-    recv_us: non_neg_integer() | nil,
-    idle_time_us: non_neg_integer() | nil,
-    reused_connection?: boolean()
-  }
+          queue_us: non_neg_integer() | nil,
+          connect_us: non_neg_integer() | nil,
+          send_us: non_neg_integer() | nil,
+          recv_us: non_neg_integer() | nil,
+          idle_time_us: non_neg_integer() | nil,
+          reused_connection?: boolean()
+        }
 
   @events [
     [:finch, :queue, :stop],
@@ -100,7 +100,9 @@ defmodule Philter.Timing do
   # cleanup/1 handles deletion after all fields are extracted.
   defp get_duration(ref, event) do
     case Process.get({ref, event}) do
-      nil -> nil
+      nil ->
+        nil
+
       %{duration: duration} ->
         System.convert_time_unit(duration, :native, :microsecond)
     end
@@ -110,10 +112,14 @@ defmodule Philter.Timing do
   # alongside duration. Read from the same stored measurements.
   defp get_idle_time(ref) do
     case Process.get({ref, [:finch, :queue, :stop]}) do
-      nil -> nil
+      nil ->
+        nil
+
       %{idle_time: idle_time} ->
         System.convert_time_unit(idle_time, :native, :microsecond)
-      _no_idle_time -> nil
+
+      _no_idle_time ->
+        nil
     end
   end
 
diff --git a/test/philter/timing_test.exs b/test/philter/timing_test.exs
index 474979c..5d2121a 100644
--- a/test/philter/timing_test.exs
+++ b/test/philter/timing_test.exs
@@ -34,7 +34,12 @@ defmodule Philter.TimingTest do
 
       ref = Timing.start_capture()
 
-      :telemetry.execute([:finch, :queue, :stop], %{duration: one_us_native * 10, idle_time: one_us_native * 2}, %{})
+      :telemetry.execute(
+        [:finch, :queue, :stop],
+        %{duration: one_us_native * 10, idle_time: one_us_native * 2},
+        %{}
+      )
+
       :telemetry.execute([:finch, :connect, :stop], %{duration: one_us_native * 20}, %{})
       :telemetry.execute([:finch, :send, :stop], %{duration: one_us_native * 30}, %{})
       :telemetry.execute([:finch, :recv, :stop], %{duration: one_us_native * 40}, %{})
@@ -134,7 +139,12 @@ defmodule Philter.TimingTest do
       one_us_native = System.convert_time_unit(1, :microsecond, :native)
 
       ref = Timing.start_capture()
-      :telemetry.execute([:finch, :queue, :stop], %{duration: one_us_native * 10, idle_time: one_us_native * 7}, %{})
+
+      :telemetry.execute(
+        [:finch, :queue, :stop],
+        %{duration: one_us_native * 10, idle_time: one_us_native * 7},
+        %{}
+      )
 
       result = Timing.collect(ref)
 
diff --git a/test/philter_test.exs b/test/philter_test.exs
index 6ef5c1b..1a7c853 100644
--- a/test/philter_test.exs
+++ b/test/philter_test.exs
@@ -826,7 +826,9 @@ defmodule PhilterTest do
       assert is_integer(timing.send_us) and timing.send_us >= 0
       assert is_integer(timing.recv_us) and timing.recv_us >= 0
       assert is_boolean(timing.reused_connection?)
-      assert timing.idle_time_us == nil or (is_integer(timing.idle_time_us) and timing.idle_time_us >= 0)
+
+      assert timing.idle_time_us == nil or
+               (is_integer(timing.idle_time_us) and timing.idle_time_us >= 0)
     end
 
     test "error paths still get timing", %{upstream: _upstream} do

From 02c030cb4fc39ac5fe55cb088f6ad4aac57e1ad7 Mon Sep 17 00:00:00 2001
From: Stuart Corbishley <corbish@gmail.com>
Date: Thu, 9 Apr 2026 10:58:06 +0200
Subject: [PATCH 08/11] Fix stale duration_us reference in README, document
 collect_timing option

---
 README.md      | 2 +-
 lib/philter.ex | 5 +++++
 2 files changed, 6 insertions(+), 1 deletion(-)

diff --git a/README.md b/README.md
index 9f106be..ccff69e 100644
--- a/README.md
+++ b/README.md
@@ -100,7 +100,7 @@ defmodule MyApp.ProxyHandler do
 
   @impl true
   def handle_response_finished(result, state) do
-    Logger.info("Completed: #{result.status} in #{result.duration_us}us")
+    Logger.info("Completed: #{result.status} in #{result.timing.total_us}us")
     # result contains :request_observation and :response_observation
     {:ok, state}
   end
diff --git a/lib/philter.ex b/lib/philter.ex
index e601b5f..0cd7d00 100644
--- a/lib/philter.ex
+++ b/lib/philter.ex
@@ -173,6 +173,11 @@ defmodule Philter do
     * `:log_level` - Logger level for lifecycle events (`:debug`, `:info`, etc.)
       or `false` to disable all logging. Default: `:debug`.
 
+    * `:collect_timing` - When `true`, captures per-phase timing breakdown
+      (queue, connect, send, recv, idle_time, reused_connection) from HTTP client
+      telemetry events. Phase fields in `timing` are `nil` when disabled.
+      Default: `false`.
+
   ## Return Value
 
   Returns the `conn` with response sent. Observations are stored in:

From d3dd4eb3fd747a9d9edd7392f10bd6bf263e16d6 Mon Sep 17 00:00:00 2001
From: Stuart Corbishley <corbish@gmail.com>
Date: Thu, 9 Apr 2026 15:36:51 +0200
Subject: [PATCH 09/11] Remove timing from body observations, consolidate in
 timing map

Breaking change: body_observation no longer has duration_us or
time_to_first_byte_us. Observations are now purely content metadata
(hash, size, preview, body). All timing lives in finished_result.timing.

Removes started_at and first_byte_at from Observation struct.
The response_started callback's time_to_first_byte_us is unchanged
(it measures request-level TTFB, not body-level).
---
 CHANGELOG.md                      |  1 +
 README.md                         |  2 +-
 lib/philter.ex                    |  5 ++---
 lib/philter/handler.ex            |  6 +-----
 lib/philter/observation.ex        | 26 +++++---------------------
 test/philter/observation_test.exs | 19 +------------------
 test/philter/observer_test.exs    |  8 +++-----
 7 files changed, 14 insertions(+), 53 deletions(-)

diff --git a/CHANGELOG.md b/CHANGELOG.md
index a553591..84cbeda 100644
--- a/CHANGELOG.md
+++ b/CHANGELOG.md
@@ -11,6 +11,7 @@ and this project adheres to [Semantic Versioning](https://semver.org/spec/v2.0.0
 
 ### Changed
 - **Breaking**: `finished_result` replaces top-level `duration_us` with `timing` map containing `total_us` and per-phase breakdown fields (`queue_us`, `connect_us`, `send_us`, `recv_us`, `idle_time_us`, `reused_connection?`)
+- **Breaking**: `body_observation` removes `duration_us` and `time_to_first_byte_us` — all timing is now consolidated in `finished_result.timing`; observations are purely content metadata (hash, size, preview, body)
 
 ### Added
 - `collect_timing: true` option for `proxy/2` enables per-phase timing capture (queue, connect, send, recv, idle_time, reused_connection) from HTTP client telemetry
diff --git a/README.md b/README.md
index ccff69e..83665cd 100644
--- a/README.md
+++ b/README.md
@@ -75,7 +75,7 @@ resp_obs = conn.private[:philter_response_observation]
 # - :size - Total body size in bytes
 # - :preview - First 64KB of the body (UTF-8 safe truncation)
 # - :body - Full body (only if under max_payload_size and content-type matches)
-# - :duration_us - Processing time in microseconds
+# Timing data is on result.timing (see Philter.Handler.timing())
 ```
 
 ## Handler Callbacks
diff --git a/lib/philter.ex b/lib/philter.ex
index 0cd7d00..10c33a5 100644
--- a/lib/philter.ex
+++ b/lib/philter.ex
@@ -65,7 +65,7 @@ defmodule Philter do
         @impl true
         def handle_response_finished(result, state) do
           # result contains :request_observation and :response_observation
-          # each with :hash, :size, :body, :preview, :duration_us
+          # each with :hash, :size, :body, :preview
           {:ok, state}
         end
       end
@@ -185,8 +185,7 @@ defmodule Philter do
     * `conn.private[:philter_request_observation]` - Request body observation
     * `conn.private[:philter_response_observation]` - Response body observation
 
-  Each observation contains `:hash`, `:size`, `:body` (if accumulated), `:preview`,
-  and `:duration_us`.
+  Each observation contains `:hash`, `:size`, `:body` (if accumulated), and `:preview`.
 
   ## Error Handling
 
diff --git a/lib/philter/handler.ex b/lib/philter/handler.ex
index 1fcc401..fdd9e6e 100644
--- a/lib/philter/handler.ex
+++ b/lib/philter/handler.ex
@@ -65,16 +65,12 @@ defmodule Philter.Handler do
   - `:size` - Total body size in bytes
   - `:body` - Full body content if accumulated, nil otherwise
   - `:preview` - First 64KB of body (always present)
-  - `:duration_us` - Time to fully transfer body in microseconds
-  - `:time_to_first_byte_us` - Time to first byte in microseconds
   """
   @type body_observation :: %{
           required(:hash) => String.t(),
           required(:size) => non_neg_integer(),
           required(:body) => binary() | nil,
-          required(:preview) => binary(),
-          required(:duration_us) => non_neg_integer(),
-          required(:time_to_first_byte_us) => non_neg_integer() | nil
+          required(:preview) => binary()
         }
 
   @typedoc """
diff --git a/lib/philter/observation.ex b/lib/philter/observation.ex
index 52fc09e..af2ee2b 100644
--- a/lib/philter/observation.ex
+++ b/lib/philter/observation.ex
@@ -2,9 +2,9 @@ defmodule Philter.Observation do
   @moduledoc false
   # Internal module: Incremental observation capture for streaming bodies.
   #
-  # Captures hash (SHA256), preview (first 64KB), size, and timing data
-  # incrementally as chunks arrive. Optionally accumulates the full body
-  # if under a size threshold.
+  # Captures hash (SHA256), preview (first 64KB), and size incrementally
+  # as chunks arrive. Optionally accumulates the full body if under a size
+  # threshold.
   #
   # ## Body Accumulation
   #
@@ -24,8 +24,6 @@ defmodule Philter.Observation do
     :hash_state,
     :preview,
     :size,
-    :started_at,
-    :first_byte_at,
     # Accumulation fields
     :accumulate?,
     :accumulated_body,
@@ -37,8 +35,6 @@ defmodule Philter.Observation do
           hash_state: term(),
           preview: binary(),
           size: non_neg_integer(),
-          started_at: integer(),
-          first_byte_at: integer() | nil,
           accumulate?: boolean(),
           accumulated_body: iodata() | nil,
           max_size: non_neg_integer(),
@@ -66,8 +62,6 @@ defmodule Philter.Observation do
       hash_state: :crypto.hash_init(:sha256),
       preview: <<>>,
       size: 0,
-      started_at: System.monotonic_time(:microsecond),
-      first_byte_at: nil,
       accumulate?: accumulate?,
       accumulated_body: if(accumulate?, do: [], else: nil),
       max_size: max_size,
@@ -76,12 +70,11 @@ defmodule Philter.Observation do
   end
 
   @doc """
-  Updates observation with a chunk. Updates hash, preview, size, timing,
+  Updates observation with a chunk. Updates hash, preview, size,
   and accumulated body (if enabled and under threshold).
   """
   @spec update(t(), binary()) :: t()
   def update(%__MODULE__{} = obs, chunk) when is_binary(chunk) do
-    now = System.monotonic_time(:microsecond)
     chunk_size = byte_size(chunk)
     new_size = obs.size + chunk_size
 
@@ -91,8 +84,6 @@ defmodule Philter.Observation do
       hash_state: :crypto.hash_update(obs.hash_state, chunk),
       preview: capture_preview(obs.preview, chunk),
       size: new_size,
-      started_at: obs.started_at,
-      first_byte_at: obs.first_byte_at || now,
       accumulate?: obs.accumulate?,
       accumulated_body: accumulated_body,
       max_size: obs.max_size,
@@ -129,8 +120,6 @@ defmodule Philter.Observation do
   - `:size` - total bytes
   - `:preview` - first 64KB (UTF-8 safe)
   - `:body` - full body binary if accumulated, nil otherwise
-  - `:duration_us` - total microseconds
-  - `:time_to_first_byte_us` - microseconds to first chunk (nil if no data)
   """
   @spec finalize(t()) :: Philter.Handler.body_observation()
   def finalize(%__MODULE__{} = obs) do
@@ -142,9 +131,7 @@ defmodule Philter.Observation do
       hash: hash,
       preview: preview,
       size: obs.size,
-      body: body,
-      duration_us: System.monotonic_time(:microsecond) - obs.started_at,
-      time_to_first_byte_us: time_to_first_byte(obs)
+      body: body
     }
   end
 
@@ -171,7 +158,4 @@ defmodule Philter.Observation do
     <<captured::binary-size(to_capture), _rest::binary>> = chunk
     existing <> captured
   end
-
-  defp time_to_first_byte(%{first_byte_at: nil}), do: nil
-  defp time_to_first_byte(%{first_byte_at: first, started_at: started}), do: first - started
 end
diff --git a/test/philter/observation_test.exs b/test/philter/observation_test.exs
index aa57aaf..6478133 100644
--- a/test/philter/observation_test.exs
+++ b/test/philter/observation_test.exs
@@ -8,8 +8,6 @@ defmodule Philter.ObservationTest do
       obs = Observation.new()
       assert obs.size == 0
       assert obs.preview == <<>>
-      assert obs.started_at != nil
-      assert obs.first_byte_at == nil
       assert obs.accumulate? == false
       assert obs.accumulated_body == nil
     end
@@ -64,20 +62,6 @@ defmodule Philter.ObservationTest do
       assert byte_size(obs.preview) == 64 * 1024
       assert obs.size == 64 * 1024 + 5
     end
-
-    test "records first byte time on first chunk only" do
-      obs = Observation.new()
-      assert obs.first_byte_at == nil
-
-      obs = Observation.update(obs, "data")
-      first_time = obs.first_byte_at
-      assert first_time != nil
-
-      Process.sleep(1)
-      obs = Observation.update(obs, "more")
-      # Unchanged
-      assert obs.first_byte_at == first_time
-    end
   end
 
   describe "finalize/1" do
@@ -100,8 +84,7 @@ defmodule Philter.ObservationTest do
       assert Map.has_key?(obs, :hash)
       assert Map.has_key?(obs, :preview)
       assert Map.has_key?(obs, :size)
-      assert Map.has_key?(obs, :duration_us)
-      assert Map.has_key?(obs, :time_to_first_byte_us)
+      assert Map.has_key?(obs, :body)
     end
 
     test "hash is correct for multi-chunk data" do
diff --git a/test/philter/observer_test.exs b/test/philter/observer_test.exs
index 083c272..3859288 100644
--- a/test/philter/observer_test.exs
+++ b/test/philter/observer_test.exs
@@ -107,7 +107,7 @@ defmodule Philter.ObserverTest do
       assert %{request: %{}, response: %{}} = result
 
       # Verify both observations have correct keys
-      for key <- [:hash, :size, :preview, :body, :duration_us, :time_to_first_byte_us] do
+      for key <- [:hash, :size, :preview, :body] do
         assert Map.has_key?(result.request, key), "request missing #{key}"
         assert Map.has_key?(result.response, key), "response missing #{key}"
       end
@@ -234,16 +234,14 @@ defmodule Philter.ObserverTest do
                hash: ^empty_hash,
                size: 0,
                body: nil,
-               preview: "",
-               time_to_first_byte_us: nil
+               preview: ""
              } = result.request
 
       assert %{
                hash: ^empty_hash,
                size: 0,
                body: nil,
-               preview: "",
-               time_to_first_byte_us: nil
+               preview: ""
              } = result.response
     end
   end

From 3cea08a323c6718233d3177f9ab05f3386c03640 Mon Sep 17 00:00:00 2001
From: Stuart Corbishley <corbish@gmail.com>
Date: Thu, 9 Apr 2026 15:38:35 +0200
Subject: [PATCH 10/11] Polish public interface after review

- Document when finished_result.status is nil (error before response)
- Remove misplaced timing comment from README observation example
- Hide internal Timing.t() type from docs (consumers use Handler.timing())
---
 README.md              | 1 -
 lib/philter/handler.ex | 4 +++-
 lib/philter/timing.ex  | 1 +
 3 files changed, 4 insertions(+), 2 deletions(-)

diff --git a/README.md b/README.md
index 83665cd..8b32c29 100644
--- a/README.md
+++ b/README.md
@@ -75,7 +75,6 @@ resp_obs = conn.private[:philter_response_observation]
 # - :size - Total body size in bytes
 # - :preview - First 64KB of the body (UTF-8 safe truncation)
 # - :body - Full body (only if under max_payload_size and content-type matches)
-# Timing data is on result.timing (see Philter.Handler.timing())
 ```
 
 ## Handler Callbacks
diff --git a/lib/philter/handler.ex b/lib/philter/handler.ex
index fdd9e6e..e2295a1 100644
--- a/lib/philter/handler.ex
+++ b/lib/philter/handler.ex
@@ -94,7 +94,9 @@ defmodule Philter.Handler do
   Result passed to handle_response_finished/2.
 
   Contains observations for both request and response bodies, plus any error
-  that occurred during proxying.
+  that occurred during proxying. The `:status` field is `nil` when the error
+  occurred before receiving a response from upstream (e.g., connection refused,
+  pool checkout timeout).
   """
   @type finished_result :: %{
           required(:request_observation) => body_observation(),
diff --git a/lib/philter/timing.ex b/lib/philter/timing.ex
index 1e7746c..e621145 100644
--- a/lib/philter/timing.ex
+++ b/lib/philter/timing.ex
@@ -17,6 +17,7 @@ defmodule Philter.Timing do
   processes handle one request at a time.
   """
 
+  @typedoc false
   @type t :: %{
           queue_us: non_neg_integer() | nil,
           connect_us: non_neg_integer() | nil,

From 8be0aff4386bfaad565fd1d41c54940ecdc2147c Mon Sep 17 00:00:00 2001
From: Stuart Corbishley <corbish@gmail.com>
Date: Thu, 9 Apr 2026 15:41:18 +0200
Subject: [PATCH 11/11] Consolidate 0.3.0 changelog entries

---
 CHANGELOG.md | 3 +--
 1 file changed, 1 insertion(+), 2 deletions(-)

diff --git a/CHANGELOG.md b/CHANGELOG.md
index 84cbeda..8e98fb0 100644
--- a/CHANGELOG.md
+++ b/CHANGELOG.md
@@ -10,8 +10,7 @@ and this project adheres to [Semantic Versioning](https://semver.org/spec/v2.0.0
 ## [0.3.0] - 2026-04-09
 
 ### Changed
-- **Breaking**: `finished_result` replaces top-level `duration_us` with `timing` map containing `total_us` and per-phase breakdown fields (`queue_us`, `connect_us`, `send_us`, `recv_us`, `idle_time_us`, `reused_connection?`)
-- **Breaking**: `body_observation` removes `duration_us` and `time_to_first_byte_us` — all timing is now consolidated in `finished_result.timing`; observations are purely content metadata (hash, size, preview, body)
+- **Breaking**: All timing consolidated into `finished_result.timing` map — `finished_result.duration_us` replaced by `timing.total_us`, and `body_observation.duration_us` / `body_observation.time_to_first_byte_us` removed. Observations are now purely content metadata (hash, size, preview, body)
 
 ### Added
 - `collect_timing: true` option for `proxy/2` enables per-phase timing capture (queue, connect, send, recv, idle_time, reused_connection) from HTTP client telemetry