From 3e7c0822936b5e2a1f1234b37e2719ffb96c279d Mon Sep 17 00:00:00 2001 From: pjh456 <147148383@qq.com> Date: Fri, 26 Jun 2026 20:50:05 +0800 Subject: [PATCH] =?UTF-8?q?feat:=20=E4=B8=BA=20VM=20=E6=B7=BB=E5=8A=A0?= =?UTF-8?q?=E7=BB=93=E6=9E=84=E5=8C=96=E6=97=A5=E5=BF=97?= MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit --- crates/oxide_vm/src/dispatch/arithmetic.rs | 14 +++++ crates/oxide_vm/src/dispatch/bitwise.rs | 14 +++++ crates/oxide_vm/src/dispatch/call.rs | 6 ++ crates/oxide_vm/src/dispatch/comparison.rs | 41 ++++++++++-- crates/oxide_vm/src/dispatch/control_flow.rs | 9 +++ crates/oxide_vm/src/dispatch/member.rs | 66 +++++++++++++++----- crates/oxide_vm/src/dispatch/misc.rs | 11 +++- crates/oxide_vm/src/dispatch/property.rs | 14 ++++- crates/oxide_vm/src/ic_helper.rs | 2 + crates/oxide_vm/src/session_arena.rs | 3 + crates/oxide_vm/src/session_gc.rs | 18 +++++- crates/oxide_vm/src/vm.rs | 14 +++++ crates/oxide_vm/src/vm_dispatch_ctrl.rs | 33 ++++++++-- crates/oxide_vm/src/vm_dispatch_misc.rs | 16 ++++- crates/oxide_vm/src/vm_pool.rs | 6 ++ crates/oxide_vm/src/vm_props.rs | 23 +++++++ crates/oxide_vm/src/vm_runtime.rs | 27 ++++++++ crates/oxide_vm/src/vm_support.rs | 14 +++-- 18 files changed, 297 insertions(+), 34 deletions(-) diff --git a/crates/oxide_vm/src/dispatch/arithmetic.rs b/crates/oxide_vm/src/dispatch/arithmetic.rs index 397c1ff4..69b59599 100644 --- a/crates/oxide_vm/src/dispatch/arithmetic.rs +++ b/crates/oxide_vm/src/dispatch/arithmetic.rs @@ -1,10 +1,12 @@ use crate::vm::Vm; +use crate::vm_trace; use oxide_runtime_api as coercion; use oxide_types::value::JsValue; impl Vm { #[inline(always)] pub(crate) fn dispatch_add(&mut self, rd: usize, a: usize, b: usize) -> Result<(), String> { + vm_trace!("ADD rd={} r{}={:?} r{}={:?}", rd, a, self.regs[a], b, self.regs[b]); let lhs = self.coerce_primitive_bounded(self.regs[a], false)?; let rhs = self.coerce_primitive_bounded(self.regs[b], false)?; if lhs.is_string() || rhs.is_string() { @@ -22,6 +24,7 @@ impl Vm { #[inline(always)] pub(crate) fn dispatch_neg(&mut self, rd: usize, a: usize) -> Result<(), String> { + vm_trace!("NEG rd={} r{}={:?}", rd, a, self.regs[a]); let v = self.coerce_number_bounded(self.regs[a])?; self.regs[rd] = JsValue::float(-v); Ok(()) @@ -29,12 +32,14 @@ impl Vm { #[inline(always)] pub(crate) fn dispatch_unary_plus(&mut self, rd: usize, a: usize) -> Result<(), String> { + vm_trace!("UNARY_PLUS rd={} r{}={:?}", rd, a, self.regs[a]); let v = self.coerce_number_bounded(self.regs[a])?; self.regs[rd] = JsValue::float(v); Ok(()) } pub(crate) fn dispatch_compound_add(&mut self, rd: usize, a: usize) -> Result<(), String> { + vm_trace!("COMPOUND_ADD rd={} r{}={:?}", rd, a, self.regs[a]); let lhs = self.coerce_primitive_bounded(self.regs[rd], false)?; let rhs = self.coerce_primitive_bounded(self.regs[a], false)?; if lhs.is_string() || rhs.is_string() { @@ -52,6 +57,7 @@ impl Vm { #[inline(always)] pub(crate) fn dispatch_compound_sub(&mut self, rd: usize, a: usize) -> Result<(), String> { + vm_trace!("COMPOUND_SUB rd={} r{}={:?}", rd, a, self.regs[a]); let l = self.coerce_number_bounded(self.regs[rd])?; let r = self.coerce_number_bounded(self.regs[a])?; self.regs[rd] = JsValue::float(l - r); @@ -60,6 +66,7 @@ impl Vm { #[inline(always)] pub(crate) fn dispatch_compound_mul(&mut self, rd: usize, a: usize) -> Result<(), String> { + vm_trace!("COMPOUND_MUL rd={} r{}={:?}", rd, a, self.regs[a]); let l = self.coerce_number_bounded(self.regs[rd])?; let r = self.coerce_number_bounded(self.regs[a])?; self.regs[rd] = JsValue::float(l * r); @@ -68,6 +75,7 @@ impl Vm { #[inline(always)] pub(crate) fn dispatch_compound_div(&mut self, rd: usize, a: usize) -> Result<(), String> { + vm_trace!("COMPOUND_DIV rd={} r{}={:?}", rd, a, self.regs[a]); let l = self.coerce_number_bounded(self.regs[rd])?; let r = self.coerce_number_bounded(self.regs[a])?; self.regs[rd] = JsValue::float(l / r); @@ -76,6 +84,7 @@ impl Vm { #[inline(always)] pub(crate) fn dispatch_compound_mod(&mut self, rd: usize, a: usize) -> Result<(), String> { + vm_trace!("COMPOUND_MOD rd={} r{}={:?}", rd, a, self.regs[a]); let l = self.coerce_number_bounded(self.regs[rd])?; let r = self.coerce_number_bounded(self.regs[a])?; self.regs[rd] = JsValue::float(l % r); @@ -84,6 +93,7 @@ impl Vm { #[inline(always)] pub(crate) fn dispatch_compound_exp(&mut self, rd: usize, a: usize) -> Result<(), String> { + vm_trace!("COMPOUND_EXP rd={} r{}={:?}", rd, a, self.regs[a]); let l = self.coerce_number_bounded(self.regs[rd])?; let r = self.coerce_number_bounded(self.regs[a])?; self.regs[rd] = JsValue::float(l.powf(r)); @@ -92,6 +102,7 @@ impl Vm { #[inline(always)] pub(crate) fn dispatch_inc_pre(&mut self, rd: usize, a: usize) -> Result<(), String> { + vm_trace!("INC_PRE rd={} a={}", rd, a); let n = self.coerce_number_bounded(self.regs[rd])?; let result = JsValue::float(n + 1.0); self.regs[rd] = result; @@ -101,6 +112,7 @@ impl Vm { #[inline(always)] pub(crate) fn dispatch_inc_post(&mut self, rd: usize, a: usize) -> Result<(), String> { + vm_trace!("INC_POST rd={} a={}", rd, a); let n = self.coerce_number_bounded(self.regs[rd])?; self.regs[a] = JsValue::float(n); self.regs[rd] = JsValue::float(n + 1.0); @@ -109,6 +121,7 @@ impl Vm { #[inline(always)] pub(crate) fn dispatch_dec_pre(&mut self, rd: usize, a: usize) -> Result<(), String> { + vm_trace!("DEC_PRE rd={} a={}", rd, a); let n = self.coerce_number_bounded(self.regs[rd])?; let result = JsValue::float(n - 1.0); self.regs[rd] = result; @@ -118,6 +131,7 @@ impl Vm { #[inline(always)] pub(crate) fn dispatch_dec_post(&mut self, rd: usize, a: usize) -> Result<(), String> { + vm_trace!("DEC_POST rd={} a={}", rd, a); let n = self.coerce_number_bounded(self.regs[rd])?; self.regs[a] = JsValue::float(n); self.regs[rd] = JsValue::float(n - 1.0); diff --git a/crates/oxide_vm/src/dispatch/bitwise.rs b/crates/oxide_vm/src/dispatch/bitwise.rs index 9edc85d9..d5d6bff8 100644 --- a/crates/oxide_vm/src/dispatch/bitwise.rs +++ b/crates/oxide_vm/src/dispatch/bitwise.rs @@ -1,4 +1,5 @@ use crate::vm::Vm; +use crate::vm_trace; use oxide_types::value::JsValue; impl Vm { @@ -13,6 +14,7 @@ impl Vm { #[inline(always)] pub(crate) fn dispatch_bit_and(&mut self, rd: usize, a: usize, b: usize) -> Result<(), String> { + vm_trace!("BIT_AND rd={} r{},r{}", rd, a, b); self.regs[rd] = JsValue::int(self.coerce_int32_bounded(self.regs[a])? & self.coerce_int32_bounded(self.regs[b])?); Ok(()) @@ -20,6 +22,7 @@ impl Vm { #[inline(always)] pub(crate) fn dispatch_bit_or(&mut self, rd: usize, a: usize, b: usize) -> Result<(), String> { + vm_trace!("BIT_OR rd={} r{},r{}", rd, a, b); self.regs[rd] = JsValue::int(self.coerce_int32_bounded(self.regs[a])? | self.coerce_int32_bounded(self.regs[b])?); Ok(()) @@ -27,6 +30,7 @@ impl Vm { #[inline(always)] pub(crate) fn dispatch_bit_xor(&mut self, rd: usize, a: usize, b: usize) -> Result<(), String> { + vm_trace!("BIT_XOR rd={} r{},r{}", rd, a, b); self.regs[rd] = JsValue::int(self.coerce_int32_bounded(self.regs[a])? ^ self.coerce_int32_bounded(self.regs[b])?); Ok(()) @@ -34,6 +38,7 @@ impl Vm { #[inline(always)] pub(crate) fn dispatch_shl(&mut self, rd: usize, a: usize, b: usize) -> Result<(), String> { + vm_trace!("SHL rd={} r{},r{}", rd, a, b); let lhs = self.coerce_int32_bounded(self.regs[a])?; let shift = self.coerce_uint32_bounded(self.regs[b])? & 0x1F; self.regs[rd] = JsValue::int(lhs.wrapping_shl(shift)); @@ -42,6 +47,7 @@ impl Vm { #[inline(always)] pub(crate) fn dispatch_shr(&mut self, rd: usize, a: usize, b: usize) -> Result<(), String> { + vm_trace!("SHR rd={} r{},r{}", rd, a, b); let lhs = self.coerce_int32_bounded(self.regs[a])?; let shift = self.coerce_uint32_bounded(self.regs[b])? & 0x1F; self.regs[rd] = JsValue::int(lhs >> shift); @@ -50,6 +56,7 @@ impl Vm { #[inline(always)] pub(crate) fn dispatch_ushr(&mut self, rd: usize, a: usize, b: usize) -> Result<(), String> { + vm_trace!("USHR rd={} r{},r{}", rd, a, b); let lhs = self.coerce_uint32_bounded(self.regs[a])?; let shift = self.coerce_uint32_bounded(self.regs[b])? & 0x1F; self.write_ushr_result(rd, lhs >> shift); @@ -58,12 +65,14 @@ impl Vm { #[inline(always)] pub(crate) fn dispatch_bit_not(&mut self, rd: usize, a: usize) -> Result<(), String> { + vm_trace!("BIT_NOT rd={} r{}", rd, a); self.regs[rd] = JsValue::int(!self.coerce_int32_bounded(self.regs[a])?); Ok(()) } #[inline(always)] pub(crate) fn dispatch_compound_bit_and(&mut self, rd: usize, a: usize) -> Result<(), String> { + vm_trace!("COMPOUND_BIT_AND rd={} r{}", rd, a); self.regs[rd] = JsValue::int(self.coerce_int32_bounded(self.regs[rd])? & self.coerce_int32_bounded(self.regs[a])?); Ok(()) @@ -71,6 +80,7 @@ impl Vm { #[inline(always)] pub(crate) fn dispatch_compound_bit_or(&mut self, rd: usize, a: usize) -> Result<(), String> { + vm_trace!("COMPOUND_BIT_OR rd={} r{}", rd, a); self.regs[rd] = JsValue::int(self.coerce_int32_bounded(self.regs[rd])? | self.coerce_int32_bounded(self.regs[a])?); Ok(()) @@ -78,6 +88,7 @@ impl Vm { #[inline(always)] pub(crate) fn dispatch_compound_bit_xor(&mut self, rd: usize, a: usize) -> Result<(), String> { + vm_trace!("COMPOUND_BIT_XOR rd={} r{}", rd, a); self.regs[rd] = JsValue::int(self.coerce_int32_bounded(self.regs[rd])? ^ self.coerce_int32_bounded(self.regs[a])?); Ok(()) @@ -85,6 +96,7 @@ impl Vm { #[inline(always)] pub(crate) fn dispatch_compound_shl(&mut self, rd: usize, a: usize) -> Result<(), String> { + vm_trace!("COMPOUND_SHL rd={} r{}", rd, a); let lhs = self.coerce_int32_bounded(self.regs[rd])?; let shift = self.coerce_uint32_bounded(self.regs[a])? & 0x1F; self.regs[rd] = JsValue::int(lhs.wrapping_shl(shift)); @@ -93,6 +105,7 @@ impl Vm { #[inline(always)] pub(crate) fn dispatch_compound_shr(&mut self, rd: usize, a: usize) -> Result<(), String> { + vm_trace!("COMPOUND_SHR rd={} r{}", rd, a); let lhs = self.coerce_int32_bounded(self.regs[rd])?; let shift = self.coerce_uint32_bounded(self.regs[a])? & 0x1F; self.regs[rd] = JsValue::int(lhs >> shift); @@ -101,6 +114,7 @@ impl Vm { #[inline(always)] pub(crate) fn dispatch_compound_ushr(&mut self, rd: usize, a: usize) -> Result<(), String> { + vm_trace!("COMPOUND_USHR rd={} r{}", rd, a); let lhs = self.coerce_uint32_bounded(self.regs[rd])?; let shift = self.coerce_uint32_bounded(self.regs[a])? & 0x1F; self.write_ushr_result(rd, lhs >> shift); diff --git a/crates/oxide_vm/src/dispatch/call.rs b/crates/oxide_vm/src/dispatch/call.rs index a27a34ca..9bedd289 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; use crate::vm::{native_fn_ptr_to_fn, CallFrame, FrameContinuation, Vm}; +use crate::{vm_debug, vm_trace}; use oxide_builtins::{builtins_debug, builtins_trace}; use oxide_bytecode::opcode; use oxide_runtime_api::NativeResult; @@ -79,6 +80,7 @@ impl Vm { impl Vm { pub(crate) fn dispatch_create_closure(&mut self, rd: usize, instr: u32) { let sub_idx = opcode::imm16(instr) as u32; + vm_trace!("CREATE_CLOSURE rd={} sub_idx={}", rd, sub_idx); debug_assert!(sub_idx > 0 && (sub_idx as usize) <= self.sub_modules.len()); let sub = &self.sub_modules[sub_idx as usize - 1]; let result = self.create_function_object( @@ -92,6 +94,7 @@ impl Vm { } pub(crate) fn dispatch_create_regexp(&mut self, rd: usize, a: usize, b: usize) -> Result, String> { + vm_trace!("CREATE_REGEXP rd={}", rd); let pat_val = self.regs[a]; let flags_val = self.regs[b]; let ctor_ptr = self.session.builtin_world().regexp_constructor.as_ptr() as *mut JsObject; @@ -124,6 +127,7 @@ impl Vm { } pub(crate) fn dispatch_super_call(&mut self, rd: usize, a: usize) -> Result { + vm_debug!("SUPER_CALL depth={}", self.frames.len()); let first_arg_reg = a as u8; let ext = self.bytecode[self.pc]; self.pc += 1; @@ -266,6 +270,7 @@ impl Vm { } pub(crate) fn dispatch_super_get_prop(&mut self, rd: usize, a: usize, b: usize) -> Result { + vm_trace!("SUPER_GET_PROP rd={} a={} b={}", rd, a, b); let key_val = self.regs[b]; let prop_name_si = self.property_key_si(key_val); let Some(frame) = self.frames.last() else { @@ -297,6 +302,7 @@ impl Vm { } pub(crate) fn dispatch_set_home_object(&mut self, rd: usize, a: usize) -> Result { + vm_trace!("SET_HOME_OBJECT rd={} a={}", rd, a); let func_val = self.regs[rd]; let home_val = self.regs[a]; if !func_val.is_object() || !home_val.is_object() { diff --git a/crates/oxide_vm/src/dispatch/comparison.rs b/crates/oxide_vm/src/dispatch/comparison.rs index ac636e45..c312dceb 100644 --- a/crates/oxide_vm/src/dispatch/comparison.rs +++ b/crates/oxide_vm/src/dispatch/comparison.rs @@ -1,52 +1,85 @@ use crate::vm::Vm; +use crate::vm_trace; use oxide_runtime_api as coercion; use oxide_types::value::JsValue; impl Vm { #[inline(always)] pub(crate) fn dispatch_eq(&mut self, rd: usize, a: usize, b: usize) { + vm_trace!("EQ rd={} r{}={:?} r{}={:?}", rd, a, self.regs[a], b, self.regs[b]); let eq = coercion::abstract_eq(self.regs[a], self.regs[b]); self.regs[rd] = JsValue::bool(eq); } #[inline(always)] pub(crate) fn dispatch_neq(&mut self, rd: usize, a: usize, b: usize) { + vm_trace!("NEQ rd={} r{}={:?} r{}={:?}", rd, a, self.regs[a], b, self.regs[b]); let ne = !coercion::abstract_eq(self.regs[a], self.regs[b]); self.regs[rd] = JsValue::bool(ne); } #[inline(always)] pub(crate) fn dispatch_lt(&mut self, rd: usize, a: usize, b: usize) { + vm_trace!("LT rd={} r{}={:?} r{}={:?}", rd, a, self.regs[a], b, self.regs[b]); let rel = coercion::relational_compare(self.regs[a], self.regs[b]); - self.regs[rd] = JsValue::bool(rel.unwrap_or(false)); + match rel { + Some(r) => self.regs[rd] = JsValue::bool(r), + None => { + vm_trace!("LT incomparable r{}={:?} r{}={:?}", a, self.regs[a], b, self.regs[b]); + self.regs[rd] = JsValue::bool(false); + } + } } #[inline(always)] pub(crate) fn dispatch_gt(&mut self, rd: usize, a: usize, b: usize) { + vm_trace!("GT rd={} r{}={:?} r{}={:?}", rd, a, self.regs[a], b, self.regs[b]); let rel = coercion::relational_compare(self.regs[b], self.regs[a]); - self.regs[rd] = JsValue::bool(rel.unwrap_or(false)); + match rel { + Some(r) => self.regs[rd] = JsValue::bool(r), + None => { + vm_trace!("GT incomparable r{}={:?} r{}={:?}", a, self.regs[a], b, self.regs[b]); + self.regs[rd] = JsValue::bool(false); + } + } } #[inline(always)] pub(crate) fn dispatch_lte(&mut self, rd: usize, a: usize, b: usize) { + vm_trace!("LTE rd={} r{}={:?} r{}={:?}", rd, a, self.regs[a], b, self.regs[b]); let rel = coercion::relational_compare(self.regs[b], self.regs[a]); - self.regs[rd] = JsValue::bool(!rel.unwrap_or(true)); + match rel { + Some(r) => self.regs[rd] = JsValue::bool(!r), + None => { + vm_trace!("LTE incomparable r{}={:?} r{}={:?}", a, self.regs[a], b, self.regs[b]); + self.regs[rd] = JsValue::bool(false); + } + } } #[inline(always)] pub(crate) fn dispatch_gte(&mut self, rd: usize, a: usize, b: usize) { + vm_trace!("GTE rd={} r{}={:?} r{}={:?}", rd, a, self.regs[a], b, self.regs[b]); let rel = coercion::relational_compare(self.regs[a], self.regs[b]); - self.regs[rd] = JsValue::bool(!rel.unwrap_or(true)); + match rel { + Some(r) => self.regs[rd] = JsValue::bool(!r), + None => { + vm_trace!("GTE incomparable r{}={:?} r{}={:?}", a, self.regs[a], b, self.regs[b]); + self.regs[rd] = JsValue::bool(false); + } + } } #[inline(always)] pub(crate) fn dispatch_strict_eq(&mut self, rd: usize, a: usize, b: usize) { + vm_trace!("STRICT_EQ rd={} r{}={:?} r{}={:?}", rd, a, self.regs[a], b, self.regs[b]); let eq = coercion::strict_equality(self.regs[a], self.regs[b]); self.regs[rd] = JsValue::bool(eq); } #[inline(always)] pub(crate) fn dispatch_strict_neq(&mut self, rd: usize, a: usize, b: usize) { + vm_trace!("STRICT_NEQ rd={} r{}={:?} r{}={:?}", rd, a, self.regs[a], b, self.regs[b]); let ne = !coercion::strict_equality(self.regs[a], self.regs[b]); self.regs[rd] = JsValue::bool(ne); } diff --git a/crates/oxide_vm/src/dispatch/control_flow.rs b/crates/oxide_vm/src/dispatch/control_flow.rs index dce8e4c0..c671f93e 100644 --- a/crates/oxide_vm/src/dispatch/control_flow.rs +++ b/crates/oxide_vm/src/dispatch/control_flow.rs @@ -1,4 +1,5 @@ use crate::vm::Vm; +use crate::vm_trace; use oxide_bytecode::opcode::{self, Instr}; use oxide_runtime_api as coercion; use oxide_types::value::JsValue; @@ -7,11 +8,13 @@ impl Vm { #[inline(always)] pub(crate) fn dispatch_jmp(&mut self, instr: Instr) { let offset = opcode::offset16(instr) as isize; + vm_trace!("JMP offset={}", offset); self.pc = ((self.pc as isize) + offset - 1) as usize; } #[inline(always)] pub(crate) fn dispatch_jmp_if_false(&mut self, rd: usize, instr: Instr) { + vm_trace!("JMP_IF_FALSE r{}={:?}", rd, self.regs[rd]); let cond = coercion::to_boolean(self.regs[rd]); if !cond { let offset = opcode::offset16(instr) as isize; @@ -21,6 +24,7 @@ impl Vm { #[inline(always)] pub(crate) fn dispatch_jmp_if_true(&mut self, rd: usize, instr: Instr) { + vm_trace!("JMP_IF_TRUE r{}={:?}", rd, self.regs[rd]); let cond = coercion::to_boolean(self.regs[rd]); if cond { let offset = opcode::offset16(instr) as isize; @@ -30,6 +34,7 @@ impl Vm { #[inline(always)] pub(crate) fn dispatch_jmp_if_nullish(&mut self, rd: usize, instr: Instr) { + vm_trace!("JMP_IF_NULLISH r{}={:?}", rd, self.regs[rd]); if self.regs[rd].is_nullish() { let offset = opcode::offset16(instr) as isize; self.pc = ((self.pc as isize) + offset - 1) as usize; @@ -38,6 +43,7 @@ impl Vm { #[inline(always)] pub(crate) fn dispatch_and(&mut self, rd: usize, a: usize, b: usize) { + vm_trace!("LOGICAL_AND rd={} r{}={:?} r{}={:?}", rd, a, self.regs[a], b, self.regs[b]); let val = self.regs[a]; if coercion::to_boolean(val) { self.regs[rd] = self.regs[b]; @@ -48,6 +54,7 @@ impl Vm { #[inline(always)] pub(crate) fn dispatch_or(&mut self, rd: usize, a: usize, b: usize) { + vm_trace!("LOGICAL_OR rd={} r{}={:?} r{}={:?}", rd, a, self.regs[a], b, self.regs[b]); let val = self.regs[a]; if coercion::to_boolean(val) { self.regs[rd] = val; @@ -58,12 +65,14 @@ impl Vm { #[inline(always)] pub(crate) fn dispatch_nullish(&mut self, rd: usize, a: usize, b: usize) { + vm_trace!("NULLISH rd={} r{}={:?} r{}={:?}", rd, a, self.regs[a], b, self.regs[b]); let val = self.regs[a]; self.regs[rd] = if val.is_nullish() { self.regs[b] } else { val }; } #[inline(always)] pub(crate) fn dispatch_not(&mut self, rd: usize, a: usize) { + vm_trace!("NOT rd={} r{}={:?}", rd, a, self.regs[a]); let b = !coercion::to_boolean(self.regs[a]); self.regs[rd] = JsValue::bool(b); } diff --git a/crates/oxide_vm/src/dispatch/member.rs b/crates/oxide_vm/src/dispatch/member.rs index 871b8e5c..c1c01015 100644 --- a/crates/oxide_vm/src/dispatch/member.rs +++ b/crates/oxide_vm/src/dispatch/member.rs @@ -3,36 +3,64 @@ use oxide_types::object::JsObject; use oxide_types::value::JsValue; use crate::vm::Vm; +use crate::vm_trace; use oxide_runtime_api as coercion; impl Vm { pub(crate) fn dispatch_member_op(&mut self, op: OpCode, rd: usize, a: usize, b: usize) -> Result<(), String> { + vm_trace!("MEMBER_OP {:?} rd={} a={} b={}", op, rd, a, b); match op { OpCode::MEMBER_INC => self.dispatch_member_inc(rd, a, b), OpCode::MEMBER_DEC => self.dispatch_member_dec(rd, a, b), OpCode::DYN_MEMBER_INC => self.dispatch_dyn_member_inc(rd, a, b), OpCode::DYN_MEMBER_DEC => self.dispatch_dyn_member_dec(rd, a, b), OpCode::COMPOUND_MEMBER_ADD => self.dispatch_compound_member_add(rd, a, b), - OpCode::COMPOUND_MEMBER_SUB => { - self.dispatch_compound_member_numeric(rd, a, b, "COMPOUND_MEMBER_SUB on non-object", |l, r| l - r) - } - OpCode::COMPOUND_MEMBER_MUL => { - self.dispatch_compound_member_numeric(rd, a, b, "COMPOUND_MEMBER_MUL on non-object", |l, r| l * r) - } - OpCode::COMPOUND_MEMBER_DIV => { - self.dispatch_compound_member_numeric(rd, a, b, "COMPOUND_MEMBER_DIV on non-object", |l, r| l / r) - } - OpCode::COMPOUND_MEMBER_MOD => { - self.dispatch_compound_member_numeric(rd, a, b, "COMPOUND_MEMBER_MOD on non-object", |l, r| l % r) - } - OpCode::COMPOUND_MEMBER_EXP => { - self.dispatch_compound_member_numeric(rd, a, b, "COMPOUND_MEMBER_EXP on non-object", |l, r| l.powf(r)) - } + OpCode::COMPOUND_MEMBER_SUB => self.dispatch_compound_member_numeric( + "COMPOUND_MEMBER_SUB", + rd, + a, + b, + "COMPOUND_MEMBER_SUB on non-object", + |l, r| l - r, + ), + OpCode::COMPOUND_MEMBER_MUL => self.dispatch_compound_member_numeric( + "COMPOUND_MEMBER_MUL", + rd, + a, + b, + "COMPOUND_MEMBER_MUL on non-object", + |l, r| l * r, + ), + OpCode::COMPOUND_MEMBER_DIV => self.dispatch_compound_member_numeric( + "COMPOUND_MEMBER_DIV", + rd, + a, + b, + "COMPOUND_MEMBER_DIV on non-object", + |l, r| l / r, + ), + OpCode::COMPOUND_MEMBER_MOD => self.dispatch_compound_member_numeric( + "COMPOUND_MEMBER_MOD", + rd, + a, + b, + "COMPOUND_MEMBER_MOD on non-object", + |l, r| l % r, + ), + OpCode::COMPOUND_MEMBER_EXP => self.dispatch_compound_member_numeric( + "COMPOUND_MEMBER_EXP", + rd, + a, + b, + "COMPOUND_MEMBER_EXP on non-object", + |l, r| l.powf(r), + ), _ => unreachable!("non-member opcode passed to dispatch_member_op"), } } fn member_target(&mut self, rd: usize, b: usize, error_msg: &str) -> Result<(*mut JsObject, u32), String> { + vm_trace!("MEMBER_TARGET rd={} b={}", rd, b); let Some(obj_ptr) = self.checked_object_ptr(self.regs[rd], error_msg)? else { return Err(String::new()); }; @@ -41,6 +69,7 @@ impl Vm { } fn dispatch_member_inc(&mut self, rd: usize, a: usize, b: usize) -> Result<(), String> { + vm_trace!("MEMBER_INC rd={} a={} b={}", rd, a, b); let Ok((obj_ptr, prop_name_si)) = self.member_target(rd, b, "MEMBER_INC on non-object") else { return Ok(()); }; @@ -55,6 +84,7 @@ impl Vm { } fn dispatch_member_dec(&mut self, rd: usize, a: usize, b: usize) -> Result<(), String> { + vm_trace!("MEMBER_DEC rd={} a={} b={}", rd, a, b); let Ok((obj_ptr, prop_name_si)) = self.member_target(rd, b, "MEMBER_DEC on non-object") else { return Ok(()); }; @@ -69,6 +99,7 @@ impl Vm { } fn dispatch_dyn_member_inc(&mut self, rd: usize, a: usize, b: usize) -> Result<(), String> { + vm_trace!("DYN_MEMBER_INC rd={} a={} b={}", rd, a, b); let Some(obj_ptr) = self.checked_object_ptr(self.regs[rd], "DYN_MEMBER_INC on non-object")? else { return Ok(()); }; @@ -84,6 +115,7 @@ impl Vm { } fn dispatch_dyn_member_dec(&mut self, rd: usize, a: usize, b: usize) -> Result<(), String> { + vm_trace!("DYN_MEMBER_DEC rd={} a={} b={}", rd, a, b); let Some(obj_ptr) = self.checked_object_ptr(self.regs[rd], "DYN_MEMBER_DEC on non-object")? else { return Ok(()); }; @@ -99,6 +131,7 @@ impl Vm { } fn dispatch_compound_member_add(&mut self, rd: usize, a: usize, b: usize) -> Result<(), String> { + vm_trace!("COMPOUND_MEMBER_ADD rd={} a={} b={}", rd, a, b); let Ok((obj_ptr, prop_name_si)) = self.member_target(rd, b, "COMPOUND_MEMBER_ADD on non-object") else { return Ok(()); }; @@ -125,11 +158,12 @@ impl Vm { } fn dispatch_compound_member_numeric( - &mut self, rd: usize, a: usize, b: usize, error_msg: &str, op: F, + &mut self, op_name: &str, rd: usize, a: usize, b: usize, error_msg: &str, op: F, ) -> Result<(), String> where F: FnOnce(f64, f64) -> f64, { + vm_trace!("{} rd={} a={} b={}", op_name, rd, a, b); let Ok((obj_ptr, prop_name_si)) = self.member_target(rd, b, error_msg) else { return Ok(()); }; diff --git a/crates/oxide_vm/src/dispatch/misc.rs b/crates/oxide_vm/src/dispatch/misc.rs index 65f39b97..28ed6622 100644 --- a/crates/oxide_vm/src/dispatch/misc.rs +++ b/crates/oxide_vm/src/dispatch/misc.rs @@ -1,4 +1,5 @@ use crate::vm::Vm; +use crate::{vm_error, vm_trace}; use oxide_bytecode::opcode; use oxide_kernel::shape_forge::EMPTY_SHAPE_ID; use oxide_types::object::JsObject; @@ -8,17 +9,20 @@ impl Vm { #[inline(always)] pub(crate) fn dispatch_load_const(&mut self, rd: usize, instr: u32) -> Result<(), String> { let idx = (instr >> 16) as usize; + vm_trace!("LOAD_CONST rd={} idx={}", rd, idx); let imm = self.immutables(); if idx < imm.len() { self.regs[rd] = imm[idx]; Ok(()) } else { + vm_error!("LOAD_CONST index {} out of bounds (len={})", idx, imm.len()); Err(format!("constant index {idx} out of bounds")) } } #[inline(always)] pub(crate) fn dispatch_typeof(&mut self, rd: usize, a: usize) { + vm_trace!("TYPEOF rd={} r{}={:?}", rd, a, self.regs[a]); let val = self.regs[a]; let result = if val.is_undefined() { "undefined" @@ -46,6 +50,7 @@ impl Vm { } pub(crate) fn dispatch_load_var(&mut self, rd: usize, a: usize) -> Result { + vm_trace!("LOAD_VAR rd={} r{}={:?}", rd, a, self.regs[a]); if a == 254 && self.frames.last().map(|frame| frame.is_derived_constructor).unwrap_or(false) && self.regs[a].is_undefined() @@ -58,6 +63,7 @@ impl Vm { } pub(crate) fn dispatch_store_var(&mut self, rd: usize, a: usize, b: usize) -> Result { + vm_trace!("STORE_VAR r{}={:?} const={}", rd, self.regs[a], b); if b != 0 { // const guard: check if already initialized if !self.regs[rd].is_undefined() { @@ -71,6 +77,7 @@ impl Vm { #[inline(always)] pub(crate) fn dispatch_new_object(&mut self, rd: usize) { + vm_trace!("NEW_OBJECT rd={}", rd); let proto_ptr = &*self.object_prototype as *const JsObject as *mut JsObject; let obj = self .epoch @@ -80,8 +87,9 @@ impl Vm { #[inline(always)] pub(crate) fn dispatch_new_array(&mut self, rd: usize, instr: u32) { - let proto_ptr = self.session.builtin_world().array_proto.as_ptr() as *mut JsObject; let n = opcode::imm16(instr) as usize; + vm_trace!("NEW_ARRAY rd={} n={}", rd, n); + let proto_ptr = self.session.builtin_world().array_proto.as_ptr() as *mut JsObject; let bump = self.epoch.bump(); let obj = self.alloc_object(JsObject::new_array(EMPTY_SHAPE_ID, JsValue::from_js_object(proto_ptr), n, bump)); self.regs[rd] = JsValue::object(obj as *mut u8); @@ -89,6 +97,7 @@ impl Vm { #[inline(always)] pub(crate) fn dispatch_void(&mut self, rd: usize) { + vm_trace!("VOID rd={}", rd); self.regs[rd] = JsValue::undefined(); } } diff --git a/crates/oxide_vm/src/dispatch/property.rs b/crates/oxide_vm/src/dispatch/property.rs index 605d4b2e..14258d62 100644 --- a/crates/oxide_vm/src/dispatch/property.rs +++ b/crates/oxide_vm/src/dispatch/property.rs @@ -1,4 +1,4 @@ -use crate::{ic_debug, ic_trace}; +use crate::{ic_debug, ic_trace, vm_trace}; use oxide_bytecode::opcode::OpCode; use oxide_kernel::prop_forge::PropTemplate; use oxide_types::object::JsObject; @@ -13,6 +13,7 @@ fn prop_cache_miss() {} impl Vm { pub(crate) fn dispatch_property_op(&mut self, op: OpCode, rd: usize, a: usize, b: usize) -> Result<(), String> { + vm_trace!("PROPERTY_OP {:?} rd={} a={} b={}", op, rd, a, b); match op { OpCode::IC_GET_PROP => self.dispatch_ic_get_prop(a, b), OpCode::IC_SET_PROP => self.dispatch_ic_set_prop(rd, a, b), @@ -88,6 +89,7 @@ impl Vm { } fn dispatch_get_private(&mut self, rd: usize, a: usize, b: usize) -> Result<(), String> { + vm_trace!("GET_PRIVATE rd={} a={} b={}", rd, a, b); let Some(obj_ptr) = self.checked_object_ptr(self.regs[a], "private field access on non-object")? else { return Ok(()); }; @@ -101,6 +103,7 @@ impl Vm { } fn dispatch_set_private(&mut self, rd: usize, a: usize, b: usize) -> Result<(), String> { + vm_trace!("SET_PRIVATE rd={} a={} b={}", rd, a, b); let Some(obj_ptr) = self.checked_object_ptr(self.regs[rd], "private field assignment on non-object")? else { return Ok(()); }; @@ -116,6 +119,7 @@ impl Vm { } fn dispatch_init_private(&mut self, rd: usize, a: usize, b: usize) -> Result<(), String> { + vm_trace!("INIT_PRIVATE rd={} a={} b={}", rd, a, b); let Some(obj_ptr) = self.checked_object_ptr(self.regs[rd], "private field initialization on non-object")? else { return Ok(()); @@ -132,6 +136,7 @@ impl Vm { } fn dispatch_private_brand_in(&mut self, rd: usize, a: usize, b: usize) -> Result<(), String> { + vm_trace!("PRIVATE_BRAND_IN rd={} a={} b={}", rd, a, b); let obj_val = self.regs[a]; if !obj_val.is_object() { self.regs[rd] = JsValue::bool(false); @@ -274,6 +279,7 @@ impl Vm { } fn dispatch_get_prop(&mut self, rd: usize, a: usize, b: usize) -> Result<(), String> { + vm_trace!("GET_PROP rd={} a={} b={}", rd, a, b); let prop_name_si = self.property_key_si(self.regs[b]); if let Some(value) = self.primitive_property_get(self.regs[rd], prop_name_si)? { self.regs[a] = value; @@ -291,6 +297,7 @@ impl Vm { } fn dispatch_set_prop(&mut self, rd: usize, a: usize, b: usize) -> Result<(), String> { + vm_trace!("SET_PROP rd={} a={} b={}", rd, a, b); let Some(obj_ptr) = self.checked_object_ptr(self.regs[rd], "Cannot create property on non-object")? else { return Ok(()); }; @@ -312,6 +319,7 @@ impl Vm { } fn dispatch_get_prop_dynamic(&mut self, rd: usize, a: usize, b: usize) -> Result<(), String> { + vm_trace!("GET_PROP_DYNAMIC rd={} a={} b={}", rd, a, b); let prop_name_si = self.property_key_si(self.regs[a]); if let Some(value) = self.primitive_property_get(self.regs[rd], prop_name_si)? { self.regs[b] = value; @@ -329,6 +337,7 @@ impl Vm { } fn dispatch_set_prop_dynamic(&mut self, rd: usize, a: usize, b: usize) -> Result<(), String> { + vm_trace!("SET_PROP_DYNAMIC rd={} a={} b={}", rd, a, b); let Some(obj_ptr) = self.checked_object_ptr(self.regs[rd], "Cannot create property on non-object")? else { return Ok(()); }; @@ -350,6 +359,7 @@ impl Vm { } fn dispatch_set_elem(&mut self, rd: usize, a: usize, b: usize) -> Result<(), String> { + vm_trace!("SET_ELEM rd={} a={} b={}", rd, a, b); let Some(obj_ptr) = self.checked_object_ptr(self.regs[rd], "Cannot create property on non-object")? else { return Ok(()); }; @@ -369,6 +379,7 @@ impl Vm { impl Vm { pub(crate) fn dispatch_delete_prop_static(&mut self, rd: usize) -> Result { + vm_trace!("DELETE_PROP_STATIC rd={}", rd); let prop_idx = self.bytecode[self.pc] as usize; self.pc += 1; let key_val = self.immutables().get(prop_idx).copied().unwrap_or_else(JsValue::undefined); @@ -385,6 +396,7 @@ impl Vm { } pub(crate) fn dispatch_delete_prop_dynamic(&mut self, rd: usize, b: usize) -> Result { + vm_trace!("DELETE_PROP_DYNAMIC rd={}", rd); let prop_name_si = self.property_key_si(self.regs[b]); let Some(obj_ptr) = self.checked_object_ptr(self.regs[rd], "delete on non-object")? else { return Ok(true); diff --git a/crates/oxide_vm/src/ic_helper.rs b/crates/oxide_vm/src/ic_helper.rs index 3bbafc88..f2d3d2c2 100644 --- a/crates/oxide_vm/src/ic_helper.rs +++ b/crates/oxide_vm/src/ic_helper.rs @@ -4,6 +4,7 @@ //! update handlers route through here, so IC format changes (like the future //! side-table migration) require editing only this file. +use crate::vm_trace; use oxide_bytecode::opcode::{self, Instr}; use oxide_types::object::JsObject; use oxide_types::value::JsValue; @@ -23,6 +24,7 @@ pub(crate) fn read_ic_entry(bytecode: &[Instr], pc: &mut usize) -> (u32, u32) { /// after resolving a property, so the next execution of this site hits the cache. pub(crate) fn write_ic_back(bytecode: &mut [Instr], pc: usize, shape_id: u32, slot_index: u32) { debug_assert!(pc >= 3, "IC write-back requires 3 extension words before pc"); + vm_trace!("write_ic_back: pc={} shape_id={} slot={}", pc, shape_id, slot_index); bytecode[pc - 3] = shape_id & 0x00FF_FFFF; bytecode[pc - 2] = slot_index; bytecode[pc - 1] = 0; diff --git a/crates/oxide_vm/src/session_arena.rs b/crates/oxide_vm/src/session_arena.rs index b02a19b8..9e249930 100644 --- a/crates/oxide_vm/src/session_arena.rs +++ b/crates/oxide_vm/src/session_arena.rs @@ -1,5 +1,6 @@ use std::collections::HashMap; +use crate::vm_debug; use oxide_types::object::JsObject; use oxide_types::value::JsValue; use rustc_hash::FxBuildHasher; @@ -17,6 +18,7 @@ impl Vm { } pub(crate) fn promote_object(&mut self, src: *mut JsObject) -> *mut JsObject { + vm_debug!("promote_object: src={:p}", src); let mut forwarding = std::mem::take(&mut self.gc_state.forwarding); let result = self.promote_object_inner(src, &mut forwarding); forwarding.clear(); @@ -27,6 +29,7 @@ impl Vm { pub(crate) fn promote_object_inner( &mut self, src: *mut JsObject, forwarding: &mut HashMap<*mut JsObject, *mut JsObject, FxBuildHasher>, ) -> *mut JsObject { + vm_debug!("promote_object_inner: src={:p}", src); if src.is_null() { return src; } diff --git a/crates/oxide_vm/src/session_gc.rs b/crates/oxide_vm/src/session_gc.rs index b0589a0e..e86b9100 100644 --- a/crates/oxide_vm/src/session_gc.rs +++ b/crates/oxide_vm/src/session_gc.rs @@ -2,7 +2,7 @@ use std::collections::{HashMap, HashSet}; use std::mem::size_of; use std::time::Instant; -use crate::vm_debug; +use crate::{vm_debug, vm_info}; use oxide_types::object::{JsObject, JsString, PropMetaEntry}; use oxide_types::value::JsValue; use rustc_hash::FxBuildHasher; @@ -35,6 +35,7 @@ impl SessionGc { impl SessionGc { pub(crate) fn clear_all_marks(&mut self, vm: &mut Vm) { + vm_debug!("[GC] clear_all_marks: {} session objects", vm.gc_state.session_object_ptrs.len()); for &ptr in &vm.gc_state.session_object_ptrs { if ptr.is_null() { continue; @@ -119,6 +120,7 @@ impl SessionGc { } pub(crate) fn mark(&mut self, vm: &Vm) { + vm_debug!("[GC] mark phase: {} roots", vm.gc_state.session_object_ptrs.len()); let mut seeds = Vec::new(); let mut string_seeds: Vec<*mut JsString> = Vec::new(); vm.for_each_root(|root| { @@ -355,6 +357,7 @@ impl SessionGc { /// `session_bytes_allocated` to object-only), re-adding surviving string bytes. Returns the /// bytes freed. pub(crate) fn sweep_session_strings(&mut self, vm: &mut Vm) -> u64 { + vm_debug!("[GC] sweep strings: {} string ptrs", vm.gc_state.session_string_ptrs.len()); let old = std::mem::take(&mut vm.gc_state.session_string_ptrs); let mut freed = 0u64; let mut live_bytes = 0usize; @@ -389,6 +392,8 @@ impl SessionGc { pub(crate) fn collect(&mut self, vm: &mut Vm) { let start = Instant::now(); + vm_info!("[GC] cycle #{} start", self.total_collections + 1); + self.mark(vm); let mut freed_bytes = self.sweep(vm); freed_bytes += self.sweep_session_strings(vm); @@ -399,6 +404,16 @@ impl SessionGc { self.max_collection_duration_us = self.max_collection_duration_us.max(self.last_collection_duration_us); self.min_collection_duration_us = self.min_collection_duration_us.min(self.last_collection_duration_us); + vm_info!( + "[GC] cycle #{} end: {} scanned, {} live, {} dead, {:.1}ms, {} bytes freed", + self.total_collections, + self.last_collection_objects_scanned, + self.last_collection_objects_live, + self.last_collection_objects_dead, + elapsed.as_secs_f64() * 1000.0, + freed_bytes, + ); + if freed_bytes > 0 || self.total_collections % 100 == 0 { vm_debug!("{}", self.stats_summary()); } @@ -457,6 +472,7 @@ fn rewrite_forwarded_value( } fn rewrite_vm_roots(vm: &mut Vm, forwarding: &HashMap<*mut JsObject, *mut JsObject, FxBuildHasher>) { + vm_debug!("[GC] rewrite_vm_roots: {} forwarded objects", forwarding.len()); for value in &mut vm.regs { *value = rewrite_forwarded_value(*value, forwarding); } diff --git a/crates/oxide_vm/src/vm.rs b/crates/oxide_vm/src/vm.rs index 50025844..c57f3d67 100644 --- a/crates/oxide_vm/src/vm.rs +++ b/crates/oxide_vm/src/vm.rs @@ -10,6 +10,7 @@ pub use crate::bindings::init_kernel_builtins; use crate::native::NativeFn; use crate::session_gc::SessionGc; use crate::vm_state::{GcState, IterState, ProfilingState, SymbolState}; +use crate::{vm_debug, vm_error, vm_trace, vm_warn}; use oxide_kernel::kernel::{KernelCore, KernelSession}; use oxide_runtime_api as coercion; use oxide_runtime_api::NativeResult; @@ -401,6 +402,7 @@ impl Vm { pub(crate) fn raise_js_error(&mut self, err: JsError) -> Result<(), String> { let kind = js_error_kind_name(err.kind); + vm_debug!("raise_js_error: {} \"{}\"", kind, err.message); let error = oxide_builtins::error::create_kind_error(self, kind, &err.message); self.exception_value = Some(error); self.pending_error_kind = Some(kind); @@ -421,6 +423,7 @@ impl Vm { .duration_since(std::time::UNIX_EPOCH) .unwrap_or_default() .as_nanos() as u64; + vm_debug!("step_rng: seeded"); } self.math_rng_state = self .math_rng_state @@ -508,6 +511,7 @@ impl Vm { } pub(crate) fn resolve_property(&self, obj: &JsObject, prop_name_si: u32) -> Option { + vm_trace!("resolve_property: shape_id={} prop_name_si={}", obj.shape_id(), prop_name_si); let length_si = self.kernel_core.perm_interner().intern("length").0; if obj.is_array() && prop_name_si == length_si { return Some(JsValue::int(obj.prop_count() as i32)); @@ -573,6 +577,7 @@ impl Vm { pub(crate) fn call_function_sync( &mut self, callee: JsValue, receiver: JsValue, args: &[JsValue], ) -> Result { + vm_debug!("call_function_sync: args={} callee_is_object={}", args.len(), callee.is_object()); if !callee.is_object() { return Err(self.error_message_text("TypeError", "accessor is not callable")); } @@ -618,6 +623,12 @@ impl Vm { &mut self, callee: JsValue, this_value: JsValue, args: &[JsValue], construct_result_reg: Option, constructed_this: Option, new_target: JsValue, continuation: FrameContinuation, ) -> Result<(), String> { + vm_trace!( + "push_bytecode_frame: depth={}, args={}, continuation={:?}", + self.frames.len(), + args.len(), + continuation + ); if !callee.is_object() { return Err(self.error_message_text("TypeError", "CALL target is not callable")); } @@ -699,11 +710,13 @@ impl Vm { steps += 1; if let Some(max_steps) = self.kernel_core.config.max_steps { if steps > max_steps { + vm_warn!("dispatch: step limit {} exceeded at pc={}", max_steps, self.pc); self.profiling.set_instruction_count(steps); return Err(format!("VM step limit exceeded at pc={}", self.pc)); } } if self.pc >= self.bytecode.len() { + vm_error!("dispatch: program counter out of bounds pc={} len={}", self.pc, self.bytecode.len()); self.profiling.instruction_count = steps; return Err("program counter out of bounds".into()); } @@ -719,6 +732,7 @@ impl Vm { OpCode::NOP => {} OpCode::HALT => { + vm_trace!("HALT: regs[0]={:?}", self.regs[0]); self.profiling.set_instruction_count(steps); return Ok(self.regs[0]); } diff --git a/crates/oxide_vm/src/vm_dispatch_ctrl.rs b/crates/oxide_vm/src/vm_dispatch_ctrl.rs index 2d7d19f6..430dc991 100644 --- a/crates/oxide_vm/src/vm_dispatch_ctrl.rs +++ b/crates/oxide_vm/src/vm_dispatch_ctrl.rs @@ -1,4 +1,5 @@ use crate::vm::{FrameContinuation, TryHandler, Vm}; +use crate::vm_trace; use oxide_bytecode::opcode; use oxide_types::object::PropAttributes; use oxide_types::value::JsValue; @@ -76,6 +77,7 @@ impl Vm { } pub(crate) fn dispatch_define_accessor(&mut self, rd: usize, a: usize, b: usize) -> Result<(), String> { + vm_trace!("DEFINE_ACCESSOR rd={} getter={} setter={}", rd, a, b); let prop_idx = self.bytecode[self.pc] as usize; self.pc += 1; if prop_idx >= self.immutables().len() { @@ -109,13 +111,23 @@ impl Vm { pub(crate) fn dispatch_return(&mut self, rd: usize) -> Result, String> { let result = self.regs[rd]; - crate::vm_debug!("RETURN depth={}", self.frames.len()); + crate::vm_debug!( + "RETURN depth={} saved_pc={}", + self.frames.len(), + self.frames.last().map(|f| f.return_addr).unwrap_or(0) + ); if let Some(frame) = self.frames.pop() { let construct_result_reg = frame.construct_result_reg; let constructed_this = frame.constructed_this; let is_derived_constructor = frame.is_derived_constructor; let continuation = frame.continuation; let callee_this = self.regs[254]; + vm_trace!( + "RETURN frame: continuation={:?}, derived={}, result_reg={}", + continuation, + is_derived_constructor, + rd + ); self.restore_frame(frame); if let (Some(target_reg), Some(constructed_this)) = (construct_result_reg, constructed_this) { if is_derived_constructor && result.is_undefined() && callee_this.is_undefined() { @@ -124,24 +136,32 @@ impl Vm { } self.regs[target_reg as usize] = if result.is_object() { result } else { constructed_this }; self.regs[0] = self.regs[target_reg as usize]; + vm_trace!("RETURN constructor: target_reg={} regs[0]={:?}", target_reg, self.regs[0]); } else { match continuation { FrameContinuation::None => self.regs[0] = result, - FrameContinuation::AccessorGet { target_reg } => self.regs[target_reg as usize] = result, - FrameContinuation::AccessorSet => {} + FrameContinuation::AccessorGet { target_reg } => { + self.regs[target_reg as usize] = result; + vm_trace!("RETURN accessor_get: target_reg={}", target_reg); + } + FrameContinuation::AccessorSet => { + vm_trace!("RETURN accessor_set"); + } } } Ok(None) } else { + vm_trace!("RETURN top-level: regs[0]={:?}", result); Ok(Some(result)) } } pub(crate) fn dispatch_throw(&mut self, rd: usize) -> Result { - crate::vm_debug!("THROW pc={}", self.pc); let exc_value = self.regs[rd]; + let kind = self.thrown_error_kind(exc_value); + vm_trace!("THROW pc={} kind={}", self.pc, kind); self.exception_value = Some(exc_value); - self.pending_error_kind = Some(self.thrown_error_kind(exc_value)); + self.pending_error_kind = Some(kind); self.unwind().map(|_| true) } @@ -161,12 +181,14 @@ impl Vm { } pub(crate) fn dispatch_try_end(&mut self) { + vm_trace!("TRY_END"); self.try_stack.pop(); } pub(crate) fn dispatch_try_finally_begin(&mut self, instr: u32) { let offset = opcode::offset16(instr) as isize; let finally_pc = ((self.pc as isize) + offset - 1) as usize; + vm_trace!("TRY_FINALLY_BEGIN finally_pc={}", finally_pc); self.try_stack.push(TryHandler { catch_pc: None, finally_pc: Some(finally_pc), @@ -175,6 +197,7 @@ impl Vm { } pub(crate) fn dispatch_try_finally_end(&mut self) -> Result { + vm_trace!("TRY_FINALLY_END has_pending_exc={}", self.pending_exception.is_some()); self.try_stack.pop(); if self.pending_exception.is_some() && self.exception_value.is_none() { self.exception_value = self.pending_exception.take(); diff --git a/crates/oxide_vm/src/vm_dispatch_misc.rs b/crates/oxide_vm/src/vm_dispatch_misc.rs index 84413228..ee5ec836 100644 --- a/crates/oxide_vm/src/vm_dispatch_misc.rs +++ b/crates/oxide_vm/src/vm_dispatch_misc.rs @@ -2,7 +2,7 @@ use std::sync::Arc; use crate::native::NativeFn; use crate::vm::{native_fn_ptr_to_fn, CallFrame, ForInIter, FrameContinuation, Vm, MAX_PROTO_CHAIN_DEPTH}; -use crate::vm_debug; +use crate::vm_trace; use oxide_runtime_api::{to_boolean, NativeResult}; use oxide_types::object::{JsObject, PropAttributes}; use oxide_types::private_key::is_private_name_key; @@ -12,7 +12,7 @@ impl Vm { pub(crate) fn dispatch_new_expression(&mut self, rd: usize, a: usize, b: usize) -> Result { let constructor_reg = a; let first_arg_reg = b as u8; - vm_debug!("NEW_EXPRESSION rd={}", rd); + vm_trace!("NEW_EXPRESSION rd={}", rd); let constructor = self.regs[constructor_reg]; if !constructor.is_object() { @@ -164,6 +164,7 @@ impl Vm { } pub(crate) fn dispatch_template_str(&mut self, rd: usize) { + vm_trace!("TEMPLATE_STR rd={}", rd); let header = self.bytecode[self.pc]; self.pc += 1; let segment_count = (header >> 16) as usize; @@ -200,6 +201,7 @@ impl Vm { } pub(crate) fn dispatch_instanceof(&mut self, rd: usize, a: usize, b: usize) -> Result<(), String> { + vm_trace!("INSTANCEOF rd={}", rd); let lhs_val = self.regs[a]; let rhs_val = self.regs[b]; @@ -246,6 +248,7 @@ impl Vm { } pub(crate) fn dispatch_in(&mut self, rd: usize, a: usize, b: usize) -> Result<(), String> { + vm_trace!("IN rd={}", rd); let key_val = self.regs[a]; let obj_ptr = self.regs[b].as_object_ptr() as *mut JsObject; if obj_ptr.is_null() { @@ -259,6 +262,7 @@ impl Vm { } pub(crate) fn dispatch_for_in_init(&mut self, a: usize) -> Result<(), String> { + vm_trace!("FOR_IN_INIT r{}={:?}", a, self.regs[a]); let obj_val = self.regs[a]; if !obj_val.is_object() { return self.raise_type_error("for-in right-hand side is not an object"); @@ -315,6 +319,7 @@ impl Vm { } pub(crate) fn dispatch_for_in_next(&mut self, rd: usize) -> Result<(), String> { + vm_trace!("FOR_IN_NEXT rd={}", rd); let iter_ptr = self.iters.last_for_in(); if iter_ptr.is_null() { return Err("FOR_IN_NEXT without active iterator".into()); @@ -330,6 +335,7 @@ impl Vm { } pub(crate) fn dispatch_for_in_done(&mut self, rd: usize) { + vm_trace!("FOR_IN_DONE rd={}", rd); let iter_ptr = self.iters.last_for_in(); if iter_ptr.is_null() { self.regs[rd] = JsValue::bool(true); @@ -340,10 +346,12 @@ impl Vm { } pub(crate) fn dispatch_for_in_cleanup(&mut self) { + vm_trace!("FOR_IN_CLEANUP"); self.iters.pop_for_in(); } pub(crate) fn dispatch_for_of_init(&mut self, a: usize) -> Result<(), String> { + vm_trace!("FOR_OF_INIT r{}={:?}", a, self.regs[a]); let iterable = self.regs[a]; match oxide_builtins::iterator::make_iterator_for_value(self, iterable) { Ok(iterator) => { @@ -360,6 +368,7 @@ impl Vm { } pub(crate) fn dispatch_for_of_done(&mut self, rd: usize) -> Result<(), String> { + vm_trace!("FOR_OF_DONE rd={}", rd); let Some(iterator) = self.iters.last_for_of() else { return Err("FOR_OF_DONE without active iterator".into()); }; @@ -385,6 +394,7 @@ impl Vm { } pub(crate) fn dispatch_for_of_next(&mut self, rd: usize) -> Result<(), String> { + vm_trace!("FOR_OF_NEXT rd={}", rd); let result = self.iters.last_for_of_result(); if !result.is_object() { self.regs[rd] = JsValue::undefined(); @@ -397,6 +407,7 @@ impl Vm { } pub(crate) fn dispatch_for_of_close(&mut self) -> Result<(), String> { + vm_trace!("FOR_OF_CLOSE"); let Some(iterator) = self.iters.pop_for_of() else { return Ok(()); }; @@ -416,6 +427,7 @@ impl Vm { } pub(crate) fn dispatch_rest_object(&mut self, rd: usize, a: usize) -> Result<(), String> { + vm_trace!("REST_OBJECT rd={}", rd); let src = self.regs[a]; if !src.is_object() { return self.raise_type_error("Cannot destructure property of null/undefined"); diff --git a/crates/oxide_vm/src/vm_pool.rs b/crates/oxide_vm/src/vm_pool.rs index 7675e686..c38441a0 100644 --- a/crates/oxide_vm/src/vm_pool.rs +++ b/crates/oxide_vm/src/vm_pool.rs @@ -4,6 +4,7 @@ use std::sync::{Arc, Condvar, Mutex}; use std::time::Duration; use crate::vm::Vm; +use crate::{vm_debug, vm_trace, vm_warn}; use oxide_kernel::kernel::KernelCore; struct VmPoolInner { @@ -50,6 +51,7 @@ impl VmPool { let mut inner = self.inner.lock().unwrap(); if let Some(vm) = inner.available.pop() { + vm_trace!("pool: reused vm, {} available", inner.available.len()); return VmGuard { vm: Some(vm), pool: Arc::clone(self), @@ -64,6 +66,7 @@ impl VmPool { if can_grow { inner.total_count += 1; + vm_debug!("pool: growing to {} vms", inner.total_count); drop(inner); let vm = Self::new_vm(&self.kernel_core); return VmGuard { @@ -76,6 +79,7 @@ impl VmPool { let (guard, wait) = self.condvar.wait_timeout(inner, Duration::from_secs(5)).unwrap(); inner = guard; if wait.timed_out() { + vm_warn!("pool: wait timeout, force-growing to {} vms", inner.total_count + 1); inner.total_count += 1; drop(inner); let vm = Self::new_vm(&self.kernel_core); @@ -108,11 +112,13 @@ impl Drop for VmGuard { let mut inner = self.pool.inner.lock().unwrap(); if self.dirty { + vm_debug!("pool: discarding dirty vm"); let new_vm = self.pool.replace_vm(); inner.available.push(new_vm); } else { vm.full_reset(); inner.available.push(vm); + vm_trace!("pool: recycled clean vm, {} available", inner.available.len()); } self.pool.condvar.notify_one(); diff --git a/crates/oxide_vm/src/vm_props.rs b/crates/oxide_vm/src/vm_props.rs index 1ea51737..d052b717 100644 --- a/crates/oxide_vm/src/vm_props.rs +++ b/crates/oxide_vm/src/vm_props.rs @@ -1,4 +1,5 @@ use crate::vm::{FrameContinuation, Vm, MAX_PROTO_CHAIN_DEPTH}; +use crate::{ic_trace, vm_trace}; use oxide_runtime_api as coercion; use oxide_types::object::{JsObject, PropAttributes, PropMetaEntry}; use oxide_types::value::JsValue; @@ -19,6 +20,7 @@ impl Vm { fn ordinary_get_inner( &mut self, obj: &JsObject, prop_name_si: u32, receiver: JsValue, target_reg: Option, ) -> Result { + vm_trace!("ordinary_get_inner: shape={} prop_si={}", obj.shape_id(), prop_name_si); let length_si = self.kernel_core.perm_interner().intern("length").0; let mut current = Some(obj); let mut depth = 0usize; @@ -58,6 +60,9 @@ impl Vm { depth += 1; let proto = obj.proto(); current = proto.is_object().then(|| unsafe { &*proto.as_js_object_ptr() }); + if let Some(proto_obj) = current { + vm_trace!("ordinary_get proto step: depth={} shape={}", depth, proto_obj.shape_id()); + } } Ok(JsValue::undefined()) } @@ -65,6 +70,11 @@ impl Vm { fn push_bytecode_getter_frame( &mut self, getter: JsValue, receiver: JsValue, target_reg: u8, ) -> Result { + vm_trace!( + "push_bytecode_getter_frame: target_reg={} native={}", + target_reg, + getter.is_object() && unsafe { &*getter.as_js_object_ptr() }.native_fn().is_some() + ); if !getter.is_object() { return Err(self.error_message_text("TypeError", "getter is not callable")); } @@ -93,6 +103,7 @@ impl Vm { } fn inherited_property_meta(&self, obj: &JsObject, prop_name_si: u32) -> Option { + vm_trace!("inherited_property_meta: shape={} prop_si={}", obj.shape_id(), prop_name_si); let mut proto = obj.proto(); let mut depth = 0usize; while proto.is_object() && depth < MAX_PROTO_CHAIN_DEPTH { @@ -121,6 +132,12 @@ impl Vm { fn ordinary_set_inner( &mut self, obj: &mut JsObject, prop_name_si: u32, val: JsValue, receiver: JsValue, use_frame_push: bool, ) -> Result<(), String> { + vm_trace!( + "ordinary_set_inner: shape={} prop_si={} frame_push={}", + obj.shape_id(), + prop_name_si, + use_frame_push + ); let val = self.promote_if_needed_for_write_ptr(obj as *mut JsObject, val); if let Some(pos) = self.get_own_property_slot(obj, prop_name_si) { if let Some(meta) = obj.prop_meta_at(pos) { @@ -157,6 +174,7 @@ impl Vm { fn call_or_push_setter( &mut self, setter: JsValue, receiver: JsValue, val: JsValue, use_frame_push: bool, ) -> Result<(), String> { + vm_trace!("call_or_push_setter: frame_push={}", use_frame_push); if !use_frame_push { self.call_function_sync(setter, receiver, &[val])?; return Ok(()); @@ -187,6 +205,7 @@ impl Vm { pub(crate) fn read_member_prop( &mut self, obj: &JsObject, prop_name_si: u32, receiver: JsValue, ) -> Result { + vm_trace!("read_member_prop: shape_id={} prop_name_si={}", obj.shape_id(), prop_name_si); let ext0 = self.bytecode[self.pc]; let ext1 = self.bytecode[self.pc + 1]; let _ext2 = self.bytecode[self.pc + 2]; @@ -224,6 +243,7 @@ impl Vm { pub(crate) fn set_member_prop( &mut self, obj: &mut JsObject, prop_name_si: u32, val: JsValue, receiver: JsValue, ) -> Result<(), String> { + ic_trace!("set_member_prop: shape_id={} prop_name_si={}", obj.shape_id(), prop_name_si); let val = self.promote_if_needed_for_write_ptr(obj as *mut JsObject, val); if let Some(pos) = self.kernel_core.shape_forge().lookup_position(obj.shape_id(), prop_name_si) { if obj.has_prop_meta() { @@ -239,6 +259,7 @@ impl Vm { } pub(crate) fn set_or_create_prop_value(&mut self, obj: &mut JsObject, prop_name_si: u32, val: JsValue) { + vm_trace!("set_or_create_prop_value: shape_id={} prop_name_si={}", obj.shape_id(), prop_name_si); let val = self.promote_if_needed_for_write_ptr(obj as *mut JsObject, val); if let Some(pos) = self.kernel_core.shape_forge().lookup_position(obj.shape_id(), prop_name_si) { obj.set_prop_at(pos, val); @@ -253,6 +274,7 @@ impl Vm { pub(crate) fn define_data_property( &mut self, obj: &mut JsObject, prop_name_si: u32, val: JsValue, attributes: PropAttributes, ) -> Result<(), String> { + vm_trace!("define_data_property: shape={} prop_si={}", obj.shape_id(), prop_name_si); let val = self.promote_if_needed_for_write_ptr(obj as *mut JsObject, val); let pos = if let Some(pos) = self.kernel_core.shape_forge().lookup_position(obj.shape_id(), prop_name_si) { pos @@ -288,6 +310,7 @@ impl Vm { pub(crate) fn define_accessor_property( &mut self, obj: &mut JsObject, prop_name_si: u32, get: JsValue, set: JsValue, attributes: PropAttributes, ) -> Result<(), String> { + vm_trace!("define_accessor_property: shape={} prop_si={}", obj.shape_id(), prop_name_si); let target_ptr = obj as *mut JsObject; let get = self.promote_if_needed_for_write_ptr(target_ptr, get); let set = self.promote_if_needed_for_write_ptr(target_ptr, set); diff --git a/crates/oxide_vm/src/vm_runtime.rs b/crates/oxide_vm/src/vm_runtime.rs index 3d8a0f5b..770c5f12 100644 --- a/crates/oxide_vm/src/vm_runtime.rs +++ b/crates/oxide_vm/src/vm_runtime.rs @@ -3,6 +3,7 @@ use std::sync::{Arc, OnceLock}; use oxide_bytecode::module::CompiledModule; use crate::vm::{CallFrame, InlineSyncState, Vm}; +use crate::{vm_debug, vm_info, vm_trace, vm_warn}; use oxide_types::object::JsObject; use oxide_types::value::JsValue; @@ -14,6 +15,12 @@ impl Vm { return Err(self.error_message_text("TypeError", "accessor is not callable")); } let sub_idx = callee_obj.sub_module_index() as usize - 1; + vm_debug!( + "call_bytecode_function_inline: sub_idx={}, args={}, depth={}", + sub_idx, + args.len(), + self.frames.len() + ); if sub_idx >= self.sub_modules.len() { return Err(format!( "accessor sub_module_index {} out of bounds (max {})", @@ -34,6 +41,7 @@ impl Vm { let subs = Arc::clone(&self.sub_modules); let sub = &subs[sub_idx]; + vm_trace!("call_bytecode: saving state pc={} depth={}", self.pc, self.frames.len()); let saved = Box::new(InlineSyncState { regs: Box::new(self.regs), pc: self.pc, @@ -74,9 +82,17 @@ impl Vm { } let _ = callee; + vm_trace!( + "call_bytecode: dispatching sub_idx={} n_regs={} n_args={} arrow={}", + sub_idx, + sub.n_registers, + sub.n_args, + sub.is_arrow + ); let result = self.dispatch(); self.native_call_depth -= 1; + vm_trace!("call_bytecode: restoring state pc={} result={:?}", saved.pc, result.as_ref().ok()); self.regs = *saved.regs; self.pc = saved.pc; self.bytecode = saved.bytecode; @@ -99,6 +115,11 @@ impl Vm { } pub(crate) fn restore_frame(&mut self, frame: CallFrame) { + vm_trace!( + "restore_frame: return_addr={} caller_reg_limit={}", + frame.return_addr, + frame.caller_reg_limit + ); if let Some(saved_bc) = self.saved_bytecode_stack.pop() { self.bytecode = saved_bc; } @@ -116,6 +137,7 @@ impl Vm { } pub fn rerun(&mut self) -> Result { + vm_info!("rerun: clearing IC caches"); self.clear_execution_state(); self.active_reg_limit = self.root_reg_limit; crate::ic_helper::clear_ic_caches(&mut self.bytecode); @@ -123,6 +145,7 @@ impl Vm { } pub fn run(&mut self, module: &CompiledModule) -> Result { + vm_debug!("run: starting bytecode execution, {} instructions", module.bytecode.len()); self.clear_execution_state(); self.sub_modules = Arc::new(module.sub_modules.clone()); // Per-run convert-once cache: slot 0 = top module, slot sub_idx+1 = sub_modules[sub_idx]. @@ -146,6 +169,7 @@ impl Vm { } pub(crate) fn unwind(&mut self) -> Result<(), String> { + vm_debug!("unwind: {} try handlers on stack", self.try_stack.len()); while let Some(handler) = self.try_stack.pop() { while self.frames.len() > handler.frame_depth { if let Some(frame) = self.frames.pop() { @@ -153,6 +177,7 @@ impl Vm { } } if let Some(finally_pc) = handler.finally_pc { + vm_trace!("unwind: entering finally at pc={}", finally_pc); if self.pending_exception.is_none() { self.pending_exception = self.exception_value.take(); } @@ -161,6 +186,7 @@ impl Vm { return Ok(()); } if let Some(catch_pc) = handler.catch_pc { + vm_trace!("unwind: caught at pc={}", catch_pc); let exc = self.exception_value.take().unwrap_or(JsValue::undefined()); self.regs[0] = exc; self.pc = catch_pc; @@ -178,6 +204,7 @@ impl Vm { } else { format!("uncaught {kind_str}: {exc_text}") }; + vm_warn!("unwind: uncaught {}: {}", kind_str, exc_text); Err(msg) } } diff --git a/crates/oxide_vm/src/vm_support.rs b/crates/oxide_vm/src/vm_support.rs index 2e1144c2..bbaac710 100644 --- a/crates/oxide_vm/src/vm_support.rs +++ b/crates/oxide_vm/src/vm_support.rs @@ -6,6 +6,7 @@ use oxide_bytecode::module::Constant; use crate::bindings; use crate::vm::Vm; +use crate::vm_info; use crate::vm_state::{GcState, IterState, ProfilingState, SymbolState}; use oxide_kernel::kernel::{KernelConfig, KernelCore, KernelSession}; use oxide_kernel::shape_forge::EMPTY_SHAPE_ID; @@ -19,7 +20,7 @@ impl Vm { let mut session = KernelSession::new(&core); bindings::init_kernel_builtins(&core, &mut session); let obj_proto = P::clone(&session.builtin_world().object_proto); - Self { + let vm = Self { regs: [JsValue::undefined(); 256], pc: 0, bytecode: Vec::new(), @@ -67,14 +68,16 @@ impl Vm { ic_misses: std::cell::Cell::new(0), instruction_count: 0, }, - } + }; + vm_info!("Vm created"); + vm } pub fn with_kernel_core(core: Arc) -> Self { let mut session = KernelSession::new(&core); bindings::init_kernel_builtins(&core, &mut session); let obj_proto = P::clone(&session.builtin_world().object_proto); - Self { + let vm = Self { regs: [JsValue::undefined(); 256], pc: 0, bytecode: Vec::new(), @@ -122,7 +125,9 @@ impl Vm { ic_misses: std::cell::Cell::new(0), instruction_count: 0, }, - } + }; + vm_info!("Vm created (pool)"); + vm } pub fn full_reset(&mut self) { @@ -138,6 +143,7 @@ impl Vm { self.session.record_snapshot(); self.object_prototype = P::clone(&self.session.builtin_world().object_proto); self.clear_full_reset_state(); + vm_info!("full_reset completed"); } #[doc(hidden)]