fix(bigtable): eliminate stats-handler MD race in internal/metrics tracer#20158
Conversation
…te race
The metrics StatsHandler stored ev.Header / ev.Trailer on the current
attempt from HandleRPC's InHeader/InTrailer branches and re-read them
from the End branch. gRPC's stats.Handler contract does not guarantee
all three events dispatch from the same goroutine — csAttempt.finish
(stream.go:1251) fires End on the caller goroutine under cancel /
deadline / GOAWAY, while the transport reader is still processing the
trailer frame. TestIntegration_Presidents caught the interleave and
produced:
WARNING: DATA RACE
Read at ... bigtable/internal/metrics/tracer.go:867
Write at ... bigtable/internal/metrics/tracer.go:859
Write at ... grpc/metadata.MD.Copy (operateHeaders)
Read at ... extractLocation -> metadata.MD.Get
Also implicated in the same nightly's FlakyBot P1 burst against
30b1dfa (see googleapis#20147, googleapis#20148, googleapis#20150, googleapis#20151, googleapis#20152).
Fix hoists the extraction into a new ingestMetadata helper that runs
on the InHeader/InTrailer dispatch itself, storing already-parsed
primitives (clusterID, zoneID, transportType/Region/Zone/SubZone,
serverLatency) on the current attempt. End then does no MD access —
it reads only the primitives ingestMetadata already wrote, so the raw
metadata.MD map is never touched cross-goroutine.
Serializes the primitive-field writes/reads with a per-Tracer
sync.Mutex — the mutex is only held around field reads/writes, never
across metric.Record calls, and per-attempt contention is limited to
the rare cancel/deadline race window. CreateTracer now returns *Tracer
(instead of Tracer) so the embedded mutex isn't copied out of the
factory.
RecordAttemptCompletionWithMetadata stays as a thin adapter for the
downstream session/vRPC path. RecordAttemptCompletion's signature
drops the two MD params — they're never needed once ingestMetadata
has run — and its former extractLocation / extractPeerInfo /
extractServerLatency blocks are gone.
Adds tracer_race_test.go with a deterministic regression test:
concurrently fires InTrailer and End on the same tracer across
different goroutines for 200 iterations, must pass under -race.
Verified to trip the race on the pre-fix code and pass on the fix.
product-auto-label
Bot
added
the
api: bigtable
![gemini-code-assist[bot]](https://avatars.githubusercontent.com/in/956858?s=60&v=4){kind=small}
There was a problem hiding this comment.
Code Review
This pull request addresses data races in the Bigtable metrics tracer by introducing a mutex to serialize access to the tracer and refactoring metadata extraction. Instead of passing raw metadata to RecordAttemptCompletion, a new ingestMetadata method parses and stashes metadata as primitive fields on the transport reader goroutine, making it safe to race with stats.End. A concurrent race test is also added. Feedback points out a bug in ingestMetadata where locationExtracted is set to true even if no location was found in the headers, which would incorrectly prevent fallback extraction from trailers.
| if !a.locationExtracted { | ||
| if clusterID, zoneID, err := extractLocation(headerMD, trailerMD); err == nil { | ||
| // Don't overwrite a cluster/zone that the vRPC path has | ||
| // already populated (SessionTable sets these directly from | ||
| // the ClusterInformation payload); only fill in if the | ||
| // attempt's value is missing or the sentinel default. | ||
| // lastClusterID / lastZoneID always track the freshest real | ||
| // value so operation-level metrics get a sensible fallback. | ||
| if clusterID != "" { | ||
| if existing := a.clusterID; existing == "" || existing == defaultCluster { | ||
| a.SetClusterID(clusterID) | ||
| } | ||
| if clusterID != defaultCluster { | ||
| mt.currOp.lastClusterID = clusterID | ||
| } | ||
| } | ||
| if zoneID != "" { | ||
| if existing := a.zoneID; existing == "" || existing == defaultZone { | ||
| a.SetZoneID(zoneID) | ||
| } | ||
| if zoneID != defaultZone { | ||
| mt.currOp.lastZoneID = zoneID | ||
| } | ||
| } | ||
| a.locationExtracted = true | ||
| } | ||
| } |
There was a problem hiding this comment.
If extractLocation is called on InHeader and the header does not contain the location metadata, it will likely return "", "", nil (since missing optional metadata is not a parsing error). In this case, a.locationExtracted is set to true even though no location was actually extracted. Consequently, when InTrailer is processed, the check !a.locationExtracted will be false, and the code will skip extracting the location from the trailer, causing the location to be missed entirely.
To prevent this, a.locationExtracted should only be set to true if a non-empty clusterID or zoneID was successfully extracted.
if !a.locationExtracted {
if clusterID, zoneID, err := extractLocation(headerMD, trailerMD); err == nil {
// Don't overwrite a cluster/zone that the vRPC path has
// already populated (SessionTable sets these directly from
// the ClusterInformation payload); only fill in if the
// attempt's value is missing or the sentinel default.
// lastClusterID / lastZoneID always track the freshest real
// value so operation-level metrics get a sensible fallback.
if clusterID != "" {
if existing := a.clusterID; existing == "" || existing == defaultCluster {
a.SetClusterID(clusterID)
}
if clusterID != defaultCluster {
mt.currOp.lastClusterID = clusterID
}
}
if zoneID != "" {
if existing := a.zoneID; existing == "" || existing == defaultZone {
a.SetZoneID(zoneID)
}
if zoneID != defaultZone {
mt.currOp.lastZoneID = zoneID
}
}
if clusterID != "" || zoneID != "" {
a.locationExtracted = true
}
}
}There was a problem hiding this comment.
False alarm, I think — the premise "missing optional metadata is not a parsing error" doesn't match extractLocation's actual contract.
At bigtable/internal/metrics/util.go:168-170:
if len(locationMetadata) < 1 {
return defaultCluster, defaultZone, errors.New("failed to get location metadata")
}When LocationMDKey is absent from the (non-nil) MD bag passed in, extractLocation returns a non-nil error. ingestMetadata gates on if err == nil, so on the (headerMD, nil) call where the header lacks the key, we get the error, skip the locationExtracted = true assignment, and the subsequent (nil, trailerMD) call from InTrailer still has a full chance to populate. That's exactly the header-preferred-trailer-fallback behaviour the old single-call extractLocation(headerMD, trailerMD) had.
The other two extractors follow the same shape:
extractPeerInforeturns(nil, nil)when the key is absent → we gatepeerInfoExtracted = trueonpeerInfo != nil, so trailer still gets its shot.extractServerLatencyreturns(0, nil)when absent → the outerif a.serverLatency == 0gate keeps re-trying until a real value lands.
The scenario the suggested change would guard against (header has the key but the marshalled ResponseParams decodes to empty cluster+zone) is a server-side pathology that wouldn't reach the trailer either, so the extra gate wouldn't recover anything real. Leaving as-is.
There was a problem hiding this comment.
Correction — my earlier "False alarm" was itself wrong, though not in the direction the bot flagged.
The bot's scenario (locationExtracted = true incorrectly latched on "") doesn't reproduce, for the reason I gave: extractLocation returns a non-nil error when LocationMDKey is absent, so the err == nil gate blocks the latch. But the same gate ALSO blocked the stamping of the (defaultCluster, defaultZone) sentinel that extractLocation returns on error — and RecordAttemptCompletion's connectivity_error_count check reads currAttempt.clusterID == defaultCluster as the "no server-side signals" marker. With the gate, no-header attempts left clusterID as ""; the check evaluated "" == "<unspecified>" → false; the counter never incremented. TestConnectivityErrorCount in bigtable/metrics_test.go caught it:
metrics_test.go:592: Metric connectivity_error_count for status Unavailable:
got cumulative value 0, want 1
Fixed in 05d910a: drop the err == nil gate around the stamping block (so the sentinel is applied on missing-header attempts, matching pre-race-fix behaviour), and set a.locationExtracted = true only when err == nil (so a later InTrailer carrying real data can still overwrite the sentinel on the same attempt). This also happens to be closer in spirit to the bot's suggestion — the latch is now guarded — just guarded on err == nil rather than clusterID != "", because the sentinel non-empty clusterID is load-bearing downstream.
…missing headers
ingestMetadata gated the entire extractLocation stamping block on
err == nil. extractLocation returns (defaultCluster, defaultZone, err)
when the LocationMDKey header is absent, and RecordAttemptCompletion's
connectivity_error_count check reads
isLocationEmpty := currAttempt.clusterID == defaultCluster
as the "no server-side signals" marker. With the gate, an attempt
without location headers left clusterID as "" (fresh AttemptTracer zero
value); the check evaluated "" == "<unspecified>" → false, and the
counter never incremented. TestConnectivityErrorCount caught this:
metrics_test.go:592: Metric connectivity_error_count for status
Unavailable: got cumulative value 0, want 1
Fix drops the err == nil gate around the stamping block so the
sentinel is applied on missing-header attempts (matching the pre-race-
fix behaviour), and only sets locationExtracted = true when err == nil
so a later InTrailer carrying real data can still overwrite the
sentinel on the same attempt.
Verified:
go test -run TestConnectivityErrorCount -count=1 ./bigtable/ → pass
go test -race -count=3 -run TestHandleRPC_ConcurrentInTrailerAndEnd_NoRace
./bigtable/internal/metrics/ → pass
go test -race -count=1 ./bigtable/internal/metrics/... → pass
| // those primitives, so stats.End (which may dispatch on a different | ||
| // goroutine under cancel/deadline/GOAWAY) never touches the raw MD. | ||
| // | ||
| // The old code stored ev.Header / ev.Trailer on the attempt and re-read |
There was a problem hiding this comment.
nit: remove the document about the old code
There was a problem hiding this comment.
Done in 4a68e10 — removed the paragraph so the doc reads forward-only.
| // didn't carry a server-timing value (serverLatency still 0), fall | ||
| // back to the client-observed T4-T7 span. Runs here rather than in | ||
| // ingestMetadata because the T4-T7 window closes only at End. | ||
| if mt.currOp.currAttempt.serverLatency == 0 && mt.currOp.currAttempt.t4t7Tracker != nil { |
There was a problem hiding this comment.
Sorry I didn't catch this earlier, but I don't think we need / want a t4t7Traacker fallback? It's not capturing the same value as the server t4t7. The gfe server latency is strictly measuring the server side, and doesn't include the latency between application to GFE. On the other hand t4t7Tracker mixes up both server side latencies and the network latencies between the app and GFE.
There was a problem hiding this comment.
yeah, we use t4t7Tracker for directpath (if gfe sends no header).
There was a problem hiding this comment.
Youre right that the two arent measuring the same slice (T4-T7 includes the app↔GFE round trip, GFEs gfet4t7 doesnt), but Id like to keep the fallback for now — this is a resurrection of behaviour that was in the tracer before the race fix, and TestFallbackT4T7Latency (bigtable/metrics_test.go:1163) explicitly pins the "server-timing header omitted → server_latencies still gets a value from T4-T7" contract with a 50 ms epsilon comparison.
The intent (as I read the original) is: when the server doesnt emit server-timing (fake servers in tests, non-GFE proxies, older backends), fall back to something rather than dropping the whole server_latencies metric for that attempt. The value is coarser but its still bounded above by the actual server-side latency plus network round-trip, which is more useful than a zero-count series.
If youd rather delete the fallback + the test as a follow-up (semantic-purity win, lose the fake-server smoke-signal), Im happy to do that in a separate PR so this one stays scoped to the race fix. Let me know which you prefer.
There was a problem hiding this comment.
Reversing course — removed the whole t4t7Tracker in ef145b2 (not just the fallback branch). Deleted the context key, the AttemptTracer field, the struct+methods, the TagRPC/HandleRPC hooks, and TestFallbackT4T7Latency. server_latencies now stays unrecorded on attempts where the server didn't emit server-timing — cleaner semantic than the mixed server+network value.
3 files changed, 9 insertions(+), 187 deletions(-). Passes race + short suites.
- Drop the paragraph in ingestMetadata's doc that recounted the pre- race-fix code (stashed MD on the attempt, csAttempt.finish vs transport reader collision, issue googleapis#20152 link). The comment now reads forward-only. - Add a nested comment on the peerInfoExtracted latch explaining why the gate is peerInfo != nil rather than the err == nil pattern used for locationExtracted: extractPeerInfo returns (nil, nil) on missing header (not an error), so gating on err == nil alone would latch on the header call and kill the trailer fallback. No behaviour change. Verified: go build ./... → clean go vet ./bigtable/internal/metrics/... → clean go test -race -count=1 ./bigtable/internal/metrics/... → pass
Per mutianf on PR review: the t4t7Tracker fallback wasn't measuring the same slice as GFE server_latencies. gfet4t7 is strictly server-side; the tracker's window (OutHeader → InHeader) also includes the app↔GFE round trip, so the fallback value was silently mixing server + network into what's supposed to be a server-only distribution. Delete the whole tracker plumbing rather than just the fallback so there's no dead code left behind: - tracer.go: drop t4t7ContextKey, AttemptTracer.t4t7Tracker field, t4t7Tracker struct + recordOutHeaderSent / recordInHeaderRecv / getLatencyMs methods, the fallback branch in RecordAttemptCompletion, StatsHandler.TagRPC installation, and the HandleRPC OutHeader/InHeader switch. Fix up the surrounding doc comments (StatsHandler, TagRPC) to stop referencing the tracker. - bigtable.go: update the "per-attempt metric setup" comment on the invoke wrapper to drop the t4t7Tracker reference. - metrics_test.go: remove TestFallbackT4T7Latency, which pinned the removed fallback via a fake server that omitted server-timing. server_latencies now stays unrecorded on attempts where the server didn't emit server-timing (the existing serverLatencyErr gate in RecordAttemptCompletion). That's the intended semantic — a zero-server-latency signal is better than a coarse mixed one. Verified: go build ./... → clean go vet ./... → clean go test -race -count=1 ./bigtable/internal/metrics/... → pass go test -short -run 'TestReadRowsMetrics|TestMetric|TestConnectivityErrorCount|TestClientBlockingLatency|TestRetryMetrics' ./bigtable/... → pass
|
@mutianf Addressed the review nits in two commits on top of 05d910a:
Verified: PTAL. |
The race-fix refactor moved extractServerLatency from End-time (in RecordAttemptCompletionWithMetadata) to the InHeader/InTrailer dispatches (in ingestMetadata). That closed the cross-goroutine race, but opened a new gap: if the stream aborts before any InHeader/InTrailer fires (pre-connect failure, DEADLINE_EXCEEDED before response, transport hangup), ingestMetadata never runs, so serverLatencyErr stays at its zero-value nil. RecordAttemptCompletion then sees serverLatencyErr == nil and records serverLatency=0. The pre-refactor code didn't hit this: RecordAttemptCompletionWith- Metadata unconditionally called extractServerLatency at End, which always stamped serverLatencyErr = err on a missing server-timing header. Add a serverLatency > 0 guard to the Record call so the aborted- stream case stays out of the distribution. This also silences the "server explicitly reported gfet4t7; dur=0" case, but a legit 0ms server latency is unrealistic — the truthful zero was a small noise source not worth preserving. Verified: go build ./... → clean go vet ./... → clean go test -race -count=1 ./bigtable/internal/metrics/... → pass go test -short -run 'TestReadRowsMetrics|TestMetric|TestConnectivityErrorCount|TestClientBlockingLatency|TestRetryMetrics' ./bigtable/... → pass
|
Follow-up in b4cc226: caught an edge case while auditing the t4t7 removal. The refactor moved Fix: gate the |
…cy > 0" This reverts b4cc226. Keeping the single serverLatencyErr == nil gate per review discussion — the aborted-stream edge case (ingestMetadata never fires, serverLatencyErr stays at zero-value nil) is being deferred to a separate follow-up rather than resolved with the value-based guard.
2 participants
Summary
HandleRPC'sstats.Endbranch and into a newingestMetadatahelper that runs on theInHeader/InTrailerdispatches.Endnow reads only already-parsed primitives — never the rawmetadata.MD— so the cross-goroutine race on the map is gone.Tracersync.Mutex. Only held around the field access, never acrossmetric.Recordcalls.CreateTracernow returns*Tracerso the embedded mutex isn't copied out of the factory.-raceregression test (tracer_race_test.go) that reproduced the failing interleave on the pre-fix code and passes cleanly on the fix.Race being fixed
Reported in the wild by the nightly integration suite; race dump captured from
TestIntegration_Presidents:Two follow-on races on the same run against the underlying
metadata.MDmap (MD.CopyinoperateHeadersvsMD.GetinextractLocation). All three came from the same design flaw:HandleRPCstoredev.Header/ev.Traileron the current attempt fromInHeader/InTrailer, then re-read them understats.End. gRPC'sstats.Handlercontract does not promiseInHeader → InTrailer → Enddispatch on a single goroutine — under cancel / deadline / GOAWAY,csAttempt.finish(google.golang.org/grpc@1.82.0/stream.go:1251) firesEndfrom the caller goroutine while the transport reader (http2_client.go:1650) is still processing the trailer frame.Also plausibly implicated in the FlakyBot P1 burst against
30b1dfa0dbon the same nightly (#20147, #20148, #20150, #20151, #20152), all of which are TestIntegration_* failures with no attached stack — the Sponge log is Google-internal, but the timing (all P1s stem from the same invocation, and the metrics refactor #20099 that introduced this pattern shipped six days earlier) strongly suggests the same underlying race.Design (why this exact fix)
Option A of the several considered — the alternatives were:
metadata.MD.GetinsideRecordAttemptCompletion. Fixes the primitive-field race but not the map-content race (gRPC's transport owns the map and mutates it insideoperateHeaders). Rejected.stats.End. Requires a gRPC-side change. Not viable short-term.Option A eliminates cross-goroutine access to the MD entirely — the raw map is read exactly once on the goroutine that received it, then dropped. The mutex only guards the small set of already-parsed primitive fields that
Endneeds to read.extractLocation/extractPeerInfo/extractServerLatencyall check header first then trailer, so passing one MD at a time (with thelocationExtracted/peerInfoExtractedbooleans + theserverLatency == 0gate) preserves the exact header-preferred-trailer-fallback behaviour.Test plan
go test -race -count=5 -run TestHandleRPC_ConcurrentInTrailerAndEnd_NoRace -timeout=120s ./bigtable/internal/metrics/— passes; same test tripped the race on the pre-fix code.go test -race -count=1 -timeout=120s ./bigtable/internal/metrics/...— full package suite passes under race.go vet ./...clean.go build ./...clean.