gallery/vendor/i-slint-backend-android-activity-1.18.1/stg.rs

//! STG (stage-timestamp) instrumentation for the jank hunt, 2026-10-28.
//!
//! The app's FR hook (rendering notifier) measures render cost and frame
//! gaps; this measures what happens AROUND rendering inside the event
//! loop: Choreographer wake latency, timer callbacks (the app's 8 ms
//! drain tick runs in `update_timers_and_animations`), and event
//! processing. Timestamps are plain atomics — the UI thread only does
//! atomic loads/stores here; the APP formats the log line from its own
//! tick (never log from the UI thread: logd backpressure).

use std::sync::atomic::{AtomicBool, AtomicU32, AtomicU64, Ordering};
/// CLOCK_THREAD_CPUTIME_ID microseconds for the current thread — for a slow
/// window, wall ≫ cpu ⇒ the thread was off-CPU (descheduled/blocked).
pub fn thread_cpu_us() -> u64 {
    #[repr(C)]
    struct Ts {
        tv_sec: i64,
        tv_nsec: i64,
    }
    unsafe extern "C" {
        fn clock_gettime(clkid: i32, tp: *mut Ts) -> i32;
    }
    const CLOCK_THREAD_CPUTIME_ID: i32 = 3;
    let mut ts = Ts { tv_sec: 0, tv_nsec: 0 };
    if unsafe { clock_gettime(CLOCK_THREAD_CPUTIME_ID, &mut ts) } == 0 {
        ts.tv_sec as u64 * 1_000_000 + ts.tv_nsec as u64 / 1000
    } else {
        0
    }
}

/// CLOCK_MONOTONIC microseconds — the SAME clock as PRES/VSYNC mon= (the
/// renderer's monotonic_ns) and the vkshim's ts=, so IT lines can be
/// correlated frame-by-frame offline.
pub fn now_us() -> u64 {
    #[repr(C)]
    struct Ts {
        tv_sec: i64,
        tv_nsec: i64,
    }
    unsafe extern "C" {
        fn clock_gettime(clkid: i32, tp: *mut Ts) -> i32;
    }
    const CLOCK_MONOTONIC: i32 = 1;
    let mut ts = Ts { tv_sec: 0, tv_nsec: 0 };
    if unsafe { clock_gettime(CLOCK_MONOTONIC, &mut ts) } == 0 {
        ts.tv_sec as u64 * 1_000_000 + ts.tv_nsec as u64 / 1000
    } else {
        0
    }
}

// Per-iteration stage marks (us since process start); reset at loop top.
pub static S_START: AtomicU64 = AtomicU64::new(0);
pub static S_FIRST_EV: AtomicU64 = AtomicU64::new(0);
pub static S_POLL_END: AtomicU64 = AtomicU64::new(0);
pub static S_RENDER_START: AtomicU64 = AtomicU64::new(0);
pub static S_RENDER_END: AtomicU64 = AtomicU64::new(0);
// Accumulated per-iteration costs.
pub static S_TIMER_US: AtomicU64 = AtomicU64::new(0);
pub static S_EVENT_US: AtomicU64 = AtomicU64::new(0);
pub static S_N_EVENTS: AtomicU64 = AtomicU64::new(0);
// Full do_render duration of the PREVIOUS iteration (the AfterRendering
// hook fires mid-render, so the current iteration's render can't be read
// yet): covers renderer.draw PLUS the wgpu surface tail (flush_and_submit
// gr_context.submit + queue.present — the Mali driver calls).
pub static S_LAST_RENDER_US: AtomicU64 = AtomicU64::new(0);

// Pointer-activity tracking for vsync pacing. While the user is dragging
// (finger down + moving), Slint has NO active animation (content-y is set
// directly by pointer events, not a physics animation), so
// `has_active_animations()` is false and the vsync driver sleeps. Without
// vsync pacing the event loop then sleeps until the next timer (16 ms on
// this app), producing 16-30 ms frame gaps = visible jank. We stamp a
// "pointer active until" deadline on every motion event so the event loop
// keeps the vsync driver running for a short window after the last touch,
// covering the direct drag; the momentum fling is covered separately by
// `has_active_animations()` (the physics animation). See
// docs/BUGS/scroll-jank-120hz.md.
pub static POINTER_ACTIVE_UNTIL_US: AtomicU64 = AtomicU64::new(0);
/// How long after the last motion event we keep vsync pacing alive (µs).
/// Short on purpose: after the finger lifts, the fling's physics animation
/// takes over (has_active_animations), and when idle we want the loop to
/// sleep to save battery.
pub const POINTER_PACING_WINDOW_US: u64 = 200_000;

