Print a timestamp on panic

07_timestamps/README.md

@@ -248,7 +248,7 @@ diff -uNr 06_uart_chainloader/src/_arch/aarch64/cpu.rs 07_timestamps/src/_arch/a
 diff -uNr 06_uart_chainloader/src/_arch/aarch64/time.rs 07_timestamps/src/_arch/aarch64/time.rs
 --- 06_uart_chainloader/src/_arch/aarch64/time.rs
 +++ 07_timestamps/src/_arch/aarch64/time.rs
-@@ -0,0 +1,119 @@
+@@ -0,0 +1,121 @@
 +// SPDX-License-Identifier: MIT OR Apache-2.0
 +//
 +// Copyright (c) 2018-2022 Andre Richter <andre.o.richter@gmail.com>
@@ -329,6 +329,7 @@ diff -uNr 06_uart_chainloader/src/_arch/aarch64/time.rs 07_timestamps/src/_arch/
 +        // Calculate the register compare value.
 +        let frq = CNTFRQ_EL0.get();
 +        let x = match frq.checked_mul(duration.as_nanos() as u64) {
++            #[allow(unused_imports)]
 +            None => {
 +                warn!("Spin duration too long, skipping");
 +                return;
@@ -347,6 +348,7 @@ diff -uNr 06_uart_chainloader/src/_arch/aarch64/time.rs 07_timestamps/src/_arch/
 +            None
 +        };
 +
++        #[allow(unused_imports)]
 +        if let Some(w) = warn {
 +            warn!(
 +                "Spin duration {} than architecturally supported, skipping",
@@ -630,10 +632,40 @@ diff -uNr 06_uart_chainloader/src/main.rs 07_timestamps/src/main.rs
 +    }
  }
 
+diff -uNr 06_uart_chainloader/src/panic_wait.rs 07_timestamps/src/panic_wait.rs
+--- 06_uart_chainloader/src/panic_wait.rs
++++ 07_timestamps/src/panic_wait.rs
+@@ -29,10 +29,23 @@
+
+ #[panic_handler]
+ fn panic(info: &PanicInfo) -> ! {
++    use crate::time::interface::TimeManager;
++
++    let timestamp = crate::time::time_manager().uptime();
++
+     if let Some(args) = info.message() {
+-        panic_println!("\nKernel panic: {}", args);
++        panic_println!(
++            "[  {:>3}.{:06}] Kernel panic: {}",
++            timestamp.as_secs(),
++            timestamp.subsec_micros(),
++            args,
++        );
+     } else {
+-        panic_println!("\nKernel panic!");
++        panic_println!(
++            "[  {:>3}.{:06}] Kernel panic!",
++            timestamp.as_secs(),
++            timestamp.subsec_micros(),
++        );
+     }
+
+     cpu::wait_forever()
+
 diff -uNr 06_uart_chainloader/src/print.rs 07_timestamps/src/print.rs
 --- 06_uart_chainloader/src/print.rs
 +++ 07_timestamps/src/print.rs
-@@ -36,3 +36,71 @@
+@@ -36,3 +36,59 @@
          $crate::print::_print(format_args_nl!($($arg)*));
      })
  }
