Skip to content

fix(outbox): stop the outstanding count checks from piling up - #4569

Merged
iancooper merged 10 commits into
BrighterCommand:masterfrom
guilhermeappel:fix/4554-one-outstanding-check-in-flight
Oct 10, 2026
Merged

iancooper merged 10 commits into
BrighterCommand:masterfrom
guilhermeappel:fix/4554-one-outstanding-check-in-flight

Conversation

@guilhermeappel

@guilhermeappel guilhermeappel commented Oct 9, 2026 •

Copy link
Copy Markdown
Contributor

Description

This is the second of the three PRs I described on issue #4554. With a limit set, the checks of the outstanding count could pile up, and each queued check held a pool thread while it waited on the semaphore. Two changes fix that.

The time of the last check is now recorded when the check is queued, and the write in the queued task, after it took the semaphore, is gone. Before, the time only moved once a queued check got a thread and the semaphore, so every post in between still saw the old time and queued its own check, even with an explicit MaxOutStandingCheckInterval. Now the interval is measured from when the previous check was queued, so setting an interval works as the workaround that was asked for on the issue.

Each mediator also has the Interlocked in-flight flag that was suggested on issue #4554: an int claimed with CompareExchange before the check is queued and released in a finally when the check ends. Only the post that claims it records the time and queues a check. A post that comes while a check is queued or running doesn't queue another and doesn't move the time, so its check is skipped, not deferred. This is what fixes the default interval of zero that AddProducers uses, where every post is due for a check. I left the semaphore alone, but now at most one pool thread per mediator can wait on it. There is one trade-off: if a count never returns, that mediator stops checking until it does, where before the checks piled up behind it. The missing timeout and cancellation on the count will go in the issue I mentioned on PR #4552. The XML docs for MaxOutStandingCheckInterval now say the interval is measured from when the previous check was queued, and that with zero a clear only queues a check if the previous one has finished.

On PR #4552 the second option was to land the async count after these changes. It went in first, but with PR #4564 and this PR all three changes listed there are now in, so the blocking async count only runs with a limit set, and one at a time per mediator.

I also fixed three docs things from my earlier PRs. A comment I wrote in OutstandingMessagesCheck for PR #4552 still said the default ceiling applies with no limit, which stopped being true with the skip at -1 in PR #4564. The comment and the release note I wrote for PR #4564 called the semaphore process-wide, but it is a static field of the generic mediator, so it is shared by every mediator with the same message and transaction types. And I forgot the release note in PR #4552: with an async-only outbox and a limit of 0 or more, PostAsync and DepositPostAsync can now throw OutboxLimitReachedException. That note is now in release_notes.md, next to the one for issue #4554, which I extended for this PR.

Related Issues

Part of issue #4554. The last PR, for the in-memory count, comes next.

Type of Change

  • Bug fix (non-breaking change which fixes an issue)
  • New feature (non-breaking change which adds functionality)
  • Breaking change (fix or feature that would cause existing functionality to change)
  • Documentation update

Checklist

  • I have read the Contributing Guide
  • I have checked the documentation for relevant guidance
  • I have added/updated XML documentation for any public API changes
  • I have added/updated tests as appropriate
  • My changes follow the existing code style and conventions

