diff --git a/Cargo.lock b/Cargo.lock index d3c47dfc..9580e923 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -537,6 +537,12 @@ dependencies = [ "wasm-bindgen", ] +[[package]] +name = "lazy_static" +version = "1.5.0" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "bbd2bcb4c963f2ddae06a2efc7e9f3591312473c50c6685e1f298068316e66fe" + [[package]] name = "leb128fmt" version = "0.1.0" @@ -570,6 +576,15 @@ version = "0.4.32" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "953f07c43838f8e6f9758cab68bf5bed85465e7587ebe0b823f1bcd81978ad3a" +[[package]] +name = "matchers" +version = "0.2.0" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "d1525a2a28c7f4fa0fc98bb91ae755d1e2d1505079e05539e35bc876b5d65ae9" +dependencies = [ + "regex-automata", +] + [[package]] name = "memchr" version = "2.8.1" @@ -603,6 +618,15 @@ version = "0.5.5" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "610a5acd306ec67f907abe5567859a3c693fb9886eb1f012ab8f2a47bef3db51" +[[package]] +name = "nu-ansi-term" +version = "0.50.3" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "7957b9740744892f114936ab4a57b3f487491bbeafaf8083688b16841a4240e5" +dependencies = [ + "windows-sys 0.61.2", +] + [[package]] name = "num-bigint" version = "0.4.6" @@ -902,6 +926,8 @@ dependencies = [ "oxide_parser", "oxide_types", "rustc-hash", + "tracing", + "tracing-subscriber", ] [[package]] @@ -956,6 +982,7 @@ dependencies = [ "regex", "ryu", "serde_json", + "tracing", "unicode-normalization", ] @@ -1355,6 +1382,15 @@ dependencies = [ "unsafe-libyaml", ] +[[package]] +name = "sharded-slab" +version = "0.1.7" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "f40ca3c46823713e0d4209592e8d6e826aa57e928f09752619fc696c499637f6" +dependencies = [ + "lazy_static", +] + [[package]] name = "shlex" version = "2.0.1" @@ -1452,6 +1488,15 @@ dependencies = [ "syn", ] +[[package]] +name = "thread_local" +version = "1.1.9" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "f60246a4944f24f6e018aa17cdeffb7818b76356965d03b07d6a9886e8962185" +dependencies = [ + "cfg-if", +] + [[package]] name = "tinyvec" version = "1.11.0" @@ -1467,6 +1512,67 @@ version = "0.1.1" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "1f3ccbac311fea05f86f61904b462b55fb3df8837a366dfc601a0161d0532f20" +[[package]] +name = "tracing" +version = "0.1.44" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "63e71662fa4b2a2c3a26f570f037eb95bb1f85397f3cd8076caed2f026a6d100" +dependencies = [ + "pin-project-lite", + "tracing-attributes", + "tracing-core", +] + +[[package]] +name = "tracing-attributes" +version = "0.1.31" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "7490cfa5ec963746568740651ac6781f701c9c5ea257c58e057f3ba8cf69e8da" +dependencies = [ + "proc-macro2", + "quote", + "syn", +] + +[[package]] +name = "tracing-core" +version = "0.1.36" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "db97caf9d906fbde555dd62fa95ddba9eecfd14cb388e4f491a66d74cd5fb79a" +dependencies = [ + "once_cell", + "valuable", +] + +[[package]] +name = "tracing-log" +version = "0.2.0" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "ee855f1f400bd0e5c02d150ae5de3840039a3f54b025156404e34c23c03f47c3" +dependencies = [ + "log", + "once_cell", + "tracing-core", +] + +[[package]] +name = "tracing-subscriber" +version = "0.3.23" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "cb7f578e5945fb242538965c2d0b04418d38ec25c79d160cd279bf0731c8d319" +dependencies = [ + "matchers", + "nu-ansi-term", + "once_cell", + "regex-automata", + "sharded-slab", + "smallvec", + "thread_local", + "tracing", + "tracing-core", + "tracing-log", +] + [[package]] name = "unarray" version = "0.1.4" @@ -1536,6 +1642,12 @@ version = "0.2.2" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "06abde3611657adf66d383f00b093d7faecc7fa57071cce2578660c9f1010821" +[[package]] +name = "valuable" +version = "0.1.1" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "ba73ea9cf16a25df0c8caa16c51acb937d5712a8429db78a3ee29d5dcacd3a65" + [[package]] name = "version_check" version = "0.9.5" diff --git a/Cargo.toml b/Cargo.toml index 0624f242..0982b186 100644 --- a/Cargo.toml +++ b/Cargo.toml @@ -42,6 +42,8 @@ regex = "1" indexmap = "2" chrono = { version = "0.4", default-features = false, features = ["clock"] } unicode-normalization = "0.1" +tracing = "0.1.44" +tracing-subscriber = { version = "0.3.23", features = ["env-filter"] } [workspace.lints.clippy] all = { level = "deny", priority = -1 } diff --git a/crates/oxide_compiler/src/compiler.rs b/crates/oxide_compiler/src/compiler.rs index 0a785851..7aaebc22 100644 --- a/crates/oxide_compiler/src/compiler.rs +++ b/crates/oxide_compiler/src/compiler.rs @@ -312,8 +312,8 @@ impl Compiler { /// (true for arrow functions, which have lexical super) or reset to false /// (false for regular functions, which create a new super scope). pub(crate) fn compile_function_body<'a>( - &self, param_names: &[String], body_stmts: &[Statement<'a>], parent_ctx: &CompileCtx, - is_expression_body: bool, is_arrow: bool, + &self, param_names: &[String], body_stmts: &[Statement<'a>], parent_ctx: &CompileCtx, is_expression_body: bool, + is_arrow: bool, ) -> Result { self.compile_function_body_with_bindings(param_names, body_stmts, parent_ctx, is_expression_body, &[], is_arrow) } diff --git a/crates/oxide_kernel/Cargo.toml b/crates/oxide_kernel/Cargo.toml index f71f689f..a6cb0977 100644 --- a/crates/oxide_kernel/Cargo.toml +++ b/crates/oxide_kernel/Cargo.toml @@ -14,3 +14,5 @@ dashmap.workspace = true hashbrown.workspace = true rustc-hash.workspace = true bumpalo.workspace = true +tracing.workspace = true +tracing-subscriber.workspace = true diff --git a/crates/oxide_kernel/src/code_forge.rs b/crates/oxide_kernel/src/code_forge.rs index 4c0b9d6a..d71fdc1d 100644 --- a/crates/oxide_kernel/src/code_forge.rs +++ b/crates/oxide_kernel/src/code_forge.rs @@ -5,6 +5,8 @@ use dashmap::DashMap; use oxide_compiler::compiler::Compiler; use oxide_compiler::module::CompiledModule; +use crate::{kernel_debug, kernel_info}; + pub use oxide_compiler::compiler::structural_hash; pub struct CodeForge { @@ -22,11 +24,13 @@ impl CodeForge { let hash = structural_hash(program); if let Some(module) = self.map.get(&hash) { + kernel_info!("CodeForge hit hash={:#x}", hash); return Ok(Arc::clone(&module)); } let module = compiler.compile(program)?; let module = Arc::new(module); + kernel_debug!("CodeForge miss hash={:#x}", hash); Ok(Arc::clone(self.map.entry(hash).or_insert(module).value())) } diff --git a/crates/oxide_kernel/src/kernel.rs b/crates/oxide_kernel/src/kernel.rs index 95625706..b534522c 100644 --- a/crates/oxide_kernel/src/kernel.rs +++ b/crates/oxide_kernel/src/kernel.rs @@ -8,6 +8,7 @@ use oxide_types::value::JsValue; use crate::builtin::BuiltinWorld; use crate::code_forge::CodeForge; +use crate::logging::{init_logging, LogLevel, SUBSYSTEM_COUNT}; use crate::prop_forge::PropForge; use crate::shape_forge::{ShapeForge, EMPTY_SHAPE_ID}; use crate::string_forge::StringForge; @@ -18,6 +19,7 @@ pub struct KernelConfig { pub max_dead_strings: Option, pub max_steps: Option, pub max_call_depth: usize, + pub log_levels: [LogLevel; SUBSYSTEM_COUNT], pub warmup_builtin_shapes: bool, pub warmup_builtin_code: bool, pub warmup_builtin_ic: bool, @@ -31,6 +33,7 @@ impl KernelConfig { max_dead_strings: Some(10_000), max_steps: None, max_call_depth: 1024, + log_levels: [LogLevel::Off; SUBSYSTEM_COUNT], warmup_builtin_shapes: true, warmup_builtin_code: false, warmup_builtin_ic: false, @@ -44,6 +47,7 @@ impl KernelConfig { max_dead_strings: Some(10_000), max_steps: None, max_call_depth: 1024, + log_levels: [LogLevel::Off; SUBSYSTEM_COUNT], warmup_builtin_shapes: true, warmup_builtin_code: true, warmup_builtin_ic: false, @@ -57,6 +61,7 @@ impl KernelConfig { max_dead_strings: Some(5_000), max_steps: None, max_call_depth: 1024, + log_levels: [LogLevel::Off; SUBSYSTEM_COUNT], warmup_builtin_shapes: true, warmup_builtin_code: true, warmup_builtin_ic: true, @@ -82,6 +87,8 @@ pub struct OxideKernel { impl OxideKernel { pub fn new(config: KernelConfig) -> Self { + init_logging(&config.log_levels); + let string_forge = Arc::new(StringForge::new()); let shape_forge = Arc::new(ShapeForge::new()); let builtin_world = Arc::new(BuiltinWorld::new(&string_forge, &shape_forge)); @@ -188,6 +195,7 @@ mod tests { assert_eq!(KernelConfig::minimal().max_steps, None); assert_eq!(KernelConfig::standard().max_steps, None); assert_eq!(KernelConfig::full().max_steps, None); + assert_eq!(KernelConfig::minimal().log_levels, [LogLevel::Off; SUBSYSTEM_COUNT]); assert!(!KernelConfig::minimal().warmup_builtin_ic); assert!(KernelConfig::full().warmup_builtin_ic); assert_eq!(KernelConfig::full().max_pool_size, None); diff --git a/crates/oxide_kernel/src/lib.rs b/crates/oxide_kernel/src/lib.rs index 2804b468..c371689d 100644 --- a/crates/oxide_kernel/src/lib.rs +++ b/crates/oxide_kernel/src/lib.rs @@ -3,6 +3,7 @@ pub mod builtin; pub mod code_forge; pub mod kernel; +pub mod logging; pub mod prop_forge; pub mod shape_forge; pub mod string_forge; diff --git a/crates/oxide_kernel/src/logging.rs b/crates/oxide_kernel/src/logging.rs new file mode 100644 index 00000000..fff34dbe --- /dev/null +++ b/crates/oxide_kernel/src/logging.rs @@ -0,0 +1,235 @@ +use std::sync::atomic::{AtomicU8, Ordering}; +use std::sync::Once; + +use tracing_subscriber::EnvFilter; + +#[repr(u8)] +#[derive(Clone, Copy, Debug, PartialEq, Eq)] +pub enum LogLevel { + Off = 0, + Error = 1, + Warn = 2, + Info = 3, + Debug = 4, + Trace = 5, +} + +#[repr(usize)] +#[derive(Clone, Copy, Debug)] +pub enum Subsystem { + Vm = 0, + Ic = 1, + Kernel = 2, + Builtins = 3, +} + +pub const SUBSYSTEM_COUNT: usize = 4; + +pub struct SubsystemLevel(AtomicU8); + +impl SubsystemLevel { + pub const fn new() -> Self { + Self(AtomicU8::new(LogLevel::Off as u8)) + } + + pub fn set(&self, level: LogLevel) { + self.0.store(level as u8, Ordering::Relaxed); + } + + pub fn get(&self) -> LogLevel { + match self.0.load(Ordering::Relaxed) { + 1 => LogLevel::Error, + 2 => LogLevel::Warn, + 3 => LogLevel::Info, + 4 => LogLevel::Debug, + 5 => LogLevel::Trace, + _ => LogLevel::Off, + } + } + + pub fn is_enabled(&self, level: LogLevel) -> bool { + self.0.load(Ordering::Relaxed) >= level as u8 + } +} + +impl Default for SubsystemLevel { + fn default() -> Self { + Self::new() + } +} + +pub static VM_LEVEL: SubsystemLevel = SubsystemLevel::new(); +pub static IC_LEVEL: SubsystemLevel = SubsystemLevel::new(); +pub static KERNEL_LEVEL: SubsystemLevel = SubsystemLevel::new(); +pub static BUILTINS_LEVEL: SubsystemLevel = SubsystemLevel::new(); + +pub fn apply_log_levels(levels: &[LogLevel; SUBSYSTEM_COUNT]) { + VM_LEVEL.set(levels[Subsystem::Vm as usize]); + IC_LEVEL.set(levels[Subsystem::Ic as usize]); + KERNEL_LEVEL.set(levels[Subsystem::Kernel as usize]); + BUILTINS_LEVEL.set(levels[Subsystem::Builtins as usize]); + apply_env_log_levels(); +} + +pub fn init_logging(log_levels: &[LogLevel; SUBSYSTEM_COUNT]) { + static LOGGING_INIT: Once = Once::new(); + + LOGGING_INIT.call_once(|| { + let filter = EnvFilter::try_from_env("OXIDE_LOG").unwrap_or_else(|_| EnvFilter::new("oxide=off")); + let subscriber = tracing_subscriber::fmt() + .with_env_filter(filter) + .with_writer(std::io::stderr) + .with_ansi(false) + .without_time() + .compact() + .finish(); + let _ = tracing::subscriber::set_global_default(subscriber); + }); + + apply_log_levels(log_levels); +} + +fn apply_env_log_levels() { + let Ok(spec) = std::env::var("OXIDE_LOG") else { + return; + }; + + for directive in spec.split(',') { + let Some((target, level)) = directive.split_once('=') else { + continue; + }; + let Some(level) = parse_level(level.trim()) else { + continue; + }; + match target.trim() { + "oxide" => { + VM_LEVEL.set(level); + IC_LEVEL.set(level); + KERNEL_LEVEL.set(level); + BUILTINS_LEVEL.set(level); + } + "oxide::vm" => VM_LEVEL.set(level), + "oxide::ic" => IC_LEVEL.set(level), + "oxide::kernel" => KERNEL_LEVEL.set(level), + "oxide::builtins" => BUILTINS_LEVEL.set(level), + _ => {} + } + } +} + +fn parse_level(level: &str) -> Option { + if level.eq_ignore_ascii_case("off") { + Some(LogLevel::Off) + } else if level.eq_ignore_ascii_case("error") { + Some(LogLevel::Error) + } else if level.eq_ignore_ascii_case("warn") { + Some(LogLevel::Warn) + } else if level.eq_ignore_ascii_case("info") { + Some(LogLevel::Info) + } else if level.eq_ignore_ascii_case("debug") { + Some(LogLevel::Debug) + } else if level.eq_ignore_ascii_case("trace") { + Some(LogLevel::Trace) + } else { + None + } +} + +#[macro_export] +macro_rules! vm_debug { + ($($arg:tt)*) => { + if $crate::logging::VM_LEVEL.is_enabled($crate::logging::LogLevel::Debug) { + tracing::event!(target: "oxide::vm", tracing::Level::DEBUG, $($arg)*); + } + }; +} + +#[macro_export] +macro_rules! vm_trace { + ($($arg:tt)*) => { + if $crate::logging::VM_LEVEL.is_enabled($crate::logging::LogLevel::Trace) { + tracing::event!(target: "oxide::vm", tracing::Level::TRACE, $($arg)*); + } + }; +} + +#[macro_export] +macro_rules! ic_debug { + ($($arg:tt)*) => { + if $crate::logging::IC_LEVEL.is_enabled($crate::logging::LogLevel::Debug) { + tracing::event!(target: "oxide::ic", tracing::Level::DEBUG, $($arg)*); + } + }; +} + +#[macro_export] +macro_rules! ic_trace { + ($($arg:tt)*) => { + if $crate::logging::IC_LEVEL.is_enabled($crate::logging::LogLevel::Trace) { + tracing::event!(target: "oxide::ic", tracing::Level::TRACE, $($arg)*); + } + }; +} + +#[macro_export] +macro_rules! kernel_info { + ($($arg:tt)*) => { + if $crate::logging::KERNEL_LEVEL.is_enabled($crate::logging::LogLevel::Info) { + tracing::event!(target: "oxide::kernel", tracing::Level::INFO, $($arg)*); + } + }; +} + +#[macro_export] +macro_rules! kernel_debug { + ($($arg:tt)*) => { + if $crate::logging::KERNEL_LEVEL.is_enabled($crate::logging::LogLevel::Debug) { + tracing::event!(target: "oxide::kernel", tracing::Level::DEBUG, $($arg)*); + } + }; +} + +#[macro_export] +macro_rules! kernel_trace { + ($($arg:tt)*) => { + if $crate::logging::KERNEL_LEVEL.is_enabled($crate::logging::LogLevel::Trace) { + tracing::event!(target: "oxide::kernel", tracing::Level::TRACE, $($arg)*); + } + }; +} + +#[macro_export] +macro_rules! builtins_debug { + ($($arg:tt)*) => { + if $crate::logging::BUILTINS_LEVEL.is_enabled($crate::logging::LogLevel::Debug) { + tracing::event!(target: "oxide::builtins", tracing::Level::DEBUG, $($arg)*); + } + }; +} + +#[macro_export] +macro_rules! builtins_trace { + ($($arg:tt)*) => { + if $crate::logging::BUILTINS_LEVEL.is_enabled($crate::logging::LogLevel::Trace) { + tracing::event!(target: "oxide::builtins", tracing::Level::TRACE, $($arg)*); + } + }; +} + +#[cfg(test)] +mod tests { + use super::{LogLevel, SubsystemLevel}; + + #[test] + fn log_level_ordinals_match_gate_contract() { + assert_eq!(LogLevel::Off as u8, 0); + assert_eq!(LogLevel::Trace as u8, 5); + } + + #[test] + fn subsystem_level_defaults_off() { + let level = SubsystemLevel::new(); + assert_eq!(level.get(), LogLevel::Off); + assert!(!level.is_enabled(LogLevel::Error)); + } +} diff --git a/crates/oxide_kernel/src/shape_forge.rs b/crates/oxide_kernel/src/shape_forge.rs index 70f2999b..51291c94 100644 --- a/crates/oxide_kernel/src/shape_forge.rs +++ b/crates/oxide_kernel/src/shape_forge.rs @@ -3,6 +3,8 @@ use std::sync::{Arc, RwLock}; use dashmap::DashMap; +use crate::kernel_debug; + pub type ShapeId = u32; pub type StringIndex = u32; @@ -70,6 +72,7 @@ impl ShapeForge { let key = Self::pack_key(parent_id, prop_name); if let Some(entry) = self.transitions.get(&key) { + kernel_debug!("ShapeForge transition cached parent={} prop={} -> id={}", parent_id, prop_name, *entry); return *entry; } @@ -89,7 +92,14 @@ impl ShapeForge { shapes[(new_id - 1) as usize] = Some(shape); } - *self.transitions.entry(key).or_insert(new_id).value() + let entry = self.transitions.entry(key).or_insert(new_id); + let id = *entry.value(); + if id == new_id { + kernel_debug!("ShapeForge transition parent={} prop={} -> id={}", parent_id, prop_name, new_id); + } else { + kernel_debug!("ShapeForge transition cached parent={} prop={} -> id={}", parent_id, prop_name, id); + } + id } pub fn get_shape(&self, id: ShapeId) -> Option> { diff --git a/crates/oxide_kernel/src/string_forge.rs b/crates/oxide_kernel/src/string_forge.rs index 8d0663ce..ff3f734a 100644 --- a/crates/oxide_kernel/src/string_forge.rs +++ b/crates/oxide_kernel/src/string_forge.rs @@ -5,6 +5,8 @@ use std::sync::RwLock; use hashbrown::hash_map::DefaultHashBuilder as FxBuildHasher; use hashbrown::HashMap; +use crate::{kernel_debug, kernel_trace}; + pub fn hash16(s: &str) -> u16 { let mut h = rustc_hash::FxHasher::default(); s.hash(&mut h); @@ -42,6 +44,7 @@ impl StringForge { if let Some(&idx) = inner.map.get(s) { let entry = &inner.entries[idx as usize]; entry.ref_count.fetch_add(1, Ordering::Release); + kernel_trace!("StringForge intern hit idx={}", idx); return (idx, entry.hash); } } @@ -50,6 +53,7 @@ impl StringForge { if let Some(&idx) = inner.map.get(s) { let entry = &inner.entries[idx as usize]; entry.ref_count.fetch_add(1, Ordering::Release); + kernel_trace!("StringForge intern hit idx={}", idx); return (idx, entry.hash); } @@ -61,6 +65,7 @@ impl StringForge { ref_count: AtomicU32::new(1), hash: h, }); + kernel_debug!("StringForge intern new idx={} len={}", idx, s.len()); (idx, h) } diff --git a/crates/oxide_test262/src/main.rs b/crates/oxide_test262/src/main.rs index 3fe2e630..cbbab3c3 100644 --- a/crates/oxide_test262/src/main.rs +++ b/crates/oxide_test262/src/main.rs @@ -377,9 +377,7 @@ fn is_skipped(meta: &TestMeta) -> Option { } } - if meta.description.contains("generator") - || meta.description.contains("async") - { + if meta.description.contains("generator") || meta.description.contains("async") { return Some("description matches excluded pattern".into()); } diff --git a/crates/oxide_vm/Cargo.toml b/crates/oxide_vm/Cargo.toml index c4c253c6..addab5ee 100644 --- a/crates/oxide_vm/Cargo.toml +++ b/crates/oxide_vm/Cargo.toml @@ -19,6 +19,7 @@ serde_json.workspace = true chrono.workspace = true indexmap.workspace = true unicode-normalization.workspace = true +tracing.workspace = true [dev-dependencies] proptest.workspace = true diff --git a/crates/oxide_vm/src/dispatch/call.rs b/crates/oxide_vm/src/dispatch/call.rs index 790ceee3..73e32b90 100644 --- a/crates/oxide_vm/src/dispatch/call.rs +++ b/crates/oxide_vm/src/dispatch/call.rs @@ -1,5 +1,6 @@ use crate::native::{NativeFn, NativeResult}; use crate::vm::{native_fn_ptr_to_fn, FrameContinuation, Vm}; +use oxide_kernel::{builtins_debug, builtins_trace}; use oxide_types::object::JsObject; use oxide_types::value::JsValue; @@ -24,6 +25,7 @@ impl Vm { } let (args_buf, len) = Self::build_native_args(first_arg_reg, arg_count, this_reg); let args_slice = &args_buf[..len]; + builtins_debug!("native_call depth={} args={}", self.native_call_depth, arg_count); // SAFETY: native_fn was set via set_native_fn with a valid NativeFn pointer; // native_fn_ptr_to_fn is the single coercion point for NativeFnPtr → NativeFn. @@ -33,6 +35,7 @@ impl Vm { match func(self, args_slice) { NativeResult::Ok(val) => { self.native_call_depth -= 1; + builtins_trace!("native_call ok depth={}", self.native_call_depth); self.regs[0] = val; Ok(()) } @@ -49,6 +52,7 @@ impl Vm { } else { format!("{err_val}") }; + builtins_debug!("native_call err={}", msg); (crate::builtins::error::create_error(self, &msg), "Error") }; self.exception_value = Some(error); diff --git a/crates/oxide_vm/src/dispatch/property.rs b/crates/oxide_vm/src/dispatch/property.rs index ed72cffc..5e46ac74 100644 --- a/crates/oxide_vm/src/dispatch/property.rs +++ b/crates/oxide_vm/src/dispatch/property.rs @@ -1,5 +1,6 @@ use oxide_compiler::opcode::OpCode; use oxide_kernel::prop_forge::PropTemplate; +use oxide_kernel::{ic_debug, ic_trace}; use oxide_types::object::JsObject; use crate::vm::Vm; @@ -71,18 +72,28 @@ impl Vm { if cached_shape_id != 0 && cached_shape_id == obj.shape_id() && cached_slot < obj.prop_vec_len() as u32 { self.regs[a] = obj.get_prop_at(cached_slot); + ic_trace!("IC_GET hit shape={} slot={}", cached_shape_id, cached_slot); } else if let Some(template) = self.kernel.prop_forge().get_template(obj.shape_id()) { if template.prop_name == prop_name_si { if template.position < obj.prop_vec_len() as u32 { self.write_ic_back(obj.shape_id(), template.position); + ic_debug!( + "IC_GET propforge hit shape={} prop={} slot={}", + obj.shape_id(), + prop_name_si, + template.position + ); self.regs[a] = obj.get_prop_at(template.position); } else { + ic_debug!("IC_GET miss shape={} prop={}", obj.shape_id(), prop_name_si); self.regs[a] = self.ordinary_get(obj, prop_name_si, val)?; } } else { + ic_debug!("IC_GET miss shape={} prop={}", obj.shape_id(), prop_name_si); self.regs[a] = self.ordinary_get(obj, prop_name_si, val)?; } } else { + ic_debug!("IC_GET miss shape={} prop={}", obj.shape_id(), prop_name_si); let resolved = self.ordinary_get(obj, prop_name_si, val)?; if let Some(pos) = self.kernel.shape_forge().lookup_position(obj.shape_id(), prop_name_si) { self.write_ic_back(obj.shape_id(), pos); @@ -127,15 +138,18 @@ impl Vm { if cached_shape_id != 0 && cached_shape_id == obj.shape_id() && cached_slot < obj.prop_vec_len() as u32 { obj.set_prop_at(cached_slot, value); + ic_trace!("IC_SET hit shape={} slot={}", cached_shape_id, cached_slot); } else if let Some(pos) = self.kernel.shape_forge().lookup_position(obj.shape_id(), prop_name_si) { obj.set_prop_at(pos, value); self.write_ic_back(obj.shape_id(), pos); + ic_debug!("IC_SET write-back shape={} slot={}", obj.shape_id(), pos); } else { let old_shape = obj.shape_id(); self.ordinary_set_dispatch(obj, prop_name_si, value, receiver)?; if old_shape != obj.shape_id() { if let Some(pos) = self.kernel.shape_forge().lookup_position(obj.shape_id(), prop_name_si) { self.write_ic_back(obj.shape_id(), pos); + ic_debug!("IC_SET write-back shape={} slot={}", obj.shape_id(), pos); self.kernel.prop_forge().upsert( obj.shape_id(), PropTemplate { diff --git a/crates/oxide_vm/src/vm.rs b/crates/oxide_vm/src/vm.rs index 47180a7d..f71e26db 100644 --- a/crates/oxide_vm/src/vm.rs +++ b/crates/oxide_vm/src/vm.rs @@ -12,6 +12,7 @@ use crate::coercion; use crate::native::{NativeFn, NativeResult}; use oxide_kernel::kernel::{KernelConfig, OxideKernel}; use oxide_kernel::shape_forge::EMPTY_SHAPE_ID; +use oxide_kernel::{vm_debug, vm_trace}; use oxide_types::mem::{Epoch, P}; use oxide_types::object::{JsObject, NativeFnPtr, PropAttributes}; use oxide_types::value::JsValue; @@ -1355,6 +1356,13 @@ impl Vm { let ext = self.bytecode[self.pc]; self.pc += 1; let arg_count = (ext & 0xFF) as usize; + vm_debug!( + "CALL rd={} this={} args={} depth={}", + rd, + this_reg, + arg_count, + self.frames.len() + ); if obj.native_fn().is_some() { match self.dispatch_native_call(obj, callee, this_reg, first_arg_reg, arg_count) { @@ -1405,6 +1413,7 @@ impl Vm { let ext = self.bytecode[self.pc]; self.pc += 1; let arg_count = (ext & 0xFF) as usize; + vm_debug!("CALL_NATIVE rd={} args={}", rd, arg_count); self.dispatch_native_call(obj, callee, this_reg, first_arg_reg, arg_count)?; } @@ -1412,6 +1421,7 @@ impl Vm { OpCode::NEW_EXPRESSION => { let constructor_reg = a; let first_arg_reg = b as u8; + vm_debug!("NEW_EXPRESSION rd={}", rd); let constructor = self.regs[constructor_reg]; if !constructor.is_object() { @@ -1780,6 +1790,7 @@ impl Vm { OpCode::RETURN => { let result = self.regs[rd]; + vm_debug!("RETURN depth={}", self.frames.len()); if let Some(frame) = self.frames.pop() { let construct_result_reg = frame.construct_result_reg; let constructed_this = frame.constructed_this; @@ -2156,6 +2167,7 @@ impl Vm { } OpCode::THROW => { + vm_debug!("THROW pc={}", self.pc); let exc_value = self.regs[rd]; self.exception_value = Some(exc_value); self.pending_error_kind = Some(self.thrown_error_kind(exc_value)); @@ -2166,6 +2178,7 @@ impl Vm { } OpCode::TRY_BEGIN => { + vm_trace!("TRY_BEGIN frame_depth={}", self.frames.len()); let offset = opcode::offset16(instr) as isize; let catch_pc = if offset == 0 { None