Per-phase timing capture for proxy requests

.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

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**: 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
+- `Philter.Timing` module for telemetry-based phase timing with lazy global handler attachment
+
 ## [0.2.1] - 2026-03-11
 
 ### Fixed

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)
-# - :duration_us - Processing time in microseconds
 ```
 
 ## Handler Callbacks
@@ -100,7 +99,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

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
@@ -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 """
@@ -172,15 +173,19 @@ 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:
 
     * `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
 
@@ -270,13 +275,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 +316,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 +340,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 +352,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 +363,8 @@ defmodule Philter do
               started_at: started_at,
               error: error,
               status: 502,
-              body: "Bad Gateway"
+              body: "Bad Gateway",
+              timing: timing
             })
         end
 
@@ -595,6 +605,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,14 +617,50 @@ 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
     )
 
     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

lib/philter/handler.ex

@@ -65,23 +65,38 @@ 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 """
+  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.
 
   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(),
@@ -90,7 +105,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 """

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