macrame/metrics.rs
1//! What the write actor knows about its own latency (T1.4, D-079).
2//!
3//! # Why this exists
4//!
5//! [`crate::CHUNK_BUDGET`] is 3 ms and the crate has, until now, had exactly one
6//! way to find out whether that bound holds: run `benches/budgets.rs` on a
7//! synthetic fixture. That is a statement about a laptop, not about a database
8//! in use. D-059 already established that the bound does **not** hold on a large
9//! file, by a factor of 15, and it took a benchmark rewrite to notice — because
10//! nothing in the running system was counting.
11//!
12//! Tier 1's other three items are all "make the tail bounded". None of them can
13//! be validated in the field without something that measures the tail, which is
14//! why this is a precondition for them rather than a nice-to-have.
15//!
16//! # What is recorded, and what is deliberately not
17//!
18//! Four things, all of them per **actor turn** — one command, start to finish:
19//!
20//! - **queue depth** on both channels, sampled *before* the turn begins;
21//! - **hold duration**, bucketed, per command kind;
22//! - **holds over budget**, counted separately per kind;
23//! - **the longest hold since open**, with the kind that caused it.
24//!
25//! The hold is the whole turn, not the `execute` call's SQL. That is the
26//! quantity the budget is about: the SQLite write lock is not preemptible, so an
27//! interactive assertion arriving mid-turn waits for the turn, whatever the turn
28//! spent its time on.
29//!
30//! There is no per-command timestamp trail and no sampling of individual slow
31//! commands. That would be a tracing problem, and `tracing` is already a
32//! dependency — spans belong there. This module answers one question ("is the
33//! bound holding, and if not, which kind breaks it") in fixed memory, with no
34//! allocation on the actor's path.
35//!
36//! # The feature gate
37//!
38//! Behind `metrics`, which has been a **default** feature since 0.12.11
39//! (D-154): a crate whose contract is a latency bound must not ship a default
40//! build that cannot report whether the bound is met. `--no-default-features`
41//! still removes it. With the feature off, [`ActorMetrics`] is a
42//! zero-sized type whose methods compile away and [`HoldTimer::start`] does not
43//! read the clock — so the actor loop has **one** shape either way. That
44//! matters more than the nanoseconds: a `#[cfg]` in the loop body is how the
45//! instrumented and uninstrumented paths drift until only one of them is the one
46//! that runs.
47
48use std::time::Duration;
49
50/// The command kinds the actor can spend a turn on.
51///
52/// One flat enum across both channels rather than one per channel. The question
53/// this exists to answer is "which command broke the budget", and a reader
54/// looking at a 400 ms hold does not first want to know which queue it came off.
55/// Priority is a property of scheduling; kind is a property of cost.
56///
57/// # `#[non_exhaustive]`, added while it was still free (0.12.8, W4.2)
58///
59/// Adding a variant here is a **breaking change** without this attribute,
60/// because a downstream `match` on `CommandKind` would stop compiling. That is
61/// not hypothetical for this enum: [`crate::metrics::CommandKind::Rehydrate`]
62/// did not exist until 0.12.9 precisely because adding it was a break, and
63/// rehydration reported as `Archive` for several releases as a result. The
64/// codebase has already paid this cost once, which is the argument for paying
65/// the attribute now rather than deciding it at 1.0 when the cost is permanent.
66///
67/// Callers must therefore include a `_ =>` arm. In exchange, this enum can grow
68/// a variant for a command kind that does not exist yet without a major version.
69#[derive(Debug, Clone, Copy, PartialEq, Eq, PartialOrd, Ord, Hash)]
70#[repr(u8)]
71#[non_exhaustive]
72pub enum CommandKind {
73 AssertEdge,
74 RetireEdge,
75 UpsertConcept,
76 WriteBulkAtomic,
77 RebuildCurrent,
78 RegisterModel,
79 Shutdown,
80 BulkImportChunk,
81 WriteConceptsChunk,
82 WriteAnalyticsChunk,
83 UpsertEmbeddingChunk,
84 Archive,
85 RebuildFts,
86 /// One step of a chunked shadow rebuild (T1.2). Its own kind rather than
87 /// folded into `RebuildCurrent`, because the two have opposite latency
88 /// profiles and the whole point of the chunked path is that its turns are
89 /// short — averaging them together would hide exactly the improvement.
90 ShadowRebuild,
91 /// Refreshing the query planner's statistics (0.12.4, D-149).
92 ///
93 /// Its own kind rather than folded into `RebuildFts`, though both are
94 /// maintenance on derived state: this one is bounded by
95 /// `PRAGMA analysis_limit` and that one is bounded by the size of the
96 /// concept table, so averaging their holds together would describe neither.
97 Analyze,
98 /// Moving archived rows back into the hot file (0.12.9, W4.3, D-152).
99 ///
100 /// Its own kind at last. Through 0.12.8 this reported as
101 /// [`CommandKind::Archive`], on the stated ground that rehydration is the
102 /// archive path run backwards and shares its budget — true of the *budget*
103 /// and false of the *attribution*, which is what a metrics surface is for.
104 /// An operator reading a long `archive` hold could not tell whether the
105 /// database had archived anything at all, and the two move rows in opposite
106 /// directions.
107 ///
108 /// The real reason it stayed folded was that adding a variant was a
109 /// breaking change. `#[non_exhaustive]` (W4.2) is what removed that
110 /// obstacle, and this variant is the first thing it bought — which is also
111 /// the evidence that the attribute was worth adding rather than a
112 /// precaution against a hypothetical.
113 ///
114 /// **Appended at the end**, per [`CommandKind::index`]: the position of
115 /// every existing variant is a persisted contract in two languages.
116 Rehydrate,
117 /// An explicit `PRAGMA wal_checkpoint` (0.12.13, W5.2, D-156).
118 ///
119 /// Its own kind because it is the one actor turn that is **not** a
120 /// transaction: it moves frames from the WAL back into the main database
121 /// file, and its duration is a function of how much WAL has accumulated
122 /// rather than of anything the caller passed. Folding it into any existing
123 /// kind would make that kind's hold distribution bimodal for a reason no
124 /// dashboard could recover.
125 ///
126 /// **Appended at the end**, per [`CommandKind::index`].
127 Checkpoint,
128 /// `PRAGMA optimize` — re-analysing only what SQLite believes has drifted
129 /// (0.13.24, W10.5, D-197).
130 ///
131 /// Split out of [`CommandKind::Analyze`], which covered both from 0.12.4 to
132 /// 0.13.23. The split is [`CommandKind::Rehydrate`]'s lesson applied before
133 /// the fact rather than after it: [D-168] refused to decide `Analyze`'s
134 /// budget exemption *because* the kind was shared, since a judgement made
135 /// about the explicit call would have landed on the automatic one —
136 /// `close()` runs `optimize()` unconditionally — without ever being made
137 /// about it.
138 ///
139 /// The two also have genuinely different hold distributions, which is the
140 /// same argument [`CommandKind::ShadowRebuild`] is separate on.
141 /// [`crate::Database::analyze`] does the work unconditionally and its hold
142 /// tracks the table. This one is a no-op when nothing has moved, so its
143 /// distribution is bimodal by design and averaging the two together
144 /// describes neither.
145 ///
146 /// **Appended at the end**, per [`CommandKind::index`].
147 ///
148 /// [D-168]: ../docs/architecture/s13-decision-register.md#d-168
149 Optimize,
150}
151
152impl CommandKind {
153 /// Every kind, in declaration order. Indexing into the per-kind arrays is by
154 /// position in this slice, so the two must not drift — which is why the
155 /// arrays are sized from `ALL.len()` rather than from a hand-written count.
156 pub const ALL: &'static [CommandKind] = &[
157 CommandKind::AssertEdge,
158 CommandKind::RetireEdge,
159 CommandKind::UpsertConcept,
160 CommandKind::WriteBulkAtomic,
161 CommandKind::RebuildCurrent,
162 CommandKind::RegisterModel,
163 CommandKind::Shutdown,
164 CommandKind::BulkImportChunk,
165 CommandKind::WriteConceptsChunk,
166 CommandKind::WriteAnalyticsChunk,
167 CommandKind::UpsertEmbeddingChunk,
168 CommandKind::Archive,
169 CommandKind::RebuildFts,
170 CommandKind::ShadowRebuild,
171 CommandKind::Analyze,
172 CommandKind::Rehydrate,
173 CommandKind::Checkpoint,
174 CommandKind::Optimize,
175 ];
176
177 pub const COUNT: usize = CommandKind::ALL.len();
178
179 /// This kind's slot in the per-kind arrays.
180 ///
181 /// # Declaration order is a persisted contract (0.12.8, W4.2)
182 ///
183 /// `self as usize` means the **order of the variants above** is the order of
184 /// every per-kind array in this module, and the compiler cannot catch a
185 /// change to it. Reordering the enum silently reassigns every counter to a
186 /// different command: the code compiles, the tests pass, and a histogram
187 /// read after the change attributes `archive`'s holds to `rebuild_fts`.
188 ///
189 /// **New variants go at the end**, always — including at the end of
190 /// [`CommandKind::ALL`], whose order is what `as_str()` and the Python
191 /// surface enumerate. This binds Python too: `BUCKET_BOUNDS_MICROS` is a
192 /// module constant there and `KindMetrics` is built by position, so a
193 /// reorder here relabels axes in a language the Rust compiler is not
194 /// looking at.
195 ///
196 /// `#[repr(u8)]` is on the enum for the same reason — it pins the
197 /// discriminants to the declaration order rather than leaving them to the
198 /// compiler — but it pins them to whatever the order *is*, so it does not
199 /// make a reorder safe. Only this rule does.
200 pub const fn index(self) -> usize {
201 self as usize
202 }
203
204 pub const fn as_str(self) -> &'static str {
205 match self {
206 CommandKind::AssertEdge => "assert_edge",
207 CommandKind::RetireEdge => "retire_edge",
208 CommandKind::UpsertConcept => "upsert_concept",
209 CommandKind::WriteBulkAtomic => "write_bulk_atomic",
210 CommandKind::RebuildCurrent => "rebuild_current",
211 CommandKind::RegisterModel => "register_model",
212 CommandKind::Shutdown => "shutdown",
213 CommandKind::BulkImportChunk => "bulk_import_chunk",
214 CommandKind::WriteConceptsChunk => "write_concepts_chunk",
215 CommandKind::WriteAnalyticsChunk => "write_analytics_chunk",
216 CommandKind::UpsertEmbeddingChunk => "upsert_embedding_chunk",
217 CommandKind::Archive => "archive",
218 CommandKind::RebuildFts => "rebuild_fts",
219 CommandKind::ShadowRebuild => "shadow_rebuild",
220 CommandKind::Analyze => "analyze",
221 CommandKind::Rehydrate => "rehydrate",
222 CommandKind::Checkpoint => "checkpoint",
223 CommandKind::Optimize => "optimize",
224 }
225 }
226
227 /// Whether this kind is exempt from [`crate::CHUNK_BUDGET`] by contract.
228 ///
229 /// The exemptions are the table in `CHUNK_BUDGET`'s own rustdoc, and they
230 /// are carried here so a dashboard can separate "the budget is being
231 /// broken" from "the budget does not apply and never claimed to". Counting
232 /// an `archive` as a budget violation would make the violation count useless
233 /// on any database that archives.
234 ///
235 /// The two lists must agree, and since 0.12.9 they are tied together in
236 /// both directions by `the_budget_exemptions_and_their_documented_table_agree`
237 /// — the extra-row direction being the one worth having, since a table row
238 /// with no code behind it promises a caller an exemption the violation
239 /// counter is about to disagree with.
240 ///
241 /// [`CommandKind::ShadowRebuild`] is deliberately **not** exempt. Its fill
242 /// chunks are meant to fit the budget and its swap turn is not going to —
243 /// the swap rebuilds three indexes under the lock, which is the residual
244 /// cost T1.2 could not remove. Both facts are worth seeing, and exempting
245 /// the kind would hide the first to excuse the second.
246 ///
247 /// # `Rehydrate` is exempt, and splitting it out is what made that a
248 /// decision rather than an accident (0.12.9, W4.3, D-152)
249 ///
250 /// Until 0.12.8 rehydration reported as [`CommandKind::Archive`] and was
251 /// therefore exempt **by inheritance** — nobody had decided it, it fell out
252 /// of the borrowed kind. Giving it its own variant would have silently
253 /// flipped it to non-exempt, and since a rehydrate is one unchunked
254 /// transaction moving rows back across the file boundary, every single one
255 /// would have counted as a budget violation. The violation count would then
256 /// have become useless on any database that rehydrates, which is precisely
257 /// the failure the `Archive` exemption exists to prevent, arriving by the
258 /// back door of a change made for attribution.
259 ///
260 /// So it is exempt, on the merits and now on the record: rehydration is the
261 /// archive path run backwards and makes the same claim about its hold —
262 /// that it is bulk movement with no latency bound, and that the caller asked
263 /// for it explicitly.
264 ///
265 /// # Neither [`CommandKind::Analyze`] nor [`CommandKind::Optimize`] is
266 /// exempt, and since 0.13.24 those are two decisions (W10.5, D-197)
267 ///
268 /// They were one kind from 0.12.4 to 0.13.23, and [D-168] declined to decide
269 /// the exemption *because* they were: `Analyze` covered
270 /// [`crate::Database::optimize`] too, `close()` calls that unconditionally,
271 /// and so a judgement made about the explicit call would have landed on the
272 /// automatic one without ever being made about it. That is
273 /// [`CommandKind::Rehydrate`]'s lesson above arriving from the other
274 /// direction — there a shared kind *granted* an exemption nobody had
275 /// decided; here one would have *laundered* one. W10.5 split the kind so
276 /// each could be answered on its own evidence. Both answers came back the
277 /// same and the reasons are different, which is the whole reason the split
278 /// had to come first.
279 ///
280 /// **[`CommandKind::Analyze`] cannot state a `Bound`, so it cannot have a
281 /// row.** `ANALYZE` is one indivisible statement whose cost is set by data
282 /// volume — measured at **5.26 ms at 10,000 edges and 19.1 ms at 40,000**
283 /// against a 3 ms budget (`examples/analyze_hold.rs`, [D-166]). Every call
284 /// is a violation and always will be. `Checkpoint`'s bound is frames
285 /// accumulated since the last one; `Archive`'s is the session's row count.
286 /// The honest entry here would be "the size of the table, damped 3–4× by
287 /// `analysis_limit`", which is not a bound but the absence of one, and a
288 /// row that cannot fill that column is this table admitting the thing it
289 /// exists to prevent.
290 ///
291 /// **[`CommandKind::Optimize`] is not exempt for the opposite reason: its
292 /// violations are rare and they are the informative ones.** Measured
293 /// (`examples/optimize_hold.rs`, 40,000 edges): **10.7 ms the first time on
294 /// a database that has never been analysed, and 90–220 µs every time
295 /// after** — comfortably inside the budget, including immediately after a
296 /// bulk load that doubled the ledger. It is over budget only when it
297 /// actually re-analyses something, and then it is over by a lot: **460 ms**
298 /// once the table had grown 25× and SQLite's staleness ratio finally
299 /// fired. So the count is bimodal by construction and it is *reporting*
300 /// rather than complaining: an `optimize` in `budget_violations()` marks
301 /// the calls that did work, which is exactly what an operator wants to
302 /// know and exactly what exempting the kind would delete.
303 ///
304 /// **The violations are expected and must not be "fixed" by lowering
305 /// [`crate::schema::ddl::ANALYSIS_LIMIT`].** That would buy the number by
306 /// sampling too little to separate the two `source_id`-leading indices,
307 /// which is the entire purpose of having statistics ([D-149]).
308 ///
309 /// [D-149]: ../docs/architecture/s13-decision-register.md#d-149
310 /// [D-166]: ../docs/architecture/s13-decision-register.md#d-166
311 /// [D-168]: ../docs/architecture/s13-decision-register.md#d-168
312 pub const fn exempt_from_budget(self) -> bool {
313 matches!(
314 self,
315 CommandKind::WriteBulkAtomic
316 | CommandKind::Archive
317 | CommandKind::RebuildCurrent
318 | CommandKind::Rehydrate
319 | CommandKind::Checkpoint
320 )
321 }
322}
323
324impl std::fmt::Display for CommandKind {
325 fn fmt(&self, f: &mut std::fmt::Formatter<'_>) -> std::fmt::Result {
326 f.write_str(self.as_str())
327 }
328}
329
330/// Upper bounds of the hold-duration histogram, in microseconds.
331///
332/// `3_000` is [`crate::CHUNK_BUDGET`] exactly, so the bucket boundary and the
333/// bound are the same number and a reader does not have to interpolate to answer
334/// "what fraction of turns fit". The tail runs to 1 s because D-059's measured
335/// worst case was 45 ms and `rebuild_current` at 40K rows is 318 ms (D-077) —
336/// a range this has to cover without saturating.
337///
338/// Anything above the last bound lands in the overflow bucket, which is why
339/// [`KindSnapshot::buckets`] is one longer than this slice.
340pub const BUCKET_BOUNDS_MICROS: &[u64] = &[
341 100, 300, 1_000, 3_000, 10_000, 30_000, 100_000, 300_000, 1_000_000,
342];
343
344/// Number of histogram buckets, including the overflow bucket.
345pub const BUCKET_COUNT: usize = BUCKET_BOUNDS_MICROS.len() + 1;
346
347#[allow(dead_code)] // used by `imp` under `metrics`, and by the tests always
348fn bucket_of(micros: u64) -> usize {
349 // Linear scan over nine bounds. A binary search here would be slower in
350 // practice and this runs once per actor turn, against a turn measured in
351 // microseconds at best.
352 BUCKET_BOUNDS_MICROS
353 .iter()
354 .position(|&bound| micros <= bound)
355 .unwrap_or(BUCKET_BOUNDS_MICROS.len())
356}
357
358/// Times one actor turn.
359///
360/// # This clock is no longer optional (0.12.0, W1)
361///
362/// Until 0.11.0 the field was `#[cfg(feature = "metrics")]` and `elapsed()`
363/// returned `Duration::ZERO` in a default build: the reading existed only to
364/// feed [`ActorMetrics::record_hold`]'s histogram, so a build that did not keep
365/// the histogram had no reason to read a clock.
366///
367/// The chunk loop changed what the reading is *for*. A chunk's measured hold is
368/// now the input to the next chunk's size (`connection::next_chunk_size`, named
369/// in prose because it is private — D-144), which means it is a control signal
370/// in every build and not an observation in some of them. Left gated, `bulk_import` would have sized its chunks off
371/// `Duration::ZERO` — a value that reads as "comfortably under budget" — and
372/// grown every chunk to the ceiling, in exactly the builds nobody was measuring.
373///
374/// So the clock is unconditional and **only the histogram is still gated**:
375/// `record_hold` remains a no-op without the feature. What that costs is one
376/// `Instant::now()` pair per actor turn — tens of nanoseconds against a turn
377/// measured in microseconds at best, and the same reasoning §5.1.5 uses to
378/// decide that a channel hop is free beside a chunk.
379///
380/// It stays a type rather than a bare `Instant::now()` in the loop because the
381/// ordering guarantee in [`crate::connection`]'s `Turn` is attached to it.
382pub struct HoldTimer {
383 start: std::time::Instant,
384}
385
386impl HoldTimer {
387 #[inline]
388 pub fn start() -> Self {
389 Self {
390 start: std::time::Instant::now(),
391 }
392 }
393
394 #[inline]
395 pub fn elapsed(&self) -> Duration {
396 self.start.elapsed()
397 }
398}
399
400// ---------------------------------------------------------------------------
401// Instrumented implementation
402// ---------------------------------------------------------------------------
403
404#[cfg(feature = "metrics")]
405mod imp {
406 use super::{bucket_of, CommandKind, BUCKET_COUNT};
407 use std::sync::atomic::{AtomicU64, Ordering};
408 use std::time::Duration;
409
410 /// One kind's counters. All `Relaxed`: these are statistics, and ordering
411 /// them against each other would buy a consistency no reader needs and cost
412 /// fences on the write path.
413 #[derive(Debug, Default)]
414 struct Kind {
415 turns: AtomicU64,
416 total_micros: AtomicU64,
417 over_budget: AtomicU64,
418 /// This kind's own high-water mark, in µs.
419 ///
420 /// Not redundant with the global `longest`. That one names a single
421 /// command, so on any real database it names whichever kind is slowest
422 /// overall — and the question "did windowing shrink the archive's worst
423 /// hold" cannot be answered by a counter that a bulk import wins. No
424 /// packing needed here: the kind is the array index.
425 longest_micros: AtomicU64,
426 buckets: [AtomicU64; BUCKET_COUNT],
427 }
428
429 /// Live counters, shared between the actor and the handle.
430 ///
431 /// Fixed size, no allocation, no lock. The actor updates; anyone may read.
432 #[derive(Debug, Default)]
433 pub struct ActorMetrics {
434 kinds: [Kind; CommandKind::COUNT],
435 /// Packed `micros << 8 | kind`, so the longest hold and the kind that
436 /// caused it are read and written as **one** value. Two atomics would
437 /// let a reader see a duration from one turn beside a kind from
438 /// another — a rare wrong answer to exactly the question this field
439 /// exists to answer. 2^56 µs is over two thousand years.
440 ///
441 /// **The duration must occupy the high bits.** The update is a
442 /// `fetch_max` on the packed word, so whichever field is packed high is
443 /// the one being compared. The first version of this had the kind up
444 /// there, which made the "longest hold" the hold with the largest
445 /// *enum index* — a 3 ms `write_concepts_chunk` beat a 10 ms
446 /// `rebuild_current` because its variant is declared later. It was
447 /// `actor_metrics_tests` that caught it, not the unit tests, because
448 /// nothing in the arithmetic is wrong: the packing is only incorrect in
449 /// the presence of the atomic operation it exists to serve.
450 longest: AtomicU64,
451 /// Loop iterations, which is **not** the number of turns taken.
452 ///
453 /// The depth sample happens at the top of the loop, before `select!`
454 /// blocks — so an idle actor has already counted the iteration for a
455 /// command that has not arrived. That is right for depth (the sample is
456 /// "what was queued when I went looking") and wrong for turns, which is
457 /// why [`MetricsSnapshot::turns`] is the sum of the per-kind counters
458 /// instead. Conflating the two made `turns` permanently one too high and
459 /// disagree with its own breakdown.
460 depth_samples: AtomicU64,
461 high_depth_sum: AtomicU64,
462 high_depth_max: AtomicU64,
463 low_depth_sum: AtomicU64,
464 low_depth_max: AtomicU64,
465 /// Turns where the actor took high-priority work while low-priority
466 /// work was already queued (0.12.10, W4.4, D-153).
467 ///
468 /// The `biased` `select!` in `run_writer_actor` has **no floor**:
469 /// sustained high-priority traffic can hold the low tier off
470 /// indefinitely, and nothing has ever said whether that happens. This
471 /// is the numerator of that question — how often the choice went
472 /// against the low tier at all.
473 low_starved_turns: AtomicU64,
474 /// The current unbroken run of such turns. Reset to zero the moment
475 /// low-priority work is taken.
476 ///
477 /// Not exposed; it is the state [`Self::low_starved_run_max`] is a
478 /// high-water mark of. A live value would be read at an arbitrary point
479 /// in a run and mean nothing.
480 low_starved_run: AtomicU64,
481 /// The longest such run since open, which is the number that answers the
482 /// question.
483 ///
484 /// A large `low_starved_turns` on a busy database is unremarkable — it
485 /// says the high tier is being used, which is what the tier is for. A
486 /// large *run* says one specific low-priority command waited that many
487 /// turns, and it is the only one of the two that can distinguish
488 /// "prioritised" from "starved".
489 low_starved_run_max: AtomicU64,
490 }
491
492 const MICROS_SHIFT: u32 = 8;
493 const KIND_MASK: u64 = (1 << MICROS_SHIFT) - 1;
494
495 impl ActorMetrics {
496 pub fn new() -> Self {
497 Self::default()
498 }
499
500 /// Sample both queue depths. Called before the turn, not after: after
501 /// the turn the queue reflects what arrived *during* it, which is a
502 /// different and much less useful quantity.
503 #[inline]
504 pub fn record_turn(&self, high_depth: usize, low_depth: usize) {
505 self.depth_samples.fetch_add(1, Ordering::Relaxed);
506 for (sum, max, depth) in [
507 (
508 &self.high_depth_sum,
509 &self.high_depth_max,
510 high_depth as u64,
511 ),
512 (&self.low_depth_sum, &self.low_depth_max, low_depth as u64),
513 ] {
514 sum.fetch_add(depth, Ordering::Relaxed);
515 max.fetch_max(depth, Ordering::Relaxed);
516 }
517 }
518
519 /// Record which tier the `select!` chose, and what was waiting.
520 ///
521 /// `low_queued` is the depth sampled *before* the `select!`, so it is
522 /// the backlog the turn found on arrival. By the time a high-priority
523 /// arm fires the low queue may have grown; using the pre-select reading
524 /// keeps this consistent with every other depth figure in this module
525 /// and makes the counter conservative — it never invents starvation
526 /// from work that arrived after the choice was made.
527 ///
528 /// A low-priority turn resets the run rather than decrementing it: the
529 /// question is "how many turns did one low-priority command wait", and
530 /// that is a run length, not a balance.
531 #[inline]
532 pub fn record_priority_choice(&self, took_high: bool, low_queued: usize) {
533 if took_high && low_queued > 0 {
534 self.low_starved_turns.fetch_add(1, Ordering::Relaxed);
535 let run = self.low_starved_run.fetch_add(1, Ordering::Relaxed) + 1;
536 self.low_starved_run_max.fetch_max(run, Ordering::Relaxed);
537 } else if !took_high {
538 self.low_starved_run.store(0, Ordering::Relaxed);
539 }
540 }
541
542 #[inline]
543 pub fn record_hold(&self, kind: CommandKind, held: Duration) {
544 let micros = held.as_micros().min(super::MICROS_CEILING as u128) as u64;
545 let k = &self.kinds[kind.index()];
546 k.turns.fetch_add(1, Ordering::Relaxed);
547 k.total_micros.fetch_add(micros, Ordering::Relaxed);
548 k.buckets[bucket_of(micros)].fetch_add(1, Ordering::Relaxed);
549 k.longest_micros.fetch_max(micros, Ordering::Relaxed);
550 if !kind.exempt_from_budget() && held > crate::CHUNK_BUDGET {
551 k.over_budget.fetch_add(1, Ordering::Relaxed);
552 }
553 self.longest.fetch_max(
554 (micros << MICROS_SHIFT) | kind.index() as u64,
555 Ordering::Relaxed,
556 );
557 }
558
559 /// A consistent-enough picture for a dashboard.
560 ///
561 /// Not a torn-read-free snapshot, and it does not pretend to be: the
562 /// actor keeps running while this walks the array, so two kinds may be
563 /// read one turn apart. Locking the actor to produce a report would make
564 /// the observer a source of the latency it is measuring.
565 pub fn snapshot(&self) -> super::MetricsSnapshot {
566 let samples = self.depth_samples.load(Ordering::Relaxed);
567 let mean = |sum: &AtomicU64| {
568 if samples == 0 {
569 0.0
570 } else {
571 sum.load(Ordering::Relaxed) as f64 / samples as f64
572 }
573 };
574
575 let packed = self.longest.load(Ordering::Relaxed);
576 let longest_micros = packed >> MICROS_SHIFT;
577 let longest = (longest_micros > 0)
578 .then(|| {
579 let idx = (packed & KIND_MASK) as usize;
580 CommandKind::ALL
581 .get(idx)
582 .map(|&kind| (kind, Duration::from_micros(longest_micros)))
583 })
584 .flatten();
585
586 let kinds: Vec<_> = CommandKind::ALL
587 .iter()
588 .map(|&kind| {
589 let k = &self.kinds[kind.index()];
590 let turns = k.turns.load(Ordering::Relaxed);
591 let total = k.total_micros.load(Ordering::Relaxed);
592 super::KindSnapshot {
593 kind,
594 turns,
595 over_budget: k.over_budget.load(Ordering::Relaxed),
596 mean: total
597 .checked_div(turns)
598 .map_or(Duration::ZERO, Duration::from_micros),
599 longest: Duration::from_micros(k.longest_micros.load(Ordering::Relaxed)),
600 buckets: std::array::from_fn(|i| k.buckets[i].load(Ordering::Relaxed)),
601 }
602 })
603 .collect();
604
605 super::MetricsSnapshot {
606 // Summed, not counted separately — see `depth_samples`.
607 turns: kinds.iter().map(|k| k.turns).sum(),
608 depth_samples: samples,
609 high_depth_mean: mean(&self.high_depth_sum),
610 high_depth_max: self.high_depth_max.load(Ordering::Relaxed),
611 low_depth_mean: mean(&self.low_depth_sum),
612 low_depth_max: self.low_depth_max.load(Ordering::Relaxed),
613 low_starved_turns: self.low_starved_turns.load(Ordering::Relaxed),
614 low_starved_run_max: self.low_starved_run_max.load(Ordering::Relaxed),
615 longest,
616 kinds,
617 }
618 }
619 }
620}
621
622// ---------------------------------------------------------------------------
623// No-op implementation
624// ---------------------------------------------------------------------------
625
626#[cfg(not(feature = "metrics"))]
627mod imp {
628 use super::CommandKind;
629 use std::time::Duration;
630
631 /// The `metrics`-off shape: zero-sized, and every method is nothing.
632 #[derive(Debug, Default)]
633 pub struct ActorMetrics;
634
635 impl ActorMetrics {
636 pub fn new() -> Self {
637 Self
638 }
639 #[inline]
640 pub fn record_turn(&self, _high_depth: usize, _low_depth: usize) {}
641 #[inline]
642 pub fn record_priority_choice(&self, _took_high: bool, _low_queued: usize) {}
643 #[inline]
644 pub fn record_hold(&self, _kind: CommandKind, _held: Duration) {}
645 }
646}
647
648pub use imp::ActorMetrics;
649
650/// Saturation point for a recorded hold, in microseconds (~2,000 years).
651///
652/// Exists so the packed `longest` field cannot have a pathological duration
653/// overflow into the kind bits. A hold this long is not a measurement, it is a
654/// hang — and the counter should stay readable rather than start reporting the
655/// wrong command.
656///
657/// Kept out of the `metrics` cfg so the invariant test below runs in the default
658/// build too: the packing is a property of the layout, and a build that does not
659/// record is exactly the build where nobody would notice it break.
660#[allow(dead_code)]
661const MICROS_CEILING: u64 = (1u64 << 56) - 1;
662
663/// One command kind's holds, as of the moment [`ActorMetrics::snapshot`] read it.
664#[cfg(feature = "metrics")]
665#[derive(Debug, Clone, PartialEq, Eq)]
666#[non_exhaustive]
667pub struct KindSnapshot {
668 pub kind: CommandKind,
669 /// Turns spent on this kind.
670 pub turns: u64,
671 /// Turns that exceeded [`crate::CHUNK_BUDGET`]. Always 0 for the three
672 /// kinds [`CommandKind::exempt_from_budget`] names — see there for why.
673 pub over_budget: u64,
674 pub mean: Duration,
675 /// This kind's longest hold. Distinct from [`MetricsSnapshot::longest`],
676 /// which names one command across all kinds and so tends to be permanently
677 /// whichever kind is slowest overall.
678 pub longest: Duration,
679 /// Counts per [`BUCKET_BOUNDS_MICROS`], plus a final overflow bucket.
680 ///
681 /// Private behind [`Self::buckets`] since 0.12.8 (W4.2). A public array
682 /// field publishes `BUCKET_COUNT` as part of the type's shape, so adding a
683 /// bucket bound would break every caller that named the length — and the
684 /// bounds are exactly the thing a latency histogram is likely to want to
685 /// re-cut. The accessor returns a slice and the length becomes an
686 /// observation rather than a signature. Python already did it this way.
687 buckets: [u64; BUCKET_COUNT],
688}
689
690#[cfg(feature = "metrics")]
691impl KindSnapshot {
692 /// Counts per [`BUCKET_BOUNDS_MICROS`], plus a final overflow bucket.
693 ///
694 /// Pair it with `BUCKET_BOUNDS_MICROS` to label the axis rather than
695 /// hard-coding the bounds; the slice is one longer than that constant,
696 /// and the extra trailing element is the overflow bucket.
697 pub fn buckets(&self) -> &[u64] {
698 &self.buckets
699 }
700}
701
702/// What the actor has done since the database was opened.
703#[cfg(feature = "metrics")]
704#[derive(Debug, Clone, PartialEq)]
705#[non_exhaustive]
706pub struct MetricsSnapshot {
707 /// Commands executed, i.e. the sum of [`KindSnapshot::turns`]. The two agree
708 /// by construction rather than by coincidence.
709 pub turns: u64,
710 /// Loop iterations that took a queue-depth reading. Always at least
711 /// `turns + 1` on a live actor, because the reading is taken on the way in
712 /// to a `select!` that has not resolved yet. This is the denominator of the
713 /// two means below, and it is exposed so the difference is visible rather
714 /// than looking like drift.
715 pub depth_samples: u64,
716 pub high_depth_mean: f64,
717 pub high_depth_max: u64,
718 pub low_depth_mean: f64,
719 pub low_depth_max: u64,
720 /// The longest hold since open and what caused it. `None` before the first
721 /// turn, and — honestly — also when every turn so far took under a
722 /// microsecond, which on this path does not happen.
723 pub longest: Option<(CommandKind, Duration)>,
724 /// Turns spent on high-priority work while low-priority work was already
725 /// queued (0.12.10, W4.4, D-153).
726 ///
727 /// The actor's `select!` is `biased` and has **no floor**, so this is the
728 /// measurement of a bound the design has always had and never observed.
729 /// On its own it is not alarming: a busy database *should* prefer
730 /// interactive writes, and this counter rising is that working. Read it
731 /// beside [`Self::low_starved_run_max`], which is the number with teeth.
732 pub low_starved_turns: u64,
733 /// The longest unbroken run of the above — i.e. the most turns any single
734 /// low-priority command has waited (0.12.10, W4.4, D-153).
735 ///
736 /// This is the one that answers "can low-priority work be starved". A large
737 /// `low_starved_turns` spread over a long session says the tiers are doing
738 /// their job; a large *run* says one specific chunk, rebuild or archive sat
739 /// behind that many interactive writes in a row.
740 ///
741 /// # There is deliberately no forced-yield policy, and the reason changed
742 /// (0.13.26, W10.4, [D-199])
743 ///
744 /// It used to be "adding one now would be fixing a bound nobody has
745 /// observed being hit". That premise died twice. [D-153] hit the bound
746 /// completely on a synthetic burst, and W10.4 then hit it on an ordinary
747 /// one: **four closed-loop writers** — each awaiting its own write before
748 /// issuing the next, which is what application code does — starve the low
749 /// tier for essentially all of their writes
750 /// (`examples/fairness_probe.rs`). The run is bounded by how long the
751 /// caller keeps offering interactive work, not by concurrency and not by
752 /// anything in this crate.
753 ///
754 /// **What replaced it is the floor's own price.** "After N starved turns,
755 /// take one low-priority command" cannot choose *which* command — the low
756 /// queue is an mpsc channel and its head is not inspectable — and at least
757 /// one low-priority kind is exempt from [`crate::CHUNK_BUDGET`] **by
758 /// contract**: an [`crate::Database::archive`] was measured at 3.3 s
759 /// unwindowed on an 8,000-key backlog. So the floor would add an unbounded
760 /// term to the interactive worst case in order to unblock work that is
761 /// declared not to be latency-sensitive, which is the tier split running
762 /// backwards.
763 ///
764 /// **The lever that does work belongs to the caller**: 1 ms of think time
765 /// between a writer's writes takes four writers from ~78 to ~2. Which makes
766 /// this field the instrument for a decision the caller owns rather than a
767 /// defect report about the actor.
768 ///
769 /// [D-153]: ../docs/architecture/s13-decision-register.md#d-153
770 /// [D-199]: ../docs/architecture/s13-decision-register.md#d-199
771 pub low_starved_run_max: u64,
772 pub kinds: Vec<KindSnapshot>,
773}
774
775#[cfg(feature = "metrics")]
776impl MetricsSnapshot {
777 /// Kinds that broke the budget, worst first. The one-line answer to "is the
778 /// 3 ms bound holding?".
779 pub fn budget_violations(&self) -> Vec<&KindSnapshot> {
780 let mut v: Vec<_> = self.kinds.iter().filter(|k| k.over_budget > 0).collect();
781 v.sort_by_key(|k| std::cmp::Reverse(k.over_budget));
782 v
783 }
784}
785
786#[cfg(test)]
787mod tests {
788 use super::*;
789
790 #[test]
791 fn every_kind_indexes_to_its_own_slot() {
792 for (i, &kind) in CommandKind::ALL.iter().enumerate() {
793 assert_eq!(kind.index(), i, "{kind} is out of order in ALL");
794 }
795 assert_eq!(CommandKind::COUNT, CommandKind::ALL.len());
796 }
797
798 /// The budget is a bucket boundary, not a value inside one — so "fits in the
799 /// budget" is a prefix sum and needs no interpolation.
800 #[test]
801 fn the_chunk_budget_is_exactly_a_bucket_boundary() {
802 let budget = crate::CHUNK_BUDGET.as_micros() as u64;
803 assert!(
804 BUCKET_BOUNDS_MICROS.contains(&budget),
805 "CHUNK_BUDGET is {budget} µs, which is not a bucket bound: \
806 {BUCKET_BOUNDS_MICROS:?}"
807 );
808 assert_eq!(bucket_of(budget), bucket_of(budget - 1));
809 assert_eq!(bucket_of(budget + 1), bucket_of(budget) + 1);
810 }
811
812 #[test]
813 fn the_overflow_bucket_catches_everything_past_the_last_bound() {
814 let last = *BUCKET_BOUNDS_MICROS.last().unwrap();
815 assert_eq!(bucket_of(last), BUCKET_BOUNDS_MICROS.len() - 1);
816 assert_eq!(bucket_of(last + 1), BUCKET_COUNT - 1);
817 assert_eq!(bucket_of(u64::MAX), BUCKET_COUNT - 1);
818 }
819
820 /// The packing is the reason `longest` is one atomic: duration high, kind
821 /// low, so a `fetch_max` on the word compares the duration.
822 #[test]
823 fn the_packing_leaves_room_for_both_fields() {
824 assert!(
825 (CommandKind::COUNT as u64) <= 0xFF,
826 "the kind index must fit in the low 8 bits"
827 );
828 // The ceiling must survive being shifted up by the kind's width.
829 assert_eq!(MICROS_CEILING.checked_shl(8), Some(MICROS_CEILING << 8));
830 assert_eq!((MICROS_CEILING << 8) >> 8, MICROS_CEILING);
831 }
832
833 #[cfg(feature = "metrics")]
834 #[test]
835 fn the_longest_hold_names_the_command_that_caused_it() {
836 let m = ActorMetrics::new();
837 m.record_hold(CommandKind::AssertEdge, Duration::from_micros(500));
838 m.record_hold(CommandKind::Archive, Duration::from_millis(40));
839 m.record_hold(CommandKind::UpsertConcept, Duration::from_micros(900));
840
841 let snap = m.snapshot();
842 assert_eq!(
843 snap.longest,
844 Some((CommandKind::Archive, Duration::from_millis(40)))
845 );
846 }
847
848 /// The regression the packing bug produced: a *short* hold of a
849 /// later-declared kind must not outrank a long hold of an earlier one.
850 ///
851 /// The test above does not catch it, because `Archive` happens to be both
852 /// the longest hold and a high enum index — which is exactly why the first
853 /// version of the packing shipped past it. Here the two orderings disagree.
854 #[cfg(feature = "metrics")]
855 #[test]
856 fn a_later_declared_kind_does_not_outrank_a_longer_hold() {
857 let long = CommandKind::AssertEdge; // index 0
858 let short = CommandKind::RebuildFts; // last index
859 assert!(short.index() > long.index(), "the fixture needs the gap");
860
861 let m = ActorMetrics::new();
862 m.record_hold(long, Duration::from_millis(40));
863 m.record_hold(short, Duration::from_micros(1));
864
865 assert_eq!(
866 m.snapshot().longest,
867 Some((long, Duration::from_millis(40))),
868 "the max is being taken over the kind index, not the duration"
869 );
870 }
871
872 /// The three contractual exemptions must not show up as violations, or the
873 /// violation count is noise on any database that archives.
874 #[cfg(feature = "metrics")]
875 #[test]
876 fn an_exempt_kind_over_budget_is_not_a_violation() {
877 let m = ActorMetrics::new();
878 m.record_hold(CommandKind::Archive, Duration::from_millis(40));
879 m.record_hold(CommandKind::AssertEdge, Duration::from_millis(40));
880
881 let snap = m.snapshot();
882 let violations = snap.budget_violations();
883 assert_eq!(violations.len(), 1);
884 assert_eq!(violations[0].kind, CommandKind::AssertEdge);
885 assert_eq!(violations[0].over_budget, 1);
886
887 // But the hold is still *recorded* — exempt means "not a violation",
888 // not "not measured". A 40 ms archive is exactly what T1.1 exists to
889 // shrink, and it cannot be shrunk if it is not counted.
890 let archive = snap
891 .kinds
892 .iter()
893 .find(|k| k.kind == CommandKind::Archive)
894 .unwrap();
895 assert_eq!(archive.turns, 1);
896 assert_eq!(archive.mean, Duration::from_millis(40));
897 }
898
899 #[cfg(feature = "metrics")]
900 #[test]
901 fn queue_depth_is_a_mean_and_a_high_water_mark() {
902 let m = ActorMetrics::new();
903 m.record_turn(0, 4);
904 m.record_turn(10, 0);
905
906 let snap = m.snapshot();
907 // No command ran, so `turns` is 0 while `depth_samples` is 2. The two
908 // counters are different facts and this is the case that shows it.
909 assert_eq!(snap.turns, 0);
910 assert_eq!(snap.depth_samples, 2);
911 assert_eq!(snap.high_depth_mean, 5.0);
912 assert_eq!(snap.high_depth_max, 10);
913 assert_eq!(snap.low_depth_mean, 2.0);
914 assert_eq!(snap.low_depth_max, 4);
915 }
916}