add log info in ch9

os/Cargo.toml

@@ -14,11 +14,12 @@ bitflags = "1.2.1"
 xmas-elf = "0.7.0"
 volatile = "0.3"
 virtio-drivers = { git = "https://github.com/rcore-os/virtio-drivers" }
-k210-pac = { git = "https://github.com/wyfcyx/k210-pac" }
+# k210-pac = { git = "https://github.com/wyfcyx/k210-pac" }
-k210-hal = { git = "https://github.com/wyfcyx/k210-hal" }
+# k210-hal = { git = "https://github.com/wyfcyx/k210-hal" }
-k210-soc = { git = "https://github.com/wyfcyx/k210-soc" }
+# k210-soc = { git = "https://github.com/wyfcyx/k210-soc" }
 easy-fs = { path = "../easy-fs" }
+#log = "0.4"
 
-[features]
+# [features]
-board_qemu = []
+# board_qemu = []
-board_k210 = []
+# board_k210 = []

os/Makefile

@@ -65,7 +65,8 @@ $(APPS):
 kernel:
 	@echo Platform: $(BOARD)
 	@cp src/linker-$(BOARD).ld src/linker.ld
-	@cargo build --release --features "board_$(BOARD)"
+#	@cargo build --release --features "board_$(BOARD)"
+	@cargo build --release
 	@rm src/linker.ld
 
 clean:

os/src/board/mod.rs

@@ -0,0 +1,47 @@
+pub const CLOCK_FREQ: usize = 12500000;
+
+pub const MMIO: &[(usize, usize)] = &[
+    (0x1000_0000, 0x1000),
+    (0x1000_1000, 0x1000),
+    (0xC00_0000, 0x40_0000),
+];
+
+pub type BlockDeviceImpl = crate::drivers::block::VirtIOBlock;
+pub type CharDeviceImpl = crate::drivers::chardev::NS16550a<VIRT_UART>;
+
+pub const VIRT_PLIC: usize = 0xC00_0000;
+pub const VIRT_UART: usize = 0x1000_0000;
+
+use crate::drivers::block::BLOCK_DEVICE;
+use crate::drivers::chardev::{CharDevice, UART};
+use crate::drivers::plic::{IntrTargetPriority, PLIC};
+
+pub fn device_init() {
+    use riscv::register::sie;
+    kprintln!("[KERN] board::qemu::device_init() begin");
+    let mut plic = unsafe { PLIC::new(VIRT_PLIC) };
+    let hart_id: usize = 0;
+    let supervisor = IntrTargetPriority::Supervisor;
+    let machine = IntrTargetPriority::Machine;
+    plic.set_threshold(hart_id, supervisor, 0);
+    plic.set_threshold(hart_id, machine, 1);
+    for intr_src_id in [1usize, 10] {
+        plic.enable(hart_id, supervisor, intr_src_id);
+        plic.set_priority(intr_src_id, 1);
+    }
+    unsafe {
+        sie::set_sext();
+    }
+    kprintln!("[KERN] board::qemu::device_init() end");
+}
+
+pub fn irq_handler() {
+    let mut plic = unsafe { PLIC::new(VIRT_PLIC) };
+    let intr_src_id = plic.claim(0, IntrTargetPriority::Supervisor);
+    match intr_src_id {
+        1 => BLOCK_DEVICE.handle_irq(),
+        10 => UART.handle_irq(),
+        _ => panic!("unsupported IRQ {}", intr_src_id),
+    }
+    plic.complete(0, IntrTargetPriority::Supervisor, intr_src_id);
+}

os/src/board/qemu.rs

