Files
xenia-rs/crates/xenia-kernel/src/event_log.rs
MechaCat02 ad45873a1b ITERATE-2.V: scheduler priority aging closes 18-day AUDIT-049 wedge
Priority aging in xenia-cpu/scheduler.rs:pick_runnable
(effective_priority = base + age_bonus(now_round - last_run_round),
capped at +31, AGING_ROUNDS_PER_BONUS=1). Strict-priority was parking
priority=0 threads behind CPU-bound priority=15 audio mixer
(sub_824D1328 guest spinwait at PC=0x824d1404 on CPU5). Aging
eventually picks the starved thread, breaking the producer-consumer
cycle that caused 5-tid wedge at PC=0x824ac578 since AUDIT-049 (10 May).

Cascade observed: tid=13 clean exit; events 121K -> 13M (107x); last
host_ns 767ms -> 51,011ms (66x); 8 new threads spawn; VdSwap 1 -> 2.

Complete two-day iterate sequence (2026-05-27 -> 2026-05-28):
- 2.F: VdSwap drain timeout 900ms -> 1ms (xenia-gpu/handle.rs); 876x
       perf win on VdSwap kernel callback
- 2.H: vA0000000 physical heap bucket added (state.rs, exports.rs);
       ctx_ptrs now in 0xA0000000-0xBFFFFFFF range matching canary
- 2.L: Phase-A diff harness categorized [return_value mismatch],
       [status mismatch], [args_resolved.path mismatch] tags
       (tools/diff-events/diff_events.py); closes reading-error #41
       (silent test-harness state leak invalidating trace diffs)
- 2.M: always-on exit-thread-state.json sibling to Phase-A JSONL
       (event_log.rs + xenia-app/main.rs); closes reading-error #42
       (Phase-A blind to blocked-forever waits)
- 2.Q: signal.match kernel instrumentation in NtSetEvent /
       NtReleaseSemaphore / KeSetEvent / KeReleaseSemaphore
       (exports.rs); emits target_handle + waiter_count + waiter_tids
- 2.T: wake.requested kernel instrumentation in wake_eligible_waiters
       (exports.rs); emits target_tid + transition + new_state
- 2.V: scheduler priority aging (xenia-cpu/scheduler.rs) [keystone]

Plus accumulated WIP from earlier May (contention_manifest,
phase_b_snapshot, xam/xaudio enhancements, analysis db, xex loader,
xenia-app main loop, etc.). Audit-runs/ artifacts remain untracked
per project convention.

Tests: 300 xenia-cpu / 227 xenia-kernel / 5 xenia-app / 19 xenia-path
/ 30+ smaller suites -- all PASS, 0 regressions. Determinism preserved
(2x cold runs bit-identical at 13,003,881 events post-2.V).

Co-Authored-By: Claude Opus 4.7 <noreply@anthropic.com>
2026-05-29 07:27:26 +02:00

775 lines
28 KiB
Rust

//! Phase A event-log emitter. Schema v1 — see
//! `xenia-rs/audit-runs/phase-a-diff-harness/schema-v1.md`.
//!
//! Cvar-gated (disabled by default). Zero cost when disabled:
//! `is_enabled()` is a relaxed atomic-bool load.
use std::collections::HashMap;
use std::fs::File;
use std::io::{BufWriter, Write};
use std::path::{Path, PathBuf};
use std::sync::atomic::{AtomicBool, Ordering};
use std::sync::{Mutex, OnceLock};
use std::time::Instant;
static ENABLED: AtomicBool = AtomicBool::new(false);
static SINK: OnceLock<Mutex<BufWriter<File>>> = OnceLock::new();
static T0: OnceLock<Instant> = OnceLock::new();
static TID_COUNTERS: OnceLock<Mutex<HashMap<u32, u64>>> = OnceLock::new();
/// Iterate 2.M (reading-error #42): record the Phase-A trace path so the
/// always-on exit-time thread-state dump can derive a sibling JSON path
/// without re-threading CLI flags through `cmd_exec_inner`. `None` when
/// Phase-A is disabled — exit-state dump falls back to a CWD-relative
/// default in that case.
static OUTPUT_PATH: OnceLock<PathBuf> = OnceLock::new();
/// Object-type codes — must match canary's enum exactly (schema-v1.md).
pub mod object_type {
pub const UNKNOWN: u32 = 0x00;
pub const EVENT: u32 = 0x01;
pub const MUTANT: u32 = 0x02;
pub const SEMAPHORE: u32 = 0x03;
pub const TIMER: u32 = 0x04;
pub const THREAD: u32 = 0x05;
pub const FILE: u32 = 0x06;
pub const IO_COMPLETION: u32 = 0x07;
pub const MODULE: u32 = 0x08;
pub const ENUM_STATE: u32 = 0x09;
pub const SECTION: u32 = 0x0A;
pub const NOTIFICATION: u32 = 0x0B;
/// Phase D Stage 1 (canary side) / Stage 3 (ours side): pseudo-type
/// used as the `object_type` input to `semantic_id_shared_global`
/// for RTL_CRITICAL_SECTION pointers. CS is NOT a real XObject
/// (it lives as a guest-memory struct, not a handle-tabled kernel
/// object), but the `site_sid` field of `contention.observed`
/// reuses the shared-global SID recipe so the Stage-3 manifest can
/// compute the same SID in both engines for the same CS pointer.
/// Must match canary's `kObjCriticalSection` exactly.
pub const CRITICAL_SECTION: u32 = 0x0C;
}
/// Initialize the emitter. Call from main once at startup with the
/// resolved path (CLI flag or env var). `None` keeps the emitter
/// disabled; cost is one relaxed atomic-bool check per emit call.
pub fn init(path: Option<&Path>) {
let _ = T0.set(Instant::now());
let Some(path) = path else {
return;
};
let _ = OUTPUT_PATH.set(path.to_path_buf());
let f = match File::create(path) {
Ok(f) => f,
Err(e) => {
eprintln!(
"phase-a event log: failed to open {:?}: {e} — disabled",
path
);
return;
}
};
let mut bw = BufWriter::new(f);
// Schema header (synthetic tid=0).
let host_ns = host_ns_since_start();
let _ = writeln!(
bw,
r#"{{"schema_version":1,"engine":"ours","kind":"schema_version","tid":0,"tid_event_idx":0,"guest_cycle":0,"host_ns":{host_ns},"deterministic":true,"payload":{{"version":1,"emitter_build":"ours-phaseA"}}}}"#
);
let _ = bw.flush();
if SINK.set(Mutex::new(bw)).is_err() {
// Already initialized — leave alone.
return;
}
let _ = TID_COUNTERS.set(Mutex::new(HashMap::new()));
ENABLED.store(true, Ordering::Release);
}
#[inline]
pub fn is_enabled() -> bool {
ENABLED.load(Ordering::Relaxed)
}
/// Path passed to `init()`, if any. Used by the iterate-2.M exit-state
/// dump so the sibling JSON lands next to the Phase-A JSONL trace.
pub fn output_path() -> Option<&'static Path> {
OUTPUT_PATH.get().map(|p| p.as_path())
}
fn host_ns_since_start() -> u128 {
let t0 = T0.get_or_init(Instant::now);
t0.elapsed().as_nanos()
}
fn next_tid_idx(tid: u32) -> u64 {
let map = TID_COUNTERS.get().expect("event_log not initialized");
let mut g = map.lock().unwrap();
let entry = g.entry(tid).or_insert(0);
let idx = *entry;
*entry = idx + 1;
idx
}
/// Peek next tid_event_idx without consuming it. Useful for handle
/// semantic-id computation that needs to match what the next emit will use.
pub fn peek_tid_idx(tid: u32) -> u64 {
let Some(map) = TID_COUNTERS.get() else {
return 0;
};
let g = map.lock().unwrap();
*g.get(&tid).unwrap_or(&0)
}
/// FNV-1a 64-bit. Identical implementation in canary (see event_log.cc).
pub fn semantic_id(
create_site_pc: u32,
creating_tid: u32,
tid_event_idx_at_creation: u64,
object_type: u32,
) -> u64 {
let mut bytes = [0u8; 4 + 4 + 8 + 4];
bytes[0..4].copy_from_slice(&create_site_pc.to_le_bytes());
bytes[4..8].copy_from_slice(&creating_tid.to_le_bytes());
bytes[8..16].copy_from_slice(&tid_event_idx_at_creation.to_le_bytes());
bytes[16..20].copy_from_slice(&object_type.to_le_bytes());
let mut h: u64 = 0xCBF29CE484222325;
for b in bytes.iter() {
h ^= *b as u64;
h = h.wrapping_mul(0x100000001B3);
}
h
}
/// Phase C+18: marker sentinel used as `create_site_pc` in
/// `semantic_id_shared_global` so the resulting SID is distinguishable
/// from regular per-thread handle SIDs (which use real guest PCs that
/// never collide with this value). Picked outside any plausible guest
/// code-address range. Both engines MUST use this exact constant.
pub const SHARED_GLOBAL_SID_MARKER: u32 = 0xC01AB005;
/// Phase C+18: scheduling-invariant SID for **process-global** kernel
/// dispatcher objects that are lazy-wrapped on first guest-thread touch
/// (see ours's `ensure_dispatcher_object` and canary's
/// `XObject::GetNativeObject`).
///
/// Whichever guest thread happens to be the first to touch a given
/// dispatcher pointer synthesizes the wrapper, but **which** thread wins
/// is timing-dependent and differs between canary and ours (and between
/// runs of the same engine). The regular per-thread `semantic_id`
/// recipe — keyed on `(create_site_pc, creating_tid, tid_event_idx)` —
/// therefore produces different SIDs in each engine for the same logical
/// object.
///
/// This helper keys on `(SHARED_GLOBAL_SID_MARKER, 0, pointer, object_type)`
/// so the SID depends only on the object's identity, not on the
/// scheduling order. Subsequent `wait.begin` events that reference the
/// dispatcher resolve a stable cross-engine SID, and the diff tool can
/// use SID equality to cross-tid match the floating `handle.create`
/// event.
///
/// Per the schema-v1 SID API, the inputs are still fed to the existing
/// `semantic_id()` FNV-1a function unchanged — we just choose inputs
/// that are scheduling-invariant. No new wire format.
pub fn semantic_id_shared_global(pointer: u32, object_type: u32) -> u64 {
semantic_id(
SHARED_GLOBAL_SID_MARKER,
0,
pointer as u64,
object_type,
)
}
fn write_line(line: &str) {
let Some(sink) = SINK.get() else { return };
let mut g = sink.lock().unwrap();
let _ = g.write_all(line.as_bytes());
let _ = g.write_all(b"\n");
let _ = g.flush();
}
fn json_escape(s: &str) -> String {
let mut out = String::with_capacity(s.len() + 2);
for c in s.chars() {
match c {
'\\' => out.push_str("\\\\"),
'"' => out.push_str("\\\""),
'\n' => out.push_str("\\n"),
'\r' => out.push_str("\\r"),
'\t' => out.push_str("\\t"),
c if (c as u32) < 0x20 => {
out.push_str(&format!("\\u{:04x}", c as u32));
}
c => out.push(c),
}
}
out
}
#[inline]
fn common_prefix(
kind: &str,
tid: u32,
idx: u64,
guest_cycle: u64,
deterministic: bool,
) -> String {
let host_ns = host_ns_since_start();
let det = if deterministic { "true" } else { "false" };
format!(
r#"{{"schema_version":1,"engine":"ours","kind":"{kind}","tid":{tid},"tid_event_idx":{idx},"guest_cycle":{guest_cycle},"host_ns":{host_ns},"deterministic":{det}"#
)
}
pub fn emit_import_call(tid: u32, guest_cycle: u64, module: &str, ord: u16, name: &str) {
if !is_enabled() {
return;
}
let idx = next_tid_idx(tid);
let mut line = common_prefix("import.call", tid, idx, guest_cycle, true);
line.push_str(&format!(
r#","payload":{{"module":"{}","ord":{},"name":"{}"}}}}"#,
json_escape(module),
ord,
json_escape(name)
));
write_line(&line);
}
pub fn emit_kernel_call(tid: u32, guest_cycle: u64, name: &str) {
if !is_enabled() {
return;
}
let idx = next_tid_idx(tid);
let mut line = common_prefix("kernel.call", tid, idx, guest_cycle, true);
line.push_str(&format!(
r#","payload":{{"name":"{}","args":{{}},"args_resolved":{{}}}}}}"#,
json_escape(name)
));
write_line(&line);
}
/// Phase C+10 schema-v1 extension: emit a `kernel.call` event whose
/// `args_resolved` field carries a best-effort dereferenced path string.
///
/// Schema-v1 already allows `args_resolved` to be a free-form object
/// (see schema-v1.md kernel.call payload), so this remains v1-compatible.
/// Cvar-gated default-off via `is_enabled()`. When the path is empty or
/// resolution failed, the caller should pass `None` and we degrade to the
/// existing empty-object form so emitter output is byte-identical to the
/// pre-extension behavior.
///
/// Determinism: the resolved path is read directly out of guest memory
/// (OBJECT_ATTRIBUTES → ANSI_STRING → bytes). It is fully deterministic
/// across runs of the same input. The event-level `deterministic:true`
/// flag is preserved.
pub fn emit_kernel_call_with_path(
tid: u32,
guest_cycle: u64,
name: &str,
path: Option<&str>,
) {
if !is_enabled() {
return;
}
let idx = next_tid_idx(tid);
let mut line = common_prefix("kernel.call", tid, idx, guest_cycle, true);
match path {
Some(p) if !p.is_empty() => {
line.push_str(&format!(
r#","payload":{{"name":"{}","args":{{}},"args_resolved":{{"path":"{}"}}}}}}"#,
json_escape(name),
json_escape(p)
));
}
_ => {
line.push_str(&format!(
r#","payload":{{"name":"{}","args":{{}},"args_resolved":{{}}}}}}"#,
json_escape(name)
));
}
}
write_line(&line);
}
pub fn emit_kernel_return(tid: u32, guest_cycle: u64, name: &str, return_value: u64) {
if !is_enabled() {
return;
}
let idx = next_tid_idx(tid);
let mut line = common_prefix("kernel.return", tid, idx, guest_cycle, true);
line.push_str(&format!(
r#","payload":{{"name":"{}","return_value":{},"status":"0x{:08x}","side_effects":[]}}}}"#,
json_escape(name),
return_value,
return_value as u32
));
write_line(&line);
}
pub fn emit_handle_create(
tid: u32,
guest_cycle: u64,
semantic_id: u64,
object_type: u32,
raw_handle_id: u32,
object_name: Option<&str>,
) {
if !is_enabled() {
return;
}
let idx = next_tid_idx(tid);
let mut line = common_prefix("handle.create", tid, idx, guest_cycle, true);
let name_field = match object_name {
Some(n) => format!(r#""{}""#, json_escape(n)),
None => "null".to_string(),
};
line.push_str(&format!(
r#","payload":{{"handle_semantic_id":"{:016x}","object_type":{},"object_name":{},"raw_handle_id":"0x{:08x}"}}}}"#,
semantic_id, object_type, name_field, raw_handle_id
));
write_line(&line);
}
pub fn emit_handle_destroy(
tid: u32,
guest_cycle: u64,
semantic_id: u64,
raw_handle_id: u32,
prior_refcount: u32,
) {
if !is_enabled() {
return;
}
let idx = next_tid_idx(tid);
let mut line = common_prefix("handle.destroy", tid, idx, guest_cycle, true);
line.push_str(&format!(
r#","payload":{{"handle_semantic_id":"{:016x}","raw_handle_id":"0x{:08x}","prior_refcount":{}}}}}"#,
semantic_id, raw_handle_id, prior_refcount
));
write_line(&line);
}
pub fn emit_thread_create(
parent_tid: u32,
guest_cycle: u64,
semantic_id: u64,
entry_pc: u32,
ctx_ptr: u32,
priority: u32,
affinity: u32,
stack_size: u32,
suspended: bool,
) {
if !is_enabled() {
return;
}
let idx = next_tid_idx(parent_tid);
let mut line = common_prefix("thread.create", parent_tid, idx, guest_cycle, true);
line.push_str(&format!(
r#","payload":{{"handle_semantic_id":"{:016x}","parent_tid":{},"entry_pc":"0x{:08x}","ctx_ptr":"0x{:08x}","priority":{},"affinity":{},"stack_size":{},"suspended":{}}}}}"#,
semantic_id,
parent_tid,
entry_pc,
ctx_ptr,
priority,
affinity,
stack_size,
suspended
));
write_line(&line);
}
pub fn emit_thread_exit(tid: u32, guest_cycle: u64, exit_code: u32) {
if !is_enabled() {
return;
}
let idx = next_tid_idx(tid);
let mut line = common_prefix("thread.exit", tid, idx, guest_cycle, true);
line.push_str(&format!(r#","payload":{{"exit_code":{}}}}}"#, exit_code));
write_line(&line);
}
pub fn emit_wait_begin(
tid: u32,
guest_cycle: u64,
handles: &[u64],
timeout_ns: i64,
alertable: bool,
wait_all: bool,
) {
if !is_enabled() {
return;
}
let idx = next_tid_idx(tid);
let mut line = common_prefix("wait.begin", tid, idx, guest_cycle, true);
let mut ids = String::from("[");
for (i, h) in handles.iter().enumerate() {
if i > 0 {
ids.push(',');
}
ids.push_str(&format!(r#""{:016x}""#, h));
}
ids.push(']');
let wait_type = if wait_all { "all" } else { "any" };
line.push_str(&format!(
r#","payload":{{"handles_semantic_ids":{},"timeout_ns":{},"alertable":{},"wait_type":"{}"}}}}"#,
ids, timeout_ns, alertable, wait_type
));
write_line(&line);
}
pub fn emit_wait_end(
tid: u32,
guest_cycle: u64,
status: u32,
woken_by: Option<u64>,
) {
if !is_enabled() {
return;
}
let idx = next_tid_idx(tid);
let mut line = common_prefix("wait.end", tid, idx, guest_cycle, false);
let woken = match woken_by {
Some(h) => format!(r#""{:016x}""#, h),
None => "null".to_string(),
};
line.push_str(&format!(
r#","payload":{{"status":"0x{:08x}","woken_by_semantic_id":{},"wait_duration_cycles":0}}}}"#,
status, woken
));
write_line(&line);
}
// ===== Phase C+15-\u03b1 — Handle-semantic-ID registry =====
//
// Maps raw handle id -> FNV-1a 64-bit semantic_id assigned at handle
// creation. Used by `handle.destroy`, `wait.begin`, and any future event
// that references a handle to emit a stable cross-engine identity.
//
// Lifetime: entries are inserted on `register_handle_semantic_id` and
// removed on `forget_handle_semantic_id` (handle destroy). The map is
// completely separate from the live KernelState object table —
// looking up a destroyed handle returns None and the caller emits 0.
static HANDLE_SEMANTIC_IDS: OnceLock<Mutex<HashMap<u32, u64>>> = OnceLock::new();
fn handle_sid_map() -> &'static Mutex<HashMap<u32, u64>> {
HANDLE_SEMANTIC_IDS.get_or_init(|| Mutex::new(HashMap::new()))
}
/// Record `(raw_handle_id -> semantic_id)` so subsequent destroy/wait
/// events can resolve the SID. No-op when event_log is disabled.
pub fn register_handle_semantic_id(raw_handle_id: u32, sid: u64) {
if !is_enabled() {
return;
}
let m = handle_sid_map();
m.lock().unwrap().insert(raw_handle_id, sid);
}
/// Look up the semantic_id previously registered for a raw handle.
/// Returns 0 if the handle was never registered (e.g. pre-init handles,
/// pseudo-handles, or already destroyed).
pub fn lookup_handle_semantic_id(raw_handle_id: u32) -> u64 {
let Some(map) = HANDLE_SEMANTIC_IDS.get() else {
return 0;
};
*map.lock().unwrap().get(&raw_handle_id).unwrap_or(&0)
}
/// Forget the semantic_id mapping for a destroyed handle. Returns the
/// previous mapping (0 if absent) so callers can emit `handle.destroy`
/// with the correct SID before the entry is dropped.
pub fn forget_handle_semantic_id(raw_handle_id: u32) -> u64 {
let Some(map) = HANDLE_SEMANTIC_IDS.get() else {
return 0;
};
map.lock().unwrap().remove(&raw_handle_id).unwrap_or(0)
}
/// Convenience wrapper used by both engines: at handle creation time,
/// peek the current tid_event_idx, compute the FNV-1a 64-bit semantic_id,
/// register it for the raw handle, and emit a `handle.create` event.
/// Returns the semantic_id so callers can stash it on object metadata
/// when needed (currently only used for the registry side-effect).
///
/// `create_site_pc` is the guest LR at the kernel call that produced
/// the handle (or 0 if not available — both engines must use the same
/// value for the cross-engine SID to match). For v1.1 we pass 0
/// universally, which preserves cross-engine identity since the SID
/// becomes `fnv1a(0, tid, idx, type)` and both engines emit the same
/// tuple in the same order.
pub fn emit_handle_create_auto(
tid: u32,
guest_cycle: u64,
create_site_pc: u32,
object_type: u32,
raw_handle_id: u32,
object_name: Option<&str>,
) -> u64 {
if !is_enabled() {
return 0;
}
let idx_at_creation = peek_tid_idx(tid);
let sid = semantic_id(create_site_pc, tid, idx_at_creation, object_type);
register_handle_semantic_id(raw_handle_id, sid);
emit_handle_create(tid, guest_cycle, sid, object_type, raw_handle_id, object_name);
sid
}
/// Phase C+18: emit `handle.create` for a **process-global** kernel
/// dispatcher (canary `XObject::GetNativeObject` / ours
/// `ensure_dispatcher_object` first-touch synthesis). The SID is
/// computed via `semantic_id_shared_global(pointer, object_type)` so
/// the same object yields the same SID in both engines regardless of
/// which guest thread happens to be the first toucher (see C+18
/// memory entry / schema-v1.md §"Shared-global SIDs"). The diff tool
/// cross-tid matches `handle.create` events on shared-global SIDs.
///
/// The `raw_handle_id` is the guest dispatcher pointer itself in
/// ours; canary's `XObject::StashHandle` round-trips through the same
/// dispatcher slot. Cross-engine SID identity is independent of raw
/// handle namespace.
pub fn emit_handle_create_shared_global(
tid: u32,
guest_cycle: u64,
object_type: u32,
raw_handle_id: u32,
object_name: Option<&str>,
) -> u64 {
if !is_enabled() {
return 0;
}
let sid = semantic_id_shared_global(raw_handle_id, object_type);
register_handle_semantic_id(raw_handle_id, sid);
emit_handle_create(tid, guest_cycle, sid, object_type, raw_handle_id, object_name);
sid
}
/// Phase D Stage 3: emit a `contention.observed` event. Mirror of canary's
/// `phase_a::EmitContentionObserved` (Stage 1). Emitted from
/// `rtl_enter_critical_section` only when the contention-manifest forces a
/// park, so per-tid ordinals stay aligned with canary's emitter. The
/// `site_sid` is computed via `semantic_id_shared_global(cs_ptr,
/// object_type::CRITICAL_SECTION)` so both engines produce the same SID
/// for the same CS pointer (cross-engine identity).
///
/// `is_enabled()` gates this just like every other emitter — when the
/// Phase A event log is disabled, this is a zero-cost no-op.
///
/// Note: `contention.observed` is marked `ENGINE_LOCAL_KINDS` in
/// `diff_events.py` (Stage 4), so the diff tool advances the per-tid
/// pointer past these events on either side without comparison. That
/// keeps the matched-prefix definition unchanged across cvar
/// configurations.
pub fn emit_contention_observed(
tid: u32,
guest_cycle: u64,
cs_ptr: u32,
contended: bool,
) {
if !is_enabled() {
return;
}
let idx = next_tid_idx(tid);
let site_sid = semantic_id_shared_global(cs_ptr, object_type::CRITICAL_SECTION);
let mut line = common_prefix("contention.observed", tid, idx, guest_cycle, true);
line.push_str(&format!(
r#","payload":{{"cs_ptr":"0x{:08x}","site_sid":"{:016x}","contended":{}}}}}"#,
cs_ptr,
site_sid,
if contended { "true" } else { "false" }
));
write_line(&line);
}
/// Iterate 2.Q: emit a `signal.match` event recording which handle a
/// signal-class call (`NtSetEvent`/`KeSetEvent`/`NtReleaseSemaphore`/
/// `KeReleaseSemaphore`) targeted at the moment the signal fired, along
/// with the set of guest threads currently parked on that handle. The
/// caller is expected to gather `waiter_tids` BEFORE the wake fans out,
/// so the emitted set reflects the pre-wake waiter list.
///
/// `signal_call` is the kernel symbol (static `&str`). `target_handle`
/// is the resolved (post-pseudo-handle / post-dup-id) handle id; the
/// SID is resolved from the global registry (0 when absent — e.g.
/// pre-init handles or AUDIT-062 wrong-slot targets that were never
/// registered). `waiter_count` is the length of `waiter_tids` (passed
/// explicitly so callers may skip the emit when 0). This kind is
/// ENGINE_LOCAL in the diff tool — it consumes one per-tid idx slot on
/// the emitter side without alignment cost.
///
/// Pure observability. No behavior change. Cvar-gated default-off via
/// `is_enabled()`; when the Phase A event log is disabled the call is
/// a single relaxed atomic-bool check.
pub fn emit_signal_match(
tid: u32,
guest_cycle: u64,
signal_call: &str,
target_handle: u32,
waiter_count: usize,
waiter_tids: &[u32],
) {
if !is_enabled() {
return;
}
let idx = next_tid_idx(tid);
let target_sid = lookup_handle_semantic_id(target_handle);
let sid_field = if target_sid != 0 {
format!(r#""{:016x}""#, target_sid)
} else {
"null".to_string()
};
let mut tids_field = String::from("[");
for (i, t) in waiter_tids.iter().enumerate() {
if i > 0 {
tids_field.push(',');
}
tids_field.push_str(&format!("{}", t));
}
tids_field.push(']');
let mut line = common_prefix("signal.match", tid, idx, guest_cycle, true);
line.push_str(&format!(
r#","payload":{{"signal_call":"{}","target_handle":"0x{:08x}","target_sid":{},"waiter_count":{},"waiter_tids":{}}}}}"#,
json_escape(signal_call),
target_handle,
sid_field,
waiter_count,
tids_field,
));
write_line(&line);
}
/// Iterate 2.T: emit a `wake.requested` event recording one waiter the
/// wake-loop in `wake_eligible_waiters` actually touched. Distinct from
/// `signal.match` (which records pre-wake intent at the call boundary):
/// `wake.requested` records the per-waiter transition outcome the kernel
/// wake primitive produced. Together they decisively distinguish:
/// C-2a (`signal.match` fires for waiter, but no `wake.requested` for
/// the same target tid) — kernel waiter list inconsistency, OR
/// C-2b (`wake.requested` fires with `transitioned=true` /
/// `new_state="Ready"`, but target tid never executes) —
/// scheduler-pick skip on Ready threads.
///
/// `signaling_tid` is the tid of the thread currently executing inside the
/// signal call (e.g., NtReleaseSemaphore caller). `target_tid` is the
/// woken thread's guest tid. `target_handle` is the handle we're waking
/// on. `wait_kind` is one of `"WaitAny"`, `"WaitAll"`, `"WaitSingle"`,
/// `"Other"`. `transitioned` is true iff prior_state was Blocked and
/// post-state is Ready; `new_state` carries the post-call state string
/// (`"Ready"`, `"StillBlocked"`, `"AlreadyReady"`, `"Exited"`, `"Other"`).
/// `target_cpu` is the woken thread's hw_id, or `null` if unknown.
///
/// ENGINE_LOCAL in the diff tool (see `ENGINE_LOCAL_KINDS` in
/// `tools/diff-events/diff_events.py`). Pure observability — no behavior
/// change.
#[allow(clippy::too_many_arguments)]
pub fn emit_wake_requested(
signaling_tid: u32,
guest_cycle: u64,
target_tid: u32,
target_handle: u32,
wait_kind: &str,
transitioned: bool,
new_state: &str,
target_cpu: Option<u8>,
) {
if !is_enabled() {
return;
}
let idx = next_tid_idx(signaling_tid);
let cpu_field = match target_cpu {
Some(c) => format!("{}", c),
None => "null".to_string(),
};
let mut line = common_prefix("wake.requested", signaling_tid, idx, guest_cycle, true);
line.push_str(&format!(
r#","payload":{{"target_tid":{},"target_handle":"0x{:08x}","wait_kind":"{}","transitioned":{},"new_state":"{}","target_cpu":{}}}}}"#,
target_tid,
target_handle,
json_escape(wait_kind),
if transitioned { "true" } else { "false" },
json_escape(new_state),
cpu_field,
));
write_line(&line);
}
/// Convenience wrapper used by both engines: emit a `handle.destroy`
/// event resolving the SID from the registry, and forget the mapping.
/// Pass `prior_refcount` as observed pre-decrement.
pub fn emit_handle_destroy_auto(
tid: u32,
guest_cycle: u64,
raw_handle_id: u32,
prior_refcount: u32,
) {
if !is_enabled() {
return;
}
let sid = forget_handle_semantic_id(raw_handle_id);
emit_handle_destroy(tid, guest_cycle, sid, raw_handle_id, prior_refcount);
}
#[cfg(test)]
mod tests {
use super::*;
#[test]
fn fnv1a_known_vector() {
// FNV-1a 64-bit of "foobar" = 0x85944171f73967e8 (standard test vector).
let bytes = b"foobar";
let mut h: u64 = 0xCBF29CE484222325;
for b in bytes.iter() {
h ^= *b as u64;
h = h.wrapping_mul(0x100000001B3);
}
assert_eq!(h, 0x85944171f73967e8);
}
#[test]
fn semantic_id_stable() {
// Identity inputs → known fixed FNV-1a output. Locks the algorithm
// so a regression here is caught at build-time.
let a = semantic_id(0x82001234, 1, 0, object_type::EVENT);
let b = semantic_id(0x82001234, 1, 0, object_type::EVENT);
assert_eq!(a, b);
// Distinct input → distinct output (with overwhelming probability).
let c = semantic_id(0x82001234, 1, 1, object_type::EVENT);
assert_ne!(a, c);
}
/// Phase C+18: the shared-global SID must depend ONLY on
/// `(pointer, object_type)`, independent of the calling tid / event idx.
/// Two calls with the same pointer+type return the same SID; otherwise
/// the diff tool's cross-tid floating-create match cannot work.
#[test]
fn semantic_id_shared_global_is_scheduling_invariant() {
let a = semantic_id_shared_global(0x828a3230, object_type::SEMAPHORE);
let b = semantic_id_shared_global(0x828a3230, object_type::SEMAPHORE);
assert_eq!(a, b);
// Distinct pointer → distinct SID.
let c = semantic_id_shared_global(0x828a3234, object_type::SEMAPHORE);
assert_ne!(a, c);
// Distinct type at the same pointer → distinct SID (defends against
// games that map the same address with different headers — unlikely
// but the property is cheap to assert).
let d = semantic_id_shared_global(0x828a3230, object_type::EVENT);
assert_ne!(a, d);
}
/// Phase C+18: the shared-global SID must NOT collide with regular
/// per-thread SIDs for plausible inputs. The marker constant
/// `0xC01AB005` sits well outside any guest PC range (PPC text lives
/// in 0x8200_0000-0x82FF_FFFF in Sylpheed; XEX header in
/// 0x3001_xxxx; heap in 0x4xxx_xxxx). Verify the marker is also not
/// a plausible tid/idx value.
#[test]
fn semantic_id_shared_global_marker_isolated() {
// A regular per-thread SID for a plausible call site / tid / idx.
let regular = semantic_id(0x82001234, 13, 42, object_type::SEMAPHORE);
// The shared-global SID for the same type but different inputs.
let global = semantic_id_shared_global(0x828a3230, object_type::SEMAPHORE);
assert_ne!(regular, global);
// Ensure marker constant is documented.
assert_eq!(SHARED_GLOBAL_SID_MARKER, 0xC01AB005);
}
}