@@ -642,31 +674,25 @@ diff -uNr 06_uart_chainloader/src/print.rs 07_timestamps/src/print.rs
 +#[macro_export]
 +macro_rules! info {
 +    ($string:expr) => ({
-+        #[allow(unused_imports)]
-+        use crate::time::interface::TimeManager;
++        use $crate::time::interface::TimeManager;
 +
 +        let timestamp = $crate::time::time_manager().uptime();
-+        let timestamp_subsec_us = timestamp.subsec_micros();
 +
 +        $crate::print::_print(format_args_nl!(
-+            concat!("[  {:>3}.{:03}{:03}] ", $string),
++            concat!("[  {:>3}.{:06}] ", $string),
 +            timestamp.as_secs(),
-+            timestamp_subsec_us / 1_000,
-+            timestamp_subsec_us modulo 1_000
++            timestamp.subsec_micros(),
 +        ));
 +    });
 +    ($format_string:expr, $($arg:tt)*) => ({
-+        #[allow(unused_imports)]
-+        use crate::time::interface::TimeManager;
++        use $crate::time::interface::TimeManager;
 +
 +        let timestamp = $crate::time::time_manager().uptime();
-+        let timestamp_subsec_us = timestamp.subsec_micros();
 +
 +        $crate::print::_print(format_args_nl!(
-+            concat!("[  {:>3}.{:03}{:03}] ", $format_string),
++            concat!("[  {:>3}.{:06}] ", $format_string),
 +            timestamp.as_secs(),
-+            timestamp_subsec_us / 1_000,
-+            timestamp_subsec_us modulo 1_000,
++            timestamp.subsec_micros(),
 +            $($arg)*
 +        ));
 +    })
@@ -676,31 +702,25 @@ diff -uNr 06_uart_chainloader/src/print.rs 07_timestamps/src/print.rs
 +#[macro_export]
 +macro_rules! warn {
 +    ($string:expr) => ({
-+        #[allow(unused_imports)]
-+        use crate::time::interface::TimeManager;
++        use $crate::time::interface::TimeManager;
 +
 +        let timestamp = $crate::time::time_manager().uptime();
-+        let timestamp_subsec_us = timestamp.subsec_micros();
 +
 +        $crate::print::_print(format_args_nl!(
-+            concat!("[W {:>3}.{:03}{:03}] ", $string),
++            concat!("[W {:>3}.{:06}] ", $string),
 +            timestamp.as_secs(),
-+            timestamp_subsec_us / 1_000,
-+            timestamp_subsec_us modulo 1_000
++            timestamp.subsec_micros(),
 +        ));
 +    });
 +    ($format_string:expr, $($arg:tt)*) => ({
-+        #[allow(unused_imports)]
-+        use crate::time::interface::TimeManager;
++        use $crate::time::interface::TimeManager;
 +
 +        let timestamp = $crate::time::time_manager().uptime();
-+        let timestamp_subsec_us = timestamp.subsec_micros();
 +
 +        $crate::print::_print(format_args_nl!(
-+            concat!("[W {:>3}.{:03}{:03}] ", $format_string),
++            concat!("[W {:>3}.{:06}] ", $format_string),
 +            timestamp.as_secs(),
-+            timestamp_subsec_us / 1_000,
-+            timestamp_subsec_us modulo 1_000,
++            timestamp.subsec_micros(),
 +            $($arg)*
 +        ));
 +    })

07_timestamps/src/_arch/aarch64/time.rs

@@ -78,6 +78,7 @@ impl time::interface::TimeManager for GenericTimer {
         // Calculate the register compare value.
         let frq = CNTFRQ_EL0.get();
         let x = match frq.checked_mul(duration.as_nanos() as u64) {
+            #[allow(unused_imports)]
             None => {
                 warn!("Spin duration too long, skipping");
                 return;
@@ -96,6 +97,7 @@ impl time::interface::TimeManager for GenericTimer {
             None
         };
 
+        #[allow(unused_imports)]
         if let Some(w) = warn {
             warn!(
                 "Spin duration {} than architecturally supported, skipping",

07_timestamps/src/panic_wait.rs

@@ -29,10 +29,23 @@ macro_rules! panic_println {
 
 #[panic_handler]
 fn panic(info: &PanicInfo) -> ! {
+    use crate::time::interface::TimeManager;
+
+    let timestamp = crate::time::time_manager().uptime();
+
     if let Some(args) = info.message() {
-        panic_println!("\nKernel panic: {}", args);
+        panic_println!(
+            "[  {:>3}.{:06}] Kernel panic: {}",
+            timestamp.as_secs(),
+            timestamp.subsec_micros(),
+            args,
+        );
     } else {
-        panic_println!("\nKernel panic!");
+        panic_println!(
+            "[  {:>3}.{:06}] Kernel panic!",
+            timestamp.as_secs(),
+            timestamp.subsec_micros(),
+        );
     }
 
     cpu::wait_forever()

07_timestamps/src/print.rs

@@ -41,31 +41,25 @@ macro_rules! println {
 #[macro_export]
 macro_rules! info {
     ($string:expr) => ({
-        #[allow(unused_imports)]
-        use crate::time::interface::TimeManager;
+        use $crate::time::interface::TimeManager;
 
         let timestamp = $crate::time::time_manager().uptime();
-        let timestamp_subsec_us = timestamp.subsec_micros();
 
         $crate::print::_print(format_args_nl!(
-            concat!("[  {:>3}.{:03}{:03}] ", $string),
+            concat!("[  {:>3}.{:06}] ", $string),
             timestamp.as_secs(),
-            timestamp_subsec_us / 1_000,
-            timestamp_subsec_us % 1_000
+            timestamp.subsec_micros(),
         ));
     });
     ($format_string:expr, $($arg:tt)*) => ({
-        #[allow(unused_imports)]
-        use crate::time::interface::TimeManager;
+        use $crate::time::interface::TimeManager;
 
         let timestamp = $crate::time::time_manager().uptime();
-        let timestamp_subsec_us = timestamp.subsec_micros();
 
         $crate::print::_print(format_args_nl!(
-            concat!("[  {:>3}.{:03}{:03}] ", $format_string),
+            concat!("[  {:>3}.{:06}] ", $format_string),
             timestamp.as_secs(),
-            timestamp_subsec_us / 1_000,
-            timestamp_subsec_us % 1_000,
+            timestamp.subsec_micros(),
             $($arg)*
         ));
     })
@@ -75,31 +69,25 @@ macro_rules! info {
 #[macro_export]
 macro_rules! warn {
     ($string:expr) => ({
-        #[allow(unused_imports)]
-        use crate::time::interface::TimeManager;
+        use $crate::time::interface::TimeManager;
 
         let timestamp = $crate::time::time_manager().uptime();
-        let timestamp_subsec_us = timestamp.subsec_micros();
 
         $crate::print::_print(format_args_nl!(
-            concat!("[W {:>3}.{:03}{:03}] ", $string),
+            concat!("[W {:>3}.{:06}] ", $string),
             timestamp.as_secs(),
-            timestamp_subsec_us / 1_000,
-            timestamp_subsec_us % 1_000
+            timestamp.subsec_micros(),
         ));
     });
     ($format_string:expr, $($arg:tt)*) => ({
-        #[allow(unused_imports)]
-        use crate::time::interface::TimeManager;
+        use $crate::time::interface::TimeManager;
 
         let timestamp = $crate::time::time_manager().uptime();
-        let timestamp_subsec_us = timestamp.subsec_micros();
 
         $crate::print::_print(format_args_nl!(
-            concat!("[W {:>3}.{:03}{:03}] ", $format_string),
+            concat!("[W {:>3}.{:06}] ", $format_string),
             timestamp.as_secs(),
-            timestamp_subsec_us / 1_000,
-            timestamp_subsec_us % 1_000,
+            timestamp.subsec_micros(),
             $($arg)*
         ));
     })

08_hw_debug_JTAG/src/_arch/aarch64/time.rs

@@ -78,6 +78,7 @@ impl time::interface::TimeManager for GenericTimer {
         // Calculate the register compare value.
         let frq = CNTFRQ_EL0.get();
         let x = match frq.checked_mul(duration.as_nanos() as u64) {
+            #[allow(unused_imports)]
             None => {
                 warn!("Spin duration too long, skipping");
                 return;
@@ -96,6 +97,7 @@ impl time::interface::TimeManager for GenericTimer {
             None
         };
 
+        #[allow(unused_imports)]
         if let Some(w) = warn {
             warn!(
                 "Spin duration {} than architecturally supported, skipping",

08_hw_debug_JTAG/src/panic_wait.rs

@@ -29,10 +29,23 @@ macro_rules! panic_println {
 
 #[panic_handler]
 fn panic(info: &PanicInfo) -> ! {
+    use crate::time::interface::TimeManager;
+
+    let timestamp = crate::time::time_manager().uptime();
+
     if let Some(args) = info.message() {
-        panic_println!("\nKernel panic: {}", args);
+        panic_println!(
+            "[  {:>3}.{:06}] Kernel panic: {}",
+            timestamp.as_secs(),
+            timestamp.subsec_micros(),
+            args,
+        );
     } else {
-        panic_println!("\nKernel panic!");
+        panic_println!(
+            "[  {:>3}.{:06}] Kernel panic!",
+            timestamp.as_secs(),
+            timestamp.subsec_micros(),
+        );
     }
 
     cpu::wait_forever()

08_hw_debug_JTAG/src/print.rs

@@ -41,31 +41,25 @@ macro_rules! println {
 #[macro_export]
 macro_rules! info {
     ($string:expr) => ({
-        #[allow(unused_imports)]
-        use crate::time::interface::TimeManager;
+        use $crate::time::interface::TimeManager;
 
         let timestamp = $crate::time::time_manager().uptime();
-        let timestamp_subsec_us = timestamp.subsec_micros();
 
         $crate::print::_print(format_args_nl!(
-            concat!("[  {:>3}.{:03}{:03}] ", $string),
+            concat!("[  {:>3}.{:06}] ", $string),
             timestamp.as_secs(),
-            timestamp_subsec_us / 1_000,
-            timestamp_subsec_us % 1_000
+            timestamp.subsec_micros(),
         ));
     });
     ($format_string:expr, $($arg:tt)*) => ({
-        #[allow(unused_imports)]
-        use crate::time::interface::TimeManager;
+        use $crate::time::interface::TimeManager;
 
         let timestamp = $crate::time::time_manager().uptime();
-        let timestamp_subsec_us = timestamp.subsec_micros();
 
         $crate::print::_print(format_args_nl!(
-            concat!("[  {:>3}.{:03}{:03}] ", $format_string),
+            concat!("[  {:>3}.{:06}] ", $format_string),
             timestamp.as_secs(),
-            timestamp_subsec_us / 1_000,
-            timestamp_subsec_us % 1_000,
+            timestamp.subsec_micros(),
             $($arg)*
         ));
     })
@@ -75,31 +69,25 @@ macro_rules! info {
 #[macro_export]
 macro_rules! warn {
     ($string:expr) => ({
-        #[allow(unused_imports)]
-        use crate::time::interface::TimeManager;
+        use $crate::time::interface::TimeManager;
 
         let timestamp = $crate::time::time_manager().uptime();
-        let timestamp_subsec_us = timestamp.subsec_micros();
 
         $crate::print::_print(format_args_nl!(
-            concat!("[W {:>3}.{:03}{:03}] ", $string),
+            concat!("[W {:>3}.{:06}] ", $string),
             timestamp.as_secs(),
-            timestamp_subsec_us / 1_000,
-            timestamp_subsec_us % 1_000
+            timestamp.subsec_micros(),
         ));
     });
     ($format_string:expr, $($arg:tt)*) => ({
-        #[allow(unused_imports)]
-        use crate::time::interface::TimeManager;
+        use $crate::time::interface::TimeManager;
 
         let timestamp = $crate::time::time_manager().uptime();
-        let timestamp_subsec_us = timestamp.subsec_micros();
 
         $crate::print::_print(format_args_nl!(
-            concat!("[W {:>3}.{:03}{:03}] ", $format_string),
+            concat!("[W {:>3}.{:06}] ", $format_string),
             timestamp.as_secs(),
-            timestamp_subsec_us / 1_000,
-            timestamp_subsec_us % 1_000,
+            timestamp.subsec_micros(),
             $($arg)*
         ));
     })

09_privilege_level/src/_arch/aarch64/time.rs

@@ -78,6 +78,7 @@ impl time::interface::TimeManager for GenericTimer {
         // Calculate the register compare value.
         let frq = CNTFRQ_EL0.get();
         let x = match frq.checked_mul(duration.as_nanos() as u64) {
+            #[allow(unused_imports)]
             None => {
                 warn!("Spin duration too long, skipping");
                 return;
@@ -96,6 +97,7 @@ impl time::interface::TimeManager for GenericTimer {
             None
         };
 
+        #[allow(unused_imports)]
         if let Some(w) = warn {
             warn!(
                 "Spin duration {} than architecturally supported, skipping",

09_privilege_level/src/panic_wait.rs

@@ -29,10 +29,23 @@ macro_rules! panic_println {
 
 #[panic_handler]
 fn panic(info: &PanicInfo) -> ! {
+    use crate::time::interface::TimeManager;
+
+    let timestamp = crate::time::time_manager().uptime();
+
     if let Some(args) = info.message() {
-        panic_println!("\nKernel panic: {}", args);
+        panic_println!(
+            "[  {:>3}.{:06}] Kernel panic: {}",
+            timestamp.as_secs(),
+            timestamp.subsec_micros(),
+            args,
+        );
     } else {
-        panic_println!("\nKernel panic!");
+        panic_println!(
+            "[  {:>3}.{:06}] Kernel panic!",
+            timestamp.as_secs(),
+            timestamp.subsec_micros(),
+        );
     }
 
     cpu::wait_forever()

09_privilege_level/src/print.rs

@@ -41,31 +41,25 @@ macro_rules! println {
 #[macro_export]
 macro_rules! info {
     ($string:expr) => ({
-        #[allow(unused_imports)]
-        use crate::time::interface::TimeManager;
+        use $crate::time::interface::TimeManager;
 
         let timestamp = $crate::time::time_manager().uptime();
-        let timestamp_subsec_us = timestamp.subsec_micros();
 
         $crate::print::_print(format_args_nl!(
-            concat!("[  {:>3}.{:03}{:03}] ", $string),
+            concat!("[  {:>3}.{:06}] ", $string),
             timestamp.as_secs(),
-            timestamp_subsec_us / 1_000,
-            timestamp_subsec_us % 1_000
+            timestamp.subsec_micros(),
         ));
     });
     ($format_string:expr, $($arg:tt)*) => ({
-        #[allow(unused_imports)]
-        use crate::time::interface::TimeManager;
+        use $crate::time::interface::TimeManager;
 
         let timestamp = $crate::time::time_manager().uptime();
-        let timestamp_subsec_us = timestamp.subsec_micros();
 
         $crate::print::_print(format_args_nl!(
-            concat!("[  {:>3}.{:03}{:03}] ", $format_string),
+            concat!("[  {:>3}.{:06}] ", $format_string),
             timestamp.as_secs(),
-            timestamp_subsec_us / 1_000,
-            timestamp_subsec_us % 1_000,
+            timestamp.subsec_micros(),
             $($arg)*
         ));
     })
@@ -75,31 +69,25 @@ macro_rules! info {
 #[macro_export]
 macro_rules! warn {
     ($string:expr) => ({
-        #[allow(unused_imports)]
-        use crate::time::interface::TimeManager;
+        use $crate::time::interface::TimeManager;
 
         let timestamp = $crate::time::time_manager().uptime();
-        let timestamp_subsec_us = timestamp.subsec_micros();
 
         $crate::print::_print(format_args_nl!(
-            concat!("[W {:>3}.{:03}{:03}] ", $string),
+            concat!("[W {:>3}.{:06}] ", $string),
             timestamp.as_secs(),
-            timestamp_subsec_us / 1_000,
-            timestamp_subsec_us % 1_000
+            timestamp.subsec_micros(),
         ));
     });
     ($format_string:expr, $($arg:tt)*) => ({
-        #[allow(unused_imports)]
-        use crate::time::interface::TimeManager;
+        use $crate::time::interface::TimeManager;
 
         let timestamp = $crate::time::time_manager().uptime();
-        let timestamp_subsec_us = timestamp.subsec_micros();
 
         $crate::print::_print(format_args_nl!(
-            concat!("[W {:>3}.{:03}{:03}] ", $format_string),
+            concat!("[W {:>3}.{:06}] ", $format_string),
             timestamp.as_secs(),
-            timestamp_subsec_us / 1_000,
-            timestamp_subsec_us % 1_000,
+            timestamp.subsec_micros(),
             $($arg)*
         ));
     })

10_virtual_mem_part1_identity_mapping/src/_arch/aarch64/time.rs

@@ -78,6 +78,7 @@ impl time::interface::TimeManager for GenericTimer {
         // Calculate the register compare value.
         let frq = CNTFRQ_EL0.get();
         let x = match frq.checked_mul(duration.as_nanos() as u64) {
+            #[allow(unused_imports)]
             None => {
                 warn!("Spin duration too long, skipping");
                 return;
@@ -96,6 +97,7 @@ impl time::interface::TimeManager for GenericTimer {
             None
         };
 
+        #[allow(unused_imports)]
         if let Some(w) = warn {
             warn!(
                 "Spin duration {} than architecturally supported, skipping",

10_virtual_mem_part1_identity_mapping/src/panic_wait.rs

@@ -29,10 +29,23 @@ macro_rules! panic_println {
 
 #[panic_handler]
 fn panic(info: &PanicInfo) -> ! {
+    use crate::time::interface::TimeManager;
+
+    let timestamp = crate::time::time_manager().uptime();
+
     if let Some(args) = info.message() {
-        panic_println!("\nKernel panic: {}", args);
+        panic_println!(
+            "[  {:>3}.{:06}] Kernel panic: {}",
+            timestamp.as_secs(),
+            timestamp.subsec_micros(),
+            args,
+        );
     } else {
-        panic_println!("\nKernel panic!");
+        panic_println!(
+            "[  {:>3}.{:06}] Kernel panic!",
+            timestamp.as_secs(),
+            timestamp.subsec_micros(),
+        );
     }
 
     cpu::wait_forever()

10_virtual_mem_part1_identity_mapping/src/print.rs

@@ -41,31 +41,25 @@ macro_rules! println {
 #[macro_export]
 macro_rules! info {
     ($string:expr) => ({
-        #[allow(unused_imports)]
-        use crate::time::interface::TimeManager;
+        use $crate::time::interface::TimeManager;
 
         let timestamp = $crate::time::time_manager().uptime();
-        let timestamp_subsec_us = timestamp.subsec_micros();
 
         $crate::print::_print(format_args_nl!(
-            concat!("[  {:>3}.{:03}{:03}] ", $string),
+            concat!("[  {:>3}.{:06}] ", $string),
             timestamp.as_secs(),
-            timestamp_subsec_us / 1_000,
-            timestamp_subsec_us % 1_000
+            timestamp.subsec_micros(),
         ));
     });
     ($format_string:expr, $($arg:tt)*) => ({
-        #[allow(unused_imports)]
-        use crate::time::interface::TimeManager;
+        use $crate::time::interface::TimeManager;
 
         let timestamp = $crate::time::time_manager().uptime();
-        let timestamp_subsec_us = timestamp.subsec_micros();
 
         $crate::print::_print(format_args_nl!(
-            concat!("[  {:>3}.{:03}{:03}] ", $format_string),
+            concat!("[  {:>3}.{:06}] ", $format_string),
             timestamp.as_secs(),
-            timestamp_subsec_us / 1_000,
-            timestamp_subsec_us % 1_000,
+            timestamp.subsec_micros(),
             $($arg)*
         ));
     })
@@ -75,31 +69,25 @@ macro_rules! info {
 #[macro_export]
 macro_rules! warn {
     ($string:expr) => ({
-        #[allow(unused_imports)]
-        use crate::time::interface::TimeManager;
+        use $crate::time::interface::TimeManager;
 
         let timestamp = $crate::time::time_manager().uptime();
-        let timestamp_subsec_us = timestamp.subsec_micros();
 
         $crate::print::_print(format_args_nl!(
-            concat!("[W {:>3}.{:03}{:03}] ", $string),
+            concat!("[W {:>3}.{:06}] ", $string),
             timestamp.as_secs(),
-            timestamp_subsec_us / 1_000,
-            timestamp_subsec_us % 1_000
+            timestamp.subsec_micros(),
         ));
     });
     ($format_string:expr, $($arg:tt)*) => ({
-        #[allow(unused_imports)]
-        use crate::time::interface::TimeManager;
+        use $crate::time::interface::TimeManager;
 
         let timestamp = $crate::time::time_manager().uptime();
-        let timestamp_subsec_us = timestamp.subsec_micros();
 
         $crate::print::_print(format_args_nl!(
-            concat!("[W {:>3}.{:03}{:03}] ", $format_string),
+            concat!("[W {:>3}.{:06}] ", $format_string),
             timestamp.as_secs(),
-            timestamp_subsec_us / 1_000,
-            timestamp_subsec_us % 1_000,
+            timestamp.subsec_micros(),
             $($arg)*
         ));
     })

11_exceptions_part1_groundwork/src/_arch/aarch64/time.rs

@@ -78,6 +78,7 @@ impl time::interface::TimeManager for GenericTimer {
         // Calculate the register compare value.
         let frq = CNTFRQ_EL0.get();
         let x = match frq.checked_mul(duration.as_nanos() as u64) {
+            #[allow(unused_imports)]
             None => {
                 warn!("Spin duration too long, skipping");
                 return;
@@ -96,6 +97,7 @@ impl time::interface::TimeManager for GenericTimer {
             None
         };
 
+        #[allow(unused_imports)]
         if let Some(w) = warn {
             warn!(
                 "Spin duration {} than architecturally supported, skipping",

11_exceptions_part1_groundwork/src/panic_wait.rs

@@ -29,10 +29,23 @@ macro_rules! panic_println {
 
 #[panic_handler]
 fn panic(info: &PanicInfo) -> ! {
+    use crate::time::interface::TimeManager;
+
+    let timestamp = crate::time::time_manager().uptime();
+
     if let Some(args) = info.message() {
-        panic_println!("\nKernel panic: {}", args);
+        panic_println!(
+            "[  {:>3}.{:06}] Kernel panic: {}",
+            timestamp.as_secs(),
+            timestamp.subsec_micros(),
+            args,
+        );
     } else {
-        panic_println!("\nKernel panic!");
+        panic_println!(
+            "[  {:>3}.{:06}] Kernel panic!",
+            timestamp.as_secs(),
+            timestamp.subsec_micros(),
+        );
     }
 
     cpu::wait_forever()

11_exceptions_part1_groundwork/src/print.rs

@@ -41,31 +41,25 @@ macro_rules! println {
 #[macro_export]
 macro_rules! info {
     ($string:expr) => ({
-        #[allow(unused_imports)]
-        use crate::time::interface::TimeManager;
+        use $crate::time::interface::TimeManager;
 
         let timestamp = $crate::time::time_manager().uptime();
-        let timestamp_subsec_us = timestamp.subsec_micros();
 
         $crate::print::_print(format_args_nl!(
-            concat!("[  {:>3}.{:03}{:03}] ", $string),
+            concat!("[  {:>3}.{:06}] ", $string),
             timestamp.as_secs(),
-            timestamp_subsec_us / 1_000,
-            timestamp_subsec_us % 1_000
+            timestamp.subsec_micros(),
         ));
     });
     ($format_string:expr, $($arg:tt)*) => ({
-        #[allow(unused_imports)]
-        use crate::time::interface::TimeManager;
+        use $crate::time::interface::TimeManager;
 
         let timestamp = $crate::time::time_manager().uptime();
-        let timestamp_subsec_us = timestamp.subsec_micros();
 
         $crate::print::_print(format_args_nl!(
-            concat!("[  {:>3}.{:03}{:03}] ", $format_string),
+            concat!("[  {:>3}.{:06}] ", $format_string),
             timestamp.as_secs(),
-            timestamp_subsec_us / 1_000,
-            timestamp_subsec_us % 1_000,
+            timestamp.subsec_micros(),
             $($arg)*
         ));
     })
@@ -75,31 +69,25 @@ macro_rules! info {
 #[macro_export]
 macro_rules! warn {
     ($string:expr) => ({
-        #[allow(unused_imports)]
-        use crate::time::interface::TimeManager;
+        use $crate::time::interface::TimeManager;
 
         let timestamp = $crate::time::time_manager().uptime();
-        let timestamp_subsec_us = timestamp.subsec_micros();
 
         $crate::print::_print(format_args_nl!(
-            concat!("[W {:>3}.{:03}{:03}] ", $string),
+            concat!("[W {:>3}.{:06}] ", $string),
             timestamp.as_secs(),
-            timestamp_subsec_us / 1_000,
-            timestamp_subsec_us % 1_000
+            timestamp.subsec_micros(),
         ));
     });
     ($format_string:expr, $($arg:tt)*) => ({
-        #[allow(unused_imports)]
-        use crate::time::interface::TimeManager;
+        use $crate::time::interface::TimeManager;
 
         let timestamp = $crate::time::time_manager().uptime();
-        let timestamp_subsec_us = timestamp.subsec_micros();
 
         $crate::print::_print(format_args_nl!(
-            concat!("[W {:>3}.{:03}{:03}] ", $format_string),
+            concat!("[W {:>3}.{:06}] ", $format_string),
             timestamp.as_secs(),
-            timestamp_subsec_us / 1_000,
-            timestamp_subsec_us % 1_000,
+            timestamp.subsec_micros(),
             $($arg)*
         ));
     })

12_integrated_testing/README.md

@@ -849,9 +849,8 @@ Compiling integration test(s) - rpi3
          🦀 Testing synchronous exception handling by causing a page fault
          -------------------------------------------------------------------
 
-         Writing beyond mapped area to address 9 GiB...
-
-         Kernel panic:
+         [    0.163030] Writing beyond mapped area to address 9 GiB...
+         [    0.164791] Kernel panic:
 
          CPU Exception!
          ESR_EL1: 0x96000004
@@ -1698,8 +1697,8 @@ diff -uNr 11_exceptions_part1_groundwork/src/panic_wait.rs 12_integrated_testing
  /// Prints with a newline - only use from the panic handler.
  ///
  /// Carbon copy from <https://doc.rust-lang.org/src/std/macros.rs.html>
-@@ -35,5 +52,5 @@
-         panic_println!("\nKernel panic!");
+@@ -48,5 +65,5 @@
+         );
      }
 
 -    cpu::wait_forever()
@@ -1929,7 +1928,7 @@ diff -uNr 11_exceptions_part1_groundwork/tests/02_exception_sync_page_fault.rs 1
 +/// or indirectly.
 +mod panic_exit_success;
 +
-+use libkernel::{bsp, cpu, exception, memory, println};
++use libkernel::{bsp, cpu, exception, info, memory, println};
 +
 +#[no_mangle]
 +unsafe fn kernel_init() -> ! {
@@ -1942,11 +1941,11 @@ diff -uNr 11_exceptions_part1_groundwork/tests/02_exception_sync_page_fault.rs 1
 +    println!("Testing synchronous exception handling by causing a page fault");
 +
 +    if let Err(string) = memory::mmu::mmu().enable_mmu_and_caching() {
-+        println!("MMU: {}", string);
++        info!("MMU: {}", string);
 +        cpu::qemu_exit_failure()
 +    }
 +
-+    println!("Writing beyond mapped area to address 9 GiB...");
++    info!("Writing beyond mapped area to address 9 GiB...");
 +    let big_addr: u64 = 9 * 1024 * 1024 * 1024;
 +    core::ptr::read_volatile(big_addr as *mut u64);
 +

12_integrated_testing/src/_arch/aarch64/time.rs

@@ -78,6 +78,7 @@ impl time::interface::TimeManager for GenericTimer {
         // Calculate the register compare value.
         let frq = CNTFRQ_EL0.get();
         let x = match frq.checked_mul(duration.as_nanos() as u64) {
+            #[allow(unused_imports)]
             None => {
                 warn!("Spin duration too long, skipping");
                 return;
@@ -96,6 +97,7 @@ impl time::interface::TimeManager for GenericTimer {
             None
         };
 
+        #[allow(unused_imports)]
         if let Some(w) = warn {
             warn!(
                 "Spin duration {} than architecturally supported, skipping",

12_integrated_testing/src/panic_wait.rs

@@ -46,10 +46,23 @@ macro_rules! panic_println {
 
 #[panic_handler]
 fn panic(info: &PanicInfo) -> ! {
+    use crate::time::interface::TimeManager;
+
+    let timestamp = crate::time::time_manager().uptime();
+
     if let Some(args) = info.message() {
-        panic_println!("\nKernel panic: {}", args);
+        panic_println!(
+            "[  {:>3}.{:06}] Kernel panic: {}",
+            timestamp.as_secs(),
+            timestamp.subsec_micros(),
+            args,
+        );
     } else {
-        panic_println!("\nKernel panic!");
+        panic_println!(
+            "[  {:>3}.{:06}] Kernel panic!",
+            timestamp.as_secs(),
+            timestamp.subsec_micros(),
+        );
     }
 
     _panic_exit()

12_integrated_testing/src/print.rs

@@ -41,31 +41,25 @@ macro_rules! println {
 #[macro_export]
 macro_rules! info {
     ($string:expr) => ({
-        #[allow(unused_imports)]
-        use crate::time::interface::TimeManager;
+        use $crate::time::interface::TimeManager;
 
         let timestamp = $crate::time::time_manager().uptime();
-        let timestamp_subsec_us = timestamp.subsec_micros();
 
         $crate::print::_print(format_args_nl!(
-            concat!("[  {:>3}.{:03}{:03}] ", $string),
+            concat!("[  {:>3}.{:06}] ", $string),
             timestamp.as_secs(),
-            timestamp_subsec_us / 1_000,
-            timestamp_subsec_us % 1_000
+            timestamp.subsec_micros(),
         ));
     });
     ($format_string:expr, $($arg:tt)*) => ({
-        #[allow(unused_imports)]
-        use crate::time::interface::TimeManager;
+        use $crate::time::interface::TimeManager;
 
         let timestamp = $crate::time::time_manager().uptime();
-        let timestamp_subsec_us = timestamp.subsec_micros();
 
         $crate::print::_print(format_args_nl!(
-            concat!("[  {:>3}.{:03}{:03}] ", $format_string),
+            concat!("[  {:>3}.{:06}] ", $format_string),
             timestamp.as_secs(),
-            timestamp_subsec_us / 1_000,
-            timestamp_subsec_us % 1_000,
+            timestamp.subsec_micros(),
             $($arg)*
         ));
     })
@@ -75,31 +69,25 @@ macro_rules! info {
 #[macro_export]
 macro_rules! warn {
     ($string:expr) => ({
-        #[allow(unused_imports)]
-        use crate::time::interface::TimeManager;
+        use $crate::time::interface::TimeManager;
 
         let timestamp = $crate::time::time_manager().uptime();
-        let timestamp_subsec_us = timestamp.subsec_micros();
 
         $crate::print::_print(format_args_nl!(
-            concat!("[W {:>3}.{:03}{:03}] ", $string),
+            concat!("[W {:>3}.{:06}] ", $string),
             timestamp.as_secs(),
-            timestamp_subsec_us / 1_000,
-            timestamp_subsec_us % 1_000
+            timestamp.subsec_micros(),
         ));
     });
     ($format_string:expr, $($arg:tt)*) => ({
-        #[allow(unused_imports)]
-        use crate::time::interface::TimeManager;
+        use $crate::time::interface::TimeManager;
 
         let timestamp = $crate::time::time_manager().uptime();
-        let timestamp_subsec_us = timestamp.subsec_micros();
 
         $crate::print::_print(format_args_nl!(
-            concat!("[W {:>3}.{:03}{:03}] ", $format_string),
+            concat!("[W {:>3}.{:06}] ", $format_string),
             timestamp.as_secs(),
-            timestamp_subsec_us / 1_000,
-            timestamp_subsec_us % 1_000,
+            timestamp.subsec_micros(),
             $($arg)*
         ));
     })

12_integrated_testing/tests/02_exception_sync_page_fault.rs

@@ -17,7 +17,7 @@
 /// or indirectly.
 mod panic_exit_success;
 
-use libkernel::{bsp, cpu, exception, memory, println};
+use libkernel::{bsp, cpu, exception, info, memory, println};
 
 #[no_mangle]
 unsafe fn kernel_init() -> ! {
@@ -30,11 +30,11 @@ unsafe fn kernel_init() -> ! {
     println!("Testing synchronous exception handling by causing a page fault");
 
     if let Err(string) = memory::mmu::mmu().enable_mmu_and_caching() {
-        println!("MMU: {}", string);
+        info!("MMU: {}", string);
         cpu::qemu_exit_failure()
     }
 
-    println!("Writing beyond mapped area to address 9 GiB...");
+    info!("Writing beyond mapped area to address 9 GiB...");
     let big_addr: u64 = 9 * 1024 * 1024 * 1024;
     core::ptr::read_volatile(big_addr as *mut u64);
 

13_exceptions_part2_peripheral_IRQs/README.md

@@ -2511,15 +2511,15 @@ diff -uNr 12_integrated_testing/src/panic_wait.rs 13_exceptions_part2_peripheral
  use core::{fmt, panic::PanicInfo};
 
  //--------------------------------------------------------------------------------------------------
-@@ -46,6 +46,8 @@
-
- #[panic_handler]
+@@ -48,6 +48,8 @@
  fn panic(info: &PanicInfo) -> ! {
+     use crate::time::interface::TimeManager;
+
 +    unsafe { exception::asynchronous::local_irq_mask() };
 +
+     let timestamp = crate::time::time_manager().uptime();
+
      if let Some(args) = info.message() {
-         panic_println!("\nKernel panic: {}", args);
-     } else {
 
 diff -uNr 12_integrated_testing/src/state.rs 13_exceptions_part2_peripheral_IRQs/src/state.rs
 --- 12_integrated_testing/src/state.rs

13_exceptions_part2_peripheral_IRQs/src/_arch/aarch64/time.rs

@@ -78,6 +78,7 @@ impl time::interface::TimeManager for GenericTimer {
         // Calculate the register compare value.
         let frq = CNTFRQ_EL0.get();
         let x = match frq.checked_mul(duration.as_nanos() as u64) {
+            #[allow(unused_imports)]
             None => {
                 warn!("Spin duration too long, skipping");
                 return;
@@ -96,6 +97,7 @@ impl time::interface::TimeManager for GenericTimer {
             None
         };
 
+        #[allow(unused_imports)]
         if let Some(w) = warn {
             warn!(
                 "Spin duration {} than architecturally supported, skipping",

13_exceptions_part2_peripheral_IRQs/src/panic_wait.rs

@@ -46,12 +46,25 @@ macro_rules! panic_println {
 
 #[panic_handler]
 fn panic(info: &PanicInfo) -> ! {
+    use crate::time::interface::TimeManager;
+
     unsafe { exception::asynchronous::local_irq_mask() };
 
+    let timestamp = crate::time::time_manager().uptime();
+
     if let Some(args) = info.message() {
-        panic_println!("\nKernel panic: {}", args);
+        panic_println!(
+            "[  {:>3}.{:06}] Kernel panic: {}",
+            timestamp.as_secs(),
+            timestamp.subsec_micros(),
+            args,
+        );
     } else {
-        panic_println!("\nKernel panic!");
+        panic_println!(
+            "[  {:>3}.{:06}] Kernel panic!",
+            timestamp.as_secs(),
+            timestamp.subsec_micros(),
+        );
     }
 
     _panic_exit()

13_exceptions_part2_peripheral_IRQs/src/print.rs

@@ -41,31 +41,25 @@ macro_rules! println {
 #[macro_export]
 macro_rules! info {
     ($string:expr) => ({
-        #[allow(unused_imports)]
-        use crate::time::interface::TimeManager;
+        use $crate::time::interface::TimeManager;
 
         let timestamp = $crate::time::time_manager().uptime();
-        let timestamp_subsec_us = timestamp.subsec_micros();
 
         $crate::print::_print(format_args_nl!(
-            concat!("[  {:>3}.{:03}{:03}] ", $string),
+            concat!("[  {:>3}.{:06}] ", $string),
             timestamp.as_secs(),
-            timestamp_subsec_us / 1_000,
-            timestamp_subsec_us % 1_000
+            timestamp.subsec_micros(),
         ));
     });
     ($format_string:expr, $($arg:tt)*) => ({
-        #[allow(unused_imports)]
-        use crate::time::interface::TimeManager;
+        use $crate::time::interface::TimeManager;
 
         let timestamp = $crate::time::time_manager().uptime();
-        let timestamp_subsec_us = timestamp.subsec_micros();
 
         $crate::print::_print(format_args_nl!(
-            concat!("[  {:>3}.{:03}{:03}] ", $format_string),
+            concat!("[  {:>3}.{:06}] ", $format_string),
             timestamp.as_secs(),
-            timestamp_subsec_us / 1_000,
-            timestamp_subsec_us % 1_000,
+            timestamp.subsec_micros(),
             $($arg)*
         ));
     })
@@ -75,31 +69,25 @@ macro_rules! info {
 #[macro_export]
 macro_rules! warn {
     ($string:expr) => ({
-        #[allow(unused_imports)]
-        use crate::time::interface::TimeManager;
+        use $crate::time::interface::TimeManager;
 
         let timestamp = $crate::time::time_manager().uptime();
-        let timestamp_subsec_us = timestamp.subsec_micros();
 
         $crate::print::_print(format_args_nl!(
-            concat!("[W {:>3}.{:03}{:03}] ", $string),
+            concat!("[W {:>3}.{:06}] ", $string),
             timestamp.as_secs(),
-            timestamp_subsec_us / 1_000,
-            timestamp_subsec_us % 1_000
+            timestamp.subsec_micros(),
         ));
     });
     ($format_string:expr, $($arg:tt)*) => ({
-        #[allow(unused_imports)]
-        use crate::time::interface::TimeManager;
+        use $crate::time::interface::TimeManager;
 
         let timestamp = $crate::time::time_manager().uptime();
-        let timestamp_subsec_us = timestamp.subsec_micros();
 
         $crate::print::_print(format_args_nl!(
-            concat!("[W {:>3}.{:03}{:03}] ", $format_string),
+            concat!("[W {:>3}.{:06}] ", $format_string),
             timestamp.as_secs(),
-            timestamp_subsec_us / 1_000,
-            timestamp_subsec_us % 1_000,
+            timestamp.subsec_micros(),
             $($arg)*
         ));
     })

13_exceptions_part2_peripheral_IRQs/tests/02_exception_sync_page_fault.rs

@@ -17,7 +17,7 @@
 /// or indirectly.
 mod panic_exit_success;
 
-use libkernel::{bsp, cpu, exception, memory, println};
+use libkernel::{bsp, cpu, exception, info, memory, println};
 
 #[no_mangle]
 unsafe fn kernel_init() -> ! {
@@ -30,11 +30,11 @@ unsafe fn kernel_init() -> ! {
     println!("Testing synchronous exception handling by causing a page fault");
 
     if let Err(string) = memory::mmu::mmu().enable_mmu_and_caching() {
-        println!("MMU: {}", string);
+        info!("MMU: {}", string);
         cpu::qemu_exit_failure()
     }
 
-    println!("Writing beyond mapped area to address 9 GiB...");
+    info!("Writing beyond mapped area to address 9 GiB...");
     let big_addr: u64 = 9 * 1024 * 1024 * 1024;
     core::ptr::read_volatile(big_addr as *mut u64);
 

14_virtual_mem_part2_mmio_remap/README.md

@@ -3609,17 +3609,17 @@ diff -uNr 13_exceptions_part2_peripheral_IRQs/tests/02_exception_sync_page_fault
      println!("Testing synchronous exception handling by causing a page fault");
 
 -    if let Err(string) = memory::mmu::mmu().enable_mmu_and_caching() {
--        println!("MMU: {}", string);
+-        info!("MMU: {}", string);
 +    let phys_kernel_tables_base_addr = match memory::mmu::kernel_map_binary() {
 +        Err(string) => {
-+            println!("Error mapping kernel binary: {}", string);
++            info!("Error mapping kernel binary: {}", string);
 +            cpu::qemu_exit_failure()
 +        }
 +        Ok(addr) => addr,
 +    };
 +
 +    if let Err(e) = memory::mmu::enable_mmu_and_caching(phys_kernel_tables_base_addr) {
-+        println!("Enabling MMU failed: {}", e);
++        info!("Enabling MMU failed: {}", e);
          cpu::qemu_exit_failure()
      }
 +    // Printing will silently fail from here on, because the driver's MMIO is not remapped yet.
@@ -3638,7 +3638,7 @@ diff -uNr 13_exceptions_part2_peripheral_IRQs/tests/02_exception_sync_page_fault
 +    bsp::driver::driver_manager().post_early_print_device_driver_init();
 +    // Printing available again from here on.
 
-     println!("Writing beyond mapped area to address 9 GiB...");
+     info!("Writing beyond mapped area to address 9 GiB...");
      let big_addr: u64 = 9 * 1024 * 1024 * 1024;
 
 ```

14_virtual_mem_part2_mmio_remap/src/_arch/aarch64/time.rs

@@ -78,6 +78,7 @@ impl time::interface::TimeManager for GenericTimer {
         // Calculate the register compare value.
         let frq = CNTFRQ_EL0.get();
         let x = match frq.checked_mul(duration.as_nanos() as u64) {
+            #[allow(unused_imports)]
             None => {
                 warn!("Spin duration too long, skipping");
                 return;
@@ -96,6 +97,7 @@ impl time::interface::TimeManager for GenericTimer {
             None
         };
 
+        #[allow(unused_imports)]
         if let Some(w) = warn {
             warn!(
                 "Spin duration {} than architecturally supported, skipping",

14_virtual_mem_part2_mmio_remap/src/panic_wait.rs

@@ -46,12 +46,25 @@ macro_rules! panic_println {
 
 #[panic_handler]
 fn panic(info: &PanicInfo) -> ! {
+    use crate::time::interface::TimeManager;
+
     unsafe { exception::asynchronous::local_irq_mask() };
 
+    let timestamp = crate::time::time_manager().uptime();
+
     if let Some(args) = info.message() {
-        panic_println!("\nKernel panic: {}", args);
+        panic_println!(
+            "[  {:>3}.{:06}] Kernel panic: {}",
+            timestamp.as_secs(),
+            timestamp.subsec_micros(),
+            args,
+        );
     } else {
-        panic_println!("\nKernel panic!");
+        panic_println!(
+            "[  {:>3}.{:06}] Kernel panic!",
+            timestamp.as_secs(),
+            timestamp.subsec_micros(),
+        );
     }
 
     _panic_exit()

14_virtual_mem_part2_mmio_remap/src/print.rs

@@ -41,31 +41,25 @@ macro_rules! println {
 #[macro_export]
 macro_rules! info {
     ($string:expr) => ({
-        #[allow(unused_imports)]
-        use crate::time::interface::TimeManager;
+        use $crate::time::interface::TimeManager;
 
         let timestamp = $crate::time::time_manager().uptime();
-        let timestamp_subsec_us = timestamp.subsec_micros();
 
         $crate::print::_print(format_args_nl!(
-            concat!("[  {:>3}.{:03}{:03}] ", $string),
+            concat!("[  {:>3}.{:06}] ", $string),
             timestamp.as_secs(),
-            timestamp_subsec_us / 1_000,
-            timestamp_subsec_us % 1_000
+            timestamp.subsec_micros(),
         ));
     });
     ($format_string:expr, $($arg:tt)*) => ({
-        #[allow(unused_imports)]
-        use crate::time::interface::TimeManager;
+        use $crate::time::interface::TimeManager;
 
         let timestamp = $crate::time::time_manager().uptime();
-        let timestamp_subsec_us = timestamp.subsec_micros();
 
         $crate::print::_print(format_args_nl!(
-            concat!("[  {:>3}.{:03}{:03}] ", $format_string),
+            concat!("[  {:>3}.{:06}] ", $format_string),
             timestamp.as_secs(),
-            timestamp_subsec_us / 1_000,
-            timestamp_subsec_us % 1_000,
+            timestamp.subsec_micros(),
             $($arg)*
         ));
     })
@@ -75,31 +69,25 @@ macro_rules! info {
 #[macro_export]
 macro_rules! warn {
     ($string:expr) => ({
-        #[allow(unused_imports)]
-        use crate::time::interface::TimeManager;
+        use $crate::time::interface::TimeManager;
 
         let timestamp = $crate::time::time_manager().uptime();
-        let timestamp_subsec_us = timestamp.subsec_micros();
 
         $crate::print::_print(format_args_nl!(
-            concat!("[W {:>3}.{:03}{:03}] ", $string),
+            concat!("[W {:>3}.{:06}] ", $string),
             timestamp.as_secs(),
-            timestamp_subsec_us / 1_000,
-            timestamp_subsec_us % 1_000
+            timestamp.subsec_micros(),
         ));
     });
     ($format_string:expr, $($arg:tt)*) => ({
-        #[allow(unused_imports)]
-        use crate::time::interface::TimeManager;
+        use $crate::time::interface::TimeManager;
 
         let timestamp = $crate::time::time_manager().uptime();
-        let timestamp_subsec_us = timestamp.subsec_micros();
 
         $crate::print::_print(format_args_nl!(
-            concat!("[W {:>3}.{:03}{:03}] ", $format_string),
+            concat!("[W {:>3}.{:06}] ", $format_string),
             timestamp.as_secs(),
-            timestamp_subsec_us / 1_000,
-            timestamp_subsec_us % 1_000,
+            timestamp.subsec_micros(),
             $($arg)*
         ));
     })

14_virtual_mem_part2_mmio_remap/tests/02_exception_sync_page_fault.rs

@@ -17,7 +17,7 @@
 /// or indirectly.
 mod panic_exit_success;
 
-use libkernel::{bsp, cpu, exception, memory, println};
+use libkernel::{bsp, cpu, exception, info, memory, println};
 
 #[no_mangle]
 unsafe fn kernel_init() -> ! {
@@ -30,14 +30,14 @@ unsafe fn kernel_init() -> ! {
 
     let phys_kernel_tables_base_addr = match memory::mmu::kernel_map_binary() {
         Err(string) => {
-            println!("Error mapping kernel binary: {}", string);
+            info!("Error mapping kernel binary: {}", string);
             cpu::qemu_exit_failure()
         }
         Ok(addr) => addr,
     };
 
     if let Err(e) = memory::mmu::enable_mmu_and_caching(phys_kernel_tables_base_addr) {
-        println!("Enabling MMU failed: {}", e);
+        info!("Enabling MMU failed: {}", e);
         cpu::qemu_exit_failure()
     }
     // Printing will silently fail from here on, because the driver's MMIO is not remapped yet.
@@ -56,7 +56,7 @@ unsafe fn kernel_init() -> ! {
     bsp::driver::driver_manager().post_early_print_device_driver_init();
     // Printing available again from here on.
 
-    println!("Writing beyond mapped area to address 9 GiB...");
+    info!("Writing beyond mapped area to address 9 GiB...");
     let big_addr: u64 = 9 * 1024 * 1024 * 1024;
     core::ptr::read_volatile(big_addr as *mut u64);
 

15_virtual_mem_part3_precomputed_tables/README.md

@@ -1739,14 +1739,14 @@ diff -uNr 14_virtual_mem_part2_mmio_remap/tests/02_exception_sync_page_fault.rs
 -
 -    let phys_kernel_tables_base_addr = match memory::mmu::kernel_map_binary() {
 -        Err(string) => {
--            println!("Error mapping kernel binary: {}", string);
+-            info!("Error mapping kernel binary: {}", string);
 -            cpu::qemu_exit_failure()
 -        }
 -        Ok(addr) => addr,
 -    };
 -
 -    if let Err(e) = memory::mmu::enable_mmu_and_caching(phys_kernel_tables_base_addr) {
--        println!("Enabling MMU failed: {}", e);
+-        info!("Enabling MMU failed: {}", e);
 -        cpu::qemu_exit_failure()
 -    }
 -    // Printing will silently fail from here on, because the driver's MMIO is not remapped yet.
@@ -1767,7 +1767,7 @@ diff -uNr 14_virtual_mem_part2_mmio_remap/tests/02_exception_sync_page_fault.rs
 +    // This line will be printed as the test header.
 +    println!("Testing synchronous exception handling by causing a page fault");
 
-     println!("Writing beyond mapped area to address 9 GiB...");
+     info!("Writing beyond mapped area to address 9 GiB...");
      let big_addr: u64 = 9 * 1024 * 1024 * 1024;
 
 diff -uNr 14_virtual_mem_part2_mmio_remap/tests/03_exception_irq_sanity.rs 15_virtual_mem_part3_precomputed_tables/tests/03_exception_irq_sanity.rs

15_virtual_mem_part3_precomputed_tables/src/_arch/aarch64/time.rs

@@ -78,6 +78,7 @@ impl time::interface::TimeManager for GenericTimer {
         // Calculate the register compare value.
         let frq = CNTFRQ_EL0.get();
         let x = match frq.checked_mul(duration.as_nanos() as u64) {
+            #[allow(unused_imports)]
             None => {
                 warn!("Spin duration too long, skipping");
                 return;
@@ -96,6 +97,7 @@ impl time::interface::TimeManager for GenericTimer {
             None
         };
 
+        #[allow(unused_imports)]
         if let Some(w) = warn {
             warn!(
                 "Spin duration {} than architecturally supported, skipping",

15_virtual_mem_part3_precomputed_tables/src/panic_wait.rs

@@ -46,12 +46,25 @@ macro_rules! panic_println {
 
 #[panic_handler]
 fn panic(info: &PanicInfo) -> ! {
+    use crate::time::interface::TimeManager;
+
     unsafe { exception::asynchronous::local_irq_mask() };
 
+    let timestamp = crate::time::time_manager().uptime();
+
     if let Some(args) = info.message() {
-        panic_println!("\nKernel panic: {}", args);
+        panic_println!(
+            "[  {:>3}.{:06}] Kernel panic: {}",
+            timestamp.as_secs(),
+            timestamp.subsec_micros(),
+            args,
+        );
     } else {
-        panic_println!("\nKernel panic!");
+        panic_println!(
+            "[  {:>3}.{:06}] Kernel panic!",
+            timestamp.as_secs(),
+            timestamp.subsec_micros(),
+        );
     }
 
     _panic_exit()

15_virtual_mem_part3_precomputed_tables/src/print.rs

@@ -41,31 +41,25 @@ macro_rules! println {
 #[macro_export]
 macro_rules! info {
     ($string:expr) => ({
-        #[allow(unused_imports)]
-        use crate::time::interface::TimeManager;
+        use $crate::time::interface::TimeManager;
 
         let timestamp = $crate::time::time_manager().uptime();
-        let timestamp_subsec_us = timestamp.subsec_micros();
 
         $crate::print::_print(format_args_nl!(
-            concat!("[  {:>3}.{:03}{:03}] ", $string),
+            concat!("[  {:>3}.{:06}] ", $string),
             timestamp.as_secs(),
-            timestamp_subsec_us / 1_000,
-            timestamp_subsec_us % 1_000
+            timestamp.subsec_micros(),
         ));
     });
     ($format_string:expr, $($arg:tt)*) => ({
-        #[allow(unused_imports)]
-        use crate::time::interface::TimeManager;
+        use $crate::time::interface::TimeManager;
 
         let timestamp = $crate::time::time_manager().uptime();
-        let timestamp_subsec_us = timestamp.subsec_micros();
 
         $crate::print::_print(format_args_nl!(
-            concat!("[  {:>3}.{:03}{:03}] ", $format_string),
+            concat!("[  {:>3}.{:06}] ", $format_string),
             timestamp.as_secs(),
-            timestamp_subsec_us / 1_000,
-            timestamp_subsec_us % 1_000,
+            timestamp.subsec_micros(),
             $($arg)*
         ));
     })
@@ -75,31 +69,25 @@ macro_rules! info {
 #[macro_export]
 macro_rules! warn {
     ($string:expr) => ({
-        #[allow(unused_imports)]
-        use crate::time::interface::TimeManager;
+        use $crate::time::interface::TimeManager;
 
         let timestamp = $crate::time::time_manager().uptime();
-        let timestamp_subsec_us = timestamp.subsec_micros();
 
         $crate::print::_print(format_args_nl!(
-            concat!("[W {:>3}.{:03}{:03}] ", $string),
+            concat!("[W {:>3}.{:06}] ", $string),
             timestamp.as_secs(),
-            timestamp_subsec_us / 1_000,
-            timestamp_subsec_us % 1_000
+            timestamp.subsec_micros(),
         ));
     });
     ($format_string:expr, $($arg:tt)*) => ({
-        #[allow(unused_imports)]
-        use crate::time::interface::TimeManager;
+        use $crate::time::interface::TimeManager;
 
         let timestamp = $crate::time::time_manager().uptime();
-        let timestamp_subsec_us = timestamp.subsec_micros();
 
         $crate::print::_print(format_args_nl!(
-            concat!("[W {:>3}.{:03}{:03}] ", $format_string),
+            concat!("[W {:>3}.{:06}] ", $format_string),
             timestamp.as_secs(),
-            timestamp_subsec_us / 1_000,
-            timestamp_subsec_us % 1_000,
+            timestamp.subsec_micros(),
             $($arg)*
         ));
     })

15_virtual_mem_part3_precomputed_tables/tests/02_exception_sync_page_fault.rs

@@ -17,7 +17,7 @@
 /// or indirectly.
 mod panic_exit_success;
 
-use libkernel::{bsp, cpu, exception, memory, println};
+use libkernel::{bsp, cpu, exception, info, memory, println};
 
 #[no_mangle]
 unsafe fn kernel_init() -> ! {
@@ -28,7 +28,7 @@ unsafe fn kernel_init() -> ! {
     // This line will be printed as the test header.
     println!("Testing synchronous exception handling by causing a page fault");
 
-    println!("Writing beyond mapped area to address 9 GiB...");
+    info!("Writing beyond mapped area to address 9 GiB...");
     let big_addr: u64 = 9 * 1024 * 1024 * 1024;
     core::ptr::read_volatile(big_addr as *mut u64);
 

16_virtual_mem_part4_higher_half_kernel/README.md

@@ -877,9 +877,9 @@ diff -uNr 15_virtual_mem_part3_precomputed_tables/tests/02_exception_sync_page_f
      // This line will be printed as the test header.
      println!("Testing synchronous exception handling by causing a page fault");
 
--    println!("Writing beyond mapped area to address 9 GiB...");
+-    info!("Writing beyond mapped area to address 9 GiB...");
 -    let big_addr: u64 = 9 * 1024 * 1024 * 1024;
-+    println!("Writing to bottom of address space to address 1 GiB...");
++    info!("Writing to bottom of address space to address 1 GiB...");
 +    let big_addr: u64 = 1 * 1024 * 1024 * 1024;
      core::ptr::read_volatile(big_addr as *mut u64);
 

16_virtual_mem_part4_higher_half_kernel/src/_arch/aarch64/time.rs

@@ -78,6 +78,7 @@ impl time::interface::TimeManager for GenericTimer {
         // Calculate the register compare value.
         let frq = CNTFRQ_EL0.get();
         let x = match frq.checked_mul(duration.as_nanos() as u64) {
+            #[allow(unused_imports)]
             None => {
                 warn!("Spin duration too long, skipping");
                 return;
@@ -96,6 +97,7 @@ impl time::interface::TimeManager for GenericTimer {
             None
         };
 
+        #[allow(unused_imports)]
         if let Some(w) = warn {
             warn!(
                 "Spin duration {} than architecturally supported, skipping",

16_virtual_mem_part4_higher_half_kernel/src/panic_wait.rs

@@ -46,12 +46,25 @@ macro_rules! panic_println {
 
 #[panic_handler]
 fn panic(info: &PanicInfo) -> ! {
+    use crate::time::interface::TimeManager;
+
     unsafe { exception::asynchronous::local_irq_mask() };
 
+    let timestamp = crate::time::time_manager().uptime();
+
     if let Some(args) = info.message() {
-        panic_println!("\nKernel panic: {}", args);
+        panic_println!(
+            "[  {:>3}.{:06}] Kernel panic: {}",
+            timestamp.as_secs(),
+            timestamp.subsec_micros(),
+            args,
+        );
     } else {
-        panic_println!("\nKernel panic!");
+        panic_println!(
+            "[  {:>3}.{:06}] Kernel panic!",
+            timestamp.as_secs(),
+            timestamp.subsec_micros(),
+        );
     }
 
     _panic_exit()

16_virtual_mem_part4_higher_half_kernel/src/print.rs

@@ -41,31 +41,25 @@ macro_rules! println {
 #[macro_export]
 macro_rules! info {
     ($string:expr) => ({
-        #[allow(unused_imports)]
-        use crate::time::interface::TimeManager;
+        use $crate::time::interface::TimeManager;
 
         let timestamp = $crate::time::time_manager().uptime();
-        let timestamp_subsec_us = timestamp.subsec_micros();
 
         $crate::print::_print(format_args_nl!(
-            concat!("[  {:>3}.{:03}{:03}] ", $string),
+            concat!("[  {:>3}.{:06}] ", $string),
             timestamp.as_secs(),
-            timestamp_subsec_us / 1_000,
-            timestamp_subsec_us % 1_000
+            timestamp.subsec_micros(),
         ));
     });
     ($format_string:expr, $($arg:tt)*) => ({
-        #[allow(unused_imports)]
-        use crate::time::interface::TimeManager;
+        use $crate::time::interface::TimeManager;
 
         let timestamp = $crate::time::time_manager().uptime();
-        let timestamp_subsec_us = timestamp.subsec_micros();
 
         $crate::print::_print(format_args_nl!(
-            concat!("[  {:>3}.{:03}{:03}] ", $format_string),
+            concat!("[  {:>3}.{:06}] ", $format_string),
             timestamp.as_secs(),
-            timestamp_subsec_us / 1_000,
-            timestamp_subsec_us % 1_000,
+            timestamp.subsec_micros(),
             $($arg)*
         ));
     })
@@ -75,31 +69,25 @@ macro_rules! info {
 #[macro_export]
 macro_rules! warn {
     ($string:expr) => ({
-        #[allow(unused_imports)]
-        use crate::time::interface::TimeManager;
+        use $crate::time::interface::TimeManager;
 
         let timestamp = $crate::time::time_manager().uptime();
-        let timestamp_subsec_us = timestamp.subsec_micros();
 
         $crate::print::_print(format_args_nl!(
-            concat!("[W {:>3}.{:03}{:03}] ", $string),
+            concat!("[W {:>3}.{:06}] ", $string),
             timestamp.as_secs(),
-            timestamp_subsec_us / 1_000,
-            timestamp_subsec_us % 1_000
+            timestamp.subsec_micros(),
         ));
     });
     ($format_string:expr, $($arg:tt)*) => ({
-        #[allow(unused_imports)]
-        use crate::time::interface::TimeManager;
+        use $crate::time::interface::TimeManager;
 
         let timestamp = $crate::time::time_manager().uptime();
-        let timestamp_subsec_us = timestamp.subsec_micros();
 
         $crate::print::_print(format_args_nl!(
-            concat!("[W {:>3}.{:03}{:03}] ", $format_string),
+            concat!("[W {:>3}.{:06}] ", $format_string),
             timestamp.as_secs(),
-            timestamp_subsec_us / 1_000,
-            timestamp_subsec_us % 1_000,
+            timestamp.subsec_micros(),
             $($arg)*
         ));
     })

16_virtual_mem_part4_higher_half_kernel/tests/02_exception_sync_page_fault.rs

@@ -17,7 +17,7 @@
 /// or indirectly.
 mod panic_exit_success;
 
-use libkernel::{bsp, cpu, exception, memory, println};
+use libkernel::{bsp, cpu, exception, info, memory, println};
 
 #[no_mangle]
 unsafe fn kernel_init() -> ! {
@@ -28,7 +28,7 @@ unsafe fn kernel_init() -> ! {
     // This line will be printed as the test header.
     println!("Testing synchronous exception handling by causing a page fault");
 
-    println!("Writing to bottom of address space to address 1 GiB...");
+    info!("Writing to bottom of address space to address 1 GiB...");
     let big_addr: u64 = 1 * 1024 * 1024 * 1024;
     core::ptr::read_volatile(big_addr as *mut u64);
 

X1_JTAG_boot/src/_arch/aarch64/time.rs

@@ -78,6 +78,7 @@ impl time::interface::TimeManager for GenericTimer {
         // Calculate the register compare value.
         let frq = CNTFRQ_EL0.get();
         let x = match frq.checked_mul(duration.as_nanos() as u64) {
+            #[allow(unused_imports)]
             None => {
                 warn!("Spin duration too long, skipping");
                 return;
@@ -96,6 +97,7 @@ impl time::interface::TimeManager for GenericTimer {
             None
         };
 
+        #[allow(unused_imports)]
         if let Some(w) = warn {
             warn!(
                 "Spin duration {} than architecturally supported, skipping",

X1_JTAG_boot/src/panic_wait.rs

@@ -29,10 +29,23 @@ macro_rules! panic_println {
 
 #[panic_handler]
 fn panic(info: &PanicInfo) -> ! {
+    use crate::time::interface::TimeManager;
+
+    let timestamp = crate::time::time_manager().uptime();
+
     if let Some(args) = info.message() {
-        panic_println!("\nKernel panic: {}", args);
+        panic_println!(
+            "[  {:>3}.{:06}] Kernel panic: {}",
+            timestamp.as_secs(),
+            timestamp.subsec_micros(),
+            args,
+        );
     } else {
-        panic_println!("\nKernel panic!");
+        panic_println!(
+            "[  {:>3}.{:06}] Kernel panic!",
+            timestamp.as_secs(),
+            timestamp.subsec_micros(),
+        );
     }
 
     cpu::wait_forever()

X1_JTAG_boot/src/print.rs

@@ -41,31 +41,25 @@ macro_rules! println {
 #[macro_export]
 macro_rules! info {
     ($string:expr) => ({
-        #[allow(unused_imports)]
-        use crate::time::interface::TimeManager;
+        use $crate::time::interface::TimeManager;
 
         let timestamp = $crate::time::time_manager().uptime();
-        let timestamp_subsec_us = timestamp.subsec_micros();
 
         $crate::print::_print(format_args_nl!(
-            concat!("[  {:>3}.{:03}{:03}] ", $string),
+            concat!("[  {:>3}.{:06}] ", $string),
             timestamp.as_secs(),
-            timestamp_subsec_us / 1_000,
-            timestamp_subsec_us % 1_000
+            timestamp.subsec_micros(),
         ));
     });
     ($format_string:expr, $($arg:tt)*) => ({
-        #[allow(unused_imports)]
-        use crate::time::interface::TimeManager;
+        use $crate::time::interface::TimeManager;
 
         let timestamp = $crate::time::time_manager().uptime();
-        let timestamp_subsec_us = timestamp.subsec_micros();
 
         $crate::print::_print(format_args_nl!(
-            concat!("[  {:>3}.{:03}{:03}] ", $format_string),
+            concat!("[  {:>3}.{:06}] ", $format_string),
             timestamp.as_secs(),
-            timestamp_subsec_us / 1_000,
-            timestamp_subsec_us % 1_000,
+            timestamp.subsec_micros(),
             $($arg)*
         ));
     })
@@ -75,31 +69,25 @@ macro_rules! info {
 #[macro_export]
 macro_rules! warn {
     ($string:expr) => ({
-        #[allow(unused_imports)]
-        use crate::time::interface::TimeManager;
+        use $crate::time::interface::TimeManager;
 
         let timestamp = $crate::time::time_manager().uptime();
-        let timestamp_subsec_us = timestamp.subsec_micros();
 
         $crate::print::_print(format_args_nl!(
-            concat!("[W {:>3}.{:03}{:03}] ", $string),
+            concat!("[W {:>3}.{:06}] ", $string),
             timestamp.as_secs(),
-            timestamp_subsec_us / 1_000,
-            timestamp_subsec_us % 1_000
+            timestamp.subsec_micros(),
         ));
     });
     ($format_string:expr, $($arg:tt)*) => ({
-        #[allow(unused_imports)]
-        use crate::time::interface::TimeManager;
+        use $crate::time::interface::TimeManager;
 
         let timestamp = $crate::time::time_manager().uptime();
-        let timestamp_subsec_us = timestamp.subsec_micros();
 
         $crate::print::_print(format_args_nl!(
-            concat!("[W {:>3}.{:03}{:03}] ", $format_string),
+            concat!("[W {:>3}.{:06}] ", $format_string),
             timestamp.as_secs(),
-            timestamp_subsec_us / 1_000,
-            timestamp_subsec_us % 1_000,
+            timestamp.subsec_micros(),
             $($arg)*
         ));
     })