[tracing] Add kernel tracing subsystem and integration validation

kconfig/config/qemu_mps2_an385/debug/defconfig

@@ -35,6 +35,8 @@ CONFIG_ASYNC_OUTPUT_THREAD_PRIORITY=256
 # end of Kernel Core Features
 
 CONFIG_ENABLE_SYSCALL=y
+# tracing
+CONFIG_TRACING=y
 # CONFIG_FDT is not set
 # CONFIG_VIRTIO is not set
 CONFIG_SERIAL_RX_FIFO_SIZE=512

kernel/src/Kconfig

@@ -45,6 +45,15 @@ config THREAD_STATS
     default n
     bool "Enable statistics of thread"
 
+config TRACING
+    default n
+    bool "Enable kernel tracing subsystem"
+
+config TRACING_BUFFER_KB
+    depends on TRACING
+    default 64
+    int "Tracing ring buffer size in KB"
+
 # os adapter configuration
 menu "os adapter configuration"
     choice

kernel/src/allocator/mod.rs

@@ -87,8 +87,16 @@ pub fn malloc(size: usize) -> *mut u8 {
     }
     const ALIGN: usize = core::mem::size_of::<usize>();
     let layout = Layout::from_size_align(size, ALIGN).unwrap();
-    HEAP.alloc(layout)
-        .map_or(ptr::null_mut(), |allocation| allocation.as_ptr())
+    let ptr = HEAP
+        .alloc(layout)
+        .map_or(ptr::null_mut(), |allocation| allocation.as_ptr());
+    #[cfg(tracing)]
+    if ptr.is_null() {
+        crate::trace_event!(record_mm_alloc_fail(size, ALIGN, 0));
+    } else {
+        crate::trace_event!(record_mm_alloc(ptr as usize, size, ALIGN, 0));
+    }
+    ptr
 }
 
 /// Free previously allocated memory pointed by ptr.
@@ -100,6 +108,7 @@ pub fn free(ptr: *mut u8) {
     if core::intrinsics::unlikely(ptr.is_null()) {
         return;
     }
+    crate::trace_event!(record_mm_free(ptr as usize, 0, 0));
     unsafe { HEAP.deallocate_unknown_align(ptr) };
 }
 
@@ -117,10 +126,20 @@ pub fn realloc(ptr: *mut u8, newsize: usize) -> *mut u8 {
     if ptr.is_null() {
         return malloc(newsize);
     }
-    unsafe {
+    let new_ptr = unsafe {
         HEAP.realloc_unknown_align(ptr, newsize)
             .map_or(ptr::null_mut(), |ptr| ptr.as_ptr())
+    };
+    #[cfg(tracing)]
+    if new_ptr.is_null() {
+        crate::trace_event!(record_mm_alloc_fail(newsize, 0, 0));
+    } else {
+        crate::trace_event!(record_mm_alloc(new_ptr as usize, newsize, 0, 0));
+        if new_ptr != ptr {
+            crate::trace_event!(record_mm_free(ptr as usize, 0, 0));
+        }
     }
+    new_ptr
 }
 
 /// Allocates memory for an array of elements and initializes all bytes in this block to zero.
@@ -156,8 +175,16 @@ pub fn malloc_align(size: usize, align: usize) -> *mut u8 {
     }
 
     let layout = Layout::from_size_align(size, align).unwrap();
-    HEAP.alloc(layout)
-        .map_or(ptr::null_mut(), |allocation| allocation.as_ptr())
+    let ptr = HEAP
+        .alloc(layout)
+        .map_or(ptr::null_mut(), |allocation| allocation.as_ptr());
+    #[cfg(tracing)]
+    if ptr.is_null() {
+        crate::trace_event!(record_mm_alloc_fail(size, align, 0));
+    } else {
+        crate::trace_event!(record_mm_alloc(ptr as usize, size, align, 0));
+    }
+    ptr
 }
 
 /// Deallocates memory that was allocated using `malloc_align`.
