From 54db9ea8052f67ba4e271d537993cd5d6621bd42 Mon Sep 17 00:00:00 2001 From: Austin Born Date: Sun, 26 Jul 2026 02:43:31 -0700 Subject: [PATCH 1/2] fix(orders): stop retention prune burning a tick on already-gone beads MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit The closed-order-tracking retention prune runs from two independent places that neither coordinate nor share a process: the controller's in-process retention watchdog, and the `gc order sweep-tracking` command an order can fire on its own cadence. Both list the same closed set live, so neither sees the other's deletions, and the sweeper that runs second finds every bead the first already removed. That race was survivable. Two things made it expensive. First, a delete failing with ErrNotFound was joined into the sweep error, so the loser reported thousands of failures for beads that were in exactly the state it wanted them in. One operator's supervisor log carried 3334 such failures across 3223 distinct ids. Second, the bounded sweep's budget counted only successful deletes, so a list whose beads had all been pruned by the other sweeper never reached the limit and walked the entire backlog. Each attempt costs a full deleteWorkflowBead pass, which walks both dependency directions before deleting; on the subprocess-backed store that is several bd invocations per bead. Treat an already-gone delete as already-pruned rather than a failure, and budget delete attempts rather than successes. The reported count still reflects real prunes, so the watchdog's "pruned N closed bead(s)" line keeps its meaning. This bounds the loser of the race. It does not stop the duplicated work, which needs the prune to have a single owner or to be single-flighted across both entry points; that is tracked separately. Generated by the operator's software factory. City: factory-main · Agent: local-core.builder-1 On behalf of: @austinborn Co-Authored-By: .invalid> --- cmd/gc/order_dispatch.go | 74 +++++++++++++++++----- cmd/gc/order_dispatch_test.go | 114 ++++++++++++++++++++++++++++++++++ 2 files changed, 174 insertions(+), 14 deletions(-) diff --git a/cmd/gc/order_dispatch.go b/cmd/gc/order_dispatch.go index cf8106aa013..1bef5dd615c 100644 --- a/cmd/gc/order_dispatch.go +++ b/cmd/gc/order_dispatch.go @@ -2356,27 +2356,33 @@ func sweepClosedOrderTrackingRetentionAcrossStores(stores []beads.Store, now tim // sweepClosedOrderTrackingRetentionAcrossStoresBounded is the watchdog variant // of sweepClosedOrderTrackingRetentionAcrossStores. It stops once the total -// deletion count across all stores reaches limit, returning the partial deleted +// delete ATTEMPTS across all stores reach limit, returning the partial deleted // count with a nil error on budget exhaustion. Store errors are returned as // normal; deletion errors within budget are propagated. +// +// The returned count stays the number of beads actually deleted, so the +// watchdog's "pruned N closed bead(s)" line keeps reporting real prunes; the +// attempt tally is internal and only spends the budget. func sweepClosedOrderTrackingRetentionAcrossStoresBounded(stores []beads.Store, now time.Time, policy orderTrackingRetentionPolicy, onlyOrders map[string]struct{}, limit int) (int, error) { //nolint:unparam // onlyOrders is nil at all current call sites; preserved for API parity with the unbounded variant if limit <= 0 { return 0, nil } deleted := 0 + attempted := 0 var errs []error for i, store := range stores { if store == nil { continue } - remaining := limit - deleted + remaining := limit - attempted if remaining <= 0 { break } // Enforce the global budget by passing the remaining allowance to the - // per-store bounded sweep, which stops deleting once it is spent. - n, err := sweepClosedOrderTrackingRetentionBounded(store, now, policy, onlyOrders, remaining) + // per-store bounded sweep, which stops once it is spent. + n, tried, err := sweepClosedOrderTrackingRetentionBounded(store, now, policy, onlyOrders, remaining) deleted += n + attempted += tried if err != nil { errs = append(errs, fmt.Errorf("pruning closed order-tracking %s: %w", orderTrackingSweepStoreLabel(store, i), err)) } @@ -2384,6 +2390,26 @@ func sweepClosedOrderTrackingRetentionAcrossStoresBounded(stores []beads.Store, return deleted, errors.Join(errs...) } +// orderTrackingRetentionDeleteAlreadyGone reports whether a retention-prune +// delete failed only because the bead is already absent. +// +// The closed-tracking prune runs from two independent places: the controller's +// runOrderTrackingRetentionWatchdog and the `gc order sweep-tracking` command an +// order can fire on its own cadence. Both list the same closed set live (the +// LiveReader handle bypasses the cache) and then delete bead-by-bead, so a bead +// the other sweeper removed between our list and our delete comes back as +// ErrNotFound. That is not a failure: the bead being gone IS the state the prune +// was trying to reach, so it is counted as already-pruned rather than joined +// into the sweep error. +// +// Treating it as a failure is what produced the observed pathology: a single +// watchdog invocation emitting thousands of `deleting closed order-tracking bead +// "...": bead not found` lines, because the loser of the race re-attempted every +// bead the winner had already deleted. +func orderTrackingRetentionDeleteAlreadyGone(err error) bool { + return errors.Is(err, beads.ErrNotFound) +} + func sweepClosedOrderTrackingRetention(store beads.Store, now time.Time, policy orderTrackingRetentionPolicy, onlyOrders map[string]struct{}) (int, error) { if store == nil { return 0, fmt.Errorf("bead store unavailable") @@ -2425,6 +2451,10 @@ func sweepClosedOrderTrackingRetention(store beads.Store, now time.Time, policy // deleteWorkflowBead is the graph-aware delete (dep unwind) the // retention prune uses; it stays raw graph residual. if err := deleteWorkflowBead(store, run.ID); err != nil { + if orderTrackingRetentionDeleteAlreadyGone(err) { + // A concurrent sweeper already pruned it. That is the goal state. + continue + } deleteErr = errors.Join(deleteErr, fmt.Errorf("deleting closed order-tracking bead %q: %w", run.ID, err)) continue } @@ -2435,31 +2465,42 @@ func sweepClosedOrderTrackingRetention(store beads.Store, now time.Time, policy } // sweepClosedOrderTrackingRetentionBounded is the per-store bounded variant of -// sweepClosedOrderTrackingRetention. It stops deleting once limit deletions have -// occurred within this store call. On budget exhaustion it returns the partial -// count with a nil error; delete errors are still propagated. -func sweepClosedOrderTrackingRetentionBounded(store beads.Store, now time.Time, policy orderTrackingRetentionPolicy, onlyOrders map[string]struct{}, limit int) (int, error) { +// sweepClosedOrderTrackingRetention. It stops once limit delete ATTEMPTS have +// been made within this store call, and returns both the number of beads it +// actually deleted and the number of attempts it spent. On budget exhaustion it +// returns the partial counts with a nil error; delete errors are still +// propagated. +// +// The budget counts attempts rather than successes because every attempt costs +// the same bounded work regardless of outcome. deleteWorkflowBead walks both +// dep directions before deleting, which on the subprocess-backed store is +// several `bd` invocations per bead. Budgeting successes alone let a list whose +// beads had all been pruned by a concurrent sweeper burn thousands of failing +// attempts in a single watchdog tick without ever reaching the limit, which is +// the controller-tick churn this bound exists to cap. +func sweepClosedOrderTrackingRetentionBounded(store beads.Store, now time.Time, policy orderTrackingRetentionPolicy, onlyOrders map[string]struct{}, limit int) (int, int, error) { if store == nil { - return 0, fmt.Errorf("bead store unavailable") + return 0, 0, fmt.Errorf("bead store unavailable") } if policy.deleteAfterClose <= 0 || limit <= 0 { - return 0, nil + return 0, 0, nil } if policy.retainLast < minClosedOrderTrackingRetained { policy.retainLast = minClosedOrderTrackingRetained } runs, err := orders.NewStore(beads.OrdersStore{Store: store}).ClosedRunsForRetention() if err != nil { - return 0, fmt.Errorf("listing closed order-tracking beads: %w", err) + return 0, 0, fmt.Errorf("listing closed order-tracking beads: %w", err) } byOrder := bucketClosedRetentionRuns(runs, onlyOrders) cutoff := now.Add(-policy.deleteAfterClose) deleted := 0 + attempted := 0 var deleteErr error for _, runs := range byOrder { - if deleted >= limit { + if attempted >= limit { break } sort.Slice(runs, func(i, j int) bool { @@ -2474,20 +2515,25 @@ func sweepClosedOrderTrackingRetentionBounded(store beads.Store, now time.Time, continue } for _, run := range runs[policy.retainLast:] { - if deleted >= limit { + if attempted >= limit { break } if !orderTrackingClosedReferenceTime(run).Before(cutoff) { continue } + attempted++ if err := deleteWorkflowBead(store, run.ID); err != nil { + if orderTrackingRetentionDeleteAlreadyGone(err) { + // A concurrent sweeper already pruned it. That is the goal state. + continue + } deleteErr = errors.Join(deleteErr, fmt.Errorf("deleting closed order-tracking bead %q: %w", run.ID, err)) continue } deleted++ } } - return deleted, deleteErr + return deleted, attempted, deleteErr } func orderTrackingRetentionBucket(run orders.OrderRun, onlyOrders map[string]struct{}) (string, bool) { diff --git a/cmd/gc/order_dispatch_test.go b/cmd/gc/order_dispatch_test.go index fce6e356f6c..fa586d8ef01 100644 --- a/cmd/gc/order_dispatch_test.go +++ b/cmd/gc/order_dispatch_test.go @@ -10143,6 +10143,120 @@ func TestSweepClosedOrderTrackingRetentionAcrossStoresBounded_ZeroLimitDeletesNo } } +// goneDeleteStore reports every bead as already absent at delete time, which is +// what the store does when a concurrent sweeper pruned the bead between our +// live list and our delete. It counts delete calls so a test can assert how much +// work a sweep spent, not just what it returned. +type goneDeleteStore struct { + *beads.MemStore + deleteCalls int +} + +func (s *goneDeleteStore) Delete(id string) error { + s.deleteCalls++ + return fmt.Errorf("deleting bead %q: %w", id, beads.ErrNotFound) +} + +// seedClosedTrackingRuns builds n closed order-tracking beads for one order, all +// aged past a 24h TTL. +func seedClosedTrackingRuns(prefix string, n int, now time.Time) []beads.Bead { + seed := make([]beads.Bead, 0, n) + for i := range n { + seed = append(seed, beads.Bead{ + ID: fmt.Sprintf("%s-%03d", prefix, i), + Title: "order:" + prefix, + Status: "closed", + Type: "task", + CreatedAt: now.Add(-48*time.Hour + time.Duration(i)*time.Minute), + Labels: []string{"order-run:" + prefix, labelOrderTracking}, + Ephemeral: true, + }) + } + return seed +} + +// TestSweepClosedOrderTrackingRetentionTreatsAlreadyGoneBeadAsPruned pins the +// idempotency half of the fix: a bead a concurrent sweeper already deleted is +// the state the prune was trying to reach, so it must not be joined into the +// sweep error. Reporting it as a failure is what made one watchdog invocation +// emit thousands of `bead not found` lines. +func TestSweepClosedOrderTrackingRetentionTreatsAlreadyGoneBeadAsPruned(t *testing.T) { + now := time.Date(2026, 7, 26, 12, 0, 0, 0, time.UTC) + store := &goneDeleteStore{ + MemStore: beads.NewMemStoreFrom(100, seedClosedTrackingRuns("gone", minClosedOrderTrackingRetained+3, now), nil), + } + + deleted, err := sweepClosedOrderTrackingRetention(store, now, orderTrackingRetentionPolicy{ + deleteAfterClose: 24 * time.Hour, + retainLast: minClosedOrderTrackingRetained, + }, nil) + if err != nil { + t.Fatalf("err = %v, want nil (already-gone beads are not sweep failures)", err) + } + if deleted != 0 { + t.Fatalf("deleted = %d, want 0 (nothing was actually pruned by this sweep)", deleted) + } + if store.deleteCalls != 3 { + t.Fatalf("deleteCalls = %d, want 3 (the eligible beads past the retain floor)", store.deleteCalls) + } +} + +// TestSweepClosedOrderTrackingRetentionBoundedCapsAttemptsWhenBeadsAlreadyGone +// is the churn regression test. The watchdog's delete budget used to count only +// successes, so a list whose beads had all been pruned by the other sweeper +// never reached the limit and walked the entire backlog — thousands of `bd` +// subprocess spawns in one controller tick. The budget now counts attempts, so +// the sweep stops after `limit` deletes regardless of their outcome. +func TestSweepClosedOrderTrackingRetentionBoundedCapsAttemptsWhenBeadsAlreadyGone(t *testing.T) { + now := time.Date(2026, 7, 26, 12, 0, 0, 0, time.UTC) + const eligible = 200 + store := &goneDeleteStore{ + MemStore: beads.NewMemStoreFrom(1000, seedClosedTrackingRuns("churn", minClosedOrderTrackingRetained+eligible, now), nil), + } + + deleted, err := sweepClosedOrderTrackingRetentionAcrossStoresBounded( + []beads.Store{store}, now, orderTrackingRetentionPolicy{ + deleteAfterClose: 24 * time.Hour, + retainLast: minClosedOrderTrackingRetained, + }, nil, 5) + if err != nil { + t.Fatalf("err = %v, want nil (already-gone beads are not sweep failures)", err) + } + if deleted != 0 { + t.Fatalf("deleted = %d, want 0 (every bead was already gone)", deleted) + } + if store.deleteCalls != 5 { + t.Fatalf("deleteCalls = %d, want 5 (attempt budget must cap the sweep; %d beads were eligible)", store.deleteCalls, eligible) + } +} + +// TestSweepClosedOrderTrackingRetentionBoundedCountsOnlyRealDeletions pins that +// already-gone beads spend the budget without inflating the pruned count the +// watchdog reports. +func TestSweepClosedOrderTrackingRetentionBoundedCountsOnlyRealDeletions(t *testing.T) { + now := time.Date(2026, 7, 26, 12, 0, 0, 0, time.UTC) + goneStore := &goneDeleteStore{ + MemStore: beads.NewMemStoreFrom(100, seedClosedTrackingRuns("vanished", minClosedOrderTrackingRetained+4, now), nil), + } + liveStore := beads.NewMemStoreFrom(100, seedClosedTrackingRuns("present", minClosedOrderTrackingRetained+4, now), nil) + + // limit=6 spans both stores: 4 already-gone attempts, then 2 real deletions. + deleted, err := sweepClosedOrderTrackingRetentionAcrossStoresBounded( + []beads.Store{goneStore, liveStore}, now, orderTrackingRetentionPolicy{ + deleteAfterClose: 24 * time.Hour, + retainLast: minClosedOrderTrackingRetained, + }, nil, 6) + if err != nil { + t.Fatalf("err = %v, want nil", err) + } + if deleted != 2 { + t.Fatalf("deleted = %d, want 2 (only the beads this sweep actually removed)", deleted) + } + if goneStore.deleteCalls != 4 { + t.Fatalf("goneStore.deleteCalls = %d, want 4", goneStore.deleteCalls) + } +} + // TestLastRunFuncGatesFallbackOnIndexMiss pins #3201: the per-order fallback // (a serial bd-query) must fire only on a genuine index miss. An index hit must // return the indexed time without consulting the fallback — otherwise every From 5bc427e93152b7601cf8a5faa00e066fbf676dda Mon Sep 17 00:00:00 2001 From: Austin Born Date: Sun, 26 Jul 2026 03:13:48 -0700 Subject: [PATCH 2/2] docs(orders): state the retention budget in attempts, not deletions MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit The prior commit on this branch changed the closed-order-tracking retention budget to count delete attempts rather than successful deletions. Two doc comments were left describing the old success-based behavior. orderTrackingRetentionWatchdogDeleteBudget's comment still said it bounds the number of beads deleted per invocation. That constant is what the whole fix hinges on, so a maintainer reading only the comment could "correct" the attempt counter back to counting successes and silently reintroduce the churn the fix removes. It now states the attempt semantics and the reason for them. runOrderTrackingRetentionWatchdog's comment carried the same pre-fix framing, at the other place a reader looks to learn the budget's unit. It now says the watchdog makes at most that many delete attempts, and notes that beads a concurrent sweeper already removed spend budget without counting toward the pruned total it reports. Comment-only. No behavior change. Generated by the operator's software factory. City: factory-main · Agent: local-core.builder-1 On behalf of: @austinborn Co-Authored-By: .invalid> --- cmd/gc/city_runtime.go | 6 ++++-- cmd/gc/order_dispatch.go | 8 ++++++-- 2 files changed, 10 insertions(+), 4 deletions(-) diff --git a/cmd/gc/city_runtime.go b/cmd/gc/city_runtime.go index d0a237659af..0d3b4c4b504 100644 --- a/cmd/gc/city_runtime.go +++ b/cmd/gc/city_runtime.go @@ -1470,8 +1470,10 @@ func (cr *CityRuntime) runOrderTrackingSweepWatchdog(now time.Time) { // runOrderTrackingRetentionWatchdog deletes closed order-tracking beads that // are past their TTL (defaulting to 7d) and beyond the retain-10 floor, at -// most once every orderTrackingRetentionWatchdogInterval. It deletes at most -// orderTrackingRetentionWatchdogDeleteBudget beads per invocation. +// most once every orderTrackingRetentionWatchdogInterval. It makes at most +// orderTrackingRetentionWatchdogDeleteBudget delete attempts per invocation; +// beads a concurrent sweeper already removed spend the budget without counting +// toward the pruned total this reports. func (cr *CityRuntime) runOrderTrackingRetentionWatchdog(now time.Time) { if !cr.orderTrackingRetentionWatchdogLast.IsZero() && now.Sub(cr.orderTrackingRetentionWatchdogLast) < orderTrackingRetentionWatchdogInterval { diff --git a/cmd/gc/order_dispatch.go b/cmd/gc/order_dispatch.go index 1bef5dd615c..d988e5ed20a 100644 --- a/cmd/gc/order_dispatch.go +++ b/cmd/gc/order_dispatch.go @@ -94,8 +94,12 @@ const ( // controller-driven closed-bead retention sweeps. 15 minutes balances // effective cleanup against per-tick overhead. orderTrackingRetentionWatchdogInterval = 15 * time.Minute - // orderTrackingRetentionWatchdogDeleteBudget bounds the number of - // closed order-tracking beads deleted per watchdog invocation. + // orderTrackingRetentionWatchdogDeleteBudget bounds the number of closed + // order-tracking delete ATTEMPTS per watchdog invocation. It deliberately + // counts attempts rather than successful deletions: every attempt costs the + // same several `bd` subprocesses regardless of outcome, so budgeting + // successes alone let a backlog whose beads a concurrent sweeper had + // already removed walk the whole list without ever reaching the limit. orderTrackingRetentionWatchdogDeleteBudget = 100 )