Skip to content

Latest commit

 

History

History
75 lines (49 loc) · 19.8 KB

File metadata and controls

75 lines (49 loc) · 19.8 KB

Usage: observability (metrics and tracing)

Back to README · See also: Concepts · ADR008

When to use

You're running RingBufferPlus in production and want the pool's internal state — current capacity, acquire faults, scale-up/scale-down events, acquire latency — visible in whatever you already use to observe the rest of the system (Grafana/Prometheus, Application Insights, Jaeger, or anything else an OpenTelemetry Collector can feed). This is on by default and needs no builder call to enable — it's covered here so you know what to point an exporter at, not because there's a switch to flip.

Minimal example

RingBufferPlus emits metrics via System.Diagnostics.Metrics.Meter and traces via System.Diagnostics.ActivitySource, both named "RingBufferPlus". It takes no dependency on OpenTelemetry itself — wire up whichever OpenTelemetry .NET SDK exporter you already use, the same way you would for System.Net.Http or ASP.NET Core's own built-in instrumentation:

builder.Services.AddOpenTelemetry()
    .WithMetrics(m => m.AddMeter("RingBufferPlus") /* + whichever exporter you already use */)
    .WithTracing(t => t.AddSource("RingBufferPlus") /* + whichever exporter you already use */);

The two calls that matter here are AddMeter("RingBufferPlus") and AddSource("RingBufferPlus") — both are OpenTelemetry SDK APIs that subscribe to any System.Diagnostics.Metrics.Meter/ActivitySource by name, and RingBufferPlus already emits under that name whether or not anything is listening. No RingBufferPlus-specific package is required on your side either. The exporter call (Prometheus, OTLP, Application Insights, or anything else) is deliberately left as a comment above — which one you add, and its exact method name, depends on your OpenTelemetry SDK version and target backend, and is not something this guide can keep in sync; consult the OpenTelemetry .NET docs for whichever exporter you use.

What happens internally

Every RingBufferManager<T> owns its own Meter and ActivitySource instance — not one shared static instance for the whole process — but both are constructed with the same constant name, "RingBufferPlus", so a single exporter subscription sees every buffer in the process. Every individual buffer is disambiguated by a buffer.name tag/attribute on every metric and every span, using the same Name you passed to RingBuffer<T>.New(name).

Metrics:

