iris_chat_core/
perflog.rs

1//! Minimal millisecond-resolution perf logger that writes straight to
2//! Android logcat (or stderr off-Android with `IRIS_PERF_LOG=1`) without pulling in `log` +
3//! `android_logger` crates. Used to diagnose where time goes between an
4//! FFI dispatch, the core thread processing, and the UI reconcile.
5
6use std::time::{Instant, SystemTime, UNIX_EPOCH};
7
8#[inline]
9pub fn now_ms() -> u64 {
10    SystemTime::now()
11        .duration_since(UNIX_EPOCH)
12        .map(|d| d.as_millis() as u64)
13        .unwrap_or(0)
14}
15
16#[cfg(target_os = "android")]
17mod sink {
18    use std::ffi::CString;
19
20    // ANDROID_LOG_INFO = 4
21    const ANDROID_LOG_INFO: i32 = 4;
22
23    extern "C" {
24        fn __android_log_write(prio: i32, tag: *const u8, msg: *const u8) -> i32;
25    }
26
27    pub fn write(tag: &str, msg: &str) {
28        // CString allocation is cheap; instrumentation hot path is rare.
29        if let (Ok(t), Ok(m)) = (CString::new(tag), CString::new(msg)) {
30            unsafe {
31                __android_log_write(
32                    ANDROID_LOG_INFO,
33                    t.as_ptr() as *const u8,
34                    m.as_ptr() as *const u8,
35                );
36            }
37        }
38    }
39
40    pub fn enabled() -> bool {
41        cfg!(debug_assertions) || option_env!("IRIS_PERF_LOG").is_some()
42    }
43}
44
45#[cfg(not(target_os = "android"))]
46mod sink {
47    use std::sync::OnceLock;
48
49    pub fn enabled() -> bool {
50        static ENABLED: OnceLock<bool> = OnceLock::new();
51        *ENABLED.get_or_init(|| {
52            std::env::var("IRIS_PERF_LOG")
53                .map(|value| {
54                    let value = value.trim().to_ascii_lowercase();
55                    !value.is_empty() && value != "0" && value != "false" && value != "off"
56                })
57                .unwrap_or(false)
58        })
59    }
60
61    pub fn write(tag: &str, msg: &str) {
62        eprintln!("{tag}: {msg}");
63    }
64}
65
66/// `IrisPerf` tag — `adb logcat IrisPerf:I *:S` shows only these.
67#[macro_export]
68macro_rules! perflog {
69    ($($arg:tt)*) => {
70        if $crate::perflog::__enabled() {
71            $crate::perflog::__write(format_args!($($arg)*))
72        }
73    };
74}
75
76#[doc(hidden)]
77pub fn __enabled() -> bool {
78    sink::enabled()
79}
80
81#[doc(hidden)]
82pub fn __write(args: std::fmt::Arguments<'_>) {
83    if !sink::enabled() {
84        return;
85    }
86    let msg = format!("{} {}", now_ms(), args);
87    sink::write("IrisPerf", &msg);
88}
89
90fn monotonic_us() -> u128 {
91    static START: std::sync::OnceLock<Instant> = std::sync::OnceLock::new();
92    START.get_or_init(Instant::now).elapsed().as_micros()
93}
94
95pub(crate) fn event(label: &'static str) {
96    crate::perflog!("phase.event label={label} monotonic_us={}", monotonic_us());
97}
98
99pub(crate) fn phase(label: &'static str) -> Option<Phase> {
100    if !sink::enabled() {
101        return None;
102    }
103    let phase = Phase {
104        label,
105        started: Instant::now(),
106    };
107    crate::perflog!("phase.start label={label} monotonic_us={}", monotonic_us());
108    Some(phase)
109}
110
111pub(crate) struct Phase {
112    label: &'static str,
113    started: Instant,
114}
115
116impl Drop for Phase {
117    fn drop(&mut self) {
118        crate::perflog!(
119            "phase.end label={} elapsed_us={}",
120            self.label,
121            self.started.elapsed().as_micros()
122        );
123    }
124}
iris_chat_core/perflog.rs

iris_chat_core/
perflog.rs