pub fn note_pointer_activity() {
    POINTER_ACTIVE_UNTIL_US
        .store(now_us().saturating_add(POINTER_PACING_WINDOW_US), Ordering::Relaxed);
}

pub fn pointer_recently_active() -> bool {
    now_us() < POINTER_ACTIVE_UNTIL_US.load(Ordering::Relaxed)
}

// Input-batch probes: how many native input events arrive in one
// `InputAvailable` batch, and how long `process_inputs` takes. A large
// batch means the app let input pile up (it wasn't reading fast enough),
// and draining the backlog in one event handler shows up as a big `ev` spike
// (poll==ev, render=0). See docs/BUGS/scroll-jank-120hz.md.
pub static INPUT_BATCH_MAX: AtomicU32 = AtomicU32::new(0);
pub static INPUT_BATCH_TOTAL_EV: AtomicU64 = AtomicU64::new(0);
pub static INPUT_PROCES_MAX_US: AtomicU64 = AtomicU64::new(0);

pub fn input_note_batch(n: u32, proc_us: u64) {
    let cur = INPUT_BATCH_MAX.load(Ordering::Relaxed);
    if n > cur {
        INPUT_BATCH_MAX.store(n, Ordering::Relaxed);
        // remember the proc time that went with the biggest batch
        INPUT_BATCH_TOTAL_EV.store(proc_us, Ordering::Relaxed);
    }
    let c2 = INPUT_PROCES_MAX_US.load(Ordering::Relaxed);
    if proc_us > c2 {
        INPUT_PROCES_MAX_US.store(proc_us, Ordering::Relaxed);
    }
}

pub fn input_snapshot() -> (u32, u64, u64) {
    (
        INPUT_BATCH_MAX.load(Ordering::Relaxed),
        INPUT_BATCH_TOTAL_EV.load(Ordering::Relaxed),
        INPUT_PROCES_MAX_US.load(Ordering::Relaxed),
    )
}

/// Log a single event whose `process_event` took longer than the threshold.
/// Lets us identify WHICH MainEvent variant is responsible for the big `ev`
/// spikes (pointer input is ~2.5 ms max, so a 20 ms event is something else).
/// Timeout-path counters: how often the loop's poll timeout is forced to
/// ZERO (because `pending_redraw` was set at iteration start) vs the 6 ms
/// animation cap vs a natural (larger) timer. A high ZERO count means the
/// loop is busy-spinning instead of sleeping between frames.
pub static TO_ZERO_COUNT: AtomicU64 = AtomicU64::new(0);
pub static TO_CAP_COUNT: AtomicU64 = AtomicU64::new(0);
pub static TO_NATURAL_COUNT: AtomicU64 = AtomicU64::new(0);

pub fn note_timeout_class(kind: u8) {
    match kind {
        0 => { TO_ZERO_COUNT.fetch_add(1, Ordering::Relaxed); }
        1 => { TO_CAP_COUNT.fetch_add(1, Ordering::Relaxed); }
        _ => { TO_NATURAL_COUNT.fetch_add(1, Ordering::Relaxed); }
    }
}

pub fn timeout_snapshot() -> (u64, u64, u64) {
    (
        TO_ZERO_COUNT.load(Ordering::Relaxed),
        TO_CAP_COUNT.load(Ordering::Relaxed),
        TO_NATURAL_COUNT.load(Ordering::Relaxed),
    )
}

/// Wake-source counters: how many times each PollEvent variant was delivered
/// to the loop. WAKE >> 120/s (vsync) means spurious waker firing.
pub static WAKE_COUNT: AtomicU64 = AtomicU64::new(0);
pub static TIMEOUT_EV_COUNT: AtomicU64 = AtomicU64::new(0);
pub static INPUT_EV_COUNT: AtomicU64 = AtomicU64::new(0);

pub fn wake_snapshot() -> (u64, u64, u64) {
    (
        WAKE_COUNT.load(Ordering::Relaxed),
        TIMEOUT_EV_COUNT.load(Ordering::Relaxed),
        INPUT_EV_COUNT.load(Ordering::Relaxed),
    )
}

pub fn log_slow_event(name: &str, us: u64, cpu_us: u64) {
    // Via the log facade (nblog) so ordering with the other perf lines is
    // preserved (single writer; see log_iter's comment). cpu_us = the
    // thread's own CPU time inside the window: wall≫cpu ⇒ off-CPU
    // (descheduled/blocked), wall≈cpu ⇒ pure CPU work.
    log::info!("SLOWEV {} {}us cpu={}us", name, us, cpu_us);
}

