A121: RPC Delay Observability

A121-rpc-delay-observability.md

@@ -0,0 +1,222 @@
+A121: RPC Delay Observability
+----
+* Author(s): Madhav Bissa (@mbissa)
+* Approver: @markdroth, @ejona86, @dfawley, @easwars
+* Implemented in: Go, Java, C++
+* Last updated: 2026-08-17
+* Discussion at: https://groups.google.com/g/grpc-io/c/NsxXJ2MxXM4
+
+## Abstract
+
+This proposal introduces client-side metrics and tracing to measure the delays an RPC experiences within the client channel before it is sent over the network — the time an RPC spends queued waiting for name resolution or for a load balancing pick. It adds two duration histograms, a client-side tracing span, new methods on the call tracer API, and two fields on the load balancer's pick result to record these delays.
+
+## Background
+
+Existing gRPC core telemetry, as defined in [gRPC A66 (OpenTelemetry Metrics)][A66] and [gRPC A72 (OpenTelemetry Tracing)][A72], tracks the overall end-to-end duration of RPC calls and attempts. However, these metrics and spans function as aggregate buckets that do not decompose latency, leaving delays inside the client channel invisible to operators.
+
+When a gRPC channel is first created, it is in IDLE state, meaning that it has not done name resolution or attempted to connect to any endpoints. When the application sends an RPC on the channel, the channel will leave IDLE state and attempt to connect. Any RPCs sent on the channel while it is attempting to connect will be queued until the channel becomes connected, which results in increased latency for these RPCs. However, because current telemetry lacks visibility into these connecting delays, developers cannot distinguish between a slow network, a slow backend, or a channel initialization delay.
+
+While there are other sources of client-side delay that involve network I/O (such as credential fetching or retry delays), this proposal focuses on the two most common: **name resolution** and **load balancing pick** delays. The framework is extensible to other client-side delays in the future.
+
+### Related Proposals:
+* **[gRPC A66: OpenTelemetry Metrics][A66]**: Establishes base OpenTelemetry metrics.
+* **[gRPC A72: OpenTelemetry Tracing][A72]**: Establishes tracing spans and events.
+* **[gRPC A56: Priority LB Policy][A56]**: Establishes the priority load balancing policy and child failover mechanics.
+* **[gRPC A28: xDS Traffic Splitting and Routing][A28]**: Establishes the `xds_cluster_manager` and `weighted_target` container policies.
+
+## Proposal
+
+### Anatomy of a Delay
+
+gRPC records a **delay** whenever an RPC is blocked inside the client channel. A delay occurs at one of two levels:
+
+*   **Call-level**: before any network attempt is initiated, while the RPC waits on name resolution. Recorded against the RPC call.
+*   **Attempt-level**: within a specific attempt, while the RPC waits on a load balancing pick or a connection. Recorded against the attempt.
+
+Whether a delay is call-level or attempt-level is reflected by which histogram it is recorded to and by whether its trace span is nested under the call span or the attempt span.
+
+Each delay results in a data point being added to the relevant histogram and a new trace span. Every delay has two attributes:
+
+*   **`grpc.delay_type`**: A low-cardinality string representing the type of the delay. See below for supported values. This value is constant over the lifetime of an individual delay; if the value changes, that implies that the original delay has ended and a new delay has started. For metrics, this value is used in a metric label. For tracing, this value is an attribute on the trace span.
+*   **`grpc.delay_reason`**: A high-cardinality string capturing runtime details (such as target names, subchannel IP addresses, or connection error messages). This value can change over the lifetime of a delay. This value is not used in metrics. In tracing, this value is recorded in an event on the trace span.
+
+The base `grpc.delay_type` values are summarized below for reference; each is defined in full — with example reasons — in the per-policy sections that follow ([Resolver Delays](#resolver-delays), [LB Pick Delays](#lb-pick-delays)):
+
+| `grpc.delay_type` | Scope | Meaning | Generated by |
+|---|---|---|---|
+| `resolving` | call | waiting on name resolution | channel (resolver) |
+| `connecting` | attempt | waiting on a subchannel connection | leaf pickers (`pick_first`, `round_robin`, `ring_hash`, `weighted_round_robin`, `xds_override_host`) |
+| `rls_lookup_pending` | attempt | waiting on an RLS control-plane lookup | `rls` |
+| `cds_dynamic_discovery` | attempt | waiting on a CDS resource | `cds` |
+| `subchannel_state_mismatch` | attempt | picked subchannel left `READY` before it could be used | channel |
+| `picker_failing_with_wait_for_ready` | attempt | `wait_for_ready` RPC queued on a failing picker | channel |
+
+The `priority` policy composes the attempt-level values by prepending its numeric priority (e.g. `"0:connecting"`), and these prefixes stack when priority policies are nested (e.g. `"0:1:connecting"`), so the composed set is not statically enumerable.
+
+A delay begins when the channel starts waiting and ends when the wait resolves, when the `grpc.delay_type` changes (which ends the current delay and starts a new one), or when the RPC is cancelled or reaches its deadline.
+
+### Metric Schema
+
+The following client-side per-call metrics are registered, extending the instrumentation framework defined in [gRPC A66][A66].
+
+#### Call Delay Duration Histogram
+
+| Field | Value |
+|---|---|
+| **Name** | `grpc.client.call.delay.duration` |
+| **Type** | Float64 Histogram |
+| **Unit** | `s` (seconds) |
+| **Description** | EXPERIMENTAL. Time an RPC spent waiting at the call level before an attempt was initiated, such as waiting for name resolution. |
+| **Labels** | `grpc.target`, `grpc.method`, `grpc.delay_type` |
+| **Bucket Boundaries** | Same as A66 latency buckets: 0, 0.00001, 0.00005, 0.0001, 0.0003, 0.0006, 0.0008, 0.001, 0.002, 0.003, 0.004, 0.005, 0.006, 0.008, 0.01, 0.013, 0.016, 0.02, 0.025, 0.03, 0.04, 0.05, 0.065, 0.08, 0.1, 0.13, 0.16, 0.2, 0.25, 0.3, 0.4, 0.5, 0.65, 0.8, 1, 2, 5, 10, 20, 50, 100 |
+| **Default Enabled** | `false` (experimental, opt-in) |
+
+#### Attempt Delay Duration Histogram
+
+| Field | Value |
+|---|---|
+| **Name** | `grpc.client.attempt.delay.duration` |
+| **Type** | Float64 Histogram |
+| **Unit** | `s` (seconds) |
+| **Description** | EXPERIMENTAL. Time an RPC attempt spent waiting for a load balancing pick or connection establishment. |
+| **Labels** | `grpc.target`, `grpc.method`, `grpc.delay_type` |
+| **Bucket Boundaries** | Same as A66 latency buckets: 0, 0.00001, 0.00005, 0.0001, 0.0003, 0.0006, 0.0008, 0.001, 0.002, 0.003, 0.004, 0.005, 0.006, 0.008, 0.01, 0.013, 0.016, 0.02, 0.025, 0.03, 0.04, 0.05, 0.065, 0.08, 0.1, 0.13, 0.16, 0.2, 0.25, 0.3, 0.4, 0.5, 0.65, 0.8, 1, 2, 5, 10, 20, 50, 100 |
+| **Default Enabled** | `false` (experimental, opt-in) |
+
+### Tracing Schema
+
+Each delay is represented by a child trace span named **`Delay`**, nested under the parent RPC call span (for call-level delays) or the individual attempt span (for attempt-level delays). The span's start and end times bound the delay. It carries a single attribute:
+
+*   **`grpc.delay_type`**: the delay type, constant for the lifetime of the span.
+
+Each value of `grpc.delay_reason` (the initial reason when the span opens, and every subsequent change) is recorded as a span event. Tracing backends can programmatically parse these events, which conform to the following schema:
+
+```json
+{
+  "name": "Delay state transition",
+  "attributes": {
+    "grpc.delay_reason": "string (the current granular state description)"
+  }
+}
+```
+
+### Call Tracer API Changes
+
+The channel records delays by calling new methods on the call tracer. The methods come in two scopes, mirroring the two delay levels:
+
+| Method | Scope | Called when |
+|---|---|---|
+| `recordCallDelayStart(delay_type, reason)` | call | a call-level delay begins (or the `delay_type` changes) |
+| `recordCallDelayReasonChanged(reason)` | call | the reason changes within the same `delay_type` |
+| `recordCallDelayEnd()` | call | the call-level delay resolves |
+| `recordAttemptDelayStart(delay_type, reason)` | attempt | an attempt-level delay begins (or the `delay_type` changes) |
+| `recordAttemptDelayReasonChanged(reason)` | attempt | the reason changes within the same `delay_type` |
+| `recordAttemptDelayEnd()` | attempt | the attempt-level delay resolves |
+
+**Caller (channel) responsibilities.** The channel detects when a delay begins and ends, chooses the `delay_type` and `delay_reason`, and calls `Start` when a `delay_type` first appears or changes, `ReasonChanged` when only the reason changes, and `End` when the wait resolves. The scope — and therefore which histogram the delay is recorded to (see [Metric Schema](#metric-schema)) — is chosen by whether the channel calls the method on the call-scoped or the attempt-scoped tracer.
+
+**Call tracer (telemetry plugin) responsibilities.** On `Start`, the plugin opens the `Delay` span (see [Tracing Schema](#tracing-schema)) and begins timing. On `ReasonChanged`, it adds a `Delay state transition` event. On `End`, it closes the span and records the elapsed duration to the corresponding histogram. The plugin owns timing, so the `End` methods carry no duration argument.
+
+**Cancellation and deadlines.** The channel already notifies the call tracer when an RPC is cancelled or reaches its deadline. If a delay is open at that point, the call tracer automatically terminates it — closing the span and recording the partial duration — so the channel does not need to explicitly end open delays on these paths.
+
+**Per-language binding.** The six operations bind onto each runtime's existing telemetry types:
+
+*   **Go**: new call-scoped and attempt-scoped tracers in gRPC-Go's new stats-handler API. A new API is required because the V1 `stats.Handler` is attempt-scoped only and cannot host a call-level hook.
+*   **Java**: new methods on the existing `ClientStreamTracer` (attempt scope) and `ClientStreamTracer.Factory` (call scope).
+*   **C++ (Core)**: new methods on the call and attempt tracer interfaces.
+
+### Resolver Delays
+
+The channel records a call-level delay of type **`resolving`** while an RPC is blocked waiting for name resolution. When an RPC is sent while the channel has not yet received its first resolver result, the channel calls `recordCallDelayStart("resolving", reason)` on the call tracer; when the resolver delivers its first result and the RPC can proceed, the channel calls `recordCallDelayEnd()`. If resolution has already completed by the time the RPC is sent, no delay is recorded.
+
+Example reason: waiting on the initial DNS query (e.g. `"waiting for DNS query to complete for target example.com"`).
+
+### LB Pick Delays
+
+Attempt-level delays occur while an attempt waits for a load balancing pick to select a ready connection. Most delay types and reasons are generated by the LB policies themselves; two are synthesized by the channel.
+
+#### LB Picker API Changes
+
+When a picker cannot return a ready connection, it defers the pick. Two values are added to the pick-result type each runtime already returns, populated on the deferred path:
+
+*   `delay_type`: the attempt-level delay type (e.g. `"connecting"`).
+*   `delay_reason`: the free-form reason.
+
+The channel reads these where it already handles a deferred pick; no new return channel and no pick-loop restructuring are introduced. The fields live on:
+
+*   **Go**: `balancer.PickResult` (deferred pick = the `ErrNoSubConnAvailable` return).
+*   **Java**: `PickResult` (deferred pick = `PickResult.withNoResult()`).
+*   **C++ (Core)**: the `PickResult::Queue` variant.
+
+The delay types and example reasons generated by each LB policy follow. These examples are non-exhaustive; implementations are encouraged to append additional debug details to the reason.
+
+##### `pick_first` and `round_robin`
+
+Generate `delay_type = "connecting"`. Example reasons:
+
+*   Subchannel is `IDLE`, triggering a new connection attempt (e.g. `"subchannel was idle, triggering connection attempt"`).
+*   TCP/TLS handshake in progress, optionally with the remote address (e.g. `"subchannel connecting: TCP handshake in progress to 192.168.1.50:8080"`). For dualstack targets, the connection attempts across address families follow [gRFC A61][A61].
+*   Transport connected, waiting for the initial Out-of-Band health check to return `SERVING`.
+*   The target subchannel has not yet been created or resolved.
+*   `round_robin`: waiting for any configured subchannel to become ready (the reason can list the subchannels being attempted).
+
+##### `weighted_round_robin`
+
+Generates `delay_type = "connecting"`; waiting for its subchannels to become ready and report load.
+
+##### `ring_hash`
+
+Generates `delay_type = "connecting"`; the hash ring is waiting for the target ring nodes to connect (the reason can list the specific nodes being attempted).
+
+##### `xds_override_host`
+
+Generates `delay_type = "connecting"`; attempting to connect to a specific overridden host that is not yet ready. This policy implements stateful session affinity, per [gRFC A55][A55], [gRFC A60][A60], and [gRFC A75][A75].
+
+##### `priority`
+
+Prepends its **numeric priority** to the child's `delay_type`, producing composed values such as `"0:connecting"`. Priority policies can be nested (a priority policy's child is itself a priority policy), in which case each level prepends its own numeric priority and the prefixes stack — e.g. `"0:1:connecting"`. On failover — e.g. priority `0` enters `TRANSIENT_FAILURE` and the policy moves to priority `1` — the `delay_type` changes (`"0:connecting"` → `"1:connecting"`), which ends the current delay and starts a new one; the reason records the failover (which can include the child policy name and the failure cause, e.g. `"failing over to priority 1 (child 'tier-1-backup'); priority 0 failed: connection timeout"`). See [gRFC A56][A56].
+
+##### `rls`
+
+Generates `delay_type = "rls_lookup_pending"` while an RPC is blocked on a control-plane lookup (a cache miss). The reason can include the RLS server target or cache keys (e.g. `"Route Lookup Service query pending on rls-server:8080"`). For picks that are not blocked on a lookup, it forwards the child's `delay_type` unmodified. *(The RLS LB policy is not a public API and is not covered by any gRFC.)*
+
+##### `cds`
+
+Generates `delay_type = "cds_dynamic_discovery"` while waiting for a dynamic CDS cluster resource definition. The reason can include the targeted cluster name (e.g. `"waiting for CDS resource definition for cluster cluster_abc"`).
+
+##### `xds_cluster_manager` and `weighted_target`
+
+These pass-through container policies do not modify the metric `delay_type`; they forward the child's value. They may add their own structural details (such as the target cluster name or weight group) to the `delay_reason`.
+
+#### Channel Behavior for LB Pick Delays
+
+For picker-generated delays, the channel reads the deferred pick's `delay_type` and `delay_reason` and drives the call tracer per the [Call Tracer API](#call-tracer-api-changes): `Start` when the `delay_type` first appears or changes, `ReasonChanged` when only the reason changes, and `End` when a pick assigns a ready subchannel.
+
+The channel additionally synthesizes two attempt-level delay types itself, keeping pickers ignorant of `wait_for_ready` semantics and transport-level races:
+
+*   **`picker_failing_with_wait_for_ready`**: When the picker returns a failing result (an error other than "no connection available") and the RPC is `wait_for_ready`, the channel queues the RPC and records this delay type, with the picker's error as the reason. (If the RPC is not `wait_for_ready`, it fails immediately and no delay is recorded.) The delay ends when a subsequent picker assigns a ready subchannel; if a queued RPC continues to see errors, the channel updates the reason. If the RPC is cancelled or reaches its deadline while queued, the call tracer terminates the open delay automatically.
+
+*   **`subchannel_state_mismatch`**: When the picker returns a ready subchannel but it has transitioned out of `READY` before the RPC can use it (a race before the picker is updated), the channel re-queues the RPC on the same attempt and records this delay type. It waits for the next picker and re-picks; no new attempt is created. The delay ends when a re-pick assigns a subchannel that is actually ready.
+
+## Rationale
+
+**Call vs. attempt metrics.** We split metrics into two histograms to differentiate channel-initialization bottlenecks (name resolution) from per-attempt routing bottlenecks (LB pick and connection). Combining them would obscure whether a delay occurred before or during connection establishment.
+
+**Child spans vs. events.** We use a child span per delay rather than attaching events to the parent RPC span because it gives better flame-graph isolation in tracing backends, especially when delays are long or when multiple attempts are made (hedging or retries).
+
+**Free-form `delay_reason`.** We allow unconstrained debug strings for `delay_reason` rather than bounded enum tokens. This risks higher cardinality in tracing backends but lets raw IP addresses, subchannel targets, and connection error messages be embedded directly in the trace. The metric label (`grpc.delay_type`) remains strictly bounded to keep metric cardinality low.
+
+**Channel-synthesized delays.** We implement `picker_failing_with_wait_for_ready` and `subchannel_state_mismatch` in the channel rather than as picker-generated types. This keeps leaf pickers ignorant of `wait_for_ready` semantics and transport-level races: the picker reports only its current state, and the channel decides queueing behavior.
+
+## Implementation
+
+We will implement this in Go, Java, and C++ (Core).
+
+[A66]: A66-otel-stats.md
+[A72]: A72-open-telemetry-tracing.md
+[A56]: A56-priority-lb-policy.md
+[A28]: A28-xds-traffic-splitting-and-routing.md
+[A61]: A61-IPv4-IPv6-dualstack-backends.md
+[A55]: A55-xds-stateful-session-affinity.md
+[A60]: A60-xds-stateful-session-affinity-weighted-clusters.md
+[A75]: A75-xds-aggregate-cluster-behavior-fixes.md