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}
129
130impl CommandKind {
131 /// Every kind, in declaration order. Indexing into the per-kind arrays is by
132 /// position in this slice, so the two must not drift — which is why the
133 /// arrays are sized from `ALL.len()` rather than from a hand-written count.
134 pub const ALL: &'static [CommandKind] = &[
135 CommandKind::AssertEdge,
136 CommandKind::RetireEdge,
137 CommandKind::UpsertConcept,
138 CommandKind::WriteBulkAtomic,
139 CommandKind::RebuildCurrent,
140 CommandKind::RegisterModel,
141 CommandKind::Shutdown,
142 CommandKind::BulkImportChunk,
143 CommandKind::WriteConceptsChunk,
144 CommandKind::WriteAnalyticsChunk,
145 CommandKind::UpsertEmbeddingChunk,
146 CommandKind::Archive,
147 CommandKind::RebuildFts,
148 CommandKind::ShadowRebuild,
149 CommandKind::Analyze,
150 CommandKind::Rehydrate,
151 CommandKind::Checkpoint,
152 ];
153
154 pub const COUNT: usize = CommandKind::ALL.len();
155
156 /// This kind's slot in the per-kind arrays.
157 ///
158 /// # Declaration order is a persisted contract (0.12.8, W4.2)
159 ///
160 /// `self as usize` means the **order of the variants above** is the order of
161 /// every per-kind array in this module, and the compiler cannot catch a
162 /// change to it. Reordering the enum silently reassigns every counter to a
163 /// different command: the code compiles, the tests pass, and a histogram
164 /// read after the change attributes `archive`'s holds to `rebuild_fts`.
165 ///
166 /// **New variants go at the end**, always — including at the end of
167 /// [`CommandKind::ALL`], whose order is what `as_str()` and the Python
168 /// surface enumerate. This binds Python too: `BUCKET_BOUNDS_MICROS` is a
169 /// module constant there and `KindMetrics` is built by position, so a
170 /// reorder here relabels axes in a language the Rust compiler is not
171 /// looking at.
172 ///
173 /// `#[repr(u8)]` is on the enum for the same reason — it pins the
174 /// discriminants to the declaration order rather than leaving them to the
175 /// compiler — but it pins them to whatever the order *is*, so it does not
176 /// make a reorder safe. Only this rule does.
177 pub const fn index(self) -> usize {
178 self as usize
179 }
180
181 pub const fn as_str(self) -> &'static str {
182 match self {
183 CommandKind::AssertEdge => "assert_edge",
184 CommandKind::RetireEdge => "retire_edge",
185 CommandKind::UpsertConcept => "upsert_concept",
186 CommandKind::WriteBulkAtomic => "write_bulk_atomic",
187 CommandKind::RebuildCurrent => "rebuild_current",
188 CommandKind::RegisterModel => "register_model",
189 CommandKind::Shutdown => "shutdown",
190 CommandKind::BulkImportChunk => "bulk_import_chunk",
191 CommandKind::WriteConceptsChunk => "write_concepts_chunk",
192 CommandKind::WriteAnalyticsChunk => "write_analytics_chunk",
193 CommandKind::UpsertEmbeddingChunk => "upsert_embedding_chunk",
194 CommandKind::Archive => "archive",
195 CommandKind::RebuildFts => "rebuild_fts",
196 CommandKind::ShadowRebuild => "shadow_rebuild",
197 CommandKind::Analyze => "analyze",
198 CommandKind::Rehydrate => "rehydrate",
199 CommandKind::Checkpoint => "checkpoint",
200 }
201 }
202
203 /// Whether this kind is exempt from [`crate::CHUNK_BUDGET`] by contract.
204 ///
205 /// The exemptions are the table in `CHUNK_BUDGET`'s own rustdoc, and they
206 /// are carried here so a dashboard can separate "the budget is being
207 /// broken" from "the budget does not apply and never claimed to". Counting
208 /// an `archive` as a budget violation would make the violation count useless
209 /// on any database that archives.
210 ///
211 /// The two lists must agree, and since 0.12.9 they are tied together in
212 /// both directions by `the_budget_exemptions_and_their_documented_table_agree`
213 /// — the extra-row direction being the one worth having, since a table row
214 /// with no code behind it promises a caller an exemption the violation
215 /// counter is about to disagree with.
216 ///
217 /// [`CommandKind::ShadowRebuild`] is deliberately **not** exempt. Its fill
218 /// chunks are meant to fit the budget and its swap turn is not going to —
219 /// the swap rebuilds three indexes under the lock, which is the residual
220 /// cost T1.2 could not remove. Both facts are worth seeing, and exempting
221 /// the kind would hide the first to excuse the second.
222 ///
223 /// # `Rehydrate` is exempt, and splitting it out is what made that a
224 /// decision rather than an accident (0.12.9, W4.3, D-152)
225 ///
226 /// Until 0.12.8 rehydration reported as [`CommandKind::Archive`] and was
227 /// therefore exempt **by inheritance** — nobody had decided it, it fell out
228 /// of the borrowed kind. Giving it its own variant would have silently
229 /// flipped it to non-exempt, and since a rehydrate is one unchunked
230 /// transaction moving rows back across the file boundary, every single one
231 /// would have counted as a budget violation. The violation count would then
232 /// have become useless on any database that rehydrates, which is precisely
233 /// the failure the `Archive` exemption exists to prevent, arriving by the
234 /// back door of a change made for attribution.
235 ///
236 /// So it is exempt, on the merits and now on the record: rehydration is the
237 /// archive path run backwards and makes the same claim about its hold —
238 /// that it is bulk movement with no latency bound, and that the caller asked
239 /// for it explicitly.
240 ///
241 /// # [`CommandKind::Analyze`] is **not** exempt, and that is a decision
242 /// (0.12.25, D-168)
243 ///
244 /// It looks like it belongs here. `ANALYZE` is one indivisible statement —
245 /// there is no smaller unit to chunk into — and its cost is set by data
246 /// volume, so it cannot meet the budget on a populated ledger. Measured
247 /// (`examples/analyze_hold.rs`): **5.26 ms at 10,000 edges, 19.1 ms at
248 /// 40,000**, against 3 ms. Every call is a violation and always will be.
249 ///
250 /// It stays counted for two reasons.
251 ///
252 /// **The table has a `Bound` column, and this kind cannot fill it in.**
253 /// `Checkpoint`'s bound is frames accumulated since the last one;
254 /// `Archive`'s is the session's row count. The honest entry here would be
255 /// "the size of the table, damped 3–4× by `analysis_limit`", which is not a
256 /// bound but the absence of one. A row that cannot state its bound is this
257 /// table admitting the thing it exists to prevent.
258 ///
259 /// **And this kind is two callers wearing one name.** `Analyze` covers
260 /// [`crate::Database::optimize`] as well as [`crate::Database::analyze`],
261 /// and `close()` calls `optimize()` unconditionally. Exempting the kind
262 /// would silence the *automatic* path — every handle close on a large
263 /// ledger holding ~19 ms with nothing reporting it — which is exactly the
264 /// call nobody chose to make. That is [`CommandKind::Rehydrate`]'s lesson
265 /// above, arriving from the other direction: there, a shared kind granted
266 /// an exemption nobody had decided; here, a shared kind would launder one.
267 ///
268 /// **So the violation is expected, permanent, and must not be "fixed" by
269 /// lowering [`crate::schema::ddl::ANALYSIS_LIMIT`].** That would buy the
270 /// number by sampling too little to separate the two `source_id`-leading
271 /// indices, which is the entire purpose of having statistics
272 /// ([D-149](../docs/architecture/s13-decision-register.md#d-149)).
273 ///
274 /// Splitting the kind is scheduled as **W10.5, 0.14.0**; the exemption
275 /// question is answerable per-caller once it is split, and not before.
276 pub const fn exempt_from_budget(self) -> bool {
277 matches!(
278 self,
279 CommandKind::WriteBulkAtomic
280 | CommandKind::Archive
281 | CommandKind::RebuildCurrent
282 | CommandKind::Rehydrate
283 | CommandKind::Checkpoint
284 )
285 }
286}
287
288impl std::fmt::Display for CommandKind {
289 fn fmt(&self, f: &mut std::fmt::Formatter<'_>) -> std::fmt::Result {
290 f.write_str(self.as_str())
291 }
292}
293
294/// Upper bounds of the hold-duration histogram, in microseconds.
295///
296/// `3_000` is [`crate::CHUNK_BUDGET`] exactly, so the bucket boundary and the
297/// bound are the same number and a reader does not have to interpolate to answer
298/// "what fraction of turns fit". The tail runs to 1 s because D-059's measured
299/// worst case was 45 ms and `rebuild_current` at 40K rows is 318 ms (D-077) —
300/// a range this has to cover without saturating.
301///
302/// Anything above the last bound lands in the overflow bucket, which is why
303/// [`KindSnapshot::buckets`] is one longer than this slice.
304pub const BUCKET_BOUNDS_MICROS: &[u64] = &[
305 100, 300, 1_000, 3_000, 10_000, 30_000, 100_000, 300_000, 1_000_000,
306];
307
308/// Number of histogram buckets, including the overflow bucket.
309pub const BUCKET_COUNT: usize = BUCKET_BOUNDS_MICROS.len() + 1;
310
311#[allow(dead_code)] // used by `imp` under `metrics`, and by the tests always
312fn bucket_of(micros: u64) -> usize {
313 // Linear scan over nine bounds. A binary search here would be slower in
314 // practice and this runs once per actor turn, against a turn measured in
315 // microseconds at best.
316 BUCKET_BOUNDS_MICROS
317 .iter()
318 .position(|&bound| micros <= bound)
319 .unwrap_or(BUCKET_BOUNDS_MICROS.len())
320}
321
322/// Times one actor turn.
323///
324/// # This clock is no longer optional (0.12.0, W1)
325///
326/// Until 0.11.0 the field was `#[cfg(feature = "metrics")]` and `elapsed()`
327/// returned `Duration::ZERO` in a default build: the reading existed only to
328/// feed [`ActorMetrics::record_hold`]'s histogram, so a build that did not keep
329/// the histogram had no reason to read a clock.
330///
331/// The chunk loop changed what the reading is *for*. A chunk's measured hold is
332/// now the input to the next chunk's size (`connection::next_chunk_size`, named
333/// in prose because it is private — D-144), which means it is a control signal
334/// in every build and not an observation in some of them. Left gated, `bulk_import` would have sized its chunks off
335/// `Duration::ZERO` — a value that reads as "comfortably under budget" — and
336/// grown every chunk to the ceiling, in exactly the builds nobody was measuring.
337///
338/// So the clock is unconditional and **only the histogram is still gated**:
339/// `record_hold` remains a no-op without the feature. What that costs is one
340/// `Instant::now()` pair per actor turn — tens of nanoseconds against a turn
341/// measured in microseconds at best, and the same reasoning §5.1.5 uses to
342/// decide that a channel hop is free beside a chunk.
343///
344/// It stays a type rather than a bare `Instant::now()` in the loop because the
345/// ordering guarantee in [`crate::connection`]'s `Turn` is attached to it.
346pub struct HoldTimer {
347 start: std::time::Instant,
348}
349
350impl HoldTimer {
351 #[inline]
352 pub fn start() -> Self {
353 Self {
354 start: std::time::Instant::now(),
355 }
356 }
357
358 #[inline]
359 pub fn elapsed(&self) -> Duration {
360 self.start.elapsed()
361 }
362}
363
364// ---------------------------------------------------------------------------
365// Instrumented implementation
366// ---------------------------------------------------------------------------
367
368#[cfg(feature = "metrics")]
369mod imp {
370 use super::{bucket_of, CommandKind, BUCKET_COUNT};
371 use std::sync::atomic::{AtomicU64, Ordering};
372 use std::time::Duration;
373
374 /// One kind's counters. All `Relaxed`: these are statistics, and ordering
375 /// them against each other would buy a consistency no reader needs and cost
376 /// fences on the write path.
377 #[derive(Debug, Default)]
378 struct Kind {
379 turns: AtomicU64,
380 total_micros: AtomicU64,
381 over_budget: AtomicU64,
382 /// This kind's own high-water mark, in µs.
383 ///
384 /// Not redundant with the global `longest`. That one names a single
385 /// command, so on any real database it names whichever kind is slowest
386 /// overall — and the question "did windowing shrink the archive's worst
387 /// hold" cannot be answered by a counter that a bulk import wins. No
388 /// packing needed here: the kind is the array index.
389 longest_micros: AtomicU64,
390 buckets: [AtomicU64; BUCKET_COUNT],
391 }
392
393 /// Live counters, shared between the actor and the handle.
394 ///
395 /// Fixed size, no allocation, no lock. The actor updates; anyone may read.
396 #[derive(Debug, Default)]
397 pub struct ActorMetrics {
398 kinds: [Kind; CommandKind::COUNT],
399 /// Packed `micros << 8 | kind`, so the longest hold and the kind that
400 /// caused it are read and written as **one** value. Two atomics would
401 /// let a reader see a duration from one turn beside a kind from
402 /// another — a rare wrong answer to exactly the question this field
403 /// exists to answer. 2^56 µs is over two thousand years.
404 ///
405 /// **The duration must occupy the high bits.** The update is a
406 /// `fetch_max` on the packed word, so whichever field is packed high is
407 /// the one being compared. The first version of this had the kind up
408 /// there, which made the "longest hold" the hold with the largest
409 /// *enum index* — a 3 ms `write_concepts_chunk` beat a 10 ms
410 /// `rebuild_current` because its variant is declared later. It was
411 /// `actor_metrics_tests` that caught it, not the unit tests, because
412 /// nothing in the arithmetic is wrong: the packing is only incorrect in
413 /// the presence of the atomic operation it exists to serve.
414 longest: AtomicU64,
415 /// Loop iterations, which is **not** the number of turns taken.
416 ///
417 /// The depth sample happens at the top of the loop, before `select!`
418 /// blocks — so an idle actor has already counted the iteration for a
419 /// command that has not arrived. That is right for depth (the sample is
420 /// "what was queued when I went looking") and wrong for turns, which is
421 /// why [`MetricsSnapshot::turns`] is the sum of the per-kind counters
422 /// instead. Conflating the two made `turns` permanently one too high and
423 /// disagree with its own breakdown.
424 depth_samples: AtomicU64,
425 high_depth_sum: AtomicU64,
426 high_depth_max: AtomicU64,
427 low_depth_sum: AtomicU64,
428 low_depth_max: AtomicU64,
429 /// Turns where the actor took high-priority work while low-priority
430 /// work was already queued (0.12.10, W4.4, D-153).
431 ///
432 /// The `biased` `select!` in `run_writer_actor` has **no floor**:
433 /// sustained high-priority traffic can hold the low tier off
434 /// indefinitely, and nothing has ever said whether that happens. This
435 /// is the numerator of that question — how often the choice went
436 /// against the low tier at all.
437 low_starved_turns: AtomicU64,
438 /// The current unbroken run of such turns. Reset to zero the moment
439 /// low-priority work is taken.
440 ///
441 /// Not exposed; it is the state [`Self::low_starved_run_max`] is a
442 /// high-water mark of. A live value would be read at an arbitrary point
443 /// in a run and mean nothing.
444 low_starved_run: AtomicU64,
445 /// The longest such run since open, which is the number that answers the
446 /// question.
447 ///
448 /// A large `low_starved_turns` on a busy database is unremarkable — it
449 /// says the high tier is being used, which is what the tier is for. A
450 /// large *run* says one specific low-priority command waited that many
451 /// turns, and it is the only one of the two that can distinguish
452 /// "prioritised" from "starved".
453 low_starved_run_max: AtomicU64,
454 }
455
456 const MICROS_SHIFT: u32 = 8;
457 const KIND_MASK: u64 = (1 << MICROS_SHIFT) - 1;
458
459 impl ActorMetrics {
460 pub fn new() -> Self {
461 Self::default()
462 }
463
464 /// Sample both queue depths. Called before the turn, not after: after
465 /// the turn the queue reflects what arrived *during* it, which is a
466 /// different and much less useful quantity.
467 #[inline]
468 pub fn record_turn(&self, high_depth: usize, low_depth: usize) {
469 self.depth_samples.fetch_add(1, Ordering::Relaxed);
470 for (sum, max, depth) in [
471 (
472 &self.high_depth_sum,
473 &self.high_depth_max,
474 high_depth as u64,
475 ),
476 (&self.low_depth_sum, &self.low_depth_max, low_depth as u64),
477 ] {
478 sum.fetch_add(depth, Ordering::Relaxed);
479 max.fetch_max(depth, Ordering::Relaxed);
480 }
481 }
482
483 /// Record which tier the `select!` chose, and what was waiting.
484 ///
485 /// `low_queued` is the depth sampled *before* the `select!`, so it is
486 /// the backlog the turn found on arrival. By the time a high-priority
487 /// arm fires the low queue may have grown; using the pre-select reading
488 /// keeps this consistent with every other depth figure in this module
489 /// and makes the counter conservative — it never invents starvation
490 /// from work that arrived after the choice was made.
491 ///
492 /// A low-priority turn resets the run rather than decrementing it: the
493 /// question is "how many turns did one low-priority command wait", and
494 /// that is a run length, not a balance.
495 #[inline]
496 pub fn record_priority_choice(&self, took_high: bool, low_queued: usize) {
497 if took_high && low_queued > 0 {
498 self.low_starved_turns.fetch_add(1, Ordering::Relaxed);
499 let run = self.low_starved_run.fetch_add(1, Ordering::Relaxed) + 1;
500 self.low_starved_run_max.fetch_max(run, Ordering::Relaxed);
501 } else if !took_high {
502 self.low_starved_run.store(0, Ordering::Relaxed);
503 }
504 }
505
506 #[inline]
507 pub fn record_hold(&self, kind: CommandKind, held: Duration) {
508 let micros = held.as_micros().min(super::MICROS_CEILING as u128) as u64;
509 let k = &self.kinds[kind.index()];
510 k.turns.fetch_add(1, Ordering::Relaxed);
511 k.total_micros.fetch_add(micros, Ordering::Relaxed);
512 k.buckets[bucket_of(micros)].fetch_add(1, Ordering::Relaxed);
513 k.longest_micros.fetch_max(micros, Ordering::Relaxed);
514 if !kind.exempt_from_budget() && held > crate::CHUNK_BUDGET {
515 k.over_budget.fetch_add(1, Ordering::Relaxed);
516 }
517 self.longest.fetch_max(
518 (micros << MICROS_SHIFT) | kind.index() as u64,
519 Ordering::Relaxed,
520 );
521 }
522
523 /// A consistent-enough picture for a dashboard.
524 ///
525 /// Not a torn-read-free snapshot, and it does not pretend to be: the
526 /// actor keeps running while this walks the array, so two kinds may be
527 /// read one turn apart. Locking the actor to produce a report would make
528 /// the observer a source of the latency it is measuring.
529 pub fn snapshot(&self) -> super::MetricsSnapshot {
530 let samples = self.depth_samples.load(Ordering::Relaxed);
531 let mean = |sum: &AtomicU64| {
532 if samples == 0 {
533 0.0
534 } else {
535 sum.load(Ordering::Relaxed) as f64 / samples as f64
536 }
537 };
538
539 let packed = self.longest.load(Ordering::Relaxed);
540 let longest_micros = packed >> MICROS_SHIFT;
541 let longest = (longest_micros > 0)
542 .then(|| {
543 let idx = (packed & KIND_MASK) as usize;
544 CommandKind::ALL
545 .get(idx)
546 .map(|&kind| (kind, Duration::from_micros(longest_micros)))
547 })
548 .flatten();
549
550 let kinds: Vec<_> = CommandKind::ALL
551 .iter()
552 .map(|&kind| {
553 let k = &self.kinds[kind.index()];
554 let turns = k.turns.load(Ordering::Relaxed);
555 let total = k.total_micros.load(Ordering::Relaxed);
556 super::KindSnapshot {
557 kind,
558 turns,
559 over_budget: k.over_budget.load(Ordering::Relaxed),
560 mean: total
561 .checked_div(turns)
562 .map_or(Duration::ZERO, Duration::from_micros),
563 longest: Duration::from_micros(k.longest_micros.load(Ordering::Relaxed)),
564 buckets: std::array::from_fn(|i| k.buckets[i].load(Ordering::Relaxed)),
565 }
566 })
567 .collect();
568
569 super::MetricsSnapshot {
570 // Summed, not counted separately — see `depth_samples`.
571 turns: kinds.iter().map(|k| k.turns).sum(),
572 depth_samples: samples,
573 high_depth_mean: mean(&self.high_depth_sum),
574 high_depth_max: self.high_depth_max.load(Ordering::Relaxed),
575 low_depth_mean: mean(&self.low_depth_sum),
576 low_depth_max: self.low_depth_max.load(Ordering::Relaxed),
577 low_starved_turns: self.low_starved_turns.load(Ordering::Relaxed),
578 low_starved_run_max: self.low_starved_run_max.load(Ordering::Relaxed),
579 longest,
580 kinds,
581 }
582 }
583 }
584}
585
586// ---------------------------------------------------------------------------
587// No-op implementation
588// ---------------------------------------------------------------------------
589
590#[cfg(not(feature = "metrics"))]
591mod imp {
592 use super::CommandKind;
593 use std::time::Duration;
594
595 /// The `metrics`-off shape: zero-sized, and every method is nothing.
596 #[derive(Debug, Default)]
597 pub struct ActorMetrics;
598
599 impl ActorMetrics {
600 pub fn new() -> Self {
601 Self
602 }
603 #[inline]
604 pub fn record_turn(&self, _high_depth: usize, _low_depth: usize) {}
605 #[inline]
606 pub fn record_priority_choice(&self, _took_high: bool, _low_queued: usize) {}
607 #[inline]
608 pub fn record_hold(&self, _kind: CommandKind, _held: Duration) {}
609 }
610}
611
612pub use imp::ActorMetrics;
613
614/// Saturation point for a recorded hold, in microseconds (~2,000 years).
615///
616/// Exists so the packed `longest` field cannot have a pathological duration
617/// overflow into the kind bits. A hold this long is not a measurement, it is a
618/// hang — and the counter should stay readable rather than start reporting the
619/// wrong command.
620///
621/// Kept out of the `metrics` cfg so the invariant test below runs in the default
622/// build too: the packing is a property of the layout, and a build that does not
623/// record is exactly the build where nobody would notice it break.
624#[allow(dead_code)]
625const MICROS_CEILING: u64 = (1u64 << 56) - 1;
626
627/// One command kind's holds, as of the moment [`ActorMetrics::snapshot`] read it.
628#[cfg(feature = "metrics")]
629#[derive(Debug, Clone, PartialEq, Eq)]
630#[non_exhaustive]
631pub struct KindSnapshot {
632 pub kind: CommandKind,
633 /// Turns spent on this kind.
634 pub turns: u64,
635 /// Turns that exceeded [`crate::CHUNK_BUDGET`]. Always 0 for the three
636 /// kinds [`CommandKind::exempt_from_budget`] names — see there for why.
637 pub over_budget: u64,
638 pub mean: Duration,
639 /// This kind's longest hold. Distinct from [`MetricsSnapshot::longest`],
640 /// which names one command across all kinds and so tends to be permanently
641 /// whichever kind is slowest overall.
642 pub longest: Duration,
643 /// Counts per [`BUCKET_BOUNDS_MICROS`], plus a final overflow bucket.
644 ///
645 /// Private behind [`Self::buckets`] since 0.12.8 (W4.2). A public array
646 /// field publishes `BUCKET_COUNT` as part of the type's shape, so adding a
647 /// bucket bound would break every caller that named the length — and the
648 /// bounds are exactly the thing a latency histogram is likely to want to
649 /// re-cut. The accessor returns a slice and the length becomes an
650 /// observation rather than a signature. Python already did it this way.
651 buckets: [u64; BUCKET_COUNT],
652}
653
654#[cfg(feature = "metrics")]
655impl KindSnapshot {
656 /// Counts per [`BUCKET_BOUNDS_MICROS`], plus a final overflow bucket.
657 ///
658 /// Pair it with `BUCKET_BOUNDS_MICROS` to label the axis rather than
659 /// hard-coding the bounds; the slice is one longer than that constant,
660 /// and the extra trailing element is the overflow bucket.
661 pub fn buckets(&self) -> &[u64] {
662 &self.buckets
663 }
664}
665
666/// What the actor has done since the database was opened.
667#[cfg(feature = "metrics")]
668#[derive(Debug, Clone, PartialEq)]
669#[non_exhaustive]
670pub struct MetricsSnapshot {
671 /// Commands executed, i.e. the sum of [`KindSnapshot::turns`]. The two agree
672 /// by construction rather than by coincidence.
673 pub turns: u64,
674 /// Loop iterations that took a queue-depth reading. Always at least
675 /// `turns + 1` on a live actor, because the reading is taken on the way in
676 /// to a `select!` that has not resolved yet. This is the denominator of the
677 /// two means below, and it is exposed so the difference is visible rather
678 /// than looking like drift.
679 pub depth_samples: u64,
680 pub high_depth_mean: f64,
681 pub high_depth_max: u64,
682 pub low_depth_mean: f64,
683 pub low_depth_max: u64,
684 /// The longest hold since open and what caused it. `None` before the first
685 /// turn, and — honestly — also when every turn so far took under a
686 /// microsecond, which on this path does not happen.
687 pub longest: Option<(CommandKind, Duration)>,
688 /// Turns spent on high-priority work while low-priority work was already
689 /// queued (0.12.10, W4.4, D-153).
690 ///
691 /// The actor's `select!` is `biased` and has **no floor**, so this is the
692 /// measurement of a bound the design has always had and never observed.
693 /// On its own it is not alarming: a busy database *should* prefer
694 /// interactive writes, and this counter rising is that working. Read it
695 /// beside [`Self::low_starved_run_max`], which is the number with teeth.
696 pub low_starved_turns: u64,
697 /// The longest unbroken run of the above — i.e. the most turns any single
698 /// low-priority command has waited (0.12.10, W4.4, D-153).
699 ///
700 /// This is the one that answers "can low-priority work be starved". A large
701 /// `low_starved_turns` spread over a long session says the tiers are doing
702 /// their job; a large *run* says one specific chunk, rebuild or archive sat
703 /// behind that many interactive writes in a row.
704 ///
705 /// **There is deliberately no forced-yield policy attached to this.**
706 /// Adding one now would be fixing a bound nobody has observed being hit,
707 /// and the counter exists precisely to find out whether it is. See D-153.
708 pub low_starved_run_max: u64,
709 pub kinds: Vec<KindSnapshot>,
710}
711
712#[cfg(feature = "metrics")]
713impl MetricsSnapshot {
714 /// Kinds that broke the budget, worst first. The one-line answer to "is the
715 /// 3 ms bound holding?".
716 pub fn budget_violations(&self) -> Vec<&KindSnapshot> {
717 let mut v: Vec<_> = self.kinds.iter().filter(|k| k.over_budget > 0).collect();
718 v.sort_by_key(|k| std::cmp::Reverse(k.over_budget));
719 v
720 }
721}
722
723#[cfg(test)]
724mod tests {
725 use super::*;
726
727 #[test]
728 fn every_kind_indexes_to_its_own_slot() {
729 for (i, &kind) in CommandKind::ALL.iter().enumerate() {
730 assert_eq!(kind.index(), i, "{kind} is out of order in ALL");
731 }
732 assert_eq!(CommandKind::COUNT, CommandKind::ALL.len());
733 }
734
735 /// The budget is a bucket boundary, not a value inside one — so "fits in the
736 /// budget" is a prefix sum and needs no interpolation.
737 #[test]
738 fn the_chunk_budget_is_exactly_a_bucket_boundary() {
739 let budget = crate::CHUNK_BUDGET.as_micros() as u64;
740 assert!(
741 BUCKET_BOUNDS_MICROS.contains(&budget),
742 "CHUNK_BUDGET is {budget} µs, which is not a bucket bound: \
743 {BUCKET_BOUNDS_MICROS:?}"
744 );
745 assert_eq!(bucket_of(budget), bucket_of(budget - 1));
746 assert_eq!(bucket_of(budget + 1), bucket_of(budget) + 1);
747 }
748
749 #[test]
750 fn the_overflow_bucket_catches_everything_past_the_last_bound() {
751 let last = *BUCKET_BOUNDS_MICROS.last().unwrap();
752 assert_eq!(bucket_of(last), BUCKET_BOUNDS_MICROS.len() - 1);
753 assert_eq!(bucket_of(last + 1), BUCKET_COUNT - 1);
754 assert_eq!(bucket_of(u64::MAX), BUCKET_COUNT - 1);
755 }
756
757 /// The packing is the reason `longest` is one atomic: duration high, kind
758 /// low, so a `fetch_max` on the word compares the duration.
759 #[test]
760 fn the_packing_leaves_room_for_both_fields() {
761 assert!(
762 (CommandKind::COUNT as u64) <= 0xFF,
763 "the kind index must fit in the low 8 bits"
764 );
765 // The ceiling must survive being shifted up by the kind's width.
766 assert_eq!(MICROS_CEILING.checked_shl(8), Some(MICROS_CEILING << 8));
767 assert_eq!((MICROS_CEILING << 8) >> 8, MICROS_CEILING);
768 }
769
770 #[cfg(feature = "metrics")]
771 #[test]
772 fn the_longest_hold_names_the_command_that_caused_it() {
773 let m = ActorMetrics::new();
774 m.record_hold(CommandKind::AssertEdge, Duration::from_micros(500));
775 m.record_hold(CommandKind::Archive, Duration::from_millis(40));
776 m.record_hold(CommandKind::UpsertConcept, Duration::from_micros(900));
777
778 let snap = m.snapshot();
779 assert_eq!(
780 snap.longest,
781 Some((CommandKind::Archive, Duration::from_millis(40)))
782 );
783 }
784
785 /// The regression the packing bug produced: a *short* hold of a
786 /// later-declared kind must not outrank a long hold of an earlier one.
787 ///
788 /// The test above does not catch it, because `Archive` happens to be both
789 /// the longest hold and a high enum index — which is exactly why the first
790 /// version of the packing shipped past it. Here the two orderings disagree.
791 #[cfg(feature = "metrics")]
792 #[test]
793 fn a_later_declared_kind_does_not_outrank_a_longer_hold() {
794 let long = CommandKind::AssertEdge; // index 0
795 let short = CommandKind::RebuildFts; // last index
796 assert!(short.index() > long.index(), "the fixture needs the gap");
797
798 let m = ActorMetrics::new();
799 m.record_hold(long, Duration::from_millis(40));
800 m.record_hold(short, Duration::from_micros(1));
801
802 assert_eq!(
803 m.snapshot().longest,
804 Some((long, Duration::from_millis(40))),
805 "the max is being taken over the kind index, not the duration"
806 );
807 }
808
809 /// The three contractual exemptions must not show up as violations, or the
810 /// violation count is noise on any database that archives.
811 #[cfg(feature = "metrics")]
812 #[test]
813 fn an_exempt_kind_over_budget_is_not_a_violation() {
814 let m = ActorMetrics::new();
815 m.record_hold(CommandKind::Archive, Duration::from_millis(40));
816 m.record_hold(CommandKind::AssertEdge, Duration::from_millis(40));
817
818 let snap = m.snapshot();
819 let violations = snap.budget_violations();
820 assert_eq!(violations.len(), 1);
821 assert_eq!(violations[0].kind, CommandKind::AssertEdge);
822 assert_eq!(violations[0].over_budget, 1);
823
824 // But the hold is still *recorded* — exempt means "not a violation",
825 // not "not measured". A 40 ms archive is exactly what T1.1 exists to
826 // shrink, and it cannot be shrunk if it is not counted.
827 let archive = snap
828 .kinds
829 .iter()
830 .find(|k| k.kind == CommandKind::Archive)
831 .unwrap();
832 assert_eq!(archive.turns, 1);
833 assert_eq!(archive.mean, Duration::from_millis(40));
834 }
835
836 #[cfg(feature = "metrics")]
837 #[test]
838 fn queue_depth_is_a_mean_and_a_high_water_mark() {
839 let m = ActorMetrics::new();
840 m.record_turn(0, 4);
841 m.record_turn(10, 0);
842
843 let snap = m.snapshot();
844 // No command ran, so `turns` is 0 while `depth_samples` is 2. The two
845 // counters are different facts and this is the case that shows it.
846 assert_eq!(snap.turns, 0);
847 assert_eq!(snap.depth_samples, 2);
848 assert_eq!(snap.high_depth_mean, 5.0);
849 assert_eq!(snap.high_depth_max, 10);
850 assert_eq!(snap.low_depth_mean, 2.0);
851 assert_eq!(snap.low_depth_max, 4);
852 }
853}