@@ -18,6 +18,7 @@ use crate::drivers::plic::{IntrTargetPriority, PLIC};
 
 pub fn device_init() {
     use riscv::register::sie;
+    kprintln!("[KERN] board::qemu::device_init() begin");
     let mut plic = unsafe { PLIC::new(VIRT_PLIC) };
     let hart_id: usize = 0;
     let supervisor = IntrTargetPriority::Supervisor;
@@ -31,6 +32,7 @@ pub fn device_init() {
     unsafe {
         sie::set_sext();
     }
+    kprintln!("[KERN] board::qemu::device_init() end");
 }
 
 pub fn irq_handler() {

os/src/console.rs

@@ -29,3 +29,33 @@ macro_rules! println {
         $crate::console::print(format_args!(concat!($fmt, "\n") $(, $($arg)+)?))
     }
 }
+
+use crate::sbi::console_putchar;
+struct Kstdout;
+
+impl Write for Kstdout {
+    fn write_str(&mut self, s: &str) -> fmt::Result {
+        for c in s.chars() {
+            console_putchar(c as usize);
+        }
+        Ok(())
+    }
+}
+
+pub fn kprint(args: fmt::Arguments) {
+    Kstdout.write_fmt(args).unwrap();
+}
+
+#[macro_export]
+macro_rules! kprint {
+    ($fmt: literal $(, $($arg: tt)+)?) => {
+        $crate::console::kprint(format_args!($fmt $(, $($arg)+)?));
+    }
+}
+
+#[macro_export]
+macro_rules! kprintln {
+    ($fmt: literal $(, $($arg: tt)+)?) => {
+        $crate::console::kprint(format_args!(concat!($fmt, "\n") $(, $($arg)+)?));
+    }
+}

os/src/drivers/block/mod.rs

@@ -1,7 +1,7 @@
-mod sdcard;
+// mod sdcard;
 mod virtio_blk;
 
-pub use sdcard::SDCardWrapper;
+// pub use sdcard::SDCardWrapper;
 pub use virtio_blk::VirtIOBlock;
 
 use crate::board::BlockDeviceImpl;

os/src/fs/inode.rs

@@ -51,11 +51,11 @@ lazy_static! {
 }
 
 pub fn list_apps() {
-    println!("/**** APPS ****");
+    kprintln!("[KERN] fs::inode::list_apps()) begin");
     for app in ROOT_INODE.ls() {
         println!("{}", app);
     }
-    println!("**************/")
+    kprintln!("[KERN] fs::inode::list_apps()) end");
 }
 
 bitflags! {
@@ -83,6 +83,7 @@ impl OpenFlags {
 }
 
 pub fn open_file(name: &str, flags: OpenFlags) -> Option<Arc<OSInode>> {
+    kprintln!("[KERN] fs::inode::open_file() begin");
     let (readable, writable) = flags.read_write();
     if flags.contains(OpenFlags::CREATE) {
         if let Some(inode) = ROOT_INODE.find(name) {
@@ -113,6 +114,7 @@ impl File for OSInode {
         self.writable
     }
     fn read(&self, mut buf: UserBuffer) -> usize {
+        kprintln!("[KERN] fs::inode::read() begin");
         let mut inner = self.inner.exclusive_access();
         let mut total_read_size = 0usize;
         for slice in buf.buffers.iter_mut() {
@@ -123,9 +125,11 @@ impl File for OSInode {
             inner.offset += read_size;
             total_read_size += read_size;
         }
+        kprintln!("[KERN] fs::inode::read() end");
         total_read_size
     }
     fn write(&self, buf: UserBuffer) -> usize {
+        kprintln!("[KERN] fs::inode::write() begin");
         let mut inner = self.inner.exclusive_access();
         let mut total_write_size = 0usize;
         for slice in buf.buffers.iter() {
@@ -134,6 +138,7 @@ impl File for OSInode {
             inner.offset += write_size;
             total_write_size += write_size;
         }
+        kprintln!("[KERN] fs::inode::write() end");
         total_write_size
     }
 }

os/src/main.rs

@@ -8,12 +8,12 @@ extern crate alloc;
 #[macro_use]
 extern crate bitflags;
 
-#[cfg(feature = "board_k210")]
+// #[cfg(feature = "board_k210")]
-#[path = "boards/k210.rs"]
+// #[path = "boards/k210.rs"]
-mod board;
+// mod board;
-#[cfg(not(any(feature = "board_k210")))]
+// #[cfg(not(any(feature = "board_k210")))]
-#[path = "boards/qemu.rs"]
+// #[path = "boards/qemu.rs"]
-mod board;
+
 
 #[macro_use]
 mod console;
@@ -28,6 +28,8 @@ mod syscall;
 mod task;
 mod timer;
 mod trap;
+mod board;
+// use board::*;
 
 core::arch::global_asm!(include_str!("entry.asm"));
 
@@ -36,10 +38,12 @@ fn clear_bss() {
         fn sbss();
         fn ebss();
     }
+    kprintln!("[KERN] clear_bss() begin");
     unsafe {
         core::slice::from_raw_parts_mut(sbss as usize as *mut u8, ebss as usize - sbss as usize)
             .fill(0);
     }
+    kprintln!("[KERN] clear_bss() end");
 }
 
 use lazy_static::*;
@@ -51,6 +55,7 @@ lazy_static! {
 
 #[no_mangle]
 pub fn rust_main() -> ! {
+    kprintln!("[KERN] rust_main() begin");
     clear_bss();
     mm::init();
     trap::init();
@@ -61,5 +66,5 @@ pub fn rust_main() -> ! {
     task::add_initproc();
     *DEV_NON_BLOCKING_ACCESS.exclusive_access() = true;
     task::run_tasks();
-    panic!("Unreachable in rust_main!");
+    panic!("[KERN] Unreachable in rust_main!");
 }

os/src/mm/frame_allocator.rs

@@ -48,7 +48,7 @@ impl StackFrameAllocator {
     pub fn init(&mut self, l: PhysPageNum, r: PhysPageNum) {
         self.current = l.0;
         self.end = r.0;
-        println!("last {} Physical Frames.", self.end - self.current);
+        println!("[KERN] last {} Physical Frames.", self.end - self.current);
     }
 }
 impl FrameAllocator for StackFrameAllocator {
@@ -73,7 +73,7 @@ impl FrameAllocator for StackFrameAllocator {
         let ppn = ppn.0;
         // validity check
         if ppn >= self.current || self.recycled.iter().any(|&v| v == ppn) {
-            panic!("Frame ppn={:#x} has not been allocated!", ppn);
+            panic!("[KERN] Frame ppn={:#x} has not been allocated!", ppn);
         }
         // recycle
         self.recycled.push(ppn);
@@ -91,10 +91,12 @@ pub fn init_frame_allocator() {
     extern "C" {
         fn ekernel();
     }
+    kprintln!("[KERN] mm::init_frame_allocator() begin");
     FRAME_ALLOCATOR.exclusive_access().init(
         PhysAddr::from(ekernel as usize).ceil(),
         PhysAddr::from(MEMORY_END).floor(),
     );
+    kprintln!("[KERN] mm::init_frame_allocator() end");
 }
 
 pub fn frame_alloc() -> Option<FrameTracker> {

os/src/mm/heap_allocator.rs

@@ -6,17 +6,19 @@ static HEAP_ALLOCATOR: LockedHeap = LockedHeap::empty();
 
 #[alloc_error_handler]
 pub fn handle_alloc_error(layout: core::alloc::Layout) -> ! {
-    panic!("Heap allocation error, layout = {:?}", layout);
+    panic!("[KERN] Heap allocation error, layout = {:?}", layout);
 }
 
 static mut HEAP_SPACE: [u8; KERNEL_HEAP_SIZE] = [0; KERNEL_HEAP_SIZE];
 
 pub fn init_heap() {
+    kprintln!("[KERN] mm::init_heap() begin");
     unsafe {
         HEAP_ALLOCATOR
             .lock()
             .init(HEAP_SPACE.as_ptr() as usize, KERNEL_HEAP_SIZE);
     }
+    kprintln!("[KERN] mm::init_heap() end");
 }
 
 #[allow(unused)]

os/src/mm/memory_set.rs

@@ -88,18 +88,19 @@ impl MemorySet {
     }
     /// Without kernel stacks.
     pub fn new_kernel() -> Self {
+        kprintln!("[KERN] mm::memory_set::MemorySet::new_kernel() begin");
         let mut memory_set = Self::new_bare();
         // map trampoline
         memory_set.map_trampoline();
         // map kernel sections
-        println!(".text [{:#x}, {:#x})", stext as usize, etext as usize);
+        println!("[KERN] .text [{:#x}, {:#x})", stext as usize, etext as usize);
-        println!(".rodata [{:#x}, {:#x})", srodata as usize, erodata as usize);
+        println!("[KERN] .rodata [{:#x}, {:#x})", srodata as usize, erodata as usize);
-        println!(".data [{:#x}, {:#x})", sdata as usize, edata as usize);
+        println!("[KERN] .data [{:#x}, {:#x})", sdata as usize, edata as usize);
         println!(
-            ".bss [{:#x}, {:#x})",
+            "[KERN] .bss [{:#x}, {:#x})",
             sbss_with_stack as usize, ebss as usize
         );
-        println!("mapping .text section");
+        println!("[KERN] mapping .text section");
         memory_set.push(
             MapArea::new(
                 (stext as usize).into(),
@@ -109,7 +110,7 @@ impl MemorySet {
             ),
             None,
         );
-        println!("mapping .rodata section");
+        println!("[KERN] mapping .rodata section");
         memory_set.push(
             MapArea::new(
                 (srodata as usize).into(),
@@ -119,7 +120,7 @@ impl MemorySet {
             ),
             None,
         );
-        println!("mapping .data section");
+        println!("[KERN] mapping .data section");
         memory_set.push(
             MapArea::new(
                 (sdata as usize).into(),
@@ -129,7 +130,7 @@ impl MemorySet {
             ),
             None,
         );
-        println!("mapping .bss section");
+        println!("[KERN] mapping .bss section");
         memory_set.push(
             MapArea::new(
                 (sbss_with_stack as usize).into(),
@@ -139,7 +140,7 @@ impl MemorySet {
             ),
             None,
         );
-        println!("mapping physical memory");
+        println!("[KERN] mapping physical memory");
         memory_set.push(
             MapArea::new(
                 (ekernel as usize).into(),
@@ -149,7 +150,7 @@ impl MemorySet {
             ),
             None,
         );
-        println!("mapping memory-mapped registers");
+        println!("[KERN] mapping memory-mapped registers");
         for pair in MMIO {
             memory_set.push(
                 MapArea::new(
@@ -161,11 +162,13 @@ impl MemorySet {
                 None,
             );
         }
+        kprintln!("[KERN] mm::memory_set::MemorySet::new_kernel() end");
         memory_set
     }
     /// Include sections in elf and trampoline,
     /// also returns user_sp_base and entry point.
     pub fn from_elf(elf_data: &[u8]) -> (Self, usize, usize) {
+        kprintln!("[KERN] mm::memory_set::MemorySet::from_elf() begin");
         let mut memory_set = Self::new_bare();
         // map trampoline
         memory_set.map_trampoline();
@@ -203,6 +206,7 @@ impl MemorySet {
         let max_end_va: VirtAddr = max_end_vpn.into();
         let mut user_stack_base: usize = max_end_va.into();
         user_stack_base += PAGE_SIZE;
+        kprintln!("[KERN] mm::memory_set::MemorySet::from_elf() end");
         (
             memory_set,
             user_stack_base,
@@ -210,6 +214,7 @@ impl MemorySet {
         )
     }
     pub fn from_existed_user(user_space: &MemorySet) -> MemorySet {
+        kprintln!("[KERN] mm::memory_set::MemorySet::from_existed_user() begin");
         let mut memory_set = Self::new_bare();
         // map trampoline
         memory_set.map_trampoline();
@@ -226,14 +231,17 @@ impl MemorySet {
                     .copy_from_slice(src_ppn.get_bytes_array());
             }
         }
+        kprintln!("[KERN] mm::memory_set::MemorySet::from_existed_user() end");
         memory_set
     }
     pub fn activate(&self) {
+        kprintln!("[KERN] mm::memory_set::MemorySet::activate() begin");
         let satp = self.page_table.token();
         unsafe {
             satp::write(satp);
             asm!("sfence.vma");
         }
+        kprintln!("[KERN] mm::memory_set::MemorySet::activate() begin");
     }
     pub fn translate(&self, vpn: VirtPageNum) -> Option<PageTableEntry> {
         self.page_table.translate(vpn)
@@ -258,8 +266,10 @@ impl MapArea {
         map_type: MapType,
         map_perm: MapPermission,
     ) -> Self {
+        kprintln!("[KERN] mm::memory_set::MapArea::new() begin");
         let start_vpn: VirtPageNum = start_va.floor();
         let end_vpn: VirtPageNum = end_va.ceil();
+        kprintln!("[KERN] mm::memory_set::MapArea::new(start_vpn: {:?}, end_vpn: {:?}) end", start_vpn, end_vpn);
         Self {
             vpn_range: VPNRange::new(start_vpn, end_vpn),
             data_frames: BTreeMap::new(),
@@ -297,18 +307,23 @@ impl MapArea {
         page_table.unmap(vpn);
     }
     pub fn map(&mut self, page_table: &mut PageTable) {
+        kprintln!("[KERN] mm::memory_set::MapArea::map() begin");
         for vpn in self.vpn_range {
             self.map_one(page_table, vpn);
         }
+        kprintln!("[KERN] mm::memory_set::MapArea::map() end");
     }
     pub fn unmap(&mut self, page_table: &mut PageTable) {
+        kprintln!("[KERN] mm::memory_set::MapArea::unmap() begin");
         for vpn in self.vpn_range {
             self.unmap_one(page_table, vpn);
         }
+        kprintln!("[KERN] mm::memory_set::MapArea::unmap() end");
     }
     /// data: start-aligned but maybe with shorter length
     /// assume that all frames were cleared before
     pub fn copy_data(&mut self, page_table: &mut PageTable, data: &[u8]) {
+        kprintln!("[KERN] mm::memory_set::MapArea::copy_data() begin");
         assert_eq!(self.map_type, MapType::Framed);
         let mut start: usize = 0;
         let mut current_vpn = self.vpn_range.get_start();
@@ -327,6 +342,7 @@ impl MapArea {
             }
             current_vpn.step();
         }
+        kprintln!("[KERN] mm::memory_set::MapArea::copy_data() end");
     }
 }
 

os/src/mm/mod.rs

@@ -16,7 +16,9 @@ pub use page_table::{
 };
 
 pub fn init() {
+    kprintln!("[KERN] mm::init() begin");
     heap_allocator::init_heap();
     frame_allocator::init_frame_allocator();
     KERNEL_SPACE.exclusive_access().activate();
+    kprintln!("[KERN] mm::init() end");
 }

os/src/syscall/fs.rs

@@ -4,6 +4,9 @@ use crate::task::{current_process, current_user_token};
 use alloc::sync::Arc;
 
 pub fn sys_write(fd: usize, buf: *const u8, len: usize) -> isize {
+    if fd!=1 && fd!=2 {
+        kprintln!("[KERN] syscall::fs::sys_write(fd: {}) begin", fd);
+       }
     let token = current_user_token();
     let process = current_process();
     let inner = process.inner_exclusive_access();
@@ -24,6 +27,9 @@ pub fn sys_write(fd: usize, buf: *const u8, len: usize) -> isize {
 }
 
 pub fn sys_read(fd: usize, buf: *const u8, len: usize) -> isize {
+    if fd!=0 {
+     kprintln!("[KERN] syscall::fs::sys_read(fd: {}) begin", fd);
+    }
     let token = current_user_token();
     let process = current_process();
     let inner = process.inner_exclusive_access();
@@ -44,6 +50,7 @@ pub fn sys_read(fd: usize, buf: *const u8, len: usize) -> isize {
 }
 
 pub fn sys_open(path: *const u8, flags: u32) -> isize {
+    kprintln!("[KERN] syscall::fs::sys_open() begin");
     let process = current_process();
     let token = current_user_token();
     let path = translated_str(token, path);
@@ -51,6 +58,7 @@ pub fn sys_open(path: *const u8, flags: u32) -> isize {
         let mut inner = process.inner_exclusive_access();
         let fd = inner.alloc_fd();
         inner.fd_table[fd] = Some(inode);
+        kprintln!("[KERN] syscall::fs::sys_open() return fd {}, end",fd);
         fd as isize
     } else {
         -1
@@ -58,6 +66,7 @@ pub fn sys_open(path: *const u8, flags: u32) -> isize {
 }
 
 pub fn sys_close(fd: usize) -> isize {
+    kprintln!("[KERN] syscall::fs::sys_close(fd: {}) begin",fd);
     let process = current_process();
     let mut inner = process.inner_exclusive_access();
     if fd >= inner.fd_table.len() {
@@ -71,6 +80,7 @@ pub fn sys_close(fd: usize) -> isize {
 }
 
 pub fn sys_pipe(pipe: *mut usize) -> isize {
+    kprintln!("[KERN] syscall::fs::sys_pipe() begin");
     let process = current_process();
     let token = current_user_token();
     let mut inner = process.inner_exclusive_access();
@@ -85,6 +95,7 @@ pub fn sys_pipe(pipe: *mut usize) -> isize {
 }
 
 pub fn sys_dup(fd: usize) -> isize {
+    kprintln!("[KERN] syscall::fs::sys_dup(fd: {}) begin", fd);
     let process = current_process();
     let mut inner = process.inner_exclusive_access();
     if fd >= inner.fd_table.len() {

os/src/syscall/mod.rs

@@ -37,6 +37,12 @@ use sync::*;
 use thread::*;
 
 pub fn syscall(syscall_id: usize, args: [usize; 3]) -> isize {
+    if syscall_id !=SYSCALL_YIELD && 
+       syscall_id !=SYSCALL_WAITPID &&
+       !(syscall_id ==SYSCALL_READ && args[0] == 0) &&
+       !(syscall_id ==SYSCALL_WRITE && (args[0] == 1|| args[0] == 2)) {
+        kprintln!("[KERN] syscall::syscall(id: {}) begin", sys_id_str(syscall_id));
+    }
     match syscall_id {
         SYSCALL_DUP => sys_dup(args[0]),
         SYSCALL_OPEN => sys_open(args[0] as *const u8, args[1] as u32),
@@ -68,3 +74,36 @@ pub fn syscall(syscall_id: usize, args: [usize; 3]) -> isize {
         _ => panic!("Unsupported syscall_id: {}", syscall_id),
     }
 }
+
+pub fn sys_id_str(syscall_id: usize) -> &'static str {
+    match syscall_id {
+        SYSCALL_DUP => "sys_dup",
+        SYSCALL_OPEN => "sys_open",
+        SYSCALL_CLOSE => "sys_close",
+        SYSCALL_PIPE => "sys_pipe",
+        SYSCALL_READ => "sys_read",
+        SYSCALL_WRITE => "sys_write",
+        SYSCALL_EXIT => "sys_exit",
+        SYSCALL_SLEEP => "sys_sleep",
+        SYSCALL_YIELD => "sys_yield",
+        SYSCALL_KILL => "sys_kill",
+        SYSCALL_GET_TIME => "sys_get_time",
+        SYSCALL_GETPID => "sys_getpid",
+        SYSCALL_FORK => "sys_fork",
+        SYSCALL_EXEC => "sys_exec",
+        SYSCALL_WAITPID => "sys_waitpid",
+        SYSCALL_THREAD_CREATE => "sys_thread_create",
+        SYSCALL_GETTID => "sys_gettid",
+        SYSCALL_WAITTID => "sys_waittid",
+        SYSCALL_MUTEX_CREATE => "sys_mutex_create",
+        SYSCALL_MUTEX_LOCK => "sys_mutex_lock",
+        SYSCALL_MUTEX_UNLOCK => "sys_mutex_unlock",
+        SYSCALL_SEMAPHORE_CREATE => "sys_semaphore_create",
+        SYSCALL_SEMAPHORE_UP => "sys_semaphore_up",
+        SYSCALL_SEMAPHORE_DOWN => "sys_semaphore_down",
+        SYSCALL_CONDVAR_CREATE => "sys_condvar_create",
+        SYSCALL_CONDVAR_SIGNAL => "sys_condvar_signal",
+        SYSCALL_CONDVAR_WAIT => "sys_condvar_wait",
+        _ => "Unsupported syscall_id",
+    }
+}

os/src/syscall/process.rs

@@ -10,6 +10,7 @@ use alloc::sync::Arc;
 use alloc::vec::Vec;
 
 pub fn sys_exit(exit_code: i32) -> ! {
+    kprintln!("[KERN] syscall::process::sys_exit begin");
     exit_current_and_run_next(exit_code);
     panic!("Unreachable in sys_exit!");
 }
@@ -20,14 +21,17 @@ pub fn sys_yield() -> isize {
 }
 
 pub fn sys_get_time() -> isize {
+    kprintln!("[KERN] syscall::process::sys_get_time begin");
     get_time_ms() as isize
 }
 
 pub fn sys_getpid() -> isize {
+    kprintln!("[KERN] syscall::process::sys_getpid begin");
     current_task().unwrap().process.upgrade().unwrap().getpid() as isize
 }
 
 pub fn sys_fork() -> isize {
+    kprintln!("[KERN] syscall::process::sys_fork begin");
     let current_process = current_process();
     let new_process = current_process.fork();
     let new_pid = new_process.getpid();
@@ -38,10 +42,12 @@ pub fn sys_fork() -> isize {
     // we do not have to move to next instruction since we have done it before
     // for child process, fork returns 0
     trap_cx.x[10] = 0;
+    kprintln!("[KERN] syscall::process::sys_fork end");
     new_pid as isize
 }
 
 pub fn sys_exec(path: *const u8, mut args: *const usize) -> isize {
+    kprintln!("[KERN] syscall::process::sys_exec begin");
     let token = current_user_token();
     let path = translated_str(token, path);
     let mut args_vec: Vec<String> = Vec::new();
@@ -60,6 +66,7 @@ pub fn sys_exec(path: *const u8, mut args: *const usize) -> isize {
         let process = current_process();
         let argc = args_vec.len();
         process.exec(all_data.as_slice(), args_vec);
+        kprintln!("[KERN] syscall::process::sys_exec end");
         // return argc because cx.x[10] will be covered with it later
         argc as isize
     } else {
@@ -70,6 +77,7 @@ pub fn sys_exec(path: *const u8, mut args: *const usize) -> isize {
 /// If there is not a child process whose pid is same as given, return -1.
 /// Else if there is a child process but it is still running, return -2.
 pub fn sys_waitpid(pid: isize, exit_code_ptr: *mut i32) -> isize {
+    //kprintln!("[KERN] syscall::process::sys_waitpid begin");
     let process = current_process();
     // find a child process
 
@@ -104,6 +112,7 @@ pub fn sys_waitpid(pid: isize, exit_code_ptr: *mut i32) -> isize {
 }
 
 pub fn sys_kill(pid: usize, signal: u32) -> isize {
+    kprintln!("[KERN] syscall::process::sys_kill begin");
     if let Some(process) = pid2process(pid) {
         if let Some(flag) = SignalFlags::from_bits(signal) {
             process.inner_exclusive_access().signals |= flag;

os/src/syscall/sync.rs

@@ -4,14 +4,17 @@ use crate::timer::{add_timer, get_time_ms};
 use alloc::sync::Arc;
 
 pub fn sys_sleep(ms: usize) -> isize {
+    kprintln!("[KERN] syscall::sync::sys_sleep begin");
     let expire_ms = get_time_ms() + ms;
     let task = current_task().unwrap();
     add_timer(expire_ms, task);
     block_current_and_run_next();
+    kprintln!("[KERN] syscall::sync::sys_sleep end");
     0
 }
 
 pub fn sys_mutex_create(blocking: bool) -> isize {
+    kprintln!("[KERN] syscall::sync::sys_mutex_create begin");
     let process = current_process();
     let mutex: Option<Arc<dyn Mutex>> = if !blocking {
         Some(Arc::new(MutexSpin::new()))
@@ -35,6 +38,7 @@ pub fn sys_mutex_create(blocking: bool) -> isize {
 }
 
 pub fn sys_mutex_lock(mutex_id: usize) -> isize {
+    kprintln!("[KERN] syscall::sync::sys_mutex_lock begin");
     let process = current_process();
     let process_inner = process.inner_exclusive_access();
     let mutex = Arc::clone(process_inner.mutex_list[mutex_id].as_ref().unwrap());
@@ -45,6 +49,7 @@ pub fn sys_mutex_lock(mutex_id: usize) -> isize {
 }
 
 pub fn sys_mutex_unlock(mutex_id: usize) -> isize {
+    kprintln!("[KERN] syscall::sync::sys_mutex_unlock begin");
     let process = current_process();
     let process_inner = process.inner_exclusive_access();
     let mutex = Arc::clone(process_inner.mutex_list[mutex_id].as_ref().unwrap());
@@ -55,6 +60,7 @@ pub fn sys_mutex_unlock(mutex_id: usize) -> isize {
 }
 
 pub fn sys_semaphore_create(res_count: usize) -> isize {
+    kprintln!("[KERN] syscall::sync::sys_semaphore_create begin");
     let process = current_process();
     let mut process_inner = process.inner_exclusive_access();
     let id = if let Some(id) = process_inner
@@ -76,6 +82,7 @@ pub fn sys_semaphore_create(res_count: usize) -> isize {
 }
 
 pub fn sys_semaphore_up(sem_id: usize) -> isize {
+    kprintln!("[KERN] syscall::sync::sys_semaphore_up begin");
     let process = current_process();
     let process_inner = process.inner_exclusive_access();
     let sem = Arc::clone(process_inner.semaphore_list[sem_id].as_ref().unwrap());
@@ -85,6 +92,7 @@ pub fn sys_semaphore_up(sem_id: usize) -> isize {
 }
 
 pub fn sys_semaphore_down(sem_id: usize) -> isize {
+    kprintln!("[KERN] syscall::sync::sys_semaphore_down begin");
     let process = current_process();
     let process_inner = process.inner_exclusive_access();
     let sem = Arc::clone(process_inner.semaphore_list[sem_id].as_ref().unwrap());
@@ -94,6 +102,7 @@ pub fn sys_semaphore_down(sem_id: usize) -> isize {
 }
 
 pub fn sys_condvar_create(_arg: usize) -> isize {
+    kprintln!("[KERN] syscall::sync::sys_condvar_create begin");
     let process = current_process();
     let mut process_inner = process.inner_exclusive_access();
     let id = if let Some(id) = process_inner
@@ -115,6 +124,7 @@ pub fn sys_condvar_create(_arg: usize) -> isize {
 }
 
 pub fn sys_condvar_signal(condvar_id: usize) -> isize {
+    kprintln!("[KERN] syscall::sync::sys_condvar_signal begin");
     let process = current_process();
     let process_inner = process.inner_exclusive_access();
     let condvar = Arc::clone(process_inner.condvar_list[condvar_id].as_ref().unwrap());
@@ -124,6 +134,7 @@ pub fn sys_condvar_signal(condvar_id: usize) -> isize {
 }
 
 pub fn sys_condvar_wait(condvar_id: usize, mutex_id: usize) -> isize {
+    kprintln!("[KERN] syscall::sync::sys_condvar_wait begin");
     let process = current_process();
     let process_inner = process.inner_exclusive_access();
     let condvar = Arc::clone(process_inner.condvar_list[condvar_id].as_ref().unwrap());

os/src/syscall/thread.rs

@@ -6,6 +6,7 @@ use crate::{
 use alloc::sync::Arc;
 
 pub fn sys_thread_create(entry: usize, arg: usize) -> isize {
+    kprintln!("[KERN] syscall::thread::sys_thread_create begin");
     let task = current_task().unwrap();
     let process = task.process.upgrade().unwrap();
     // create a new thread
@@ -39,10 +40,12 @@ pub fn sys_thread_create(entry: usize, arg: usize) -> isize {
         trap_handler as usize,
     );
     (*new_task_trap_cx).x[10] = arg;
+    kprintln!("[KERN] syscall::thread::sys_thread_create end");
     new_task_tid as isize
 }
 
 pub fn sys_gettid() -> isize {
+    kprintln!("[KERN] syscall::thread::sys_gettid begin");
     current_task()
         .unwrap()
         .inner_exclusive_access()
@@ -56,6 +59,7 @@ pub fn sys_gettid() -> isize {
 /// thread has not exited yet, return -2
 /// otherwise, return thread's exit code
 pub fn sys_waittid(tid: usize) -> i32 {
+    kprintln!("[KERN] syscall::thread::sys_waittid begin");
     let task = current_task().unwrap();
     let process = task.process.upgrade().unwrap();
     let task_inner = task.inner_exclusive_access();

os/src/task/manager.rs

@@ -31,10 +31,13 @@ lazy_static! {
 }
 
 pub fn add_task(task: Arc<TaskControlBlock>) {
+    //kprintln!("[KERN] task::manager::add_task() begin");
     TASK_MANAGER.exclusive_access().add(task);
+    //kprintln!("[KERN] task::manager::add_task() end");
 }
 
 pub fn fetch_task() -> Option<Arc<TaskControlBlock>> {
+    //kprintln!("[KERN] task::manager::fetch_task() begin");
     TASK_MANAGER.exclusive_access().fetch()
 }
 

os/src/task/mod.rs

@@ -27,6 +27,7 @@ pub use task::{TaskControlBlock, TaskStatus};
 
 pub fn suspend_current_and_run_next() {
     // There must be an application running.
+    //kprintln!("[KERN] task::suspend_current_and_run_next() begin");
     let task = take_current_task().unwrap();
 
     // ---- access current TCB exclusively
@@ -40,14 +41,17 @@ pub fn suspend_current_and_run_next() {
     // push back to ready queue.
     add_task(task);
     // jump to scheduling cycle
+    //kprintln!("[KERN] task::suspend_current_and_run_next() end");
     schedule(task_cx_ptr);
 }
 
 /// This function must be followed by a schedule
 pub fn block_current_task() -> *mut TaskContext {
+    //kprintln!("[KERN] task::block_current_task() begin");
     let task = take_current_task().unwrap();
     let mut task_inner = task.inner_exclusive_access();
     task_inner.task_status = TaskStatus::Blocking;
+    //kprintln!("[KERN] task::block_current_task() end");
     &mut task_inner.task_cx as *mut TaskContext
 }
 
@@ -57,6 +61,7 @@ pub fn block_current_and_run_next() {
 }
 
 pub fn exit_current_and_run_next(exit_code: i32) {
+    kprintln!("[KERN] task::exit_current_and_run_next() begin");
     let task = take_current_task().unwrap();
     let mut task_inner = task.inner_exclusive_access();
     let process = task.process.upgrade().unwrap();
@@ -105,11 +110,13 @@ pub fn exit_current_and_run_next(exit_code: i32) {
     drop(process);
     // we do not have to save task context
     let mut _unused = TaskContext::zero_init();
+    kprintln!("[KERN] task::exit_current_and_run_next() end");
     schedule(&mut _unused as *mut _);
 }
 
 lazy_static! {
     pub static ref INITPROC: Arc<ProcessControlBlock> = {
+        kprintln!("[KERN] task::lazy_static!INITPROC begin");
         let inode = open_file("initproc", OpenFlags::RDONLY).unwrap();
         let v = inode.read_all();
         ProcessControlBlock::new(v.as_slice())
@@ -117,7 +124,9 @@ lazy_static! {
 }
 
 pub fn add_initproc() {
+    kprintln!("[KERN] task::add_initproc() begin");
     let _initproc = INITPROC.clone();
+    kprintln!("[KERN] task::add_initproc() end");
 }
 
 pub fn check_signals_of_current() -> Option<(i32, &'static str)> {

os/src/task/process.rs

@@ -73,6 +73,7 @@ impl ProcessControlBlock {
 
     pub fn new(elf_data: &[u8]) -> Arc<Self> {
         // memory_set with elf program headers/trampoline/trap context/user stack
+        kprintln!("[KERN] task::process::new() begin");
         let (memory_set, ustack_base, entry_point) = MemorySet::from_elf(elf_data);
         // allocate a pid
         let pid_handle = pid_alloc();
@@ -128,6 +129,7 @@ impl ProcessControlBlock {
         insert_into_pid2process(process.getpid(), Arc::clone(&process));
         // add main thread to scheduler
         add_task(task);
+        kprintln!("[KERN] task::process::new() end");
         process
     }
 
@@ -135,6 +137,7 @@ impl ProcessControlBlock {
     pub fn exec(self: &Arc<Self>, elf_data: &[u8], args: Vec<String>) {
         assert_eq!(self.inner_exclusive_access().thread_count(), 1);
         // memory_set with elf program headers/trampoline/trap context/user stack
+        kprintln!("[KERN] task::process::exec() begin");
         let (memory_set, ustack_base, entry_point) = MemorySet::from_elf(elf_data);
         let new_token = memory_set.token();
         // substitute memory_set
@@ -182,10 +185,12 @@ impl ProcessControlBlock {
         trap_cx.x[10] = args.len();
         trap_cx.x[11] = argv_base;
         *task_inner.get_trap_cx() = trap_cx;
+        kprintln!("[KERN] task::process::exec() end");
     }
 
     /// Only support processes with a single thread.
     pub fn fork(self: &Arc<Self>) -> Arc<Self> {
+        kprintln!("[KERN] task::process::fork() begin");
         let mut parent = self.inner_exclusive_access();
         assert_eq!(parent.thread_count(), 1);
         // clone parent's memory_set completely including trampoline/ustacks/trap_cxs
@@ -249,6 +254,7 @@ impl ProcessControlBlock {
         insert_into_pid2process(child.getpid(), Arc::clone(&child));
         // add this thread to scheduler
         add_task(task);
+        kprintln!("[KERN] task::process::fork() end");
         child
     }
 

os/src/task/processor.rs

@@ -34,6 +34,7 @@ lazy_static! {
 }
 
 pub fn run_tasks() {
+    kprintln!("[KERN] task::processor::run_tasks() begin");
     loop {
         let mut processor = PROCESSOR.exclusive_access();
         if let Some(task) = fetch_task() {

os/src/task/task.rs

@@ -49,10 +49,12 @@ impl TaskControlBlock {
         ustack_base: usize,
         alloc_user_res: bool,
     ) -> Self {
+        kprintln!("[KERN] TaskControlBlock::new() begin");
         let res = TaskUserRes::new(Arc::clone(&process), ustack_base, alloc_user_res);
         let trap_cx_ppn = res.trap_cx_ppn();
         let kstack = kstack_alloc();
         let kstack_top = kstack.get_top();
+        kprintln!("[KERN] TaskControlBlock::new() end");
         Self {
             process: Arc::downgrade(&process),
             kstack,

os/src/timer.rs

@@ -21,7 +21,9 @@ pub fn get_time_ms() -> usize {
 }
 
 pub fn set_next_trigger() {
+    //kprintln!("[KERN] timer::set_next_trigger() begin");
     set_timer(get_time() + CLOCK_FREQ / TICKS_PER_SEC);
+    //kprintln!("[KERN] timer::set_next_trigger() end");
 }
 
 pub struct TimerCondVar {

os/src/trap/context.rs

@@ -22,6 +22,7 @@ impl TrapContext {
         kernel_sp: usize,
         trap_handler: usize,
     ) -> Self {
+        kprintln!("[KERN] trap::context::TrapContext::app_init_context begin");
         let mut sstatus = sstatus::read();
         // set CPU privilege to User after trapping back
         sstatus.set_spp(SPP::User);
@@ -34,6 +35,7 @@ impl TrapContext {
             trap_handler,
         };
         cx.set_sp(sp);
+        kprintln!("[KERN] trap::context::TrapContext::app_init_context end");
         cx
     }
 }

os/src/trap/mod.rs

@@ -17,7 +17,9 @@ use riscv::register::{
 global_asm!(include_str!("trap.S"));
 
 pub fn init() {
+    kprintln!("[KERN] trap::init() begin");
     set_kernel_trap_entry();
+    kprintln!("[KERN] trap::init() end");
 }
 
 fn set_kernel_trap_entry() {
@@ -39,9 +41,11 @@ fn set_user_trap_entry() {
 }
 
 pub fn enable_timer_interrupt() {
+    kprintln!("[KERN] trap::enable_timer_interrupt() begin");
     unsafe {
         sie::set_stimer();
     }
+    kprintln!("[KERN] trap::enable_timer_interrupt() end");
 }
 
 fn enable_supervisor_interrupt() {