@@ -169,6 +196,7 @@ pub fn free_align(ptr: *mut u8, align: usize) {
     if ptr.is_null() {
         return;
     }
+    crate::trace_event!(record_mm_free(ptr as usize, 0, 0));
     unsafe {
         let layout = Layout::from_size_align_unchecked(0, align);
         HEAP.dealloc(ptr, layout);

kernel/src/arch/aarch64/exception.rs

@@ -167,9 +167,11 @@ extern "C" fn handle_svc(context: &mut Context) -> usize {
             context.x0, context.x1, context.x2, context.x3, context.x4, context.x5,
         ],
     };
+    crate::trace_event!(record_sys_enter(sc.nr, sc.args[0], sc.args[1], sc.args[2]));
     enable_local_irq();
     context.x0 = dispatch_syscall(&sc);
     disable_local_irq();
+    crate::trace_event!(record_sys_exit(sc.nr, context.x0 as isize, 0));
     compiler_fence(Ordering::SeqCst);
     old_sp
 }

kernel/src/arch/arm/mod.rs

@@ -417,8 +417,10 @@ extern "C" fn syscall_handler(ctx: &mut Context) {
         nr: ctx.r7,
         args: [ctx.r0, ctx.r1, ctx.r2, ctx.r3, ctx.r4, ctx.r5],
     };
+    crate::trace_event!(record_sys_enter(sc.nr, sc.args[0], sc.args[1], sc.args[2]));
     // r0 should contain the return value.
     ctx.r0 = dispatch_syscall(&sc);
+    crate::trace_event!(record_sys_exit(sc.nr, ctx.r0 as isize, 0));
 }
 
 #[naked]

kernel/src/arch/riscv/trap.rs

@@ -195,7 +195,9 @@ extern "C" fn handle_ecall(ctx: &mut Context, cont: usize) -> usize {
             nr: ctx.a7,
             args: [ctx.a0, ctx.a1, ctx.a2, ctx.a3, ctx.a4, ctx.a5],
         };
+        crate::trace_event!(record_sys_enter(sc.nr, sc.args[0], sc.args[1], sc.args[2]));
         ctx.a0 = dispatch_syscall(&sc);
+        crate::trace_event!(record_sys_exit(sc.nr, ctx.a0 as isize, 0));
         compiler_fence(Ordering::SeqCst);
     }
     sp

kernel/src/boot.rs

@@ -16,6 +16,8 @@
 use crate::asynk;
 #[cfg(enable_net)]
 use crate::net;
