iris-chat 0.1.57

//! Minimal millisecond-resolution perf logger that writes straight to
//! Android logcat (or stderr off-Android with `IRIS_PERF_LOG=1`) without pulling in `log` +
//! `android_logger` crates. Used to diagnose where time goes between an
//! FFI dispatch, the core thread processing, and the UI reconcile.

use std::time::{Instant, SystemTime, UNIX_EPOCH};

#[inline]
pub fn now_ms() -> u64 {
    SystemTime::now()
        .duration_since(UNIX_EPOCH)
        .map(|d| d.as_millis() as u64)
        .unwrap_or(0)
}

#[cfg(target_os = "android")]
mod sink {
    use std::ffi::CString;

    // ANDROID_LOG_INFO = 4
    const ANDROID_LOG_INFO: i32 = 4;

    extern "C" {
        fn __android_log_write(prio: i32, tag: *const u8, msg: *const u8) -> i32;
    }

    pub fn write(tag: &str, msg: &str) {
        // CString allocation is cheap; instrumentation hot path is rare.
        if let (Ok(t), Ok(m)) = (CString::new(tag), CString::new(msg)) {
            unsafe {
                __android_log_write(
                    ANDROID_LOG_INFO,
                    t.as_ptr() as *const u8,
                    m.as_ptr() as *const u8,
                );
            }
        }
    }

    pub fn enabled() -> bool {
        cfg!(debug_assertions) || option_env!("IRIS_PERF_LOG").is_some()
    }
}

#[cfg(not(target_os = "android"))]
mod sink {
    use std::sync::OnceLock;

    pub fn enabled() -> bool {
        static ENABLED: OnceLock<bool> = OnceLock::new();
        *ENABLED.get_or_init(|| {
            std::env::var("IRIS_PERF_LOG")
                .map(|value| {
                    let value = value.trim().to_ascii_lowercase();
                    !value.is_empty() && value != "0" && value != "false" && value != "off"
                })
                .unwrap_or(false)
        })
    }

    pub fn write(tag: &str, msg: &str) {
        eprintln!("{tag}: {msg}");
    }
}

/// `IrisPerf` tag — `adb logcat IrisPerf:I *:S` shows only these.
#[macro_export]
macro_rules! perflog {
    ($($arg:tt)*) => {
        if $crate::perflog::__enabled() {
            $crate::perflog::__write(format_args!($($arg)*))
        }
    };
}

#[doc(hidden)]
pub fn __enabled() -> bool {
    sink::enabled()
}

#[doc(hidden)]
pub fn __write(args: std::fmt::Arguments<'_>) {
    if !sink::enabled() {
        return;
    }
    let msg = format!("{} {}", now_ms(), args);
    sink::write("IrisPerf", &msg);
}

fn monotonic_us() -> u128 {
    static START: std::sync::OnceLock<Instant> = std::sync::OnceLock::new();
    START.get_or_init(Instant::now).elapsed().as_micros()
}

pub(crate) fn event(label: &'static str) {
    crate::perflog!("phase.event label={label} monotonic_us={}", monotonic_us());
}

pub(crate) fn phase(label: &'static str) -> Option<Phase> {
    if !sink::enabled() {
        return None;
    }
    let phase = Phase {
        label,
        started: Instant::now(),
    };
    crate::perflog!("phase.start label={label} monotonic_us={}", monotonic_us());
    Some(phase)
}

pub(crate) struct Phase {
    label: &'static str,
    started: Instant,
}

impl Drop for Phase {
    fn drop(&mut self) {
        crate::perflog!(
            "phase.end label={} elapsed_us={}",
            self.label,
            self.started.elapsed().as_micros()
        );
    }
}