diff --git a/Cargo.lock b/Cargo.lock index 499faa59d7..6362f3b413 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -3339,7 +3339,6 @@ dependencies = [ "backtrace", "bincode", "cfg-if 1.0.0", - "cpp_demangle", "indexmap", "lazy_static", "libc", @@ -3349,7 +3348,6 @@ dependencies = [ "psm", "rayon", "region", - "rustc-demangle", "serde", "target-lexicon", "tempfile", @@ -3563,6 +3561,7 @@ dependencies = [ "cpp_demangle", "gimli", "ittapi-rs", + "log", "object", "region", "rustc-demangle", diff --git a/Cargo.toml b/Cargo.toml index ba9cd8dd2c..748cb801da 100644 --- a/Cargo.toml +++ b/Cargo.toml @@ -86,7 +86,7 @@ members = [ exclude = [ 'crates/wasi-common/WASI/tools/witx-cli', 'docs/rust_wasi_markdown_parser' - ] +] [features] default = ["jitdump", "wasmtime/wat", "wasmtime/parallel-compilation", "wasi-nn"] diff --git a/crates/jit/Cargo.toml b/crates/jit/Cargo.toml index 733fc1ff96..3c7b7b9a54 100644 --- a/crates/jit/Cargo.toml +++ b/crates/jit/Cargo.toml @@ -26,6 +26,7 @@ ittapi-rs = { version = "0.1.6", optional = true } bincode = "1.2.1" rustc-demangle = "0.1.16" cpp_demangle = "0.3.2" +log = "0.4.8" [target.'cfg(target_os = "windows")'.dependencies] winapi = { version = "0.3.8", features = ["winnt", "impl-default"] } diff --git a/crates/jit/src/demangling.rs b/crates/jit/src/demangling.rs new file mode 100644 index 0000000000..83b07d6f80 --- /dev/null +++ b/crates/jit/src/demangling.rs @@ -0,0 +1,27 @@ +//! Helpers for demangling function names. + +/// Demangles a single function name into a user-readable form. +/// +/// Currently supported: Rust/C/C++ function names. +pub fn demangle_function_name(writer: &mut impl std::fmt::Write, name: &str) -> std::fmt::Result { + if let Ok(demangled) = rustc_demangle::try_demangle(name) { + write!(writer, "{}", demangled) + } else if let Ok(demangled) = cpp_demangle::Symbol::new(name) { + write!(writer, "{}", demangled) + } else { + write!(writer, "{}", name) + } +} + +/// Demangles a function name if it's provided, or returns a unified representation based on the +/// function index otherwise. +pub fn demangle_function_name_or_index( + writer: &mut impl std::fmt::Write, + name: Option<&str>, + func_id: usize, +) -> std::fmt::Result { + match name { + Some(name) => demangle_function_name(writer, name), + None => write!(writer, "", func_id), + } +} diff --git a/crates/jit/src/lib.rs b/crates/jit/src/lib.rs index 8bbad9c9ca..7fff78b6ae 100644 --- a/crates/jit/src/lib.rs +++ b/crates/jit/src/lib.rs @@ -22,6 +22,7 @@ mod code_memory; mod debug; +mod demangling; mod instantiate; mod link; mod mmap_vec; @@ -34,6 +35,7 @@ pub use crate::instantiate::{ SymbolizeContext, TypeTables, }; pub use crate::mmap_vec::MmapVec; +pub use demangling::*; pub use profiling::*; /// Version number of this crate. diff --git a/crates/jit/src/profiling.rs b/crates/jit/src/profiling.rs index 08f9a957c6..a45db568aa 100644 --- a/crates/jit/src/profiling.rs +++ b/crates/jit/src/profiling.rs @@ -1,6 +1,4 @@ -use crate::CompiledModule; -use std::error::Error; -use std::fmt; +use crate::{demangling::demangle_function_name_or_index, CompiledModule}; use wasmtime_environ::{DefinedFuncIndex, EntityRef, Module}; cfg_if::cfg_if! { @@ -30,45 +28,38 @@ pub use vtune::VTuneAgent; pub trait ProfilingAgent: Send + Sync + 'static { /// Notify the profiler of a new module loaded into memory fn module_load(&self, module: &CompiledModule, dbg_image: Option<&[u8]>); - /// Notify the profiler that the object file provided contains - /// dynamically-generated trampolines which are now being loaded. - fn trampoline_load(&self, file: &object::File<'_>); + + /// Notify the profiler about a single dynamically-generated trampoline (for host function) + /// that is being loaded now.` + fn load_single_trampoline(&self, name: &str, addr: *const u8, size: usize, pid: u32, tid: u32); } /// Default agent for unsupported profiling build. #[derive(Debug, Default, Clone, Copy)] pub struct NullProfilerAgent; -#[derive(Debug)] -struct NullProfilerAgentError; - -impl fmt::Display for NullProfilerAgentError { - fn fmt(&self, f: &mut fmt::Formatter) -> fmt::Result { - write!(f, "A profiler agent is not supported by this build") - } -} - -// This is important for other errors to wrap this one. -impl Error for NullProfilerAgentError { - fn source(&self) -> Option<&(dyn Error + 'static)> { - // Generic error, underlying cause isn't tracked. - None - } -} - impl ProfilingAgent for NullProfilerAgent { fn module_load(&self, _module: &CompiledModule, _dbg_image: Option<&[u8]>) {} - fn trampoline_load(&self, _file: &object::File<'_>) {} + fn load_single_trampoline( + &self, + _name: &str, + _addr: *const u8, + _size: usize, + _pid: u32, + _tid: u32, + ) { + } } #[allow(dead_code)] fn debug_name(module: &Module, index: DefinedFuncIndex) -> String { let index = module.func_index(index); - match module.func_names.get(&index) { - Some(s) => rustc_demangle::try_demangle(s) - .map(|demangle| demangle.to_string()) - .or_else(|_| cpp_demangle::Symbol::new(s).map(|sym| sym.to_string())) - .unwrap_or_else(|_| s.clone()), - None => format!("wasm::wasm-function[{}]", index.index()), - } + let mut debug_name = String::new(); + demangle_function_name_or_index( + &mut debug_name, + module.func_names.get(&index).map(|s| s.as_str()), + index.index(), + ) + .unwrap(); + debug_name } diff --git a/crates/jit/src/profiling/jitdump_disabled.rs b/crates/jit/src/profiling/jitdump_disabled.rs index a007a72661..f88d76a58c 100644 --- a/crates/jit/src/profiling/jitdump_disabled.rs +++ b/crates/jit/src/profiling/jitdump_disabled.rs @@ -20,5 +20,13 @@ impl JitDumpAgent { impl ProfilingAgent for JitDumpAgent { fn module_load(&self, _module: &CompiledModule, _dbg_image: Option<&[u8]>) {} - fn trampoline_load(&self, _file: &object::File<'_>) {} + fn load_single_trampoline( + &self, + _name: &str, + _addr: *const u8, + _size: usize, + __pid: u32, + _tid: u32, + ) { + } } diff --git a/crates/jit/src/profiling/jitdump_linux.rs b/crates/jit/src/profiling/jitdump_linux.rs index f79880163f..50cb7487dd 100644 --- a/crates/jit/src/profiling/jitdump_linux.rs +++ b/crates/jit/src/profiling/jitdump_linux.rs @@ -203,8 +203,11 @@ impl ProfilingAgent for JitDumpAgent { fn module_load(&self, module: &CompiledModule, dbg_image: Option<&[u8]>) { self.state.lock().unwrap().module_load(module, dbg_image); } - fn trampoline_load(&self, file: &object::File<'_>) { - self.state.lock().unwrap().trampoline_load(file) + fn load_single_trampoline(&self, name: &str, addr: *const u8, size: usize, pid: u32, tid: u32) { + self.state + .lock() + .unwrap() + .load_single_trampoline(name, addr, size, pid, tid); } } @@ -303,6 +306,8 @@ impl State { self.dump_code_load_record(&name, addr, len, timestamp, pid, tid); } } + + // Note: these are the trampolines into exported functions. for (idx, func, len) in module.trampolines() { let (addr, len) = (func as usize as *const u8, len); let timestamp = self.get_time_stamp(); @@ -311,44 +316,16 @@ impl State { } } - fn trampoline_load(&mut self, image: &object::File<'_>) { - use object::{ObjectSection, ObjectSymbol, SectionKind, SymbolKind}; - let pid = process::id(); - let tid = pid; - - let text_base = match image.sections().find(|s| s.kind() == SectionKind::Text) { - Some(section) => match section.data() { - Ok(data) => data.as_ptr() as usize, - Err(_) => return, - }, - None => return, - }; - - for sym in image.symbols() { - if !sym.is_definition() { - continue; - } - if sym.kind() != SymbolKind::Text { - continue; - } - let address = sym.address(); - let size = sym.size(); - if address == 0 || size == 0 { - continue; - } - if let Ok(name) = sym.name() { - let addr = text_base + address as usize; - let timestamp = self.get_time_stamp(); - self.dump_code_load_record( - &name, - addr as *const u8, - size as usize, - timestamp, - pid, - tid, - ); - } - } + fn load_single_trampoline( + &mut self, + name: &str, + addr: *const u8, + size: usize, + pid: u32, + tid: u32, + ) { + let timestamp = self.get_time_stamp(); + self.dump_code_load_record(name, addr, size, timestamp, pid, tid); } fn dump_code_load_record( diff --git a/crates/jit/src/profiling/vtune_disabled.rs b/crates/jit/src/profiling/vtune_disabled.rs index 7a84fd03d7..01da215919 100644 --- a/crates/jit/src/profiling/vtune_disabled.rs +++ b/crates/jit/src/profiling/vtune_disabled.rs @@ -20,5 +20,13 @@ impl VTuneAgent { impl ProfilingAgent for VTuneAgent { fn module_load(&self, _module: &crate::CompiledModule, _dbg_image: Option<&[u8]>) {} - fn trampoline_load(&self, _file: &object::File<'_>) {} + fn load_single_trampoline( + &self, + _name: &str, + _addr: *const u8, + _size: usize, + __pid: u32, + _tid: u32, + ) { + } } diff --git a/crates/jit/src/profiling/vtune_linux.rs b/crates/jit/src/profiling/vtune_linux.rs index 7e6e80aa85..9b52ef3aac 100644 --- a/crates/jit/src/profiling/vtune_linux.rs +++ b/crates/jit/src/profiling/vtune_linux.rs @@ -9,10 +9,10 @@ //! ### Profile //! //! ```ignore -//! amplxe-cl -run-pass-thru=--no-altstack -v -collect hotspots target/debug/wasmtime --vtune test.wasm +//! vtune -run-pass-thru=--no-altstack -v -collect hotspots target/debug/wasmtime --vtune test.wasm //! ``` //! -//! Note: `amplxe-cl` is a command-line tool for VTune which must [be +//! Note: `vtune` is a command-line tool for VTune which must [be //! installed](https://www.intel.com/content/www/us/en/developer/tools/oneapi/vtune-profiler.html#standalone) //! for this to work. @@ -20,10 +20,9 @@ use crate::{CompiledModule, ProfilingAgent}; use anyhow::Result; use core::ptr; use ittapi_rs::*; -use std::collections::HashMap; use std::ffi::CString; use std::sync::{atomic, Mutex}; -use wasmtime_environ::DefinedFuncIndex; +use wasmtime_environ::EntityRef; /// Interface for driving the ittapi for VTune support pub struct VTuneAgent { @@ -34,19 +33,13 @@ pub struct VTuneAgent { /// Interface for driving vtune #[derive(Clone, Debug, Default)] -struct State { - /// Unique identifier for the jitted function - method_id: HashMap<(usize, DefinedFuncIndex), u32>, -} +struct State; impl VTuneAgent { - /// Intialize a VTuneAgent and write out the header + /// Initialize a VTuneAgent. pub fn new() -> Result { - let state = State { - method_id: HashMap::new(), - }; Ok(VTuneAgent { - state: Mutex::new(state), + state: Mutex::new(State), }) } } @@ -58,24 +51,15 @@ impl Drop for VTuneAgent { } impl State { - /// Return the unique method ID for use with the ittapi - pub fn get_method_id(&mut self, module_id: usize, func_idx: DefinedFuncIndex) -> u32 { - let method_id: u32; - unsafe { - method_id = iJIT_GetNewMethodID(); - } - assert_eq!( - self.method_id.insert((module_id, func_idx), method_id), - None - ); - method_id + /// Return a method ID for use with the ittapi. + fn get_method_id(&self) -> u32 { + unsafe { iJIT_GetNewMethodID() } } - /// Load module - pub fn event_load( + /// Notify vtune about a newly tracked code region. + fn event_load( &mut self, method_id: u32, - filename: &str, module_name: &str, method_name: &str, addr: *const u8, @@ -94,13 +78,16 @@ impl State { class_file_name: CString::new(module_name) .expect("CString::new failed") .into_raw(), - source_file_name: CString::new(filename) + source_file_name: CString::new("") .expect("CString::new failed") .into_raw(), }; let jmethod_ptr = &mut jmethod as *mut _ as *mut _; unsafe { - println!("EventLoad: NotifyEvent Called {}", method_id); + log::trace!( + "NotifyEvent: method load (single method with id {})", + method_id + ); let _ret = iJIT_NotifyEvent( iJIT_jvm_event_iJVM_EVENT_TYPE_METHOD_LOAD_FINISHED, jmethod_ptr as *mut ::std::os::raw::c_void, @@ -111,7 +98,7 @@ impl State { /// Shutdown module fn event_shutdown(&mut self) -> () { unsafe { - println!("Drop was called!!!!!!\n"); + log::trace!("NotifyEvent shutdown (whole module)"); let _ret = iJIT_NotifyEvent(iJIT_jvm_event_iJVM_EVENT_TYPE_SHUTDOWN, ptr::null_mut()); } } @@ -121,8 +108,11 @@ impl ProfilingAgent for VTuneAgent { fn module_load(&self, module: &CompiledModule, dbg_image: Option<&[u8]>) { self.state.lock().unwrap().module_load(module, dbg_image); } - fn trampoline_load(&self, _file: &object::File<'_>) { - // TODO: needs an implementation + fn load_single_trampoline(&self, name: &str, addr: *const u8, size: usize, pid: u32, tid: u32) { + self.state + .lock() + .unwrap() + .load_single_trampoline(name, addr, size, pid, tid); } } @@ -132,29 +122,52 @@ impl State { static MODULE_ID: atomic::AtomicUsize = atomic::AtomicUsize::new(0); let global_module_id = MODULE_ID.fetch_add(1, atomic::Ordering::SeqCst); + let module_name = module + .module() + .name + .as_ref() + .cloned() + .unwrap_or_else(|| format!("wasm_module_{}", global_module_id)); + for (idx, func) in module.finished_functions() { let (addr, len) = unsafe { ((*func).as_ptr() as *const u8, (*func).len()) }; - let default_filename = "wasm_file"; - let default_module_name = String::from("wasm_module"); - let module_name = module - .module() - .name - .as_ref() - .unwrap_or(&default_module_name); let method_name = super::debug_name(module.module(), idx); - let method_id = self.get_method_id(global_module_id, idx); - println!( - "Event Load: ({}) {:?}::{:?} Addr:{:?}\n", - method_id, module_name, method_name, addr - ); - self.event_load( + let method_id = self.get_method_id(); + log::trace!( + "new function ({}) {:?}::{:?} @ {:?}\n", method_id, - default_filename, module_name, - &method_name, - addr, - len, + method_name, + addr ); + self.event_load(method_id, &module_name, &method_name, addr, len); } + + // Note: these are the trampolines into exported functions. + for (idx, func, len) in module.trampolines() { + let idx = idx.index(); + let (addr, len) = (func as usize as *const u8, len); + let method_name = format!("wasm::trampoline[{}]", idx,); + let method_id = self.get_method_id(); + log::trace!( + "new trampoline ({}) for exported signature {} @ {:?}\n", + method_id, + idx, + addr + ); + self.event_load(method_id, &module_name, &method_name, addr, len); + } + } + + fn load_single_trampoline( + &mut self, + name: &str, + addr: *const u8, + size: usize, + _pid: u32, + _tid: u32, + ) { + let method_id = self.get_method_id(); + self.event_load(method_id, "wasm trampoline for Func::new", name, addr, size); } } diff --git a/crates/wasmtime/Cargo.toml b/crates/wasmtime/Cargo.toml index 9d4410854c..b5912ceb83 100644 --- a/crates/wasmtime/Cargo.toml +++ b/crates/wasmtime/Cargo.toml @@ -26,8 +26,6 @@ region = "2.2.0" libc = "0.2" cfg-if = "1.0" backtrace = "0.3.61" -rustc-demangle = "0.1.16" -cpp_demangle = "0.3.2" log = "0.4.8" wat = { version = "1.0.36", optional = true } serde = { version = "1.0.94", features = ["derive"] } diff --git a/crates/wasmtime/src/trampoline/func.rs b/crates/wasmtime/src/trampoline/func.rs index fc217377be..67d57fc334 100644 --- a/crates/wasmtime/src/trampoline/func.rs +++ b/crates/wasmtime/src/trampoline/func.rs @@ -6,7 +6,7 @@ use std::any::Any; use std::panic::{self, AssertUnwindSafe}; use std::sync::Arc; use wasmtime_environ::{EntityIndex, Module, ModuleType, PrimaryMap, SignatureIndex}; -use wasmtime_jit::{CodeMemory, MmapVec}; +use wasmtime_jit::{CodeMemory, MmapVec, ProfilingAgent}; use wasmtime_runtime::{ Imports, InstanceAllocationRequest, InstanceAllocator, InstanceHandle, OnDemandInstanceAllocator, StorePtr, VMContext, VMFunctionBody, VMSharedSignatureIndex, @@ -66,6 +66,39 @@ unsafe extern "C" fn stub_fn( } } +#[cfg(compiler)] +fn register_trampolines(profiler: &dyn ProfilingAgent, image: &object::File<'_>) { + use object::{Object as _, ObjectSection, ObjectSymbol, SectionKind, SymbolKind}; + let pid = std::process::id(); + let tid = pid; + + let text_base = match image.sections().find(|s| s.kind() == SectionKind::Text) { + Some(section) => match section.data() { + Ok(data) => data.as_ptr() as usize, + Err(_) => return, + }, + None => return, + }; + + for sym in image.symbols() { + if !sym.is_definition() { + continue; + } + if sym.kind() != SymbolKind::Text { + continue; + } + let address = sym.address(); + let size = sym.size(); + if address == 0 || size == 0 { + continue; + } + if let Ok(name) = sym.name() { + let addr = text_base + address as usize; + profiler.load_single_trampoline(name, addr as *const u8, size as usize, pid, tid); + } + } +} + #[cfg(compiler)] pub fn create_function( ft: &FuncType, @@ -87,7 +120,8 @@ where // also take care of unwind table registration. let mut code_memory = CodeMemory::new(obj); let code = code_memory.publish()?; - engine.config().profiler.trampoline_load(&code.obj); + + register_trampolines(engine.config().profiler.as_ref(), &code.obj); // Extract the host/wasm trampolines from the results of compilation since // we know their start/length. diff --git a/crates/wasmtime/src/trap.rs b/crates/wasmtime/src/trap.rs index 87d1832009..70ae11bda9 100644 --- a/crates/wasmtime/src/trap.rs +++ b/crates/wasmtime/src/trap.rs @@ -4,6 +4,7 @@ use backtrace::Backtrace; use std::fmt; use std::sync::Arc; use wasmtime_environ::TrapCode as EnvTrapCode; +use wasmtime_jit::{demangle_function_name, demangle_function_name_or_index}; /// A struct representing an aborted instruction execution, with a message /// indicating the cause. @@ -327,17 +328,8 @@ impl fmt::Display for Trap { write!(f, "{:#6x} - ", offset)?; } - let demangle = - |f: &mut fmt::Formatter<'_>, name: &str| match rustc_demangle::try_demangle(name) { - Ok(name) => write!(f, "{}", name), - Err(_) => match cpp_demangle::Symbol::new(name) { - Ok(name) => write!(f, "{}", name), - Err(_) => write!(f, "{}", name), - }, - }; - let write_raw_func_name = |f: &mut fmt::Formatter<'_>| match frame.func_name() { - Some(name) => demangle(f, name), - None => write!(f, "", frame.func_index()), + let write_raw_func_name = |f: &mut fmt::Formatter<'_>| { + demangle_function_name_or_index(f, frame.func_name(), frame.func_index() as usize) }; if frame.symbols().is_empty() { write!(f, "{}!", name)?; @@ -351,7 +343,7 @@ impl fmt::Display for Trap { // ... } match symbol.name() { - Some(name) => demangle(f, name)?, + Some(name) => demangle_function_name(f, name)?, None if i == 0 => write_raw_func_name(f)?, None => write!(f, "")?, }