Additional Notes

  • Tests. Two tests for the first fix hold the semaphore with a second mediator, so the first check can't start: a burst of 50 posts now queues one count, where it queued 50 before, and with an interval of 1s a check queued at 2s that only starts at 2.5s gives no second check at 2.9s and one at 3.2s. For the flag, the mediator's own first check is held open with the interval at zero, and 50 posts give one count, where they gave 51. A last test covers the flag being released and a post that loses it not moving the time; it fails if the flag is never released or if the time is written before the flag is claimed. The two tests that use a second mediator rely on the semaphore being shared, so they will need a change if it ever becomes per mediator.

  • I measured the head of PR fix(outbox): skip the outstanding count when no limit is set #4564 against this branch with AddProducers, a limit of 100000, the default interval and 16 tasks posting at once. Counts are per batch, after a warm-up batch.

    Outbox Posts per batch Counts before Counts after Peak pool threads before / after
    Postgres 512 512 43 to 54 36 / 18
    SQL Server 512 512 32 to 41 31 / 17
    In-memory 2,000 2,000 1 to 6 36 / 16

    The pool's minimum was 16 threads, so after the change it stays at about the minimum. On Postgres the throughput went from about 930 to about 3,000 posts a second; SQL Server was too noisy to compare. In memory the pool's queue peaked at about 1,950 pending work items before and 2 after. With an interval of 1s it is now one count a second, where before five seconds of posting in memory queued up to about 3,000 checks. With no limit neither version counts. Posting one at a time against a database, a post takes longer than a count, so there is still about one count per post there, which is what "only if the previous one has finished" in the docs means.

  • It merges without conflicts with PR fix: TimedOutboxSweeper starvation and publish-confirm floods (#4560) #4562. Both touch OutboxProducerMediator.cs and release_notes.md, but in different places.

  • The Core suite passes on net10.0 and net9.0 (1688 passed, 7 skipped on each).

  • Please merge with a merge commit rather than squash, as CONTRIBUTING asks.

CheckOutstandingMessages decides whether a check is due from
_lastOutStandingMessageCheckAt, but after the constructor that time was
only written by the queued task, once it had a pool thread and the
semaphore shared by every mediator with the same message and transaction
types. Until then every further Post still saw the old time and queued a
check of its own, so a burst of posts queued many counts instead of one.

Write the time when the check is queued, and remove the write at the
start of the task, so the interval is measured from when the previous
check was queued rather than from when it started. Keeping both would
move the time forward again when the check starts. The XML docs for the
interval say so. With an interval of TimeSpan.Zero every post is still
due, so a burst still queues a check per post; a later commit in this
series limits that.

The first test holds the semaphore with a second mediator, so a burst
of 50 posts arrives before the first check starts, and expects one
count. It got 50 before the change. The second test queues a check at
2s that only starts at 2.5s, and expects no second check at 2.9s and
one at 3.2s. CountingOutbox can now hold a count open, and its builder
takes a TimeProvider.

Part of issue BrighterCommand#4554
The comment in CheckOutstandingMessages calls it a process-wide
semaphore. It is a static field of the generic
OutboxProducerMediator<TMessage, TTransaction>, so it is shared by every
mediator with the same message and transaction types.

Part of issue BrighterCommand#4554
With a limit set and the interval at TimeSpan.Zero, which is the
ProducersConfiguration default that AddProducers uses, every post is due
for a check, so a burst queued a check per post. Each one that started
held a pool thread while it waited on the semaphore shared by every
mediator with the same message and transaction types.

Add an int flag on the mediator, claimed with
Interlocked.CompareExchange before the check is queued and released in
a finally around the queued check, however it ends. Only the caller
that claims it records the time and queues the check. A post that finds
a check queued or running does not queue another and does not move the
time, so the check it would have queued is skipped, not deferred: the
next post that is due after it ends queues the next check.

Log.RunningOutstandingMessageCheck now runs after Task.Run, so a logger
that throws cannot leave the flag claimed. If a count never returns,
this mediator stops checking until it does, where before the checks
piled up behind it. The XML docs for the interval now say that with
TimeSpan.Zero a clear queues a check only if the previous one has
finished.

The test holds the mediator's own first check open with an interval of
zero and posts 50 times. It counted 51 before the change and 1 after.
Making the flag static fails both tests added by the previous fix, which
records the check time when the check is queued, so the flag has to be
per mediator. The finally around the queued check is not covered by a
test: OutstandingMessagesCheck already catches a count that throws, so
in practice only one of its log calls throwing would reach it.

Part of issue BrighterCommand#4554
When a check finishes, the next post that is due queues the next check,
and a post that comes while the check is in flight does not move the
time of the last check. With an interval of 1s, the test queues a
check at 2s and holds it open, posts at 4s while it is in flight, then
releases it and posts with the clock still at 4s until a second check
runs.

It passes on the current code. Each of these temporary mutations of
CheckOutstandingMessages, not committed, made it fail with "No check ran
after the first one finished":

- never releasing the in-flight flag
- recording the check time before claiming the flag: the post at 4s,
  which finds the flag taken, still moves the time to 4s, so no later
  post at 4s is due

Part of issue BrighterCommand#4554
The note that PR BrighterCommand#4564 added for issue BrighterCommand#4554 only covers the case with
no limit. Extend it with what changes when a limit is set: each
mediator keeps at most one check queued or running, and the time of
the last check is recorded when the check is queued. Retitle the entry
to match.

Also correct the semaphore the checks wait on: the note called it
process-wide, but it is a static field of the generic mediator, so it
is shared by every mediator with the same message and transaction
types.

Part of issue BrighterCommand#4554
CheckOutstandingMessages returns before queuing a check when the limit
is -1, so OutstandingMessagesCheck never runs with no limit. The comment
that said the outbox's default ceiling applies with no limit has been
out of date since PR BrighterCommand#4564 added the skip at -1.

Part of issue BrighterCommand#4554
I didn't add a release note in PR BrighterCommand#4552. With an async-only outbox and
a limit of 0 or more, PostAsync and DepositPostAsync can now throw
OutboxLimitReachedException where they never did before, so add one.
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

3 - Done Bug .NET Pull requests that update .net code V10.X

Projects

None yet

Development

Successfully merging this pull request may close these issues.

2 participants