feat: 为 VM 添加结构化日志

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);

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);

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<Option<JsValue>, 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<bool, String> {
+        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<bool, String> {
+        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<bool, String> {
+        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() {

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);
     }

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);
     }

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 => {
+            OpCode::COMPOUND_MEMBER_SUB => self.dispatch_compound_member_numeric(
-                self.dispatch_compound_member_numeric(rd, a, b, "COMPOUND_MEMBER_SUB on non-object", |l, r| l - r)
+                "COMPOUND_MEMBER_SUB",
-            }
+                rd,
-            OpCode::COMPOUND_MEMBER_MUL => {
+                a,
-                self.dispatch_compound_member_numeric(rd, a, b, "COMPOUND_MEMBER_MUL on non-object", |l, r| l * r)
+                b,
-            }
+                "COMPOUND_MEMBER_SUB on non-object",
-            OpCode::COMPOUND_MEMBER_DIV => {
+                |l, r| l - r,
-                self.dispatch_compound_member_numeric(rd, a, b, "COMPOUND_MEMBER_DIV on non-object", |l, r| l / r)
+            ),
-            }
+            OpCode::COMPOUND_MEMBER_MUL => self.dispatch_compound_member_numeric(
-            OpCode::COMPOUND_MEMBER_MOD => {
+                "COMPOUND_MEMBER_MUL",
-                self.dispatch_compound_member_numeric(rd, a, b, "COMPOUND_MEMBER_MOD on non-object", |l, r| l % r)
+                rd,
-            }
+                a,
-            OpCode::COMPOUND_MEMBER_EXP => {
+                b,
-                self.dispatch_compound_member_numeric(rd, a, b, "COMPOUND_MEMBER_EXP on non-object", |l, r| l.powf(r))
+                "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<F>(
-        &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(());
         };

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<bool, String> {
+        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<bool, String> {
+        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();
     }
 }

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<bool, String> {
+        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<bool, String> {
+        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);

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;

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;
         }

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);
     }

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<JsValue> {
+        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<JsValue, String> {
+        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<u8>,
         constructed_this: Option<JsValue>, 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]);
                 }

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<Option<JsValue>, 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::AccessorGet { target_reg } => {
-                    FrameContinuation::AccessorSet => {}
+                        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<bool, String> {
-        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<bool, String> {
+        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();

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<bool, String> {
         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");

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();

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<u8>,
     ) -> Result<JsValue, String> {
+        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<bool, String> {
+        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<PropMetaEntry> {
+        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<JsValue, String> {
+        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);

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<JsValue, String> {
+        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<JsValue, String> {
+        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)
     }
 }

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<KernelCore>) -> 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)]