diff --git a/Cargo.lock b/Cargo.lock index c7315d3..efa9e0d 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -1507,6 +1507,20 @@ dependencies = [ "slab", ] +[[package]] +name = "fxprof-processed-profile" +version = "0.8.1" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "25234f20a3ec0a962a61770cfe39ecf03cb529a6e474ad8cff025ed497eda557" +dependencies = [ + "bitflags 2.9.1", + "debugid", + "rustc-hash 2.1.1", + "serde", + "serde_derive", + "serde_json", +] + [[package]] name = "gethostname" version = "0.4.3" @@ -2140,10 +2154,12 @@ dependencies = [ "egui_extras", "elf", "fixed", + "fxprof-processed-profile", "gilrs", "hex", "image", "itertools 0.14.0", + "normpath", "num-derive", "num-traits", "oneshot", @@ -2569,6 +2585,15 @@ dependencies = [ "minimal-lexical", ] +[[package]] +name = "normpath" +version = "1.3.0" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "c8911957c4b1549ac0dc74e30db9c8b0e66ddcd6d7acc33098f4c63a64a6d7ed" +dependencies = [ + "windows-sys 0.59.0", +] + [[package]] name = "nu-ansi-term" version = "0.46.0" diff --git a/Cargo.toml b/Cargo.toml index 2909eac..e8c5c8c 100644 --- a/Cargo.toml +++ b/Cargo.toml @@ -22,11 +22,13 @@ egui-notify = "0.20" egui-winit = "0.32" egui-wgpu = { version = "0.32", features = ["winit"] } elf = "0.8" +fxprof-processed-profile = "0.8" fixed = { version = "1.28", features = ["num-traits"] } gilrs = { version = "0.11", features = ["serde-serialize"] } hex = "0.4" image = { version = "0.25", default-features = false, features = ["png"] } itertools = "0.14" +normpath = "1" num-derive = "0.4" num-traits = "0.2" oneshot = "0.1" diff --git a/src/profiler.rs b/src/profiler.rs index a9ccb22..62ebac1 100644 --- a/src/profiler.rs +++ b/src/profiler.rs @@ -1,15 +1,19 @@ use std::{ - collections::HashMap, path::PathBuf, sync::{Arc, Mutex}, thread, }; -use anyhow::{Result, bail}; +use anyhow::Result; use tokio::{select, sync::mpsc}; -use wholesym::{SymbolManager, SymbolMap}; use crate::emulator::{EmulatorClient, EmulatorCommand, ProfileEvent, SimEvent, SimId}; +use recording::Recording; +use state::ProgramState; + +mod recording; +mod state; +mod symbols; pub struct Profiler { sim_id: SimId, @@ -182,14 +186,6 @@ enum RecordingAction { Cancel, } -struct Recording {} - -impl Recording { - fn new() -> Self { - Self {} - } -} - struct ProfilerSession { program: Option, recording: Option, @@ -210,8 +206,8 @@ impl ProfilerSession { } fn track_elapsed_cycles(&mut self, cycles: u32) -> Result<()> { - if let Some(program) = &mut self.program { - program.track_elapsed_cycles(cycles)?; + if let (Some(state), Some(recording)) = (&self.program, &mut self.recording) { + recording.track_elapsed_cycles(state, cycles); } Ok(()) } @@ -224,126 +220,16 @@ impl ProfilerSession { } fn start_recording(&mut self) { - self.recording = Some(Recording::new()); + if let Some(program) = &self.program { + self.recording = Some(Recording::new(program)); + } } fn finish_recording(&mut self) -> Option> { - self.recording.take().map(|_| vec![]) + self.recording.take().map(|r| r.finish()) } fn cancel_recording(&mut self) { self.recording.take(); } } - -struct ProgramState { - symbol_map: SymbolMap, - call_stacks: HashMap>, - context_stack: Vec, -} - -struct StackFrame { - #[expect(dead_code)] - address: u32, - cycles: u64, -} - -const RESET_CODE: u16 = 0xfff0; -impl ProgramState { - async fn new(file_path: PathBuf) -> Result { - let symbol_manager = SymbolManager::with_config(Default::default()); - let symbol_map = symbol_manager - .load_symbol_map_for_binary_at_path(&file_path, None) - .await?; - let mut call_stacks = HashMap::new(); - call_stacks.insert( - RESET_CODE, - vec![StackFrame { - address: 0xfffffff0, - cycles: 0, - }], - ); - Ok(Self { - symbol_map, - call_stacks, - context_stack: vec![RESET_CODE], - }) - } - - fn track_elapsed_cycles(&mut self, cycles: u32) -> Result<()> { - let Some(code) = self.context_stack.last() else { - return Ok(()); // program is halted, CPU is idle - }; - let Some(stack) = self.call_stacks.get_mut(code) else { - bail!("missing stack {code:04x}"); - }; - for frame in stack { - frame.cycles += cycles as u64; - } - Ok(()) - } - - fn track_event(&mut self, event: SimEvent) -> Result<()> { - match event { - SimEvent::Call(address) => { - let Some(code) = self.context_stack.last() else { - bail!("How did we call anything when we're halted?"); - }; - let Some(stack) = self.call_stacks.get_mut(code) else { - bail!("missing stack {code:04x}"); - }; - let name = self - .symbol_map - .lookup_sync(wholesym::LookupAddress::Svma(address as u64)); - println!("depth {}: {:x?}", stack.len(), name); - stack.push(StackFrame { address, cycles: 0 }); - } - SimEvent::Return => { - let Some(code) = self.context_stack.last() else { - bail!("how did we return when we're halted?"); - }; - let Some(stack) = self.call_stacks.get_mut(code) else { - bail!("missing stack {code:04x}"); - }; - if stack.pop().is_none() { - bail!("returned from {code:04x} but stack was empty"); - } - if stack.is_empty() { - bail!("returned to oblivion"); - } - } - SimEvent::Halt => { - let Some(RESET_CODE) = self.context_stack.pop() else { - bail!("halted when not in an interrupt"); - }; - } - SimEvent::Interrupt(code, address) => { - // if the CPU was halted before, wake it up now - if self.context_stack.is_empty() { - self.context_stack.push(RESET_CODE); - } - - self.context_stack.push(code); - if self - .call_stacks - .insert(code, vec![StackFrame { address, cycles: 0 }]) - .is_some() - { - bail!("{code:04x} fired twice"); - } - } - SimEvent::Reti => { - let Some(code) = self.context_stack.pop() else { - bail!("RETI when halted"); - }; - if code == RESET_CODE { - bail!("RETI when not in interrupt"); - } - if self.call_stacks.remove(&code).is_none() { - bail!("{code:04x} popped but never called"); - } - } - } - Ok(()) - } -} diff --git a/src/profiler/recording.rs b/src/profiler/recording.rs new file mode 100644 index 0000000..d4836eb --- /dev/null +++ b/src/profiler/recording.rs @@ -0,0 +1,114 @@ +use std::collections::HashMap; + +use fxprof_processed_profile::{ + CategoryHandle, CpuDelta, Frame, FrameFlags, FrameInfo, ProcessHandle, Profile, + ReferenceTimestamp, SamplingInterval, StackHandle, ThreadHandle, Timestamp, +}; + +use crate::profiler::state::{ProgramState, RESET_CODE, StackFrame}; + +pub struct Recording { + profile: Profile, + process: ProcessHandle, + threads: HashMap, + now: u64, +} + +impl Recording { + pub fn new(state: &ProgramState) -> Self { + let symbol_file = state.symbol_file(); + + let name = &symbol_file.name(); + let reference_timestamp = ReferenceTimestamp::from_millis_since_unix_epoch(0.0); + let interval = SamplingInterval::from_hz(20_000_000.0); + let mut profile = Profile::new(name, reference_timestamp, interval); + + let process = profile.add_process(name, 1, Timestamp::from_nanos_since_reference(0)); + + let lib = profile.add_lib(symbol_file.library_info().clone()); + profile.add_lib_mapping(process, lib, 0x00000000, 0xffffffff, 0); + + let mut me = Self { + profile, + process, + threads: HashMap::new(), + now: 0, + }; + me.track_elapsed_cycles(state, 0); + me + } + + pub fn track_elapsed_cycles(&mut self, state: &ProgramState, cycles: u32) { + self.now += cycles as u64; + let timestamp = Timestamp::from_nanos_since_reference(self.now * 50); + let weight = 1; + + let active_code = if let Some((code, frames)) = state.current_stack() { + let thread = *self.threads.entry(code).or_insert_with(|| { + let process = self.process; + let tid = code as u32; + let start_time = Timestamp::from_nanos_since_reference(self.now * 50); + let is_main = code == RESET_CODE; + let thread = self.profile.add_thread(process, tid, start_time, is_main); + self.profile + .set_thread_name(thread, &thread_name_for_code(code)); + thread + }); + + let stack = self.handle_for_stack(thread, frames); + let cpu_delta = CpuDelta::from_nanos((self.now - cycles as u64) * 50); + self.profile + .add_sample(thread, timestamp, stack, cpu_delta, weight); + Some(code) + } else { + None + }; + for (code, thread) in &self.threads { + if active_code == Some(*code) { + continue; + } + self.profile + .add_sample_same_stack_zero_cpu(*thread, timestamp, weight); + } + } + + pub fn finish(self) -> Vec { + serde_json::to_vec(&self.profile).expect("could not serialize profile") + } + + fn handle_for_stack( + &mut self, + thread: ThreadHandle, + frames: &[StackFrame], + ) -> Option { + self.profile.intern_stack_frames( + thread, + frames.iter().map(|f| FrameInfo { + frame: Frame::InstructionPointer(f.address as u64), + category_pair: CategoryHandle::OTHER.into(), + flags: FrameFlags::empty(), + }), + ) + } +} + +fn thread_name_for_code(code: u16) -> std::borrow::Cow<'static, str> { + match code { + RESET_CODE => "Main".into(), + 0xffd0 => "Duplexed exception".into(), + 0xfe40 => "VIP interrupt".into(), + 0xfe30 => "Communication interrupt".into(), + 0xfe20 => "Game pak interrupt".into(), + 0xfe10 => "Timer interrupt".into(), + 0xfe00 => "Game pad interrupt".into(), + 0xffc0 => "Address trap".into(), + 0xffa0..0xffc0 => format!("Trap (vector {})", code - 0xffa0).into(), + 0xff90 => "Illegal opcode exception".into(), + 0xff80 => "Zero division exception".into(), + 0xff60 => "Floating-point reserved operand exception".into(), + 0xff70 => "Floating-point invalid operation exception".into(), + 0xff68 => "Floating-point zero division exception".into(), + 0xff64 => "Floating-point overflow exception".into(), + other => format!("Unrecognized handler (0x{other:04x})").into(), + } +} diff --git a/src/profiler/state.rs b/src/profiler/state.rs new file mode 100644 index 0000000..40bdc72 --- /dev/null +++ b/src/profiler/state.rs @@ -0,0 +1,104 @@ +use std::{collections::HashMap, path::PathBuf}; + +use anyhow::{Result, bail}; + +use crate::{emulator::SimEvent, profiler::symbols::SymbolFile}; + +pub struct ProgramState { + symbol_file: SymbolFile, + call_stacks: HashMap>, + context_stack: Vec, +} + +pub struct StackFrame { + pub address: u32, +} + +pub const RESET_CODE: u16 = 0xfff0; +impl ProgramState { + pub async fn new(file_path: PathBuf) -> Result { + let symbol_file = SymbolFile::load(&file_path).await?; + let mut call_stacks = HashMap::new(); + call_stacks.insert( + RESET_CODE, + vec![StackFrame { + address: 0xfffffff0, + }], + ); + Ok(Self { + symbol_file, + call_stacks, + context_stack: vec![RESET_CODE], + }) + } + + pub fn symbol_file(&self) -> &SymbolFile { + &self.symbol_file + } + + pub fn current_stack(&self) -> Option<(u16, &[StackFrame])> { + let code = self.context_stack.last()?; + let call_stack = self.call_stacks.get(code)?; + Some((*code, call_stack)) + } + + pub fn track_event(&mut self, event: SimEvent) -> Result<()> { + match event { + SimEvent::Call(address) => { + let Some(code) = self.context_stack.last() else { + bail!("How did we call anything when we're halted?"); + }; + let Some(stack) = self.call_stacks.get_mut(code) else { + bail!("missing stack {code:04x}"); + }; + stack.push(StackFrame { address }); + } + SimEvent::Return => { + let Some(code) = self.context_stack.last() else { + bail!("how did we return when we're halted?"); + }; + let Some(stack) = self.call_stacks.get_mut(code) else { + bail!("missing stack {code:04x}"); + }; + if stack.pop().is_none() { + bail!("returned from {code:04x} but stack was empty"); + } + if stack.is_empty() { + bail!("returned to oblivion"); + } + } + SimEvent::Halt => { + let Some(RESET_CODE) = self.context_stack.pop() else { + bail!("halted when not in an interrupt"); + }; + } + SimEvent::Interrupt(code, address) => { + // if the CPU was halted before, wake it up now + if self.context_stack.is_empty() { + self.context_stack.push(RESET_CODE); + } + + self.context_stack.push(code); + if self + .call_stacks + .insert(code, vec![StackFrame { address }]) + .is_some() + { + bail!("{code:04x} fired twice"); + } + } + SimEvent::Reti => { + let Some(code) = self.context_stack.pop() else { + bail!("RETI when halted"); + }; + if code == RESET_CODE { + bail!("RETI when not in interrupt"); + } + if self.call_stacks.remove(&code).is_none() { + bail!("{code:04x} popped but never called"); + } + } + } + Ok(()) + } +} diff --git a/src/profiler/symbols.rs b/src/profiler/symbols.rs new file mode 100644 index 0000000..fd84211 --- /dev/null +++ b/src/profiler/symbols.rs @@ -0,0 +1,67 @@ +use std::{path::Path, sync::Arc}; + +use anyhow::Result; +use fxprof_processed_profile::{LibraryInfo, Symbol, SymbolTable}; +use wholesym::{SymbolManager, samply_symbols::demangle_any}; + +pub struct SymbolFile { + library_info: LibraryInfo, +} + +impl SymbolFile { + pub async fn load(file_path: &Path) -> Result { + let normalized = normpath::PathExt::normalize(file_path)?; + let library_info = + SymbolManager::library_info_for_binary_at_path(normalized.as_path(), None).await?; + + let symbol_manager = SymbolManager::with_config(Default::default()); + let symbol_map = symbol_manager + .load_symbol_map_for_binary_at_path(normalized.as_path(), None) + .await?; + + let name = library_info + .name + .or_else(|| { + normalized + .file_name() + .map(|n| n.to_string_lossy().into_owned()) + }) + .unwrap_or("game".to_string()); + let debug_name = library_info.debug_name.unwrap_or_else(|| name.clone()); + let path = library_info + .path + .unwrap_or_else(|| normalized.into_os_string().to_string_lossy().into_owned()); + let debug_path = library_info.debug_path.unwrap_or_else(|| path.clone()); + let debug_id = library_info.debug_id.unwrap_or_default(); + let code_id = library_info.code_id.map(|id| id.to_string()); + let arch = library_info.arch; + let symbols = symbol_map + .iter_symbols() + .map(|(address, name)| Symbol { + address: address + 0x07000000, + size: None, + name: demangle_any(&name), + }) + .collect(); + Ok(Self { + library_info: LibraryInfo { + name, + debug_name, + path, + debug_path, + debug_id, + code_id, + arch, + symbol_table: Some(Arc::new(SymbolTable::new(symbols))), + }, + }) + } + + pub fn name(&self) -> &str { + &self.library_info.name + } + + pub fn library_info(&self) -> &LibraryInfo { + &self.library_info + } +}