1#![forbid(unsafe_code)]
2
3use std::sync::atomic::{AtomicU64, Ordering};
17use web_time::Instant;
18
19static EFFECTS_COMMAND_TOTAL: AtomicU64 = AtomicU64::new(0);
24static EFFECTS_SUBSCRIPTION_TOTAL: AtomicU64 = AtomicU64::new(0);
25static EFFECTS_QUEUE_ENQUEUED: AtomicU64 = AtomicU64::new(0);
26static EFFECTS_QUEUE_PROCESSED: AtomicU64 = AtomicU64::new(0);
27static EFFECTS_QUEUE_DROPPED: AtomicU64 = AtomicU64::new(0);
28static EFFECTS_QUEUE_HIGH_WATER: AtomicU64 = AtomicU64::new(0);
29
30#[must_use]
32pub fn effects_command_total() -> u64 {
33 EFFECTS_COMMAND_TOTAL.load(Ordering::Relaxed)
34}
35
36#[must_use]
38pub fn effects_subscription_total() -> u64 {
39 EFFECTS_SUBSCRIPTION_TOTAL.load(Ordering::Relaxed)
40}
41
42#[must_use]
44pub fn effects_executed_total() -> u64 {
45 effects_command_total() + effects_subscription_total()
46}
47
48#[must_use]
54pub fn effects_queue_enqueued() -> u64 {
55 EFFECTS_QUEUE_ENQUEUED.load(Ordering::Relaxed)
56}
57
58#[must_use]
60pub fn effects_queue_processed() -> u64 {
61 EFFECTS_QUEUE_PROCESSED.load(Ordering::Relaxed)
62}
63
64#[must_use]
66pub fn effects_queue_dropped() -> u64 {
67 EFFECTS_QUEUE_DROPPED.load(Ordering::Relaxed)
68}
69
70#[must_use]
72pub fn effects_queue_high_water() -> u64 {
73 EFFECTS_QUEUE_HIGH_WATER.load(Ordering::Relaxed)
74}
75
76pub fn record_queue_enqueue(current_depth: u64) {
78 EFFECTS_QUEUE_ENQUEUED.fetch_add(1, Ordering::Relaxed);
79 let mut prev = EFFECTS_QUEUE_HIGH_WATER.load(Ordering::Relaxed);
81 while current_depth > prev {
82 match EFFECTS_QUEUE_HIGH_WATER.compare_exchange_weak(
83 prev,
84 current_depth,
85 Ordering::Relaxed,
86 Ordering::Relaxed,
87 ) {
88 Ok(_) => break,
89 Err(actual) => prev = actual,
90 }
91 }
92}
93
94pub fn record_queue_processed() {
96 EFFECTS_QUEUE_PROCESSED.fetch_add(1, Ordering::Relaxed);
97}
98
99pub fn record_queue_drop(reason: &str) {
101 EFFECTS_QUEUE_DROPPED.fetch_add(1, Ordering::Relaxed);
102 tracing::warn!(
103 target: "ftui.effect",
104 reason = reason,
105 monotonic.counter.effects_queue_dropped_total = 1_u64,
106 "effect queue task dropped"
107 );
108}
109
110#[derive(Debug, Clone, Copy, PartialEq, Eq)]
112pub struct QueueTelemetry {
113 pub enqueued: u64,
115 pub processed: u64,
117 pub dropped: u64,
119 pub high_water: u64,
121 pub in_flight: u64,
126}
127
128#[must_use]
145pub fn queue_telemetry() -> QueueTelemetry {
146 let enqueued = effects_queue_enqueued();
147 let processed = effects_queue_processed();
148 let dropped = effects_queue_dropped();
149 let in_flight = enqueued.saturating_sub(processed);
150 QueueTelemetry {
151 enqueued,
152 processed,
153 dropped,
154 high_water: effects_queue_high_water(),
155 in_flight,
156 }
157}
158
159static SUBSCRIPTION_STARTS_TOTAL: AtomicU64 = AtomicU64::new(0);
167static SUBSCRIPTION_STOPS_TOTAL: AtomicU64 = AtomicU64::new(0);
168static SUBSCRIPTION_PANICS_TOTAL: AtomicU64 = AtomicU64::new(0);
169static RECONCILE_COUNT: AtomicU64 = AtomicU64::new(0);
170static RECONCILE_DURATION_US_TOTAL: AtomicU64 = AtomicU64::new(0);
171static SHUTDOWN_DURATION_US_LAST: AtomicU64 = AtomicU64::new(0);
172static SHUTDOWN_TIMED_OUT_TOTAL: AtomicU64 = AtomicU64::new(0);
173
174#[must_use]
176pub fn subscription_starts_total() -> u64 {
177 SUBSCRIPTION_STARTS_TOTAL.load(Ordering::Relaxed)
178}
179
180#[must_use]
182pub fn subscription_stops_total() -> u64 {
183 SUBSCRIPTION_STOPS_TOTAL.load(Ordering::Relaxed)
184}
185
186#[must_use]
188pub fn subscription_panics_total() -> u64 {
189 SUBSCRIPTION_PANICS_TOTAL.load(Ordering::Relaxed)
190}
191
192#[must_use]
194pub fn reconcile_count() -> u64 {
195 RECONCILE_COUNT.load(Ordering::Relaxed)
196}
197
198#[must_use]
200pub fn reconcile_duration_us_total() -> u64 {
201 RECONCILE_DURATION_US_TOTAL.load(Ordering::Relaxed)
202}
203
204#[must_use]
206pub fn shutdown_duration_us_last() -> u64 {
207 SHUTDOWN_DURATION_US_LAST.load(Ordering::Relaxed)
208}
209
210#[must_use]
212pub fn shutdown_timed_out_total() -> u64 {
213 SHUTDOWN_TIMED_OUT_TOTAL.load(Ordering::Relaxed)
214}
215
216pub fn record_dynamics_sub_start() {
218 SUBSCRIPTION_STARTS_TOTAL.fetch_add(1, Ordering::Relaxed);
219}
220
221pub fn record_dynamics_sub_stop() {
223 SUBSCRIPTION_STOPS_TOTAL.fetch_add(1, Ordering::Relaxed);
224}
225
226pub fn record_dynamics_sub_panic() {
228 SUBSCRIPTION_PANICS_TOTAL.fetch_add(1, Ordering::Relaxed);
229}
230
231pub fn record_dynamics_reconcile(duration_us: u64) {
233 RECONCILE_COUNT.fetch_add(1, Ordering::Relaxed);
234 RECONCILE_DURATION_US_TOTAL.fetch_add(duration_us, Ordering::Relaxed);
235}
236
237pub fn record_dynamics_shutdown(duration_us: u64, timed_out: u64) {
239 SHUTDOWN_DURATION_US_LAST.store(duration_us, Ordering::Relaxed);
240 SHUTDOWN_TIMED_OUT_TOTAL.fetch_add(timed_out, Ordering::Relaxed);
241}
242
243#[derive(Debug, Clone, Copy, PartialEq, Eq)]
245pub struct RuntimeDynamics {
246 pub sub_starts: u64,
248 pub sub_stops: u64,
250 pub sub_panics: u64,
252 pub sub_active_estimate: u64,
254 pub reconciles: u64,
256 pub reconcile_avg_us: u64,
258 pub shutdown_last_us: u64,
260 pub shutdown_timeouts: u64,
262}
263
264#[must_use]
266pub fn runtime_dynamics() -> RuntimeDynamics {
267 let sub_starts = subscription_starts_total();
268 let sub_stops = subscription_stops_total();
269 let reconciles = reconcile_count();
270 let reconcile_total_us = reconcile_duration_us_total();
271 RuntimeDynamics {
272 sub_starts,
273 sub_stops,
274 sub_panics: subscription_panics_total(),
275 sub_active_estimate: sub_starts.saturating_sub(sub_stops),
276 reconciles,
277 reconcile_avg_us: reconcile_total_us.checked_div(reconciles).unwrap_or(0),
278 shutdown_last_us: shutdown_duration_us_last(),
279 shutdown_timeouts: shutdown_timed_out_total(),
280 }
281}
282
283pub fn trace_command_effect<F, R>(command_type: &str, f: F) -> R
292where
293 F: FnOnce() -> R,
294{
295 EFFECTS_COMMAND_TOTAL.fetch_add(1, Ordering::Relaxed);
296
297 let start = Instant::now();
298 let _span = tracing::debug_span!(
299 "effect.command",
300 command_type = %command_type,
301 duration_us = tracing::field::Empty,
302 result = tracing::field::Empty,
303 )
304 .entered();
305
306 tracing::debug!(
307 target: "ftui.effect",
308 command_type = %command_type,
309 "command effect started"
310 );
311
312 let result = f();
313 let duration_us = start.elapsed().as_micros() as u64;
314
315 tracing::debug!(
316 target: "ftui.effect",
317 command_type = %command_type,
318 duration_us = duration_us,
319 effect_duration_us = duration_us,
320 "command effect completed"
321 );
322
323 result
324}
325
326pub fn record_command_effect(command_type: &str, duration_us: u64) {
328 EFFECTS_COMMAND_TOTAL.fetch_add(1, Ordering::Relaxed);
329
330 let _span = tracing::debug_span!(
331 "effect.command",
332 command_type = %command_type,
333 duration_us = duration_us,
334 result = "ok",
335 )
336 .entered();
337
338 tracing::debug!(
339 target: "ftui.effect",
340 command_type = %command_type,
341 duration_us = duration_us,
342 effect_duration_us = duration_us,
343 "command effect recorded"
344 );
345}
346
347pub fn record_subscription_start(sub_type: &str, sub_id: u64) {
353 EFFECTS_SUBSCRIPTION_TOTAL.fetch_add(1, Ordering::Relaxed);
354
355 let _span = tracing::debug_span!(
356 "effect.subscription",
357 sub_type = %sub_type,
358 event_count = 0u64,
359 active = true,
360 )
361 .entered();
362
363 tracing::debug!(
364 target: "ftui.effect",
365 sub_type = %sub_type,
366 sub_id = sub_id,
367 active = true,
368 "subscription started"
369 );
370}
371
372pub fn record_subscription_stop(sub_type: &str, sub_id: u64, event_count: u64) {
374 let _span = tracing::debug_span!(
375 "effect.subscription",
376 sub_type = %sub_type,
377 event_count = event_count,
378 active = false,
379 )
380 .entered();
381
382 tracing::debug!(
383 target: "ftui.effect",
384 sub_type = %sub_type,
385 sub_id = sub_id,
386 event_count = event_count,
387 active = false,
388 "subscription stopped"
389 );
390}
391
392pub fn warn_effect_timeout(effect_type: &str, deadline_us: u64) {
394 tracing::warn!(
395 target: "ftui.effect",
396 effect_type = %effect_type,
397 deadline_us = deadline_us,
398 "effect timeout exceeded deadline"
399 );
400}
401
402pub fn error_effect_panic(effect_type: &str, panic_msg: &str) {
404 tracing::error!(
405 target: "ftui.effect",
406 effect_type = %effect_type,
407 panic_msg = %panic_msg,
408 "effect panicked during execution"
409 );
410}
411
412#[cfg(test)]
417mod tests {
418 use super::*;
419 use std::collections::HashMap;
420 use std::sync::{Arc, Mutex};
421 use tracing_subscriber::layer::SubscriberExt;
422 use tracing_subscriber::registry::LookupSpan;
423
424 #[derive(Debug, Clone)]
426 #[allow(dead_code)]
427 struct CapturedSpan {
428 name: String,
429 fields: HashMap<String, String>,
430 }
431
432 #[derive(Debug, Clone)]
433 #[allow(dead_code)]
434 struct CapturedEvent {
435 level: tracing::Level,
436 target: String,
437 fields: HashMap<String, String>,
438 }
439
440 struct SpanCapture {
441 spans: Arc<Mutex<Vec<CapturedSpan>>>,
442 events: Arc<Mutex<Vec<CapturedEvent>>>,
443 }
444
445 impl SpanCapture {
446 fn new() -> (Self, CaptureHandle) {
447 let spans = Arc::new(Mutex::new(Vec::new()));
448 let events = Arc::new(Mutex::new(Vec::new()));
449 let handle = CaptureHandle {
450 spans: spans.clone(),
451 events: events.clone(),
452 };
453 (Self { spans, events }, handle)
454 }
455 }
456
457 struct CaptureHandle {
458 spans: Arc<Mutex<Vec<CapturedSpan>>>,
459 events: Arc<Mutex<Vec<CapturedEvent>>>,
460 }
461
462 impl CaptureHandle {
463 fn spans(&self) -> Vec<CapturedSpan> {
464 self.spans.lock().unwrap().clone()
465 }
466
467 fn events(&self) -> Vec<CapturedEvent> {
468 self.events.lock().unwrap().clone()
469 }
470 }
471
472 struct FieldVisitor(Vec<(String, String)>);
473
474 impl tracing::field::Visit for FieldVisitor {
475 fn record_debug(&mut self, field: &tracing::field::Field, value: &dyn std::fmt::Debug) {
476 self.0
477 .push((field.name().to_string(), format!("{value:?}")));
478 }
479 fn record_u64(&mut self, field: &tracing::field::Field, value: u64) {
480 self.0.push((field.name().to_string(), value.to_string()));
481 }
482 fn record_i64(&mut self, field: &tracing::field::Field, value: i64) {
483 self.0.push((field.name().to_string(), value.to_string()));
484 }
485 fn record_str(&mut self, field: &tracing::field::Field, value: &str) {
486 self.0.push((field.name().to_string(), value.to_string()));
487 }
488 fn record_bool(&mut self, field: &tracing::field::Field, value: bool) {
489 self.0.push((field.name().to_string(), value.to_string()));
490 }
491 }
492
493 impl<S> tracing_subscriber::Layer<S> for SpanCapture
494 where
495 S: tracing::Subscriber + for<'a> LookupSpan<'a>,
496 {
497 fn on_new_span(
498 &self,
499 attrs: &tracing::span::Attributes<'_>,
500 _id: &tracing::span::Id,
501 _ctx: tracing_subscriber::layer::Context<'_, S>,
502 ) {
503 let mut visitor = FieldVisitor(Vec::new());
504 attrs.record(&mut visitor);
505 let mut fields: HashMap<String, String> = visitor.0.into_iter().collect();
506 for field in attrs.metadata().fields() {
507 fields.entry(field.name().to_string()).or_default();
508 }
509 self.spans.lock().unwrap().push(CapturedSpan {
510 name: attrs.metadata().name().to_string(),
511 fields,
512 });
513 }
514
515 fn on_event(
516 &self,
517 event: &tracing::Event<'_>,
518 _ctx: tracing_subscriber::layer::Context<'_, S>,
519 ) {
520 let mut visitor = FieldVisitor(Vec::new());
521 event.record(&mut visitor);
522 let fields: HashMap<String, String> = visitor.0.into_iter().collect();
523 self.events.lock().unwrap().push(CapturedEvent {
524 level: *event.metadata().level(),
525 target: event.metadata().target().to_string(),
526 fields,
527 });
528 }
529 }
530
531 fn with_captured_tracing<F>(f: F) -> CaptureHandle
532 where
533 F: FnOnce(),
534 {
535 let (layer, handle) = SpanCapture::new();
536 let subscriber = tracing_subscriber::registry().with(layer);
537 tracing::subscriber::with_default(subscriber, f);
538 handle
539 }
540
541 #[test]
546 fn trace_command_effect_emits_span() {
547 let handle = with_captured_tracing(|| {
548 trace_command_effect("task", || 42);
549 });
550
551 let spans = handle.spans();
552 let cmd_spans: Vec<_> = spans
553 .iter()
554 .filter(|s| s.name == "effect.command")
555 .collect();
556 assert!(!cmd_spans.is_empty(), "expected effect.command span");
557 assert!(cmd_spans[0].fields.contains_key("command_type"));
558 }
559
560 #[test]
561 fn trace_command_effect_returns_value() {
562 let result = trace_command_effect("test", || 42);
563 assert_eq!(result, 42);
564 }
565
566 #[test]
567 fn trace_command_effect_debug_events() {
568 let handle = with_captured_tracing(|| {
569 trace_command_effect("file_io", || {});
570 });
571
572 let events = handle.events();
573 let start_events: Vec<_> = events
574 .iter()
575 .filter(|e| {
576 e.target == "ftui.effect"
577 && e.fields
578 .get("message")
579 .is_some_and(|m| m.contains("started"))
580 })
581 .collect();
582 assert!(!start_events.is_empty(), "expected start event");
583
584 let complete_events: Vec<_> = events
585 .iter()
586 .filter(|e| {
587 e.target == "ftui.effect"
588 && e.fields
589 .get("message")
590 .is_some_and(|m| m.contains("completed"))
591 })
592 .collect();
593 assert!(!complete_events.is_empty(), "expected complete event");
594
595 let evt = &complete_events[0];
596 assert!(
597 evt.fields.contains_key("duration_us"),
598 "missing duration_us"
599 );
600 assert!(
601 evt.fields.contains_key("effect_duration_us"),
602 "missing effect_duration_us histogram"
603 );
604 }
605
606 #[test]
607 fn record_command_effect_emits_span() {
608 let handle = with_captured_tracing(|| {
609 record_command_effect("clipboard", 150);
610 });
611
612 let spans = handle.spans();
613 let cmd_spans: Vec<_> = spans
614 .iter()
615 .filter(|s| s.name == "effect.command")
616 .collect();
617 assert!(!cmd_spans.is_empty());
618 assert_eq!(
619 cmd_spans[0].fields.get("command_type").unwrap(),
620 "clipboard"
621 );
622 }
623
624 #[test]
629 fn record_subscription_start_emits_span() {
630 let handle = with_captured_tracing(|| {
631 record_subscription_start("timer", 42);
632 });
633
634 let spans = handle.spans();
635 let sub_spans: Vec<_> = spans
636 .iter()
637 .filter(|s| s.name == "effect.subscription")
638 .collect();
639 assert!(!sub_spans.is_empty(), "expected effect.subscription span");
640 assert!(sub_spans[0].fields.contains_key("sub_type"));
641 assert!(sub_spans[0].fields.contains_key("active"));
642 }
643
644 #[test]
645 fn record_subscription_stop_emits_span() {
646 let handle = with_captured_tracing(|| {
647 record_subscription_stop("keyboard", 7, 100);
648 });
649
650 let spans = handle.spans();
651 let sub_spans: Vec<_> = spans
652 .iter()
653 .filter(|s| s.name == "effect.subscription")
654 .collect();
655 assert!(!sub_spans.is_empty());
656 assert!(sub_spans[0].fields.contains_key("event_count"));
657 }
658
659 #[test]
664 fn warn_effect_timeout_emits_warn_event() {
665 let handle = with_captured_tracing(|| {
666 warn_effect_timeout("task", 500_000);
667 });
668
669 let events = handle.events();
670 let warn_events: Vec<_> = events
671 .iter()
672 .filter(|e| e.level == tracing::Level::WARN && e.target == "ftui.effect")
673 .collect();
674 assert!(!warn_events.is_empty(), "expected WARN event for timeout");
675 }
676
677 #[test]
678 fn error_effect_panic_emits_error_event() {
679 let handle = with_captured_tracing(|| {
680 error_effect_panic("subscription", "thread panicked");
681 });
682
683 let events = handle.events();
684 let error_events: Vec<_> = events
685 .iter()
686 .filter(|e| e.level == tracing::Level::ERROR && e.target == "ftui.effect")
687 .collect();
688 assert!(!error_events.is_empty(), "expected ERROR event for panic");
689 }
690
691 #[test]
696 fn counter_accessors_callable() {
697 let cmd = effects_command_total();
698 let sub = effects_subscription_total();
699 let total = effects_executed_total();
700 assert_eq!(total, cmd + sub);
701 }
702
703 #[test]
704 fn counters_increment_on_command() {
705 let before = effects_command_total();
706 trace_command_effect("test", || {});
707 let after = effects_command_total();
708 assert!(
709 after > before,
710 "command counter should increment: {before} → {after}"
711 );
712 }
713
714 #[test]
715 fn counters_increment_on_subscription() {
716 let before = effects_subscription_total();
717 record_subscription_start("test", 1);
718 let after = effects_subscription_total();
719 assert!(
720 after > before,
721 "subscription counter should increment: {before} → {after}"
722 );
723 }
724
725 #[test]
730 fn queue_enqueue_increments_counter() {
731 let before = effects_queue_enqueued();
732 record_queue_enqueue(1);
733 let after = effects_queue_enqueued();
734 assert!(after > before, "enqueued counter should increment");
735 }
736
737 #[test]
738 fn queue_processed_increments_counter() {
739 let before = effects_queue_processed();
740 record_queue_processed();
741 let after = effects_queue_processed();
742 assert!(after > before, "processed counter should increment");
743 }
744
745 #[test]
746 fn queue_drop_increments_counter() {
747 let before = effects_queue_dropped();
748 record_queue_drop("test");
749 let after = effects_queue_dropped();
750 assert!(after > before, "dropped counter should increment");
751 }
752
753 #[test]
754 fn queue_high_water_ratchets_upward() {
755 let before = effects_queue_high_water();
756 let new_mark = before + 100;
757 record_queue_enqueue(new_mark);
758 assert!(
759 effects_queue_high_water() >= new_mark,
760 "high-water should ratchet to at least {new_mark}"
761 );
762 record_queue_enqueue(1);
764 assert!(
765 effects_queue_high_water() >= new_mark,
766 "high-water should not decrease"
767 );
768 }
769
770 #[test]
771 fn queue_telemetry_snapshot_consistent() {
772 let snap = queue_telemetry();
773 assert_eq!(
778 snap.in_flight,
779 snap.enqueued.saturating_sub(snap.processed),
780 "in_flight should be enqueued - processed"
781 );
782 }
783
784 #[test]
789 fn dynamics_sub_start_increments() {
790 let before = subscription_starts_total();
791 record_dynamics_sub_start();
792 let after = subscription_starts_total();
793 assert!(after > before);
794 }
795
796 #[test]
797 fn dynamics_sub_stop_increments() {
798 let before = subscription_stops_total();
799 record_dynamics_sub_stop();
800 let after = subscription_stops_total();
801 assert!(after > before);
802 }
803
804 #[test]
805 fn dynamics_sub_panic_increments() {
806 let before = subscription_panics_total();
807 record_dynamics_sub_panic();
808 let after = subscription_panics_total();
809 assert!(after > before);
810 }
811
812 #[test]
813 fn dynamics_reconcile_records_count_and_duration() {
814 let before_count = reconcile_count();
815 let before_dur = reconcile_duration_us_total();
816 record_dynamics_reconcile(500);
817 assert!(reconcile_count() > before_count);
818 assert!(reconcile_duration_us_total() >= before_dur + 500);
819 }
820
821 #[test]
822 fn dynamics_shutdown_records_duration() {
823 record_dynamics_shutdown(1234, 2);
824 assert_eq!(shutdown_duration_us_last(), 1234);
825 let timeouts = shutdown_timed_out_total();
826 assert!(timeouts >= 2);
827 }
828
829 #[test]
830 fn dynamics_snapshot_consistent() {
831 let snap = runtime_dynamics();
832 assert_eq!(
833 snap.sub_active_estimate,
834 snap.sub_starts.saturating_sub(snap.sub_stops),
835 "active estimate = starts - stops"
836 );
837 if snap.reconciles > 0 {
838 assert!(
839 snap.reconcile_avg_us > 0 || reconcile_duration_us_total() == 0,
840 "avg should be > 0 when reconciles happened with non-zero duration"
841 );
842 }
843 }
844}