feat: 添加 Kernel 与 VM 分层结构化日志

crates/oxide_compiler/src/compiler.rs

@@ -312,8 +312,8 @@ impl Compiler {
     /// (true for arrow functions, which have lexical super) or reset to false
     /// (false for regular functions, which create a new super scope).
     pub(crate) fn compile_function_body<'a>(
-        &self, param_names: &[String], body_stmts: &[Statement<'a>], parent_ctx: &CompileCtx,
-        is_expression_body: bool, is_arrow: bool,
+        &self, param_names: &[String], body_stmts: &[Statement<'a>], parent_ctx: &CompileCtx, is_expression_body: bool,
+        is_arrow: bool,
     ) -> Result<CompiledModule, String> {
         self.compile_function_body_with_bindings(param_names, body_stmts, parent_ctx, is_expression_body, &[], is_arrow)
     }

crates/oxide_kernel/Cargo.toml

@@ -14,3 +14,5 @@ dashmap.workspace = true
 hashbrown.workspace = true
 rustc-hash.workspace = true
 bumpalo.workspace = true
+tracing.workspace = true
+tracing-subscriber.workspace = true

crates/oxide_kernel/src/code_forge.rs

@@ -5,6 +5,8 @@ use dashmap::DashMap;
 use oxide_compiler::compiler::Compiler;
 use oxide_compiler::module::CompiledModule;
 
+use crate::{kernel_debug, kernel_info};
+
 pub use oxide_compiler::compiler::structural_hash;
 
 pub struct CodeForge {
@@ -22,11 +24,13 @@ impl CodeForge {
         let hash = structural_hash(program);
 
         if let Some(module) = self.map.get(&hash) {
+            kernel_info!("CodeForge hit hash={:#x}", hash);
             return Ok(Arc::clone(&module));
         }
 
         let module = compiler.compile(program)?;
         let module = Arc::new(module);
+        kernel_debug!("CodeForge miss hash={:#x}", hash);
 
         Ok(Arc::clone(self.map.entry(hash).or_insert(module).value()))
     }

crates/oxide_kernel/src/kernel.rs

@@ -8,6 +8,7 @@ use oxide_types::value::JsValue;
 
 use crate::builtin::BuiltinWorld;
 use crate::code_forge::CodeForge;
+use crate::logging::{init_logging, LogLevel, SUBSYSTEM_COUNT};
 use crate::prop_forge::PropForge;
 use crate::shape_forge::{ShapeForge, EMPTY_SHAPE_ID};
 use crate::string_forge::StringForge;
@@ -18,6 +19,7 @@ pub struct KernelConfig {
     pub max_dead_strings: Option<usize>,
     pub max_steps: Option<u64>,
     pub max_call_depth: usize,
+    pub log_levels: [LogLevel; SUBSYSTEM_COUNT],
     pub warmup_builtin_shapes: bool,
     pub warmup_builtin_code: bool,
     pub warmup_builtin_ic: bool,
@@ -31,6 +33,7 @@ impl KernelConfig {
             max_dead_strings: Some(10_000),
             max_steps: None,
             max_call_depth: 1024,
+            log_levels: [LogLevel::Off; SUBSYSTEM_COUNT],
             warmup_builtin_shapes: true,
             warmup_builtin_code: false,
             warmup_builtin_ic: false,
@@ -44,6 +47,7 @@ impl KernelConfig {
             max_dead_strings: Some(10_000),
             max_steps: None,
             max_call_depth: 1024,
+            log_levels: [LogLevel::Off; SUBSYSTEM_COUNT],
             warmup_builtin_shapes: true,
             warmup_builtin_code: true,
             warmup_builtin_ic: false,
@@ -57,6 +61,7 @@ impl KernelConfig {
             max_dead_strings: Some(5_000),
             max_steps: None,
             max_call_depth: 1024,
+            log_levels: [LogLevel::Off; SUBSYSTEM_COUNT],
             warmup_builtin_shapes: true,
             warmup_builtin_code: true,
             warmup_builtin_ic: true,
@@ -82,6 +87,8 @@ pub struct OxideKernel {
 
 impl OxideKernel {
     pub fn new(config: KernelConfig) -> Self {
+        init_logging(&config.log_levels);
+
         let string_forge = Arc::new(StringForge::new());
         let shape_forge = Arc::new(ShapeForge::new());
         let builtin_world = Arc::new(BuiltinWorld::new(&string_forge, &shape_forge));
@@ -188,6 +195,7 @@ mod tests {
         assert_eq!(KernelConfig::minimal().max_steps, None);
         assert_eq!(KernelConfig::standard().max_steps, None);
         assert_eq!(KernelConfig::full().max_steps, None);
+        assert_eq!(KernelConfig::minimal().log_levels, [LogLevel::Off; SUBSYSTEM_COUNT]);
         assert!(!KernelConfig::minimal().warmup_builtin_ic);
         assert!(KernelConfig::full().warmup_builtin_ic);
         assert_eq!(KernelConfig::full().max_pool_size, None);

crates/oxide_kernel/src/lib.rs

@@ -3,6 +3,7 @@
 pub mod builtin;
 pub mod code_forge;
 pub mod kernel;
+pub mod logging;
 pub mod prop_forge;
 pub mod shape_forge;
 pub mod string_forge;

crates/oxide_kernel/src/logging.rs

@@ -0,0 +1,235 @@
+use std::sync::atomic::{AtomicU8, Ordering};
+use std::sync::Once;
+
+use tracing_subscriber::EnvFilter;
+
+#[repr(u8)]
+#[derive(Clone, Copy, Debug, PartialEq, Eq)]
+pub enum LogLevel {
+    Off = 0,
+    Error = 1,
+    Warn = 2,
+    Info = 3,
+    Debug = 4,
+    Trace = 5,
+}
+
+#[repr(usize)]
+#[derive(Clone, Copy, Debug)]
+pub enum Subsystem {
+    Vm = 0,
+    Ic = 1,
+    Kernel = 2,
+    Builtins = 3,
+}
+
+pub const SUBSYSTEM_COUNT: usize = 4;
+
+pub struct SubsystemLevel(AtomicU8);
+
+impl SubsystemLevel {
+    pub const fn new() -> Self {
+        Self(AtomicU8::new(LogLevel::Off as u8))
+    }
+
+    pub fn set(&self, level: LogLevel) {
+        self.0.store(level as u8, Ordering::Relaxed);
+    }
+
+    pub fn get(&self) -> LogLevel {
+        match self.0.load(Ordering::Relaxed) {
+            1 => LogLevel::Error,
+            2 => LogLevel::Warn,
+            3 => LogLevel::Info,
+            4 => LogLevel::Debug,
+            5 => LogLevel::Trace,
+            _ => LogLevel::Off,
+        }
+    }
+
+    pub fn is_enabled(&self, level: LogLevel) -> bool {
+        self.0.load(Ordering::Relaxed) >= level as u8
+    }
+}
+
+impl Default for SubsystemLevel {
+    fn default() -> Self {
+        Self::new()
+    }
+}
+
+pub static VM_LEVEL: SubsystemLevel = SubsystemLevel::new();
+pub static IC_LEVEL: SubsystemLevel = SubsystemLevel::new();
+pub static KERNEL_LEVEL: SubsystemLevel = SubsystemLevel::new();
+pub static BUILTINS_LEVEL: SubsystemLevel = SubsystemLevel::new();
+
+pub fn apply_log_levels(levels: &[LogLevel; SUBSYSTEM_COUNT]) {
+    VM_LEVEL.set(levels[Subsystem::Vm as usize]);
+    IC_LEVEL.set(levels[Subsystem::Ic as usize]);
+    KERNEL_LEVEL.set(levels[Subsystem::Kernel as usize]);
+    BUILTINS_LEVEL.set(levels[Subsystem::Builtins as usize]);
+    apply_env_log_levels();
+}
+
+pub fn init_logging(log_levels: &[LogLevel; SUBSYSTEM_COUNT]) {
+    static LOGGING_INIT: Once = Once::new();
+
+    LOGGING_INIT.call_once(|| {
+        let filter = EnvFilter::try_from_env("OXIDE_LOG").unwrap_or_else(|_| EnvFilter::new("oxide=off"));
+        let subscriber = tracing_subscriber::fmt()
+            .with_env_filter(filter)
+            .with_writer(std::io::stderr)
+            .with_ansi(false)
+            .without_time()
+            .compact()
+            .finish();
+        let _ = tracing::subscriber::set_global_default(subscriber);
+    });
+
+    apply_log_levels(log_levels);
+}
+
+fn apply_env_log_levels() {
+    let Ok(spec) = std::env::var("OXIDE_LOG") else {
+        return;
+    };
+
+    for directive in spec.split(',') {
+        let Some((target, level)) = directive.split_once('=') else {
+            continue;
+        };
+        let Some(level) = parse_level(level.trim()) else {
+            continue;
+        };
+        match target.trim() {
+            "oxide" => {
+                VM_LEVEL.set(level);
+                IC_LEVEL.set(level);
+                KERNEL_LEVEL.set(level);
+                BUILTINS_LEVEL.set(level);
+            }
+            "oxide::vm" => VM_LEVEL.set(level),
+            "oxide::ic" => IC_LEVEL.set(level),
+            "oxide::kernel" => KERNEL_LEVEL.set(level),
+            "oxide::builtins" => BUILTINS_LEVEL.set(level),
+            _ => {}
+        }
+    }
+}
+
+fn parse_level(level: &str) -> Option<LogLevel> {
+    if level.eq_ignore_ascii_case("off") {
+        Some(LogLevel::Off)
+    } else if level.eq_ignore_ascii_case("error") {
+        Some(LogLevel::Error)
+    } else if level.eq_ignore_ascii_case("warn") {
+        Some(LogLevel::Warn)
+    } else if level.eq_ignore_ascii_case("info") {
+        Some(LogLevel::Info)
+    } else if level.eq_ignore_ascii_case("debug") {
+        Some(LogLevel::Debug)
+    } else if level.eq_ignore_ascii_case("trace") {
+        Some(LogLevel::Trace)
+    } else {
+        None
+    }
+}
+
+#[macro_export]
+macro_rules! vm_debug {
+    ($($arg:tt)*) => {
+        if $crate::logging::VM_LEVEL.is_enabled($crate::logging::LogLevel::Debug) {
+            tracing::event!(target: "oxide::vm", tracing::Level::DEBUG, $($arg)*);
+        }
+    };
+}
+
+#[macro_export]
+macro_rules! vm_trace {
+    ($($arg:tt)*) => {
+        if $crate::logging::VM_LEVEL.is_enabled($crate::logging::LogLevel::Trace) {
+            tracing::event!(target: "oxide::vm", tracing::Level::TRACE, $($arg)*);
+        }
+    };
+}
+
+#[macro_export]
+macro_rules! ic_debug {
+    ($($arg:tt)*) => {
+        if $crate::logging::IC_LEVEL.is_enabled($crate::logging::LogLevel::Debug) {
+            tracing::event!(target: "oxide::ic", tracing::Level::DEBUG, $($arg)*);
+        }
+    };
+}
+
+#[macro_export]
+macro_rules! ic_trace {
+    ($($arg:tt)*) => {
+        if $crate::logging::IC_LEVEL.is_enabled($crate::logging::LogLevel::Trace) {
+            tracing::event!(target: "oxide::ic", tracing::Level::TRACE, $($arg)*);
+        }
+    };
+}
+
+#[macro_export]
+macro_rules! kernel_info {
+    ($($arg:tt)*) => {
+        if $crate::logging::KERNEL_LEVEL.is_enabled($crate::logging::LogLevel::Info) {
+            tracing::event!(target: "oxide::kernel", tracing::Level::INFO, $($arg)*);
+        }
+    };
+}
+
+#[macro_export]
+macro_rules! kernel_debug {
+    ($($arg:tt)*) => {
+        if $crate::logging::KERNEL_LEVEL.is_enabled($crate::logging::LogLevel::Debug) {
+            tracing::event!(target: "oxide::kernel", tracing::Level::DEBUG, $($arg)*);
+        }
+    };
+}
+
+#[macro_export]
+macro_rules! kernel_trace {
+    ($($arg:tt)*) => {
+        if $crate::logging::KERNEL_LEVEL.is_enabled($crate::logging::LogLevel::Trace) {
+            tracing::event!(target: "oxide::kernel", tracing::Level::TRACE, $($arg)*);
+        }
+    };
+}
+
+#[macro_export]
+macro_rules! builtins_debug {
+    ($($arg:tt)*) => {
+        if $crate::logging::BUILTINS_LEVEL.is_enabled($crate::logging::LogLevel::Debug) {
+            tracing::event!(target: "oxide::builtins", tracing::Level::DEBUG, $($arg)*);
+        }
+    };
+}
+
+#[macro_export]
+macro_rules! builtins_trace {
+    ($($arg:tt)*) => {
+        if $crate::logging::BUILTINS_LEVEL.is_enabled($crate::logging::LogLevel::Trace) {
+            tracing::event!(target: "oxide::builtins", tracing::Level::TRACE, $($arg)*);
+        }
+    };
+}
+
+#[cfg(test)]
+mod tests {
+    use super::{LogLevel, SubsystemLevel};
+
+    #[test]
+    fn log_level_ordinals_match_gate_contract() {
+        assert_eq!(LogLevel::Off as u8, 0);
+        assert_eq!(LogLevel::Trace as u8, 5);
+    }
+
+    #[test]
+    fn subsystem_level_defaults_off() {
+        let level = SubsystemLevel::new();
+        assert_eq!(level.get(), LogLevel::Off);
+        assert!(!level.is_enabled(LogLevel::Error));
+    }
+}

crates/oxide_kernel/src/shape_forge.rs

@@ -3,6 +3,8 @@ use std::sync::{Arc, RwLock};
 
 use dashmap::DashMap;
 
+use crate::kernel_debug;
+
 pub type ShapeId = u32;
 pub type StringIndex = u32;
 
@@ -70,6 +72,7 @@ impl ShapeForge {
         let key = Self::pack_key(parent_id, prop_name);
 
         if let Some(entry) = self.transitions.get(&key) {
+            kernel_debug!("ShapeForge transition cached parent={} prop={} -> id={}", parent_id, prop_name, *entry);
             return *entry;
         }
 
@@ -89,7 +92,14 @@ impl ShapeForge {
             shapes[(new_id - 1) as usize] = Some(shape);
         }
 
-        *self.transitions.entry(key).or_insert(new_id).value()
+        let entry = self.transitions.entry(key).or_insert(new_id);
+        let id = *entry.value();
+        if id == new_id {
+            kernel_debug!("ShapeForge transition parent={} prop={} -> id={}", parent_id, prop_name, new_id);
+        } else {
+            kernel_debug!("ShapeForge transition cached parent={} prop={} -> id={}", parent_id, prop_name, id);
+        }
+        id
     }
 
     pub fn get_shape(&self, id: ShapeId) -> Option<Arc<Shape>> {

crates/oxide_kernel/src/string_forge.rs

@@ -5,6 +5,8 @@ use std::sync::RwLock;
 use hashbrown::hash_map::DefaultHashBuilder as FxBuildHasher;
 use hashbrown::HashMap;
 
+use crate::{kernel_debug, kernel_trace};
+
 pub fn hash16(s: &str) -> u16 {
     let mut h = rustc_hash::FxHasher::default();
     s.hash(&mut h);
@@ -42,6 +44,7 @@ impl StringForge {
             if let Some(&idx) = inner.map.get(s) {
                 let entry = &inner.entries[idx as usize];
                 entry.ref_count.fetch_add(1, Ordering::Release);
+                kernel_trace!("StringForge intern hit idx={}", idx);
                 return (idx, entry.hash);
             }
         }
@@ -50,6 +53,7 @@ impl StringForge {
         if let Some(&idx) = inner.map.get(s) {
             let entry = &inner.entries[idx as usize];
             entry.ref_count.fetch_add(1, Ordering::Release);
+            kernel_trace!("StringForge intern hit idx={}", idx);
             return (idx, entry.hash);
         }
 
@@ -61,6 +65,7 @@ impl StringForge {
             ref_count: AtomicU32::new(1),
             hash: h,
         });
+        kernel_debug!("StringForge intern new idx={} len={}", idx, s.len());
         (idx, h)
     }
 

crates/oxide_test262/src/main.rs

@@ -377,9 +377,7 @@ fn is_skipped(meta: &TestMeta) -> Option<String> {
         }
     }
 
-    if meta.description.contains("generator")
-        || meta.description.contains("async")
-    {
+    if meta.description.contains("generator") || meta.description.contains("async") {
         return Some("description matches excluded pattern".into());
     }
 

crates/oxide_vm/Cargo.toml

@@ -19,6 +19,7 @@ serde_json.workspace = true
 chrono.workspace = true
 indexmap.workspace = true
 unicode-normalization.workspace = true
+tracing.workspace = true
 
 [dev-dependencies]
 proptest.workspace = true

crates/oxide_vm/src/dispatch/call.rs

@@ -1,5 +1,6 @@
 use crate::native::{NativeFn, NativeResult};
 use crate::vm::{native_fn_ptr_to_fn, FrameContinuation, Vm};
+use oxide_kernel::{builtins_debug, builtins_trace};
 use oxide_types::object::JsObject;
 use oxide_types::value::JsValue;
 
@@ -24,6 +25,7 @@ impl Vm {
         }
         let (args_buf, len) = Self::build_native_args(first_arg_reg, arg_count, this_reg);
         let args_slice = &args_buf[..len];
+        builtins_debug!("native_call depth={} args={}", self.native_call_depth, arg_count);
 
         // SAFETY: native_fn was set via set_native_fn with a valid NativeFn pointer;
         // native_fn_ptr_to_fn is the single coercion point for NativeFnPtr → NativeFn.
@@ -33,6 +35,7 @@ impl Vm {
         match func(self, args_slice) {
             NativeResult::Ok(val) => {
                 self.native_call_depth -= 1;
+                builtins_trace!("native_call ok depth={}", self.native_call_depth);
                 self.regs[0] = val;
                 Ok(())
             }
@@ -49,6 +52,7 @@ impl Vm {
                     } else {
                         format!("{err_val}")
                     };
+                    builtins_debug!("native_call err={}", msg);
                     (crate::builtins::error::create_error(self, &msg), "Error")
                 };
                 self.exception_value = Some(error);

crates/oxide_vm/src/dispatch/property.rs

@@ -1,5 +1,6 @@
 use oxide_compiler::opcode::OpCode;
 use oxide_kernel::prop_forge::PropTemplate;
+use oxide_kernel::{ic_debug, ic_trace};
 use oxide_types::object::JsObject;
 
 use crate::vm::Vm;
@@ -71,18 +72,28 @@ impl Vm {
 
         if cached_shape_id != 0 && cached_shape_id == obj.shape_id() && cached_slot < obj.prop_vec_len() as u32 {
             self.regs[a] = obj.get_prop_at(cached_slot);
+            ic_trace!("IC_GET hit shape={} slot={}", cached_shape_id, cached_slot);
         } else if let Some(template) = self.kernel.prop_forge().get_template(obj.shape_id()) {
             if template.prop_name == prop_name_si {
                 if template.position < obj.prop_vec_len() as u32 {
                     self.write_ic_back(obj.shape_id(), template.position);
+                    ic_debug!(
+                        "IC_GET propforge hit shape={} prop={} slot={}",
+                        obj.shape_id(),
+                        prop_name_si,
+                        template.position
+                    );
                     self.regs[a] = obj.get_prop_at(template.position);
                 } else {
+                    ic_debug!("IC_GET miss shape={} prop={}", obj.shape_id(), prop_name_si);
                     self.regs[a] = self.ordinary_get(obj, prop_name_si, val)?;
                 }
             } else {
+                ic_debug!("IC_GET miss shape={} prop={}", obj.shape_id(), prop_name_si);
                 self.regs[a] = self.ordinary_get(obj, prop_name_si, val)?;
             }
         } else {
+            ic_debug!("IC_GET miss shape={} prop={}", obj.shape_id(), prop_name_si);
             let resolved = self.ordinary_get(obj, prop_name_si, val)?;
             if let Some(pos) = self.kernel.shape_forge().lookup_position(obj.shape_id(), prop_name_si) {
                 self.write_ic_back(obj.shape_id(), pos);
@@ -127,15 +138,18 @@ impl Vm {
 
         if cached_shape_id != 0 && cached_shape_id == obj.shape_id() && cached_slot < obj.prop_vec_len() as u32 {
             obj.set_prop_at(cached_slot, value);
+            ic_trace!("IC_SET hit shape={} slot={}", cached_shape_id, cached_slot);
         } else if let Some(pos) = self.kernel.shape_forge().lookup_position(obj.shape_id(), prop_name_si) {
             obj.set_prop_at(pos, value);
             self.write_ic_back(obj.shape_id(), pos);
+            ic_debug!("IC_SET write-back shape={} slot={}", obj.shape_id(), pos);
         } else {
             let old_shape = obj.shape_id();
             self.ordinary_set_dispatch(obj, prop_name_si, value, receiver)?;
             if old_shape != obj.shape_id() {
                 if let Some(pos) = self.kernel.shape_forge().lookup_position(obj.shape_id(), prop_name_si) {
                     self.write_ic_back(obj.shape_id(), pos);
+                    ic_debug!("IC_SET write-back shape={} slot={}", obj.shape_id(), pos);
                     self.kernel.prop_forge().upsert(
                         obj.shape_id(),
                         PropTemplate {

crates/oxide_vm/src/vm.rs

@@ -12,6 +12,7 @@ use crate::coercion;
 use crate::native::{NativeFn, NativeResult};
 use oxide_kernel::kernel::{KernelConfig, OxideKernel};
 use oxide_kernel::shape_forge::EMPTY_SHAPE_ID;
+use oxide_kernel::{vm_debug, vm_trace};
 use oxide_types::mem::{Epoch, P};
 use oxide_types::object::{JsObject, NativeFnPtr, PropAttributes};
 use oxide_types::value::JsValue;
@@ -1355,6 +1356,13 @@ impl Vm {
                                 let ext = self.bytecode[self.pc];
                                 self.pc += 1;
                                 let arg_count = (ext & 0xFF) as usize;
+                                vm_debug!(
+                                    "CALL rd={} this={} args={} depth={}",
+                                    rd,
+                                    this_reg,
+                                    arg_count,
+                                    self.frames.len()
+                                );
 
                                 if obj.native_fn().is_some() {
                                     match self.dispatch_native_call(obj, callee, this_reg, first_arg_reg, arg_count) {
@@ -1405,6 +1413,7 @@ impl Vm {
                     let ext = self.bytecode[self.pc];
                     self.pc += 1;
                     let arg_count = (ext & 0xFF) as usize;
+                    vm_debug!("CALL_NATIVE rd={} args={}", rd, arg_count);
 
                     self.dispatch_native_call(obj, callee, this_reg, first_arg_reg, arg_count)?;
                 }
@@ -1412,6 +1421,7 @@ impl Vm {
                 OpCode::NEW_EXPRESSION => {
                     let constructor_reg = a;
                     let first_arg_reg = b as u8;
+                    vm_debug!("NEW_EXPRESSION rd={}", rd);
 
                     let constructor = self.regs[constructor_reg];
                     if !constructor.is_object() {
@@ -1780,6 +1790,7 @@ impl Vm {
 
                 OpCode::RETURN => {
                     let result = self.regs[rd];
+                    vm_debug!("RETURN depth={}", self.frames.len());
                     if let Some(frame) = self.frames.pop() {
                         let construct_result_reg = frame.construct_result_reg;
                         let constructed_this = frame.constructed_this;
@@ -2156,6 +2167,7 @@ impl Vm {
                 }
 
                 OpCode::THROW => {
+                    vm_debug!("THROW pc={}", self.pc);
                     let exc_value = self.regs[rd];
                     self.exception_value = Some(exc_value);
                     self.pending_error_kind = Some(self.thrown_error_kind(exc_value));
@@ -2166,6 +2178,7 @@ impl Vm {
                 }
 
                 OpCode::TRY_BEGIN => {
+                    vm_trace!("TRY_BEGIN frame_depth={}", self.frames.len());
                     let offset = opcode::offset16(instr) as isize;
                     let catch_pc = if offset == 0 {
                         None