Skip to content

test(server): TestReachRank_ExpiredSnapshotAlwaysRefreshes misses its 3s round deadline under load #237

Description

@dborup

Relates to #224, #234

Problem

Under CPU load, TestReachRank_ExpiredSnapshotAlwaysRefreshes in cmd/server sometimes fails with round N: expired snapshot never refreshed. One round exceeds the test's 3 s per-round deadline, while a normal round takes about 13 ms. This is not a race report; that separate flake was #224.

It was found during #234 and measured with another cmd/server -race run looping alongside:

It did not occur in 200 processes after #234, or in two further acceptance runs.

Proposed approach

Before raising the deadline, find out whether a round is starved, or whether a refresh can be delayed by a leftover flight from the previous round. The #234 analysis showed that late singleflight refreshes can outlive a round.

Acceptance

  • go test -race -count=200 -run TestReachRank_ExpiredSnapshotAlwaysRefreshes ./cmd/server/ passes under parallel CPU load.
  • The cause is named in the PR. A deadline is only raised if the cause is genuine scheduling starvation.

Activity

  1. dborup commented on Oct 5, 2026

    @dborup
    OwnerAuthor

    Related test-hardening items from the #234 review (merged), in the same test area:

    1. awaitDegreeRefresh runs only on the success path of TestReachRank_ExpiredSnapshotAlwaysRefreshes. A t.Fatalf in the round loop skips it, so a failing run can leave a stray refresh behind and add a misleading race report in the next test. Register the join with t.Cleanup. Cleanup is LIFO, so it runs before resetReachState's cleanup.
    2. TestIssue1008_PathHopIndexReadyFalseImmediatelyAfterLoad has the same race class as test: TestIssue1008_HandlerReturns503WhileSubpathIndexLoading races the background index build under load (-race flake) #227: it asserts "not ready" right after Load(), and the path-hop builder can win. It failed 1/900 on master under heavy load. A gate like subpathBuildGate for the path-hop builder would fix it.
    3. store.subpathBuildGate = func() { close(building); <-release } closes building unguarded, so a second Load() on the same store would panic. Guard it with sync.Once.
  2. adminopenclaw8-sketch commented on Oct 5, 2026

    @adminopenclaw8-sketch
    Collaborator

    Plan — CS-Macmini #237

    Cause found first, with instrumentation in a scratch copy. Short answer to the
    question in the issue: neither a starved round in the abstract nor a leftover
    singleflight flight from the previous round. The round is starved by the test's
    own 16 hot-spinning goroutines
    , and the delay lands inside the one snapshot
    load the round is waiting for.

    Evidence so far [T] [A]

    Instrumented clone of the test (per-round duration, per-round refresh count,
    singleflight path counters, goroutine dump when a round runs long), -race,
    GOMAXPROCS=2, a loaded host.

    • Slow rounds are load-bound, not scheduler-bound at the test level: the
      slowest round captured was 276 ms of which 272 ms was spent inside
      loadDegreeSnapshot. The round waits on exactly one load.

    • The goroutine dump at that moment shows all 16 spin goroutines parked in
      singleflight.(*Group).DoChan on the group mutex, and the single refresh
      goroutine parked inside the sqlite driver mid-query.

    • A leftover flight is measurable but cheap: a round sees 1-8 flights, of which
      at most one loads; the others return the already-fresh snapshot. Joining a
      leftover costs a caller one iteration, not a round.

    • The backoff path is never entered: degreeFailAt is zero and degreeFailErr
      is nil at every slow round, so the 15 s retry backoff is not involved.

    • Volume of the spin: ~500k-640k refreshDegreeSnapshot calls per test process
      (up to ~30k in a single round), all of which append a singleflight result
      channel that nobody reads.

    • The round-duration tail scales with how hot the spin is. Same host, same
      load, interleaved runs:

      per-request pause requests/process dur p50 dur p99 dur max
      none (master) ~530k 1.9-2.3 ms 17-43 ms 36-75 ms
      100 us ~30k 1.2-1.4 ms 2-11 ms 2.4-12.2 ms
      1 ms ~7k 2.2-2.4 ms 6-13 ms 8-21 ms
    • Scaled-deadline probe (the 3 s budget scaled 100x down to 30 ms, which turns
      the rare tail event into a measurable rate), 20 processes per cell,
      interleaved: hot spin 9/20, 8/20, 17/20 failed; 100 us pause 0/20, 1/20,
      1/20.

    Fix direction

    Test-only, in TestReachRank_ExpiredSnapshotAlwaysRefreshes:

    1. Give each hammering caller a short pause between requests, so the 16
      callers stop competing with the single refresh goroutine for the few
      available Ps. The round still has 16 concurrent callers hitting the stale
      snapshot continuously across all 300 rounds; it just stops issuing hundreds
      of thousands of requests per process. The 3 s deadline is not raised.
    2. Take the test-hardening item from the test(server): deflake reach_rank hook race and the #1008 not-ready window (#224, #227) #234 review that belongs to this
      test: register awaitDegreeRefresh with t.Cleanup, so the join also runs
      when a round assertion fails and a failing run cannot leave a stray refresh
      behind for the next test (cleanup is LIFO, so it runs before
      resetReachState's cleanup).

    The other two #234 items are in index_ready_1008* and belong to a different
    test; they will be listed as remaining work, not folded in here.

    Checks planned

    • Before/after: -count=200 at the real 3 s deadline, and the scaled-deadline
      rate above, under the same load.
    • Mutants: (a) remove the pause and the round deadline misses come back under
      load at the scaled deadline; (b) force a round failure with the t.Cleanup
      join removed and the reach_rank tests: onDegreeSnapshotLoad written while a previous test's singleflight refresh still reads it (-race flake) #224 stray-refresh race returns in the next test.
    • go test -race ./... for the whole package, go vet, gofmt -l.
    • cmd/server stays read-only, no new map[string]interface{}, fork guards
      unchanged (9 in deploy.yml, 1 in release-fast-path.yml).
  3. added a commit that references this issue on Oct 6, 2026
  4. dborup commented on Oct 6, 2026

    @dborup
    OwnerAuthor

    Fixed by #269 (merged as b8372984).

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Metadata

Metadata

Assignees

No one assigned

    Labels

    No labels
    No labels

    Projects

    No projects

      Milestone

      No milestone

      Relationships

      None yet

      Development

      No branches or pull requests

      Issue actions