+#[cfg(tracing)]
+use crate::tracing;
 #[cfg(enable_vfs)]
 use crate::vfs;
 use crate::{
@@ -157,6 +159,8 @@ extern "C" fn init() {
 
     scheduler::init();
     logger::logger_init();
+    #[cfg(tracing)]
+    tracing::init();
     time::timer::init();
     #[cfg(kernel_async)]
     asynk::init();

kernel/src/irq.rs

@@ -33,7 +33,12 @@ impl IrqTrace {
 
     #[inline]
     fn enter(&self) {
-        enter_irq();
+        let nesting = enter_irq();
+        crate::trace_event!(record_irq_enter(
+            usize::from(self.irq_number) as u16,
+            0,
+            nesting as u8
+        ));
         #[cfg(procfs)]
         unsafe {
             irq_trace::IRQ_COUNTERS[usize::from(self.irq_number)].fetch_add(1, Ordering::Relaxed);
@@ -42,7 +47,12 @@ impl IrqTrace {
 
     #[inline]
     fn leave(&self) {
-        leave_irq();
+        let nesting = leave_irq();
+        crate::trace_event!(record_irq_exit(
+            usize::from(self.irq_number) as u16,
+            0,
+            nesting as u8
+        ));
     }
 }
 

kernel/src/lib.rs

@@ -80,6 +80,8 @@ pub mod sync;
 pub mod syscall_handlers;
 pub mod thread;
 pub mod time;
+#[cfg(tracing)]
+pub mod tracing;
 pub mod types;
 #[cfg(enable_vfs)]
 pub mod vfs;
@@ -113,6 +115,16 @@ macro_rules! trace {
     }};
 }
 
+#[macro_export]
+macro_rules! trace_event {
+    ($func:ident ( $($arg:expr),* $(,)? )) => {{
+        #[cfg(tracing)]
+        {
+            $crate::tracing::$func($($arg),*);
+        }
+    }};
+}
+
 #[cfg(test)]
 mod tests {
     extern crate alloc;

kernel/src/scheduler/mod.rs

@@ -214,6 +214,13 @@ fn switch_current_thread(next: ThreadNode, old_sp: usize) -> usize {
     let ok = next.transfer_state(thread::READY, thread::RUNNING);
     debug_assert_eq!(ok, Ok(()));
     let mut old = set_current_thread(next);
+    crate::trace_event!(record_sched_switch(
+        Thread::id(&old) as u32,
+        next_id as u32,
+        old.priority() as usize,
+        next_priority as usize,
+        old.state() as usize,
+    ));
     #[cfg(thread_stats)]
     old.increment_cycles(cycles);
     #[cfg(debugging_scheduler)]
@@ -276,6 +283,7 @@ pub(crate) extern "C" fn relinquish_me_and_return_next_sp(old_sp: usize) -> usiz
 
 pub fn retire_me() -> ! {
     let retiring = current_thread_ref();
+    crate::trace_event!(record_thread_exit(Thread::id(retiring) as u32, 0));
     #[cfg(procfs)]
     {
         let _ = crate::vfs::trace_thread_close(unsafe { Arc::clone_from(retiring) });
@@ -357,6 +365,12 @@ pub fn suspend_me_until<T>(deadline: Tick, wq: Option<SpinLockGuard<'_, T>>) ->
         current_thread_id()
     );
     let old = current_thread_ref();
+    crate::trace_event!(record_thread_block(
+        Thread::id(old) as u32,
+        1,
+        0,
+        deadline.0
+    ));
     let current_idle = idle::current_idle_thread_ref();
     debug_assert_ne!(Thread::id(old), Thread::id(current_idle));
     let next = next_ready_thread().map_or_else(|| unsafe { Arc::clone_from(current_idle) }, |v| v);

kernel/src/sync/mutex.rs

@@ -124,6 +124,7 @@ impl Mutex {
     pub fn pend_for(&self, mut ticks: Tick) -> bool {
         debug_assert!(!irq::is_in_irq());
         let this_thread = scheduler::current_thread();
+        let lock_id = self as *const _ as usize;
         let this_mutex = unsafe { MutexList::clone_from(&self.mutex_node) };
         #[cfg(debugging_scheduler)]
         crate::trace!(
@@ -144,6 +145,10 @@ impl Mutex {
                 self.increment_nesting_count();
                 let old = self.replace_owner(Some(this_thread.clone()));
                 debug_assert!(old.is_none());
+                crate::trace_event!(record_lock_hold_begin(
+                    lock_id,
+                    Thread::id(&this_thread) as u32
+                ));
                 let mut guard = this_thread.lock();
                 let ok = guard.add_acquired_mutex(this_mutex.clone());
                 debug_assert!(ok);
@@ -182,12 +187,15 @@ impl Mutex {
             );
 
             let timeout;
+            crate::trace_event!(record_lock_wait_begin(lock_id, 0));
             (timeout, w) = Self::inner_pend_for(ticks, &this_mutex, w, &this_thread, &owner);
             if timeout {
+                crate::trace_event!(record_lock_wait_end(lock_id, false));
                 this_thread.replace_pending_on_mutex(None);
                 Self::recover_priority(&this_thread, &this_mutex);
                 return false;
             }
+            crate::trace_event!(record_lock_wait_end(lock_id, true));
             if ticks != Tick::MAX {
                 let now = Tick::now();
                 ticks = ticks.since(now.since(start));
@@ -313,6 +321,7 @@ impl Mutex {
     pub fn post(&self) {
         debug_assert!(!irq::is_in_irq());
         let this_thread = scheduler::current_thread();
+        let lock_id = self as *const _ as usize;
         {
             #[cfg(debugging_scheduler)]
             crate::trace!(
@@ -336,6 +345,7 @@ impl Mutex {
             if self.decrement_nesting_count() > 1 {
                 return;
             }
+            crate::trace_event!(record_lock_hold_end(lock_id));
             let mut this_mutex = unsafe { MutexList::clone_from(&self.mutex_node) };
             for we in this_lock.iter() {
                 let t = we.thread.clone();

kernel/src/thread/builder.rs

@@ -145,6 +145,12 @@ impl Builder {
         {
             let _ = crate::vfs::trace_thread_create(thread.clone());
         }
+        crate::trace_event!(record_thread_create(
+            Thread::id(&thread) as u32,
+            0,
+            self.priority as usize,
+            0
+        ));
 
         thread
     }