diff --git a/cmd/cache-proxy/README.md b/cmd/cache-proxy/README.md index ff7fb2cb..cd2409f6 100644 --- a/cmd/cache-proxy/README.md +++ b/cmd/cache-proxy/README.md @@ -17,9 +17,16 @@ available, and forwards cache misses to origin object storage. | `CACHE_BLOCK_MODE` | `off` | `on` enables block-aligned caching; any other value (including unset) keeps the legacy exact-range path. See [Block-aligned mode](#block-aligned-mode). | | `CACHE_BLOCK_SIZE_BYTES` | `8388608` (8 MiB) | Fixed block size for block-aligned mode. Ignored when block mode is off. | | `CACHE_BLOCK_MAX_SPAN_BLOCKS` | `8` | Max blocks coalesced into one origin range fetch. Ignored when block mode is off. | +| `CACHE_PEER_FETCH_MAX_CONCURRENCY` | `32` | Process-wide limit for admitted peer lookup/body transfers. Each request is additionally limited to 8 peer fills. Must be positive. | +| `CACHE_PEER_FETCH_MAX_BYTES` | `CACHE_PEER_FETCH_MAX_CONCURRENCY × CACHE_BLOCK_SIZE_BYTES` | Process-wide byte reservations for admitted peer transfers (256 MiB with the source defaults; 32 MiB with 1 MiB blocks at concurrency 32). Must be positive. | | `OTEL_EXPORTER_OTLP_TRACES_ENDPOINT` / `DUCKGRES_TRACE_ENDPOINT` | empty | OTLP/HTTP trace endpoint. Unset → tracing is a no-op. | | `OTEL_EXPORTER_OTLP_TRACES_PATH` | empty | Overrides the OTLP path (e.g. VictoriaTraces' `/insert/opentelemetry/v1/traces`). Mirrors the main duckgres binary. | +The concurrency default was selected from an isolated 16/32/64 contention +sweep. A cap of 64 removed synthetic origin fallback but did not produce a +stable latency improvement and doubled the worst-case byte reservation; 32 +kept the safer resource bound while materially reducing fallback versus 16. + ## Block-aligned mode The legacy cache key is `sha256(url|range)` — an exact match on the client's @@ -70,6 +77,70 @@ to clamp ranges that cross EOF and return `416` for ranges that start at or beyond EOF. Before a `206` response is committed, every required cache block is opened so LRU eviction cannot truncate an in-progress assembled response. +### Peer racing and overload behavior + +Peer probes retain their 150 ms timeout, and block fills run in parallel with +at most 8 workers per client request. All requests share the process-wide +count and byte ceilings above. Time spent queued for either permit counts +against the peer's adaptive head start; a fill that is still queued when that +deadline expires is permanently shed to the coalesced origin path instead of +starting late and adding more load. + +The origin hedge starts after the rolling p50 of the last 64 successful peer +block fetches, clamped to 25–150 ms (25 ms before any samples exist). Peer and +origin then run concurrently. A peer win cancels an origin span once no other +request still needs that shared span. Origin hedges continue to use contiguous +miss-run coalescing and the shared origin-span flight, so hedging does not split +one miss into per-block origin requests. Each validated origin block commit +immediately cancels the matching peer transfer for every waiter sharing that +origin flight; later blocks remain independently viable if the origin span +subsequently fails. + +A process-local circuit breaker compares one-block peer latency with origin's +time through its first validated, atomically committed block. That first-block +sample comes from the existing coalesced span, so it retains request/TTFB cost +without adding or fragmenting origin reads. Eight sustained comparisons with +peer latency above 1.5× origin open the breaker; origin winning by itself is +not evidence, so a peer that is only marginally slower does not get disabled. +When cancellation has already proved that a peer exceeded 1.5×, that lower +bound is included in the peer EWMA and in a separate sustained-evidence streak +so a formerly healthy EWMA cannot hide an abrupt slowdown. If prompt +cancellation leaves the result ambiguous, at most one process-wide diagnostic +every 5 seconds restarts that block fetch with an instantaneous limiter +acquisition and a hard 1.5× deadline. The user response still uses origin +immediately; the bounded sample makes the slowdown measurable without +preserving every losing transfer. + +While open, requests start origin immediately and one non-blocking peer +recovery sample is allowed every 5 seconds. It is compared with the current +first-block commit in the normal coalesced origin span. Until that commit +arrives, a 1.5× rolling-origin-EWMA deadline provides the initial bound. The +response never waits for the sample or for the rest of that span; the +diagnostic peer may run only to the active 1.5× boundary before cancellation. +Three samples within 1.5× close the breaker. +These constants are deliberately fixed; the two resource ceilings are the +operational tuning controls. + +The legacy exact-range path uses the same process-wide controller when an +absolute range provides a safe byte reservation. Suffix, open-ended, and +missing ranges bypass peers because their transfer size cannot be bounded. + +### Peer-path recovery runbook + +1. Check `cache_proxy_peer_breaker_state`, hedge winners, queue duration, and + the in-flight count/byte gauges. A breaker value of `1` is protective: the + proxy is serving origin traffic and will probe for recovery automatically. +2. If `cache_proxy_peer_fetch_shed_total{reason="deadline"}` rises while both + in-flight gauges stay at their ceilings, increase the constrained ceiling + (`CACHE_PEER_FETCH_MAX_CONCURRENCY` or `CACHE_PEER_FETCH_MAX_BYTES`) and + restart the proxy. Keep the byte ceiling at least one block. +3. If peer traffic itself is destabilizing the node, unset `PEER_SERVICE` and + restart. This disables peer discovery and sends misses to origin without + disabling the local cache. Restore it after peer latency and error rate + recover. +4. To undo tuning, restore concurrency to `32` and remove the explicit byte + override so it again follows concurrency × `CACHE_BLOCK_SIZE_BYTES`. + ## Tracing When a trace endpoint is set the proxy exports OpenTelemetry spans under diff --git a/cmd/cache-proxy/block_serve.go b/cmd/cache-proxy/block_serve.go index 196a908a..7dc61833 100644 --- a/cmd/cache-proxy/block_serve.go +++ b/cmd/cache-proxy/block_serve.go @@ -9,6 +9,8 @@ import ( "net/http" "strconv" "strings" + "sync" + "sync/atomic" "time" "github.com/prometheus/client_golang/prometheus" @@ -90,16 +92,37 @@ func writeRangeNotSatisfiable(w http.ResponseWriter, objectSize int64) { // is committed, and each selected block must contain exactly the advertised // number of bytes. func (p *CacheProxy) fetchOriginSpan(r *http.Request, blockSize, firstIdx, lastIdx int64) error { + _, _, err := p.fetchOriginSpanContext(r.Context(), r, blockSize, firstIdx, lastIdx, nil) + return err +} + +// fetchOriginSpanContext is the cancelable implementation used by origin +// hedges. bytesRead includes partial network traffic when cancellation wins; +// successfully committed bytes remain accounted by cacheOriginBytesTotal. +// firstBlockDuration measures request setup, transfer, and durable cache commit +// for the first block, which is directly comparable to one peer block fetch. +func (p *CacheProxy) fetchOriginSpanContext( + parent context.Context, + r *http.Request, + blockSize, firstIdx, lastIdx int64, + onBlockCommit func(idx int64, elapsed time.Duration), +) (bytesRead int64, firstBlockDuration time.Duration, retErr error) { + startedAt := time.Now() + originFetchInFlight.Inc() + defer func() { + originFetchInFlight.Dec() + originFetchesTotal.WithLabelValues(originFetchOutcome(retErr)).Inc() + }() timeout := p.originTimeout if timeout <= 0 { timeout = defaultOriginTimeout } - ctx, cancel := context.WithTimeout(r.Context(), timeout) + ctx, cancel := context.WithTimeout(parent, timeout) defer cancel() req, err := http.NewRequestWithContext(ctx, http.MethodGet, r.URL.String(), nil) if err != nil { - return err + return 0, 0, err } for k, vv := range r.Header { if hopByHop[strings.ToLower(k)] || strings.EqualFold(k, "Range") { @@ -116,9 +139,10 @@ func (p *CacheProxy) fetchOriginSpan(r *http.Request, blockSize, firstIdx, lastI resp, err := p.client.Do(req) if err != nil { - return err + return 0, 0, err } defer func() { _ = resp.Body.Close() }() + counted := &countingReader{r: resp.Body} if resp.StatusCode >= 400 { if resp.StatusCode == http.StatusRequestedRangeNotSatisfiable { @@ -126,8 +150,8 @@ func (p *CacheProxy) fetchOriginSpan(r *http.Request, blockSize, firstIdx, lastI p.rememberObjectSize(r.URL.String(), objectSize) } } - body, _ := io.ReadAll(io.LimitReader(resp.Body, originErrorBodyCap)) - return &originStatusError{status: resp.StatusCode, headers: resp.Header.Clone(), body: body} + body, _ := io.ReadAll(io.LimitReader(counted, originErrorBodyCap)) + return counted.n, 0, &originStatusError{status: resp.StatusCode, headers: resp.Header.Clone(), body: body} } // This function always sends a Range header, so anything other than 206 @@ -139,43 +163,927 @@ func (p *CacheProxy) fetchOriginSpan(r *http.Request, blockSize, firstIdx, lastI // since blocks are treated as immutable once cached, the corruption would // never self-heal. Fail closed instead. if resp.StatusCode != http.StatusPartialContent { - return fmt.Errorf("origin ignored Range (status %d): refusing to cache misaligned blocks", resp.StatusCode) + return counted.n, 0, fmt.Errorf("origin ignored Range (status %d): refusing to cache misaligned blocks", resp.StatusCode) } gotStart, gotEnd, objectSize, ok := parsePartialContentRange(resp.Header.Get("Content-Range")) if !ok { - return fmt.Errorf("origin returned invalid Content-Range %q", resp.Header.Get("Content-Range")) + return counted.n, 0, fmt.Errorf("origin returned invalid Content-Range %q", resp.Header.Get("Content-Range")) } wantResponseEnd := min(wantEnd, objectSize-1) if gotStart != wantStart || gotEnd != wantResponseEnd { - return fmt.Errorf("origin returned Content-Range bytes %d-%d/%d for requested bytes %d-%d", + return counted.n, 0, fmt.Errorf("origin returned Content-Range bytes %d-%d/%d for requested bytes %d-%d", gotStart, gotEnd, objectSize, wantStart, wantEnd) } expectedBodySize := gotEnd - gotStart + 1 if resp.ContentLength >= 0 && resp.ContentLength != expectedBodySize { - return fmt.Errorf("origin Content-Length %d does not match Content-Range length %d", resp.ContentLength, expectedBodySize) + return counted.n, 0, fmt.Errorf("origin Content-Length %d does not match Content-Range length %d", resp.ContentLength, expectedBodySize) } remaining := expectedBodySize for idx := firstIdx; idx <= lastIdx && remaining > 0; idx++ { blockBytes := min(blockSize, remaining) size, err := p.store.PutStream(BlockKey(r.URL.String(), idx, blockSize), &exactLengthReader{ - r: resp.Body, + r: counted, remaining: blockBytes, }) if err != nil { - return fmt.Errorf("commit block %d: %w", idx, err) + return counted.n, firstBlockDuration, fmt.Errorf("commit block %d: %w", idx, err) } if size != blockBytes { - return fmt.Errorf("commit block %d: stored %d bytes, expected %d", idx, size, blockBytes) + return counted.n, firstBlockDuration, fmt.Errorf("commit block %d: stored %d bytes, expected %d", idx, size, blockBytes) } cacheOriginBytesTotal.Add(float64(size)) + if idx == firstIdx { + firstBlockDuration = time.Since(startedAt) + } + if onBlockCommit != nil { + onBlockCommit(idx, time.Since(startedAt)) + } remaining -= size } if remaining != 0 { - return fmt.Errorf("origin body ended with %d bytes still expected", remaining) + return counted.n, firstBlockDuration, fmt.Errorf("origin body ended with %d bytes still expected", remaining) } p.rememberObjectSize(r.URL.String(), objectSize) - return nil + return counted.n, firstBlockDuration, nil +} + +// peerFillConcurrency bounds how many of one request's blocks are fetched +// from peers at the same time. Requests typically span one or two blocks, so +// this only matters for wide spans, where it keeps a single request from +// monopolizing peer bandwidth. +const peerFillConcurrency = 8 + +// peerFill is one cancelable per-block peer attempt. At most eight workers are +// created per request; the process-wide policy adds count and byte ceilings. +type peerFill struct { + idx int64 + key string + ctx context.Context + cancel context.CancelFunc + done chan struct{} + + started atomic.Bool + loser atomic.Bool + lateEligible atomic.Bool + accounted atomic.Bool + recoveryDone atomic.Bool + recoveryDetached atomic.Bool + measurementQueued atomic.Bool + recoveryMu sync.Mutex + recoveryUpdates chan time.Duration + startedAt time.Time + recovery bool + policy *peerFetchPolicy + result controlledPeerFetchResult +} + +func (f *peerFill) isDone() bool { + select { + case <-f.done: + return true + default: + return false + } +} + +func (f *peerFill) finish(result controlledPeerFetchResult) { + f.result = result + close(f.done) + if f.recovery && !result.ok { + f.completeRecovery(false) + } + if f.loser.Load() { + f.accountLosingResult() + } +} + +func (f *peerFill) markStarted() { + f.startedAt = time.Now() + f.started.Store(true) +} + +func (f *peerFill) completeRecovery(success bool) { + if !f.recovery || f.policy == nil || !f.recoveryDone.CompareAndSwap(false, true) { + return + } + f.policy.finishProbe(true, success) +} + +func (f *peerFill) accountLosingResult() { + if !f.accounted.CompareAndSwap(false, true) { + return + } + if f.result.bytes > 0 { + peerHedgeDuplicateBytesTotal.WithLabelValues("peer").Add(float64(f.result.bytes)) + } + if f.lateEligible.Load() && f.result.ok { + latePeerSuccessesTotal.Inc() + } +} + +// markOriginWinnerWithoutCancel classifies a diagnostic recovery transfer as +// duplicate work once the request has committed to origin, while allowing the +// one sampled transfer to finish inside the breaker's latency-ratio budget. +func (f *peerFill) markOriginWinnerWithoutCancel() { + doneBefore := f.isDone() + f.loser.Store(true) + if !doneBefore { + f.lateEligible.Store(true) + } + if f.isDone() { + f.accountLosingResult() + } +} + +// cancelForOrigin marks this fill as losing work. Queued fills are canceled +// without consuming a global permit; admitted network work is counted as a +// peer-side cancellation and reports any bytes already transferred. +func (f *peerFill) cancelForOrigin() { + doneBefore := f.isDone() + f.markOriginWinnerWithoutCancel() + if !doneBefore { + if f.started.Load() { + peerFetchCancellationsTotal.WithLabelValues("peer").Inc() + } + f.cancel() + } + if f.isDone() { + f.accountLosingResult() + } +} + +func (p *CacheProxy) launchPeerFills( + ctx context.Context, + urlStr string, + firstIdx, lastIdx int64, +) (map[int64]*peerFill, <-chan struct{}, time.Time) { + fills := make(map[int64]*peerFill) + allDone := make(chan struct{}) + if p.peers == nil { + close(allDone) + return fills, allDone, time.Now() + } + policy := p.peerPolicy + if policy == nil { + close(allDone) + return fills, allDone, time.Now() + } + startedAt := time.Now() + deadline := startedAt.Add(policy.headStart()) + breakerWasOpen := policy.breakerOpen() + jobs := make(chan *peerFill, int(lastIdx-firstIdx+1)) + pendingJobs := 0 + for idx := firstIdx; idx <= lastIdx; idx++ { + key := BlockKey(urlStr, idx, p.blockSize) + if p.store.Has(key) { + continue + } + allowed, recovery := policy.allowPeer(true) + fillParent := ctx + if recovery { + // A sampled recovery fetch is bounded by the measured 1.5x ratio + // after origin completes, not by the client request returning. + fillParent = context.Background() + } + fillCtx, cancel := context.WithCancel(fillParent) + fill := &peerFill{ + idx: idx, key: key, ctx: fillCtx, cancel: cancel, done: make(chan struct{}), + recovery: recovery, policy: policy, + } + fills[idx] = fill + if !allowed { + peerFetchShedTotal.WithLabelValues("breaker").Inc() + fill.finish(controlledPeerFetchResult{}) + continue + } + if recovery { + // Half-open probes are diagnostic. Origin starts immediately and the + // probe gets only an instantaneous limiter acquisition. + breakerWasOpen = true + } + jobs <- fill + pendingJobs++ + } + close(jobs) + if breakerWasOpen { + deadline = startedAt + } + if len(fills) == 0 { + close(allDone) + return fills, allDone, deadline + } + + if pendingJobs == 0 { + close(allDone) + return fills, allDone, deadline + } + workers := min(peerFillConcurrency, pendingJobs) + var wg sync.WaitGroup + wg.Add(pendingJobs) + for range workers { + go func() { + for fill := range jobs { + result := p.fetchFromPeers(fill.ctx, deadline, p.blockSize, fill.key, func(rd io.Reader) (int64, error) { + return p.store.PutStream(fill.key, io.LimitReader(rd, p.blockSize)) + }, peerFetchDecision{allowed: true, nonBlocking: fill.recovery}, true, + fill.markStarted) + fill.finish(result) + wg.Done() + } + }() + } + go func() { + wg.Wait() + close(allDone) + }() + return fills, allDone, deadline +} + +func waitForPeerHeadStart(ctx context.Context, allDone <-chan struct{}, deadline time.Time) error { + wait := time.Until(deadline) + if wait <= 0 { + return nil + } + timer := time.NewTimer(wait) + defer timer.Stop() + select { + case <-allDone: + return nil + case <-timer.C: + return nil + case <-ctx.Done(): + return ctx.Err() + } +} + +type blockSpanRaceResult struct { + source string // source for blocks not in originCommittedThrough + originCommittedThrough int64 + hedged bool + breakerRatioEvidence bool + breakerComparison peerThresholdComparison + breakerComparisonObserved bool + originWait time.Duration + peerWait time.Duration + err error +} + +func spanPeerState(store *DiskCache, fills map[int64]*peerFill, lo, hi int64) (canWin, ready bool) { + ready = true + for idx := lo; idx <= hi; idx++ { + fill := fills[idx] + if fill != nil && store.Has(fill.key) { + continue + } + if fill == nil { + return false, false + } + if fill.isDone() { + if !fill.result.ok || !store.Has(fill.key) { + return false, false + } + continue + } + if !fill.started.Load() { + // Still queued when the adaptive head-start expired. It is no + // longer eligible to start, so this span must shed directly. + return false, false + } + ready = false + } + return true, ready +} + +type spanReadyResult struct { + ready bool + originCommittedThrough int64 +} + +func spanPeerOutcome( + ctx context.Context, + store *DiskCache, + lease *originSpanLease, + fills map[int64]*peerFill, + lo, hi int64, +) <-chan spanReadyResult { + outcome := make(chan spanReadyResult, 1) + go func() { + for idx := lo; idx <= hi; idx++ { + fill := fills[idx] + if fill != nil && store.Has(fill.key) { + continue + } + if fill == nil { + outcome <- spanReadyResult{} + return + } + select { + case <-fill.done: + // An origin commit can cancel this peer fill. Re-check the + // shared cache before treating its canceled result as a gap. + if !store.Has(fill.key) { + outcome <- spanReadyResult{} + return + } + case <-ctx.Done(): + return + } + } + outcome <- spanReadyResult{ + ready: true, + originCommittedThrough: lease.committedThroughIn(lo, hi), + } + }() + return outcome +} + +// abandonSpanPeerFills stops request-owned work after origin failure or client +// cancellation. It is not a hedge win, so it deliberately avoids loser and +// duplicate-byte accounting. A detached recovery sample keeps its hard bound. +func abandonSpanPeerFills(fills map[int64]*peerFill, lo, hi int64) { + for idx := lo; idx <= hi; idx++ { + if fill := fills[idx]; fill != nil { + if fill.recovery && fill.recoveryDetached.Load() { + continue + } + fill.cancel() + } + } +} + +// finishSpanRecovery resolves only recovery fills that never transferred a +// bounded timer from the commit watcher. Detached fills are classified by +// assessRecoveryAtOriginCommit at the exact first-block ratio boundary. +func finishSpanRecovery(store *DiskCache, fills map[int64]*peerFill, lo, hi int64) { + for idx := lo; idx <= hi; idx++ { + fill := fills[idx] + if fill == nil || !fill.recovery || fill.recoveryDetached.Load() { + continue + } + success := fill.isDone() && fill.result.ok && store.Has(fill.key) + fill.completeRecovery(success) + } +} + +func failSpanRecovery(fills map[int64]*peerFill, lo, hi int64) { + for idx := lo; idx <= hi; idx++ { + if fill := fills[idx]; fill != nil { + if fill.recoveryDetached.Load() { + continue + } + fill.completeRecovery(false) + } + } +} + +func spanHasRecovery(fills map[int64]*peerFill, lo, hi int64) bool { + for idx := lo; idx <= hi; idx++ { + if fill := fills[idx]; fill != nil && fill.recovery { + return true + } + } + return false +} + +// armRecoveryAssessment starts one service-owned bounded controller or updates +// its comparison when a fresher first-block sample arrives. The initial bound +// comes from the rolling origin EWMA, so a peer cannot run to its 30-second GET +// timeout even when the current origin stalls before returning a first byte. +func (p *CacheProxy) armRecoveryAssessment(fill *peerFill, originComparison time.Duration) { + if p.peerPolicy == nil || fill == nil || !fill.recovery || fill.recoveryDone.Load() || originComparison <= 0 { + return + } + + fill.recoveryMu.Lock() + updates := fill.recoveryUpdates + start := updates == nil + if start { + updates = make(chan time.Duration, 1) + fill.recoveryUpdates = updates + fill.recoveryDetached.Store(true) + } + fill.recoveryMu.Unlock() + + if start { + go p.runRecoveryAssessment(fill, originComparison, updates) + return + } + select { + case updates <- originComparison: + default: + // Only the latest (first-commit) comparison matters. Replace a stale + // queued update without blocking the origin commit callback. + select { + case <-updates: + default: + } + select { + case updates <- originComparison: + default: + } + } +} + +func (p *CacheProxy) runRecoveryAssessment( + fill *peerFill, + originComparison time.Duration, + updates <-chan time.Duration, +) { + peerDone := false + hasCurrentComparison := false + fillDone := (<-chan struct{})(fill.done) + completeFromPeer := func() { + healthy := fill.result.ok && peerWithinBreakerRatio( + fill.result.duration, + originComparison, + p.peerPolicy.cfg.breakerRatio, + ) + fill.completeRecovery(healthy) + } + for { + budget := time.Duration(p.peerPolicy.cfg.breakerRatio * float64(originComparison)) + remaining := budget + if fill.started.Load() { + remaining -= time.Since(fill.startedAt) + } + if remaining <= 0 { + fill.cancelForOrigin() + fill.completeRecovery(false) + return + } + + timer := time.NewTimer(remaining) + select { + case <-fillDone: + if !timer.Stop() { + select { + case <-timer.C: + default: + } + } + if !fill.result.ok { + fill.completeRecovery(false) + return + } + peerDone = true + fillDone = nil + if hasCurrentComparison { + completeFromPeer() + return + } + // A successful peer may finish before the current origin supplies + // its first block. Keep only this small controller alive: classify + // against a fresher commit if it arrives, otherwise against the + // rolling fallback when the existing hard deadline expires. + continue + case next := <-updates: + if !timer.Stop() { + select { + case <-timer.C: + default: + } + } + originComparison = next + hasCurrentComparison = true + if peerDone { + completeFromPeer() + return + } + continue + case <-timer.C: + if peerDone { + completeFromPeer() + } else { + fill.cancelForOrigin() + fill.completeRecovery(false) + } + return + } + } +} + +// assessRecoveryAtOriginCommit marks the current origin block as the winner +// for duplicate-byte accounting and tightens/classifies the controller with +// the contemporaneous first-block duration. +func (p *CacheProxy) assessRecoveryAtOriginCommit(fill *peerFill, originComparison time.Duration) { + if p.peerPolicy == nil || fill == nil || !fill.recovery { + return + } + if !fill.started.Load() || originComparison <= 0 { + fill.cancelForOrigin() + fill.completeRecovery(false) + return + } + fill.markOriginWinnerWithoutCancel() + p.armRecoveryAssessment(fill, originComparison) +} + +func (p *CacheProxy) armSpanRecoveryFallback(fills map[int64]*peerFill, lo, hi int64) { + if p.peerPolicy == nil { + return + } + originComparison, ok := p.peerPolicy.comparableOriginLatency(0) + if !ok { + // A naturally opened breaker always has an origin baseline. Keep a + // defensive hard bound for restored/test state that was forced open. + originComparison = p.peerPolicy.cfg.maxHeadStart + } + for idx := lo; idx <= hi; idx++ { + if fill := fills[idx]; fill != nil && fill.recovery { + p.armRecoveryAssessment(fill, originComparison) + } + } +} + +// watchOriginCommits applies producer progress to this request's own peer +// fills. Progress is replayable for leases that join an existing flight, and +// all cancellation/classification happens outside the flight mutex. +func (p *CacheProxy) watchOriginCommits( + ctx context.Context, + lease *originSpanLease, + fills map[int64]*peerFill, + lo, hi int64, +) <-chan struct{} { + done := make(chan struct{}) + go func() { + defer close(done) + processedThrough := lo - 1 + for { + committedThrough, firstBlockDuration, progress, complete := lease.progressSnapshot() + for idx := processedThrough + 1; idx <= min(committedThrough, hi); idx++ { + fill := fills[idx] + if fill == nil { + continue + } + if fill.recovery { + p.assessRecoveryAtOriginCommit(fill, firstBlockDuration) + continue + } + + doneBefore := fill.isDone() + peerElapsed := time.Duration(0) + if fill.started.Load() { + peerElapsed = time.Since(fill.startedAt) + } + fill.cancelForOrigin() + if !doneBefore && peerElapsed > 0 && + peerWithinBreakerRatio(peerElapsed, firstBlockDuration, p.peerPolicy.cfg.breakerRatio) && + fill.measurementQueued.CompareAndSwap(false, true) { + // Wait only for prompt context cancellation to release the + // original permit, then run the globally sampled diagnostic. + go func(fill *peerFill) { + <-fill.done + if !p.startAmbiguousPeerMeasurement(fill.key, firstBlockDuration) { + fill.measurementQueued.Store(false) + } + }(fill) + } + } + processedThrough = max(processedThrough, min(committedThrough, hi)) + if complete || processedThrough >= hi { + if complete { + for idx := lo; idx <= hi; idx++ { + fill := fills[idx] + if fill != nil && fill.recovery && idx > committedThrough && + !fill.recoveryDone.Load() { + fill.cancel() + fill.completeRecovery(false) + } + } + } + return + } + select { + case <-progress: + case <-ctx.Done(): + return + } + } + }() + return done +} + +type peerThresholdComparison uint8 + +const ( + peerThresholdUnknown peerThresholdComparison = iota + peerThresholdHealthy + peerThresholdExceeded +) + +// observeCanceledPeers records threshold-qualified lower bounds and returns a +// tri-state paired comparison. Healthy requires every observed peer fill in +// this span to have completed successfully within the ratio; a canceled fill, +// fast miss, or still-running fill is unknown rather than evidence of health. +// At most one slow lower bound is added per span. +func (p *CacheProxy) observeCanceledPeers( + fills map[int64]*peerFill, + lo, hi int64, + originFirstBlockDuration time.Duration, +) (ratioEvidence bool, comparison peerThresholdComparison, ambiguousKey string, originComparison time.Duration) { + if p.peerPolicy == nil || originFirstBlockDuration <= 0 { + return false, peerThresholdUnknown, "", 0 + } + originComparison, comparable := p.peerPolicy.comparableOriginLatency(originFirstBlockDuration) + if !comparable { + return false, peerThresholdUnknown, "", 0 + } + var slowestLowerBound time.Duration + observed := false + allHealthy := true + thresholdExceeded := false + for idx := lo; idx <= hi; idx++ { + fill := fills[idx] + if fill == nil || fill.recovery || !fill.started.Load() { + continue + } + observed = true + peerLowerBound := time.Since(fill.startedAt) + if fill.isDone() { + if fill.result.ok { + // Successful completions were already added to the peer EWMA. + ratioEvidence = true + if !peerWithinBreakerRatio( + fill.result.duration, + originComparison, + p.peerPolicy.cfg.breakerRatio, + ) { + thresholdExceeded = true + allHealthy = false + } + continue + } + allHealthy = false + peerLowerBound = fill.result.duration + if fill.loser.Load() && !fill.measurementQueued.Load() && ambiguousKey == "" { + ambiguousKey = fill.key + } + } else { + allHealthy = false + } + if !fill.isDone() && !fill.measurementQueued.Load() && ambiguousKey == "" { + ambiguousKey = fill.key + } + if !peerWithinBreakerRatio(peerLowerBound, originComparison, p.peerPolicy.cfg.breakerRatio) && + peerLowerBound > slowestLowerBound { + thresholdExceeded = true + slowestLowerBound = peerLowerBound + } + } + if slowestLowerBound > 0 { + p.peerPolicy.observePeerLowerBound(slowestLowerBound) + } + if thresholdExceeded { + return true, peerThresholdExceeded, "", originComparison + } + if observed && allHealthy { + return ratioEvidence, peerThresholdHealthy, "", originComparison + } + return ratioEvidence, peerThresholdUnknown, ambiguousKey, originComparison +} + +// startAmbiguousPeerMeasurement restarts one promptly canceled loser as a +// non-blocking diagnostic. The normal transfer is still canceled immediately; +// this sampled fetch gets an instantaneous global permit and at most the 1.5x +// origin budget, which provides the otherwise-missing evidence after an abrupt +// slowdown without reviving the 30-second zombie path. +func (p *CacheProxy) startAmbiguousPeerMeasurement(cacheKey string, originComparison time.Duration) bool { + policy := p.peerPolicy + if policy == nil || cacheKey == "" || originComparison <= 0 || !policy.startAmbiguousMeasurement() { + return false + } + go func() { + defer policy.finishAmbiguousMeasurement() + budget := time.Duration(policy.cfg.breakerRatio * float64(originComparison)) + if budget <= 0 { + return + } + ctx, cancel := context.WithTimeout(context.Background(), budget) + result := p.fetchFromPeers(ctx, time.Time{}, p.blockSize, cacheKey, func(rd io.Reader) (int64, error) { + return io.Copy(io.Discard, io.LimitReader(rd, p.blockSize)) + }, peerFetchDecision{allowed: true, nonBlocking: true}, true, nil) + timedOut := errors.Is(ctx.Err(), context.DeadlineExceeded) + cancel() + if !result.started { + return + } + if result.bytes > 0 { + peerHedgeDuplicateBytesTotal.WithLabelValues("peer").Add(float64(result.bytes)) + } + if result.ok { + latePeerSuccessesTotal.Inc() + } + if timedOut { + peerFetchCancellationsTotal.WithLabelValues("peer").Inc() + // The transfer was still incomplete at the boundary, so its true + // latency is strictly greater than the configured ratio. + policy.observePeerLowerBound(budget + time.Nanosecond) + policy.recordThresholdComparison(true) + return + } + if !result.ok && !peerWithinBreakerRatio(result.duration, originComparison, policy.cfg.breakerRatio) { + policy.observePeerLowerBound(result.duration) + policy.recordThresholdComparison(true) + return + } + if result.ok { + policy.recordThresholdComparison(!peerWithinBreakerRatio( + result.duration, + originComparison, + policy.cfg.breakerRatio, + )) + policy.recordLatencyRatioObservation() + } + }() + return true +} + +func (p *CacheProxy) raceOriginSpan( + r *http.Request, + urlStr string, + lo, hi int64, + fills map[int64]*peerFill, +) blockSpanRaceResult { + noOriginCommit := lo - 1 + hasRecovery := spanHasRecovery(fills, lo, hi) + canWin, ready := spanPeerState(p.store, fills, lo, hi) + if ready && !hasRecovery { + finishSpanRecovery(p.store, fills, lo, hi) + return blockSpanRaceResult{source: "peer", originCommittedThrough: noOriginCommit} + } + // An open breaker always starts origin immediately. Its one periodic peer + // sample is diagnostic and never delays or supplies the user request. + hedged := canWin && !hasRecovery + if hasRecovery { + p.armSpanRecoveryFallback(fills, lo, hi) + } + + flightKey := fmt.Sprintf("%s|%d", BlockKey(urlStr, lo, p.blockSize), hi) + originStarted := time.Now() + lease := p.blockFlights.startWithProgress(flightKey, lo, func( + ctx context.Context, + reportCommit func(int64, time.Duration), + ) (originSpanResult, error) { + fetchStarted := time.Now() + bytesRead, firstBlockDuration, err := p.fetchOriginSpanContext( + ctx, + r, + p.blockSize, + lo, + hi, + func(idx int64, elapsed time.Duration) { + if idx == lo && p.peerPolicy != nil { + p.peerPolicy.observeOriginFirstBlock(elapsed) + } + reportCommit(idx, elapsed) + }, + ) + duration := time.Since(fetchStarted) + if p.peerPolicy != nil { + p.peerPolicy.observeOriginSpan(duration, err == nil, errors.Is(err, context.Canceled)) + } + return originSpanResult{ + bytesRead: bytesRead, duration: duration, firstBlockDuration: firstBlockDuration, + }, err + }) + commitWatchCtx, cancelCommitWatch := context.WithCancel(r.Context()) + commitWatchDone := p.watchOriginCommits(commitWatchCtx, lease, fills, lo, hi) + stopCommitWatch := func() { + cancelCommitWatch() + <-commitWatchDone + } + if hedged { + peerHedgesTotal.Inc() + } + + if !hedged { + result, err := lease.wait(r.Context()) + stopCommitWatch() + breakerRatioEvidence := false + breakerComparison := peerThresholdUnknown + breakerComparisonObserved := false + if err == nil { + if !hasRecovery { + var ambiguousKey string + var originComparison time.Duration + breakerRatioEvidence, breakerComparison, ambiguousKey, originComparison = + p.observeCanceledPeers(fills, lo, hi, result.firstBlockDuration) + breakerComparisonObserved = true + finishSpanRecovery(p.store, fills, lo, hi) + p.startAmbiguousPeerMeasurement(ambiguousKey, originComparison) + } + } else { + failSpanRecovery(fills, lo, hi) + abandonSpanPeerFills(fills, lo, hi) + } + if err == nil { + lease.releaseOriginUsed() + } else { + lease.release() + } + return blockSpanRaceResult{ + source: "s3", + originCommittedThrough: lease.committedThroughIn(lo, hi), + breakerRatioEvidence: breakerRatioEvidence, + breakerComparison: breakerComparison, + breakerComparisonObserved: breakerComparisonObserved, + originWait: time.Since(originStarted), + err: err, + } + } + + peerWaitStarted := time.Now() + peerCtx, cancelPeerWait := context.WithCancel(r.Context()) + defer cancelPeerWait() + defer cancelCommitWatch() + peerOutcome := spanPeerOutcome(peerCtx, p.store, lease, fills, lo, hi) + originDone := lease.call.done + var originErr error + for { + select { + case spanReady := <-peerOutcome: + peerOutcome = nil + if spanReady.ready { + finishSpanRecovery(p.store, fills, lo, hi) + cancelPeerWait() + stopCommitWatch() + raceResult := blockSpanRaceResult{ + source: "peer", + originCommittedThrough: spanReady.originCommittedThrough, + hedged: true, + originWait: time.Since(originStarted), + peerWait: time.Since(peerWaitStarted), + } + if spanReady.originCommittedThrough >= lo { + _, firstBlockDuration, _, _ := lease.progressSnapshot() + var ambiguousKey string + var originComparison time.Duration + raceResult.breakerRatioEvidence, raceResult.breakerComparison, + ambiguousKey, originComparison = + p.observeCanceledPeers(fills, lo, hi, firstBlockDuration) + raceResult.breakerComparisonObserved = true + p.startAmbiguousPeerMeasurement(ambiguousKey, originComparison) + lease.releaseOriginUsed() + peerHedgeWinsTotal.WithLabelValues("origin").Inc() + } else { + lease.releasePeerWinner() + peerHedgeWinsTotal.WithLabelValues("peer").Inc() + } + return raceResult + } + if originDone == nil { + failSpanRecovery(fills, lo, hi) + lease.release() + return blockSpanRaceResult{ + source: "s3", originCommittedThrough: lease.committedThroughIn(lo, hi), + hedged: true, originWait: time.Since(originStarted), err: originErr, + } + } + case <-originDone: + result, err := lease.wait(context.Background()) + stopCommitWatch() + originDone = nil + originErr = err + if err == nil { + breakerRatioEvidence, breakerComparison, ambiguousKey, originComparison := + p.observeCanceledPeers(fills, lo, hi, result.firstBlockDuration) + lease.releaseOriginUsed() + cancelPeerWait() + finishSpanRecovery(p.store, fills, lo, hi) + p.startAmbiguousPeerMeasurement(ambiguousKey, originComparison) + peerHedgeWinsTotal.WithLabelValues("origin").Inc() + return blockSpanRaceResult{ + source: "s3", + originCommittedThrough: lease.committedThroughIn(lo, hi), + hedged: true, + breakerRatioEvidence: breakerRatioEvidence, + breakerComparison: breakerComparison, + breakerComparisonObserved: true, + originWait: time.Since(originStarted), + } + } + // Origin failed while peers were still viable. Let them finish as + // the redundant path; if any peer fails too, return origin's error. + if peerOutcome == nil { + lease.release() + return blockSpanRaceResult{ + source: "s3", originCommittedThrough: lease.committedThroughIn(lo, hi), + hedged: true, originWait: time.Since(originStarted), err: err, + } + } + case <-r.Context().Done(): + lease.release() + cancelPeerWait() + stopCommitWatch() + failSpanRecovery(fills, lo, hi) + abandonSpanPeerFills(fills, lo, hi) + return blockSpanRaceResult{ + source: "s3", originCommittedThrough: lease.committedThroughIn(lo, hi), + hedged: hedged, originWait: time.Since(originStarted), err: r.Context().Err(), + } + } + } } // serveBlockAligned serves a cacheable GET whose Range is an absolute @@ -218,45 +1126,79 @@ func (p *CacheProxy) serveBlockAligned(w http.ResponseWriter, r *http.Request, r return false } + // Launch at most eight peer workers for this request. Every worker must + // also acquire the process-wide count and byte permits before the adaptive + // head-start expires; queued work that misses it never starts later. + peerPhaseStart := time.Now() + fills, allPeerFillsDone, fillDeadline := p.launchPeerFills(r.Context(), urlStr, firstIdx, lastIdx) + defer func() { + for _, fill := range fills { + if fill.recovery && fill.recoveryDetached.Load() { + continue + } + fill.completeRecovery(false) + fill.cancel() + } + }() + if err := waitForPeerHeadStart(r.Context(), allPeerFillsDone, fillDeadline); err != nil { + http.Error(w, err.Error(), http.StatusBadGateway) + return true + } + peerDur += time.Since(peerPhaseStart) + // Phase 1: ensure every block is present locally. Track sources for the // hit/miss accounting and the log line. - var nLocal, nPeer, nOrigin int64 + sources := make(map[int64]string, blockCount) + var nHedged int64 + var peerWonHedge, originWonHedge, breakerRatioEvidence bool + var breakerComparisonSeen, breakerComparisonUnknown, breakerComparisonHealthy, breakerComparisonExceeded bool var missRunStart int64 = -1 flushRun := func(runEnd int64) bool { if missRunStart < 0 { return true } - for lo := missRunStart; lo <= runEnd; lo += p.maxSpanBlocks { + runStart := missRunStart + missRunStart = -1 + for lo := runStart; lo <= runEnd; { hi := min(lo+p.maxSpanBlocks-1, runEnd) - // hi must be part of the single-flight key, not just lo: two - // concurrent requests can both start a missing run at the same lo - // but need different-length spans (their own runEnd differs), and - // if only lo keyed the call, the loser would adopt the winner's - // (shorter) fetch result while believing its own longer span was - // covered — silently leaving trailing blocks unfetched. - flightKey := fmt.Sprintf("%s|%d", BlockKey(urlStr, lo, p.blockSize), hi) - _, err := p.flights.Do(flightKey, func() (fetchResult, error) { - fetchStart := time.Now() - fetchErr := p.fetchOriginSpan(r, p.blockSize, lo, hi) - s3Dur += time.Since(fetchStart) - return fetchResult{}, fetchErr - }) - if err != nil { + race := p.raceOriginSpan(r, urlStr, lo, hi, fills) + breakerRatioEvidence = breakerRatioEvidence || race.breakerRatioEvidence + if race.breakerComparisonObserved { + breakerComparisonSeen = true + switch race.breakerComparison { + case peerThresholdExceeded: + breakerComparisonExceeded = true + case peerThresholdHealthy: + breakerComparisonHealthy = true + default: + breakerComparisonUnknown = true + } + } + s3Dur += race.originWait + peerDur += race.peerWait + if race.hedged { + nHedged += hi - lo + 1 + if race.originCommittedThrough < lo { + peerWonHedge = true + } else if race.err == nil { + originWonHedge = true + } + } + if race.err != nil { var oe *originStatusError - if errors.As(err, &oe) { + if errors.As(race.err, &oe) { if oe.status == http.StatusRequestedRangeNotSatisfiable { if objectSize, known := p.knownObjectSize(urlStr); known && start < objectSize { end = min(end, objectSize-1) lastIdx = end / p.blockSize - missRunStart = -1 return true } } oe.writeTo(w) return false } - slog.Error("Block span fetch failed.", "url", urlStr, "blocks", fmt.Sprintf("%d-%d", lo, hi), "error", err) - http.Error(w, err.Error(), http.StatusBadGateway) + slog.Error("Block span fetch failed.", "url", urlStr, "blocks", fmt.Sprintf("%d-%d", lo, hi), "error", race.err) + http.Error(w, race.err.Error(), http.StatusBadGateway) return false } if objectSize, known := p.knownObjectSize(urlStr); known { @@ -268,41 +1210,34 @@ func (p *CacheProxy) serveBlockAligned(w http.ResponseWriter, r *http.Request, r lastIdx = end / p.blockSize } actualHi := min(hi, lastIdx) - if actualHi >= lo { - nOrigin += actualHi - lo + 1 + for idx := lo; idx <= actualHi; idx++ { + if idx <= race.originCommittedThrough { + sources[idx] = "s3" + } else { + sources[idx] = race.source + } } + lo = hi + 1 } - missRunStart = -1 return true } for idx := firstIdx; idx <= lastIdx; idx++ { key := BlockKey(urlStr, idx, p.blockSize) - if p.store.Has(key) { + fill := fills[idx] + if p.store.Has(key) && (fill == nil || !fill.recovery) { if !flushRun(idx - 1) { - return true // error already written + return true } if idx > lastIdx { break } - nLocal++ - continue - } - if p.peers != nil { - peerStart := time.Now() - _, _, ok := p.peers.FetchFromPeers(key, func(rd io.Reader) (int64, error) { - return p.store.PutStream(key, rd) - }) - peerDur += time.Since(peerStart) - if ok { - if !flushRun(idx - 1) { - return true - } - if idx > lastIdx { - break - } - nPeer++ - continue + if fill != nil && fill.isDone() && fill.result.ok { + fill.completeRecovery(true) + sources[idx] = "peer" + } else { + sources[idx] = "local" } + continue } if missRunStart < 0 { missRunStart = idx @@ -335,7 +1270,9 @@ func (p *CacheProxy) serveBlockAligned(w http.ResponseWriter, r *http.Request, r "url", urlStr, "blocks", fmt.Sprintf("%d-%d", lo, runEnd), "error", err) return } - nOrigin += runEnd - lo + 1 + for idx := lo; idx <= runEnd; idx++ { + sources[idx] = "s3" + } } for idx := firstIdx; idx <= lastIdx; idx++ { if p.store.Has(BlockKey(urlStr, idx, p.blockSize)) { @@ -355,6 +1292,20 @@ func (p *CacheProxy) serveBlockAligned(w http.ResponseWriter, r *http.Request, r } } + var nLocal, nPeer, nOrigin int64 + for idx := firstIdx; idx <= lastIdx; idx++ { + switch sources[idx] { + case "peer": + nPeer++ + case "s3": + nOrigin++ + default: + // A concurrent request may have populated a residual block between + // phase checks. It is local from this request's perspective. + nLocal++ + } + } + // Phase 2: open every block before committing response headers. Open file // descriptors keep their contents readable even if the LRU removes the // directory entries while the response is being assembled. If an entry @@ -440,6 +1391,18 @@ func (p *CacheProxy) serveBlockAligned(w http.ResponseWriter, r *http.Request, r } else { cacheMissesTotal.Inc() } + if p.peerPolicy != nil { + switch { + case breakerComparisonExceeded: + p.peerPolicy.recordThresholdComparison(true) + case !breakerComparisonUnknown && ((breakerComparisonSeen && breakerComparisonHealthy) || + peerWonHedge || (nOrigin == 0 && nPeer > 0)): + p.peerPolicy.recordThresholdComparison(false) + } + if originWonHedge || breakerRatioEvidence || peerWonHedge || (nOrigin == 0 && nPeer > 0) { + p.peerPolicy.recordLatencyRatioObservation() + } + } representationSize := "*" if objectSize, known := p.knownObjectSize(urlStr); known { @@ -475,8 +1438,10 @@ func (p *CacheProxy) serveBlockAligned(w http.ResponseWriter, r *http.Request, r cacheBytesServed.WithLabelValues(source).Add(float64(served)) totalDur := time.Since(requestStart) requestDurationSeconds.WithLabelValues("block", source).Observe(totalDur.Seconds()) - slog.Info("Served.", "source", "blocks", "url", urlStr, "range", rangeHeader, + slog.Info("Served.", "source", "blocks", "client", clientAddress(r.RemoteAddr), + "url", urlStr, "range", rangeHeader, "bytes", served, "blocks_local", nLocal, "blocks_peer", nPeer, "blocks_s3", nOrigin, + "blocks_hedged", nHedged, "dur_ms", totalDur.Milliseconds(), "peer_ms", peerDur.Milliseconds(), "s3_ms", s3Dur.Milliseconds(), "write_ms", writeDur.Milliseconds()) return true diff --git a/cmd/cache-proxy/block_serve_test.go b/cmd/cache-proxy/block_serve_test.go index e988b59e..1d4a4708 100644 --- a/cmd/cache-proxy/block_serve_test.go +++ b/cmd/cache-proxy/block_serve_test.go @@ -12,6 +12,7 @@ import ( "sync" "sync/atomic" "testing" + "time" "github.com/prometheus/client_golang/prometheus" ) @@ -96,6 +97,78 @@ func TestFetchOriginSpan(t *testing.T) { } } +func TestFetchOriginSpanReportsFirstBlockCommitBeforeSpanCompletion(t *testing.T) { + const blockSize = int64(1024) + body := make([]byte, 2*blockSize) + releaseSecond := make(chan struct{}) + var releaseOnce sync.Once + release := func() { releaseOnce.Do(func() { close(releaseSecond) }) } + defer release() + + origin := httptest.NewServer(http.HandlerFunc(func(w http.ResponseWriter, _ *http.Request) { + w.Header().Set("Content-Range", fmt.Sprintf("bytes 0-%d/%d", len(body)-1, len(body))) + w.WriteHeader(http.StatusPartialContent) + _, _ = w.Write(body[:blockSize]) + if flusher, ok := w.(http.Flusher); ok { + flusher.Flush() + } + <-releaseSecond + _, _ = w.Write(body[blockSize:]) + })) + t.Cleanup(origin.Close) + t.Cleanup(release) + + store, err := NewDiskCache(t.TempDir(), 80) + if err != nil { + t.Fatal(err) + } + p := NewCacheProxy(store, nil, nil) + p.client = origin.Client() + u, _ := url.Parse(origin.URL + "/bucket/coalesced.parquet") + req := &http.Request{Method: http.MethodGet, URL: u, Host: u.Host, Header: http.Header{}} + + type fetchResult struct { + bytesRead int64 + firstBlockDuration time.Duration + err error + } + done := make(chan fetchResult, 1) + started := time.Now() + go func() { + bytesRead, firstBlockDuration, fetchErr := p.fetchOriginSpanContext( + context.Background(), req, blockSize, 0, 1, nil, + ) + done <- fetchResult{bytesRead: bytesRead, firstBlockDuration: firstBlockDuration, err: fetchErr} + }() + + deadline := time.Now().Add(time.Second) + for !store.Has(BlockKey(u.String(), 0, blockSize)) && time.Now().Before(deadline) { + time.Sleep(time.Millisecond) + } + if !store.Has(BlockKey(u.String(), 0, blockSize)) { + t.Fatal("first origin block was not committed while the span remained open") + } + select { + case result := <-done: + t.Fatalf("span returned before the second block was released: %+v", result) + default: + } + time.Sleep(50 * time.Millisecond) + release() + result := <-done + totalDuration := time.Since(started) + if result.err != nil { + t.Fatalf("fetchOriginSpanContext: %v", result.err) + } + if result.bytesRead != int64(len(body)) { + t.Fatalf("bytes read = %d, want %d", result.bytesRead, len(body)) + } + if result.firstBlockDuration <= 0 || totalDuration-result.firstBlockDuration < 40*time.Millisecond { + t.Fatalf("first-block duration = %v, total = %v; want the committed first block, not full span latency", + result.firstBlockDuration, totalDuration) + } +} + // TestFetchOriginSpanRejects200 guards the immutable-block-cache poisoning // hazard: fetchOriginSpan always sends a Range header, so an origin that // ignores it and returns 200 + the full body would otherwise be split from @@ -282,6 +355,13 @@ func newBlockProxy(t *testing.T, origin *httptest.Server, blockSize int64) (*Cac return p, store } +func setTestPeerPolicy(p *CacheProxy, maxConcurrent, maxBytes int64, headStart time.Duration) { + cfg := defaultPeerFetchPolicyConfig(maxConcurrent, maxBytes) + cfg.minHeadStart = headStart + cfg.maxHeadStart = headStart + p.peerPolicy = newPeerFetchPolicy(cfg) +} + func doBlockRequest(t *testing.T, p *CacheProxy, rawURL, rangeHeader string) *httptest.ResponseRecorder { t.Helper() u, _ := url.Parse(rawURL) @@ -471,6 +551,10 @@ func TestServeBlockAlignedPeerFillCountsAsHit(t *testing.T) { p := NewCacheProxy(store, peerManagerWith([]string{peerAddr}), []string{}) p.blockSize = blockSize p.maxSpanBlocks = 8 + p.peerPolicy.mu.Lock() + p.peerPolicy.directBadStreak = p.peerPolicy.cfg.breakerOpenAfter - 1 + p.peerPolicy.lastDirectBad = p.peerPolicy.cfg.now() + p.peerPolicy.mu.Unlock() hitsBefore := counterValue(t, cacheHitsTotal) missesBefore := counterValue(t, cacheMissesTotal) @@ -500,6 +584,1173 @@ func TestServeBlockAlignedPeerFillCountsAsHit(t *testing.T) { if got := counterValue(t, cacheBytesServed.WithLabelValues("peer")); got != peerBytesBefore+100 { t.Fatalf("cacheBytesServed{peer} delta = %v, want 100 (sourceLabel must resolve to peer when no origin fetch happened)", got-peerBytesBefore) } + p.peerPolicy.mu.Lock() + directBadStreak := p.peerPolicy.directBadStreak + p.peerPolicy.mu.Unlock() + if directBadStreak != 0 { + t.Fatalf("direct bad streak = %d after a pure peer win, want reset", directBadStreak) + } +} + +// TestServeBlockAlignedPeerFillsRunConcurrently locks in the parallel peer +// fill behavior: the peer's /cache/get handlers gate on all three of the +// request's blocks being fetched at once, so a regression to one-at-a-time +// fills can never open the gate — the request would hedge to a closed origin +// and fail instead of assembling the response. +func TestServeBlockAlignedPeerFillsRunConcurrently(t *testing.T) { + const blockSize = 1024 + const nBlocks = 3 + origin := originServer(t, nBlocks*blockSize) + target := origin.URL + "/bucket/f.parquet" + + body := make([]byte, nBlocks*blockSize) + for i := range body { + body[i] = byte(i % 251) + } + keys := make(map[string]int64, nBlocks) + for idx := int64(0); idx < nBlocks; idx++ { + keys[BlockKey(target, idx, blockSize)] = idx + } + + var arrivals int32 + gate := make(chan struct{}) + mux := http.NewServeMux() + mux.HandleFunc("/cache/has", func(w http.ResponseWriter, r *http.Request) { + if _, ok := keys[r.URL.Query().Get("key")]; ok { + w.WriteHeader(http.StatusOK) + return + } + w.WriteHeader(http.StatusNotFound) + }) + mux.HandleFunc("/cache/get", func(w http.ResponseWriter, r *http.Request) { + idx, ok := keys[r.URL.Query().Get("key")] + if !ok { + w.WriteHeader(http.StatusNotFound) + return + } + if atomic.AddInt32(&arrivals, 1) == nBlocks { + close(gate) + } + <-gate + block := body[idx*blockSize : (idx+1)*blockSize] + w.Header().Set("Content-Length", strconv.Itoa(len(block))) + _, _ = w.Write(block) + }) + srv := httptest.NewServer(mux) + t.Cleanup(srv.Close) + + origin.Close() // all blocks must come from the peer; a hedge to origin fails loudly + + store, err := NewDiskCache(t.TempDir(), 80) + if err != nil { + t.Fatal(err) + } + p := NewCacheProxy(store, peerManagerWith([]string{strings.TrimPrefix(srv.URL, "http://")}), []string{}) + p.blockSize = blockSize + p.maxSpanBlocks = 8 + + w := doBlockRequest(t, p, target, fmt.Sprintf("bytes=0-%d", nBlocks*blockSize-1)) + if w.Code != http.StatusPartialContent { + t.Fatalf("status %d, want 206 (sequential fills would starve the gate and hedge into the closed origin)", w.Code) + } + if got := w.Body.Bytes(); string(got) != string(body) { + t.Fatalf("body mismatch: got %d bytes, want %d", len(got), len(body)) + } + if got := atomic.LoadInt32(&arrivals); got != nBlocks { + t.Fatalf("peer /cache/get arrivals = %d, want %d", got, nBlocks) + } +} + +// TestServeBlockAlignedHedgesSlowPeerToOrigin covers the adaptive head start: a +// peer that claims the block but stalls the body transfer must not pin the +// request for the full peer get timeout. Origin starts while peer work is still +// running, and the first successful side completes the response. +func TestServeBlockAlignedHedgesSlowPeerToOrigin(t *testing.T) { + const blockSize = 1024 + origin := originServer(t, 4*blockSize) + t.Cleanup(origin.Close) + target := origin.URL + "/bucket/f.parquet" + key := BlockKey(target, 0, blockSize) + + release := make(chan struct{}) + mux := http.NewServeMux() + mux.HandleFunc("/cache/has", func(w http.ResponseWriter, r *http.Request) { + if r.URL.Query().Get("key") == key { + w.WriteHeader(http.StatusOK) + return + } + w.WriteHeader(http.StatusNotFound) + }) + mux.HandleFunc("/cache/get", func(w http.ResponseWriter, r *http.Request) { + <-release // stall the body transfer past the wait budget + w.WriteHeader(http.StatusNotFound) + }) + srv := httptest.NewServer(mux) + t.Cleanup(srv.Close) + t.Cleanup(func() { close(release) }) // LIFO: unblock the handler before srv.Close waits on it + + store, err := NewDiskCache(t.TempDir(), 80) + if err != nil { + t.Fatal(err) + } + p := NewCacheProxy(store, peerManagerWith([]string{strings.TrimPrefix(srv.URL, "http://")}), []string{}) + p.blockSize = blockSize + p.maxSpanBlocks = 8 + setTestPeerPolicy(p, 32, 32*blockSize, 50*time.Millisecond) + p.peerPolicy.cfg.breakerMinSamples = 1 + p.peerPolicy.cfg.breakerOpenAfter = 1 + + hedgedBefore := counterValue(t, peerHedgesTotal) + originWinsBefore := counterValue(t, peerHedgeWinsTotal.WithLabelValues("origin")) + s3ReadsBefore := counterValue(t, blockReadsTotal.WithLabelValues("s3")) + + w := doBlockRequest(t, p, target, "bytes=0-99") + if w.Code != http.StatusPartialContent { + t.Fatalf("status %d, want 206", w.Code) + } + want := make([]byte, 100) + for i := range want { + want[i] = byte(i % 251) + } + if got := w.Body.Bytes(); string(got) != string(want) { + t.Fatalf("body mismatch: got %d bytes", len(got)) + } + if got := counterValue(t, peerHedgesTotal); got != hedgedBefore+1 { + t.Fatalf("peerHedgesTotal delta = %v, want 1", got-hedgedBefore) + } + if got := counterValue(t, peerHedgeWinsTotal.WithLabelValues("origin")); got != originWinsBefore+1 { + t.Fatalf("origin hedge-win delta = %v, want 1", got-originWinsBefore) + } + if got := counterValue(t, blockReadsTotal.WithLabelValues("s3")); got != s3ReadsBefore+1 { + t.Fatalf("blockReadsTotal{s3} delta = %v, want 1 (hedged block must be served from origin)", got-s3ReadsBefore) + } + if !p.peerPolicy.breakerOpen() { + t.Fatal("threshold-qualified canceled peer lower bound did not open the breaker") + } +} + +func TestAmbiguousOriginWinnerRunsBoundedBreakerMeasurement(t *testing.T) { + const blockSize = int64(1024) + body := make([]byte, blockSize) + origin := httptest.NewServer(http.HandlerFunc(func(w http.ResponseWriter, _ *http.Request) { + time.Sleep(100 * time.Millisecond) + w.Header().Set("Content-Range", fmt.Sprintf("bytes 0-%d/%d", blockSize-1, blockSize)) + w.WriteHeader(http.StatusPartialContent) + _, _ = w.Write(body) + })) + t.Cleanup(origin.Close) + target := origin.URL + "/bucket/abrupt-slowdown.parquet" + key := BlockKey(target, 0, blockSize) + + var peerGets, peerCancels atomic.Int32 + mux := http.NewServeMux() + mux.HandleFunc("/cache/has", func(w http.ResponseWriter, _ *http.Request) { w.WriteHeader(http.StatusOK) }) + mux.HandleFunc("/cache/get", func(w http.ResponseWriter, r *http.Request) { + if r.URL.Query().Get("key") != key { + w.WriteHeader(http.StatusNotFound) + return + } + peerGets.Add(1) + <-r.Context().Done() + peerCancels.Add(1) + }) + peer := httptest.NewServer(mux) + t.Cleanup(peer.Close) + + store, err := NewDiskCache(t.TempDir(), 80) + if err != nil { + t.Fatal(err) + } + p := NewCacheProxy(store, peerManagerWith([]string{strings.TrimPrefix(peer.URL, "http://")}), nil) + p.client = origin.Client() + p.blockSize = blockSize + p.maxSpanBlocks = 8 + cfg := defaultPeerFetchPolicyConfig(32, 32*blockSize) + cfg.minHeadStart = 25 * time.Millisecond + cfg.maxHeadStart = 25 * time.Millisecond + cfg.breakerMinSamples = 1 + cfg.breakerOpenAfter = 1 + p.peerPolicy = newPeerFetchPolicy(cfg) + + w := doBlockRequest(t, p, target, "bytes=0-99") + if w.Code != http.StatusPartialContent { + t.Fatalf("status = %d, want 206", w.Code) + } + deadline := time.Now().Add(time.Second) + for !p.peerPolicy.breakerOpen() && time.Now().Before(deadline) { + time.Sleep(time.Millisecond) + } + if !p.peerPolicy.breakerOpen() { + t.Fatal("breaker did not learn from a bounded measurement after an ambiguous canceled peer") + } + if got := peerGets.Load(); got != 2 { + t.Fatalf("peer GETs = %d, want normal hedge plus one sampled measurement", got) + } + deadline = time.Now().Add(time.Second) + for peerCancels.Load() < 2 && time.Now().Before(deadline) { + time.Sleep(time.Millisecond) + } + if got := peerCancels.Load(); got != 2 { + t.Fatalf("peer cancellations = %d, want both losing transfers canceled", got) + } +} + +func TestServeBlockAlignedOriginWinnerCancelsPeerAndCountsDuplicateBytes(t *testing.T) { + const blockSize = 1024 + origin := originServer(t, 4*blockSize) + t.Cleanup(origin.Close) + target := origin.URL + "/bucket/cancel-peer.parquet" + key := BlockKey(target, 0, blockSize) + + peerCanceled := make(chan struct{}) + mux := http.NewServeMux() + mux.HandleFunc("/cache/has", func(w http.ResponseWriter, r *http.Request) { + if r.URL.Query().Get("key") == key { + w.WriteHeader(http.StatusOK) + return + } + w.WriteHeader(http.StatusNotFound) + }) + mux.HandleFunc("/cache/get", func(w http.ResponseWriter, r *http.Request) { + flusher, _ := w.(http.Flusher) + _, _ = w.Write(make([]byte, 128)) + if flusher != nil { + flusher.Flush() + } + select { + case <-r.Context().Done(): + close(peerCanceled) + case <-time.After(time.Second): + } + }) + peer := httptest.NewServer(mux) + t.Cleanup(peer.Close) + + store, err := NewDiskCache(t.TempDir(), 80) + if err != nil { + t.Fatal(err) + } + p := NewCacheProxy(store, peerManagerWith([]string{strings.TrimPrefix(peer.URL, "http://")}), []string{}) + p.client = origin.Client() + p.blockSize = blockSize + p.maxSpanBlocks = 8 + setTestPeerPolicy(p, 32, 32*blockSize, 10*time.Millisecond) + + cancelsBefore := counterValue(t, peerFetchCancellationsTotal.WithLabelValues("peer")) + duplicatesBefore := counterValue(t, peerHedgeDuplicateBytesTotal.WithLabelValues("peer")) + w := doBlockRequest(t, p, target, "bytes=0-99") + if w.Code != http.StatusPartialContent { + t.Fatalf("status = %d, want 206", w.Code) + } + select { + case <-peerCanceled: + case <-time.After(500 * time.Millisecond): + t.Fatal("origin won but the losing peer transfer was not canceled") + } + deadline := time.Now().Add(time.Second) + for counterValue(t, peerHedgeDuplicateBytesTotal.WithLabelValues("peer")) == duplicatesBefore && time.Now().Before(deadline) { + time.Sleep(time.Millisecond) + } + if got := counterValue(t, peerFetchCancellationsTotal.WithLabelValues("peer")); got != cancelsBefore+1 { + t.Fatalf("peer cancellation delta = %v, want 1", got-cancelsBefore) + } + if got := counterValue(t, peerHedgeDuplicateBytesTotal.WithLabelValues("peer")); got <= duplicatesBefore { + t.Fatal("partial losing peer bytes were not recorded as duplicate traffic") + } +} + +func TestServeBlockAlignedPeerWinnerCancelsOrigin(t *testing.T) { + const blockSize = 1024 + originStarted := make(chan struct{}) + originCanceled := make(chan struct{}) + var startedOnce, canceledOnce sync.Once + origin := httptest.NewServer(http.HandlerFunc(func(_ http.ResponseWriter, r *http.Request) { + startedOnce.Do(func() { close(originStarted) }) + <-r.Context().Done() + canceledOnce.Do(func() { close(originCanceled) }) + })) + t.Cleanup(origin.Close) + target := origin.URL + "/bucket/cancel-origin.parquet" + key := BlockKey(target, 0, blockSize) + data := make([]byte, blockSize) + for i := range data { + data[i] = byte(i % 251) + } + + mux := http.NewServeMux() + mux.HandleFunc("/cache/has", func(w http.ResponseWriter, _ *http.Request) { w.WriteHeader(http.StatusOK) }) + mux.HandleFunc("/cache/get", func(w http.ResponseWriter, r *http.Request) { + if r.URL.Query().Get("key") != key { + w.WriteHeader(http.StatusNotFound) + return + } + time.Sleep(40 * time.Millisecond) + _, _ = w.Write(data) + }) + peer := httptest.NewServer(mux) + t.Cleanup(peer.Close) + + store, err := NewDiskCache(t.TempDir(), 80) + if err != nil { + t.Fatal(err) + } + p := NewCacheProxy(store, peerManagerWith([]string{strings.TrimPrefix(peer.URL, "http://")}), []string{}) + p.client = origin.Client() + p.originTimeout = 200 * time.Millisecond + p.blockSize = blockSize + p.maxSpanBlocks = 8 + setTestPeerPolicy(p, 32, 32*blockSize, 10*time.Millisecond) + + cancelsBefore := counterValue(t, peerFetchCancellationsTotal.WithLabelValues("origin")) + w := doBlockRequest(t, p, target, "bytes=0-99") + if w.Code != http.StatusPartialContent { + t.Fatalf("status = %d, want 206", w.Code) + } + select { + case <-originStarted: + default: + t.Fatal("adaptive head start never launched the origin hedge") + } + select { + case <-originCanceled: + case <-time.After(time.Second): + t.Fatal("peer won but the losing origin transfer was not canceled") + } + if got := counterValue(t, peerFetchCancellationsTotal.WithLabelValues("origin")); got != cancelsBefore+1 { + t.Fatalf("origin cancellation delta = %v, want 1", got-cancelsBefore) + } +} + +func TestServeBlockAlignedQueuedPeerShedsToOriginWithoutStartingLater(t *testing.T) { + const blockSize = 1024 + origin := originServer(t, 4*blockSize) + t.Cleanup(origin.Close) + target := origin.URL + "/bucket/queued.parquet" + key := BlockKey(target, 0, blockSize) + var peerCalls int32 + peerAddr := newPeerServer(t, key, make([]byte, blockSize), &peerCalls, &peerCalls) + + store, err := NewDiskCache(t.TempDir(), 80) + if err != nil { + t.Fatal(err) + } + p := NewCacheProxy(store, peerManagerWith([]string{peerAddr}), []string{}) + p.client = origin.Client() + p.blockSize = blockSize + p.maxSpanBlocks = 8 + setTestPeerPolicy(p, 1, blockSize, 20*time.Millisecond) + + blocker, reason := p.peerPolicy.limiter.acquire(context.Background(), blockSize) + if blocker == nil || reason != "" { + t.Fatalf("occupy limiter = (%v, %q), want permit", blocker, reason) + } + w := doBlockRequest(t, p, target, "bytes=0-99") + blocker.release() + if w.Code != http.StatusPartialContent { + t.Fatalf("status = %d, want 206", w.Code) + } + time.Sleep(40 * time.Millisecond) + if got := atomic.LoadInt32(&peerCalls); got != 0 { + t.Fatalf("queued peer issued %d network calls after its head-start expired", got) + } +} + +func TestLaunchPeerFillsDoesNotStartLaterWorkerBatchesAfterHeadStart(t *testing.T) { + const ( + blockSize = int64(1024) + blockCount = int64(peerFillConcurrency + 4) + ) + target := "http://origin.invalid/bucket/wide.parquet" + + releaseFirstBatch := make(chan struct{}) + var peerCalls atomic.Int32 + mux := http.NewServeMux() + mux.HandleFunc("/cache/has", func(w http.ResponseWriter, _ *http.Request) { + w.WriteHeader(http.StatusOK) + }) + mux.HandleFunc("/cache/get", func(w http.ResponseWriter, _ *http.Request) { + call := peerCalls.Add(1) + if call <= peerFillConcurrency { + <-releaseFirstBatch + } + w.Header().Set("Content-Length", strconv.FormatInt(blockSize, 10)) + _, _ = w.Write(make([]byte, blockSize)) + }) + peer := httptest.NewServer(mux) + t.Cleanup(peer.Close) + + store, err := NewDiskCache(t.TempDir(), 80) + if err != nil { + t.Fatal(err) + } + p := NewCacheProxy(store, peerManagerWith([]string{strings.TrimPrefix(peer.URL, "http://")}), []string{}) + p.blockSize = blockSize + setTestPeerPolicy(p, peerFillConcurrency, peerFillConcurrency*blockSize, 20*time.Millisecond) + + ctx, cancel := context.WithCancel(context.Background()) + t.Cleanup(cancel) + _, allDone, deadline := p.launchPeerFills(ctx, target, 0, blockCount-1) + waitUntil := time.Now().Add(time.Second) + for peerCalls.Load() < peerFillConcurrency && time.Now().Before(waitUntil) { + time.Sleep(time.Millisecond) + } + if got := peerCalls.Load(); got != peerFillConcurrency { + close(releaseFirstBatch) + t.Fatalf("first peer batch calls = %d, want %d", got, peerFillConcurrency) + } + if wait := time.Until(deadline) + 10*time.Millisecond; wait > 0 { + time.Sleep(wait) + } + close(releaseFirstBatch) + + select { + case <-allDone: + case <-time.After(time.Second): + t.Fatal("peer fill workers did not finish") + } + if got := peerCalls.Load(); got != peerFillConcurrency { + t.Fatalf("peer calls = %d, want only the first %d; later batches started after the head-start deadline", got, peerFillConcurrency) + } +} + +func TestServeBlockAlignedGlobalPeerCapAcrossRequests(t *testing.T) { + const blockSize = 1024 + const requests = 4 + origin := originServer(t, 4*blockSize) + t.Cleanup(origin.Close) + + release := make(chan struct{}) + var active, maxActive atomic.Int32 + data := make([]byte, blockSize) + for i := range data { + data[i] = byte(i % 251) + } + mux := http.NewServeMux() + mux.HandleFunc("/cache/has", func(w http.ResponseWriter, _ *http.Request) { w.WriteHeader(http.StatusOK) }) + mux.HandleFunc("/cache/get", func(w http.ResponseWriter, _ *http.Request) { + current := active.Add(1) + defer active.Add(-1) + for { + prior := maxActive.Load() + if current <= prior || maxActive.CompareAndSwap(prior, current) { + break + } + } + <-release + _, _ = w.Write(data) + }) + peer := httptest.NewServer(mux) + t.Cleanup(peer.Close) + + store, err := NewDiskCache(t.TempDir(), 80) + if err != nil { + t.Fatal(err) + } + p := NewCacheProxy(store, peerManagerWith([]string{strings.TrimPrefix(peer.URL, "http://")}), []string{}) + p.client = origin.Client() + p.blockSize = blockSize + p.maxSpanBlocks = 8 + setTestPeerPolicy(p, 2, 2*blockSize, 150*time.Millisecond) + + statuses := make(chan int, requests) + for i := 0; i < requests; i++ { + go func(i int) { + target := fmt.Sprintf("%s/bucket/file-%d.parquet", origin.URL, i) + u, _ := url.Parse(target) + req := &http.Request{Method: http.MethodGet, URL: u, Host: u.Host, + Header: http.Header{"Range": []string{"bytes=0-99"}}} + w := httptest.NewRecorder() + if !p.serveBlockAligned(w, req.WithContext(context.Background()), "bytes=0-99") { + statuses <- 0 + return + } + statuses <- w.Code + }(i) + } + time.Sleep(50 * time.Millisecond) + close(release) + for i := 0; i < requests; i++ { + if status := <-statuses; status != http.StatusPartialContent { + t.Fatalf("request status = %d, want 206", status) + } + } + if got := maxActive.Load(); got > 2 { + t.Fatalf("global concurrent peer GETs = %d, want <= 2", got) + } +} + +func TestServeBlockAlignedKeepsPerRequestPeerFairnessBound(t *testing.T) { + const blockSize = 128 + const nBlocks = 20 + body := make([]byte, nBlocks*blockSize) + for i := range body { + body[i] = byte(i % 251) + } + origin := originServer(t, int64(len(body))) + target := origin.URL + "/bucket/wide.parquet" + + var active, maxActive atomic.Int32 + mux := http.NewServeMux() + mux.HandleFunc("/cache/has", func(w http.ResponseWriter, _ *http.Request) { w.WriteHeader(http.StatusOK) }) + mux.HandleFunc("/cache/get", func(w http.ResponseWriter, r *http.Request) { + current := active.Add(1) + defer active.Add(-1) + for { + prior := maxActive.Load() + if current <= prior || maxActive.CompareAndSwap(prior, current) { + break + } + } + time.Sleep(5 * time.Millisecond) + for idx := int64(0); idx < nBlocks; idx++ { + if r.URL.Query().Get("key") == BlockKey(target, idx, blockSize) { + _, _ = w.Write(body[idx*blockSize : (idx+1)*blockSize]) + return + } + } + w.WriteHeader(http.StatusNotFound) + }) + peer := httptest.NewServer(mux) + t.Cleanup(peer.Close) + origin.Close() + + store, err := NewDiskCache(t.TempDir(), 80) + if err != nil { + t.Fatal(err) + } + p := NewCacheProxy(store, peerManagerWith([]string{strings.TrimPrefix(peer.URL, "http://")}), nil) + p.blockSize = blockSize + p.maxSpanBlocks = nBlocks + setTestPeerPolicy(p, 32, 32*blockSize, 150*time.Millisecond) + + w := doBlockRequest(t, p, target, fmt.Sprintf("bytes=0-%d", len(body)-1)) + if w.Code != http.StatusPartialContent { + t.Fatalf("status = %d, want 206", w.Code) + } + if got := maxActive.Load(); got > peerFillConcurrency { + t.Fatalf("one request used %d concurrent peer GETs, want <= %d", got, peerFillConcurrency) + } +} + +func TestOnePeerBlockDoesNotCancelOriginNeededForRestOfSpan(t *testing.T) { + const blockSize = 1024 + body := make([]byte, 2*blockSize) + for i := range body { + body[i] = byte(i % 251) + } + var originCalls atomic.Int32 + var originCanceled atomic.Bool + var originRange atomic.Value + origin := httptest.NewServer(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { + originCalls.Add(1) + originRange.Store(r.Header.Get("Range")) + select { + case <-time.After(70 * time.Millisecond): + case <-r.Context().Done(): + originCanceled.Store(true) + return + } + w.Header().Set("Content-Range", fmt.Sprintf("bytes 0-%d/%d", len(body)-1, len(body))) + w.WriteHeader(http.StatusPartialContent) + _, _ = w.Write(body) + })) + t.Cleanup(origin.Close) + target := origin.URL + "/bucket/span-race.parquet" + + secondCanceled := make(chan struct{}) + var secondCanceledOnce sync.Once + mux := http.NewServeMux() + mux.HandleFunc("/cache/has", func(w http.ResponseWriter, _ *http.Request) { w.WriteHeader(http.StatusOK) }) + mux.HandleFunc("/cache/get", func(w http.ResponseWriter, r *http.Request) { + switch r.URL.Query().Get("key") { + case BlockKey(target, 0, blockSize): + time.Sleep(35 * time.Millisecond) + _, _ = w.Write(body[:blockSize]) + case BlockKey(target, 1, blockSize): + <-r.Context().Done() + secondCanceledOnce.Do(func() { close(secondCanceled) }) + default: + w.WriteHeader(http.StatusNotFound) + } + }) + peer := httptest.NewServer(mux) + t.Cleanup(peer.Close) + + store, err := NewDiskCache(t.TempDir(), 80) + if err != nil { + t.Fatal(err) + } + p := NewCacheProxy(store, peerManagerWith([]string{strings.TrimPrefix(peer.URL, "http://")}), nil) + p.client = origin.Client() + p.blockSize = blockSize + p.maxSpanBlocks = 8 + setTestPeerPolicy(p, 32, 32*blockSize, 10*time.Millisecond) + + w := doBlockRequest(t, p, target, fmt.Sprintf("bytes=0-%d", len(body)-1)) + if w.Code != http.StatusPartialContent { + t.Fatalf("status = %d, want 206", w.Code) + } + if originCanceled.Load() { + t.Fatal("one completed peer block canceled the origin span still needed by another block") + } + if got := originCalls.Load(); got != 1 { + t.Fatalf("origin calls = %d, want one coalesced span", got) + } + if got, _ := originRange.Load().(string); got != "bytes=0-2047" { + t.Fatalf("origin Range = %q, want bytes=0-2047", got) + } + select { + case <-secondCanceled: + case <-time.After(time.Second): + t.Fatal("origin won without canceling the remaining peer block") + } +} + +func TestOriginCommitCancelsMatchingPeerBeforeWideSpanCompletes(t *testing.T) { + const blockSize = int64(1024) + body := make([]byte, 2*blockSize) + releaseSecond := make(chan struct{}) + var releaseOnce sync.Once + release := func() { releaseOnce.Do(func() { close(releaseSecond) }) } + defer release() + + origin := httptest.NewServer(http.HandlerFunc(func(w http.ResponseWriter, _ *http.Request) { + w.Header().Set("Content-Range", fmt.Sprintf("bytes 0-%d/%d", len(body)-1, len(body))) + w.WriteHeader(http.StatusPartialContent) + _, _ = w.Write(body[:blockSize]) + if flusher, ok := w.(http.Flusher); ok { + flusher.Flush() + } + <-releaseSecond + _, _ = w.Write(body[blockSize:]) + })) + t.Cleanup(origin.Close) + t.Cleanup(release) + target := origin.URL + "/bucket/per-block-cancel.parquet" + + peerCanceled := []chan struct{}{make(chan struct{}), make(chan struct{})} + var canceledOnce [2]sync.Once + mux := http.NewServeMux() + mux.HandleFunc("/cache/has", func(w http.ResponseWriter, _ *http.Request) { w.WriteHeader(http.StatusOK) }) + mux.HandleFunc("/cache/get", func(w http.ResponseWriter, r *http.Request) { + for idx := range int64(2) { + if r.URL.Query().Get("key") != BlockKey(target, idx, blockSize) { + continue + } + <-r.Context().Done() + canceledOnce[idx].Do(func() { close(peerCanceled[idx]) }) + return + } + w.WriteHeader(http.StatusNotFound) + }) + peer := httptest.NewServer(mux) + t.Cleanup(peer.Close) + + store, err := NewDiskCache(t.TempDir(), 80) + if err != nil { + t.Fatal(err) + } + p := NewCacheProxy(store, peerManagerWith([]string{strings.TrimPrefix(peer.URL, "http://")}), nil) + p.client = origin.Client() + p.blockSize = blockSize + p.maxSpanBlocks = 8 + setTestPeerPolicy(p, 32, 32*blockSize, 10*time.Millisecond) + + response := make(chan *httptest.ResponseRecorder, 1) + go func() { + response <- doBlockRequest(t, p, target, fmt.Sprintf("bytes=0-%d", len(body)-1)) + }() + select { + case <-peerCanceled[0]: + case <-time.After(time.Second): + t.Fatal("first peer was not canceled when origin committed its block") + } + select { + case <-peerCanceled[1]: + t.Fatal("second peer was canceled before origin committed the second block") + default: + } + select { + case <-response: + t.Fatal("request completed while the second origin block was still withheld") + default: + } + release() + if w := <-response; w.Code != http.StatusPartialContent { + t.Fatalf("status = %d, want 206", w.Code) + } + select { + case <-peerCanceled[1]: + case <-time.After(time.Second): + t.Fatal("second peer was not canceled when origin committed its block") + } +} + +func TestWideSpanRecoveryIsBoundedFromFirstOriginBlockCommit(t *testing.T) { + const blockSize = int64(1024) + body := make([]byte, 2*blockSize) + releaseSecond := make(chan struct{}) + var releaseOnce sync.Once + release := func() { releaseOnce.Do(func() { close(releaseSecond) }) } + defer release() + + origin := httptest.NewServer(http.HandlerFunc(func(w http.ResponseWriter, _ *http.Request) { + time.Sleep(40 * time.Millisecond) + w.Header().Set("Content-Range", fmt.Sprintf("bytes 0-%d/%d", len(body)-1, len(body))) + w.WriteHeader(http.StatusPartialContent) + _, _ = w.Write(body[:blockSize]) + if flusher, ok := w.(http.Flusher); ok { + flusher.Flush() + } + <-releaseSecond + _, _ = w.Write(body[blockSize:]) + })) + t.Cleanup(origin.Close) + t.Cleanup(release) + target := origin.URL + "/bucket/wide-recovery.parquet" + key := BlockKey(target, 0, blockSize) + + peerCanceled := make(chan struct{}) + var peerCanceledOnce sync.Once + mux := http.NewServeMux() + mux.HandleFunc("/cache/has", func(w http.ResponseWriter, _ *http.Request) { w.WriteHeader(http.StatusOK) }) + mux.HandleFunc("/cache/get", func(w http.ResponseWriter, r *http.Request) { + if r.URL.Query().Get("key") != key { + w.WriteHeader(http.StatusNotFound) + return + } + <-r.Context().Done() + peerCanceledOnce.Do(func() { close(peerCanceled) }) + }) + peer := httptest.NewServer(mux) + t.Cleanup(peer.Close) + + store, err := NewDiskCache(t.TempDir(), 80) + if err != nil { + t.Fatal(err) + } + p := NewCacheProxy(store, peerManagerWith([]string{strings.TrimPrefix(peer.URL, "http://")}), nil) + p.client = origin.Client() + p.blockSize = blockSize + p.maxSpanBlocks = 8 + now := time.Unix(1_000, 0) + cfg := defaultPeerFetchPolicyConfig(32, 32*blockSize) + cfg.now = func() time.Time { return now } + p.peerPolicy = newPeerFetchPolicy(cfg) + p.peerPolicy.mu.Lock() + p.peerPolicy.open = true + p.peerPolicy.nextProbe = now + p.peerPolicy.mu.Unlock() + + response := make(chan *httptest.ResponseRecorder, 1) + go func() { + response <- doBlockRequest(t, p, target, fmt.Sprintf("bytes=0-%d", len(body)-1)) + }() + select { + case <-peerCanceled: + case <-time.After(300 * time.Millisecond): + t.Fatal("recovery peer outlived 1.5x first-block latency while the wider origin span was stalled") + } + select { + case <-response: + t.Fatal("request completed while the second origin block was still withheld") + default: + } + release() + if w := <-response; w.Code != http.StatusPartialContent { + t.Fatalf("status = %d, want 206", w.Code) + } + if !p.peerPolicy.breakerOpen() { + t.Fatal("unhealthy wide-span recovery sample closed the breaker") + } +} + +func TestRecoveryIsBoundedWhenOriginStallsBeforeFirstBlock(t *testing.T) { + const blockSize = int64(1024) + body := make([]byte, blockSize) + releaseOrigin := make(chan struct{}) + var releaseOnce sync.Once + release := func() { releaseOnce.Do(func() { close(releaseOrigin) }) } + defer release() + + origin := httptest.NewServer(http.HandlerFunc(func(w http.ResponseWriter, _ *http.Request) { + <-releaseOrigin + w.Header().Set("Content-Range", fmt.Sprintf("bytes 0-%d/%d", blockSize-1, blockSize)) + w.WriteHeader(http.StatusPartialContent) + _, _ = w.Write(body) + })) + t.Cleanup(origin.Close) + target := origin.URL + "/bucket/pre-first-block-stall.parquet" + key := BlockKey(target, 0, blockSize) + + peerCanceled := make(chan struct{}) + var canceledOnce sync.Once + mux := http.NewServeMux() + mux.HandleFunc("/cache/has", func(w http.ResponseWriter, _ *http.Request) { w.WriteHeader(http.StatusOK) }) + mux.HandleFunc("/cache/get", func(w http.ResponseWriter, r *http.Request) { + if r.URL.Query().Get("key") != key { + w.WriteHeader(http.StatusNotFound) + return + } + <-r.Context().Done() + canceledOnce.Do(func() { close(peerCanceled) }) + }) + peer := httptest.NewServer(mux) + t.Cleanup(peer.Close) + + store, err := NewDiskCache(t.TempDir(), 80) + if err != nil { + t.Fatal(err) + } + p := NewCacheProxy(store, peerManagerWith([]string{strings.TrimPrefix(peer.URL, "http://")}), nil) + p.client = origin.Client() + p.blockSize = blockSize + p.maxSpanBlocks = 8 + now := time.Unix(1_000, 0) + cfg := defaultPeerFetchPolicyConfig(32, 32*blockSize) + cfg.now = func() time.Time { return now } + p.peerPolicy = newPeerFetchPolicy(cfg) + p.peerPolicy.observeOriginFirstBlock(50 * time.Millisecond) + p.peerPolicy.mu.Lock() + p.peerPolicy.open = true + p.peerPolicy.nextProbe = now + p.peerPolicy.mu.Unlock() + + response := make(chan *httptest.ResponseRecorder, 1) + go func() { + response <- doBlockRequest(t, p, target, "bytes=0-99") + }() + select { + case <-peerCanceled: + case <-time.After(250 * time.Millisecond): + t.Fatal("recovery peer outlived the rolling-origin fallback while origin had no first byte") + } + select { + case <-response: + t.Fatal("request completed while origin was still withheld") + default: + } + release() + if w := <-response; w.Code != http.StatusPartialContent { + t.Fatalf("status = %d, want 206", w.Code) + } + if !p.peerPolicy.breakerOpen() { + t.Fatal("timed-out recovery sample closed the breaker") + } +} + +func TestConcurrentIdenticalHedgesShareOriginSpan(t *testing.T) { + const blockSize = 1024 + body := make([]byte, blockSize) + var originCalls atomic.Int32 + bothPeersStarted := make(chan struct{}) + origin := httptest.NewServer(http.HandlerFunc(func(w http.ResponseWriter, _ *http.Request) { + originCalls.Add(1) + <-bothPeersStarted + time.Sleep(50 * time.Millisecond) + w.Header().Set("Content-Range", fmt.Sprintf("bytes 0-%d/%d", blockSize-1, blockSize)) + w.WriteHeader(http.StatusPartialContent) + _, _ = w.Write(body) + })) + t.Cleanup(origin.Close) + target := origin.URL + "/bucket/shared-span.parquet" + key := BlockKey(target, 0, blockSize) + + var peerArrivals atomic.Int32 + normalPeerCanceled := []chan struct{}{make(chan struct{}), make(chan struct{})} + mux := http.NewServeMux() + mux.HandleFunc("/cache/has", func(w http.ResponseWriter, _ *http.Request) { w.WriteHeader(http.StatusOK) }) + mux.HandleFunc("/cache/get", func(w http.ResponseWriter, r *http.Request) { + if r.URL.Query().Get("key") != key { + w.WriteHeader(http.StatusNotFound) + return + } + arrival := peerArrivals.Add(1) + if arrival == 2 { + close(bothPeersStarted) + } + <-r.Context().Done() + if arrival <= int32(len(normalPeerCanceled)) { + close(normalPeerCanceled[arrival-1]) + } + }) + peer := httptest.NewServer(mux) + t.Cleanup(peer.Close) + + store, err := NewDiskCache(t.TempDir(), 80) + if err != nil { + t.Fatal(err) + } + p := NewCacheProxy(store, peerManagerWith([]string{strings.TrimPrefix(peer.URL, "http://")}), nil) + p.client = origin.Client() + p.blockSize = blockSize + p.maxSpanBlocks = 8 + setTestPeerPolicy(p, 32, 32*blockSize, 10*time.Millisecond) + + start := make(chan struct{}) + statuses := make(chan int, 2) + for i := 0; i < 2; i++ { + go func() { + <-start + u, _ := url.Parse(target) + req := (&http.Request{Method: http.MethodGet, URL: u, Host: u.Host, + Header: http.Header{"Range": []string{"bytes=0-99"}}}).WithContext(context.Background()) + w := httptest.NewRecorder() + if !p.serveBlockAligned(w, req, "bytes=0-99") { + statuses <- 0 + return + } + statuses <- w.Code + }() + } + close(start) + for i := 0; i < 2; i++ { + if status := <-statuses; status != http.StatusPartialContent { + t.Fatalf("status = %d, want 206", status) + } + } + if got := originCalls.Load(); got != 1 { + t.Fatalf("identical concurrent hedges made %d origin calls, want 1", got) + } + for i, canceled := range normalPeerCanceled { + select { + case <-canceled: + case <-time.After(time.Second): + t.Fatalf("shared origin commit did not cancel peer fill for waiter %d", i+1) + } + } +} + +func TestOpenBreakerRecoveryProbeDoesNotWaitOrGetCanceledByAdjacentBlocks(t *testing.T) { + const blockSize = 1024 + body := make([]byte, 2*blockSize) + for i := range body { + body[i] = byte(i % 251) + } + originStarted := make(chan struct{}) + var originOnce sync.Once + var originCalls atomic.Int32 + origin := httptest.NewServer(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { + originCalls.Add(1) + originOnce.Do(func() { close(originStarted) }) + time.Sleep(80 * time.Millisecond) + start, end, ok := parseAbsoluteRange(r.Header.Get("Range")) + if !ok { + t.Fatalf("origin Range = %q, want absolute range", r.Header.Get("Range")) + } + end = min(end, int64(len(body))-1) + w.Header().Set("Content-Range", fmt.Sprintf("bytes %d-%d/%d", start, end, len(body))) + w.WriteHeader(http.StatusPartialContent) + _, _ = w.Write(body[start : end+1]) + })) + t.Cleanup(origin.Close) + target := origin.URL + "/bucket/recovery.parquet" + + var peerGets atomic.Int32 + mux := http.NewServeMux() + mux.HandleFunc("/cache/has", func(w http.ResponseWriter, _ *http.Request) { w.WriteHeader(http.StatusOK) }) + mux.HandleFunc("/cache/get", func(w http.ResponseWriter, r *http.Request) { + peerGets.Add(1) + select { + case <-originStarted: + case <-time.After(20 * time.Millisecond): + t.Error("open-breaker request delayed origin for its recovery probe") + } + time.Sleep(20 * time.Millisecond) + for idx := int64(0); idx < 2; idx++ { + if r.URL.Query().Get("key") == BlockKey(target, idx, blockSize) { + _, _ = w.Write(body[idx*blockSize : (idx+1)*blockSize]) + return + } + } + w.WriteHeader(http.StatusNotFound) + }) + peer := httptest.NewServer(mux) + t.Cleanup(peer.Close) + + store, err := NewDiskCache(t.TempDir(), 80) + if err != nil { + t.Fatal(err) + } + p := NewCacheProxy(store, peerManagerWith([]string{strings.TrimPrefix(peer.URL, "http://")}), nil) + p.client = origin.Client() + p.blockSize = blockSize + p.maxSpanBlocks = 8 + now := time.Unix(1_000, 0) + cfg := defaultPeerFetchPolicyConfig(32, 32*blockSize) + cfg.now = func() time.Time { return now } + cfg.breakerCloseAfter = 1 + p.peerPolicy = newPeerFetchPolicy(cfg) + p.peerPolicy.mu.Lock() + p.peerPolicy.open = true + p.peerPolicy.nextProbe = now + p.peerPolicy.mu.Unlock() + + w := doBlockRequest(t, p, target, fmt.Sprintf("bytes=0-%d", len(body)-1)) + if w.Code != http.StatusPartialContent { + t.Fatalf("status = %d, want 206", w.Code) + } + if got := peerGets.Load(); got != 1 { + t.Fatalf("recovery peer GETs = %d, want exactly one sampled block", got) + } + if got := originCalls.Load(); got != 1 { + t.Fatalf("origin calls = %d, want one coalesced span; recovery sampling must not serialize origin", got) + } + if p.peerPolicy.breakerOpen() { + t.Fatal("recovered peer beat origin but the breaker remained open") + } +} + +func TestOpenBreakerRecoveryAcceptsPeerWithinLatencyRatioAfterOriginWins(t *testing.T) { + const blockSize = int64(1024) + body := make([]byte, blockSize) + originStarted := make(chan struct{}) + var originOnce sync.Once + var originCalls atomic.Int32 + origin := httptest.NewServer(http.HandlerFunc(func(w http.ResponseWriter, _ *http.Request) { + originCalls.Add(1) + originOnce.Do(func() { close(originStarted) }) + time.Sleep(100 * time.Millisecond) + w.Header().Set("Content-Range", fmt.Sprintf("bytes 0-%d/%d", blockSize-1, blockSize)) + w.WriteHeader(http.StatusPartialContent) + _, _ = w.Write(body) + })) + t.Cleanup(origin.Close) + target := origin.URL + "/bucket/marginal-recovery.parquet" + key := BlockKey(target, 0, blockSize) + + peerFinished := make(chan struct{}) + var peerFinishOnce sync.Once + var peerGets atomic.Int32 + mux := http.NewServeMux() + mux.HandleFunc("/cache/has", func(w http.ResponseWriter, _ *http.Request) { w.WriteHeader(http.StatusOK) }) + mux.HandleFunc("/cache/get", func(w http.ResponseWriter, r *http.Request) { + if r.URL.Query().Get("key") != key { + w.WriteHeader(http.StatusNotFound) + return + } + peerGets.Add(1) + <-originStarted + time.Sleep(130 * time.Millisecond) // 1.3x origin: slower, but below the 1.5x breaker threshold. + w.Header().Set("Content-Length", strconv.FormatInt(blockSize, 10)) + _, _ = w.Write(body) + peerFinishOnce.Do(func() { close(peerFinished) }) + }) + peer := httptest.NewServer(mux) + t.Cleanup(peer.Close) + + store, err := NewDiskCache(t.TempDir(), 80) + if err != nil { + t.Fatal(err) + } + p := NewCacheProxy(store, peerManagerWith([]string{strings.TrimPrefix(peer.URL, "http://")}), nil) + p.client = origin.Client() + p.blockSize = blockSize + p.maxSpanBlocks = 8 + now := time.Unix(1_000, 0) + cfg := defaultPeerFetchPolicyConfig(32, 32*blockSize) + cfg.now = func() time.Time { return now } + cfg.breakerCloseAfter = 1 + p.peerPolicy = newPeerFetchPolicy(cfg) + p.peerPolicy.mu.Lock() + p.peerPolicy.open = true + p.peerPolicy.nextProbe = now + p.peerPolicy.mu.Unlock() + + w := doBlockRequest(t, p, target, "bytes=0-99") + if w.Code != http.StatusPartialContent { + t.Fatalf("status = %d, want 206", w.Code) + } + select { + case <-peerFinished: + t.Fatal("open-breaker request waited for a slower diagnostic peer instead of returning origin") + default: + } + select { + case <-peerFinished: + case <-time.After(time.Second): + t.Fatal("recovery peer was canceled when origin won") + } + deadline := time.Now().Add(time.Second) + for p.peerPolicy.breakerOpen() && time.Now().Before(deadline) { + time.Sleep(time.Millisecond) + } + if p.peerPolicy.breakerOpen() { + t.Fatal("breaker stayed open even though sampled peer latency was within 1.5x origin") + } + if got := originCalls.Load(); got != 1 { + t.Fatalf("origin calls = %d, want 1", got) + } + if got := peerGets.Load(); got != 1 { + t.Fatalf("recovery peer GETs = %d, want 1", got) + } +} + +func TestOpenBreakerRecoveryCancelsPeerAtLatencyRatioBoundary(t *testing.T) { + const blockSize = int64(1024) + body := make([]byte, blockSize) + originStarted := make(chan struct{}) + var originOnce sync.Once + origin := httptest.NewServer(http.HandlerFunc(func(w http.ResponseWriter, _ *http.Request) { + originOnce.Do(func() { close(originStarted) }) + time.Sleep(100 * time.Millisecond) + w.Header().Set("Content-Range", fmt.Sprintf("bytes 0-%d/%d", blockSize-1, blockSize)) + w.WriteHeader(http.StatusPartialContent) + _, _ = w.Write(body) + })) + t.Cleanup(origin.Close) + target := origin.URL + "/bucket/slow-recovery.parquet" + key := BlockKey(target, 0, blockSize) + + peerCanceled := make(chan struct{}) + var canceledOnce sync.Once + mux := http.NewServeMux() + mux.HandleFunc("/cache/has", func(w http.ResponseWriter, _ *http.Request) { w.WriteHeader(http.StatusOK) }) + mux.HandleFunc("/cache/get", func(w http.ResponseWriter, r *http.Request) { + if r.URL.Query().Get("key") != key { + w.WriteHeader(http.StatusNotFound) + return + } + <-originStarted + <-r.Context().Done() + canceledOnce.Do(func() { close(peerCanceled) }) + }) + peer := httptest.NewServer(mux) + t.Cleanup(peer.Close) + + store, err := NewDiskCache(t.TempDir(), 80) + if err != nil { + t.Fatal(err) + } + p := NewCacheProxy(store, peerManagerWith([]string{strings.TrimPrefix(peer.URL, "http://")}), nil) + p.client = origin.Client() + p.blockSize = blockSize + p.maxSpanBlocks = 8 + now := time.Unix(1_000, 0) + cfg := defaultPeerFetchPolicyConfig(32, 32*blockSize) + cfg.now = func() time.Time { return now } + p.peerPolicy = newPeerFetchPolicy(cfg) + p.peerPolicy.mu.Lock() + p.peerPolicy.open = true + p.peerPolicy.nextProbe = now + p.peerPolicy.mu.Unlock() + + cancellationsBefore := counterValue(t, peerFetchCancellationsTotal.WithLabelValues("peer")) + w := doBlockRequest(t, p, target, "bytes=0-99") + if w.Code != http.StatusPartialContent { + t.Fatalf("status = %d, want 206", w.Code) + } + select { + case <-peerCanceled: + case <-time.After(time.Second): + t.Fatal("recovery peer exceeded 1.5x origin without cancellation") + } + if !p.peerPolicy.breakerOpen() { + t.Fatal("unhealthy recovery sample closed the breaker") + } + if got := counterValue(t, peerFetchCancellationsTotal.WithLabelValues("peer")); got != cancellationsBefore+1 { + t.Fatalf("peer cancellation delta = %v, want 1", got-cancellationsBefore) + } } // TestServeBlockAlignedDoesNotReverifyPastObjectEOF covers the cold-request @@ -853,6 +2104,53 @@ func TestHandleProxyBlockModeRecordsInflightAndDuration(t *testing.T) { } } +func TestBlockOriginFetchUpdatesOriginInflightGauge(t *testing.T) { + const blockSize = 1024 + started := make(chan struct{}) + release := make(chan struct{}) + origin := httptest.NewServer(http.HandlerFunc(func(w http.ResponseWriter, _ *http.Request) { + close(started) + <-release + w.Header().Set("Content-Range", "bytes 0-1023/1024") + w.WriteHeader(http.StatusPartialContent) + _, _ = w.Write(make([]byte, blockSize)) + })) + t.Cleanup(origin.Close) + p, _ := newBlockProxy(t, origin, blockSize) + p.blockMode = true + originURL, _ := url.Parse(origin.URL) + p.cacheHostSuffixes = []string{originURL.Host} + + before := gaugeValue(t, originFetchInFlight) + done := make(chan int, 1) + go func() { + u, _ := url.Parse(origin.URL + "/bucket/inflight.parquet") + req := httptest.NewRequest(http.MethodGet, u.String(), nil) + req.URL = u + req.Header.Set("Range", "bytes=0-99") + w := httptest.NewRecorder() + p.HandleProxy(w, req) + done <- w.Code + }() + + select { + case <-started: + case <-time.After(time.Second): + t.Fatal("block origin request did not start") + } + during := gaugeValue(t, originFetchInFlight) + close(release) + if status := <-done; status != http.StatusPartialContent { + t.Fatalf("status = %d, want 206", status) + } + if during != before+1 { + t.Fatalf("originFetchInFlight during block fetch = %v, want %v", during, before+1) + } + if got := gaugeValue(t, originFetchInFlight); got != before { + t.Fatalf("originFetchInFlight after block fetch = %v, want %v", got, before) + } +} + func TestHandleProxyOversizedBlockSpanFallsBackToLegacy(t *testing.T) { const blockSize = int64(1024) origin := originServer(t, 4*blockSize) diff --git a/cmd/cache-proxy/main.go b/cmd/cache-proxy/main.go index 32a85a02..e741c830 100644 --- a/cmd/cache-proxy/main.go +++ b/cmd/cache-proxy/main.go @@ -126,7 +126,15 @@ func main() { blockMode := os.Getenv("CACHE_BLOCK_MODE") == "on" blockSize := envInt64("CACHE_BLOCK_SIZE_BYTES", 8<<20) maxSpanBlocks := envInt64("CACHE_BLOCK_MAX_SPAN_BLOCKS", 8) - slog.Info("Block mode configured.", "enabled", blockMode, "block_size", blockSize, "max_span_blocks", maxSpanBlocks) + peerFetchMaxConcurrency := envPositiveInt64("CACHE_PEER_FETCH_MAX_CONCURRENCY", defaultPeerFetchMaxConcurrent) + peerFetchMaxBytes := envPositiveInt64("CACHE_PEER_FETCH_MAX_BYTES", defaultPeerFetchMaxBytes(peerFetchMaxConcurrency, blockSize)) + slog.Info("Block mode configured.", + "enabled", blockMode, + "block_size", blockSize, + "max_span_blocks", maxSpanBlocks, + "peer_fetch_max_concurrency", peerFetchMaxConcurrency, + "peer_fetch_max_bytes", peerFetchMaxBytes, + ) // Initialize cache store store, err := NewDiskCache(cacheDir, maxPercent) @@ -146,6 +154,7 @@ func main() { proxy.blockMode = blockMode proxy.blockSize = blockSize proxy.maxSpanBlocks = maxSpanBlocks + proxy.peerPolicy = newPeerFetchPolicy(defaultPeerFetchPolicyConfig(peerFetchMaxConcurrency, peerFetchMaxBytes)) // Forward HTTP proxy (DuckDB httpfs traffic). ServeMux can't match absolute // URLs in forward-proxy requests, so use the handler directly. @@ -227,3 +236,15 @@ func envInt64(key string, def int64) int64 { } return n } + +// envPositiveInt64 is used for resource ceilings: zero or a negative value +// would either deadlock all acquisitions or silently disable protection, so +// invalid values fall back to the documented safe default. +func envPositiveInt64(key string, def int64) int64 { + n := envInt64(key, def) + if n <= 0 { + slog.Warn("Non-positive integer env var; using default.", "key", key, "value", n, "default", def) + return def + } + return n +} diff --git a/cmd/cache-proxy/main_test.go b/cmd/cache-proxy/main_test.go new file mode 100644 index 00000000..11df644f --- /dev/null +++ b/cmd/cache-proxy/main_test.go @@ -0,0 +1,37 @@ +package main + +import "testing" + +func TestEnvPositiveInt64(t *testing.T) { + tests := []struct { + name string + value string + want int64 + }{ + {name: "unset", want: 32}, + {name: "valid", value: "64", want: 64}, + {name: "zero", value: "0", want: 32}, + {name: "negative", value: "-1", want: 32}, + {name: "invalid", value: "many", want: 32}, + } + for _, tt := range tests { + t.Run(tt.name, func(t *testing.T) { + t.Setenv("TEST_POSITIVE_INT64", tt.value) + if got := envPositiveInt64("TEST_POSITIVE_INT64", 32); got != tt.want { + t.Fatalf("envPositiveInt64 = %d, want %d", got, tt.want) + } + }) + } +} + +func TestDefaultPeerFetchMaxBytesTracksBlockSize(t *testing.T) { + if got, want := defaultPeerFetchMaxBytes(32, 1<<20), int64(32<<20); got != want { + t.Fatalf("1 MiB blocks: default bytes = %d, want %d", got, want) + } + if got, want := defaultPeerFetchMaxBytes(32, 8<<20), int64(256<<20); got != want { + t.Fatalf("8 MiB blocks: default bytes = %d, want %d", got, want) + } + if got, want := defaultPeerFetchMaxBytes(64, 1<<20), int64(64<<20); got != want { + t.Fatalf("64-way sweep: default bytes = %d, want %d", got, want) + } +} diff --git a/cmd/cache-proxy/peer_fetch_control.go b/cmd/cache-proxy/peer_fetch_control.go new file mode 100644 index 00000000..d52c2b4e --- /dev/null +++ b/cmd/cache-proxy/peer_fetch_control.go @@ -0,0 +1,883 @@ +package main + +import ( + "context" + "io" + "sort" + "sync" + "sync/atomic" + "time" + + "github.com/prometheus/client_golang/prometheus" + "github.com/prometheus/client_golang/prometheus/promauto" + "golang.org/x/sync/semaphore" +) + +var ( + peerHedgesTotal = promauto.NewCounter(prometheus.CounterOpts{ + Name: "cache_proxy_peer_hedges_total", + Help: "Origin span fetches started while every block in the span was still eligible to arrive from peers", + }) + peerHedgeWinsTotal = promauto.NewCounterVec(prometheus.CounterOpts{ + Name: "cache_proxy_peer_hedge_wins_total", + Help: "Completed peer/origin races by winning side", + }, []string{"winner"}) // peer, origin + peerFetchCancellationsTotal = promauto.NewCounterVec(prometheus.CounterOpts{ + Name: "cache_proxy_fetch_cancellations_total", + Help: "Hedged transfers canceled after the other side won", + }, []string{"side"}) // peer, origin + peerHedgeDuplicateBytesTotal = promauto.NewCounterVec(prometheus.CounterOpts{ + Name: "cache_proxy_hedge_duplicate_bytes_total", + Help: "Bytes received by a losing hedged transfer before cancellation", + }, []string{"side"}) // peer, origin + latePeerSuccessesTotal = promauto.NewCounter(prometheus.CounterOpts{ + Name: "cache_proxy_late_peer_successes_total", + Help: "Peer transfers that still completed successfully after origin won", + }) + peerBreakerTransitionsTotal = promauto.NewCounterVec(prometheus.CounterOpts{ + Name: "cache_proxy_peer_breaker_transitions_total", + Help: "Peer circuit-breaker state transitions", + }, []string{"state"}) // open, closed + peerBreakerState = promauto.NewGauge(prometheus.GaugeOpts{ + Name: "cache_proxy_peer_breaker_state", + Help: "Whether peer lookup is circuit-broken (1=open, 0=closed)", + }) + peerFetchInFlight = promauto.NewGauge(prometheus.GaugeOpts{ + Name: "cache_proxy_peer_fetches_in_flight", + Help: "Peer lookup/body transfers admitted by the process-wide limiter", + }) + peerFetchBytesInFlight = promauto.NewGauge(prometheus.GaugeOpts{ + Name: "cache_proxy_peer_fetch_bytes_in_flight", + Help: "Bytes reserved by admitted peer transfers", + }) + peerFetchShedTotal = promauto.NewCounterVec(prometheus.CounterOpts{ + Name: "cache_proxy_peer_fetch_shed_total", + Help: "Peer fetches skipped before network I/O, by reason", + }, []string{"reason"}) // deadline, capacity, canceled, breaker, unbounded, unconfigured + peerFetchQueueDuration = promauto.NewHistogram(prometheus.HistogramOpts{ + Name: "cache_proxy_peer_fetch_queue_duration_seconds", + Help: "Time spent waiting for process-wide peer count and byte permits", + Buckets: prometheus.ExponentialBuckets(0.001, 2, 10), + }) + peerFetchDuration = promauto.NewHistogramVec(prometheus.HistogramOpts{ + Name: "cache_proxy_peer_fetch_duration_seconds", + Help: "Admitted peer lookup plus body-transfer duration", + Buckets: prometheus.ExponentialBuckets(0.001, 2, 14), + }, []string{"outcome"}) // hit, miss, canceled + originSpanFetchDuration = promauto.NewHistogramVec(prometheus.HistogramOpts{ + Name: "cache_proxy_origin_span_fetch_duration_seconds", + Help: "Block-aligned origin span fetch duration", + Buckets: prometheus.ExponentialBuckets(0.001, 2, 14), + }, []string{"outcome"}) // success, error, canceled + peerHedgeHeadStartSeconds = promauto.NewGauge(prometheus.GaugeOpts{ + Name: "cache_proxy_peer_hedge_head_start_seconds", + Help: "Current adaptive peer head-start before an origin hedge", + }) + peerFetchLatencyEWMASeconds = promauto.NewGauge(prometheus.GaugeOpts{ + Name: "cache_proxy_peer_fetch_latency_ewma_seconds", + Help: "EWMA of successful peer block fetches and threshold-qualified canceled lower bounds", + }) + originFetchLatencyEWMASeconds = promauto.NewGauge(prometheus.GaugeOpts{ + Name: "cache_proxy_origin_fetch_latency_ewma_seconds", + Help: "EWMA of time through a validated, atomically committed first origin block", + }) +) + +const ( + defaultPeerFetchMaxConcurrent = int64(32) + peerLatencyWindowSize = 64 + defaultPeerHedgeMinDelay = 25 * time.Millisecond + defaultPeerHedgeMaxDelay = 150 * time.Millisecond + defaultPeerBreakerRatio = 1.5 + defaultPeerBreakerOpenAfter = 8 + defaultPeerBreakerCloseAfter = 3 + defaultPeerBreakerProbeEvery = 5 * time.Second + defaultPeerBreakerMinSamples = 8 + peerLatencyEWMAAlpha = 0.2 +) + +// defaultPeerFetchMaxBytes keeps one complete block reservation available for +// every configured concurrent fetch. It follows CACHE_BLOCK_SIZE_BYTES so the +// deployed 1 MiB configuration at concurrency 32 reserves 32 MiB, while the +// source defaults reserve 256 MiB. +func defaultPeerFetchMaxBytes(maxConcurrent, blockSize int64) int64 { + if maxConcurrent <= 0 { + maxConcurrent = defaultPeerFetchMaxConcurrent + } + if blockSize <= 0 { + blockSize = 8 << 20 + } + const maxInt64 = int64(^uint64(0) >> 1) + if blockSize > maxInt64/maxConcurrent { + return maxInt64 + } + return blockSize * maxConcurrent +} + +// peerFetchLimiter enforces process-wide count and reserved-byte ceilings. +// Callers use a context whose deadline is the hedge start: a queued peer fetch +// that cannot get both permits before then is shed to origin and never starts +// later. The reservation is pessimistically one complete cache block. +type peerFetchLimiter struct { + count *semaphore.Weighted + bytes *semaphore.Weighted + maxBytes int64 + + inFlight atomic.Int64 + bytesInFlight atomic.Int64 +} + +type peerFetchPermit struct { + limiter *peerFetchLimiter + bytes int64 + once sync.Once +} + +type controlledPeerFetchResult struct { + bytes int64 + duration time.Duration + ok bool + started bool +} + +type peerFetchDecision struct { + allowed bool + nonBlocking bool +} + +// fetchFromPeers applies the process-wide breaker and count/byte limits around +// the complete peer lookup plus body transfer. acquireDeadline is the absolute +// adaptive hedge start; a request still queued then is permanently shed. +func (p *CacheProxy) fetchFromPeers( + ctx context.Context, + acquireDeadline time.Time, + reservedBytes int64, + cacheKey string, + sink func(io.Reader) (int64, error), + decision peerFetchDecision, + observeLatency bool, + onStart func(), +) controlledPeerFetchResult { + if p.peers == nil { + return controlledPeerFetchResult{} + } + policy := p.peerPolicy + if policy == nil { + peerFetchShedTotal.WithLabelValues("unconfigured").Inc() + return controlledPeerFetchResult{} + } + if !decision.allowed { + peerFetchShedTotal.WithLabelValues("breaker").Inc() + return controlledPeerFetchResult{} + } + if ctx.Err() != nil { + peerFetchShedTotal.WithLabelValues("canceled").Inc() + return controlledPeerFetchResult{} + } + + var permit *peerFetchPermit + var reason string + if decision.nonBlocking { + permit, reason = policy.limiter.tryAcquire(reservedBytes) + } else { + permit, reason = policy.limiter.acquireBefore(ctx, acquireDeadline, reservedBytes) + } + if permit == nil { + peerFetchShedTotal.WithLabelValues(reason).Inc() + return controlledPeerFetchResult{} + } + defer permit.release() + if onStart != nil { + onStart() + } + + startedAt := time.Now() + _, n, ok := p.peers.FetchFromPeers(ctx, cacheKey, sink) + duration := time.Since(startedAt) + if ctx.Err() != nil { + peerFetchDuration.WithLabelValues("canceled").Observe(duration.Seconds()) + } else if observeLatency { + policy.observePeer(duration, ok) + } else { + outcome := "miss" + if ok { + outcome = "hit" + } + peerFetchDuration.WithLabelValues(outcome).Observe(duration.Seconds()) + } + return controlledPeerFetchResult{ + bytes: n, + duration: duration, + ok: ok, + started: true, + } +} + +func newPeerFetchLimiter(maxConcurrent, maxBytes int64) *peerFetchLimiter { + if maxConcurrent <= 0 { + maxConcurrent = defaultPeerFetchMaxConcurrent + } + if maxBytes <= 0 { + maxBytes = 1 + } + return &peerFetchLimiter{ + count: semaphore.NewWeighted(maxConcurrent), + bytes: semaphore.NewWeighted(maxBytes), + maxBytes: maxBytes, + } +} + +func (l *peerFetchLimiter) acquire(ctx context.Context, reservedBytes int64) (*peerFetchPermit, string) { + queuedAt := time.Now() + defer func() { peerFetchQueueDuration.Observe(time.Since(queuedAt).Seconds()) }() + if reservedBytes <= 0 || reservedBytes > l.maxBytes { + return nil, "capacity" + } + if err := l.count.Acquire(ctx, 1); err != nil { + return nil, acquireFailureReason(ctx) + } + if err := l.bytes.Acquire(ctx, reservedBytes); err != nil { + l.count.Release(1) + return nil, acquireFailureReason(ctx) + } + return l.admit(reservedBytes), "" +} + +// acquireBefore makes the absolute hedge deadline part of the limiter's own +// contract. The explicit checks prevent a late fetch even if semaphore +// cancellation semantics change or the deadline expires in the narrow gap +// after both permits are granted. +func (l *peerFetchLimiter) acquireBefore( + ctx context.Context, + deadline time.Time, + reservedBytes int64, +) (*peerFetchPermit, string) { + if !deadline.IsZero() && !time.Now().Before(deadline) { + return nil, "deadline" + } + queueCtx := ctx + cancelQueue := func() {} + if !deadline.IsZero() { + queueCtx, cancelQueue = context.WithDeadline(ctx, deadline) + } + permit, reason := l.acquire(queueCtx, reservedBytes) + cancelQueue() + if permit == nil { + return nil, reason + } + if !deadline.IsZero() && !time.Now().Before(deadline) { + permit.release() + return nil, "deadline" + } + return permit, "" +} + +// tryAcquire is used by half-open recovery probes. A diagnostic probe must +// never queue in front of origin or delay a user request while the breaker is +// open, so it either takes both permits immediately or skips this interval. +func (l *peerFetchLimiter) tryAcquire(reservedBytes int64) (*peerFetchPermit, string) { + if reservedBytes <= 0 || reservedBytes > l.maxBytes { + return nil, "capacity" + } + if !l.count.TryAcquire(1) { + return nil, "capacity" + } + if !l.bytes.TryAcquire(reservedBytes) { + l.count.Release(1) + return nil, "capacity" + } + return l.admit(reservedBytes), "" +} + +func (l *peerFetchLimiter) admit(reservedBytes int64) *peerFetchPermit { + l.inFlight.Add(1) + l.bytesInFlight.Add(reservedBytes) + peerFetchInFlight.Inc() + peerFetchBytesInFlight.Add(float64(reservedBytes)) + return &peerFetchPermit{limiter: l, bytes: reservedBytes} +} + +func acquireFailureReason(ctx context.Context) string { + if ctx.Err() == context.DeadlineExceeded { + return "deadline" + } + return "canceled" +} + +func (p *peerFetchPermit) release() { + if p == nil || p.limiter == nil { + return + } + p.once.Do(func() { + p.limiter.bytes.Release(p.bytes) + p.limiter.count.Release(1) + p.limiter.inFlight.Add(-1) + p.limiter.bytesInFlight.Add(-p.bytes) + peerFetchInFlight.Dec() + peerFetchBytesInFlight.Sub(float64(p.bytes)) + }) +} + +func (l *peerFetchLimiter) snapshot() (int64, int64) { + return l.inFlight.Load(), l.bytesInFlight.Load() +} + +type peerFetchPolicyConfig struct { + maxConcurrent int64 + maxBytes int64 + minHeadStart time.Duration + maxHeadStart time.Duration + breakerRatio float64 + breakerOpenAfter int + breakerCloseAfter int + breakerProbeInterval time.Duration + breakerMinSamples int + now func() time.Time +} + +func defaultPeerFetchPolicyConfig(maxConcurrent, maxBytes int64) peerFetchPolicyConfig { + if maxConcurrent <= 0 { + maxConcurrent = defaultPeerFetchMaxConcurrent + } + if maxBytes <= 0 { + maxBytes = defaultPeerFetchMaxBytes(maxConcurrent, 8<<20) + } + return peerFetchPolicyConfig{ + maxConcurrent: maxConcurrent, + maxBytes: maxBytes, + minHeadStart: defaultPeerHedgeMinDelay, + maxHeadStart: defaultPeerHedgeMaxDelay, + breakerRatio: defaultPeerBreakerRatio, + breakerOpenAfter: defaultPeerBreakerOpenAfter, + breakerCloseAfter: defaultPeerBreakerCloseAfter, + breakerProbeInterval: defaultPeerBreakerProbeEvery, + breakerMinSamples: defaultPeerBreakerMinSamples, + now: time.Now, + } +} + +type latencyEWMA struct { + value float64 + initialized bool + samples int +} + +func (e *latencyEWMA) add(d time.Duration) { + v := d.Seconds() + if !e.initialized { + e.value = v + e.initialized = true + } else { + e.value = peerLatencyEWMAAlpha*v + (1-peerLatencyEWMAAlpha)*e.value + } + e.samples++ +} + +// peerFetchPolicy owns the process-wide limiter, latency estimators, adaptive +// hedge delay, and circuit breaker. All mutable policy state is protected by +// mu so request goroutines observe one coherent breaker decision. +type peerFetchPolicy struct { + limiter *peerFetchLimiter + cfg peerFetchPolicyConfig + + mu sync.Mutex + peerWindow []time.Duration + peerWindowNext int + peerEWMA latencyEWMA + originEWMA latencyEWMA + + open bool + badStreak int + directBadStreak int + lastDirectBad time.Time + recoveryStreak int + probeInFlight bool + nextProbe time.Time + measureInFlight bool + nextMeasurement time.Time +} + +func newPeerFetchPolicy(cfg peerFetchPolicyConfig) *peerFetchPolicy { + defaults := defaultPeerFetchPolicyConfig(cfg.maxConcurrent, cfg.maxBytes) + if cfg.maxConcurrent <= 0 { + cfg.maxConcurrent = defaults.maxConcurrent + } + if cfg.maxBytes <= 0 { + cfg.maxBytes = defaults.maxBytes + } + if cfg.minHeadStart <= 0 { + cfg.minHeadStart = defaults.minHeadStart + } + if cfg.maxHeadStart < cfg.minHeadStart { + cfg.maxHeadStart = defaults.maxHeadStart + } + if cfg.breakerRatio <= 0 { + cfg.breakerRatio = defaults.breakerRatio + } + if cfg.breakerOpenAfter <= 0 { + cfg.breakerOpenAfter = defaults.breakerOpenAfter + } + if cfg.breakerCloseAfter <= 0 { + cfg.breakerCloseAfter = defaults.breakerCloseAfter + } + if cfg.breakerProbeInterval <= 0 { + cfg.breakerProbeInterval = defaults.breakerProbeInterval + } + if cfg.breakerMinSamples <= 0 { + cfg.breakerMinSamples = defaults.breakerMinSamples + } + if cfg.now == nil { + cfg.now = time.Now + } + return &peerFetchPolicy{ + limiter: newPeerFetchLimiter(cfg.maxConcurrent, cfg.maxBytes), + cfg: cfg, + } +} + +func (p *peerFetchPolicy) headStart() time.Duration { + p.mu.Lock() + samples := append([]time.Duration(nil), p.peerWindow...) + minDelay, maxDelay := p.cfg.minHeadStart, p.cfg.maxHeadStart + p.mu.Unlock() + + delay := minDelay + if len(samples) > 0 { + sort.Slice(samples, func(i, j int) bool { return samples[i] < samples[j] }) + delay = samples[len(samples)/2] + } + if delay < minDelay { + delay = minDelay + } + if delay > maxDelay { + delay = maxDelay + } + peerHedgeHeadStartSeconds.Set(delay.Seconds()) + return delay +} + +func (p *peerFetchPolicy) observePeer(d time.Duration, success bool) { + outcome := "miss" + if success { + outcome = "hit" + } + peerFetchDuration.WithLabelValues(outcome).Observe(d.Seconds()) + if !success { + return + } + p.mu.Lock() + if len(p.peerWindow) < peerLatencyWindowSize { + p.peerWindow = append(p.peerWindow, d) + } else { + p.peerWindow[p.peerWindowNext] = d + p.peerWindowNext = (p.peerWindowNext + 1) % peerLatencyWindowSize + } + p.peerEWMA.add(d) + ewma := p.peerEWMA.value + p.mu.Unlock() + peerFetchLatencyEWMASeconds.Set(ewma) +} + +// observePeerLowerBound records only a threshold-qualified censored sample: +// origin won and cancellation proves the still-running peer had already taken +// at least d. Keeping it out of the p50 window avoids treating an incomplete +// transfer as a completed hedge-delay sample, while still letting sustained +// evidence update the breaker EWMA after an abrupt slowdown. +func (p *peerFetchPolicy) observePeerLowerBound(d time.Duration) { + if d <= 0 { + return + } + p.mu.Lock() + p.peerEWMA.add(d) + ewma := p.peerEWMA.value + p.mu.Unlock() + peerFetchLatencyEWMASeconds.Set(ewma) +} + +func (p *peerFetchPolicy) observeOriginSpan(totalDuration time.Duration, success, canceled bool) { + outcome := "error" + if canceled { + outcome = "canceled" + } else if success { + outcome = "success" + } + originSpanFetchDuration.WithLabelValues(outcome).Observe(totalDuration.Seconds()) +} + +// observeOriginFirstBlock records the peer-comparable unit from a coalesced +// origin span. Content-Range and Content-Length have already been validated, +// and exactLengthReader plus PutStream prove that the first block was committed +// atomically. A later block failing cannot invalidate this completed sample. +func (p *peerFetchPolicy) observeOriginFirstBlock(firstBlockDuration time.Duration) { + if firstBlockDuration <= 0 { + return + } + p.mu.Lock() + p.originEWMA.add(firstBlockDuration) + ewma := p.originEWMA.value + p.mu.Unlock() + originFetchLatencyEWMASeconds.Set(ewma) +} + +func (p *peerFetchPolicy) comparableOriginLatency(current time.Duration) (time.Duration, bool) { + if current > 0 { + return current, true + } + p.mu.Lock() + defer p.mu.Unlock() + if !p.originEWMA.initialized { + return 0, false + } + return time.Duration(p.originEWMA.value * float64(time.Second)), true +} + +func (p *peerFetchPolicy) allowPeer(recoveryEligible bool) (allowed, recoverySample bool) { + p.mu.Lock() + defer p.mu.Unlock() + if !p.open { + return true, false + } + if !recoveryEligible { + return false, false + } + now := p.cfg.now() + if p.probeInFlight || now.Before(p.nextProbe) { + return false, false + } + p.probeInFlight = true + return true, true +} + +func (p *peerFetchPolicy) finishProbe(recoverySample, success bool) { + if !recoverySample { + return + } + p.mu.Lock() + defer p.mu.Unlock() + p.probeInFlight = false + p.nextProbe = p.cfg.now().Add(p.cfg.breakerProbeInterval) + if !p.open { + return + } + // The caller classifies this individual recovery sample from its actual + // peer/origin durations. Do not re-apply the stale pre-open EWMAs here: the + // whole purpose of the sampled probe is to discover that the regime changed. + if success { + p.recoveryStreak++ + } else { + p.recoveryStreak = 0 + } + if p.recoveryStreak >= p.cfg.breakerCloseAfter { + p.open = false + p.badStreak = 0 + p.directBadStreak = 0 + p.lastDirectBad = time.Time{} + p.recoveryStreak = 0 + peerBreakerState.Set(0) + peerBreakerTransitionsTotal.WithLabelValues("closed").Inc() + } +} + +// startAmbiguousMeasurement admits at most one closed-breaker diagnostic per +// sampling interval. It is used only when prompt loser cancellation leaves a +// peer latency sample censored below the 1.5x threshold. +func (p *peerFetchPolicy) startAmbiguousMeasurement() bool { + p.mu.Lock() + defer p.mu.Unlock() + now := p.cfg.now() + if p.open || p.measureInFlight || now.Before(p.nextMeasurement) { + return false + } + p.measureInFlight = true + return true +} + +func (p *peerFetchPolicy) finishAmbiguousMeasurement() { + p.mu.Lock() + p.measureInFlight = false + p.nextMeasurement = p.cfg.now().Add(p.cfg.breakerProbeInterval) + p.mu.Unlock() +} + +// recordLatencyRatioObservation evaluates the sustained ratio signal once per +// client request, regardless of how many coalesced origin spans it needed. +func (p *peerFetchPolicy) recordLatencyRatioObservation() { + p.mu.Lock() + defer p.mu.Unlock() + if p.open { + return + } + ratioSlow := p.peerEWMA.samples >= p.cfg.breakerMinSamples && + p.originEWMA.samples >= p.cfg.breakerMinSamples && + p.peerEWMA.value > p.cfg.breakerRatio*p.originEWMA.value + if ratioSlow { + p.badStreak++ + } else { + p.badStreak = 0 + } + p.maybeOpenLocked() +} + +// recordThresholdComparison tracks paired observations that prove whether a +// peer exceeded the configured origin-latency ratio. This evidence is kept +// separate from the EWMAs: a timeout exactly at the ratio boundary is censored +// proof of a slow peer, but averaging that lower bound into a formerly healthy +// EWMA could otherwise take minutes to cross the threshold. Unknown origin +// wins do not call this method and therefore do not reset the streak. +func (p *peerFetchPolicy) recordThresholdComparison(exceeded bool) { + p.mu.Lock() + defer p.mu.Unlock() + if p.open { + return + } + if !exceeded { + p.directBadStreak = 0 + p.lastDirectBad = time.Time{} + return + } + now := p.cfg.now() + if !p.lastDirectBad.IsZero() && now.Sub(p.lastDirectBad) > 2*p.cfg.breakerProbeInterval { + p.directBadStreak = 0 + } + p.lastDirectBad = now + p.directBadStreak++ + p.maybeOpenLocked() +} + +func (p *peerFetchPolicy) maybeOpenLocked() { + if p.open || (p.badStreak < p.cfg.breakerOpenAfter && p.directBadStreak < p.cfg.breakerOpenAfter) { + return + } + p.open = true + p.recoveryStreak = 0 + p.nextProbe = p.cfg.now().Add(p.cfg.breakerProbeInterval) + peerBreakerState.Set(1) + peerBreakerTransitionsTotal.WithLabelValues("open").Inc() +} + +func (p *peerFetchPolicy) breakerOpen() bool { + p.mu.Lock() + defer p.mu.Unlock() + return p.open +} + +func peerWithinBreakerRatio(peer, origin time.Duration, ratio float64) bool { + if peer < 0 || origin <= 0 || ratio <= 0 { + return false + } + return float64(peer) <= ratio*float64(origin) +} + +type originSpanResult struct { + bytesRead int64 + duration time.Duration + firstBlockDuration time.Duration +} + +// originSpanFlights coalesces identical block-origin spans while allowing +// each request to stop waiting independently. The producer has a service-owned +// context and is canceled only after its final interested waiter leaves. +type originSpanFlights struct { + mu sync.Mutex + calls map[string]*originSpanCall +} + +type originSpanCall struct { + ctx context.Context + cancel context.CancelFunc + done chan struct{} + refs int + + firstIdx int64 + committedThrough int64 + firstBlockDuration time.Duration + progress chan struct{} + + result originSpanResult + err error + complete bool + canceledAsLoser bool + originUsed bool + peerWon bool + duplicateCounted bool +} + +type originSpanLease struct { + group *originSpanFlights + key string + call *originSpanCall + once sync.Once +} + +func (g *originSpanFlights) start(key string, fn func(context.Context) (originSpanResult, error)) *originSpanLease { + return g.startWithProgress(key, 0, func(ctx context.Context, _ func(int64, time.Duration)) (originSpanResult, error) { + return fn(ctx) + }) +} + +// startWithProgress coalesces an origin span while publishing monotonic block +// commits to every lease. A close-and-replace progress channel avoids callback +// backpressure and lets late joiners replay the committed prefix from state. +func (g *originSpanFlights) startWithProgress( + key string, + firstIdx int64, + fn func(context.Context, func(int64, time.Duration)) (originSpanResult, error), +) *originSpanLease { + g.mu.Lock() + if g.calls == nil { + g.calls = make(map[string]*originSpanCall) + } + if call, ok := g.calls[key]; ok { + call.refs++ + g.mu.Unlock() + return &originSpanLease{group: g, key: key, call: call} + } + ctx, cancel := context.WithCancel(context.Background()) + call := &originSpanCall{ + ctx: ctx, cancel: cancel, done: make(chan struct{}), refs: 1, + firstIdx: firstIdx, committedThrough: firstIdx - 1, progress: make(chan struct{}), + } + g.calls[key] = call + g.mu.Unlock() + + reportCommit := func(idx int64, elapsed time.Duration) { + g.mu.Lock() + if !call.complete && idx > call.committedThrough { + call.committedThrough = idx + if idx == call.firstIdx { + call.firstBlockDuration = elapsed + } + close(call.progress) + call.progress = make(chan struct{}) + } + g.mu.Unlock() + } + go func() { + result, err := fn(ctx, reportCommit) + g.mu.Lock() + call.result = result + call.err = err + call.complete = true + loser := call.canceledAsLoser + close(call.done) + close(call.progress) + if g.calls[key] == call { + delete(g.calls, key) + } + g.mu.Unlock() + if loser && result.bytesRead > 0 { + peerHedgeDuplicateBytesTotal.WithLabelValues("origin").Add(float64(result.bytesRead)) + } + }() + return &originSpanLease{group: g, key: key, call: call} +} + +// progressSnapshot returns immutable commit state plus a notification channel +// that closes on the next commit or final completion. Callers act only after +// the flight mutex is released. +func (l *originSpanLease) progressSnapshot() ( + committedThrough int64, + firstBlockDuration time.Duration, + progress <-chan struct{}, + complete bool, +) { + if l == nil || l.group == nil || l.call == nil { + return -1, 0, nil, true + } + l.group.mu.Lock() + committedThrough = l.call.committedThrough + firstBlockDuration = l.call.firstBlockDuration + progress = l.call.progress + complete = l.call.complete + l.group.mu.Unlock() + return committedThrough, firstBlockDuration, progress, complete +} + +func (l *originSpanLease) committedThroughIn(lo, hi int64) int64 { + if l == nil || l.group == nil || l.call == nil { + return lo - 1 + } + l.group.mu.Lock() + through := min(l.call.committedThrough, hi) + if through < lo { + through = lo - 1 + } + l.group.mu.Unlock() + return through +} + +func (l *originSpanLease) wait(ctx context.Context) (originSpanResult, error) { + select { + case <-l.call.done: + return l.call.result, l.call.err + case <-ctx.Done(): + return originSpanResult{}, ctx.Err() + } +} + +type originLeaseOutcome uint8 + +const ( + originLeaseAbandoned originLeaseOutcome = iota + originLeaseUsed + originLeaseLostToPeer +) + +// release drops a caller that no longer needs the origin result. Abandonment +// (for example a client disconnect) may cancel an unneeded producer, but only +// a peer winner is classified as a hedge cancellation or duplicate traffic. +func (l *originSpanLease) release() bool { + return l.releaseWithOutcome(originLeaseAbandoned) +} + +func (l *originSpanLease) releaseOriginUsed() bool { + return l.releaseWithOutcome(originLeaseUsed) +} + +func (l *originSpanLease) releasePeerWinner() bool { + return l.releaseWithOutcome(originLeaseLostToPeer) +} + +func (l *originSpanLease) releaseWithOutcome(outcome originLeaseOutcome) (canceled bool) { + if l == nil || l.group == nil || l.call == nil { + return false + } + var duplicateBytes int64 + var hedgeCancellation bool + l.once.Do(func() { + l.group.mu.Lock() + switch outcome { + case originLeaseUsed: + l.call.originUsed = true + case originLeaseLostToPeer: + l.call.peerWon = true + } + l.call.refs-- + if l.call.refs == 0 { + // Do not let a fresh request attach to a producer whose context is + // about to be canceled. Producer cleanup is identity-checked, so it + // cannot delete a newer call installed under the same key. + if l.group.calls[l.key] == l.call { + delete(l.group.calls, l.key) + } + losingHedge := !l.call.originUsed && l.call.peerWon + if !l.call.complete { + l.call.canceledAsLoser = losingHedge + l.call.cancel() + canceled = true + hedgeCancellation = losingHedge + } else if losingHedge && !l.call.duplicateCounted { + l.call.duplicateCounted = true + duplicateBytes = l.call.result.bytesRead + } + } + l.group.mu.Unlock() + if hedgeCancellation { + peerFetchCancellationsTotal.WithLabelValues("origin").Inc() + } + if duplicateBytes > 0 { + peerHedgeDuplicateBytesTotal.WithLabelValues("origin").Add(float64(duplicateBytes)) + } + }) + return canceled +} diff --git a/cmd/cache-proxy/peer_fetch_control_test.go b/cmd/cache-proxy/peer_fetch_control_test.go new file mode 100644 index 00000000..6b9af7fb --- /dev/null +++ b/cmd/cache-proxy/peer_fetch_control_test.go @@ -0,0 +1,456 @@ +package main + +import ( + "context" + "errors" + "sync/atomic" + "testing" + "time" +) + +func TestPeerFetchLimiterEnforcesCountAndBytesTogether(t *testing.T) { + limiter := newPeerFetchLimiter(2, 20) + + first, reason := limiter.acquire(context.Background(), 10) + if first == nil || reason != "" { + t.Fatalf("first acquire = (%v, %q), want permit", first, reason) + } + second, reason := limiter.acquire(context.Background(), 10) + if second == nil || reason != "" { + t.Fatalf("second acquire = (%v, %q), want permit", second, reason) + } + + ctx, cancel := context.WithTimeout(context.Background(), 20*time.Millisecond) + defer cancel() + if permit, gotReason := limiter.acquire(ctx, 1); permit != nil || gotReason != "deadline" { + t.Fatalf("blocked acquire = (%v, %q), want (nil, deadline)", permit, gotReason) + } + if gotCount, gotBytes := limiter.snapshot(); gotCount != 2 || gotBytes != 20 { + t.Fatalf("in flight = (%d, %d), want (2, 20)", gotCount, gotBytes) + } + + first.release() + third, reason := limiter.acquire(context.Background(), 10) + if third == nil || reason != "" { + t.Fatalf("acquire after release = (%v, %q), want permit", third, reason) + } + second.release() + third.release() + if gotCount, gotBytes := limiter.snapshot(); gotCount != 0 || gotBytes != 0 { + t.Fatalf("in flight after release = (%d, %d), want zero", gotCount, gotBytes) + } +} + +func TestPeerFetchLimiterRejectsReservationAboveCeiling(t *testing.T) { + limiter := newPeerFetchLimiter(32, 8) + permit, reason := limiter.acquire(context.Background(), 9) + if permit != nil || reason != "capacity" { + t.Fatalf("oversized acquire = (%v, %q), want (nil, capacity)", permit, reason) + } +} + +func TestPeerFetchLimiterReleasesCountPermitWhenByteWaitExpires(t *testing.T) { + limiter := newPeerFetchLimiter(2, 1) + first, reason := limiter.acquire(context.Background(), 1) + if first == nil || reason != "" { + t.Fatalf("first acquire = (%v, %q), want permit", first, reason) + } + + ctx, cancel := context.WithTimeout(context.Background(), 20*time.Millisecond) + defer cancel() + if permit, gotReason := limiter.acquire(ctx, 1); permit != nil || gotReason != "deadline" { + t.Fatalf("byte-blocked acquire = (%v, %q), want (nil, deadline)", permit, gotReason) + } + + // The failed acquire must release exactly its own count permit. Releasing + // the original permit must not over-release the weighted semaphore. + first.release() + if gotCount, gotBytes := limiter.snapshot(); gotCount != 0 || gotBytes != 0 { + t.Fatalf("in flight after release = (%d, %d), want zero", gotCount, gotBytes) + } +} + +func TestPeerFetchLimiterRejectsExpiredAbsoluteDeadline(t *testing.T) { + limiter := newPeerFetchLimiter(1, 1) + permit, reason := limiter.acquireBefore(context.Background(), time.Now().Add(-time.Millisecond), 1) + if permit != nil || reason != "deadline" { + t.Fatalf("expired acquire = (%v, %q), want (nil, deadline)", permit, reason) + } + if gotCount, gotBytes := limiter.snapshot(); gotCount != 0 || gotBytes != 0 { + t.Fatalf("in flight after expired acquire = (%d, %d), want zero", gotCount, gotBytes) + } +} + +func TestPeerFetchPolicyAdaptiveHeadStartUsesRollingMedianAndClamps(t *testing.T) { + cfg := defaultPeerFetchPolicyConfig(32, 32<<20) + policy := newPeerFetchPolicy(cfg) + + if got := policy.headStart(); got != 25*time.Millisecond { + t.Fatalf("empty-window head start = %v, want 25ms", got) + } + for _, sample := range []time.Duration{5, 10, 15, 20, 30} { + policy.observePeer(sample*time.Millisecond, true) + } + if got := policy.headStart(); got != 25*time.Millisecond { + t.Fatalf("low-median head start = %v, want lower clamp 25ms", got) + } + for i := 0; i < peerLatencyWindowSize; i++ { + policy.observePeer(500*time.Millisecond, true) + } + if got := policy.headStart(); got != 150*time.Millisecond { + t.Fatalf("high-median head start = %v, want upper clamp 150ms", got) + } +} + +func TestPeerCircuitBreakerRequiresSustainedLatencyRatioAndSamplesRecovery(t *testing.T) { + now := time.Unix(1_000, 0) + cfg := defaultPeerFetchPolicyConfig(32, 32<<20) + cfg.now = func() time.Time { return now } + cfg.breakerOpenAfter = 3 + cfg.breakerCloseAfter = 2 + cfg.breakerProbeInterval = time.Second + cfg.breakerMinSamples = 1 + policy := newPeerFetchPolicy(cfg) + + for i := 0; i < 2; i++ { + policy.observePeer(200*time.Millisecond, true) + policy.observeOriginFirstBlock(100 * time.Millisecond) + policy.recordLatencyRatioObservation() + } + if policy.breakerOpen() { + t.Fatal("breaker opened before sustained-ratio threshold") + } + policy.observePeer(200*time.Millisecond, true) + policy.observeOriginFirstBlock(100 * time.Millisecond) + policy.recordLatencyRatioObservation() + if !policy.breakerOpen() { + t.Fatal("breaker remained closed after a sustained peer/origin ratio above 1.5") + } + + if allowed, sample := policy.allowPeer(true); allowed || sample { + t.Fatalf("peer allowed before recovery interval: allowed=%v sample=%v", allowed, sample) + } + now = now.Add(time.Second) + allowed, sample := policy.allowPeer(true) + if !allowed || !sample { + t.Fatalf("recovery sample = (%v, %v), want (true, true)", allowed, sample) + } + if allowedAgain, sampleAgain := policy.allowPeer(true); allowedAgain || sampleAgain { + t.Fatal("breaker allowed more than one concurrent recovery sample") + } + policy.finishProbe(sample, true) + + now = now.Add(time.Second) + allowed, sample = policy.allowPeer(true) + if !allowed || !sample { + t.Fatal("second recovery sample was not admitted") + } + policy.finishProbe(sample, true) + if policy.breakerOpen() { + t.Fatal("breaker did not close after sustained successful recovery samples") + } +} + +func TestPeerCircuitBreakerDoesNotOpenWithoutLatencyRatioEvidence(t *testing.T) { + cfg := defaultPeerFetchPolicyConfig(32, 32<<20) + cfg.breakerOpenAfter = 3 + policy := newPeerFetchPolicy(cfg) + + for i := 0; i < 10; i++ { + policy.recordLatencyRatioObservation() + } + if policy.breakerOpen() { + t.Fatal("breaker opened on origin wins without comparable peer/origin latency samples") + } +} + +func TestAmbiguousPeerMeasurementIsGloballySampled(t *testing.T) { + now := time.Unix(1_000, 0) + cfg := defaultPeerFetchPolicyConfig(32, 32<<20) + cfg.now = func() time.Time { return now } + cfg.breakerProbeInterval = time.Second + policy := newPeerFetchPolicy(cfg) + + if !policy.startAmbiguousMeasurement() { + t.Fatal("first ambiguous measurement was not admitted") + } + if policy.startAmbiguousMeasurement() { + t.Fatal("second concurrent ambiguous measurement was admitted") + } + policy.finishAmbiguousMeasurement() + if policy.startAmbiguousMeasurement() { + t.Fatal("ambiguous measurement was admitted before the sample interval") + } + now = now.Add(time.Second) + if !policy.startAmbiguousMeasurement() { + t.Fatal("ambiguous measurement was not admitted after the sample interval") + } + policy.finishAmbiguousMeasurement() +} + +func TestPeerWithinBreakerRatioAllowsMarginallySlowerPeer(t *testing.T) { + if !peerWithinBreakerRatio(130*time.Millisecond, 100*time.Millisecond, 1.5) { + t.Fatal("peer at 1.3x origin should be a healthy recovery sample") + } + if peerWithinBreakerRatio(151*time.Millisecond, 100*time.Millisecond, 1.5) { + t.Fatal("peer above 1.5x origin should be an unhealthy recovery sample") + } +} + +func TestPeerCircuitBreakerOpensOnSustainedLatencyRatio(t *testing.T) { + cfg := defaultPeerFetchPolicyConfig(32, 32<<20) + cfg.breakerMinSamples = 2 + cfg.breakerOpenAfter = 2 + policy := newPeerFetchPolicy(cfg) + + // The first sample warms the comparable EWMA window; the next two + // slow-ratio decisions satisfy the sustained-loss threshold. + for i := 0; i < 3; i++ { + policy.observePeer(200*time.Millisecond, true) + policy.observeOriginFirstBlock(100 * time.Millisecond) + policy.recordLatencyRatioObservation() + } + if !policy.breakerOpen() { + t.Fatal("breaker stayed closed with a sustained peer/origin ratio above 1.5") + } +} + +func TestPeerCircuitBreakerUsesThresholdQualifiedCanceledLowerBounds(t *testing.T) { + cfg := defaultPeerFetchPolicyConfig(32, 32<<20) + cfg.breakerMinSamples = 2 + cfg.breakerOpenAfter = 2 + policy := newPeerFetchPolicy(cfg) + + for i := 0; i < 3; i++ { + policy.observeOriginFirstBlock(100 * time.Millisecond) + policy.observePeerLowerBound(160 * time.Millisecond) + policy.recordLatencyRatioObservation() + } + if !policy.breakerOpen() { + t.Fatal("breaker stayed closed despite sustained canceled-peer lower bounds above 1.5x origin") + } +} + +func TestPeerCircuitBreakerOpensOnSustainedDirectThresholdEvidence(t *testing.T) { + cfg := defaultPeerFetchPolicyConfig(32, 32<<20) + cfg.breakerOpenAfter = 3 + policy := newPeerFetchPolicy(cfg) + + // Model an abrupt regression from a healthy low EWMA. A diagnostic that + // times out at exactly the ratio boundary proves peer > ratio*origin, even + // though adding that censored lower bound to the EWMA would take many + // samples to overcome the old healthy history. + for i := 0; i < 16; i++ { + policy.observePeer(20*time.Millisecond, true) + } + for i := 0; i < 2; i++ { + policy.recordThresholdComparison(true) + } + if policy.breakerOpen() { + t.Fatal("breaker opened before the sustained direct-evidence threshold") + } + policy.recordThresholdComparison(true) + if !policy.breakerOpen() { + t.Fatal("breaker stayed closed after three direct peer>origin ratio observations") + } +} + +func TestPeerCircuitBreakerDirectEvidenceResetsOnKnownHealthyComparison(t *testing.T) { + cfg := defaultPeerFetchPolicyConfig(32, 32<<20) + cfg.breakerOpenAfter = 3 + policy := newPeerFetchPolicy(cfg) + + policy.recordThresholdComparison(true) + policy.recordThresholdComparison(true) + policy.recordThresholdComparison(false) + policy.recordThresholdComparison(true) + policy.recordThresholdComparison(true) + if policy.breakerOpen() { + t.Fatal("non-consecutive direct evidence opened after a known healthy comparison") + } + policy.recordThresholdComparison(true) + if !policy.breakerOpen() { + t.Fatal("breaker did not open after a new sustained run of direct evidence") + } +} + +func TestLatePeerSuccessAndDuplicateBytesAreCounted(t *testing.T) { + ctx, cancel := context.WithCancel(context.Background()) + fill := &peerFill{ctx: ctx, cancel: cancel, done: make(chan struct{})} + fill.started.Store(true) + + lateBefore := counterValue(t, latePeerSuccessesTotal) + duplicateBefore := counterValue(t, peerHedgeDuplicateBytesTotal.WithLabelValues("peer")) + fill.cancelForOrigin() + fill.finish(controlledPeerFetchResult{ok: true, bytes: 128, started: true}) + + if got := counterValue(t, latePeerSuccessesTotal); got != lateBefore+1 { + t.Fatalf("late peer successes delta = %v, want 1", got-lateBefore) + } + if got := counterValue(t, peerHedgeDuplicateBytesTotal.WithLabelValues("peer")); got != duplicateBefore+128 { + t.Fatalf("duplicate peer bytes delta = %v, want 128", got-duplicateBefore) + } +} + +func TestOriginSpanFlightsCancelOnlyAfterLastWaiterLeaves(t *testing.T) { + var flights originSpanFlights + started := make(chan struct{}) + producerCanceled := make(chan struct{}) + var starts atomic.Int32 + + start := func(ctx context.Context) (originSpanResult, error) { + if starts.Add(1) == 1 { + close(started) + } + <-ctx.Done() + close(producerCanceled) + return originSpanResult{}, ctx.Err() + } + + first := flights.start("same-span", start) + second := flights.start("same-span", start) + <-started + if first.release() { + t.Fatal("first waiter canceled a producer still needed by another waiter") + } + select { + case <-producerCanceled: + t.Fatal("shared producer was canceled while a waiter remained") + case <-time.After(20 * time.Millisecond): + } + if !second.release() { + t.Fatal("last waiter did not cancel the unneeded producer") + } + select { + case <-producerCanceled: + case <-time.After(time.Second): + t.Fatal("producer did not observe cancellation") + } + if starts.Load() != 1 { + t.Fatalf("producer starts = %d, want 1", starts.Load()) + } +} + +func TestOriginSpanFlightWaitHonorsCallerCancellation(t *testing.T) { + var flights originSpanFlights + releaseProducer := make(chan struct{}) + flight := flights.start("span", func(context.Context) (originSpanResult, error) { + <-releaseProducer + return originSpanResult{}, nil + }) + t.Cleanup(func() { close(releaseProducer) }) + + ctx, cancel := context.WithCancel(context.Background()) + cancel() + _, err := flight.wait(ctx) + if !errors.Is(err, context.Canceled) { + t.Fatalf("wait error = %v, want context.Canceled", err) + } + flight.release() +} + +func TestOriginSpanFlightNewCallerDoesNotJoinCanceledCall(t *testing.T) { + var flights originSpanFlights + firstCanceled := make(chan struct{}) + allowFirstExit := make(chan struct{}) + secondStarted := make(chan struct{}) + var starts atomic.Int32 + + start := func(ctx context.Context) (originSpanResult, error) { + if starts.Add(1) == 1 { + <-ctx.Done() + close(firstCanceled) + <-allowFirstExit + return originSpanResult{}, ctx.Err() + } + close(secondStarted) + return originSpanResult{bytesRead: 1}, nil + } + + first := flights.start("same-span", start) + first.release() + <-firstCanceled + second := flights.start("same-span", start) + select { + case <-secondStarted: + case <-time.After(20 * time.Millisecond): + close(allowFirstExit) + second.release() + t.Fatalf("producer starts = %d, want a fresh producer after last-waiter cancellation", starts.Load()) + } + close(allowFirstExit) + if result, err := second.wait(context.Background()); err != nil || result.bytesRead != 1 { + t.Fatalf("fresh producer result = (%+v, %v), want one byte and no error", result, err) + } + second.release() +} + +func TestOriginSpanFlightAbandonmentIsNotHedgeCancellation(t *testing.T) { + var flights originSpanFlights + cancelBefore := counterValue(t, peerFetchCancellationsTotal.WithLabelValues("origin")) + duplicateBefore := counterValue(t, peerHedgeDuplicateBytesTotal.WithLabelValues("origin")) + + flight := flights.start("abandoned", func(ctx context.Context) (originSpanResult, error) { + <-ctx.Done() + return originSpanResult{bytesRead: 64}, ctx.Err() + }) + if !flight.release() { + t.Fatal("last abandoned waiter did not cancel its unneeded producer") + } + <-flight.call.done + + if got := counterValue(t, peerFetchCancellationsTotal.WithLabelValues("origin")); got != cancelBefore { + t.Fatalf("ordinary abandonment changed hedge cancellations by %v", got-cancelBefore) + } + if got := counterValue(t, peerHedgeDuplicateBytesTotal.WithLabelValues("origin")); got != duplicateBefore { + t.Fatalf("ordinary abandonment changed hedge duplicate bytes by %v", got-duplicateBefore) + } +} + +func TestCompletedUnusedOriginIsCountedAsHedgeDuplication(t *testing.T) { + var flights originSpanFlights + cancelBefore := counterValue(t, peerFetchCancellationsTotal.WithLabelValues("origin")) + duplicateBefore := counterValue(t, peerHedgeDuplicateBytesTotal.WithLabelValues("origin")) + + flight := flights.start("completed-loser", func(context.Context) (originSpanResult, error) { + return originSpanResult{bytesRead: 128}, nil + }) + if _, err := flight.wait(context.Background()); err != nil { + t.Fatal(err) + } + if flight.releasePeerWinner() { + t.Fatal("completed origin was reported as canceled") + } + + if got := counterValue(t, peerFetchCancellationsTotal.WithLabelValues("origin")); got != cancelBefore { + t.Fatalf("completed loser cancellation delta = %v, want 0", got-cancelBefore) + } + if got := counterValue(t, peerHedgeDuplicateBytesTotal.WithLabelValues("origin")); got != duplicateBefore+128 { + t.Fatalf("completed loser duplicate-byte delta = %v, want 128", got-duplicateBefore) + } +} + +func TestSharedOriginUsedByOneWaiterIsNotDuplicate(t *testing.T) { + var flights originSpanFlights + releaseProducer := make(chan struct{}) + duplicateBefore := counterValue(t, peerHedgeDuplicateBytesTotal.WithLabelValues("origin")) + start := func(context.Context) (originSpanResult, error) { + <-releaseProducer + return originSpanResult{bytesRead: 256}, nil + } + used := flights.start("shared-used", start) + peerWon := flights.start("shared-used", start) + close(releaseProducer) + if _, err := used.wait(context.Background()); err != nil { + t.Fatal(err) + } + if _, err := peerWon.wait(context.Background()); err != nil { + t.Fatal(err) + } + used.releaseOriginUsed() + peerWon.releasePeerWinner() + + if got := counterValue(t, peerHedgeDuplicateBytesTotal.WithLabelValues("origin")); got != duplicateBefore { + t.Fatalf("origin bytes used by another waiter were counted duplicate: delta=%v", got-duplicateBefore) + } +} diff --git a/cmd/cache-proxy/peers.go b/cmd/cache-proxy/peers.go index c2fae053..29187367 100644 --- a/cmd/cache-proxy/peers.go +++ b/cmd/cache-proxy/peers.go @@ -31,8 +31,16 @@ var ( // separate: sharing one 2s budget (as the original code did) meant a slow // has-race ate into the body-transfer time and large peer ranges timed out // mid-stream, silently downgrading the hit to a full S3 fetch. +// +// The has budget is deliberately tight: a healthy peer answers the probe in +// single-digit ms even under load, while an origin block fetch costs roughly +// 200ms — so once a probe has gone unanswered for ~150ms, waiting longer only +// delays a faster origin fallback. FetchFromPeers waits for every peer's "no" +// before giving up, which means the slowest peer in the fleet gates every +// cold fill; with a 1s budget, production trails showed 16% of cold-scan +// requests burning the full second on that drain. const ( - peerHasTimeout = 1 * time.Second + peerHasTimeout = 150 * time.Millisecond peerGetTimeout = 30 * time.Second ) @@ -40,7 +48,7 @@ const ( // via a Kubernetes headless Service. type PeerManager struct { serviceName string - peerPort string // port for peer API (e.g. ":8081") + peerPort string // port for peer API (e.g. ":8081") client *http.Client // /cache/has probes (short timeout) streamClient *http.Client // /cache/get body transfers (long timeout) @@ -128,7 +136,7 @@ func (pm *PeerManager) resolve() { // ok is false if no peer has the key (or the chosen peer's body couldn't be // streamed). The body is never buffered here — sink (typically DiskCache.PutStream) // consumes it as it arrives, so a peer hit costs only sink's copy buffer. -func (pm *PeerManager) FetchFromPeers(cacheKey string, sink func(io.Reader) (int64, error)) (string, int64, bool) { +func (pm *PeerManager) FetchFromPeers(ctx context.Context, cacheKey string, sink func(io.Reader) (int64, error)) (string, int64, bool) { pm.mu.RLock() peers := make([]string, len(pm.peers)) copy(peers, pm.peers) @@ -143,7 +151,7 @@ func (pm *PeerManager) FetchFromPeers(cacheKey string, sink func(io.Reader) (int // Phase 1: ask every peer "do you have this?" in parallel (cheap, no body) // and take the first that says yes. Its own short context bounds the probe // so a slow/dead peer can't eat into the body-transfer budget below. - hasCtx, hasCancel := context.WithTimeout(context.Background(), peerHasTimeout) + hasCtx, hasCancel := context.WithTimeout(ctx, peerHasTimeout) defer hasCancel() holderCh := make(chan string, len(peers)) @@ -171,8 +179,15 @@ func (pm *PeerManager) FetchFromPeers(cacheKey string, sink func(io.Reader) (int var holder string for range peers { - if a := <-holderCh; a != "" { - holder = a + select { + case a := <-holderCh: + if a != "" { + holder = a + } + case <-hasCtx.Done(): + return "", 0, false + } + if holder != "" { break } } @@ -186,7 +201,7 @@ func (pm *PeerManager) FetchFromPeers(cacheKey string, sink func(io.Reader) (int // Phase 2: stream the body from the chosen holder straight into sink, with // its own generous budget (a multi-MB Parquet range can take a while). Only // the winner is fetched, so we never pull a body we won't use. - getCtx, getCancel := context.WithTimeout(context.Background(), peerGetTimeout) + getCtx, getCancel := context.WithTimeout(ctx, peerGetTimeout) defer getCancel() getURL := fmt.Sprintf("http://%s/cache/get?key=%s", holder, cacheKey) @@ -203,14 +218,30 @@ func (pm *PeerManager) FetchFromPeers(cacheKey string, sink func(io.Reader) (int } defer func() { _ = resp.Body.Close() }() - n, err := sink(resp.Body) + counted := &countingReader{r: resp.Body} + n, err := sink(counted) if err != nil { - return "", 0, false + return holder, counted.n, false } peerHitsTotal.Inc() return holder, n, true } +// countingReader preserves partial-transfer accounting when the caller +// cancels while DiskCache.PutStream is copying. PutStream correctly returns +// zero on a failed copy because it commits nothing, but the network bytes were +// still spent and must be included in hedge-amplification metrics. +type countingReader struct { + r io.Reader + n int64 +} + +func (r *countingReader) Read(p []byte) (int, error) { + n, err := r.r.Read(p) + r.n += int64(n) + return n, err +} + func getLocalIPs() []string { addrs, err := net.InterfaceAddrs() if err != nil { diff --git a/cmd/cache-proxy/peers_test.go b/cmd/cache-proxy/peers_test.go index ad254b42..475ff53b 100644 --- a/cmd/cache-proxy/peers_test.go +++ b/cmd/cache-proxy/peers_test.go @@ -2,6 +2,7 @@ package main import ( "bytes" + "context" "fmt" "io" "net/http" @@ -9,6 +10,7 @@ import ( "strings" "sync/atomic" "testing" + "time" ) // collectSink returns a sink that streams the peer body into buf, mirroring how @@ -68,7 +70,7 @@ func TestFetchFromPeersHit(t *testing.T) { pm := peerManagerWith([]string{addr}) var buf bytes.Buffer - from, n, ok := pm.FetchFromPeers(key, collectSink(&buf)) + from, n, ok := pm.FetchFromPeers(context.Background(), key, collectSink(&buf)) if !ok { t.Fatal("expected peer hit") } @@ -99,7 +101,7 @@ func TestFetchFromPeersMissFromAll(t *testing.T) { pm := peerManagerWith([]string{addr}) var buf bytes.Buffer - _, _, ok := pm.FetchFromPeers(key, collectSink(&buf)) + _, _, ok := pm.FetchFromPeers(context.Background(), key, collectSink(&buf)) if ok { t.Fatalf("expected miss, got %q", buf.String()) } @@ -124,7 +126,7 @@ func TestFetchFromPeersReturnsFirstHit(t *testing.T) { pm := peerManagerWith([]string{addr1, addr2}) var buf bytes.Buffer - _, _, ok := pm.FetchFromPeers(key, collectSink(&buf)) + _, _, ok := pm.FetchFromPeers(context.Background(), key, collectSink(&buf)) if !ok { t.Fatal("expected peer hit from one of two peers") } @@ -141,11 +143,85 @@ func TestFetchFromPeersReturnsFirstHit(t *testing.T) { func TestFetchFromPeersEmptyPeerList(t *testing.T) { pm := peerManagerWith(nil) var buf bytes.Buffer - if _, _, ok := pm.FetchFromPeers(strings.Repeat("a", 64), collectSink(&buf)); ok { + if _, _, ok := pm.FetchFromPeers(context.Background(), strings.Repeat("a", 64), collectSink(&buf)); ok { t.Error("expected miss when no peers are known") } } +func TestFetchFromPeersHonorsCallerCancellationDuringProbe(t *testing.T) { + started := make(chan struct{}) + srv := httptest.NewServer(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { + close(started) + <-r.Context().Done() + })) + t.Cleanup(srv.Close) + + pm := peerManagerWith([]string{strings.TrimPrefix(srv.URL, "http://")}) + ctx, cancel := context.WithCancel(context.Background()) + done := make(chan struct{}) + go func() { + defer close(done) + var buf bytes.Buffer + _, _, _ = pm.FetchFromPeers(ctx, strings.Repeat("d", 64), collectSink(&buf)) + }() + <-started + cancel() + select { + case <-done: + case <-time.After(time.Second): + t.Fatal("peer probe did not stop after caller cancellation") + } +} + +func TestFetchFromPeersHonorsCallerCancellationDuringBodyAndReportsBytes(t *testing.T) { + key := strings.Repeat("e", 64) + bodyStarted := make(chan struct{}) + sinkStarted := make(chan struct{}) + mux := http.NewServeMux() + mux.HandleFunc("/cache/has", func(w http.ResponseWriter, _ *http.Request) { + w.WriteHeader(http.StatusOK) + }) + mux.HandleFunc("/cache/get", func(w http.ResponseWriter, r *http.Request) { + flusher, _ := w.(http.Flusher) + _, _ = w.Write([]byte("partial")) + if flusher != nil { + flusher.Flush() + } + close(bodyStarted) + <-r.Context().Done() + }) + srv := httptest.NewServer(mux) + t.Cleanup(srv.Close) + + pm := peerManagerWith([]string{strings.TrimPrefix(srv.URL, "http://")}) + ctx, cancel := context.WithCancel(context.Background()) + done := make(chan int64, 1) + go func() { + _, n, _ := pm.FetchFromPeers(ctx, key, func(r io.Reader) (int64, error) { + buf := make([]byte, len("partial")) + first, err := io.ReadFull(r, buf) + close(sinkStarted) + if err != nil { + return int64(first), err + } + rest, err := io.Copy(io.Discard, r) + return int64(first) + rest, err + }) + done <- n + }() + <-bodyStarted + <-sinkStarted + cancel() + select { + case n := <-done: + if n == 0 { + t.Fatal("canceled peer transfer lost its partial-byte accounting") + } + case <-time.After(time.Second): + t.Fatal("peer body transfer did not stop after caller cancellation") + } +} + func TestPeerServesBlockKeys(t *testing.T) { store, err := NewDiskCache(t.TempDir(), 80) if err != nil { diff --git a/cmd/cache-proxy/proxy.go b/cmd/cache-proxy/proxy.go index d5232191..d2061635 100644 --- a/cmd/cache-proxy/proxy.go +++ b/cmd/cache-proxy/proxy.go @@ -30,10 +30,21 @@ func requestSpanAttrs(r *http.Request) []attribute.KeyValue { attribute.String("server.address", r.URL.Host), attribute.String("url.path", r.URL.Path), attribute.String("duckgres.s3.range", r.Header.Get("Range")), - attribute.String("client.address", r.RemoteAddr), + attribute.String("client.address", clientAddress(r.RemoteAddr)), } } +// clientAddress removes the ephemeral source port so Served. logs and traces +// can be grouped by worker address. RemoteAddr is kernel-owned; unlike a +// forwarded header it cannot be spoofed by the HTTP client. +func clientAddress(remoteAddr string) string { + host, _, err := net.SplitHostPort(remoteAddr) + if err == nil { + return host + } + return remoteAddr +} + // CacheProxy is a forward HTTP proxy that caches responses on local NVMe. // DuckDB httpfs sends each S3 request as a signed plain-HTTP request to the // proxy; the proxy caches by URL+Range and forwards misses verbatim. The @@ -62,6 +73,8 @@ type CacheProxy struct { blockMode bool blockSize int64 maxSpanBlocks int64 + peerPolicy *peerFetchPolicy + blockFlights originSpanFlights // objectSizes remembers validated complete lengths learned from origin // Content-Range responses. Disk blocks remain the durable cache; this map @@ -133,6 +146,10 @@ func NewCacheProxy(store *DiskCache, peers *PeerManager, cacheHostSuffixes []str originRetryInitialBackoff: defaultOriginRetryInitialBackoff, originRetryMaxBackoff: defaultOriginRetryMaxBackoff, cacheHostSuffixes: cacheHostSuffixes, + peerPolicy: newPeerFetchPolicy(defaultPeerFetchPolicyConfig( + defaultPeerFetchMaxConcurrent, + defaultPeerFetchMaxBytes(defaultPeerFetchMaxConcurrent, 8<<20), + )), } } @@ -176,7 +193,7 @@ func (p *CacheProxy) handleConnect(w http.ResponseWriter, r *http.Request) { target := r.Host _, span := proxyTracer.Start(r.Context(), "cache.connect", trace.WithAttributes( attribute.String("server.address", target), - attribute.String("client.address", r.RemoteAddr), + attribute.String("client.address", clientAddress(r.RemoteAddr)), )) upstream, err := net.DialTimeout("tcp", target, 10*time.Second) if err != nil { @@ -321,7 +338,8 @@ func (p *CacheProxy) HandleProxy(w http.ResponseWriter, r *http.Request) { attribute.Bool("duckgres.cache.hit", true), attribute.Int64("duckgres.bytes", size), ) - slog.Info("Served.", "source", "hit", "url", r.URL.String(), "range", rangeHeader, "bytes", size) + slog.Info("Served.", "source", "hit", "client", clientAddress(r.RemoteAddr), + "url", r.URL.String(), "range", rangeHeader, "bytes", size) p.serveStream(w, reader, size, rangeHeader, "") _ = reader.Close() return @@ -370,7 +388,8 @@ func (p *CacheProxy) HandleProxy(w http.ResponseWriter, r *http.Request) { attribute.String("duckgres.cache.source", res.source), attribute.Int64("duckgres.bytes", size), ) - slog.Info("Served.", "source", res.source, "url", r.URL.String(), "range", rangeHeader, "bytes", size) + slog.Info("Served.", "source", res.source, "client", clientAddress(r.RemoteAddr), + "url", r.URL.String(), "range", rangeHeader, "bytes", size) p.serveStream(w, reader, size, rangeHeader, res.contentType) } @@ -380,18 +399,37 @@ func (p *CacheProxy) HandleProxy(w http.ResponseWriter, r *http.Request) { func (p *CacheProxy) fetchDedup(cacheKey string, r *http.Request, rangeHeader string) (fetchResult, error) { return p.flights.Do(cacheKey, func() (fetchResult, error) { if p.peers != nil { - _, peerSpan := proxyTracer.Start(r.Context(), "cache.peer_fetch") - _, n, ok := p.peers.FetchFromPeers(cacheKey, func(body io.Reader) (int64, error) { - return p.store.PutStream(cacheKey, body) - }) - peerSpan.SetAttributes(attribute.Bool("duckgres.cache.peer_hit", ok)) - if ok { - peerSpan.SetAttributes(attribute.Int64("duckgres.bytes", n)) - } - peerSpan.End() - if ok { - cacheBytesServed.WithLabelValues("peer").Add(float64(n)) - return fetchResult{size: n, source: "peer"}, nil + reservedBytes, bounded := absoluteRangeLength(rangeHeader) + if bounded { + _, peerSpan := proxyTracer.Start(r.Context(), "cache.peer_fetch") + deadline := time.Now() + if p.peerPolicy != nil { + deadline = deadline.Add(p.peerPolicy.headStart()) + } + decision := peerFetchDecision{} + if p.peerPolicy != nil { + allowed, recoverySample := p.peerPolicy.allowPeer(false) + decision = peerFetchDecision{allowed: allowed, nonBlocking: recoverySample} + } + result := p.fetchFromPeers(r.Context(), deadline, reservedBytes, cacheKey, func(body io.Reader) (int64, error) { + return p.store.PutStream(cacheKey, io.LimitReader(body, reservedBytes)) + }, decision, false, nil) + peerSpan.SetAttributes( + attribute.Bool("duckgres.cache.peer_started", result.started), + attribute.Bool("duckgres.cache.peer_hit", result.ok), + ) + if result.ok { + peerSpan.SetAttributes(attribute.Int64("duckgres.bytes", result.bytes)) + } + peerSpan.End() + if result.ok { + cacheBytesServed.WithLabelValues("peer").Add(float64(result.bytes)) + return fetchResult{size: result.bytes, source: "peer"}, nil + } + } else { + // Suffix/open-ended/no-range requests have no trustworthy upper + // bound. Bypass peers rather than evade the process byte ceiling. + peerFetchShedTotal.WithLabelValues("unbounded").Inc() } } originFetchInFlight.Inc() @@ -407,6 +445,19 @@ func (p *CacheProxy) fetchDedup(cacheKey string, r *http.Request, rangeHeader st }) } +func absoluteRangeLength(rangeHeader string) (int64, bool) { + start, end, ok := parseAbsoluteRange(rangeHeader) + if !ok { + return 0, false + } + const maxInt64 = int64(^uint64(0) >> 1) + lengthMinusOne := end - start + if lengthMinusOne == maxInt64 { + return 0, false + } + return lengthMinusOne + 1, true +} + // fetchOrigin forwards the request verbatim (headers, Host, signature) to the // real origin and streams a successful body straight to the on-disk cache, // returning the stored size and Content-Type. The SigV4 signature remains valid diff --git a/cmd/cache-proxy/proxy_test.go b/cmd/cache-proxy/proxy_test.go index 4d2790d4..7f82b541 100644 --- a/cmd/cache-proxy/proxy_test.go +++ b/cmd/cache-proxy/proxy_test.go @@ -155,6 +155,42 @@ func TestHandleProxyGETMissThenHit(t *testing.T) { } } +func TestClientAddressStripsEphemeralPort(t *testing.T) { + tests := map[string]string{ + "10.0.0.7:54321": "10.0.0.7", + "[2001:db8::7]:80": "2001:db8::7", + "worker-name": "worker-name", + } + for remote, want := range tests { + if got := clientAddress(remote); got != want { + t.Errorf("clientAddress(%q) = %q, want %q", remote, got, want) + } + } +} + +func TestServedLogIncludesClientAddressWithoutPort(t *testing.T) { + proxy := newTestProxy(t) + _, originURL := newTestServer(t, func(w http.ResponseWriter, _ *http.Request) { + _, _ = w.Write([]byte("body")) + }) + logs, restore := captureSlog(t) + defer restore() + + req := httptest.NewRequest(http.MethodGet, originURL+"/bucket/client.parquet", nil) + req.Host = req.URL.Host + req.RemoteAddr = "10.0.0.7:54321" + req.Header.Set("Range", "bytes=0-3") + proxy.HandleProxy(httptest.NewRecorder(), req) + + got := logs.String() + if !strings.Contains(got, `msg=Served.`) || !strings.Contains(got, `client=10.0.0.7`) { + t.Fatalf("Served log missing stable client address: %s", got) + } + if strings.Contains(got, "54321") { + t.Fatalf("Served log retained ephemeral client port: %s", got) + } +} + func TestHandleProxyHEADForwardedUncached(t *testing.T) { proxy := newTestProxy(t) @@ -1381,3 +1417,62 @@ func TestForwardUncachedPreservesMethod(t *testing.T) { }) } } + +func TestLegacyPeerFetchUsesProcessWideCap(t *testing.T) { + const requests = 4 + release := make(chan struct{}) + var active, maxActive atomic.Int32 + data := []byte("peer-data") + + mux := http.NewServeMux() + mux.HandleFunc("/cache/has", func(w http.ResponseWriter, _ *http.Request) { + w.WriteHeader(http.StatusOK) + }) + mux.HandleFunc("/cache/get", func(w http.ResponseWriter, _ *http.Request) { + current := active.Add(1) + defer active.Add(-1) + for { + prior := maxActive.Load() + if current <= prior || maxActive.CompareAndSwap(prior, current) { + break + } + } + <-release + _, _ = w.Write(data) + }) + peer := httptest.NewServer(mux) + t.Cleanup(peer.Close) + + store, err := NewDiskCache(t.TempDir(), 80) + if err != nil { + t.Fatal(err) + } + p := NewCacheProxy(store, peerManagerWith([]string{strings.TrimPrefix(peer.URL, "http://")}), nil) + setTestPeerPolicy(p, 2, 2*int64(len(data)), 150*time.Millisecond) + + results := make(chan error, requests) + for i := 0; i < requests; i++ { + go func(i int) { + rawURL := fmt.Sprintf("http://example.test/file-%d.parquet", i) + u, _ := url.Parse(rawURL) + req := (&http.Request{ + Method: http.MethodGet, + URL: u, + Host: u.Host, + Header: http.Header{"Range": []string{"bytes=0-8"}}, + }).WithContext(context.Background()) + _, err := p.fetchDedup(CacheKey(rawURL, "bytes=0-8"), req, "bytes=0-8") + results <- err + }(i) + } + time.Sleep(50 * time.Millisecond) + close(release) + for i := 0; i < requests; i++ { + if err := <-results; err != nil { + t.Fatalf("fetchDedup: %v", err) + } + } + if got := maxActive.Load(); got > 2 { + t.Fatalf("legacy concurrent peer GETs = %d, want <= 2", got) + } +} diff --git a/docs/metrics.md b/docs/metrics.md index bddceb45..193466c6 100644 --- a/docs/metrics.md +++ b/docs/metrics.md @@ -223,6 +223,25 @@ These are emitted by the standalone `cache-proxy` binary itself (`cmd/cache-prox | `cache_proxy_request_duration_seconds` | Histogram | `path`, `source` | End-to-end duration of a served request. `path` is `block` (block-aligned cache path) or `forward` (uncached forward-proxy path); `source` is `local`, `peer`, or `s3` for `block`, and always `origin` for `forward`. | | `cache_proxy_forward_requests_total` | Counter | `method` | Requests handled by the uncached forward-proxy path, by HTTP method. | | `cache_proxy_inflight_requests` | Gauge | None | Requests currently being handled by the proxy's request entry point; the queue-depth signal. | +| `cache_proxy_origin_fetches_total` | Counter | `outcome` | Origin cache-fill outcomes across legacy and block-aligned paths. | +| `cache_proxy_origin_fetches_in_flight` | Gauge | None | Actual origin cache fills currently running, including shared block-span producers (waiters are not double-counted). | +| `cache_proxy_origin_fetch_retries_total` | Counter | `reason` | Legacy origin-fetch retries by failure reason; block-span hedges do not retry here. | +| `cache_proxy_peer_hedges_total` | Counter | None | Coalesced origin spans started while all blocks in the span could still arrive from peers. | +| `cache_proxy_peer_hedge_wins_total` | Counter | `winner` | Completed hedge races won by `peer` or `origin`. | +| `cache_proxy_fetch_cancellations_total` | Counter | `side` | Losing `peer` or `origin` transfers canceled after the other side won. | +| `cache_proxy_hedge_duplicate_bytes_total` | Counter | `side` | Bytes received from a losing `peer` or `origin` transfer before cancellation took effect. | +| `cache_proxy_late_peer_successes_total` | Counter | None | Peer transfers that raced with an origin winner but nevertheless committed successfully. | +| `cache_proxy_peer_breaker_transitions_total` | Counter | `state` | Circuit-breaker transitions to `open` or `closed`. | +| `cache_proxy_peer_breaker_state` | Gauge | None | `1` while peer fetching is circuit-broken; `0` while closed. | +| `cache_proxy_peer_fetches_in_flight` | Gauge | None | Peer lookup/body transfers holding a process-wide concurrency permit. | +| `cache_proxy_peer_fetch_bytes_in_flight` | Gauge | None | Bytes reserved by admitted peer transfers. | +| `cache_proxy_peer_fetch_shed_total` | Counter | `reason` | Peer work skipped before network I/O: `deadline`, `capacity`, `canceled`, `breaker`, `unbounded`, or `unconfigured`. | +| `cache_proxy_peer_fetch_queue_duration_seconds` | Histogram | None | Time waiting for the global count and byte permits. | +| `cache_proxy_peer_fetch_duration_seconds` | Histogram | `outcome` | Admitted peer lookup plus body-transfer duration for `hit`, `miss`, or `canceled`. | +| `cache_proxy_origin_span_fetch_duration_seconds` | Histogram | `outcome` | Block-aligned coalesced origin fetch duration for `success`, `error`, or `canceled`. | +| `cache_proxy_peer_hedge_head_start_seconds` | Gauge | None | Current rolling-p50 peer head start, clamped to 25–150 ms. | +| `cache_proxy_peer_fetch_latency_ewma_seconds` | Gauge | None | EWMA of successful peer block fetch latency plus canceled lower bounds that already exceeded the 1.5× breaker threshold. | +| `cache_proxy_origin_fetch_latency_ewma_seconds` | Gauge | None | EWMA of time through a validated, atomically committed first origin block, the peer-comparable breaker input from an otherwise coalesced span. | ## PromQL recipes