/// Slot-ledger (hypotheses-120hz.md): a wake arrived for a slot >= 2 past
/// the last rendered slot — the intermediate slot(s) produced NO frame.
/// nowake = whether THIS wake was seen (a no-wake iteration precedes it).
/// This line is the missing evidence for the 20-100 ms stall slots:
///   saw_wake=true  ⇒ the previous slots' wakes were LOST (eventfd/waker)
///   nowake context + slow poll/ev in the preceding IT line ⇒ loop blocked
/// sw/sn = the wake's and last-render's edge-grid slot indices; eage_ms =
/// how stale the edge reference (VSYNC_EDGE_NS) is (ms); lastage_ms = how
/// old the last render start is (ms). Diagnosis from these:
///   sw <= sn with eage small  ⇒ guard arithmetic (slot grid) bug
///   sw > sn but saw_wake=0    ⇒ no Wake arrived (chain dead / eventfd lost)
///   eage large (>> 2 slots)   ⇒ Choreographer callbacks stalled; the edge
///                               grid is stale and slot math is garbage —
///                               the callback CHAIN is the failure
///   lastage huge + saw_wake=1 ⇒ loop was stuck (see IT line / ctxsw)
pub fn log_miss(slots: i128, saw_wake: bool, now_ns: u64, sw: i128, sn: i128,
               eage_us: u64, lastage_us: u64) {
    log::info!("MISS mon={} slots={} nowake={} sw={} sn={} eage={}us lastage={}us",
        now_ns, slots, if saw_wake { 1 } else { 0 }, sw, sn, eage_us, lastage_us);
}

/// Context-switch counters for the UI (main) thread, sampled from
/// /proc/self/task/<pid>/stat (main thread: pid == tid). Called twice per
/// iteration (start/end); the delta attributes the iteration:
///   vsw high,  pcpu low  ⇒ thread VOLUNTARILY blocked (epoll with no wake
///                           byte, futex/lock, IO, binder — "waiting on
///                           something")
///   nvol high, pcpu low  ⇒ SCHEDULER descheduled it (priority/pressure)
///   pcpu ≈ wall           ⇒ ran on CPU (Skia/driver work)
/// Rolling baseline of the last ctxsw sample (CONDITIONAL sampling — see
/// lib.rs): the delta reported on a slow iteration spans [previous slow
/// iteration .. this slow iteration]. Coarse, but enough to separate
/// voluntary-blocking from involuntary-descheduling windows.
pub static CTX_PREV_V: AtomicU64 = AtomicU64::new(0);
pub static CTX_PREV_NV: AtomicU64 = AtomicU64::new(0);
pub static CTX_SAMPLED: AtomicBool = AtomicBool::new(false);

pub fn ctxsw_sample() -> (u64, u64) {
    use std::io::{Read, Seek, SeekFrom};
    static F: std::sync::Mutex<Option<std::fs::File>> = std::sync::Mutex::new(None);
    let mut g = match F.lock() { Ok(g) => g, Err(_) => return (0, 0) };
    if g.is_none() {
        let p = format!("/proc/self/task/{}/stat", std::process::id());
        *g = std::fs::File::open(p).ok();
    }
    let f = match g.as_mut() { Some(f) => f, None => return (0, 0) };
    let _ = f.seek(SeekFrom::Start(0));
    let mut buf = [0u8; 600];
    let n = match f.read(&mut buf) { Ok(n) => n, Err(_) => return (0, 0) };
    let s = String::from_utf8_lossy(&buf[..n]);
    let after = match s.rfind(')') { Some(i) => &s[i + 2..], None => return (0, 0) };
    let toks: Vec<&str> = after.split_whitespace().collect();
    // after ')': tok[0] = field 3 (state) … field 40 (voluntary) = tok[37],
    // field 41 (nonvoluntary) = tok[38]
    match (toks.get(37).and_then(|t| t.parse().ok()),
           toks.get(38).and_then(|t| t.parse().ok())) {
        (Some(v), Some(nv)) => (v, nv),
        _ => (0, 0),
    }
}

/// Jank-hunt: total `invoke_from_event_loop` pushes (INVK n=..).
pub static INVK_PUSH_COUNT: AtomicU64 = AtomicU64::new(0);

/// Jank-hunt: serial counter for slow `Event::Other` closures drained in
/// `process_event` (OTHR n=..).
pub static OTHER_CLOSE_COUNT: AtomicU64 = AtomicU64::new(0);

/// Log a raw perf line through the facade (ordering-preserving).
pub fn log_line(line: &str) {
    log::info!("{line}");
}

// Per-iteration logging: records EVERY loop iteration (render or not)
// so the time inside an FR gap can be accounted for iteration by
// iteration. Off by default; the app enables it for jank hunts.
pub static IT_ON: AtomicBool = AtomicBool::new(false);

