The cloud probe budget test no longer fails when the thread pool is starved (#4741)

[erikdarlingdata]

Fixes #4741

Why

ProbeAsync_NeitherCloudResponds_ReturnsNone_WithinItsOwnBudget asserted that the whole probe call finished in under 2000 ms against a 200 ms budget. It failed on CI at 2035 ms and 2084 ms with the probe unchanged since #4330.

The cause is thread-pool starvation. CancelAfter's timer callback, and every continuation after it, need a free pool thread. When the other tests in a shard hold the pool's threads, the pool adds about one thread per 500 ms, so the budget itself fires late. The clock cannot tell a slow probe from a starved pool, and the probe has no say in the second.

Diagnosis, measured

Harness: queue N work items that each wait on one event, leave SetMinThreads alone, then time the test's own ProbeAsync call with its fake handler. One process per run, so the pool starts fresh. The harness recorded three times per run: the moment the budget token was cancelled ("cancel-fired"), the moment the fake handler's own continuation ran, and the test's total elapsed time.

4 processors (DOTNET_PROCESSOR_COUNT=4, the shape of CI's Windows runner), blocked with ManualResetEventSlim:

N blocked	elapsed	cancel-fired
0	205 ms	203 ms
4 (1 x cores)	968 ms	966 ms
8 (2 x cores)	993 ms	990 ms
16 (4 x cores)	587 ms	584 ms

A wider sweep at 4 processors (N = 4, 5, 6, 8, 12, 24, 60, two blocking styles, two runs each, 28 runs) ranged from 541 ms to 2492 ms. Two of the 28 runs went past 2 s (2492 ms and 2289 ms), which is the CI symptom.

32 processors (this machine's natural count):

N blocked	elapsed, run 1	elapsed, run 2
0	206 ms	215 ms
32 (1 x cores)	4578 ms	245 ms
64 (2 x cores)	1567 ms	833 ms
128 (4 x cores)	3278 ms	886 ms

In every slow run the cancel-fired time was within a few milliseconds of the total elapsed time (for example 4573 ms of 4578 ms). The delay is the budget firing late, not slow work after the cancellation. In these tests SynchronizationContext.Current is null, so the continuations go through the pool too; there is no separate queue to blame.

Is there a wait the budget token does not bound? No.

I read ProbeAsync, TryEc2Async, TryAzureAsync and ReadCappedValueAsync in DarlingCloudIdentityProbe.cs:

• Line 126-127: one linked source, one CancelAfter(ProbeBudget).
• Line 133: HttpClient.Timeout is infinite, so there is no second timeout.
• Lines 139 and 145: both cloud attempts use budget.Token. Lines 173, 185, 199 (SendAsync) and 218, 225 (ReadAsStreamAsync, ReadAsync) all pass it through.
• No retry, no Task.Delay, no .Result, .Wait( or GetAwaiter. The disposals (using, await using at 219) do not wait.

So there is no product change and no CHANGELOG entry.

What changes

Test only, in Darling/Darling.Tests/DarlingCloudIdentityProbeTests.cs:

• ProbeAsync_NeitherCloudResponds_ReturnsNone_WithinItsOwnBudget no longer has a wall-clock upper bound on the budget itself. The fake handler records when its first request started and when that request's own Task.Delay ended. The test asserts: the probe returned None; the handler's first request started within 1000 ms of the call; the handler's request was ended before the probe returned (so the budget cancelled it rather than the probe walking away from a pending request); that end was not earlier than half the budget (a one-sided bound, since starvation can only make it later); and ProbeAsync returned within 1000 ms of that end. A 30 s WaitAsync hang guard turns "the probe never cancels its handler" into a failure instead of a hang until the job timeout.
• New ProbeBudget_IsTwoHundredMilliseconds pins the 200 ms value without a clock. The old check also failed a budget that grew to seconds; this keeps that. CreateHandler_ArmsExactlyOneBudget_NotAPerRequestTimeout already pins that only one budget is armed.
• No other test in this class has the wall-clock shape (the old line 104 was the only one).

Two bars that still catch a wait the budget does not bound

The old < 2000 ms bar also caught extra waiting inside the probe that the budget does not bound (an untokened Task.Delay, say). Two bars keep that. Each one times only steps that need no thread-pool thread, so a starved pool cannot trip them:

• The handler's first request starts within 1000 ms of the call. The path from the test to the handler's Task.Delay (ProbeAsync, TryEc2Async, HttpClient.SendAsync, the fake handler) is synchronous. A wait before the first request shows here.
• ProbeAsync returns within 1000 ms of the first request's end. The cancellation's continuations run inline on the thread that fires the budget, so the probe returns within a few ms of the cancel (4573 ms of 4578 ms in the slow runs above). A wait after the cancel shows here.

Both bars read only the first request's start and end (Interlocked.CompareExchange against -1), so a later attempt cannot overwrite either value and move it past a wait.

When the budget cancels the hanging EC2 request, TryEc2Async throws and the probe's catch block returns None, so the Azure attempt is never made in this test. The code that runs after the cancel is the catch block; the test plan shows where the return bar was proved.

Why not "cancelled within the budget plus slack"

I did not assert the handler's cancel moment against the budget plus a slack (for example 1500 ms). The data above shows the cancellation itself lands at 2.3 to 4.6 s under a blocked pool, so any slack small enough to mean something still flakes, and one large enough not to flake is the hang guard.

Why not a non-parallel collection

It would shrink the starvation window, not remove it (the pool's injection cadence is the same after any earlier test leaves threads blocked), it would serialize part of the suite, and the assertion would still be a clock that can lose to the machine.

Load harness is not committed

The harness clamps the process-wide pool with ThreadPool.SetMaxThreads(min, ...) and blocks every allowed thread, so it starves every test running in parallel with it. It cannot run inside this suite. Setup, for anyone repeating it: run with DOTNET_PROCESSOR_COUNT=4, clamp the max worker threads to the min, queue min-many items that wait on an event, release the event from a dedicated thread after the hold time, then restore the maximum.

Other tests elsewhere in the project use a wall-clock upper bound too (ClipboardTextRetryBudgetTests, PgLogEventsPipelineTests). They are not part of this failure and I left them.

Test plan

• RED: with the pool blocked for 2600 ms, the old test body fails ("took 2606 ms - the 200 ms budget did not bound it"). With a 4000 ms hold it failed at 4016 ms.
• GREEN, with only the hang guard and the half-budget bar (before the two bars above were added): the test, called directly under the same 2600 ms clamp, passed (2612 ms).
• Mutation, the CancelAfter argument changed to 5 ms: the test fails ("the handler's request ended after 11 ms, well before the 200 ms budget: something other than the probe's budget ended it"). Changing the ProbeBudget constant itself is caught by ProbeBudget_IsTwoHundredMilliseconds, since the budget test reads the constant.
• Mutation, the CancelAfter argument changed to infinite: the test fails after 30.3 s with the hang-guard message ("ProbeAsync was still waiting after 30 s: nothing cancelled the handler's request, so the probe's own 200 ms budget is not what bounds it"). Both mutations were reverted; the diff is the test file only.
• RED, plant (a): an untokened await Task.Delay(3000); in ProbeAsync just before the TryEc2Async call. The start bar fails: "the handler's first request started at 3027 ms (-1 means it never started), not within 1000 ms of the call: the probe waited before sending it, and nothing bounds that wait". Reverted.
• Plant (b) as first placed: the same line between the TryEc2Async and TryAzureAsync calls. The test stays green (0.39 s), because the budget's cancel throws out of TryEc2Async and the catch block returns None, so that line is never reached in this test. Reverted.
• RED, plant (b), moved to the only code that runs after the cancel: the same line in the catch block, before return CloudIdentity.None;. The return bar fails: "ProbeAsync returned 3010 ms after the handler's request ended (at 207 ms), not within 1000 ms: the probe waited after the budget cancelled the request, and nothing bounds that wait". Reverted.
• GREEN under load, five runs of the test (assertions as committed): one process per run, DOTNET_PROCESSOR_COUNT=4, the pool's max worker threads clamped to its min (4), four items blocked and released after 2600 ms from a dedicated thread, the test method called directly. All five passed. The call took 2617, 2614, 2614, 2623 and 2620 ms, so the budget fired about 2.4 s late each time, which the old < 2000 ms bar would have failed. The harness stayed uncommitted.
• Darling.Tests builds with 0 warnings and 0 errors.
• DarlingCloudIdentityProbeTests, DarlingCloudIdentityProbeSourcePinTests and DocCommentHygieneTests: 97 passed, 0 failed.
• Full Darling.Tests suite once, without DARLING_TEST_PG: Total 17085, Errors 0, Failed 0, Skipped 1111 (the live tests), Not Run 1 (as the runner printed it; I did not chase that one), 120 s.
• PostgreSQL live tests: not run locally; CI runs them.