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                finished: false,
297            }
298        } else {
299            ScopedTimer {
300                counter: None,
301                start: Instant::now(), // unused but cheap
302                finished: false,
303            }
304        }
305    }
306
307    /// Record bytes if metrics are enabled.
308    #[inline]
309    pub fn record_bytes(&self, counter: &ByteCounter, bytes: u64) {
310        if self.enabled() {
311            counter.record(bytes);
312        }
313    }
314
315    /// Reset all counters to zero.
316    pub fn reset_all(&self) {
317        self.jsonl_save.reset();
318        self.jsonl_serialize.reset();
319        self.jsonl_io.reset();
320        self.jsonl_bytes.reset();
321        self.jsonl_queue_wait.reset();
322        self.sqlite_save.reset();
323        self.sqlite_append.reset();
324        self.sqlite_serialize.reset();
325        self.sqlite_bytes.reset();
326        self.sqlite_load.reset();
327        self.sqlite_load_meta.reset();
328        self.index_lock.reset();
329        self.index_upsert.reset();
330        self.index_list.reset();
331        self.index_reindex.reset();
332        self.append.reset();
333    }
334
335    /// Produce a structured snapshot of all metrics.
336    pub fn snapshot(&self) -> MetricsSnapshot {
337        MetricsSnapshot {
338            enabled: self.enabled(),
339            jsonl_save: self.jsonl_save.snapshot(),
340            jsonl_serialize: self.jsonl_serialize.snapshot(),
341            jsonl_io: self.jsonl_io.snapshot(),
342            jsonl_bytes: self.jsonl_bytes.snapshot(),
343            jsonl_queue_wait: self.jsonl_queue_wait.snapshot(),
344            sqlite_save: self.sqlite_save.snapshot(),
345            sqlite_append: self.sqlite_append.snapshot(),
346            sqlite_serialize: self.sqlite_serialize.snapshot(),
347            sqlite_bytes: self.sqlite_bytes.snapshot(),
348            sqlite_load: self.sqlite_load.snapshot(),
349            sqlite_load_meta: self.sqlite_load_meta.snapshot(),
350            index_lock: self.index_lock.snapshot(),
351            index_upsert: self.index_upsert.snapshot(),
352            index_list: self.index_list.snapshot(),
353            index_reindex: self.index_reindex.snapshot(),
354            append: self.append.snapshot(),
355        }
356    }
357
358    /// Human-readable multi-line summary for diagnostics.
359    pub fn summary(&self) -> String {
360        if !self.enabled() {
361            return "Session telemetry disabled (set PI_PERF_TELEMETRY=1 to enable)".to_string();
362        }
363        let s = self.snapshot();
364        format!(
365            "Session hot-path metrics:\n  \
366             JSONL save:       {}\n  \
367             JSONL serialize:  {}\n  \
368             JSONL IO:         {}\n  \
369             JSONL bytes:      {}\n  \
370             JSONL queue wait: {}\n  \
371             SQLite save:      {}\n  \
372             SQLite append:    {}\n  \
373             SQLite serialize: {}\n  \
374             SQLite bytes:     {}\n  \
375             SQLite load:      {}\n  \
376             SQLite load meta: {}\n  \
377             Index lock:       {}\n  \
378             Index upsert:     {}\n  \
379             Index list:       {}\n  \
380             Index reindex:    {}\n  \
381             Append:           {}",
382            s.jsonl_save,
383            s.jsonl_serialize,
384            s.jsonl_io,
385            s.jsonl_bytes,
386            s.jsonl_queue_wait,
387            s.sqlite_save,
388            s.sqlite_append,
389            s.sqlite_serialize,
390            s.sqlite_bytes,
391            s.sqlite_load,
392            s.sqlite_load_meta,
393            s.index_lock,
394            s.index_upsert,
395            s.index_list,
396            s.index_reindex,
397            s.append,
398        )
399    }
400
401    /// Emit the summary to `tracing::debug` (called periodically or on demand).
402    pub fn emit(&self) {
403        if self.enabled() {
404            tracing::debug!("{}", self.summary());
405        }
406    }
407}
408
409// ---------------------------------------------------------------------------
410// MetricsSnapshot
411// ---------------------------------------------------------------------------
412
413/// Complete point-in-time snapshot of all session metrics.
414#[derive(Debug, Clone)]
415pub struct MetricsSnapshot {
416    pub enabled: bool,
417    pub jsonl_save: TimingSnapshot,
418    pub jsonl_serialize: TimingSnapshot,
419    pub jsonl_io: TimingSnapshot,
420    pub jsonl_bytes: ByteSnapshot,
421    pub jsonl_queue_wait: TimingSnapshot,
422    pub sqlite_save: TimingSnapshot,
423    pub sqlite_append: TimingSnapshot,
424    pub sqlite_serialize: TimingSnapshot,
425    pub sqlite_bytes: ByteSnapshot,
426    pub sqlite_load: TimingSnapshot,
427    pub sqlite_load_meta: TimingSnapshot,
428    pub index_lock: TimingSnapshot,
429    pub index_upsert: TimingSnapshot,
430    pub index_list: TimingSnapshot,
431    pub index_reindex: TimingSnapshot,
432    pub append: TimingSnapshot,
433}
434
435// ---------------------------------------------------------------------------
436// ScopedTimer
437// ---------------------------------------------------------------------------
438
439/// RAII timer that records elapsed microseconds into a [`TimingCounter`]
440/// when dropped. If `counter` is `None` (metrics disabled), drop is a no-op.
441pub struct ScopedTimer<'a> {
442    counter: Option<&'a TimingCounter>,
443    start: Instant,
444    finished: bool,
445}
446
447impl ScopedTimer<'_> {
448    /// Manually finish the timer and return elapsed microseconds.
449    /// Consumes self so drop won't double-record.
450    #[allow(clippy::cast_possible_truncation)]
451    pub fn finish(mut self) -> u64 {
452        let elapsed_us = self.start.elapsed().as_micros().min(u128::from(u64::MAX)) as u64;
453        if let Some(counter) = self.counter {
454            counter.record(elapsed_us);
455        }
456        // Prevent drop from recording again.
457        self.finished = true;
458        elapsed_us
459    }
460}
461
462impl Drop for ScopedTimer<'_> {
463    #[allow(clippy::cast_possible_truncation)]
464    fn drop(&mut self) {
465        if !self.finished {
466            if let Some(counter) = self.counter {
467                let elapsed_us = self.start.elapsed().as_micros().min(u128::from(u64::MAX)) as u64;
468                counter.record(elapsed_us);
469            }
470        }
471    }
472}
473
474// ---------------------------------------------------------------------------
475// Global accessor
476// ---------------------------------------------------------------------------
477
478static GLOBAL_METRICS: OnceLock<SessionMetrics> = OnceLock::new();
479
480/// Return the global `SessionMetrics` singleton.
481///
482/// On first call, reads `PI_PERF_TELEMETRY` to decide whether collection
483/// is enabled. The singleton lives for the process lifetime.
484pub fn global() -> &'static SessionMetrics {
485    GLOBAL_METRICS.get_or_init(|| {
486        let metrics = SessionMetrics::new();
487        let enabled =
488            std::env::var_os("PI_PERF_TELEMETRY").is_some_and(|v| v == "1" || v == "true");
489        if enabled {
490            metrics.enabled.store(true, Ordering::Relaxed);
491        }
492        metrics
493    })
494}
495
496// ---------------------------------------------------------------------------
497// Tests
498// ---------------------------------------------------------------------------
499
500#[cfg(test)]
501mod tests {
502    use super::*;
503
504    #[test]
505    fn timing_counter_starts_at_zero() {
506        let counter = TimingCounter::new();
507        let snap = counter.snapshot();
508        assert_eq!(snap.count, 0);
509        assert_eq!(snap.total_us, 0);
510        assert_eq!(snap.max_us, 0);
511        assert_eq!(snap.avg_us, 0);
512    }
513
514    #[test]
515    fn timing_counter_records_single_observation() {
516        let counter = TimingCounter::new();
517        counter.record(500);
518        let snap = counter.snapshot();
519        assert_eq!(snap.count, 1);
520        assert_eq!(snap.total_us, 500);
521        assert_eq!(snap.max_us, 500);
522        assert_eq!(snap.avg_us, 500);
523    }
524
525    #[test]
526    fn timing_counter_records_multiple_observations() {
527        let counter = TimingCounter::new();
528        counter.record(100);
529        counter.record(300);
530        counter.record(200);
531        let snap = counter.snapshot();
532        assert_eq!(snap.count, 3);
533        assert_eq!(snap.total_us, 600);
534        assert_eq!(snap.max_us, 300);
535        assert_eq!(snap.avg_us, 200);
536    }
537
538    #[test]
539    fn timing_counter_max_tracks_peak() {
540        let counter = TimingCounter::new();
541        counter.record(50);
542        counter.record(999);
543        counter.record(100);
544        assert_eq!(counter.snapshot().max_us, 999);
545    }
546
547    #[test]
548    fn timing_counter_reset_clears_all() {
549        let counter = TimingCounter::new();
550        counter.record(100);
551        counter.record(200);
552        counter.reset();
553        let snap = counter.snapshot();
554        assert_eq!(snap.count, 0);
555        assert_eq!(snap.total_us, 0);
556        assert_eq!(snap.max_us, 0);
557    }
558
559    #[test]
560    fn byte_counter_starts_at_zero() {
561        let counter = ByteCounter::new();
562        let snap = counter.snapshot();
563        assert_eq!(snap.count, 0);
564        assert_eq!(snap.total_bytes, 0);
565        assert_eq!(snap.avg_bytes, 0);
566    }
567
568    #[test]
569    fn byte_counter_records_observations() {
570        let counter = ByteCounter::new();
571        counter.record(1024);
572        counter.record(2048);
573        let snap = counter.snapshot();
574        assert_eq!(snap.count, 2);
575        assert_eq!(snap.total_bytes, 3072);
576        assert_eq!(snap.avg_bytes, 1536);
577    }
578
579    #[test]
580    fn byte_counter_reset_clears_all() {
581        let counter = ByteCounter::new();
582        counter.record(512);
583        counter.reset();
584        let snap = counter.snapshot();
585        assert_eq!(snap.count, 0);
586        assert_eq!(snap.total_bytes, 0);
587    }
588
589    #[test]
590    fn scoped_timer_records_on_drop() {
591        let counter = TimingCounter::new();
592        {
593            let _timer = ScopedTimer {
594                counter: Some(&counter),
595                start: Instant::now(),
596                finished: false,
597            };
598            // Simulate some work
599            std::thread::sleep(std::time::Duration::from_micros(100));
600        }
601        let snap = counter.snapshot();
602        assert_eq!(snap.count, 1);
603        assert!(
604            snap.total_us > 0,
605            "Timer should record nonzero elapsed time"
606        );
607    }
608
609    #[test]
610    fn scoped_timer_finish_returns_elapsed_and_records() {
611        let counter = TimingCounter::new();
612        let timer = ScopedTimer {
613            counter: Some(&counter),
614            start: Instant::now(),
615            finished: false,
616        };
617        std::thread::sleep(std::time::Duration::from_micros(100));
618        let elapsed = timer.finish();
619        assert!(elapsed > 0);
620        assert_eq!(counter.snapshot().count, 1);
621    }
622
623    #[test]
624    fn scoped_timer_noop_when_disabled() {
625        let counter = TimingCounter::new();
626        {
627            let _timer = ScopedTimer {
628                counter: None,
629                start: Instant::now(),
630                finished: false,
631            };
632        }
633        assert_eq!(counter.snapshot().count, 0);
634    }
635
636    #[test]
637    fn session_metrics_disabled_by_default() {
638        let metrics = SessionMetrics::new();
639        assert!(!metrics.enabled());
640    }
641
642    #[test]
643    fn session_metrics_enable_disable() {
644        let metrics = SessionMetrics::new();
645        metrics.enable();
646        assert!(metrics.enabled());
647        metrics.disable();
648        assert!(!metrics.enabled());
649    }
650
651    #[test]
652    fn session_metrics_start_timer_noop_when_disabled() {
653        let metrics = SessionMetrics::new();
654        assert!(!metrics.enabled());
655        {
656            let _timer = metrics.start_timer(&metrics.sqlite_save);
657        }
658        assert_eq!(metrics.sqlite_save.snapshot().count, 0);
659    }
660
661    #[test]
662    fn session_metrics_start_timer_records_when_enabled() {
663        let metrics = SessionMetrics::new();
664        metrics.enable();
665        {
666            let _timer = metrics.start_timer(&metrics.sqlite_save);
667            std::thread::sleep(std::time::Duration::from_micros(50));
668        }
669        assert_eq!(metrics.sqlite_save.snapshot().count, 1);
670        assert!(metrics.sqlite_save.snapshot().total_us > 0);
671    }
672
673    #[test]
674    fn session_metrics_record_bytes_noop_when_disabled() {
675        let metrics = SessionMetrics::new();
676        metrics.record_bytes(&metrics.jsonl_bytes, 1024);
677        assert_eq!(metrics.jsonl_bytes.snapshot().count, 0);
678    }
679
680    #[test]
681    fn session_metrics_record_bytes_when_enabled() {
682        let metrics = SessionMetrics::new();
683        metrics.enable();
684        metrics.record_bytes(&metrics.jsonl_bytes, 1024);
685        metrics.record_bytes(&metrics.jsonl_bytes, 2048);
686        let snap = metrics.jsonl_bytes.snapshot();
687        assert_eq!(snap.count, 2);
688        assert_eq!(snap.total_bytes, 3072);
689    }
690
691    #[test]
692    fn session_metrics_reset_all() {
693        let metrics = SessionMetrics::new();
694        metrics.enable();
695        metrics.sqlite_save.record(100);
696        metrics.index_upsert.record(200);
697        metrics.jsonl_bytes.record(512);
698        metrics.reset_all();
699        assert_eq!(metrics.sqlite_save.snapshot().count, 0);
700        assert_eq!(metrics.index_upsert.snapshot().count, 0);
701        assert_eq!(metrics.jsonl_bytes.snapshot().count, 0);
702    }
703
704    #[test]
705    fn session_metrics_snapshot_captures_all_counters() {
706        let metrics = SessionMetrics::new();
707        metrics.enable();
708        metrics.sqlite_save.record(100);
709        metrics.sqlite_load.record(200);
710        metrics.index_lock.record(50);
711        metrics.jsonl_bytes.record(4096);
712        let snap = metrics.snapshot();
713        assert!(snap.enabled);
714        assert_eq!(snap.sqlite_save.count, 1);
715        assert_eq!(snap.sqlite_load.count, 1);
716        assert_eq!(snap.index_lock.count, 1);
717        assert_eq!(snap.jsonl_bytes.count, 1);
718        assert_eq!(snap.jsonl_bytes.total_bytes, 4096);
719    }
720
721    #[test]
722    fn session_metrics_summary_disabled() {
723        let metrics = SessionMetrics::new();
724        let summary = metrics.summary();
725        assert!(summary.contains("disabled"));
726    }
727
728    #[test]
729    fn session_metrics_summary_enabled_contains_all_labels() {
730        let metrics = SessionMetrics::new();
731        metrics.enable();
732        metrics.sqlite_save.record(100);
733        let summary = metrics.summary();
734        assert!(summary.contains("JSONL save:"));
735        assert!(summary.contains("JSONL serialize:"));
736        assert!(summary.contains("JSONL IO:"));
737        assert!(summary.contains("JSONL bytes:"));
738        assert!(summary.contains("JSONL queue wait:"));
739        assert!(summary.contains("SQLite save:"));
740        assert!(summary.contains("SQLite append:"));
741        assert!(summary.contains("SQLite serialize:"));
742        assert!(summary.contains("SQLite bytes:"));
743        assert!(summary.contains("SQLite load:"));
744        assert!(summary.contains("SQLite load meta:"));
745        assert!(summary.contains("Index lock:"));
746        assert!(summary.contains("Index upsert:"));
747        assert!(summary.contains("Index list:"));
748        assert!(summary.contains("Index reindex:"));
749        assert!(summary.contains("Append:"));
750    }
751
752    #[test]
753    fn timing_snapshot_display_zero() {
754        let snap = TimingSnapshot {
755            count: 0,
756            total_us: 0,
757            max_us: 0,
758            avg_us: 0,
759        };
760        assert_eq!(format!("{snap}"), "n=0");
761    }
762
763    #[test]
764    fn timing_snapshot_display_nonzero() {
765        let snap = TimingSnapshot {
766            count: 3,
767            total_us: 6000,
768            max_us: 3000,
769            avg_us: 2000,
770        };
771        let display = format!("{snap}");
772        assert!(display.contains("n=3"));
773        assert!(display.contains("avg=2.0ms"));
774        assert!(display.contains("max=3.0ms"));
775        assert!(display.contains("total=6.0ms"));
776    }
777
778    #[test]
779    fn byte_snapshot_display_zero() {
780        let snap = ByteSnapshot {
781            count: 0,
782            total_bytes: 0,
783            avg_bytes: 0,
784        };
785        assert_eq!(format!("{snap}"), "n=0");
786    }
787
788    #[test]
789    fn byte_snapshot_display_nonzero() {
790        let snap = ByteSnapshot {
791            count: 2,
792            total_bytes: 3072,
793            avg_bytes: 1536,
794        };
795        let display = format!("{snap}");
796        assert!(display.contains("n=2"));
797        assert!(display.contains("avg=1536B"));
798        assert!(display.contains("total=3072B"));
799    }
800
801    #[test]
802    fn global_returns_same_instance() {
803        let a = global();
804        let b = global();
805        assert!(std::ptr::eq(a, b));
806    }
807
808    #[test]
809    fn timing_counter_concurrent_recording() {
810        use std::sync::Arc;
811
812        let counter = Arc::new(TimingCounter::new());
813        let threads: Vec<_> = (0..4)
814            .map(|_| {
815                let c = Arc::clone(&counter);
816                std::thread::spawn(move || {
817                    for i in 0..100 {
818                        c.record(i);
819                    }
820                })
821            })
822            .collect();
823        for t in threads {
824            t.join().expect("thread join");
825        }
826        let snap = counter.snapshot();
827        assert_eq!(snap.count, 400);
828        // Total should be 4 * sum(0..100) = 4 * 4950 = 19800
829        assert_eq!(snap.total_us, 19800);
830        assert_eq!(snap.max_us, 99);
831    }
832
833    mod proptest_session_metrics {
834        use super::*;
835        use proptest::prelude::*;
836
837        proptest! {
838            /// After recording n values, count == n and total == sum.
839            #[test]
840            fn timing_counter_sum_and_count(
841                values in prop::collection::vec(0u64..10_000, 0..50)
842            ) {
843                let counter = TimingCounter::new();
844                for &v in &values {
845                    counter.record(v);
846                }
847                let snap = counter.snapshot();
848                assert_eq!(snap.count, values.len() as u64);
849                assert_eq!(
850                    snap.total_us,
851                    values.iter().copied().sum::<u64>()
852                );
853            }
854
855            /// max_us tracks the maximum recorded value.
856            #[test]
857            fn timing_counter_tracks_max(
858                values in prop::collection::vec(0u64..100_000, 1..50)
859            ) {
860                let counter = TimingCounter::new();
861                for &v in &values {
862                    counter.record(v);
863                }
864                let snap = counter.snapshot();
865                assert_eq!(snap.max_us, *values.iter().max().unwrap());
866            }
867
868            /// avg_us == total_us / count (integer division).
869            #[test]
870            fn timing_snapshot_avg_is_floor_division(
871                values in prop::collection::vec(1u64..10_000, 1..50)
872            ) {
873                let counter = TimingCounter::new();
874                for &v in &values {
875                    counter.record(v);
876                }
877                let snap = counter.snapshot();
878                let expected = snap.total_us / snap.count;
879                assert_eq!(snap.avg_us, expected);
880            }
881
882            /// Empty counter snapshot has all zeros.
883            #[test]
884            fn empty_counter_snapshot(_dummy in 0..1u8) {
885                let counter = TimingCounter::new();
886                let snap = counter.snapshot();
887                assert_eq!(snap.count, 0);
888                assert_eq!(snap.total_us, 0);
889                assert_eq!(snap.max_us, 0);
890                assert_eq!(snap.avg_us, 0);
891            }
892
893            /// After reset, snapshot returns all zeros.
894            #[test]
895            fn timing_reset_clears(values in prop::collection::vec(1u64..1000, 1..20)) {
896                let counter = TimingCounter::new();
897                for &v in &values {
898                    counter.record(v);
899                }
900                counter.reset();
901                let snap = counter.snapshot();
902                assert_eq!(snap.count, 0);
903                assert_eq!(snap.total_us, 0);
904                assert_eq!(snap.max_us, 0);
905            }
906
907            /// `ByteCounter` tracks sum and count correctly.
908            #[test]
909            fn byte_counter_sum_and_count(
910                values in prop::collection::vec(0u64..100_000, 0..50)
911            ) {
912                let counter = ByteCounter::new();
913                for &v in &values {
914                    counter.record(v);
915                }
916                let snap = counter.snapshot();
917                assert_eq!(snap.count, values.len() as u64);
918                assert_eq!(snap.total_bytes, values.iter().copied().sum::<u64>());
919            }
920
921            /// `ByteCounter` avg_bytes is floor division.
922            #[test]
923            fn byte_counter_avg(
924                values in prop::collection::vec(1u64..10_000, 1..50)
925            ) {
926                let counter = ByteCounter::new();
927                for &v in &values {
928                    counter.record(v);
929                }
930                let snap = counter.snapshot();
931                assert_eq!(snap.avg_bytes, snap.total_bytes / snap.count);
932            }
933
934            /// `ByteCounter` reset clears all.
935            #[test]
936            fn byte_counter_reset(values in prop::collection::vec(1u64..1000, 1..10)) {
937                let counter = ByteCounter::new();
938                for &v in &values {
939                    counter.record(v);
940                }
941                counter.reset();
942                let snap = counter.snapshot();
943                assert_eq!(snap.count, 0);
944                assert_eq!(snap.total_bytes, 0);
945            }
946
947            /// `TimingSnapshot` display is "n=0" when count == 0.
948            #[test]
949            fn timing_display_zero(_dummy in 0..1u8) {
950                let snap = TimingSnapshot {
951                    count: 0,
952                    total_us: 0,
953                    max_us: 0,
954                    avg_us: 0,
955                };
956                assert_eq!(format!("{snap}"), "n=0");
957            }
958
959            /// `TimingSnapshot` display contains all fields when count > 0.
960            #[test]
961            fn timing_display_nonzero(
962                count in 1u64..1000,
963                total_us in 1u64..1_000_000,
964                max_us in 1u64..1_000_000
965            ) {
966                let snap = TimingSnapshot {
967                    count,
968                    total_us,
969                    max_us,
970                    avg_us: total_us / count,
971                };
972                let display = format!("{snap}");
973                assert!(display.contains(&format!("n={count}")));
974                assert!(display.contains("avg="));
975                assert!(display.contains("max="));
976                assert!(display.contains("total="));
977            }
978
979            /// `ByteSnapshot` display is "n=0" when count == 0.
980            #[test]
981            fn byte_display_zero(_dummy in 0..1u8) {
982                let snap = ByteSnapshot {
983                    count: 0,
984                    total_bytes: 0,
985                    avg_bytes: 0,
986                };
987                assert_eq!(format!("{snap}"), "n=0");
988            }
989
990            /// `ByteSnapshot` display contains count and bytes when count > 0.
991            #[test]
992            fn byte_display_nonzero(
993                count in 1u64..1000,
994                total in 1u64..1_000_000
995            ) {
996                let snap = ByteSnapshot {
997                    count,
998                    total_bytes: total,
999                    avg_bytes: total / count,
1000                };
1001                let display = format!("{snap}");
1002                assert!(display.contains(&format!("n={count}")));
1003                assert!(display.contains("avg="));
1004                assert!(display.contains("total="));
1005            }
1006        }
1007    }
1008}
pi/session_metrics.rs

pi/
session_metrics.rs