/// Jank-hunt / 120Hz: when set, the event loop renders on every vsync wake
/// while animating (vsync-locked present phase). OFF by default; sltest (and
/// the A/B test) opt in.
pub static VSYNC_LOCKED_RENDER: AtomicBool = AtomicBool::new(false);

/// ListView probes: (virtualized-pass-ms, rows-created-in-it, eager-last-count,
/// eager-max-count, eager-calls).
pub fn lv_snapshot() -> (u64, u32, u32, u32, u64, u64, u64) {
    use i_slint_core::model::repeater as r;
    (
        r::LV_LAST_PASS_MS.load(Ordering::Relaxed),
        r::LV_CREATED_ROWS.load(Ordering::Relaxed),
        r::LV_EAGER_LAST_COUNT.load(Ordering::Relaxed),
        r::LV_EAGER_MAX_COUNT.load(Ordering::Relaxed),
        r::LV_EAGER_CALLS.load(Ordering::Relaxed),
        r::LV_LISTVIEW_ENTRY_CALLS.load(Ordering::Relaxed),
        r::LV_EAGER_ENTRY_CALLS.load(Ordering::Relaxed),
    )
}

/// Flickable pointer-handling probes: (handle_mouse_max_us,
/// content_y_set_max_us). These are running maxima since process start,
/// used to confirm whether the 16 ms event spikes are inside
/// Flickable::handle_mouse and, within it, the content_x/y `.set()` call.
pub fn flick_snapshot() -> (u64, u64) {
    use i_slint_core::items::flickable as f;
    (
        f::FLICK_MOUSE_MAX_US.load(Ordering::Relaxed),
        f::FLICK_CONTENTSET_MAX_US.load(Ordering::Relaxed),
    )
}

/// Log one event-loop iteration. `start_us` is the iteration start time
/// (stg clock); all other costs are microseconds. `lv1` = last ListView
/// pass at poll-end (input-triggered), `lv2` = at iteration end
/// (render-triggered): (pass-ms, rows-created).
pub fn log_iter(
    start_us: u64,
    poll_us: u64,
    nev: u64,
    first_ev_us: u64,
    timer_us: u64,
    event_us: u64,
    render_us: u64,
    animating: bool,
    timeout_ms: u64,
    lv1: (u64, u32, u32, u32, u64, u64, u64),
    lv2: (u64, u32, u32, u32, u64, u64, u64),
    flk: (u64, u64),
    inp: (u32, u64, u64),
    tocls: (u64, u64, u64),
    wk: (u64, u64, u64),
    dec: (bool, bool, bool, bool),
    poll_cpu_us: u64,
    render_cpu_us: u64,
    vsw: u64,
    nvol: u64,
) {
    // Jank-hunt fix: emit through the log facade (nblog) instead of a private
    // BufWriter — two independent buffers appending to the same file made IT
    // lines land out of order (flush-blocked), breaking per-gap correlation.
    // nblog is non-blocking (the drain thread does the I/O).
    let live_rows = i_slint_core::model::repeater::LV_LIVE_ROWS
        .load(std::sync::atomic::Ordering::Relaxed);
    log::info!(
        "IT {} poll={}us nev={} fe={}us timers={}us ev={}us render={}us anim={} to={}ms lv1={}/{} e={}/{}/{} ent={}/{} lv2={}/{} flk={}/{} inb={}/{} toc={}/{}/{} wk={}/{}/{} live={} dec={}/{}/{}/{} pcpu={}us rcpu={}us vsw={} nvol={}",
        start_us, poll_us, nev, first_ev_us, timer_us, event_us, render_us, animating as u8, timeout_ms,
        lv1.0, lv1.1, lv1.2, lv1.3, lv1.4, lv1.5, lv1.6, lv2.0, lv2.1, flk.0, flk.1, inp.0, inp.2, tocls.0, tocls.1, tocls.2, wk.0, wk.1, wk.2, live_rows,
        dec.0 as u8, dec.1 as u8, dec.2 as u8, dec.3 as u8, poll_cpu_us, render_cpu_us, vsw, nvol
    );
}

/// One iteration of the event loop: start, first-event, poll-end,
/// render-start, render-end, timer-us, event-us, n-events.
pub fn snapshot() -> (u64, u64, u64, u64, u64, u64, u64, u64) {
    (
        S_START.load(Ordering::Relaxed),
        S_FIRST_EV.load(Ordering::Relaxed),
        S_POLL_END.load(Ordering::Relaxed),
        S_RENDER_START.load(Ordering::Relaxed),
        S_RENDER_END.load(Ordering::Relaxed),
        S_TIMER_US.load(Ordering::Relaxed),
        S_EVENT_US.load(Ordering::Relaxed),
        S_N_EVENTS.load(Ordering::Relaxed),
    )
}