Skip to main content

keyhog_profile/
insight.rs

1//! Turn one recorded profile into the answers an operator asked for.
2//!
3//! The measurement layers record spans, counters, resources, and allocator
4//! ownership. This module reads one finished [`crate::CausalProfileV2`] and
5//! derives the six questions a slow scan actually raises: where the wall time
6//! went, how much of it was serial, how much of the machine was used, how much
7//! memory the run cost and why, what a byte and a file cost, and which caches
8//! paid off.
9//!
10//! Every derived number is an integer. Ratios are thousandths (`_milli`) or
11//! parts per million (`_ppm`), so two runs diff exactly and a diff never shows
12//! float noise.
13//!
14//! ```
15//! use keyhog_profile::{CausalProfileV2, RunIdentity, RunState, Session};
16//!
17//! let identity = RunIdentity::new("0.5.49", "d", "c", "filesystem", "small-text", "auto");
18//! let session = Session::start(identity).expect("start profile");
19//! let profile = session.finish(RunState::Completed);
20//! let causal = CausalProfileV2::from_v1(profile);
21//! let insight = keyhog_profile::RunInsightV2::derive(&causal);
22//! assert!(insight.render_summary().starts_with("bottleneck "));
23//! ```
24
25use crate::metrics::{MacroStageId, MetricId};
26use crate::schema::{RunState, StateMeasurement};
27use crate::schema_v2::{
28    CacheEffectivenessV2, CausalProfileV2, Evidence, QueueDepthV2, RetryRecordV2,
29};
30use serde::{Deserialize, Serialize};
31
32pub const RUN_INSIGHT_V2_VERSION: u16 = 1;
33
34/// A stage is treated as serial when its average worker count stays under this.
35const SERIAL_CONCURRENCY_MILLI: u64 = 1_500;
36/// A phase must hold at least this share of wall time to be worth naming.
37const MATERIAL_SHARE_PPM: u64 = 50_000;
38/// A serial region below this share of wall time is noise, not a finding.
39const SERIAL_REPORT_SHARE_PPM: u64 = 10_000;
40/// Amplification is only meaningful once the input is a real workload.
41const AMPLIFICATION_FLOOR_BYTES: u64 = 1024 * 1024;
42/// Below this average worker count a region is sparse, not serial: it spans a
43/// long window without occupying it.
44const SERIAL_FLOOR_MILLI: u64 = 700;
45/// A region must own most of the work recorded during its window to be a
46/// barrier rather than a wrapper around parallel children.
47const SERIAL_EXCLUSIVITY_PPM: u64 = 600_000;
48/// Peak resident above this, with input far below it, is a fixed memory floor.
49const MEMORY_FLOOR_BYTES: u64 = 64 * 1024 * 1024;
50/// Peak resident this many times the input is amplification worth naming.
51const AMPLIFICATION_MILLI: u64 = 2_000;
52
53fn ppm(part: u64, whole: u64) -> u64 {
54    if whole == 0 {
55        return 0;
56    }
57    u64::try_from((u128::from(part) * 1_000_000) / u128::from(whole)).unwrap_or(u64::MAX)
58}
59
60fn milli(part: u64, whole: u64) -> u64 {
61    if whole == 0 {
62        return 0;
63    }
64    u64::try_from((u128::from(part) * 1_000) / u128::from(whole)).unwrap_or(u64::MAX)
65}
66
67fn per_second_milli(count: u64, elapsed_ns: u64) -> u64 {
68    if elapsed_ns == 0 {
69        return 0;
70    }
71    u64::try_from((u128::from(count) * 1_000_000_000_000) / u128::from(elapsed_ns))
72        .unwrap_or(u64::MAX)
73}
74
75fn mib_per_second_milli(bytes: u64, elapsed_ns: u64) -> u64 {
76    if elapsed_ns == 0 {
77        return 0;
78    }
79    u64::try_from((u128::from(bytes) * 1_000_000_000_000) / (u128::from(elapsed_ns) * 1_048_576))
80        .unwrap_or(u64::MAX)
81}
82
83fn format_bytes(bytes: u64) -> String {
84    const UNITS: [(&str, u64); 4] = [
85        ("GiB", 1024 * 1024 * 1024),
86        ("MiB", 1024 * 1024),
87        ("KiB", 1024),
88        ("B", 1),
89    ];
90    for (label, scale) in UNITS {
91        if bytes >= scale {
92            return format!("{:.1} {label}", bytes as f64 / scale as f64);
93        }
94    }
95    format!("{bytes} B")
96}
97
98fn format_ms(nanoseconds: u64) -> String {
99    format!("{:.3} ms", nanoseconds as f64 / 1_000_000.0)
100}
101
102fn format_ratio(value_milli: u64) -> String {
103    format!("{:.2}x", value_milli as f64 / 1_000.0)
104}
105
106fn format_percent_ppm(value_ppm: u64) -> String {
107    format!("{:.1}%", value_ppm as f64 / 10_000.0)
108}
109
110/// What limited this run.
111#[derive(Clone, Copy, Debug, Eq, PartialEq, Serialize, Deserialize)]
112#[serde(rename_all = "kebab-case")]
113pub enum BottleneckKindV2 {
114    /// A phase held the wall clock while the worker pool sat idle.
115    SerialPhase,
116    /// Workers were available but the achieved speedup stayed far below them.
117    ParallelStarvation,
118    /// Workers spent their time blocked waiting for a queue to deliver work.
119    QueueStarvation,
120    /// One micro-function dominated an otherwise parallel run.
121    StageBound,
122    /// Resident memory is dominated by a fixed cost the input did not cause.
123    MemoryFloor,
124    /// Resident memory scales as a large multiple of the input.
125    MemoryAmplification,
126    /// A reuse cache missed often enough to pay for the recomputation twice.
127    CacheMiss,
128    /// Work had to be attempted again, so a failure was not designed out.
129    RetriedWork,
130    /// Wall time went to work outside scanning: startup, config, reporting.
131    FixedOverhead,
132    /// Nothing measured is large enough to name a bottleneck honestly.
133    Insufficient,
134}
135
136impl BottleneckKindV2 {
137    pub const fn as_str(self) -> &'static str {
138        match self {
139            Self::SerialPhase => "serial-phase",
140            Self::ParallelStarvation => "parallel-starvation",
141            Self::QueueStarvation => "queue-starvation",
142            Self::StageBound => "stage-bound",
143            Self::MemoryFloor => "memory-floor",
144            Self::MemoryAmplification => "memory-amplification",
145            Self::CacheMiss => "cache-miss",
146            Self::RetriedWork => "retried-work",
147            Self::FixedOverhead => "fixed-overhead",
148            Self::Insufficient => "insufficient-evidence",
149        }
150    }
151}
152
153/// One ranked conclusion with the measurement that supports it.
154#[derive(Clone, Debug, Eq, PartialEq, Serialize, Deserialize)]
155pub struct FindingV2 {
156    pub version: u16,
157    pub kind: BottleneckKindV2,
158    /// Zero is informational, three is the run's limiting factor.
159    pub severity: u8,
160    /// Wall time this finding accounts for. Zero when the finding is not timed.
161    pub impact_ns: u64,
162    pub impact_share_ppm: u64,
163    /// Phase, micro-function, or cache the finding is about.
164    pub subject: String,
165    /// One sentence stating the conclusion and the number behind it.
166    pub statement: String,
167}
168
169/// Wall time, CPU time, and memory for one macro phase.
170#[derive(Clone, Debug, Eq, PartialEq, Serialize, Deserialize)]
171pub struct PhaseInsightV2 {
172    pub version: u16,
173    pub state: RunState,
174    pub wall_ns: u64,
175    pub share_ppm: u64,
176    pub cpu_ns: u64,
177    /// `cpu_ns / wall_ns` in thousandths: the workers this phase actually used.
178    pub speedup_milli: u64,
179    /// True when the phase ran at roughly one worker while a pool existed.
180    pub serial: bool,
181    pub mib_per_second_milli: u64,
182    pub units_per_second_milli: u64,
183    pub resident_start_bytes: u64,
184    pub resident_end_bytes: u64,
185    pub threads_start: u64,
186    pub threads_end: u64,
187}
188
189/// Overall and per-phase rates.
190#[derive(Clone, Debug, Eq, PartialEq, Serialize, Deserialize)]
191pub struct ThroughputInsightV2 {
192    pub version: u16,
193    pub wall_ns: u64,
194    pub input_bytes: u64,
195    pub input_units: u64,
196    /// MiB per second times one thousand.
197    pub mib_per_second_milli: u64,
198    /// Input units per second times one thousand.
199    pub units_per_second_milli: u64,
200    pub ns_per_unit: u64,
201    /// Nanoseconds per input byte times one thousand.
202    pub ns_per_byte_milli: u64,
203    /// CPU nanoseconds per input byte times one thousand.
204    pub cpu_ns_per_byte_milli: u64,
205    pub phases: Vec<PhaseInsightV2>,
206}
207
208/// Allocation ownership for one micro-function.
209#[derive(Clone, Debug, Eq, PartialEq, Serialize, Deserialize)]
210pub struct StageMemoryV2 {
211    pub version: u16,
212    /// `None` is the root slot: allocations made outside any recorded span.
213    pub metric_id: Option<MetricId>,
214    pub allocations: u64,
215    pub allocated_bytes: u64,
216    pub live_bytes: u64,
217    pub peak_live_bytes: u64,
218}
219
220/// Where resident memory went and what caused it.
221#[derive(Clone, Debug, Eq, PartialEq, Serialize, Deserialize)]
222pub struct MemoryInsightV2 {
223    pub version: u16,
224    /// Exact kernel high water when available, otherwise the sampled maximum.
225    pub peak_resident_bytes: u64,
226    /// `kernel-vmhwm`, `boundary-samples`, or `unavailable`.
227    pub peak_source: String,
228    /// Resident memory at the first recorded boundary of the run.
229    pub baseline_resident_bytes: u64,
230    /// Resident memory on entry to scanning: the cost of standing the engine up.
231    pub engine_init_resident_bytes: u64,
232    /// Peak minus the engine-init floor: the part the input actually caused.
233    pub input_driven_resident_bytes: u64,
234    pub input_bytes: u64,
235    /// Peak resident per input byte in thousandths.
236    pub amplification_milli: u64,
237    pub scanner_threads: u64,
238    /// Peak resident divided by scanner threads; compare across thread counts
239    /// to read the per-thread scratch slope.
240    pub resident_per_scanner_thread_bytes: u64,
241    /// Input-driven resident divided by scanner threads.
242    pub input_driven_per_scanner_thread_bytes: u64,
243    pub allocations: u64,
244    pub allocated_bytes: u64,
245    pub deallocated_bytes: u64,
246    pub allocation_peak_live_bytes: u64,
247    /// Bytes allocated per input byte in thousandths.
248    pub allocated_per_input_byte_milli: u64,
249    /// Allocation owners sorted by attributed bytes, largest first.
250    pub stages: Vec<StageMemoryV2>,
251}
252
253/// Per-worker time and how much of the machine the run reached.
254#[derive(Clone, Debug, Eq, PartialEq, Serialize, Deserialize)]
255pub struct ParallelismInsightV2 {
256    pub version: u16,
257    pub logical_cpus: u64,
258    pub scanner_threads: u64,
259    pub wall_ns: u64,
260    pub process_cpu_ns: u64,
261    /// `process_cpu_ns / wall_ns` in thousandths: the speedup actually achieved.
262    pub achieved_speedup_milli: u64,
263    /// Achieved speedup over logical CPUs, in parts per million.
264    pub parallel_efficiency_ppm: u64,
265    /// Amdahl ceiling implied by the measured serial share, in thousandths.
266    pub speedup_ceiling_milli: u64,
267    pub worker_count: u64,
268    pub active_worker_count: u64,
269    /// Summed outermost-span time across workers.
270    pub instrumented_busy_ns: u64,
271    /// Summed outermost blocked-wait time across workers.
272    pub instrumented_blocked_ns: u64,
273    /// `wall_ns * worker_count`: the time the pool could have spent working.
274    pub worker_capacity_ns: u64,
275    pub idle_ns: u64,
276    pub idle_share_ppm: u64,
277    pub busiest_busy_ns: u64,
278    pub median_busy_ns: u64,
279    /// Busiest minus median over busiest, in parts per million.
280    pub imbalance_ppm: u64,
281    /// Time inside outermost spans that was not on CPU. Threads sitting in an
282    /// instrumented region while runnable-but-not-running show up here, which
283    /// is where a large worker pool loses its speedup without ever going idle.
284    pub busy_off_cpu_ns: u64,
285    pub source_blocked_ns: u64,
286    pub scanner_blocked_ns: u64,
287    pub queues: Vec<QueueDepthV2>,
288}
289
290/// Scope a serial region was observed at.
291#[derive(Clone, Copy, Debug, Eq, PartialEq, Serialize, Deserialize)]
292#[serde(rename_all = "kebab-case")]
293pub enum SerialScopeV2 {
294    /// A macro run state such as acquiring or scanning.
295    Phase,
296    /// One micro-function.
297    Stage,
298}
299
300/// One region that held the wall clock without using the pool.
301#[derive(Clone, Debug, Eq, PartialEq, Serialize, Deserialize)]
302pub struct SerialRegionV2 {
303    pub version: u16,
304    pub scope: SerialScopeV2,
305    pub subject: String,
306    pub wall_ns: u64,
307    pub share_ppm: u64,
308    /// Average workers inside the region, in thousandths.
309    pub concurrency_milli: u64,
310    pub worker_count: u64,
311    /// Share of the work recorded during this window that belongs to this
312    /// region, in parts per million. An inclusive wrapper span scores low
313    /// because its children run inside it; a real barrier scores near one.
314    pub exclusivity_ppm: u64,
315    /// True when a caller declared the region serial with `serial_span`.
316    pub declared: bool,
317}
318
319/// What one micro-function cost per call, per file, per byte.
320#[derive(Clone, Debug, Eq, PartialEq, Serialize, Deserialize)]
321pub struct StageAttributionV2 {
322    pub version: u16,
323    pub metric_id: MetricId,
324    pub macro_stage_id: MacroStageId,
325    pub calls: u64,
326    pub elapsed_ns: u64,
327    pub share_of_recorded_ppm: u64,
328    pub ns_per_call: u64,
329    pub ns_per_input_unit: u64,
330    /// Nanoseconds per input byte times one thousand.
331    pub ns_per_input_byte_milli: u64,
332    /// Bytes the caller attributed to this micro-function.
333    pub bytes: u64,
334    pub mib_per_second_milli: u64,
335    pub concurrency_milli: u64,
336    pub worker_count: u64,
337}
338
339/// What one backend was asked to do.
340#[derive(Clone, Debug, Eq, PartialEq, Serialize, Deserialize)]
341pub struct BackendAttributionV2 {
342    pub version: u16,
343    pub backend: String,
344    pub batches: u64,
345    pub recovered_batches: u64,
346    pub share_ppm: u64,
347}
348
349/// Which measurements were available, so a missing number reads as a gap.
350#[derive(Clone, Debug, Eq, PartialEq, Serialize, Deserialize)]
351pub struct InsightCoverageV2 {
352    pub version: u16,
353    pub process_metrics: bool,
354    pub allocation_tracking: bool,
355    pub stage_concurrency: bool,
356    pub worker_occupancy: bool,
357    pub dropped_span_events: u64,
358    /// Plain sentences naming each gap that weakens a conclusion above.
359    pub notes: Vec<String>,
360}
361
362/// Every derived answer for one run.
363#[derive(Clone, Debug, Eq, PartialEq, Serialize, Deserialize)]
364pub struct RunInsightV2 {
365    pub version: u16,
366    /// Ranked conclusions; the first is the run's limiting factor.
367    pub findings: Vec<FindingV2>,
368    pub throughput: ThroughputInsightV2,
369    pub memory: MemoryInsightV2,
370    pub parallelism: ParallelismInsightV2,
371    pub serial_regions: Vec<SerialRegionV2>,
372    /// Micro-functions sorted by summed time, largest first.
373    pub stages: Vec<StageAttributionV2>,
374    pub backends: Vec<BackendAttributionV2>,
375    pub caches: Vec<CacheEffectivenessV2>,
376    pub retries: Vec<RetryRecordV2>,
377    pub coverage: InsightCoverageV2,
378}
379
380impl RunInsightV2 {
381    /// Derive every answer from one finished profile.
382    pub fn derive(profile: &CausalProfileV2) -> Self {
383        let wall_ns = profile.wall_time_ns;
384        let identity = &profile.identity;
385        let input_bytes = identity.workload.raw_source_bytes;
386        let input_units = identity.workload.source_units;
387        let logical_cpus = u64::from(identity.host.logical_cpus);
388        let scanner_threads = u64::try_from(identity.scanner_threads_requested).unwrap_or(0);
389
390        let process_cpu_ns = process_cpu_ns(profile);
391        let phases = derive_phases(profile, wall_ns, input_bytes, input_units);
392        let memory = derive_memory(profile, input_bytes, scanner_threads.max(1));
393        let (serial_regions, serial_wall_ns) = derive_serial(profile, &phases, wall_ns);
394        let parallelism = derive_parallelism(
395            profile,
396            wall_ns,
397            process_cpu_ns,
398            logical_cpus,
399            scanner_threads,
400            serial_wall_ns,
401        );
402        let stages = derive_stages(profile, input_bytes, input_units);
403        let backends = derive_backends(profile);
404        let coverage = derive_coverage(profile, &memory, &parallelism);
405
406        let throughput = ThroughputInsightV2 {
407            version: RUN_INSIGHT_V2_VERSION,
408            wall_ns,
409            input_bytes,
410            input_units,
411            mib_per_second_milli: mib_per_second_milli(input_bytes, wall_ns),
412            units_per_second_milli: per_second_milli(input_units, wall_ns),
413            ns_per_unit: if input_units == 0 {
414                0
415            } else {
416                wall_ns / input_units
417            },
418            ns_per_byte_milli: milli(wall_ns, input_bytes),
419            cpu_ns_per_byte_milli: milli(process_cpu_ns, input_bytes),
420            phases,
421        };
422
423        let findings = rank_findings(
424            wall_ns,
425            &throughput,
426            &memory,
427            &parallelism,
428            &serial_regions,
429            &stages,
430            &profile.caches,
431            &profile.retries,
432        );
433
434        Self {
435            version: RUN_INSIGHT_V2_VERSION,
436            findings,
437            throughput,
438            memory,
439            parallelism,
440            serial_regions,
441            stages,
442            backends,
443            caches: profile.caches.clone(),
444            retries: profile.retries.clone(),
445            coverage,
446        }
447    }
448
449    /// The run's limiting factor, or an insufficient-evidence finding.
450    pub fn bottleneck(&self) -> &FindingV2 {
451        self.findings.first().expect("findings is never empty")
452    }
453
454    /// Render the operator summary, leading with the bottleneck.
455    ///
456    /// The first line is the conclusion. Everything after it is the evidence
457    /// for that conclusion, in the order an operator would ask for it.
458    pub fn render_summary(&self) -> String {
459        let mut out = String::with_capacity(2_048);
460        let bottleneck = self.bottleneck();
461        out.push_str(&format!(
462            "bottleneck {} {}\n",
463            bottleneck.kind.as_str(),
464            bottleneck.statement
465        ));
466        for finding in self.findings.iter().skip(1) {
467            out.push_str(&format!(
468                "  also {} {}\n",
469                finding.kind.as_str(),
470                finding.statement
471            ));
472        }
473
474        let throughput = &self.throughput;
475        // A ratio taken against a handful of bytes is arithmetic, not
476        // information. Say so rather than print eight significant digits.
477        let small_input = throughput.input_bytes < AMPLIFICATION_FLOOR_BYTES;
478        let per_mib = if small_input {
479            "n/a (input below 1 MiB)".to_owned()
480        } else {
481            format_ms(throughput.ns_per_byte_milli * 1_048_576 / 1_000)
482        };
483        out.push_str(&format!(
484            "throughput wall={} input={} units={} rate={:.2} MiB/s files_per_s={:.1} per_file={} per_MiB={per_mib}\n",
485            format_ms(throughput.wall_ns),
486            format_bytes(throughput.input_bytes),
487            throughput.input_units,
488            throughput.mib_per_second_milli as f64 / 1_000.0,
489            throughput.units_per_second_milli as f64 / 1_000.0,
490            format_ms(throughput.ns_per_unit),
491        ));
492
493        for phase in &throughput.phases {
494            out.push_str(&format!(
495                "  phase {:<10} wall={:>12} share={:>6} cpu={:>8} rss={:>10} -> {:<10} threads={}->{}{}\n",
496                phase_name(phase.state),
497                format_ms(phase.wall_ns),
498                format_percent_ppm(phase.share_ppm),
499                format_ratio(phase.speedup_milli),
500                format_bytes(phase.resident_start_bytes),
501                format_bytes(phase.resident_end_bytes),
502                phase.threads_start,
503                phase.threads_end,
504                if phase.serial { "  SERIAL" } else { "" },
505            ));
506        }
507
508        let memory = &self.memory;
509        let amplification = if small_input {
510            "n/a (input below 1 MiB)".to_owned()
511        } else {
512            format_ratio(memory.amplification_milli)
513        };
514        out.push_str(&format!(
515            "memory peak={} ({}) engine_init_floor={} input_driven={} amplification={amplification} per_scanner_thread={} threads={}\n",
516            format_bytes(memory.peak_resident_bytes),
517            memory.peak_source,
518            format_bytes(memory.engine_init_resident_bytes),
519            format_bytes(memory.input_driven_resident_bytes),
520            format_bytes(memory.resident_per_scanner_thread_bytes),
521            memory.scanner_threads,
522        ));
523        if memory.allocated_bytes != 0 {
524            out.push_str(&format!(
525                "  allocator allocations={} allocated={} freed={} peak_live={} per_input_byte={}\n",
526                memory.allocations,
527                format_bytes(memory.allocated_bytes),
528                format_bytes(memory.deallocated_bytes),
529                format_bytes(memory.allocation_peak_live_bytes),
530                format_ratio(memory.allocated_per_input_byte_milli),
531            ));
532        }
533        for stage in memory.stages.iter().take(5) {
534            out.push_str(&format!(
535                "  owns {:<24} allocated={:>10} peak_live={:>10} allocations={}\n",
536                stage
537                    .metric_id
538                    .map_or("outside-any-span", crate::MetricId::as_str),
539                format_bytes(stage.allocated_bytes),
540                format_bytes(stage.peak_live_bytes),
541                stage.allocations,
542            ));
543        }
544
545        let parallel = &self.parallelism;
546        out.push_str(&format!(
547            "parallelism achieved={} of {} cpus (efficiency={}) ceiling={} workers={}/{} busy={} blocked={} idle={} ({})\n",
548            format_ratio(parallel.achieved_speedup_milli),
549            parallel.logical_cpus,
550            format_percent_ppm(parallel.parallel_efficiency_ppm),
551            format_ratio(parallel.speedup_ceiling_milli),
552            parallel.active_worker_count,
553            parallel.worker_count,
554            format_ms(parallel.instrumented_busy_ns),
555            format_ms(parallel.instrumented_blocked_ns),
556            format_ms(parallel.idle_ns),
557            format_percent_ppm(parallel.idle_share_ppm),
558        ));
559        out.push_str(&format!(
560            "  workers busiest={} median={} imbalance={} process_cpu={} in_span_off_cpu={} source_wait={} scanner_wait={}\n",
561            format_ms(parallel.busiest_busy_ns),
562            format_ms(parallel.median_busy_ns),
563            format_percent_ppm(parallel.imbalance_ppm),
564            format_ms(parallel.process_cpu_ns),
565            format_ms(parallel.busy_off_cpu_ns),
566            format_ms(parallel.source_blocked_ns),
567            format_ms(parallel.scanner_blocked_ns),
568        ));
569        for queue in &parallel.queues {
570            out.push_str(&format!(
571                "  queue {:?} high_water={} enqueued={} dequeued={}\n",
572                queue.queue, queue.high_water, queue.enqueues, queue.dequeues,
573            ));
574        }
575
576        for region in self.serial_regions.iter().take(8) {
577            out.push_str(&format!(
578                "serial {:<6} {:<22} wall={:>12} share={:>6} concurrency={} exclusivity={} workers={}{}\n",
579                match region.scope {
580                    SerialScopeV2::Phase => "phase",
581                    SerialScopeV2::Stage => "stage",
582                },
583                region.subject,
584                format_ms(region.wall_ns),
585                format_percent_ppm(region.share_ppm),
586                format_ratio(region.concurrency_milli),
587                format_percent_ppm(region.exclusivity_ppm),
588                region.worker_count,
589                if region.declared { " declared" } else { "" },
590            ));
591        }
592
593        for stage in self.stages.iter().take(8) {
594            out.push_str(&format!(
595                "cost {:<24} total={:>12} share={:>6} calls={:<9} per_call={:>10} per_file={:>10} concurrency={}\n",
596                stage.metric_id.as_str(),
597                format_ms(stage.elapsed_ns),
598                format_percent_ppm(stage.share_of_recorded_ppm),
599                stage.calls,
600                format_ms(stage.ns_per_call),
601                format_ms(stage.ns_per_input_unit),
602                format_ratio(stage.concurrency_milli),
603            ));
604        }
605
606        for backend in &self.backends {
607            out.push_str(&format!(
608                "backend {:<16} batches={} recovered={} share={}\n",
609                backend.backend,
610                backend.batches,
611                backend.recovered_batches,
612                format_percent_ppm(backend.share_ppm),
613            ));
614        }
615
616        for record in &self.retries {
617            out.push_str(&format!(
618                "retry {:<24} attempts={}\n",
619                record.cause.as_str(),
620                record.attempts,
621            ));
622        }
623
624        for cache in &self.caches {
625            out.push_str(&format!(
626                "cache {:<24} hits={} misses={} hit_rate={}\n",
627                cache.cache.as_str(),
628                cache.hits,
629                cache.misses,
630                format_percent_ppm(cache.hit_rate_ppm),
631            ));
632        }
633
634        for note in &self.coverage.notes {
635            out.push_str(&format!("gap {note}\n"));
636        }
637        out
638    }
639}
640
641fn phase_name(state: RunState) -> &'static str {
642    match state {
643        RunState::Created => "created",
644        RunState::Acquiring => "acquiring",
645        RunState::Scanning => "scanning",
646        RunState::Resolving => "resolving",
647        RunState::Verifying => "verifying",
648        RunState::Reporting => "reporting",
649        RunState::Completed => "completed",
650        RunState::Failed => "failed",
651    }
652}
653
654fn process_cpu_ns(profile: &CausalProfileV2) -> u64 {
655    let start = profile.resources.start.cpu_time_ms.unwrap_or_default();
656    let finish = profile.resources.finish.cpu_time_ms.unwrap_or_default();
657    finish.saturating_sub(start).saturating_mul(1_000_000)
658}
659
660fn derive_phases(
661    profile: &CausalProfileV2,
662    wall_ns: u64,
663    input_bytes: u64,
664    input_units: u64,
665) -> Vec<PhaseInsightV2> {
666    profile
667        .states
668        .iter()
669        .map(|state: &StateMeasurement| {
670            let cpu_ns = state
671                .cpu_time_ms
672                .unwrap_or_default()
673                .saturating_mul(1_000_000);
674            let speedup_milli = milli(cpu_ns, state.elapsed_ns);
675            // Only the scanning phases can be parallel; naming a single
676            // threaded startup "serial" is noise, not a finding.
677            let parallel_capable = matches!(
678                state.state,
679                RunState::Acquiring | RunState::Scanning | RunState::Verifying
680            );
681            PhaseInsightV2 {
682                version: RUN_INSIGHT_V2_VERSION,
683                state: state.state,
684                wall_ns: state.elapsed_ns,
685                share_ppm: ppm(state.elapsed_ns, wall_ns),
686                cpu_ns,
687                speedup_milli,
688                serial: parallel_capable
689                    && speedup_milli < SERIAL_CONCURRENCY_MILLI
690                    && ppm(state.elapsed_ns, wall_ns) >= SERIAL_REPORT_SHARE_PPM,
691                mib_per_second_milli: mib_per_second_milli(input_bytes, state.elapsed_ns),
692                units_per_second_milli: per_second_milli(input_units, state.elapsed_ns),
693                resident_start_bytes: state.resident_start_bytes.unwrap_or_default(),
694                resident_end_bytes: state.resident_end_bytes.unwrap_or_default(),
695                threads_start: state.threads_start.unwrap_or_default(),
696                threads_end: state.threads_end.unwrap_or_default(),
697            }
698        })
699        .collect()
700}
701
702fn derive_memory(
703    profile: &CausalProfileV2,
704    input_bytes: u64,
705    scanner_threads: u64,
706) -> MemoryInsightV2 {
707    let kernel_peak = match &profile.system {
708        Evidence::Recorded { value } => match &value.memory.resident_high_water_bytes.value {
709            Evidence::Recorded { value } => Some(*value),
710            Evidence::Unavailable { .. } => None,
711        },
712        Evidence::Unavailable { .. } => None,
713    };
714    let sampled_peak = profile.resources.max_observed_resident_bytes;
715    let (peak_resident_bytes, peak_source) = match (kernel_peak, sampled_peak) {
716        // The kernel high water covers the whole process lifetime including
717        // allocations that were freed before any boundary sample was taken.
718        (Some(kernel), sampled) => (kernel.max(sampled.unwrap_or(0)), "kernel-vmhwm"),
719        (None, Some(sampled)) => (sampled, "boundary-samples"),
720        (None, None) => (0, "unavailable"),
721    };
722
723    let baseline_resident_bytes = profile
724        .resources
725        .start
726        .resident_bytes
727        .or_else(|| {
728            profile
729                .states
730                .first()
731                .and_then(|state| state.resident_start_bytes)
732        })
733        .unwrap_or_default();
734    // Resident memory on entry to scanning is the engine-init floor: detectors
735    // compiled, matchers built, pool stood up, before a single input byte.
736    let engine_init_resident_bytes = profile
737        .states
738        .iter()
739        .find(|state| state.state == RunState::Scanning)
740        .and_then(|state| state.resident_start_bytes)
741        .or(Some(baseline_resident_bytes))
742        .unwrap_or_default();
743
744    let (allocations, allocated_bytes, deallocated_bytes, allocation_peak_live_bytes, stages) =
745        match &profile.system {
746            Evidence::Recorded { value } => {
747                let totals = match &value.allocation.totals {
748                    Evidence::Recorded { value } => (
749                        value.allocations,
750                        value.allocated_bytes,
751                        value.deallocated_bytes,
752                        value.peak_live_bytes,
753                    ),
754                    Evidence::Unavailable { .. } => (0, 0, 0, 0),
755                };
756                let mut stages: Vec<StageMemoryV2> = value
757                    .allocation
758                    .stages
759                    .iter()
760                    .filter(|stage| stage.allocated_bytes != 0 || stage.peak_live_bytes != 0)
761                    .map(|stage| StageMemoryV2 {
762                        version: RUN_INSIGHT_V2_VERSION,
763                        metric_id: stage.metric_id,
764                        allocations: stage.allocations,
765                        allocated_bytes: stage.allocated_bytes,
766                        live_bytes: stage.live_bytes,
767                        peak_live_bytes: stage.peak_live_bytes,
768                    })
769                    .collect();
770                stages.sort_by(|left, right| {
771                    right
772                        .allocated_bytes
773                        .cmp(&left.allocated_bytes)
774                        .then_with(|| left.metric_id.cmp(&right.metric_id))
775                });
776                (totals.0, totals.1, totals.2, totals.3, stages)
777            }
778            Evidence::Unavailable { .. } => (0, 0, 0, 0, Vec::new()),
779        };
780
781    let input_driven_resident_bytes =
782        peak_resident_bytes.saturating_sub(engine_init_resident_bytes);
783    MemoryInsightV2 {
784        version: RUN_INSIGHT_V2_VERSION,
785        peak_resident_bytes,
786        peak_source: peak_source.to_owned(),
787        baseline_resident_bytes,
788        engine_init_resident_bytes,
789        input_driven_resident_bytes,
790        input_bytes,
791        amplification_milli: milli(peak_resident_bytes, input_bytes),
792        scanner_threads,
793        resident_per_scanner_thread_bytes: peak_resident_bytes / scanner_threads.max(1),
794        input_driven_per_scanner_thread_bytes: input_driven_resident_bytes / scanner_threads.max(1),
795        allocations,
796        allocated_bytes,
797        deallocated_bytes,
798        allocation_peak_live_bytes,
799        allocated_per_input_byte_milli: milli(allocated_bytes, input_bytes),
800        stages,
801    }
802}
803
804/// Work recorded by every other micro-function while `subject` was open.
805///
806/// Each stage's time is spread evenly over its own window, so overlapping a
807/// fraction of that window charges that fraction of its time. This is what
808/// separates a real barrier from an inclusive wrapper: a wrapper's children
809/// run inside its window, so the wrapper scores low.
810fn overlapping_work_ns(
811    stages: &[crate::schema_v2::StageConcurrencyV2],
812    subject: &crate::schema_v2::StageConcurrencyV2,
813) -> u64 {
814    stages
815        .iter()
816        .filter(|other| other.metric_id != subject.metric_id && other.window_ns != 0)
817        .fold(0_u64, |total, other| {
818            let start = other.first_start_ns.max(subject.first_start_ns);
819            let end = other.last_end_ns.min(subject.last_end_ns);
820            let Some(overlap) = end.checked_sub(start) else {
821                return total;
822            };
823            // Weight by the capped concurrency, not raw elapsed, so a stage
824            // entered recursively on one thread cannot drown out a barrier it
825            // sits inside.
826            let density_milli = other.concurrency_milli;
827            let share = u64::try_from((u128::from(density_milli) * u128::from(overlap)) / 1_000)
828                .unwrap_or(u64::MAX);
829            total.saturating_add(share)
830        })
831}
832
833fn derive_serial(
834    profile: &CausalProfileV2,
835    phases: &[PhaseInsightV2],
836    wall_ns: u64,
837) -> (Vec<SerialRegionV2>, u64) {
838    let mut regions: Vec<SerialRegionV2> = phases
839        .iter()
840        .filter(|phase| phase.serial && phase.wall_ns != 0)
841        .map(|phase| SerialRegionV2 {
842            version: RUN_INSIGHT_V2_VERSION,
843            scope: SerialScopeV2::Phase,
844            subject: phase_name(phase.state).to_owned(),
845            wall_ns: phase.wall_ns,
846            share_ppm: phase.share_ppm,
847            concurrency_milli: phase.speedup_milli,
848            worker_count: 1,
849            // A macro phase is measured by process CPU over its own wall, so
850            // it already accounts for everything running at the time.
851            exclusivity_ppm: 1_000_000,
852            declared: false,
853        })
854        .collect();
855    // A phase's serial wall time is the wall time no extra thread can remove.
856    let serial_wall_ns = regions
857        .iter()
858        .fold(0_u64, |total, region| total.saturating_add(region.wall_ns));
859
860    regions.extend(profile.stage_concurrency.iter().filter_map(|stage| {
861        if stage.window_ns == 0 {
862            return None;
863        }
864        let share_ppm = ppm(stage.window_ns, wall_ns);
865        if share_ppm < SERIAL_REPORT_SHARE_PPM {
866            return None;
867        }
868        let other_ns = overlapping_work_ns(&profile.stage_concurrency, stage);
869        let own_ns = u64::try_from(
870            (u128::from(stage.concurrency_milli) * u128::from(stage.window_ns)) / 1_000,
871        )
872        .unwrap_or(u64::MAX);
873        let exclusivity_ppm = ppm(own_ns, own_ns.saturating_add(other_ns));
874        // Three conditions, and all three are needed. Concurrency near
875        // one rules out a sparse stage that merely spans a long window.
876        // Exclusivity rules out an inclusive wrapper whose children are
877        // the parallel work. A declaration overrides both because the
878        // caller knows something the aggregates cannot show.
879        let looks_serial = stage.concurrency_milli >= SERIAL_FLOOR_MILLI
880            && stage.concurrency_milli < SERIAL_CONCURRENCY_MILLI
881            && exclusivity_ppm >= SERIAL_EXCLUSIVITY_PPM;
882        if !looks_serial && stage.declared_serial_calls == 0 {
883            return None;
884        }
885        Some(SerialRegionV2 {
886            version: RUN_INSIGHT_V2_VERSION,
887            scope: SerialScopeV2::Stage,
888            subject: stage.metric_id.as_str().to_owned(),
889            wall_ns: stage.window_ns,
890            share_ppm,
891            concurrency_milli: stage.concurrency_milli,
892            worker_count: stage.worker_count,
893            exclusivity_ppm,
894            declared: stage.declared_serial_calls != 0,
895        })
896    }));
897    regions.sort_by(|left, right| {
898        right
899            .wall_ns
900            .cmp(&left.wall_ns)
901            .then_with(|| left.subject.cmp(&right.subject))
902    });
903    (regions, serial_wall_ns)
904}
905
906fn derive_parallelism(
907    profile: &CausalProfileV2,
908    wall_ns: u64,
909    process_cpu_ns: u64,
910    logical_cpus: u64,
911    scanner_threads: u64,
912    serial_wall_ns: u64,
913) -> ParallelismInsightV2 {
914    let occupancy = profile.worker_occupancy.as_ref();
915    let worker_count = occupancy.map_or(0, |occupancy| occupancy.worker_count);
916    let instrumented_busy_ns = occupancy.map_or(0, |occupancy| occupancy.busy_ns);
917    let instrumented_blocked_ns = occupancy.map_or(0, |occupancy| occupancy.blocked_ns);
918    let worker_capacity_ns = wall_ns.saturating_mul(worker_count);
919    let idle_ns = worker_capacity_ns
920        .saturating_sub(instrumented_busy_ns)
921        .saturating_sub(instrumented_blocked_ns);
922    let busiest_busy_ns = occupancy.map_or(0, |occupancy| occupancy.busiest_busy_ns);
923    let median_busy_ns = occupancy.map_or(0, |occupancy| occupancy.median_busy_ns);
924
925    let blocked_ns_for = |metric: MetricId| -> u64 {
926        profile
927            .blocked_waits
928            .iter()
929            .find(|record| record.metric_id == metric)
930            .map_or(0, |record| record.blocked_ns)
931    };
932
933    // Amdahl: with a serial part that no thread count removes, the ceiling is
934    // wall over serial. A run with no measured serial part is unbounded here,
935    // which we report as the logical CPU count rather than infinity.
936    let speedup_ceiling_milli = if serial_wall_ns == 0 {
937        logical_cpus.saturating_mul(1_000)
938    } else {
939        milli(wall_ns, serial_wall_ns)
940    };
941
942    ParallelismInsightV2 {
943        version: RUN_INSIGHT_V2_VERSION,
944        logical_cpus,
945        scanner_threads,
946        wall_ns,
947        process_cpu_ns,
948        achieved_speedup_milli: milli(process_cpu_ns, wall_ns),
949        parallel_efficiency_ppm: ppm(process_cpu_ns, wall_ns.saturating_mul(logical_cpus)),
950        speedup_ceiling_milli,
951        worker_count,
952        active_worker_count: occupancy.map_or(0, |occupancy| occupancy.active_worker_count),
953        instrumented_busy_ns,
954        instrumented_blocked_ns,
955        worker_capacity_ns,
956        idle_ns,
957        idle_share_ppm: ppm(idle_ns, worker_capacity_ns),
958        busiest_busy_ns,
959        median_busy_ns,
960        imbalance_ppm: ppm(
961            busiest_busy_ns.saturating_sub(median_busy_ns),
962            busiest_busy_ns,
963        ),
964        busy_off_cpu_ns: instrumented_busy_ns.saturating_sub(process_cpu_ns),
965        source_blocked_ns: blocked_ns_for(MetricId::SourceQueueWait),
966        scanner_blocked_ns: blocked_ns_for(MetricId::ScannerQueueWait),
967        queues: profile.queue_depths.clone(),
968    }
969}
970
971fn derive_stages(
972    profile: &CausalProfileV2,
973    input_bytes: u64,
974    input_units: u64,
975) -> Vec<StageAttributionV2> {
976    let recorded_ns = profile
977        .stages
978        .iter()
979        .fold(0_u64, |total, stage| total.saturating_add(stage.elapsed_ns));
980    let mut rows: Vec<StageAttributionV2> = profile
981        .stages
982        .iter()
983        .filter(|stage| stage.calls != 0)
984        .map(|stage| {
985            let concurrency = profile
986                .stage_concurrency
987                .iter()
988                .find(|record| record.metric_id == stage.stage.metric_id());
989            let bytes = concurrency.map_or(0, |record| record.bytes);
990            StageAttributionV2 {
991                version: RUN_INSIGHT_V2_VERSION,
992                metric_id: stage.stage.metric_id(),
993                macro_stage_id: stage.stage.macro_stage_id(),
994                calls: stage.calls,
995                elapsed_ns: stage.elapsed_ns,
996                share_of_recorded_ppm: ppm(stage.elapsed_ns, recorded_ns),
997                ns_per_call: stage.elapsed_ns / stage.calls.max(1),
998                ns_per_input_unit: if input_units == 0 {
999                    0
1000                } else {
1001                    stage.elapsed_ns / input_units
1002                },
1003                ns_per_input_byte_milli: milli(stage.elapsed_ns, input_bytes),
1004                bytes,
1005                mib_per_second_milli: mib_per_second_milli(
1006                    bytes,
1007                    concurrency.map_or(0, |record| record.window_ns),
1008                ),
1009                concurrency_milli: concurrency.map_or(0, |record| record.concurrency_milli),
1010                worker_count: concurrency.map_or(0, |record| record.worker_count),
1011            }
1012        })
1013        .collect();
1014    rows.sort_by(|left, right| {
1015        right
1016            .elapsed_ns
1017            .cmp(&left.elapsed_ns)
1018            .then_with(|| left.metric_id.cmp(&right.metric_id))
1019    });
1020    rows
1021}
1022
1023fn derive_backends(profile: &CausalProfileV2) -> Vec<BackendAttributionV2> {
1024    let mut totals: Vec<(String, u64, u64)> = Vec::new();
1025    for batch in &profile.identity.route.batches {
1026        let recovered = u64::from(matches!(
1027            batch.recovered_from_backend,
1028            Evidence::Recorded { .. }
1029        ));
1030        match totals
1031            .iter_mut()
1032            .find(|(backend, _, _)| backend == &batch.completed_backend)
1033        {
1034            Some(entry) => {
1035                entry.1 += 1;
1036                entry.2 += recovered;
1037            }
1038            None => totals.push((batch.completed_backend.clone(), 1, recovered)),
1039        }
1040    }
1041    let batch_total = totals.iter().fold(0_u64, |total, entry| total + entry.1);
1042    let mut rows: Vec<BackendAttributionV2> = totals
1043        .into_iter()
1044        .map(
1045            |(backend, batches, recovered_batches)| BackendAttributionV2 {
1046                version: RUN_INSIGHT_V2_VERSION,
1047                backend,
1048                batches,
1049                recovered_batches,
1050                share_ppm: ppm(batches, batch_total),
1051            },
1052        )
1053        .collect();
1054    rows.sort_by(|left, right| {
1055        right
1056            .batches
1057            .cmp(&left.batches)
1058            .then_with(|| left.backend.cmp(&right.backend))
1059    });
1060    rows
1061}
1062
1063fn derive_coverage(
1064    profile: &CausalProfileV2,
1065    memory: &MemoryInsightV2,
1066    parallelism: &ParallelismInsightV2,
1067) -> InsightCoverageV2 {
1068    let mut notes = Vec::new();
1069    let process_metrics = memory.peak_resident_bytes != 0;
1070    if !process_metrics {
1071        notes.push(
1072            "resident memory is unavailable, so every memory conclusion is missing".to_owned(),
1073        );
1074    }
1075    let allocation_tracking = memory.allocated_bytes != 0;
1076    if !allocation_tracking {
1077        notes.push(
1078            "the tracking allocator is not installed, so allocation volume and per-stage ownership are absent"
1079                .to_owned(),
1080        );
1081    }
1082    let stage_concurrency = !profile.stage_concurrency.is_empty();
1083    if !stage_concurrency {
1084        notes.push(
1085            "no micro-function recorded a span, so serial detection falls back to phase CPU ratios"
1086                .to_owned(),
1087        );
1088    }
1089    let worker_occupancy = parallelism.worker_count != 0;
1090    if !worker_occupancy {
1091        notes.push("no worker shard registered, so busy versus idle time is absent".to_owned());
1092    }
1093    if parallelism.process_cpu_ns == 0 {
1094        notes.push(
1095            "process CPU time is unavailable, so achieved speedup cannot be computed".to_owned(),
1096        );
1097    }
1098    if profile.events.dropped_span_events != 0 {
1099        notes.push(format!(
1100            "{} span records were dropped for capacity; aggregate counters remain exact",
1101            profile.events.dropped_span_events
1102        ));
1103    }
1104    InsightCoverageV2 {
1105        version: RUN_INSIGHT_V2_VERSION,
1106        process_metrics,
1107        allocation_tracking,
1108        stage_concurrency,
1109        worker_occupancy,
1110        dropped_span_events: profile.events.dropped_span_events,
1111        notes,
1112    }
1113}
1114
1115fn finding(
1116    kind: BottleneckKindV2,
1117    severity: u8,
1118    impact_ns: u64,
1119    wall_ns: u64,
1120    subject: impl Into<String>,
1121    statement: impl Into<String>,
1122) -> FindingV2 {
1123    FindingV2 {
1124        version: RUN_INSIGHT_V2_VERSION,
1125        kind,
1126        severity,
1127        impact_ns,
1128        impact_share_ppm: ppm(impact_ns, wall_ns),
1129        subject: subject.into(),
1130        statement: statement.into(),
1131    }
1132}
1133
1134fn rank_findings(
1135    wall_ns: u64,
1136    throughput: &ThroughputInsightV2,
1137    memory: &MemoryInsightV2,
1138    parallelism: &ParallelismInsightV2,
1139    serial_regions: &[SerialRegionV2],
1140    stages: &[StageAttributionV2],
1141    caches: &[CacheEffectivenessV2],
1142    retries: &[RetryRecordV2],
1143) -> Vec<FindingV2> {
1144    let mut findings = Vec::new();
1145
1146    for region in serial_regions
1147        .iter()
1148        .filter(|region| region.share_ppm >= MATERIAL_SHARE_PPM)
1149        .take(3)
1150    {
1151        findings.push(finding(
1152            BottleneckKindV2::SerialPhase,
1153            if region.share_ppm >= 250_000 { 3 } else { 2 },
1154            region.wall_ns,
1155            wall_ns,
1156            region.subject.clone(),
1157            format!(
1158                "{} is a serial barrier: {} of wall ({}) at {} workers, and no extra thread removes it",
1159                region.subject,
1160                format_ms(region.wall_ns),
1161                format_percent_ppm(region.share_ppm),
1162                format_ratio(region.concurrency_milli),
1163            ),
1164        ));
1165    }
1166
1167    if parallelism.logical_cpus > 1 && parallelism.process_cpu_ns != 0 {
1168        let half_the_box = parallelism.logical_cpus.saturating_mul(500);
1169        if parallelism.achieved_speedup_milli < half_the_box {
1170            findings.push(finding(
1171                BottleneckKindV2::ParallelStarvation,
1172                if parallelism.parallel_efficiency_ppm < 250_000 {
1173                    3
1174                } else {
1175                    2
1176                },
1177                wall_ns.saturating_sub(
1178                    parallelism
1179                        .process_cpu_ns
1180                        .checked_div(parallelism.logical_cpus)
1181                        .unwrap_or(wall_ns),
1182                ),
1183                wall_ns,
1184                "worker-pool",
1185                format!(
1186                    "the run reached {} of {} logical CPUs ({} efficiency); {} of CPU time ran in {} of wall, and the Amdahl ceiling from measured serial work is {}",
1187                    format_ratio(parallelism.achieved_speedup_milli),
1188                    parallelism.logical_cpus,
1189                    format_percent_ppm(parallelism.parallel_efficiency_ppm),
1190                    format_ms(parallelism.process_cpu_ns),
1191                    format_ms(wall_ns),
1192                    format_ratio(parallelism.speedup_ceiling_milli),
1193                ),
1194            ));
1195        }
1196    }
1197
1198    if parallelism.instrumented_blocked_ns > parallelism.instrumented_busy_ns
1199        && parallelism.instrumented_blocked_ns != 0
1200    {
1201        findings.push(finding(
1202            BottleneckKindV2::QueueStarvation,
1203            2,
1204            parallelism.instrumented_blocked_ns,
1205            wall_ns,
1206            "source-queue",
1207            format!(
1208                "workers spent {} blocked against {} busy; the source side is not feeding the pool",
1209                format_ms(parallelism.instrumented_blocked_ns),
1210                format_ms(parallelism.instrumented_busy_ns),
1211            ),
1212        ));
1213    }
1214
1215    if memory.peak_resident_bytes >= MEMORY_FLOOR_BYTES
1216        && memory.engine_init_resident_bytes.saturating_mul(2) >= memory.peak_resident_bytes
1217    {
1218        findings.push(finding(
1219            BottleneckKindV2::MemoryFloor,
1220            if memory.input_bytes < 1_048_576 { 3 } else { 1 },
1221            0,
1222            wall_ns,
1223            "engine-init",
1224            format!(
1225                "{} of the {} peak is standing the engine up, not the input: {} of input produced only {} of extra resident memory",
1226                format_bytes(memory.engine_init_resident_bytes),
1227                format_bytes(memory.peak_resident_bytes),
1228                format_bytes(memory.input_bytes),
1229                format_bytes(memory.input_driven_resident_bytes),
1230            ),
1231        ));
1232    }
1233
1234    if memory.input_bytes >= MEMORY_FLOOR_BYTES && memory.amplification_milli >= AMPLIFICATION_MILLI
1235    {
1236        findings.push(finding(
1237            BottleneckKindV2::MemoryAmplification,
1238            2,
1239            0,
1240            wall_ns,
1241            "resident-amplification",
1242            format!(
1243                "peak resident is {} of the input: {} held for {}",
1244                format_ratio(memory.amplification_milli),
1245                format_bytes(memory.peak_resident_bytes),
1246                format_bytes(memory.input_bytes),
1247            ),
1248        ));
1249    }
1250
1251    for cache in caches
1252        .iter()
1253        .filter(|cache| cache.hit_rate_ppm < 500_000 && cache.misses >= 8)
1254    {
1255        findings.push(finding(
1256            BottleneckKindV2::CacheMiss,
1257            1,
1258            0,
1259            wall_ns,
1260            cache.cache.as_str(),
1261            format!(
1262                "{} served {} of {} lookups ({}); every miss pays the full cost again",
1263                cache.cache.as_str(),
1264                cache.hits,
1265                cache.hits.saturating_add(cache.misses),
1266                format_percent_ppm(cache.hit_rate_ppm),
1267            ),
1268        ));
1269    }
1270
1271    let retry_attempts = retries
1272        .iter()
1273        .fold(0_u64, |total, record| total.saturating_add(record.attempts));
1274    if retry_attempts != 0 {
1275        let worst = retries
1276            .iter()
1277            .max_by_key(|record| record.attempts)
1278            .expect("a nonzero total implies at least one record");
1279        findings.push(finding(
1280            BottleneckKindV2::RetriedWork,
1281            2,
1282            0,
1283            wall_ns,
1284            worst.cause.as_str(),
1285            format!(
1286                "{retry_attempts} operations were attempted again, {} of them for {}; a retry that fires is a failure that was not designed out",
1287                worst.attempts,
1288                worst.cause.as_str(),
1289            ),
1290        ));
1291    }
1292
1293    let scanning_ns = throughput
1294        .phases
1295        .iter()
1296        .filter(|phase| phase.state == RunState::Scanning)
1297        .fold(0_u64, |total, phase| total.saturating_add(phase.wall_ns));
1298    let non_scanning_ns = wall_ns.saturating_sub(scanning_ns);
1299    if scanning_ns != 0 && non_scanning_ns > scanning_ns {
1300        findings.push(finding(
1301            BottleneckKindV2::FixedOverhead,
1302            2,
1303            non_scanning_ns,
1304            wall_ns,
1305            "outside-scanning",
1306            format!(
1307                "{} of {} wall ran outside scanning; scanning itself took {}",
1308                format_ms(non_scanning_ns),
1309                format_ms(wall_ns),
1310                format_ms(scanning_ns),
1311            ),
1312        ));
1313    }
1314
1315    if let Some(stage) = stages.first() {
1316        if stage.share_of_recorded_ppm >= 400_000 && stage.concurrency_milli != 0 {
1317            findings.push(finding(
1318                BottleneckKindV2::StageBound,
1319                1,
1320                stage.elapsed_ns,
1321                wall_ns,
1322                stage.metric_id.as_str(),
1323                format!(
1324                    "{} holds {} of recorded stage time across {} calls at {} per call",
1325                    stage.metric_id.as_str(),
1326                    format_percent_ppm(stage.share_of_recorded_ppm),
1327                    stage.calls,
1328                    format_ms(stage.ns_per_call),
1329                ),
1330            ));
1331        }
1332    }
1333
1334    if findings.is_empty() {
1335        findings.push(finding(
1336            BottleneckKindV2::Insufficient,
1337            0,
1338            wall_ns,
1339            wall_ns,
1340            "run",
1341            format!(
1342                "no phase, worker, cache, or memory measurement crossed a reporting threshold in {}",
1343                format_ms(wall_ns)
1344            ),
1345        ));
1346    }
1347
1348    findings.sort_by(|left, right| {
1349        right
1350            .severity
1351            .cmp(&left.severity)
1352            .then_with(|| right.impact_ns.cmp(&left.impact_ns))
1353            .then_with(|| left.subject.cmp(&right.subject))
1354    });
1355    // Three nested serial regions are one conclusion, not three. Keep the
1356    // largest of each kind here; the sections below carry the full lists.
1357    let mut seen: Vec<BottleneckKindV2> = Vec::with_capacity(findings.len());
1358    findings.retain(|finding| {
1359        if seen.contains(&finding.kind) {
1360            return false;
1361        }
1362        seen.push(finding.kind);
1363        true
1364    });
1365    findings
1366}