diff --git a/kconfig/config/qemu_mps2_an385/debug/defconfig b/kconfig/config/qemu_mps2_an385/debug/defconfig index 8a2d1f7e..c2653cf3 100644 --- a/kconfig/config/qemu_mps2_an385/debug/defconfig +++ b/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 diff --git a/kernel/src/Kconfig b/kernel/src/Kconfig index a576f08b..ac286823 100644 --- a/kernel/src/Kconfig +++ b/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 diff --git a/kernel/src/allocator/mod.rs b/kernel/src/allocator/mod.rs index 13acd459..7d917fed 100644 --- a/kernel/src/allocator/mod.rs +++ b/kernel/src/allocator/mod.rs @@ -87,8 +87,16 @@ pub fn malloc(size: usize) -> *mut u8 { } const ALIGN: usize = core::mem::size_of::(); 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); diff --git a/kernel/src/arch/aarch64/exception.rs b/kernel/src/arch/aarch64/exception.rs index c8f22f09..781d598a 100644 --- a/kernel/src/arch/aarch64/exception.rs +++ b/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 } diff --git a/kernel/src/arch/arm/mod.rs b/kernel/src/arch/arm/mod.rs index 4df3e114..c07fdd68 100644 --- a/kernel/src/arch/arm/mod.rs +++ b/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] diff --git a/kernel/src/arch/riscv/trap.rs b/kernel/src/arch/riscv/trap.rs index 30dc8725..3f042936 100644 --- a/kernel/src/arch/riscv/trap.rs +++ b/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 diff --git a/kernel/src/boot.rs b/kernel/src/boot.rs index 6342cf78..a24214e8 100644 --- a/kernel/src/boot.rs +++ b/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(); diff --git a/kernel/src/irq.rs b/kernel/src/irq.rs index 143de45f..873b4b02 100644 --- a/kernel/src/irq.rs +++ b/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 + )); } } diff --git a/kernel/src/lib.rs b/kernel/src/lib.rs index c53a46bd..23ca908b 100644 --- a/kernel/src/lib.rs +++ b/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; diff --git a/kernel/src/scheduler/mod.rs b/kernel/src/scheduler/mod.rs index db03cf3d..e3003535 100644 --- a/kernel/src/scheduler/mod.rs +++ b/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(deadline: Tick, wq: Option>) -> 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); diff --git a/kernel/src/sync/mutex.rs b/kernel/src/sync/mutex.rs index e6faba5e..7689bae2 100644 --- a/kernel/src/sync/mutex.rs +++ b/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(); diff --git a/kernel/src/thread/builder.rs b/kernel/src/thread/builder.rs index 9ce85cf1..2fb8b23d 100644 --- a/kernel/src/thread/builder.rs +++ b/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 } diff --git a/kernel/src/tracing/buffer.rs b/kernel/src/tracing/buffer.rs new file mode 100644 index 00000000..47c509d5 --- /dev/null +++ b/kernel/src/tracing/buffer.rs @@ -0,0 +1,110 @@ +// Copyright (c) 2026 vivo Mobile Communication Co., Ltd. +// +// Licensed under the Apache License, Version 2.0 (the "License"); +// you may not use this file except in compliance with the License. +// You may obtain a copy of the License at +// +// http://www.apache.org/licenses/LICENSE-2.0 +// +// Unless required by applicable law or agreed to in writing, software +// distributed under the License is distributed on an "AS IS" BASIS, +// WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. +// See the License for the specific language governing permissions and +// limitations under the License. + +use super::event::EventRecord; +use core::{ + cell::UnsafeCell, + cmp, + sync::atomic::{AtomicUsize, Ordering}, +}; + +pub const RECORD_CAPACITY: usize = 512; +const NUM_CPUS: usize = blueos_kconfig::CONFIG_NUM_CORES as usize; +const INVALID_SEQ: usize = usize::MAX; + +struct Slot { + record: UnsafeCell, + commit_seq: AtomicUsize, +} + +impl Slot { + const fn new() -> Self { + Self { + record: UnsafeCell::new(EventRecord::empty()), + commit_seq: AtomicUsize::new(INVALID_SEQ), + } + } +} + +// SAFETY: Slot concurrent access is coordinated by commit sequence atomics. +unsafe impl Sync for Slot {} + +struct CpuRing { + write_seq: AtomicUsize, + slots: [Slot; RECORD_CAPACITY], +} + +impl CpuRing { + const fn new() -> Self { + Self { + write_seq: AtomicUsize::new(0), + slots: [const { Slot::new() }; RECORD_CAPACITY], + } + } + + fn init(&self) { + self.write_seq.store(0, Ordering::Relaxed); + for slot in &self.slots { + slot.commit_seq.store(INVALID_SEQ, Ordering::Relaxed); + } + } +} + +static RINGS: [CpuRing; NUM_CPUS] = [const { CpuRing::new() }; NUM_CPUS]; + +pub fn init() { + for ring in &RINGS { + ring.init(); + } +} + +// Returns true if an old record was overwritten. +pub fn push(record: EventRecord) -> bool { + let cpu_id = crate::arch::current_cpu_id(); + let ring = &RINGS[cpu_id]; + + // Reserve a slot lock-free. This is safe under IRQ and SMP because each + // writer gets a unique sequence number. + let seq = ring.write_seq.fetch_add(1, Ordering::Relaxed); + let idx = seq % RECORD_CAPACITY; + let slot = &ring.slots[idx]; + // SAFETY: this slot is uniquely owned by `seq` until commit_seq is set. + unsafe { *slot.record.get() = record }; + // Publish the record after write is complete. + slot.commit_seq.store(seq, Ordering::Release); + + seq >= RECORD_CAPACITY +} + +pub fn for_each_committed(mut f: impl FnMut(EventRecord) -> bool) { + for ring in &RINGS { + // Snapshot writer progress for this CPU ring. + let end_seq = ring.write_seq.load(Ordering::Acquire); + let span = cmp::min(end_seq, RECORD_CAPACITY); + let start_seq = end_seq - span; + for seq in start_seq..end_seq { + let idx = seq % RECORD_CAPACITY; + let slot = &ring.slots[idx]; + // A slot belongs to this sequence only when commit_seq matches. + if slot.commit_seq.load(Ordering::Acquire) != seq { + continue; + } + // SAFETY: commit_seq == seq guarantees a fully published record. + let record = unsafe { *slot.record.get() }; + if !f(record) { + return; + } + } + } +} diff --git a/kernel/src/tracing/control.rs b/kernel/src/tracing/control.rs new file mode 100644 index 00000000..ec4098f6 --- /dev/null +++ b/kernel/src/tracing/control.rs @@ -0,0 +1,114 @@ +// Copyright (c) 2026 vivo Mobile Communication Co., Ltd. +// +// Licensed under the Apache License, Version 2.0 (the "License"); +// you may not use this file except in compliance with the License. +// You may obtain a copy of the License at +// +// http://www.apache.org/licenses/LICENSE-2.0 +// +// Unless required by applicable law or agreed to in writing, software +// distributed under the License is distributed on an "AS IS" BASIS, +// WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. +// See the License for the specific language governing permissions and +// limitations under the License. + +use super::event::EventId; +use core::sync::atomic::{AtomicBool, AtomicUsize, Ordering}; +use spin::Mutex; + +#[derive(Clone, Copy, Debug)] +pub struct TraceConfig { + pub event_mask: usize, + pub sample_rate: usize, + pub buffer_kb: usize, +} + +impl Default for TraceConfig { + fn default() -> Self { + Self { + event_mask: usize::MAX, + sample_rate: 1, + #[cfg(tracing)] + buffer_kb: blueos_kconfig::CONFIG_TRACING_BUFFER_KB as usize, + #[cfg(not(tracing))] + buffer_kb: 64, + } + } +} + +#[derive(Clone, Copy, Debug, Default)] +pub struct TraceStats { + pub enabled: bool, + pub total_events: usize, + pub dropped_events: usize, +} + +static ENABLED: AtomicBool = AtomicBool::new(false); +static TOTAL_EVENTS: AtomicUsize = AtomicUsize::new(0); +static DROPPED_EVENTS: AtomicUsize = AtomicUsize::new(0); +#[cfg(tracing)] +const DEFAULT_BUFFER_KB: usize = blueos_kconfig::CONFIG_TRACING_BUFFER_KB as usize; +#[cfg(not(tracing))] +const DEFAULT_BUFFER_KB: usize = 64; + +static CONFIG: Mutex = Mutex::new(TraceConfig { + event_mask: usize::MAX, + sample_rate: 1, + buffer_kb: DEFAULT_BUFFER_KB, +}); + +pub fn init() { + ENABLED.store(false, Ordering::Relaxed); + TOTAL_EVENTS.store(0, Ordering::Relaxed); + DROPPED_EVENTS.store(0, Ordering::Relaxed); +} + +pub fn reset_counters() { + TOTAL_EVENTS.store(0, Ordering::Relaxed); + DROPPED_EVENTS.store(0, Ordering::Relaxed); +} + +pub fn configure(cfg: TraceConfig) { + let mut w = CONFIG.lock(); + *w = cfg; +} + +pub fn config() -> TraceConfig { + *CONFIG.lock() +} + +pub fn start() -> bool { + !ENABLED.swap(true, Ordering::SeqCst) +} + +pub fn stop() -> bool { + ENABLED.swap(false, Ordering::SeqCst) +} + +#[inline] +pub fn enabled() -> bool { + ENABLED.load(Ordering::SeqCst) +} + +#[inline] +pub fn should_record(_event_id: EventId) -> bool { + enabled() +} + +#[inline] +pub fn on_event_recorded() { + TOTAL_EVENTS.fetch_add(1, Ordering::Relaxed); +} + +#[inline] +pub fn on_event_dropped(dropped: usize) { + DROPPED_EVENTS.fetch_add(dropped, Ordering::Relaxed); +} + +pub fn stats() -> TraceStats { + TraceStats { + enabled: enabled(), + total_events: TOTAL_EVENTS.load(Ordering::Relaxed), + dropped_events: DROPPED_EVENTS.load(Ordering::Relaxed), + } +} diff --git a/kernel/src/tracing/dump.rs b/kernel/src/tracing/dump.rs new file mode 100644 index 00000000..45fd76b0 --- /dev/null +++ b/kernel/src/tracing/dump.rs @@ -0,0 +1,131 @@ +// Copyright (c) 2026 vivo Mobile Communication Co., Ltd. +// +// Licensed under the Apache License, Version 2.0 (the "License"); +// you may not use this file except in compliance with the License. +// You may obtain a copy of the License at +// +// http://www.apache.org/licenses/LICENSE-2.0 +// +// Unless required by applicable law or agreed to in writing, software +// distributed under the License is distributed on an "AS IS" BASIS, +// WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. +// See the License for the specific language governing permissions and +// limitations under the License. + +use super::{buffer, control}; + +#[repr(C)] +struct TraceFileHeader { + magic: [u8; 4], + version: u16, + header_size: u16, + flags: u32, + boot_time_ns: u64, + tsc_freq_hz: u64, + cpu_count: u32, + reserved: u32, +} + +impl TraceFileHeader { + const fn new() -> Self { + Self { + magic: *b"BTRC", + version: 1, + header_size: core::mem::size_of::() as u16, + flags: 0, + boot_time_ns: 0, + tsc_freq_hz: 0, + cpu_count: blueos_kconfig::CONFIG_NUM_CORES as u32, + reserved: 0, + } + } +} + +#[inline] +fn put_u8(out: &mut [u8], off: &mut usize, v: u8) -> bool { + if *off + 1 > out.len() { + return false; + } + out[*off] = v; + *off += 1; + true +} + +#[inline] +fn put_u16(out: &mut [u8], off: &mut usize, v: u16) -> bool { + if *off + 2 > out.len() { + return false; + } + out[*off..*off + 2].copy_from_slice(&v.to_le_bytes()); + *off += 2; + true +} + +#[inline] +fn put_u32(out: &mut [u8], off: &mut usize, v: u32) -> bool { + if *off + 4 > out.len() { + return false; + } + out[*off..*off + 4].copy_from_slice(&v.to_le_bytes()); + *off += 4; + true +} + +#[inline] +fn put_u64(out: &mut [u8], off: &mut usize, v: u64) -> bool { + if *off + 8 > out.len() { + return false; + } + out[*off..*off + 8].copy_from_slice(&v.to_le_bytes()); + *off += 8; + true +} + +fn write_header(out: &mut [u8], off: &mut usize) -> bool { + let hdr = TraceFileHeader::new(); + if *off + core::mem::size_of::() > out.len() { + return false; + } + out[*off..*off + 4].copy_from_slice(&hdr.magic); + *off += 4; + put_u16(out, off, hdr.version) + && put_u16(out, off, hdr.header_size) + && put_u32(out, off, hdr.flags) + && put_u64(out, off, hdr.boot_time_ns) + && put_u64(out, off, hdr.tsc_freq_hz) + && put_u32(out, off, hdr.cpu_count) + && put_u32(out, off, hdr.reserved) +} + +pub fn dump_to_slice(out: &mut [u8]) -> usize { + let mut off = 0; + if !write_header(out, &mut off) { + return 0; + } + + // Emit a synthetic dropped counter event into dump metadata region. + let stats = control::stats(); + if !put_u64(out, &mut off, stats.dropped_events as u64) { + return off; + } + + buffer::for_each_committed(|rec| { + if !(put_u64(out, &mut off, rec.header.ts_ns) + && put_u16(out, &mut off, rec.header.event_id) + && put_u16(out, &mut off, rec.header.cpu_id) + && put_u32(out, &mut off, rec.header.tid) + && put_u8(out, &mut off, rec.header.phase) + && put_u8(out, &mut off, rec.header.flags) + && put_u16(out, &mut off, rec.header.payload_len)) + { + return false; + } + for datum in rec.data { + if !put_u64(out, &mut off, datum as u64) { + return false; + } + } + true + }); + off +} diff --git a/kernel/src/tracing/event.rs b/kernel/src/tracing/event.rs new file mode 100644 index 00000000..91bd33c5 --- /dev/null +++ b/kernel/src/tracing/event.rs @@ -0,0 +1,89 @@ +// Copyright (c) 2026 vivo Mobile Communication Co., Ltd. +// +// Licensed under the Apache License, Version 2.0 (the "License"); +// you may not use this file except in compliance with the License. +// You may obtain a copy of the License at +// +// http://www.apache.org/licenses/LICENSE-2.0 +// +// Unless required by applicable law or agreed to in writing, software +// distributed under the License is distributed on an "AS IS" BASIS, +// WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. +// See the License for the specific language governing permissions and +// limitations under the License. + +#[repr(u8)] +#[derive(Clone, Copy, Debug, PartialEq, Eq)] +pub enum EventPhase { + Begin = 1, + End = 2, + Instant = 3, + Counter = 4, +} + +#[repr(u16)] +#[derive(Clone, Copy, Debug, PartialEq, Eq)] +pub enum EventId { + TraceStart = 0x0001, + TraceStop = 0x0002, + TraceDropped = 0x0003, + + SchedSwitch = 0x0101, + ThreadCreate = 0x0102, + ThreadExit = 0x0103, + ThreadWakeup = 0x0104, + ThreadBlock = 0x0105, + + IrqEnter = 0x0201, + IrqExit = 0x0202, + + SysEnter = 0x0301, + SysExit = 0x0302, + + LockWaitBegin = 0x0401, + LockWaitEnd = 0x0402, + LockHoldBegin = 0x0403, + LockHoldEnd = 0x0404, + + MmAlloc = 0x0501, + MmFree = 0x0502, + MmAllocFail = 0x0503, + + CounterMemUsedBytes = 0x0601, +} + +#[derive(Clone, Copy, Debug)] +#[repr(C)] +pub struct RecordHeader { + pub ts_ns: u64, + pub event_id: u16, + pub cpu_id: u16, + pub tid: u32, + pub phase: u8, + pub flags: u8, + pub payload_len: u16, +} + +#[derive(Clone, Copy, Debug)] +#[repr(C)] +pub struct EventRecord { + pub header: RecordHeader, + pub data: [usize; 4], +} + +impl EventRecord { + pub const fn empty() -> Self { + Self { + header: RecordHeader { + ts_ns: 0, + event_id: 0, + cpu_id: 0, + tid: 0, + phase: 0, + flags: 0, + payload_len: 0, + }, + data: [0; 4], + } + } +} diff --git a/kernel/src/tracing/mod.rs b/kernel/src/tracing/mod.rs new file mode 100644 index 00000000..e837df39 --- /dev/null +++ b/kernel/src/tracing/mod.rs @@ -0,0 +1,287 @@ +// Copyright (c) 2026 vivo Mobile Communication Co., Ltd. +// +// Licensed under the Apache License, Version 2.0 (the "License"); +// you may not use this file except in compliance with the License. +// You may obtain a copy of the License at +// +// http://www.apache.org/licenses/LICENSE-2.0 +// +// Unless required by applicable law or agreed to in writing, software +// distributed under the License is distributed on an "AS IS" BASIS, +// WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. +// See the License for the specific language governing permissions and +// limitations under the License. + +pub mod buffer; +pub mod control; +pub mod dump; +pub mod event; + +pub use control::{TraceConfig, TraceStats}; +use event::{EventId, EventPhase, EventRecord, RecordHeader}; + +#[inline] +fn now_ns() -> u64 { + crate::time::now().as_nanos() as u64 +} + +#[inline] +fn current_tid() -> u32 { + if crate::scheduler::is_schedule_ready() { + crate::scheduler::current_thread_id() as u32 + } else { + 0 + } +} + +#[inline] +fn record_raw(event_id: EventId, phase: EventPhase, tid: u32, data: [usize; 4]) { + if !control::should_record(event_id) { + return; + } + let record = EventRecord { + header: RecordHeader { + ts_ns: now_ns(), + event_id: event_id as u16, + cpu_id: crate::arch::current_cpu_id() as u16, + tid, + phase: phase as u8, + flags: 0, + payload_len: core::mem::size_of::<[usize; 4]>() as u16, + }, + data, + }; + let overwritten = buffer::push(record); + control::on_event_recorded(); + if overwritten { + control::on_event_dropped(1); + } +} + +pub fn init() { + control::init(); + buffer::init(); +} + +pub fn reset() { + control::stop(); + control::reset_counters(); + buffer::init(); +} + +pub fn start(cfg: TraceConfig) -> bool { + if control::enabled() { + return false; + } + reset(); + control::configure(cfg); + let started = control::start(); + if started { + record_raw( + EventId::TraceStart, + EventPhase::Instant, + 0, + [cfg.event_mask, cfg.sample_rate, cfg.buffer_kb, 0], + ); + } + started +} + +pub fn stop(reason: u16) -> bool { + if !control::enabled() { + return false; + } + record_raw( + EventId::TraceStop, + EventPhase::Instant, + 0, + [reason as usize, 0, 0, 0], + ); + control::stop() +} + +#[inline] +pub fn enabled() -> bool { + control::enabled() +} + +#[inline] +pub fn stats() -> TraceStats { + control::stats() +} + +#[inline] +pub fn dump_to_slice(out: &mut [u8]) -> usize { + dump::dump_to_slice(out) +} + +#[inline] +pub fn record_sched_switch( + prev_tid: u32, + next_tid: u32, + prev_prio: usize, + next_prio: usize, + prev_state: usize, +) { + record_raw( + EventId::SchedSwitch, + EventPhase::Instant, + next_tid, + [ + prev_tid as usize, + next_tid as usize, + prev_prio, + (next_prio << 16) | prev_state, + ], + ); +} + +#[inline] +pub fn record_thread_create(new_tid: u32, parent_tid: u32, prio: usize, kind: usize) { + record_raw( + EventId::ThreadCreate, + EventPhase::Instant, + current_tid(), + [new_tid as usize, parent_tid as usize, prio, kind], + ); +} + +#[inline] +pub fn record_thread_exit(tid: u32, code: isize) { + record_raw( + EventId::ThreadExit, + EventPhase::Instant, + tid, + [tid as usize, code as usize, 0, 0], + ); +} + +#[inline] +pub fn record_thread_wakeup(target_tid: u32, by_tid: u32, reason: usize, obj_id: usize) { + record_raw( + EventId::ThreadWakeup, + EventPhase::Instant, + by_tid, + [target_tid as usize, by_tid as usize, reason, obj_id], + ); +} + +#[inline] +pub fn record_thread_block(tid: u32, reason: usize, obj_id: usize, timeout: usize) { + record_raw( + EventId::ThreadBlock, + EventPhase::Instant, + tid, + [tid as usize, reason, obj_id, timeout], + ); +} + +#[inline] +pub fn record_irq_enter(irq: u16, kind: u8, nesting: u8) { + record_raw( + EventId::IrqEnter, + EventPhase::Begin, + 0, + [irq as usize, kind as usize, nesting as usize, 0], + ); +} + +#[inline] +pub fn record_irq_exit(irq: u16, kind: u8, nesting: u8) { + record_raw( + EventId::IrqExit, + EventPhase::End, + 0, + [irq as usize, kind as usize, nesting as usize, 0], + ); +} + +#[inline] +pub fn record_sys_enter(nr: usize, arg0: usize, arg1: usize, arg2: usize) { + record_raw( + EventId::SysEnter, + EventPhase::Begin, + current_tid(), + [nr, arg0, arg1, arg2], + ); +} + +#[inline] +pub fn record_sys_exit(nr: usize, ret: isize, errno: isize) { + record_raw( + EventId::SysExit, + EventPhase::End, + current_tid(), + [nr, ret as usize, errno as usize, 0], + ); +} + +#[inline] +pub fn record_lock_wait_begin(lock_id: usize, lock_type: usize) { + record_raw( + EventId::LockWaitBegin, + EventPhase::Begin, + current_tid(), + [lock_id, lock_type, 0, 0], + ); +} + +#[inline] +pub fn record_lock_wait_end(lock_id: usize, success: bool) { + record_raw( + EventId::LockWaitEnd, + EventPhase::End, + current_tid(), + [lock_id, success as usize, 0, 0], + ); +} + +#[inline] +pub fn record_lock_hold_begin(lock_id: usize, owner_tid: u32) { + record_raw( + EventId::LockHoldBegin, + EventPhase::Begin, + owner_tid, + [lock_id, owner_tid as usize, 0, 0], + ); +} + +#[inline] +pub fn record_lock_hold_end(lock_id: usize) { + record_raw( + EventId::LockHoldEnd, + EventPhase::End, + current_tid(), + [lock_id, 0, 0, 0], + ); +} + +#[inline] +pub fn record_mm_alloc(ptr: usize, size: usize, align: usize, heap_id: usize) { + record_raw( + EventId::MmAlloc, + EventPhase::Instant, + current_tid(), + [ptr, size, align, heap_id], + ); +} + +#[inline] +pub fn record_mm_free(ptr: usize, size: usize, heap_id: usize) { + record_raw( + EventId::MmFree, + EventPhase::Instant, + current_tid(), + [ptr, size, heap_id, 0], + ); +} + +#[inline] +pub fn record_mm_alloc_fail(size: usize, align: usize, heap_id: usize) { + record_raw( + EventId::MmAllocFail, + EventPhase::Instant, + current_tid(), + [size, align, heap_id, 0], + ); +} diff --git a/kernel/src/vfs/procfs/mod.rs b/kernel/src/vfs/procfs/mod.rs index 40c3d29d..c11d321d 100644 --- a/kernel/src/vfs/procfs/mod.rs +++ b/kernel/src/vfs/procfs/mod.rs @@ -15,6 +15,7 @@ mod memory_info; mod stat; mod task; +mod trace; use memory_info::MemoryInfo; use stat::SystemStat; @@ -136,6 +137,7 @@ impl ProcFileSystem { self.root.create_meminfo_file("meminfo")?; self.root.create_stat_file("stat")?; + trace::init_trace_files(&self.root)?; // not support process yet, use thread info instead. and put all threads in /proc let mut global_queue_visitor = GlobalQueueVisitor::new(); @@ -235,43 +237,43 @@ struct ProcDir { } impl ProcDir { - pub fn create_task_file( + pub fn create_proc_file( &self, name: &str, - thread: ThreadNode, + file: T, + mode: InodeMode, + is_dcacheable: bool, ) -> Result, Error> { if name.len() > NAME_MAX { return Err(code::ENAMETOOLONG); } let ino = self.base.fs.upgrade().unwrap().alloc_inode_no(); - let inode = ProcFile::new(ProcTaskFile::new(thread), ino, self.base.fs.clone(), false) + let inode = ProcFile::new(file, ino, self.base.fs.clone(), is_dcacheable, mode) as Arc; self.insert(name, inode.clone()); - Ok(inode) } + pub fn create_task_file( + &self, + name: &str, + thread: ThreadNode, + ) -> Result, Error> { + self.create_proc_file( + name, + ProcTaskFile::new(thread), + InodeMode::from(0o444), + false, + ) + } + pub fn create_meminfo_file(&self, name: &str) -> Result, Error> { - if name.len() > NAME_MAX { - return Err(code::ENAMETOOLONG); - } - let ino = self.base.fs.upgrade().unwrap().alloc_inode_no(); - let inode = - ProcFile::new(MemoryInfo {}, ino, self.base.fs.clone(), true) as Arc; - self.insert(name, inode.clone()); - Ok(inode) + self.create_proc_file(name, MemoryInfo {}, InodeMode::from(0o444), true) } pub fn create_stat_file(&self, name: &str) -> Result, Error> { - if name.len() > NAME_MAX { - return Err(code::ENAMETOOLONG); - } - let ino = self.base.fs.upgrade().unwrap().alloc_inode_no(); - let inode = - ProcFile::new(SystemStat {}, ino, self.base.fs.clone(), true) as Arc; - self.insert(name, inode.clone()); - Ok(inode) + self.create_proc_file(name, SystemStat {}, InodeMode::from(0o444), true) } pub fn create_dir(&self, name: &str, is_dcacheable: bool) -> Result, Error> { @@ -432,13 +434,14 @@ impl ProcFile { inode_no: InodeNo, fs: Weak, is_dcacheable: bool, + mode: InodeMode, ) -> Arc { Arc::new(Self { base: BaseNode { attr: RwLock::new(InodeAttr::new( inode_no, InodeFileType::Regular, - InodeMode::from(0o444), + mode, 0, 0, BLOCK_SIZE, @@ -471,8 +474,14 @@ impl InodeOps for ProcFile { Ok(len) } - fn write_at(&self, _offset: usize, _buf: &[u8], _nonblock: bool) -> Result { - Err(code::EPERM) + fn write_at(&self, offset: usize, buf: &[u8], _nonblock: bool) -> Result { + if !self.mode().is_writable() { + return Err(code::EPERM); + } + if offset != 0 { + return Err(code::EINVAL); + } + self.inner.set_content(buf.to_vec()) } fn resize(&self, _new_size: usize) -> Result<(), Error> { diff --git a/kernel/src/vfs/procfs/trace.rs b/kernel/src/vfs/procfs/trace.rs new file mode 100644 index 00000000..051db7dc --- /dev/null +++ b/kernel/src/vfs/procfs/trace.rs @@ -0,0 +1,329 @@ +// Copyright (c) 2026 vivo Mobile Communication Co., Ltd. +// +// Licensed under the Apache License, Version 2.0 (the "License"); +// you may not use this file except in compliance with the License. +// You may obtain a copy of the License at +// +// http://www.apache.org/licenses/LICENSE-2.0 +// +// Unless required by applicable law or agreed to in writing, software +// distributed under the License is distributed on an "AS IS" BASIS, +// WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. +// See the License for the specific language governing permissions and +// limitations under the License. + +use super::{ProcDir, ProcFileOps}; +use crate::{ + error::{code, Error}, + vfs::inode_mode::InodeMode, +}; +use alloc::{string::String, vec, vec::Vec}; +use core::{fmt::Write, str}; + +const TRACE_HEADER_LEN: usize = 36; +const DROPPED_META_LEN: usize = 8; +const RECORDS_OFFSET: usize = TRACE_HEADER_LEN + DROPPED_META_LEN; +const RECORD_SERIALIZED_LEN: usize = 52; + +pub(super) fn init_trace_files(root: &ProcDir) -> Result<(), Error> { + let trace_dir = root.create_dir("trace", true)?; + trace_dir.create_proc_file("status", TraceStatus, InodeMode::from(0o444), true)?; + trace_dir.create_proc_file("control", TraceControl, InodeMode::from(0o644), true)?; + trace_dir.create_proc_file("stats", TraceStats, InodeMode::from(0o444), true)?; + trace_dir.create_proc_file("dump", TraceDump, InodeMode::from(0o444), true)?; + trace_dir.create_proc_file("raw", TraceRaw, InodeMode::from(0o444), true)?; + Ok(()) +} + +struct TraceStatus; +struct TraceControl; +struct TraceStats; +struct TraceDump; +struct TraceRaw; + +impl ProcFileOps for TraceStatus { + fn get_content(&self) -> Result, Error> { + #[cfg(tracing)] + { + let stats = crate::tracing::stats(); + let mut out = String::new(); + writeln!(&mut out, "Name: trace").ok(); + writeln!( + &mut out, + "State: {}", + if stats.enabled { "running" } else { "stopped" } + ) + .ok(); + writeln!(&mut out, "Compiled: yes").ok(); + writeln!(&mut out, "Total: {}", stats.total_events).ok(); + writeln!(&mut out, "Dropped: {}", stats.dropped_events).ok(); + Ok(out.into_bytes()) + } + #[cfg(not(tracing))] + { + Ok(b"Name: trace\nState: disabled\nCompiled: no\n".to_vec()) + } + } + + fn set_content(&self, _content: Vec) -> Result { + Err(code::EPERM) + } +} + +impl ProcFileOps for TraceControl { + fn get_content(&self) -> Result, Error> { + #[cfg(tracing)] + { + let enabled = crate::tracing::enabled(); + let mut out = String::new(); + writeln!(&mut out, "compiled_in=1").ok(); + writeln!(&mut out, "enabled={}", enabled as u8).ok(); + writeln!(&mut out, "commands=start stop reset").ok(); + Ok(out.into_bytes()) + } + #[cfg(not(tracing))] + { + Ok(b"tracing is disabled in this build\n".to_vec()) + } + } + + fn set_content(&self, content: Vec) -> Result { + let cmd = str::from_utf8(&content) + .map_err(|_| code::EINVAL)? + .trim() + .to_ascii_lowercase(); + if cmd.is_empty() { + return Err(code::EINVAL); + } + + #[cfg(tracing)] + { + match cmd.as_str() { + "start" => { + if !crate::tracing::start(crate::tracing::TraceConfig::default()) { + return Err(code::EBUSY); + } + } + "stop" => { + if !crate::tracing::stop(0) { + return Err(code::EINVAL); + } + } + "reset" => crate::tracing::reset(), + _ => return Err(code::EINVAL), + } + Ok(content.len()) + } + #[cfg(not(tracing))] + { + Err(code::ENOTSUP) + } + } +} + +impl ProcFileOps for TraceStats { + fn get_content(&self) -> Result, Error> { + #[cfg(tracing)] + { + let stats = crate::tracing::stats(); + let mut out = String::new(); + writeln!(&mut out, "compiled_in=1").ok(); + writeln!(&mut out, "enabled={}", stats.enabled as u8).ok(); + writeln!(&mut out, "total_events={}", stats.total_events).ok(); + writeln!(&mut out, "dropped_events={}", stats.dropped_events).ok(); + Ok(out.into_bytes()) + } + #[cfg(not(tracing))] + { + Ok( + b"compiled_in=0\nenabled=0\ntotal_events=0\ndropped_events=0\ntracing is disabled in this build\n" + .to_vec(), + ) + } + } + + fn set_content(&self, _content: Vec) -> Result { + Err(code::EPERM) + } +} + +impl ProcFileOps for TraceDump { + fn get_content(&self) -> Result, Error> { + #[cfg(tracing)] + { + let raw = dump_raw_bytes()?; + decode_dump(&raw) + } + #[cfg(not(tracing))] + { + Ok(b"tracing is disabled in this build\n".to_vec()) + } + } + + fn set_content(&self, _content: Vec) -> Result { + Err(code::EPERM) + } +} + +impl ProcFileOps for TraceRaw { + fn get_content(&self) -> Result, Error> { + #[cfg(tracing)] + { + dump_raw_bytes() + } + #[cfg(not(tracing))] + { + Ok(b"tracing is disabled in this build\n".to_vec()) + } + } + + fn set_content(&self, _content: Vec) -> Result { + Err(code::EPERM) + } +} + +#[cfg(tracing)] +fn dump_raw_bytes() -> Result, Error> { + // Ensure a stable snapshot during export by quiescing writers. + let _ = crate::tracing::stop(0xFFFE); + let max_records = + crate::tracing::buffer::RECORD_CAPACITY * blueos_kconfig::CONFIG_NUM_CORES as usize; + let mut raw = vec![0u8; RECORDS_OFFSET + max_records * RECORD_SERIALIZED_LEN]; + let written = crate::tracing::dump_to_slice(&mut raw); + raw.truncate(written); + Ok(raw) +} + +#[cfg(tracing)] +fn decode_dump(raw: &[u8]) -> Result, Error> { + if raw.len() < RECORDS_OFFSET { + return Ok(b"trace dump is empty\n".to_vec()); + } + if raw[0..4] != *b"BTRC" { + return Err(code::EINVAL); + } + + let dropped = read_u64(raw, TRACE_HEADER_LEN).ok_or(code::EINVAL)?; + let mut out = String::new(); + writeln!(&mut out, "format=BTRC v1 dropped_events={}", dropped).ok(); + writeln!( + &mut out, + "ts_ns,event,event_id,cpu,tid,phase,data0,data1,data2,data3" + ) + .ok(); + + let mut off = RECORDS_OFFSET; + let mut count = 0usize; + while off + RECORD_SERIALIZED_LEN <= raw.len() { + let ts_ns = read_u64(raw, off).ok_or(code::EINVAL)?; + let event_id = read_u16(raw, off + 8).ok_or(code::EINVAL)?; + let cpu_id = read_u16(raw, off + 10).ok_or(code::EINVAL)?; + let tid = read_u32(raw, off + 12).ok_or(code::EINVAL)?; + let phase = raw[off + 16]; + let d0 = read_u64(raw, off + 20).ok_or(code::EINVAL)?; + let d1 = read_u64(raw, off + 28).ok_or(code::EINVAL)?; + let d2 = read_u64(raw, off + 36).ok_or(code::EINVAL)?; + let d3 = read_u64(raw, off + 44).ok_or(code::EINVAL)?; + writeln!( + &mut out, + "{},{},0x{:04x},{},{},{},{},{},{},{}", + ts_ns, + event_name(event_id), + event_id, + cpu_id, + tid, + phase_name(phase), + d0, + d1, + d2, + d3 + ) + .ok(); + off += RECORD_SERIALIZED_LEN; + count += 1; + } + if count == 0 { + writeln!(&mut out, "(no events)").ok(); + } + Ok(out.into_bytes()) +} + +#[cfg(tracing)] +fn event_name(event_id: u16) -> &'static str { + use crate::tracing::event::EventId; + match event_id { + x if x == EventId::TraceStart as u16 => "TraceStart", + x if x == EventId::TraceStop as u16 => "TraceStop", + x if x == EventId::TraceDropped as u16 => "TraceDropped", + x if x == EventId::SchedSwitch as u16 => "SchedSwitch", + x if x == EventId::ThreadCreate as u16 => "ThreadCreate", + x if x == EventId::ThreadExit as u16 => "ThreadExit", + x if x == EventId::ThreadWakeup as u16 => "ThreadWakeup", + x if x == EventId::ThreadBlock as u16 => "ThreadBlock", + x if x == EventId::IrqEnter as u16 => "IrqEnter", + x if x == EventId::IrqExit as u16 => "IrqExit", + x if x == EventId::SysEnter as u16 => "SysEnter", + x if x == EventId::SysExit as u16 => "SysExit", + x if x == EventId::LockWaitBegin as u16 => "LockWaitBegin", + x if x == EventId::LockWaitEnd as u16 => "LockWaitEnd", + x if x == EventId::LockHoldBegin as u16 => "LockHoldBegin", + x if x == EventId::LockHoldEnd as u16 => "LockHoldEnd", + x if x == EventId::MmAlloc as u16 => "MmAlloc", + x if x == EventId::MmFree as u16 => "MmFree", + x if x == EventId::MmAllocFail as u16 => "MmAllocFail", + x if x == EventId::CounterMemUsedBytes as u16 => "CounterMemUsedBytes", + _ => "Unknown", + } +} + +#[cfg(tracing)] +fn phase_name(phase: u8) -> &'static str { + match phase { + 1 => "B", + 2 => "E", + 3 => "I", + 4 => "C", + _ => "?", + } +} + +#[cfg(tracing)] +#[inline] +fn read_u16(buf: &[u8], off: usize) -> Option { + if off + 2 > buf.len() { + return None; + } + Some(u16::from_le_bytes([buf[off], buf[off + 1]])) +} + +#[cfg(tracing)] +#[inline] +fn read_u32(buf: &[u8], off: usize) -> Option { + if off + 4 > buf.len() { + return None; + } + Some(u32::from_le_bytes([ + buf[off], + buf[off + 1], + buf[off + 2], + buf[off + 3], + ])) +} + +#[cfg(tracing)] +#[inline] +fn read_u64(buf: &[u8], off: usize) -> Option { + if off + 8 > buf.len() { + return None; + } + Some(u64::from_le_bytes([ + buf[off], + buf[off + 1], + buf[off + 2], + buf[off + 3], + buf[off + 4], + buf[off + 5], + buf[off + 6], + buf[off + 7], + ])) +} diff --git a/kernel/tests/integration_test.rs b/kernel/tests/integration_test.rs index 3bc3eb96..042068dc 100644 --- a/kernel/tests/integration_test.rs +++ b/kernel/tests/integration_test.rs @@ -29,6 +29,8 @@ mod test_futex; /// Unstable rust custom test framework test file hierarchy. /// Since there is no cargo framework, we manually set it up. mod test_semaphore; +#[cfg(tracing)] +mod test_tracing; #[cfg(enable_vfs)] mod test_vfs; diff --git a/kernel/tests/test_tracing.rs b/kernel/tests/test_tracing.rs new file mode 100644 index 00000000..b137ca50 --- /dev/null +++ b/kernel/tests/test_tracing.rs @@ -0,0 +1,289 @@ +// Copyright (c) 2026 vivo Mobile Communication Co., Ltd. +// +// Licensed under the Apache License, Version 2.0 (the "License"); +// you may not use this file except in compliance with the License. +// You may obtain a copy of the License at +// +// http://www.apache.org/licenses/LICENSE-2.0 +// +// Unless required by applicable law or agreed to in writing, software +// distributed under the License is distributed on an "AS IS" BASIS, +// WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. +// See the License for the specific language governing permissions and +// limitations under the License. + +use blueos::{ + allocator, + tracing::{self, event::EventId, TraceConfig}, +}; +use blueos_test_macro::test; +#[cfg(procfs)] +use core::ffi::c_char; +#[cfg(procfs)] +use libc::{O_RDONLY, O_WRONLY}; +use semihosting::println; +#[cfg(procfs)] +use { + alloc::{string::String, vec::Vec}, + blueos::vfs::syscalls::{close, open, read, write}, +}; + +const TRACE_HEADER_LEN: usize = 36; +const DROPPED_META_LEN: usize = 8; +const RECORDS_OFFSET: usize = TRACE_HEADER_LEN + DROPPED_META_LEN; +const RECORD_SERIALIZED_LEN: usize = 52; + +#[inline] +fn event_id_at(buf: &[u8], event_offset: usize) -> u16 { + let event_id_offset = event_offset + 8; + u16::from_le_bytes([buf[event_id_offset], buf[event_id_offset + 1]]) +} + +fn collect_event_ids(buf: &[u8], len: usize) -> alloc::vec::Vec { + let mut ids = alloc::vec::Vec::new(); + let mut off = RECORDS_OFFSET; + while off + RECORD_SERIALIZED_LEN <= len { + ids.push(event_id_at(buf, off)); + off += RECORD_SERIALIZED_LEN; + } + ids +} + +fn has_event(ids: &[u16], event: EventId) -> bool { + ids.iter().any(|id| *id == event as u16) +} + +#[cfg(procfs)] +fn read_text_file(path: &core::ffi::CStr) -> String { + let fd = open(path.as_ptr() as *const c_char, O_RDONLY, 0); + assert!(fd >= 0, "failed to open {:?}", path); + let mut data = Vec::new(); + let mut buf = [0u8; 512]; + loop { + let n = read(fd, buf.as_mut_ptr(), buf.len()); + assert!(n >= 0, "read failed for {:?}", path); + if n == 0 { + break; + } + data.extend_from_slice(&buf[..n as usize]); + } + assert_eq!(close(fd), 0); + String::from_utf8(data).expect("invalid utf-8") +} + +#[cfg(procfs)] +fn read_raw_file(path: &core::ffi::CStr) -> Vec { + let fd = open(path.as_ptr() as *const c_char, O_RDONLY, 0); + assert!(fd >= 0, "failed to open {:?}", path); + let mut data = Vec::new(); + let mut buf = [0u8; 1024]; + loop { + let n = read(fd, buf.as_mut_ptr(), buf.len()); + assert!(n >= 0, "read failed for {:?}", path); + if n == 0 { + break; + } + data.extend_from_slice(&buf[..n as usize]); + } + assert_eq!(close(fd), 0); + data +} + +#[cfg(procfs)] +fn write_control(cmd: &[u8]) { + let control = c"/proc/trace/control"; + let fd = open(control.as_ptr() as *const c_char, O_WRONLY, 0); + assert!(fd >= 0, "failed to open control"); + let n = write(fd, cmd.as_ptr(), cmd.len()); + assert_eq!(n, cmd.len() as isize, "failed to write command"); + assert_eq!(close(fd), 0); +} + +#[cfg(procfs)] +fn parse_stat(stats: &str, key: &str) -> usize { + for line in stats.lines() { + if let Some(val) = line.strip_prefix(key) { + return val.trim().parse::().expect("invalid stats value"); + } + } + panic!("missing stats key {}", key); +} + +fn event_name(event_id: u16) -> &'static str { + if event_id == EventId::TraceStart as u16 { + "TraceStart" + } else if event_id == EventId::TraceStop as u16 { + "TraceStop" + } else if event_id == EventId::TraceDropped as u16 { + "TraceDropped" + } else if event_id == EventId::SchedSwitch as u16 { + "SchedSwitch" + } else if event_id == EventId::ThreadCreate as u16 { + "ThreadCreate" + } else if event_id == EventId::ThreadExit as u16 { + "ThreadExit" + } else if event_id == EventId::ThreadWakeup as u16 { + "ThreadWakeup" + } else if event_id == EventId::ThreadBlock as u16 { + "ThreadBlock" + } else if event_id == EventId::IrqEnter as u16 { + "IrqEnter" + } else if event_id == EventId::IrqExit as u16 { + "IrqExit" + } else if event_id == EventId::SysEnter as u16 { + "SysEnter" + } else if event_id == EventId::SysExit as u16 { + "SysExit" + } else if event_id == EventId::LockWaitBegin as u16 { + "LockWaitBegin" + } else if event_id == EventId::LockWaitEnd as u16 { + "LockWaitEnd" + } else if event_id == EventId::LockHoldBegin as u16 { + "LockHoldBegin" + } else if event_id == EventId::LockHoldEnd as u16 { + "LockHoldEnd" + } else if event_id == EventId::MmAlloc as u16 { + "MmAlloc" + } else if event_id == EventId::MmFree as u16 { + "MmFree" + } else if event_id == EventId::MmAllocFail as u16 { + "MmAllocFail" + } else if event_id == EventId::CounterMemUsedBytes as u16 { + "CounterMemUsedBytes" + } else { + "Unknown" + } +} + +fn print_events(ids: &[u16]) { + println!("[tracing-test] dumped {} event(s):", ids.len()); + for (idx, id) in ids.iter().enumerate() { + println!( + "[tracing-test] #{:02} {} (0x{:04x})", + idx, + event_name(*id), + id + ); + } +} + +#[test] +fn test_tracing_records_real_system_events() { + // Keep test deterministic across runs. + if tracing::enabled() { + let _ = tracing::stop(0); + } + tracing::init(); + + let initial = tracing::stats(); + assert_eq!(initial.total_events, 0); + assert_eq!(initial.dropped_events, 0); + assert!(!initial.enabled); + + assert!(tracing::start(TraceConfig::default())); + assert!(tracing::enabled()); + assert!(!tracing::start(TraceConfig::default())); + + // Trigger memory alloc/free events from the real allocator path. + let p = allocator::malloc(128); + assert!(!p.is_null()); + allocator::free(p); + + let running = tracing::stats(); + assert!(running.enabled); + assert!( + running.total_events >= 3, + "expected at least TraceStart + 2 probe events, got {}", + running.total_events + ); + + let mut dump = [0u8; 4096]; + let dumped = tracing::dump_to_slice(&mut dump); + assert!(dumped > RECORDS_OFFSET, "dump is too small: {}", dumped); + assert_eq!(&dump[0..4], b"BTRC"); + + let event_ids = collect_event_ids(&dump, dumped); + assert!(!event_ids.is_empty(), "no events found in dump"); + print_events(&event_ids); + assert!( + has_event(&event_ids, EventId::TraceStart), + "TraceStart not found in dump" + ); + assert!( + has_event(&event_ids, EventId::MmAlloc), + "MmAlloc not found in dump" + ); + assert!( + has_event(&event_ids, EventId::MmFree), + "MmFree not found in dump" + ); + + let before_stop_total = running.total_events; + assert!(tracing::stop(0)); + assert!(!tracing::enabled()); + let stopped = tracing::stats(); + assert!(!stopped.enabled); + assert!( + stopped.total_events > before_stop_total, + "TraceStop should be recorded when stopping" + ); + + let stable_total = stopped.total_events; + let p2 = allocator::malloc(64); + assert!(!p2.is_null()); + allocator::free(p2); + let after_stop_probe = tracing::stats(); + assert_eq!(after_stop_probe.total_events, stable_total); +} + +#[cfg(procfs)] +#[test] +fn test_tracing_procfs_control_and_dump() { + write_control(b"reset"); + write_control(b"start"); + + let running_dump = read_text_file(c"/proc/trace/dump"); + assert!( + running_dump.contains("TraceStart"), + "expected TraceStart in running dump, got: {}", + running_dump + ); + assert!( + running_dump.contains("TraceStop"), + "dump should force-stop tracing before snapshot, got: {}", + running_dump + ); + + let p = allocator::malloc(96); + assert!(!p.is_null()); + allocator::free(p); + + let stats = read_text_file(c"/proc/trace/stats"); + println!("[tracing-test] /proc/trace/stats:\n{}", stats); + assert!(stats.contains("enabled=0")); + let total_events = parse_stat(&stats, "total_events="); + assert!( + total_events >= 4, + "unexpected total_events={}", + total_events + ); + + let dump = read_text_file(c"/proc/trace/dump"); + println!("[tracing-test] /proc/trace/dump:\n{}", dump); + assert!(dump.contains("TraceStart")); + assert!(dump.contains("MmAlloc")); + assert!(dump.contains("MmFree")); + assert!(dump.contains("TraceStop")); + + let raw = read_raw_file(c"/proc/trace/raw"); + assert!(raw.len() > RECORDS_OFFSET); + assert_eq!(&raw[0..4], b"BTRC"); + + let stable_before = parse_stat(&stats, "total_events="); + let p2 = allocator::malloc(32); + assert!(!p2.is_null()); + allocator::free(p2); + let stats_after = read_text_file(c"/proc/trace/stats"); + let stable_after = parse_stat(&stats_after, "total_events="); + assert_eq!(stable_before, stable_after); +}