Merge pull request #1796 from hermit-os/logger-format

feat(logging): print time and target

Author: mkroening

Cargo.toml

@@ -55,6 +55,7 @@ fsgsbase = []
 fuse = ["pci", "dep:fuse-abi", "fuse-abi/num_enum"]
 gem-net = ["tcp", "dep:tock-registers"]
 idle-poll = []
+log-target = []
 mmap = []
 newlib = []
 nostd = []

src/arch/aarch64/kernel/mod.rs

@@ -151,6 +151,7 @@ pub fn boot_processor_init() {
 	env::init();
 	interrupts::init();
 	processor::detect_frequency();
+	crate::logging::KERNEL_LOGGER.set_time(true);
 	processor::print_information();
 	systemtime::init();
 	#[cfg(feature = "pci")]

src/arch/riscv64/kernel/start.rs

@@ -50,6 +50,8 @@ unsafe extern "C" fn pre_init(hart_id: usize, boot_info: Option<&'static RawBoot
 	CURRENT_BOOT_ID.store(hart_id as u32, Ordering::Relaxed);
 
 	if CPU_ONLINE.load(Ordering::Acquire) == 0 {
+		crate::logging::KERNEL_LOGGER.set_time(true);
+
 		env::set_boot_info(*boot_info.unwrap());
 		let fdt = unsafe { Fdt::from_ptr(get_dtb_ptr()).expect("FDT is invalid") };
 		// Init HART_MASK

src/arch/x86_64/kernel/mod.rs

@@ -154,6 +154,7 @@ pub fn boot_processor_init() {
 	crate::mm::print_information();
 	CoreLocal::get().add_irq_counter();
 	env::init();
+	crate::logging::KERNEL_LOGGER.set_time(true);
 	gdt::add_current_core();
 	interrupts::load_idt();
 	pic::init();

src/logging.rs

@@ -1,10 +1,31 @@
 use core::fmt;
+use core::sync::atomic::{AtomicBool, Ordering};
 
 use anstyle::AnsiColor;
 use log::{Level, LevelFilter, Metadata, Record};
 
+pub static KERNEL_LOGGER: KernelLogger = KernelLogger::new();
+
 /// Data structure to filter kernel messages
-struct KernelLogger;
+pub struct KernelLogger {
+	time: AtomicBool,
+}
+
+impl KernelLogger {
+	pub const fn new() -> Self {
+		Self {
+			time: AtomicBool::new(false),
+		}
+	}
+
+	pub fn time(&self) -> bool {
+		self.time.load(Ordering::Relaxed)
+	}
+
+	pub fn set_time(&self, time: bool) {
+		self.time.store(time, Ordering::Relaxed);
+	}
+}
 
 impl log::Log for KernelLogger {
 	fn enabled(&self, _: &Metadata<'_>) -> bool {
@@ -16,14 +37,39 @@ impl log::Log for KernelLogger {
 	}
 
 	fn log(&self, record: &Record<'_>) {
-		if self.enabled(record.metadata()) {
-			println!(
-				"[{}][{}] {}",
-				crate::arch::core_local::core_id(),
-				ColorLevel(record.level()),
-				record.args()
-			);
+		if !self.enabled(record.metadata()) {
+			return;
 		}
+
+		// FIXME: Use `super let` once stable
+		let time;
+		let format_time = if self.time() {
+			time = Microseconds(crate::processor::get_timer_ticks());
+			format_args!("[{time}]")
+		} else {
+			format_args!("[            ]")
+		};
+		let core_id = crate::arch::core_local::core_id();
+		let level = ColorLevel(record.level());
+		// FIXME: Use `super let` once stable
+		let target = record.target();
+		let format_target = if cfg!(feature = "log-target") {
+			format_args!(" {target}")
+		} else {
+			format_args!("")
+		};
+		let args = record.args();
+		println!("{format_time}[{core_id}][{level}{format_target}] {args}");
+	}
+}
+
+struct Microseconds(u64);
+
+impl fmt::Display for Microseconds {
+	fn fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result {
+		let seconds = self.0 / 1_000_000;
+		let microseconds = self.0 % 1_000_000;
+		write!(f, "{seconds:5}.{microseconds:06}")
 	}
 }
 
@@ -55,7 +101,7 @@ fn no_color() -> bool {
 }
 
 pub unsafe fn init() {
-	log::set_logger(&KernelLogger).expect("Can't initialize logger");
+	log::set_logger(&KERNEL_LOGGER).expect("Can't initialize logger");
 	// Determines LevelFilter at compile time
 	let log_level: Option<&'static str> = option_env!("HERMIT_LOG_LEVEL_FILTER");
 	let mut max_level = LevelFilter::Info;