fix(bigtable): AFE picker latency signal — subtract poolWait and compute TransportLatency = wire − backend at source - #20281
Conversation
SessionPoolImpl.Invoke fed the full user-visible latency (poolWait +
wire + backend) into noteVRpcOutcome, which routes to
sessionList.RecordVRpcOutcome and updates the per-AFE e2eEwma and
transportEwma. The AFE picker's cost signal was contaminated by
pool-side queue contention that the AFE itself had nothing to do
with.
Concrete impact observed in the sushanb-uc1 sandbox:
Slow vRPC: Latency=13.947ms PoolWait=12.57ms Transport=1.366ms
Backend=431µs
AFE 222545b8... wire+AFE actual = 935µs
e2eEwma got fed 13.947ms ← 15× overcharge
Under sustained saturation, every AFE picked during a queue spike
gets a 10-30ms sample fed into its EWMA. LeastLatencyPicker then
steers traffic AWAY from those AFEs on the next tick, and over time
every AFE's EWMA drifts upward as saturation events poison the
signal — the picker becomes a noise mirror instead of a routing
oracle.
Fix: compute rpcLatency = latency − poolWait inside the deferred
noteVRpcOutcome call and pass it instead of raw latency. Sessionz's
TotalLatency histogram is unaffected (still records the raw
user-visible latency at session_pool.go:552 — that's the correct
metric for user-visible p95/p99).
Defensive: clamp rpcLatency to 0 on the (theoretically unreachable)
edge where poolWait > latency, so a clock-skew glitch can't feed a
negative sample into PeakEwma.
No signature change to noteVRpcOutcome or RecordVRpcOutcome —
caller-side one-line fix.
There was a problem hiding this comment.
Code Review
This pull request updates the Invoke method in SessionPoolImpl to calculate and pass rpcLatency (defined as latency - poolWait) instead of raw latency to noteVRpcOutcome. This prevents pool-side queue contention from skewing the picker's EWMA metrics during saturation. A defensive check is also introduced to ensure rpcLatency remains non-negative. There are no review comments, so no feedback is provided.
…y; add computed TransportLatency The old field name lied vs its doc comment. The value set at session_vrpc.go:260 was time.Since(SentAt) — Send→Recv wall time INCLUDING server backend. The doc claimed it was "AttemptLatency - BackendLatency" (the AFE-attributable portion, which subtracts backend). Two different quantities under one name; downstream consumers (sessionz Transport histogram, OTel transport_latencies, per-AFE picker) were all reading the wire-with- backend value while thinking it was pure wire+AFE. Split into two fields that match their names: - WireLatency: client-measured Send→Recv wall time. Includes BackendLatency. Populated at source in Session.processResult. - TransportLatency: WireLatency − BackendLatency. Populated in SessionPoolImpl.Invoke after BackendLatency is known. This is what the sessionz Transport histogram, OTel transport_latencies, and any AFE picker cost signal should consume. wire ≥ backend by construction (wire = RTT + backend + decode) so subtraction is unconditional; the existing `> 0` guard at the histogram/OTel record sites catches the vanishingly-rare clock-skew edge. Together with the prior commit on this branch (feed rpcLatency = latency − poolWait into RecordVRpcOutcome), the AFE picker now sees: e2eEwma ← rpcLatency (RPC-only, no pool contention) transportEwma ← rpcLatency − backend (wire + AFE, no server time) which is what the picker's cost model has always assumed but the inputs never actually delivered.
…t WireLatency field Simpler shape: processResult holds a local wire = time.Since(SentAt) just long enough to derive TransportLatency = wire − backend when Stats.BackendLatency is present. No separate WireLatency field on InvokeResult — nothing consumed it, and keeping it around would just be a redundant intermediate that callers might accidentally mistake for the wire+AFE metric they actually want. wire ≥ backend by construction (wire = RTT + backend + decode) so subtraction is unconditional at the site. Downstream `> 0` gate at session_pool.go's histogram + OTel record sites now only serves the "Stats absent" case (TransportLatency stays at zero-value when the server didn't populate Stats).
| // established-session vRPCs. | ||
| RPCIDOnSession int64 | ||
| // TransportLatency = AttemptLatency - BackendLatency. | ||
| // TransportLatency is the AFE-attributable overhead — the |
There was a problem hiding this comment.
just say TransportLatency = Wire Latency - BackendLatency
There was a problem hiding this comment.
Done in cf81566447 — trimmed to one-liner.
| // The AFE-wake fires from the response handler BEFORE this defer runs, | ||
| // so pickers may see pre-update EWMAs for one tick — accepted lag. | ||
| // | ||
| // noteVRpcOutcome is fed rpcLatency (latency − poolWait), NOT the |
There was a problem hiding this comment.
just say noteVRPCOutcome feeds (e2e latency) not including CheckoutSession
There was a problem hiding this comment.
Done in cf81566447 — one-liner + inlined latency-poolWait in the defer.
| s.recordLatency(res.resp.Stats.BackendLatency.AsDuration()) | ||
| backend := res.resp.Stats.BackendLatency.AsDuration() | ||
| s.recordLatency(backend) | ||
| // TransportLatency = wire − backend = AFE-attributable |
There was a problem hiding this comment.
no nneed for comment.
There was a problem hiding this comment.
I would just TransporrtLatncy = wire- (if backend latency is set)
There was a problem hiding this comment.
Done in cf81566447 — comment removed.
There was a problem hiding this comment.
Done in cf81566447 — dropped the rationale comment; the if ... BackendLatency != nil branch already guards the set-only-when-backend-known case.
- invoke_result.go: one-liner doc "TransportLatency = WireLatency − BackendLatency". - session_pool.go: one-liner "noteVRpcOutcome feeds e2e latency (not including CheckoutSession)"; inline `latency-poolWait` in the defer, drop the defensive < 0 clamp. - session_vrpc.go: drop the local-var doc and the wire-≥-backend rationale. No behavior change.
Larger cold-start footprint so the pool carries more traffic during the first-poll warm-up window before ClientConfigurationManager reshapes it via SessionClientConfiguration. Doc comment already notes the constant is only a bootstrap value; the server-driven reshape is unchanged.
🤖 I have created a release *beep* *boop* --- ## [1.52.0](bigtable/v1.51.0...bigtable/v1.52.0) (2026-08-03) ### Features * **bigtable:** Add AFE picker (Simple / LeastInFlight / LeastLatency) ([#20204](#20204)) ([bcbf714](bcbf714)) * **bigtable:** Add ClientConfig.DisableSession to opt out of session backend ([#20297](#20297)) ([7ee5e44](7ee5e44)) * **bigtable:** Add getClientConfigDirectAccessChecker for session pools ([#20209](#20209)) ([3b8d30a](3b8d30a)) * **bigtable:** Add NoOpChannelPrimer for session channel pools ([#20208](#20208)) ([d055a8a](d055a8a)) * **bigtable:** Add per-AFE sessionList for the two-tier session pool ([#20224](#20224)) ([dbf0c3f](dbf0c3f)) * **bigtable:** Add protoRowToRow conversion helper for TableShim ([#20257](#20257)) ([1297143](1297143)) * **bigtable:** Add Session debug surface (observability fields + methods) ([#20211](#20211)) ([d8d3e16](d8d3e16)) * **bigtable:** Add Session lifecycle (Start, Close, ForceClose, readLoop, heartBeatLoop) ([#20215](#20215)) ([b9e53c6](b9e53c6)) * **bigtable:** Add Session struct + state machine ([#20117](#20117)) ([09acbb3](09acbb3)) * **bigtable:** Add session.Config.EnableDebug to gate sessionz debug state ([#20247](#20247)) ([ce74c31](ce74c31)) * **bigtable:** Add SessionClient + SessionTable + lazyPool ([#20228](#20228)) ([ab2c96c](ab2c96c)) * **bigtable:** Add SessionPoolImpl (two-tier pool + scaling + debug) ([#20225](#20225)) ([683eda8](683eda8)) * **bigtable:** Rename session pool display to <resource-id>-<PERM> ([#20248](#20248)) ([35e146e](35e146e)) * **bigtable:** Route Client.Open()-returned *Table through the Diverter ([#20273](#20273)) ([2b81c7d](2b81c7d)) * **bigtable:** State-based classification for abnormal session close ([#20243](#20243)) ([f2905b7](f2905b7)) * **bigtable:** TableShim fallback to classic on session UNIMPLEMENTED ([#20269](#20269)) ([36540af](36540af)) * **bigtable:** TTL-on-idle cache for per-resource session.TableAPI ([#20263](#20263)) ([00b2a49](00b2a49)) * **bigtable:** Wire Diverter on Client and route Open* via TableShim ([#20256](#20256)) ([b32fbd7](b32fbd7)) ### Bug Fixes * **bigtable:** AFE picker latency signal — subtract poolWait and compute TransportLatency = wire − backend at source ([#20281](#20281)) ([bb8c4d5](bb8c4d5)) * **bigtable:** Guard NewStream OnFinish against grpc-go double-fire ([#20295](#20295)) ([b51da29](b51da29)) * **bigtable:** Real per-resource pool teardown on sessionTable.Close + cache close-race gate ([#20264](#20264)) ([599aea9](599aea9)) * **bigtable:** Session.durations / session.uptime — set explicit histogram bucket boundaries ([#20276](#20276)) ([97eee22](97eee22)) * **bigtable:** SessionTableHandle self-heals across cache eviction ([#20296](#20296)) ([0dd98cd](0dd98cd)) * **bigtable:** Translate ctx errors to gRPC status on session vRPC ([#20299](#20299)) ([0f3b2a5](0f3b2a5)) * **bigtable:** Treat PingAndWarm NotFound as a successful prime ([#20219](#20219)) ([a1557ad](a1557ad)) ### Performance Improvements * **bigtable:** Delete periodic Tick loop; sizing is event-driven ([#20285](#20285)) ([2c096bd](2c096bd)) * **bigtable:** Drop pick_lost_race debug tag from CheckoutSession hot path ([#20280](#20280)) ([bd0e400](bd0e400)) --- This PR was generated with [Release Please](https://github.com/googleapis/release-please). See [documentation](https://github.com/googleapis/release-please#release-please). Co-authored-by: release-please[bot] <55107282+release-please[bot]@users.noreply.github.com>
Summary
Two related fixes that make the AFE picker's cost signal reflect only what the AFE actually contributed. Before this PR the picker was reading a value that mixed in pool-side queue contention AND server-side backend processing — neither of which the AFE has any influence over.
Fix 1 — Subtract
poolWaitfrom the AFE picker latency feedSessionPoolImpl.Invokefed the full user-visible latency(
poolWait + wire + backend) intonoteVRpcOutcome, which routes tosessionList.RecordVRpcOutcomeand updates the per-AFEe2eEwma/transportEwma. Passing rawlatencypoisoned the picker: undersaturation every AFE that happened to be picked during a queue spike
got a 10-30ms sample fed into its EWMA even though the AFE actually
served a 1ms wire+backend round-trip.
Fix: compute
rpcLatency := latency − poolWaitinside the deferrednoteVRpcOutcomecall and pass it instead of rawlatency.Sessionz's
TotalLatencyhistogram is unaffected (still records theraw user-visible latency).
Fix 2 — Compute
TransportLatency = wire − backendat sourceInvokeResult.TransportLatencywas set totime.Since(SentAt)— theSend→Recv wall clock that INCLUDES the server's
BackendLatency.The doc comment claimed it was
AttemptLatency − BackendLatency(theAFE-attributable portion). Two different quantities under one name;
downstream consumers (sessionz Transport histogram, OTel
transport_latencies metric, per-AFE picker) were all reading the
wire-plus-backend value while thinking it was pure wire+AFE.
Fix: derive
TransportLatency = wire − backendinSession.processResultonce BackendLatency is available.wire ≥ backendby construction (
wire = RTT + backend + decode) so subtraction isunconditional. The
if result.TransportLatency > 0gate at thehistogram / OTel record sites remains — it now only handles the
"Stats absent" case (server didn't populate Stats, TransportLatency
stays at zero-value).
Sample: sushanb-uc1 sandbox row (pre-fix)
Post-fix the same row would feed the AFE picker:
Commits (three)
8d7101082bpoolWaitfrom AFE picker latency feedcd1fefa3f9TransportLatency → WireLatency; add derivedTransportLatencyin the pool3f58926da8WireLatencyfield entirely; computeTransportLatencyat source with localwirevarCommits are chronological; the net diff is what would land after squash.
API surface
InvokeResult.TransportLatencyunchanged as an exported field; semantics corrected to match its doc.noteVRpcOutcome/RecordVRpcOutcomesignatures unchanged.SlowVRpcEventunchanged.TotalLatencyhistogram atsession_pool.gostill records raw user-visiblelatency(correct for user-facing p95/p99).Test plan
go build ./...clean.go vet ./internal/transport/clean.go test -race -count=1 -short -timeout=120s ./internal/transport/passes.TransportLatencyunaffected — value is now the correct wire+AFE overhead they always expected.Post-merge verification (live smoke)
After merging + a warm-up window (~30s for existing peak-EWMAs to decay), expect on afez: