From 9680277171f86d3b467dd18213285cc77d286357 Mon Sep 17 00:00:00 2001 From: Ian Cooper Date: Thu, 8 Oct 2026 20:22:45 +0100 Subject: [PATCH 1/3] docs: outbox sweeper health metrics Adds an "Outbox Sweeper Metrics" section to Telemetry.md: the three sweeper instruments from ADR 0081, suggested alerts, histogram bucket configuration for second-valued histograms, and using the System.Runtime meter to tell a slow broker from a starved thread pool. Notes in BrighterOutboxSupport.md that TimerInterval must be at least 1 and links to the new section. Refs BrighterCommand/Brighter#4560 Co-Authored-By: Claude Opus 5.5 Claude-Session: https://claude.ai/code/session_01SpjnqGWbARr3Z3ofGc6C2x --- contents/BrighterOutboxSupport.md | 4 +- contents/Telemetry.md | 122 ++++++++++++++++++++++++++++++ 2 files changed, 125 insertions(+), 1 deletion(-) diff --git a/contents/BrighterOutboxSupport.md b/contents/BrighterOutboxSupport.md index 2719d0b..a79088f 100644 --- a/contents/BrighterOutboxSupport.md +++ b/contents/BrighterOutboxSupport.md @@ -181,7 +181,7 @@ The benefits of using an **Outbox Sweeper** are: | Option | Type | Default | Description | |---|---|---|---| -| `TimerInterval` | `int` | `5` | How many seconds the Sweeper waits between checks for undispatched messages. | +| `TimerInterval` | `int` | `5` | How many seconds the Sweeper waits between checks for undispatched messages. Must be at least 1; a lower value throws a `ConfigurationException` when the Sweeper is created. | | `MinimumMessageAge` | `TimeSpan` | `5000 ms` | How old a message must be before the Sweeper attempts to dispatch it. | | `BatchSize` | `int` | `100` | How many messages the Sweeper attempts to dispatch in each check. | | `UseBulk` | `bool` | `false` | Whether the Sweeper dispatches in bulk; not every messaging gateway supports it. | @@ -190,6 +190,8 @@ The benefits of using an **Outbox Sweeper** are: arguments a particular flavour of Outbox needs. It is read-only, so add to the dictionary rather than assigning a new one. +To monitor whether the sweeper is running and keeping to its schedule, see [Outbox Sweeper Metrics](/contents/Telemetry.md#outbox-sweeper-metrics). + It is important to note that the lower the Minimum Message age is the more likely it is that your message will be dispatches more than once (as if you are explicitly clearing messages your application may have instructed the clearing of a message at the same time as the **Outbox Sweeper**) ### Singleton Sweeper diff --git a/contents/Telemetry.md b/contents/Telemetry.md index 62eded7..663dc84 100644 --- a/contents/Telemetry.md +++ b/contents/Telemetry.md @@ -386,6 +386,126 @@ Set both flags and both sets of attributes will be recorded. --- +## Outbox Sweeper Metrics + +The [Outbox Sweeper](/contents/BrighterOutboxSupport.md#implicit-clear) runs in the background, so when it stalls nothing fails visibly. Messages simply stay in the Outbox. To make a stall visible, the sweeper records three metrics about its own health on the `Paramore.Brighter` meter. They tell you whether sweeps are running, whether they start on time, and how long they take. + +### Enabling the Metrics + +`AddBrighterInstrumentation()` on the `MeterProviderBuilder` registers the sweeper's meter, alongside Brighter's messaging and database meters, and listens to the `Paramore.Brighter` meter. It comes from the `Paramore.Brighter.Extensions.Diagnostics` package: + +```csharp +using OpenTelemetry.Metrics; +using Paramore.Brighter.Extensions.Diagnostics; + +builder.Services.AddOpenTelemetry() + .WithMetrics(metrics => metrics + .AddBrighterInstrumentation() + .AddOtlpExporter()); +``` + +If you do not call `AddBrighterInstrumentation()`, the sweeper uses a no-op meter and records nothing. + +### Instruments + +| Instrument | Type | Unit | Description | +|------------|------|------|-------------| +| `paramore.brighter.outbox_sweeper.tick.lag` | Histogram | `s` | How long after its due time a sweep started | +| `paramore.brighter.outbox_sweeper.sweep.duration` | Histogram | `s` | How long a sweep took | +| `paramore.brighter.outbox_sweeper.sweeps` | Counter | `{sweep}` | Number of sweeps, by how each ended | + +`sweep.duration` and `sweeps` carry a `paramore.brighter.outbox_sweeper.outcome` attribute: + +| Outcome | Meaning | +|---------|---------| +| `completed` | The sweep ran to the end | +| `failed` | The sweep threw an exception. The sweeper logs it and sweeps again on the next tick | +| `lock_unavailable` | The sweep did not run, because another sweeper holds the [distributed lock](/contents/DistributedLock.md) | + +These metrics describe the sweeper, not the messages it sends. They do not count how many messages a sweep found or dispatched. + +### How the Sweeper Keeps Time + +The sweeper runs on its own dedicated thread, not on a thread-pool timer. So a busy or starved thread pool cannot stop sweeps from starting. Each sweep is due one `TimerInterval` after the previous one was due: + +- If a sweep overruns its interval, the next sweep starts late, and `tick.lag` shows by how much. +- If a sweep starts a whole interval or more late, the schedule restarts from that sweep. The sweeper never runs sweeps back to back to catch up. + +Only the schedule is free of the thread pool. Once a sweep does real asynchronous I/O, such as sending to Kafka or reading a database Outbox, its continuations still run on the pool. A starved pool therefore shows up first as a longer `sweep.duration`, and then as `tick.lag` on the sweeps that follow. + +### Suggested Alerts + +The examples below use PromQL, with the names a Prometheus exporter produces: dots become underscores, and the unit and `_total` are added as suffixes. Adjust them for your backend. + +**The sweeper has stalled.** No sweep has completed for several intervals. With a 5-second `TimerInterval`, this alerts after about 30 seconds: + +```promql +sum(increase(paramore_brighter_outbox_sweeper_sweeps_total{paramore_brighter_outbox_sweeper_outcome="completed"}[30s])) == 0 +``` + +Sum across instances. When several instances share a distributed lock, only one of them completes sweeps, and the rest record `lock_unavailable`. An alert on each instance would fire for every instance that is not holding the lock. A stalled sweeper may also stop reporting altogether, so pair the alert with `absent()` on the same series if your backend drops series that go stale. + +**Sweeps start late.** The p99 tick lag is above the sweep interval: + +```promql +histogram_quantile(0.99, sum by (le) (rate(paramore_brighter_outbox_sweeper_tick_lag_seconds_bucket[5m]))) > 5 +``` + +**Sweeps are failing.** + +```promql +sum(increase(paramore_brighter_outbox_sweeper_sweeps_total{paramore_brighter_outbox_sweeper_outcome="failed"}[5m])) > 0 +``` + +To find the reason for a failure, check the sweeper's error log. + +### Histogram Buckets + +The OpenTelemetry .NET SDK's default histogram buckets were designed for millisecond values: 0, 5, 10, 25, 50 and so on. Both sweeper histograms record seconds, and most values fall below 5, so with the default buckets nearly every value lands in the first one or two. Add a view that sets buckets that fit your `TimerInterval`: + +```csharp +using OpenTelemetry.Metrics; +using Paramore.Brighter.Extensions.Diagnostics; + +var sweeperBuckets = new ExplicitBucketHistogramConfiguration +{ + Boundaries = [0, 0.01, 0.05, 0.1, 0.25, 0.5, 1, 2.5, 5, 10, 30, 60] +}; + +builder.Services.AddOpenTelemetry() + .WithMetrics(metrics => metrics + .AddBrighterInstrumentation() + .AddView("paramore.brighter.outbox_sweeper.tick.lag", sweeperBuckets) + .AddView("paramore.brighter.outbox_sweeper.sweep.duration", sweeperBuckets) + .AddOtlpExporter()); +``` + +### Telling a Slow Broker From a Starved Process + +| `sweep.duration` | `tick.lag` | Likely cause | +|------------------|------------|--------------| +| Low | Low | Healthy | +| High | Low | The broker or Outbox store is slow, but each sweep still finishes within its interval | +| High | High | Sweeps overrun their interval. Check whether the broker or Outbox is slow, or the thread pool is starved (see below) | +| Low | High | The process is not getting CPU, for example because of container CPU throttling | + +To see whether the thread pool is starved, enable the .NET runtime's built-in `System.Runtime` meter (.NET 9 and later) and look at the thread pool's queue length and thread count: + +```csharp +using OpenTelemetry.Metrics; +using Paramore.Brighter.Extensions.Diagnostics; + +builder.Services.AddOpenTelemetry() + .WithMetrics(metrics => metrics + .AddBrighterInstrumentation() + .AddMeter("System.Runtime") + .AddOtlpExporter()); +``` + +A `dotnet.thread_pool.queue.length` that keeps growing, together with a `dotnet.thread_pool.thread.count` that climbs only slowly, means work is queuing faster than the pool can add threads. On Kubernetes, compare this with CPU throttling (`container_cpu_cfs_throttled_periods_total`). Brighter does not re-export these runtime metrics. See [.NET runtime metrics](https://learn.microsoft.com/dotnet/core/diagnostics/built-in-metrics-runtime). + +--- + ## Telemetry Best Practices 1. **Start with Minimal Instrumentation**: Enable `RequestInformation` and `Messaging`, and leave out expensive flags like `RequestBody` @@ -502,3 +622,5 @@ V9 used custom attribute names. V10 uses OTel standard conventions: - [OpenTelemetry .NET Documentation](https://opentelemetry.io/docs/instrumentation/net/) - [Brighter CloudEvents Support](CloudEventsSupport.md) - [Brighter Request Context](UsingTheContextBag.md) +- [Outbox Support](/contents/BrighterOutboxSupport.md) - The Outbox Sweeper, whose health metrics are described above +- [.NET Runtime Metrics](https://learn.microsoft.com/dotnet/core/diagnostics/built-in-metrics-runtime) From 2bc6bd8683a7a947e569e90216072471d8d3e8eb Mon Sep 17 00:00:00 2001 From: Ian Cooper Date: Fri, 9 Oct 2026 09:18:33 +0100 Subject: [PATCH 2/3] docs: sweep stays off the pool across sends; confirmation queue depth Follows the review changes in BrighterCommand/Brighter#4562: a Kafka sweep now resumes on the sweeper thread, the schedule uses elapsed time, and a new paramore.brighter.publish_confirmation.queue.depth instrument reports confirmation backlogs. Co-Authored-By: Claude Opus 5.5 Claude-Session: https://claude.ai/code/session_01SpjnqGWbARr3Z3ofGc6C2x --- contents/Telemetry.md | 18 +++++++++++++++++- 1 file changed, 17 insertions(+), 1 deletion(-) diff --git a/contents/Telemetry.md b/contents/Telemetry.md index 663dc84..14c0d0d 100644 --- a/contents/Telemetry.md +++ b/contents/Telemetry.md @@ -431,7 +431,23 @@ The sweeper runs on its own dedicated thread, not on a thread-pool timer. So a b - If a sweep overruns its interval, the next sweep starts late, and `tick.lag` shows by how much. - If a sweep starts a whole interval or more late, the schedule restarts from that sweep. The sweeper never runs sweeps back to back to catch up. -Only the schedule is free of the thread pool. Once a sweep does real asynchronous I/O, such as sending to Kafka or reading a database Outbox, its continuations still run on the pool. A starved pool therefore shows up first as a longer `sweep.duration`, and then as `tick.lag` on the sweeps that follow. +The sweep itself also stays on that thread: when a send completes, as Kafka's does, on the broker client's own thread, the sweep resumes on the sweeper's thread rather than waiting for a pool thread. A producer or Outbox that awaits with `ConfigureAwait(false)` internally, as database clients and the AWS SDK do, still resumes on the pool. With those, a starved pool shows up first as a longer `sweep.duration`, and then as `tick.lag` on the sweeps that follow. + +The schedule is measured in elapsed time, not by the wall clock, so a clock that steps backwards does not delay a sweep. + +### Publish Confirmation Queue Depth + +Kafka and RabbitMQ (`RMQ.Sync`) producers raise publish confirmations on a dedicated thread per producer, in batches of up to 32. Brighter's own handler for a confirmation marks the message dispatched in the Outbox. If confirmations arrive faster than those handlers finish, they queue. Messages then stay unmarked past `MinimumMessageAge`, and the sweeper sends them again. + +| Instrument | Type | Unit | Attributes | +|------------|------|------|------------| +| `paramore.brighter.publish_confirmation.queue.depth` | UpDownCounter (observable) | `{confirmation}` | `messaging.system`, `messaging.destination.name` | + +It counts the confirmations waiting or running for each producer. `AddBrighterInstrumentation()` registers it. A depth that keeps growing means the Outbox cannot keep up with the broker's confirmations: + +```promql +min_over_time(sum by (messaging_destination_name) (paramore_brighter_publish_confirmation_queue_depth)[5m:]) > 100 +``` ### Suggested Alerts From 6468dd98e394297bfb8031b4360bac7429911948 Mon Sep 17 00:00:00 2001 From: Ian Cooper Date: Fri, 9 Oct 2026 17:03:07 +0100 Subject: [PATCH 3/3] docs: a hung outbox sweep records nothing; alert on missing completed sweeps Co-Authored-By: Claude Opus 5.5 Claude-Session: https://claude.ai/code/session_01SpjnqGWbARr3Z3ofGc6C2x --- contents/Telemetry.md | 6 +++++- 1 file changed, 5 insertions(+), 1 deletion(-) diff --git a/contents/Telemetry.md b/contents/Telemetry.md index 14c0d0d..8db2932 100644 --- a/contents/Telemetry.md +++ b/contents/Telemetry.md @@ -435,6 +435,10 @@ The sweep itself also stays on that thread: when a send completes, as Kafka's do The schedule is measured in elapsed time, not by the wall clock, so a clock that steps backwards does not delay a sweep. +Because sweeps run one after another on that one thread, **a hung sweep records nothing**. No later sweep starts while it is stuck, so there is no `tick.lag`, `sweep.duration` or `sweeps` until it ends. `lock_unavailable` shows up only on *other* instances that share the distributed lock, and with a single instance or the in-memory lock, not even that. So don't use `lock_unavailable` or `tick.lag` to detect a stall. Alert on sweeps that should have completed and didn't, as in [Suggested Alerts](#suggested-alerts). + +The same thread also means that code in the sweep's path that blocks on a task, such as a custom distributed lock, producer or Outbox that calls `.GetAwaiter().GetResult()` on an async method, can deadlock the sweeper. Brighter's own implementations don't do this. + ### Publish Confirmation Queue Depth Kafka and RabbitMQ (`RMQ.Sync`) producers raise publish confirmations on a dedicated thread per producer, in batches of up to 32. Brighter's own handler for a confirmation marks the message dispatched in the Outbox. If confirmations arrive faster than those handlers finish, they queue. Messages then stay unmarked past `MinimumMessageAge`, and the sweeper sends them again. @@ -459,7 +463,7 @@ The examples below use PromQL, with the names a Prometheus exporter produces: do sum(increase(paramore_brighter_outbox_sweeper_sweeps_total{paramore_brighter_outbox_sweeper_outcome="completed"}[30s])) == 0 ``` -Sum across instances. When several instances share a distributed lock, only one of them completes sweeps, and the rest record `lock_unavailable`. An alert on each instance would fire for every instance that is not holding the lock. A stalled sweeper may also stop reporting altogether, so pair the alert with `absent()` on the same series if your backend drops series that go stale. +Sum across instances, and count only `completed`. When several instances share a distributed lock, only one of them completes sweeps, and the rest record `lock_unavailable`. An alert on each instance would fire for every instance that is not holding the lock. An alert on sweeps of any outcome would never fire while the lock holder is hung, because the other instances keep recording `lock_unavailable`. A stalled sweeper may also stop reporting altogether, so pair the alert with `absent()` on the same series if your backend drops series that go stale. **Sweeps start late.** The p99 tick lag is above the sweep interval: