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>
775 lines
28 KiB
Rust
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);
|
|
}
|
|
}
|