pi/
session_metrics.rs

1//! Session hot-path observability.
2//!
3//! Thread-safe atomic counters and timing for save/append/serialize/IO
4//! operations. Gated behind `PI_PERF_TELEMETRY=1` for zero overhead in
5//! production: when disabled, all recording methods are instant no-ops.
6//!
7//! ## Design
8//!
9//! - [`TimingCounter`]: atomic count + total microseconds + max microseconds.
10//! - [`ByteCounter`]: atomic count + total bytes.
11//! - [`SessionMetrics`]: composes counters for every instrumented phase.
12//! - [`ScopedTimer`]: RAII guard that records elapsed time on drop.
13//! - [`global()`]: returns `&'static SessionMetrics` (lazy-initialized once).
14//!
15//! ## Integration points
16//!
17//! Currently instrumented (files owned by this bead):
18//! - `session_sqlite.rs`: save, load, metadata load
19//! - `session_index.rs`: lock acquisition, upsert, list, reindex
20//!
21//! Future instrumentation (requires session.rs access):
22//! - `Session::save()` JSONL path: queue wait, serialization, IO, persist
23//! - `Session::append_*()`: in-memory append timing
24
25use std::sync::OnceLock;
26use std::sync::atomic::{AtomicBool, AtomicU64, Ordering};
27use std::time::Instant;
28
29// ---------------------------------------------------------------------------
30// TimingCounter
31// ---------------------------------------------------------------------------
32
33/// Atomic counter that tracks invocation count, cumulative time (µs), and
34/// peak time (µs) for a single instrumented phase.
35///
36/// All operations use `Relaxed` ordering because we tolerate slightly stale
37/// reads in exchange for zero contention. The counters are append-only
38/// (monotonically increasing), so torn reads cannot produce logically
39/// inconsistent results.
40#[derive(Debug)]
41pub struct TimingCounter {
42    count: AtomicU64,
43    total_us: AtomicU64,
44    max_us: AtomicU64,
45}
46
47impl TimingCounter {
48    const fn new() -> Self {
49        Self {
50            count: AtomicU64::new(0),
51            total_us: AtomicU64::new(0),
52            max_us: AtomicU64::new(0),
53        }
54    }
55
56    /// Record one observation of `elapsed_us` microseconds.
57    #[inline]
58    pub fn record(&self, elapsed_us: u64) {
59        self.count.fetch_add(1, Ordering::Relaxed);
60        self.total_us.fetch_add(elapsed_us, Ordering::Relaxed);
61        // Relaxed CAS loop for max — bounded to one retry on contention.
62        let mut current = self.max_us.load(Ordering::Relaxed);
63        while elapsed_us > current {
64            match self.max_us.compare_exchange_weak(
65                current,
66                elapsed_us,
67                Ordering::Relaxed,
68                Ordering::Relaxed,
69            ) {
70                Ok(_) => break,
71                Err(actual) => current = actual,
72            }
73        }
74    }
75
76    /// Snapshot the current counters.
77    pub fn snapshot(&self) -> TimingSnapshot {
78        let count = self.count.load(Ordering::Relaxed);
79        let total_us = self.total_us.load(Ordering::Relaxed);
80        let max_us = self.max_us.load(Ordering::Relaxed);
81        TimingSnapshot {
82            count,
83            total_us,
84            max_us,
85            avg_us: total_us.checked_div(count).unwrap_or(0),
86        }
87    }
88
89    /// Reset all counters to zero.
90    pub fn reset(&self) {
91        self.count.store(0, Ordering::Relaxed);
92        self.total_us.store(0, Ordering::Relaxed);
93        self.max_us.store(0, Ordering::Relaxed);
94    }
95}
96
97/// Point-in-time snapshot of a [`TimingCounter`].
98#[derive(Debug, Clone, Copy, PartialEq, Eq)]
99pub struct TimingSnapshot {
100    pub count: u64,
101    pub total_us: u64,
102    pub max_us: u64,
103    pub avg_us: u64,
104}
105
106impl std::fmt::Display for TimingSnapshot {
107    #[allow(clippy::cast_precision_loss)]
108    fn fmt(&self, f: &mut std::fmt::Formatter<'_>) -> std::fmt::Result {
109        if self.count == 0 {
110            write!(f, "n=0")
111        } else {
112            write!(
113                f,
114                "n={} avg={:.1}ms max={:.1}ms total={:.1}ms",
115                self.count,
116                self.avg_us as f64 / 1000.0,
117                self.max_us as f64 / 1000.0,
118                self.total_us as f64 / 1000.0,
119            )
120        }
121    }
122}
123
124// ---------------------------------------------------------------------------
125// ByteCounter
126// ---------------------------------------------------------------------------
127
128/// Atomic counter for tracking bytes written/read.
129#[derive(Debug)]
130pub struct ByteCounter {
131    count: AtomicU64,
132    total_bytes: AtomicU64,
133}
134
135impl ByteCounter {
136    const fn new() -> Self {
137        Self {
138            count: AtomicU64::new(0),
139            total_bytes: AtomicU64::new(0),
140        }
141    }
142
143    /// Record one observation of `bytes` bytes.
144    #[inline]
145    pub fn record(&self, bytes: u64) {
146        self.count.fetch_add(1, Ordering::Relaxed);
147        self.total_bytes.fetch_add(bytes, Ordering::Relaxed);
148    }
149
150    /// Snapshot the current counters.
151    pub fn snapshot(&self) -> ByteSnapshot {
152        let count = self.count.load(Ordering::Relaxed);
153        let total_bytes = self.total_bytes.load(Ordering::Relaxed);
154        ByteSnapshot {
155            count,
156            total_bytes,
157            avg_bytes: total_bytes.checked_div(count).unwrap_or(0),
158        }
159    }
160
161    /// Reset all counters to zero.
162    pub fn reset(&self) {
163        self.count.store(0, Ordering::Relaxed);
164        self.total_bytes.store(0, Ordering::Relaxed);
165    }
166}
167
168/// Point-in-time snapshot of a [`ByteCounter`].
169#[derive(Debug, Clone, Copy, PartialEq, Eq)]
170pub struct ByteSnapshot {
171    pub count: u64,
172    pub total_bytes: u64,
173    pub avg_bytes: u64,
174}
175
176impl std::fmt::Display for ByteSnapshot {
177    fn fmt(&self, f: &mut std::fmt::Formatter<'_>) -> std::fmt::Result {
178        if self.count == 0 {
179            write!(f, "n=0")
180        } else {
181            write!(
182                f,
183                "n={} avg={}B total={}B",
184                self.count, self.avg_bytes, self.total_bytes,
185            )
186        }
187    }
188}
189
190// ---------------------------------------------------------------------------
191// SessionMetrics
192// ---------------------------------------------------------------------------
193
194/// Centralized session hot-path metrics collector.
195///
196/// Covers four key phases identified in the PERF-3X measurement plan:
197/// 1. **Queueing**: time between save request and actual IO start
198/// 2. **Serialization**: `serde_json` encoding time and output size
199/// 3. **IO / Fsync**: file write, flush, and atomic-rename time
200/// 4. **Index update**: session-index upsert time
201///
202/// Plus additional breakdowns for SQLite paths and lock contention.
203pub struct SessionMetrics {
204    enabled: AtomicBool,
205
206    // -- JSONL save path (session.rs — future integration) --
207    /// Total wall-clock time for a complete `Session::save()` JSONL call.
208    pub jsonl_save: TimingCounter,
209    /// Time spent in `serde_json::to_writer` for header + entries.
210    pub jsonl_serialize: TimingCounter,
211    /// Time spent in `BufWriter::flush()` + `tempfile::persist()`.
212    pub jsonl_io: TimingCounter,
213    /// Bytes written per JSONL save (header + entries).
214    pub jsonl_bytes: ByteCounter,
215    /// Queue wait: time from `save()` entry to IO thread start.
216    pub jsonl_queue_wait: TimingCounter,
217
218    // -- SQLite save path (session_sqlite.rs) --
219    /// Total wall-clock time for `save_session()` (full rewrite).
220    pub sqlite_save: TimingCounter,
221    /// Total wall-clock time for `append_entries()` (incremental append).
222    pub sqlite_append: TimingCounter,
223    /// Time spent serializing entries to JSON strings within SQLite save.
224    pub sqlite_serialize: TimingCounter,
225    /// Total JSON bytes produced during SQLite save serialization.
226    pub sqlite_bytes: ByteCounter,
227
228    // -- SQLite load path (session_sqlite.rs) --
229    /// Total wall-clock time for `load_session()`.
230    pub sqlite_load: TimingCounter,
231    /// Total wall-clock time for `load_session_meta()`.
232    pub sqlite_load_meta: TimingCounter,
233
234    // -- Session index (session_index.rs) --
235    /// Lock acquisition time in `SessionIndex::with_lock()`.
236    pub index_lock: TimingCounter,
237    /// Total wall-clock time for `upsert_meta()` (including lock).
238    pub index_upsert: TimingCounter,
239    /// Total wall-clock time for `list_sessions()` (including lock).
240    pub index_list: TimingCounter,
241    /// Total wall-clock time for `reindex_all()`.
242    pub index_reindex: TimingCounter,
243
244    // -- In-memory append (session.rs — future integration) --
245    /// Time for `Session::append_message()` and similar in-memory ops.
246    pub append: TimingCounter,
247}
248
249impl SessionMetrics {
250    const fn new() -> Self {
251        Self {
252            enabled: AtomicBool::new(false),
253            jsonl_save: TimingCounter::new(),
254            jsonl_serialize: TimingCounter::new(),
255            jsonl_io: TimingCounter::new(),
256            jsonl_bytes: ByteCounter::new(),
257            jsonl_queue_wait: TimingCounter::new(),
258            sqlite_save: TimingCounter::new(),
259            sqlite_append: TimingCounter::new(),
260            sqlite_serialize: TimingCounter::new(),
261            sqlite_bytes: ByteCounter::new(),
262            sqlite_load: TimingCounter::new(),
263            sqlite_load_meta: TimingCounter::new(),
264            index_lock: TimingCounter::new(),
265            index_upsert: TimingCounter::new(),
266            index_list: TimingCounter::new(),
267            index_reindex: TimingCounter::new(),
268            append: TimingCounter::new(),
269        }
270    }
271
272    /// Whether metrics collection is active.
273    #[inline]
274    pub fn enabled(&self) -> bool {
275        self.enabled.load(Ordering::Relaxed)
276    }
277
278    /// Explicitly enable metrics (useful for tests).
279    pub fn enable(&self) {
280        self.enabled.store(true, Ordering::Relaxed);
281    }
282
283    /// Explicitly disable metrics.
284    pub fn disable(&self) {
285        self.enabled.store(false, Ordering::Relaxed);
286    }
287
288    /// Start a scoped timer for `counter`. If metrics are disabled, returns
289    /// a no-op timer that does nothing on drop.
290    #[inline]
291    pub fn start_timer<'a>(&'a self, counter: &'a TimingCounter) -> ScopedTimer<'a> {
292        if self.enabled() {
293            ScopedTimer {
294                counter: Some(counter),
295                start: Instant::now(),
296            }
297        } else {
298            ScopedTimer {
299                counter: None,
300                start: Instant::now(), // unused but cheap
301            }
302        }
303    }
304
305    /// Record bytes if metrics are enabled.
306    #[inline]
307    pub fn record_bytes(&self, counter: &ByteCounter, bytes: u64) {
308        if self.enabled() {
309            counter.record(bytes);
310        }
311    }
312
313    /// Reset all counters to zero.
314    pub fn reset_all(&self) {
315        self.jsonl_save.reset();
316        self.jsonl_serialize.reset();
317        self.jsonl_io.reset();
318        self.jsonl_bytes.reset();
319        self.jsonl_queue_wait.reset();
320        self.sqlite_save.reset();
321        self.sqlite_append.reset();
322        self.sqlite_serialize.reset();
323        self.sqlite_bytes.reset();
324        self.sqlite_load.reset();
325        self.sqlite_load_meta.reset();
326        self.index_lock.reset();
327        self.index_upsert.reset();
328        self.index_list.reset();
329        self.index_reindex.reset();
330        self.append.reset();
331    }
332
333    /// Produce a structured snapshot of all metrics.
334    pub fn snapshot(&self) -> MetricsSnapshot {
335        MetricsSnapshot {
336            enabled: self.enabled(),
337            jsonl_save: self.jsonl_save.snapshot(),
338            jsonl_serialize: self.jsonl_serialize.snapshot(),
339            jsonl_io: self.jsonl_io.snapshot(),
340            jsonl_bytes: self.jsonl_bytes.snapshot(),
341            jsonl_queue_wait: self.jsonl_queue_wait.snapshot(),
342            sqlite_save: self.sqlite_save.snapshot(),
343            sqlite_append: self.sqlite_append.snapshot(),
344            sqlite_serialize: self.sqlite_serialize.snapshot(),
345            sqlite_bytes: self.sqlite_bytes.snapshot(),
346            sqlite_load: self.sqlite_load.snapshot(),
347            sqlite_load_meta: self.sqlite_load_meta.snapshot(),
348            index_lock: self.index_lock.snapshot(),
349            index_upsert: self.index_upsert.snapshot(),
350            index_list: self.index_list.snapshot(),
351            index_reindex: self.index_reindex.snapshot(),
352            append: self.append.snapshot(),
353        }
354    }
355
356    /// Human-readable multi-line summary for diagnostics.
357    pub fn summary(&self) -> String {
358        if !self.enabled() {
359            return "Session telemetry disabled (set PI_PERF_TELEMETRY=1 to enable)".to_string();
360        }
361        let s = self.snapshot();
362        format!(
363            "Session hot-path metrics:\n  \
364             JSONL save:       {}\n  \
365             JSONL serialize:  {}\n  \
366             JSONL IO:         {}\n  \
367             JSONL bytes:      {}\n  \
368             JSONL queue wait: {}\n  \
369             SQLite save:      {}\n  \
370             SQLite append:    {}\n  \
371             SQLite serialize: {}\n  \
372             SQLite bytes:     {}\n  \
373             SQLite load:      {}\n  \
374             SQLite load meta: {}\n  \
375             Index lock:       {}\n  \
376             Index upsert:     {}\n  \
377             Index list:       {}\n  \
378             Index reindex:    {}\n  \
379             Append:           {}",
380            s.jsonl_save,
381            s.jsonl_serialize,
382            s.jsonl_io,
383            s.jsonl_bytes,
384            s.jsonl_queue_wait,
385            s.sqlite_save,
386            s.sqlite_append,
387            s.sqlite_serialize,
388            s.sqlite_bytes,
389            s.sqlite_load,
390            s.sqlite_load_meta,
391            s.index_lock,
392            s.index_upsert,
393            s.index_list,
394            s.index_reindex,
395            s.append,
396        )
397    }
398
399    /// Emit the summary to `tracing::debug` (called periodically or on demand).
400    pub fn emit(&self) {
401        if self.enabled() {
402            tracing::debug!("{}", self.summary());
403        }
404    }
405}
406
407// ---------------------------------------------------------------------------
408// MetricsSnapshot
409// ---------------------------------------------------------------------------
410
411/// Complete point-in-time snapshot of all session metrics.
412#[derive(Debug, Clone)]
413pub struct MetricsSnapshot {
414    pub enabled: bool,
415    pub jsonl_save: TimingSnapshot,
416    pub jsonl_serialize: TimingSnapshot,
417    pub jsonl_io: TimingSnapshot,
418    pub jsonl_bytes: ByteSnapshot,
419    pub jsonl_queue_wait: TimingSnapshot,
420    pub sqlite_save: TimingSnapshot,
421    pub sqlite_append: TimingSnapshot,
422    pub sqlite_serialize: TimingSnapshot,
423    pub sqlite_bytes: ByteSnapshot,
424    pub sqlite_load: TimingSnapshot,
425    pub sqlite_load_meta: TimingSnapshot,
426    pub index_lock: TimingSnapshot,
427    pub index_upsert: TimingSnapshot,
428    pub index_list: TimingSnapshot,
429    pub index_reindex: TimingSnapshot,
430    pub append: TimingSnapshot,
431}
432
433// ---------------------------------------------------------------------------
434// ScopedTimer
435// ---------------------------------------------------------------------------
436
437/// RAII timer that records elapsed microseconds into a [`TimingCounter`]
438/// when dropped. If `counter` is `None` (metrics disabled), drop is a no-op.
439pub struct ScopedTimer<'a> {
440    counter: Option<&'a TimingCounter>,
441    start: Instant,
442}
443
444impl ScopedTimer<'_> {
445    /// Manually finish the timer and return elapsed microseconds.
446    /// Consumes self so drop won't double-record.
447    #[allow(clippy::cast_possible_truncation)]
448    pub fn finish(self) -> u64 {
449        let elapsed_us = self.start.elapsed().as_micros().min(u128::from(u64::MAX)) as u64;
450        if let Some(counter) = self.counter {
451            counter.record(elapsed_us);
452        }
453        // Prevent drop from recording again.
454        std::mem::forget(self);
455        elapsed_us
456    }
457}
458
459impl Drop for ScopedTimer<'_> {
460    #[allow(clippy::cast_possible_truncation)]
461    fn drop(&mut self) {
462        if let Some(counter) = self.counter {
463            let elapsed_us = self.start.elapsed().as_micros().min(u128::from(u64::MAX)) as u64;
464            counter.record(elapsed_us);
465        }
466    }
467}
468
469// ---------------------------------------------------------------------------
470// Global accessor
471// ---------------------------------------------------------------------------
472
473static GLOBAL_METRICS: OnceLock<SessionMetrics> = OnceLock::new();
474
475/// Return the global `SessionMetrics` singleton.
476///
477/// On first call, reads `PI_PERF_TELEMETRY` to decide whether collection
478/// is enabled. The singleton lives for the process lifetime.
479pub fn global() -> &'static SessionMetrics {
480    GLOBAL_METRICS.get_or_init(|| {
481        let metrics = SessionMetrics::new();
482        let enabled =
483            std::env::var_os("PI_PERF_TELEMETRY").is_some_and(|v| v == "1" || v == "true");
484        if enabled {
485            metrics.enabled.store(true, Ordering::Relaxed);
486        }
487        metrics
488    })
489}
490
491// ---------------------------------------------------------------------------
492// Tests
493// ---------------------------------------------------------------------------
494
495#[cfg(test)]
496mod tests {
497    use super::*;
498
499    #[test]
500    fn timing_counter_starts_at_zero() {
501        let counter = TimingCounter::new();
502        let snap = counter.snapshot();
503        assert_eq!(snap.count, 0);
504        assert_eq!(snap.total_us, 0);
505        assert_eq!(snap.max_us, 0);
506        assert_eq!(snap.avg_us, 0);
507    }
508
509    #[test]
510    fn timing_counter_records_single_observation() {
511        let counter = TimingCounter::new();
512        counter.record(500);
513        let snap = counter.snapshot();
514        assert_eq!(snap.count, 1);
515        assert_eq!(snap.total_us, 500);
516        assert_eq!(snap.max_us, 500);
517        assert_eq!(snap.avg_us, 500);
518    }
519
520    #[test]
521    fn timing_counter_records_multiple_observations() {
522        let counter = TimingCounter::new();
523        counter.record(100);
524        counter.record(300);
525        counter.record(200);
526        let snap = counter.snapshot();
527        assert_eq!(snap.count, 3);
528        assert_eq!(snap.total_us, 600);
529        assert_eq!(snap.max_us, 300);
530        assert_eq!(snap.avg_us, 200);
531    }
532
533    #[test]
534    fn timing_counter_max_tracks_peak() {
535        let counter = TimingCounter::new();
536        counter.record(50);
537        counter.record(999);
538        counter.record(100);
539        assert_eq!(counter.snapshot().max_us, 999);
540    }
541
542    #[test]
543    fn timing_counter_reset_clears_all() {
544        let counter = TimingCounter::new();
545        counter.record(100);
546        counter.record(200);
547        counter.reset();
548        let snap = counter.snapshot();
549        assert_eq!(snap.count, 0);
550        assert_eq!(snap.total_us, 0);
551        assert_eq!(snap.max_us, 0);
552    }
553
554    #[test]
555    fn byte_counter_starts_at_zero() {
556        let counter = ByteCounter::new();
557        let snap = counter.snapshot();
558        assert_eq!(snap.count, 0);
559        assert_eq!(snap.total_bytes, 0);
560        assert_eq!(snap.avg_bytes, 0);
561    }
562
563    #[test]
564    fn byte_counter_records_observations() {
565        let counter = ByteCounter::new();
566        counter.record(1024);
567        counter.record(2048);
568        let snap = counter.snapshot();
569        assert_eq!(snap.count, 2);
570        assert_eq!(snap.total_bytes, 3072);
571        assert_eq!(snap.avg_bytes, 1536);
572    }
573
574    #[test]
575    fn byte_counter_reset_clears_all() {
576        let counter = ByteCounter::new();
577        counter.record(512);
578        counter.reset();
579        let snap = counter.snapshot();
580        assert_eq!(snap.count, 0);
581        assert_eq!(snap.total_bytes, 0);
582    }
583
584    #[test]
585    fn scoped_timer_records_on_drop() {
586        let counter = TimingCounter::new();
587        {
588            let _timer = ScopedTimer {
589                counter: Some(&counter),
590                start: Instant::now(),
591            };
592            // Simulate some work
593            std::thread::sleep(std::time::Duration::from_micros(100));
594        }
595        let snap = counter.snapshot();
596        assert_eq!(snap.count, 1);
597        assert!(
598            snap.total_us > 0,
599            "Timer should record nonzero elapsed time"
600        );
601    }
602
603    #[test]
604    fn scoped_timer_finish_returns_elapsed_and_records() {
605        let counter = TimingCounter::new();
606        let timer = ScopedTimer {
607            counter: Some(&counter),
608            start: Instant::now(),
609        };
610        std::thread::sleep(std::time::Duration::from_micros(100));
611        let elapsed = timer.finish();
612        assert!(elapsed > 0);
613        assert_eq!(counter.snapshot().count, 1);
614    }
615
616    #[test]
617    fn scoped_timer_noop_when_disabled() {
618        let counter = TimingCounter::new();
619        {
620            let _timer = ScopedTimer {
621                counter: None,
622                start: Instant::now(),
623            };
624        }
625        assert_eq!(counter.snapshot().count, 0);
626    }
627
628    #[test]
629    fn session_metrics_disabled_by_default() {
630        let metrics = SessionMetrics::new();
631        assert!(!metrics.enabled());
632    }
633
634    #[test]
635    fn session_metrics_enable_disable() {
636        let metrics = SessionMetrics::new();
637        metrics.enable();
638        assert!(metrics.enabled());
639        metrics.disable();
640        assert!(!metrics.enabled());
641    }
642
643    #[test]
644    fn session_metrics_start_timer_noop_when_disabled() {
645        let metrics = SessionMetrics::new();
646        assert!(!metrics.enabled());
647        {
648            let _timer = metrics.start_timer(&metrics.sqlite_save);
649        }
650        assert_eq!(metrics.sqlite_save.snapshot().count, 0);
651    }
652
653    #[test]
654    fn session_metrics_start_timer_records_when_enabled() {
655        let metrics = SessionMetrics::new();
656        metrics.enable();
657        {
658            let _timer = metrics.start_timer(&metrics.sqlite_save);
659            std::thread::sleep(std::time::Duration::from_micros(50));
660        }
661        assert_eq!(metrics.sqlite_save.snapshot().count, 1);
662        assert!(metrics.sqlite_save.snapshot().total_us > 0);
663    }
664
665    #[test]
666    fn session_metrics_record_bytes_noop_when_disabled() {
667        let metrics = SessionMetrics::new();
668        metrics.record_bytes(&metrics.jsonl_bytes, 1024);
669        assert_eq!(metrics.jsonl_bytes.snapshot().count, 0);
670    }
671
672    #[test]
673    fn session_metrics_record_bytes_when_enabled() {
674        let metrics = SessionMetrics::new();
675        metrics.enable();
676        metrics.record_bytes(&metrics.jsonl_bytes, 1024);
677        metrics.record_bytes(&metrics.jsonl_bytes, 2048);
678        let snap = metrics.jsonl_bytes.snapshot();
679        assert_eq!(snap.count, 2);
680        assert_eq!(snap.total_bytes, 3072);
681    }
682
683    #[test]
684    fn session_metrics_reset_all() {
685        let metrics = SessionMetrics::new();
686        metrics.enable();
687        metrics.sqlite_save.record(100);
688        metrics.index_upsert.record(200);
689        metrics.jsonl_bytes.record(512);
690        metrics.reset_all();
691        assert_eq!(metrics.sqlite_save.snapshot().count, 0);
692        assert_eq!(metrics.index_upsert.snapshot().count, 0);
693        assert_eq!(metrics.jsonl_bytes.snapshot().count, 0);
694    }
695
696    #[test]
697    fn session_metrics_snapshot_captures_all_counters() {
698        let metrics = SessionMetrics::new();
699        metrics.enable();
700        metrics.sqlite_save.record(100);
701        metrics.sqlite_load.record(200);
702        metrics.index_lock.record(50);
703        metrics.jsonl_bytes.record(4096);
704        let snap = metrics.snapshot();
705        assert!(snap.enabled);
706        assert_eq!(snap.sqlite_save.count, 1);
707        assert_eq!(snap.sqlite_load.count, 1);
708        assert_eq!(snap.index_lock.count, 1);
709        assert_eq!(snap.jsonl_bytes.count, 1);
710        assert_eq!(snap.jsonl_bytes.total_bytes, 4096);
711    }
712
713    #[test]
714    fn session_metrics_summary_disabled() {
715        let metrics = SessionMetrics::new();
716        let summary = metrics.summary();
717        assert!(summary.contains("disabled"));
718    }
719
720    #[test]
721    fn session_metrics_summary_enabled_contains_all_labels() {
722        let metrics = SessionMetrics::new();
723        metrics.enable();
724        metrics.sqlite_save.record(100);
725        let summary = metrics.summary();
726        assert!(summary.contains("JSONL save:"));
727        assert!(summary.contains("JSONL serialize:"));
728        assert!(summary.contains("JSONL IO:"));
729        assert!(summary.contains("JSONL bytes:"));
730        assert!(summary.contains("JSONL queue wait:"));
731        assert!(summary.contains("SQLite save:"));
732        assert!(summary.contains("SQLite append:"));
733        assert!(summary.contains("SQLite serialize:"));
734        assert!(summary.contains("SQLite bytes:"));
735        assert!(summary.contains("SQLite load:"));
736        assert!(summary.contains("SQLite load meta:"));
737        assert!(summary.contains("Index lock:"));
738        assert!(summary.contains("Index upsert:"));
739        assert!(summary.contains("Index list:"));
740        assert!(summary.contains("Index reindex:"));
741        assert!(summary.contains("Append:"));
742    }
743
744    #[test]
745    fn timing_snapshot_display_zero() {
746        let snap = TimingSnapshot {
747            count: 0,
748            total_us: 0,
749            max_us: 0,
750            avg_us: 0,
751        };
752        assert_eq!(format!("{snap}"), "n=0");
753    }
754
755    #[test]
756    fn timing_snapshot_display_nonzero() {
757        let snap = TimingSnapshot {
758            count: 3,
759            total_us: 6000,
760            max_us: 3000,
761            avg_us: 2000,
762        };
763        let display = format!("{snap}");
764        assert!(display.contains("n=3"));
765        assert!(display.contains("avg=2.0ms"));
766        assert!(display.contains("max=3.0ms"));
767        assert!(display.contains("total=6.0ms"));
768    }
769
770    #[test]
771    fn byte_snapshot_display_zero() {
772        let snap = ByteSnapshot {
773            count: 0,
774            total_bytes: 0,
775            avg_bytes: 0,
776        };
777        assert_eq!(format!("{snap}"), "n=0");
778    }
779
780    #[test]
781    fn byte_snapshot_display_nonzero() {
782        let snap = ByteSnapshot {
783            count: 2,
784            total_bytes: 3072,
785            avg_bytes: 1536,
786        };
787        let display = format!("{snap}");
788        assert!(display.contains("n=2"));
789        assert!(display.contains("avg=1536B"));
790        assert!(display.contains("total=3072B"));
791    }
792
793    #[test]
794    fn global_returns_same_instance() {
795        let a = global();
796        let b = global();
797        assert!(std::ptr::eq(a, b));
798    }
799
800    #[test]
801    fn timing_counter_concurrent_recording() {
802        use std::sync::Arc;
803
804        let counter = Arc::new(TimingCounter::new());
805        let threads: Vec<_> = (0..4)
806            .map(|_| {
807                let c = Arc::clone(&counter);
808                std::thread::spawn(move || {
809                    for i in 0..100 {
810                        c.record(i);
811                    }
812                })
813            })
814            .collect();
815        for t in threads {
816            t.join().expect("thread join");
817        }
818        let snap = counter.snapshot();
819        assert_eq!(snap.count, 400);
820        // Total should be 4 * sum(0..100) = 4 * 4950 = 19800
821        assert_eq!(snap.total_us, 19800);
822        assert_eq!(snap.max_us, 99);
823    }
824
825    mod proptest_session_metrics {
826        use super::*;
827        use proptest::prelude::*;
828
829        proptest! {
830            /// After recording n values, count == n and total == sum.
831            #[test]
832            fn timing_counter_sum_and_count(
833                values in prop::collection::vec(0u64..10_000, 0..50)
834            ) {
835                let counter = TimingCounter::new();
836                for &v in &values {
837                    counter.record(v);
838                }
839                let snap = counter.snapshot();
840                assert_eq!(snap.count, values.len() as u64);
841                assert_eq!(
842                    snap.total_us,
843                    values.iter().copied().sum::<u64>()
844                );
845            }
846
847            /// max_us tracks the maximum recorded value.
848            #[test]
849            fn timing_counter_tracks_max(
850                values in prop::collection::vec(0u64..100_000, 1..50)
851            ) {
852                let counter = TimingCounter::new();
853                for &v in &values {
854                    counter.record(v);
855                }
856                let snap = counter.snapshot();
857                assert_eq!(snap.max_us, *values.iter().max().unwrap());
858            }
859
860            /// avg_us == total_us / count (integer division).
861            #[test]
862            fn timing_snapshot_avg_is_floor_division(
863                values in prop::collection::vec(1u64..10_000, 1..50)
864            ) {
865                let counter = TimingCounter::new();
866                for &v in &values {
867                    counter.record(v);
868                }
869                let snap = counter.snapshot();
870                let expected = snap.total_us / snap.count;
871                assert_eq!(snap.avg_us, expected);
872            }
873
874            /// Empty counter snapshot has all zeros.
875            #[test]
876            fn empty_counter_snapshot(_dummy in 0..1u8) {
877                let counter = TimingCounter::new();
878                let snap = counter.snapshot();
879                assert_eq!(snap.count, 0);
880                assert_eq!(snap.total_us, 0);
881                assert_eq!(snap.max_us, 0);
882                assert_eq!(snap.avg_us, 0);
883            }
884
885            /// After reset, snapshot returns all zeros.
886            #[test]
887            fn timing_reset_clears(values in prop::collection::vec(1u64..1000, 1..20)) {
888                let counter = TimingCounter::new();
889                for &v in &values {
890                    counter.record(v);
891                }
892                counter.reset();
893                let snap = counter.snapshot();
894                assert_eq!(snap.count, 0);
895                assert_eq!(snap.total_us, 0);
896                assert_eq!(snap.max_us, 0);
897            }
898
899            /// `ByteCounter` tracks sum and count correctly.
900            #[test]
901            fn byte_counter_sum_and_count(
902                values in prop::collection::vec(0u64..100_000, 0..50)
903            ) {
904                let counter = ByteCounter::new();
905                for &v in &values {
906                    counter.record(v);
907                }
908                let snap = counter.snapshot();
909                assert_eq!(snap.count, values.len() as u64);
910                assert_eq!(snap.total_bytes, values.iter().copied().sum::<u64>());
911            }
912
913            /// `ByteCounter` avg_bytes is floor division.
914            #[test]
915            fn byte_counter_avg(
916                values in prop::collection::vec(1u64..10_000, 1..50)
917            ) {
918                let counter = ByteCounter::new();
919                for &v in &values {
920                    counter.record(v);
921                }
922                let snap = counter.snapshot();
923                assert_eq!(snap.avg_bytes, snap.total_bytes / snap.count);
924            }
925
926            /// `ByteCounter` reset clears all.
927            #[test]
928            fn byte_counter_reset(values in prop::collection::vec(1u64..1000, 1..10)) {
929                let counter = ByteCounter::new();
930                for &v in &values {
931                    counter.record(v);
932                }
933                counter.reset();
934                let snap = counter.snapshot();
935                assert_eq!(snap.count, 0);
936                assert_eq!(snap.total_bytes, 0);
937            }
938
939            /// `TimingSnapshot` display is "n=0" when count == 0.
940            #[test]
941            fn timing_display_zero(_dummy in 0..1u8) {
942                let snap = TimingSnapshot {
943                    count: 0,
944                    total_us: 0,
945                    max_us: 0,
946                    avg_us: 0,
947                };
948                assert_eq!(format!("{snap}"), "n=0");
949            }
950
951            /// `TimingSnapshot` display contains all fields when count > 0.
952            #[test]
953            fn timing_display_nonzero(
954                count in 1u64..1000,
955                total_us in 1u64..1_000_000,
956                max_us in 1u64..1_000_000
957            ) {
958                let snap = TimingSnapshot {
959                    count,
960                    total_us,
961                    max_us,
962                    avg_us: total_us / count,
963                };
964                let display = format!("{snap}");
965                assert!(display.contains(&format!("n={count}")));
966                assert!(display.contains("avg="));
967                assert!(display.contains("max="));
968                assert!(display.contains("total="));
969            }
970
971            /// `ByteSnapshot` display is "n=0" when count == 0.
972            #[test]
973            fn byte_display_zero(_dummy in 0..1u8) {
974                let snap = ByteSnapshot {
975                    count: 0,
976                    total_bytes: 0,
977                    avg_bytes: 0,
978                };
979                assert_eq!(format!("{snap}"), "n=0");
980            }
981
982            /// `ByteSnapshot` display contains count and bytes when count > 0.
983            #[test]
984            fn byte_display_nonzero(
985                count in 1u64..1000,
986                total in 1u64..1_000_000
987            ) {
988                let snap = ByteSnapshot {
989                    count,
990                    total_bytes: total,
991                    avg_bytes: total / count,
992                };
993                let display = format!("{snap}");
994                assert!(display.contains(&format!("n={count}")));
995                assert!(display.contains("avg="));
996                assert!(display.contains("total="));
997            }
998        }
999    }
1000}
pi/session_metrics.rs

pi/
session_metrics.rs