Instrument Kind Tags Description
ringbufferplus.acquire.duration Histogram<double> (seconds) buffer.name, acquire.success, acquire.timed_out, acquire.cancelled, acquire.warmup_failed Duration of every AcquireAsync call — the same value already available per-call as RingBufferValue<T>.ElapsedTime, except on an acquire.warmup_failed=true row: that call never reached a RingBufferValue<T> at all (it rethrew the buffer's cached initial-warmup failure, see below), so there is no corresponding ElapsedTime to compare against. On a failed row, acquire.timed_out distinguishes a genuine AcquireTimeout expiring from an ordinary shutdown/caller-cancellation; acquire.cancelled is true only when the caller's own token ended the call (same meaning as the Acquire activity's own cancelled tag below, just prefixed here to disambiguate it from scale.duration's differently-defined cancelled); acquire.warmup_failed is true only when the buffer's initial warmup already failed and is now permanently cached (see ADR011) — every AcquireAsync call against a buffer in that state lands here, which is what makes this tag the one to alert on for "this buffer is completely broken," as opposed to acquire.timed_out/acquire.cancelled rows, which are ordinary, expected traffic even on a healthy buffer.
ringbufferplus.acquire.faults Counter<long> buffer.name Count of AcquireAsync calls that timed out with nothing available.
ringbufferplus.capacity.current ObservableGauge<int> buffer.name Current capacity, read live whenever your exporter's collection interval polls it.
ringbufferplus.scale.operations Counter<long> buffer.name, direction (up/down), trigger (manual — a SwitchToAsync pin; floor — repairing a CurrentCapacity breach below MinCapacity; backlog — reacting to waiting callers; auto — the Monitor's predictive tick), target (the capacity this operation was aiming for), success, cancelled Count of scale-up/scale-down attempts, including ones that failed, timed out, or were cancelled by an ordinary DisposeAsync() racing them — check success before reading this as "capacity actually changed N times", and cancelled before reading a success=false scale-up row as a genuine factory/broker problem (see the Logging section below for the same distinction on the log side). A scale-down's cancelled is always false and a success=false row there is never a factory/broker problem — see the Tracing paragraph below for why. The initial warmup fill is not counted here — see below.
ringbufferplus.scale.duration Histogram<double> (seconds) buffer.name, direction, trigger, target, success, cancelled Duration of scale-up/scale-down attempts, whether or not they succeeded.
ringbufferplus.heartbeat.invalidations Counter<long> buffer.name Count of HeartBeat callback verdicts that returned false — the item was invalidated and a replacement will follow. Paired with a matching Debug-level log message ("Heart Beat item invalidated - replacement will follow."); together, these are the only signals this specific verdict produces (there is no trace) — without them, a pool where every single heartbeat pulse is invalidating and replacing its item looks identical, on every other channel, to one where the callback always returns true.

Tracing: one Activity named "RingBufferPlus.Acquire" per AcquireAsync call (tagged buffer.name, success, timed_out, cancelled, warmup_failed — same meanings as the metric's tags above; cancelled is true only when the caller's own token, not a timeout, ended the call, and is present as false on every other span, not merely absent; its ActivityStatusCode is Ok unless timed_out or warmup_failed is true, in which case it's Error — an ordinary shutdown or caller cancellation is not a health signal, only a genuine AcquireTimeout expiring or a permanently-broken warmup is). This Activity/histogram pair exists only for AcquireAsync — a SwitchToAsync call that fails against the same cached warmup failure rethrows with no signal of its own on either channel (it has never had a per-call Activity/metric the way AcquireAsync does; its only observability comes from the "RingBufferPlus.Scale" span a successful dispatch produces, described next), a known, currently-accepted asymmetry. And one named "RingBufferPlus.Scale" per scale operation (tagged buffer.name, direction, trigger, target, success, cancelled, and its ActivityStatusCode set to Error only on a genuine failed/timed-out attempt — Ok if it succeeded, or if it was cancelled by an ordinary DisposeAsync() racing it). The Acquire activity correlates naturally with the rest of your request trace if AcquireAsync happens inside a traced request, but a Scale activity never does, regardless of what triggered it — DispatchScaleUp/DispatchScaleDown run on the buffer's own internal engine loop, not on any caller's async flow, so every "RingBufferPlus.Scale" span is always its own trace root, with no Parent. A scale-down that only partially reaches its target (not enough idle items available right now — see ADR001's opportunistic, non-blocking design) is always Ok/cancelled=false too, never Error: it can't genuinely fail or be cancelled the way a scale-up can, since it never calls Factory and never observes a token — check success (not the status) if you need to know whether it fully reached its target.

cancelled means something different on each of these two signals — on Acquire, it's true only when your own cancellation token ended the call (an ordinary shutdown leaves it false, distinguishable via timed_out instead); on Scale, it's true when an ordinary DisposeAsync() (the buffer's own shutdown, not a caller-supplied token) cancelled an in-flight scale-up — a scale-down's cancelled is always false, even when DisposeAsync() raced it (see the Tracing paragraph above for why). Each is documented accurately where it's tagged, but don't assume the two mean the same thing if you're aggregating across both.

Two things that are easy to miss because they follow directly from what counts as an "acquire" or a "scale operation" here, not from any special-casing:

  • Warmup emits nothing. The initial fill produces no scale.* metric, no "RingBufferPlus.Scale" activity, and no acquire.* signal either — it isn't a scale operation in the manual/auto sense those describe, and it doesn't go through AcquireAsync. capacity.current still reflects the buffer correctly the moment your collector's polling interval fires, since that gauge just reads live state, but there is no event marking "warmup finished" in either metrics or traces.
  • HeartBeat acquires count too, but don't drive autoscale. Every PulseHeartBeat tick internally acquires the item your callback inspects, so it shows up in acquire.duration/acquire.faults and produces its own "RingBufferPlus.Acquire" span, indistinguishable from a caller-initiated acquire by tag. If your dashboard cares about the difference, there is currently no tag for it — correlate by volume/interval against your configured PulseHeartBeat instead. A heartbeat acquire that times out is still counted in acquire.faults, but it is deliberately exempt from ever triggering the backlog-reactive signal's scale-up — only genuine caller demand counts toward that. Watching acquire.faults to predict an autoscale reaction can therefore be misleading on any elastic buffer with HeartBeat configured. The callback's own verdict is a separate signal from the acquire itself: a false return invalidates the item for replacement, incrementing heartbeat.invalidations and logging at Debug level (see the table above) — without both, a pool where every single pulse is invalidating and replacing its item would look, on every other channel, identical to one where the callback always returns true.
  • A Monitor tick that decides not to scale is Debug-log-only, never a metric/trace event - and only for two of its three reasons. scale.*/"RingBufferPlus.Scale" only exist for a dispatched scale operation. Enable LogLevel.Debug on the configured Logger to see "Monitor tick: demand={demand}, target={target} equals current capacity {current} - no scale." when the target already equals CurrentCapacity, or "Monitor tick: demand={demand}, target={target}, current={current} - within deadband ({deadband}), no scale." when the change is smaller than the effective MonitorDeadband. Neither fires while demand is at or above capacity (an "active" episode, demand >= CurrentCapacity — this includes genuine backlog, but also ordinary full utilization with nobody actually waiting: demand here is busy-plus-waiting, so it reaches CurrentCapacity the moment every item is checked out, whether or not anyone is queued for one) - the tick returns before any log in that case (the sample window is cleared later, on the tick where the episode ends, not during it), so the most likely reason an operator asks "why didn't it scale" (sustained full utilization, with or without an actual queue) leaves no trace at any log level; correlate acquire.faults/waiting-caller volume instead, or reproduce against AutoScaleMonitor.EvaluateTarget directly.

Trade-offs / limitations

  • Both APIs are "pay for play," but "near-zero" is not "zero" — measured on this project's own benchmark harness (benchmarks/RingBufferPlus.Benchmarks/ObservabilityOverheadBenchmarks.cs):
    • Before this feature existed: ~279ns, 568 B per AcquireAsync/release cycle (AcquireThroughputBenchmarks, measured against the commit before ADR008 — a fixed historical reference point, not re-measured since; several unrelated AcquireCoreAsync allocation fixes landed in later pre-release audit rounds, so this number is no longer directly comparable to the two below).
    • After, with nothing subscribed: low hundreds of ns (typically ~300ns), 472 B — the instrumentation call sites still run their internal "is anyone listening" checks even when the answer is no, but that cost is now smaller than the allocation this method has shed elsewhere since the historical baseline above, so it no longer shows up as a net increase against it.
    • After, with a MeterListener/ActivityListener actually attached: high hundreds of ns (typically ~600ns), 1088 B — roughly 2.3x the unobserved allocation, ~2x the unobserved time. Treat the ns figures as an order of magnitude, not a precise point value — run-to-run variance on this project's own hardware has moved the mean by tens of ns between otherwise-identical runs; the B figures are exact (allocations don't have that kind of run-to-run noise). Both are negligible next to any real factory work (network calls, database connections, RabbitMQ channels) the pool exists to manage, but the ~2x jump from unobserved to actually-observed is real, not a rounding artifact, and worth knowing if you're benchmarking RingBufferPlus itself rather than a workload built on top of it. (Last measured 2026-08-24 against the current v6 branch, after every allocation-affecting change up to that point had landed — re-measure locally with the harness above if you need a number current to your own checkout.)
  • This is always on — there is no builder method to disable it. It costs nothing to leave alone if you don't use it; there is nothing to configure either.
  • No RingBufferPlus-specific NuGet package is needed on either end: the emitting side needs none (see ADR008), and the consuming side just needs whatever OpenTelemetry SDK/exporter you'd use for any other System.Diagnostics.DiagnosticSource-based library.

Logging: a normal shutdown is not the same signal as a genuine failure

This guide otherwise covers Meter/ActivitySource only — Logger/OnError (see the heartbeat guide) are a separate signal, but this distinction is worth knowing if you alert on logged errors: an operation still in flight when DisposeAsync() runs (an ordinary, clean shutdown racing a background operation) logs informationally via Logger instead of at error level — this informational path always goes through Logger alone; OnError is only ever invoked for a genuine error-level event, and when configured it substitutes for Logger's error-level output for that event rather than adding to it, so Logger/OnError below means "whichever one you configured for errors," not "both, together." This applies to three independent operations, each with its own message and error-level exception type when the cause is a genuine failure instead:

  • A scale-up or item-replacement factory call has three outcomes, not two: "ScaleUp cancelled by shutdown..."/"Replacement cancelled by shutdown." on an ordinary shutdown; LogError(TimeoutException(...)) on a genuine per-item or overall FactoryTimeout expiring; or, for any other genuine factory failure — including a raw OperationCanceledException/TaskCanceledException the factory itself throws for its own unrelated reasons (e.g. an internal HttpClient/gRPC/DB-driver timeout) — LogError with that real exception as-is, neither swallowed as an ordinary cancellation nor fabricated into a TimeoutException.
  • The initial warmup fill: "Warmup cancelled by shutdown before reaching initial capacity." vs. LogError(InvalidOperationException("RingBuffer did not reach initial capacity")) on a genuine failure to reach capacity.
  • A HeartBeat callback still running when DisposeAsync() races it: "Heart Beat cancelled by shutdown, callback still running - deferring dispose." vs. LogError(TimeoutException("Timeout Heart Beat")) when the callback instead exceeded its own pulse budget. A third, Debug-level outcome covers a narrower race within the same shutdown-vs-failure family: "Heart Beat cancelled by shutdown after the callback had already finished." when shutdown lands just after the callback itself already returned - distinct from "still running" above, but not a failure either.

A fourth message is a different kind of case - not "shutdown vs. failure," but "shutdown completed, but a resource is not yet confirmed disposed": if DisposeAsync() had to wait for a deferred heartbeat-related item disposal (either an orphaned callback's, the third case above, or the fifth case below) and it still hasn't finished once DisposeAsync()'s own pulse-bounded grace period elapses, it logs "DisposeAsync did not wait for {N} pending heartbeat item dispose(s) still running past the grace period..." at LogWarning - a step above the informational level of the three cases above, since this one is a real, indeterminate-duration resource leak, not a shutdown-vs-failure ambiguity - and returns anyway - the resource(s) will still be disposed later if/when they actually finish, just not before this DisposeAsync() call already returned.

A fifth message covers a related but distinct case, unrelated to shutdown: the pump itself invalidated an item (a false verdict that arrived within pulse, not a timed-out callback) and that item's own Dispose()/DisposeAsync() is itself slow. It logs "Heart Beat item dispose did not complete within one pulse - deferring." at LogWarning and moves on to the next tick instead of stalling the pump on it - see the heartbeat guide for the mechanism. If that deferred dispose later faults, the failure is still delivered through Logger/OnError like any other background disposal fault - it is not silently dropped.

A sixth message is the floor guard's own (see the autoscale guide for the mechanism): LogError(InvalidOperationException("RingBuffer below minimum capacity for longer than one FactoryTimeout cycle...")) once CurrentCapacity has stayed below MinCapacity for a full FactoryTimeout cycle without recovering, repeated on that same cadence for as long as the breach persists (a fallback so an ongoing outage never goes silent) rather than firing once and stopping, or firing on every retry attempt underneath it.

If your alerting treats every logged error from this library as a factory/broker/callback health signal, a clean restart racing any of these three should no longer trip it — and if you previously saw such an error disappear after upgrading, this is why.

Common errors

  • Expecting AddMeter("RingBufferPlus")/AddSource("RingBufferPlus") to only pick up one specific buffer — they subscribe by name, not by instance; every buffer in the process with that default name shares the subscription. Use the buffer.name tag/attribute to split them apart in your dashboard/query, not a separate subscription per buffer.
  • Looking for a metric/span the moment a buffer is built — nothing is emitted until the first real AcquireAsync/scale operation happens; capacity.current is the only signal available immediately (as soon as your collector's polling interval fires), since it's a live gauge, not an event.