Skip to content

fix(bigtable): AFE picker latency signal — subtract poolWait and compute TransportLatency = wire − backend at source - #20281

Merged
sushanb merged 5 commits into
googleapis:mainfrom
sushanb:fix/bigtable-afe-ewma-exclude-pool-wait
Jul 31, 2026
Merged

fix(bigtable): AFE picker latency signal — subtract poolWait and compute TransportLatency = wire − backend at source#20281
sushanb merged 5 commits into
googleapis:mainfrom
sushanb:fix/bigtable-afe-ewma-exclude-pool-wait

Conversation

@sushanb

@sushanb sushanb commented Jul 31, 2026

Copy link
Copy Markdown
Contributor

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 poolWait from the AFE picker latency feed

SessionPoolImpl.Invoke fed the full user-visible latency
(poolWait + wire + backend) into noteVRpcOutcome, which routes to
sessionList.RecordVRpcOutcome and updates the per-AFE e2eEwma /
transportEwma. Passing raw latency poisoned the picker: under
saturation 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 − 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).

Fix 2 — Compute TransportLatency = wire − backend at source

InvokeResult.TransportLatency was set to time.Since(SentAt) — the
Send→Recv wall clock that INCLUDES the server's BackendLatency.
The doc comment claimed it was AttemptLatency − BackendLatency (the
AFE-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 − backend in
Session.processResult once BackendLatency is available. wire ≥ backend
by construction (wire = RTT + backend + decode) so subtraction is
unconditional. The if result.TransportLatency > 0 gate at the
histogram / 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)

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 (poolWait leak)
                 transportEwma got fed 1.366ms (still wire+backend, mislabeled)

Post-fix the same row would feed the AFE picker:

e2eEwma        ← rpcLatency = 1.377ms         (wire + backend, no pool)
transportEwma  ← rpcLatency − backend = 946µs (wire only, no backend)

Commits (three)

SHA Change
8d7101082b Fix 1: subtract poolWait from AFE picker latency feed
cd1fefa3f9 Rename TransportLatency → WireLatency; add derived TransportLatency in the pool
3f58926da8 Refactor: drop WireLatency field entirely; compute TransportLatency at source with local wire var

Commits are chronological; the net diff is what would land after squash.

API surface

  • InvokeResult.TransportLatency unchanged as an exported field; semantics corrected to match its doc.
  • noteVRpcOutcome / RecordVRpcOutcome signatures unchanged.
  • SlowVRpcEvent unchanged.
  • Sessionz TotalLatency histogram at session_pool.go still records raw user-visible latency (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.
  • Existing sessionz/afez/loadz consumers of TransportLatency unaffected — 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:

  • Transport EWMA drops from current 11-18ms range toward sub-2ms typical.
  • E2e EWMA drops from 13-90ms range toward sub-5ms typical (only true backend outliers should peak it now).
  • Spread across AFEs becomes a real signal of AFE-attributable health rather than pool-contention noise.

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.
@sushanb
sushanb requested review from a team as code owners July 31, 2026 16:53
@product-auto-label product-auto-label Bot added the api: bigtable Issues related to the Bigtable API. label Jul 31, 2026

@gemini-code-assist gemini-code-assist Bot left a comment

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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.

sushanb added 2 commits July 31, 2026 17:03
…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

Copy link
Copy Markdown
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

just say TransportLatency = Wire Latency - BackendLatency

Copy link
Copy Markdown
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Done in cf81566447 — trimmed to one-liner.

@sushanb sushanb changed the title fix(bigtable): subtract poolWait from AFE picker latency feed fix(bigtable): AFE picker latency signal — subtract poolWait and compute TransportLatency = wire − backend at source Jul 31, 2026
// 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

Copy link
Copy Markdown
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

just say noteVRPCOutcome feeds (e2e latency) not including CheckoutSession

Copy link
Copy Markdown
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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

Copy link
Copy Markdown
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

no nneed for comment.

Copy link
Copy Markdown
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I would just TransporrtLatncy = wire- (if backend latency is set)

Copy link
Copy Markdown
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Done in cf81566447 — comment removed.

Copy link
Copy Markdown
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Done in cf81566447 — dropped the rationale comment; the if ... BackendLatency != nil branch already guards the set-only-when-backend-known case.

sushanb added 2 commits July 31, 2026 17:14
- 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.
@sushanb
sushanb merged commit bb8c4d5 into googleapis:main Jul 31, 2026
19 checks passed
sushanb pushed a commit that referenced this pull request Aug 3, 2026
🤖 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
&lt;resource-id&gt;-&lt;PERM&gt;
([#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>
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

api: bigtable Issues related to the Bigtable API.

Projects

None yet

Development

Successfully merging this pull request may close these issues.

2 participants