melpomene: tracing improvements

source/kernel/src/lib.rs

@@ -78,11 +78,9 @@ impl Kernel {
     const INIT_IDLE: usize = 2;
     const INIT_LOCK: usize = 3;
 
-    pub unsafe fn new(
-        settings: KernelSettings,
-    ) -> Result<HeapBox<Self>, ()> {
+    pub unsafe fn new(settings: KernelSettings) -> Result<HeapBox<Self>, ()> {
         info!(
-            start = settings.heap_start as usize,
+            start = ?settings.heap_start,
             size = settings.heap_size,
             "Initializing heap"
         );

source/melpomene/Cargo.toml

@@ -30,8 +30,12 @@ path = "../mstd"
 version = "0.7.3"
 default-features = false
 
+[dependencies.atty]
+version = "0.2"
+optional = true
+
 [features]
-trace-fmt = ["tracing-subscriber"]
+trace-fmt = ["tracing-subscriber", "atty"]
 # Note, the "trace-modality" feature requires the use of the Auxon modality tool.
 # More information: https://auxon.io/products/modality
 trace-modality = ["tracing-modality"]

source/melpomene/src/main.rs

@@ -1,32 +1,35 @@
 use std::{
-    sync::atomic::{Ordering, AtomicBool},
-    thread::{spawn, yield_now, sleep},
-    time::{Duration, Instant},
     future::Future,
+    sync::atomic::{AtomicBool, Ordering},
     task::Poll,
+    thread::{sleep, spawn, yield_now},
+    time::{Duration, Instant},
 };
 
 use abi::{bbqueue_ipc::BBBuffer, syscall::DriverKind};
-use mnemos_kernel::{Kernel, KernelSettings, DriverHandle, KChannel};
 use melpomene::sim_tracing::setup_tracing;
+use mnemos_kernel::{DriverHandle, KChannel, Kernel, KernelSettings};
 
 const HEAP_SIZE: usize = 192 * 1024;
 static KERNEL_LOCK: AtomicBool = AtomicBool::new(true);
 
 fn main() {
     setup_tracing();
+    let _span = tracing::info_span!("Melpo").entered();
 
     println!("========================================");
     let kernel = spawn(move || {
         kernel_entry();
     });
-    println!("[Melpo]: Kernel started.");
+    tracing::info!("Kernel started.");
 
     // Wait for the kernel to complete initialization...
     while KERNEL_LOCK.load(Ordering::Acquire) {
         yield_now();
     }
 
+    tracing::debug!("Kernel initialized.");
+
     // let userspace = spawn(move || {
     //     userspace_entry();
     // });
@@ -40,14 +43,14 @@ fn main() {
 
     let kj = kernel.join();
     sleep(Duration::from_millis(50));
-    println!("[Melpo]: Kernel ended:    {:?}", kj);
-
+    tracing::info!("Kernel ended:    {:?}", kj);
 
     println!("========================================");
 
-    println!("[Melpo]: You've met with a terrible fate, haven't you?");
+    tracing::error!("You've met with a terrible fate, haven't you?");
 }
 
+#[tracing::instrument(name = "Kernel", level = "info")]
 fn kernel_entry() {
     // First, we'll do some stuff that later the linker script will do...
     let kernel_heap = Box::into_raw(Box::new([0u8; HEAP_SIZE]));
@@ -72,7 +75,9 @@ fn kernel_entry() {
         k.register_driver(DriverHandle {
             kind: DriverKind::Todo,
             queue: dummy_chan.clone(),
-        }).map_err(drop).unwrap();
+        })
+        .map_err(drop)
+        .unwrap();
 
         let dummy_fut = async move {
             let _ = dummy_chan;
@@ -87,7 +92,6 @@ fn kernel_entry() {
         k.spawn_allocated(boxed_dummy);
     }
 
-
     //////////////////////////////////////////////////////////////////////////////
     // TODO: Userspace doesn't really do anything yet! Simulate initialization of
     // the userspace structures, and just periodically wake the kernel for now.
@@ -104,6 +108,7 @@ fn kernel_entry() {
     }
 
     let _userspace = spawn(|| {
+        let _span = tracing::info_span!("userspace").entered();
         loop {
             while KERNEL_LOCK.load(Ordering::Acquire) {
                 sleep(Duration::from_millis(10));
@@ -114,7 +119,6 @@ fn kernel_entry() {
         }
     });
 
-
     loop {
         while !KERNEL_LOCK.load(Ordering::Acquire) {
             sleep(Duration::from_millis(10));
@@ -158,8 +162,6 @@ fn kernel_entry() {
 //     };
 //     mstd::executor::mailbox::MAILBOX.set_rings(rings);
 
-
-
 //     let start = Instant::now();
 //     loop {
 //         *mstd::executor::time::CURRENT_TIME.borrow_mut().unwrap() = start.elapsed().as_micros() as u64;
@@ -215,7 +217,10 @@ impl Sleepy {
 impl Future for Sleepy {
     type Output = ();
 
-    fn poll(self: std::pin::Pin<&mut Self>, cx: &mut std::task::Context<'_>) -> std::task::Poll<Self::Output> {
+    fn poll(
+        self: std::pin::Pin<&mut Self>,
+        cx: &mut std::task::Context<'_>,
+    ) -> std::task::Poll<Self::Output> {
         cx.waker().wake_by_ref();
         if self.start.elapsed() < self.dur {
             Poll::Pending

source/melpomene/src/sim_tracing.rs

@@ -1,9 +1,31 @@
-#[cfg(feature = "trace-fmt")]
-pub fn setup_tracing() {
-    tracing_subscriber::fmt::init();
-}
+const ENV_FILTER: &str = "MELPOMENE_TRACE";
 
-#[cfg(feature = "trace-modality")]
 pub fn setup_tracing() {
-    tracing_modality::TracingModality::init().expect("init");
+    use tracing_subscriber::prelude::*;
+
+    let subscriber = tracing_subscriber::registry();
+
+    // if `trace-fmt` is enabled, add a `tracing-subscriber::fmt` layer along
+    // with an `EnvFilter`
+    #[cfg(feature = "trace-fmt")]
+    let subscriber = {
+        use tracing_subscriber::{filter, fmt};
+
+        let filter = filter::EnvFilter::builder()
+            .with_default_directive(filter::LevelFilter::INFO.into())
+            .with_env_var(ENV_FILTER)
+            .from_env_lossy();
+
+        let fmt = fmt::layer()
+            .with_timer(fmt::time::uptime())
+            .with_ansi(atty::is(atty::Stream::Stdout))
+            .with_filter(filter);
+        subscriber.with(fmt)
+    };
+
+    // if `trace-modality` is enabled, add the Modality layer as well.
+    #[cfg(feature = "trace-modality")]
+    let subscriber = subscriber.with(tracing_modality::ModalityLayer::new());
+
+    subscriber.init();
 }