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

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