Merge #897

897: Add support for `rtos-trace` behind a feature flag r=lulf a=quentinmit

This allows SystemView to be used to profile the behavior of the user's application.

Co-authored-by: Quentin Smith <quentin@mit.edu>

embassy-executor/Cargo.toml

@@ -30,9 +30,13 @@ nightly = []
 
 integrated-timers = ["dep:embassy-time"]
 
+# Trace interrupt invocations with rtos-trace.
+rtos-trace-interrupt = ["rtos-trace"]
+
 [dependencies]
 defmt = { version = "0.3", optional = true }
 log = { version = "0.4.14", optional = true }
+rtos-trace = { version = "0.1.2", optional = true }
 
 futures-util = { version = "0.3.17", default-features = false }
 embassy-macros  = { version = "0.1.0", path = "../embassy-macros"}

embassy-executor/src/lib.rs

@@ -38,6 +38,31 @@ cfg_if::cfg_if! {
     }
 }
 
+#[doc(hidden)]
+/// Implementation details for embassy macros. DO NOT USE.
+pub mod export {
+    #[cfg(feature = "rtos-trace")]
+    pub use rtos_trace::trace;
+
+    /// Expands the given block of code when `embassy-executor` is compiled with
+    /// the `rtos-trace-interrupt` feature.
+    #[doc(hidden)]
+    #[macro_export]
+    #[cfg(feature = "rtos-trace-interrupt")]
+    macro_rules! rtos_trace_interrupt {
+        ($($tt:tt)*) => { $($tt)* };
+    }
+
+    /// Does not expand the given block of code when `embassy-executor` is
+    /// compiled without the `rtos-trace-interrupt` feature.
+    #[doc(hidden)]
+    #[macro_export]
+    #[cfg(not(feature = "rtos-trace-interrupt"))]
+    macro_rules! rtos_trace_interrupt {
+        ($($tt:tt)*) => {};
+    }
+}
+
 pub mod raw;
 
 mod spawner;

embassy-executor/src/raw/mod.rs

@@ -26,6 +26,8 @@ use critical_section::CriticalSection;
 use embassy_time::driver::{self, AlarmHandle};
 #[cfg(feature = "integrated-timers")]
 use embassy_time::Instant;
+#[cfg(feature = "rtos-trace")]
+use rtos_trace::trace;
 
 use self::run_queue::{RunQueue, RunQueueItem};
 use self::util::UninitCell;
@@ -306,6 +308,9 @@ impl Executor {
     /// - `task` must NOT be already enqueued (in this executor or another one).
     #[inline(always)]
     unsafe fn enqueue(&self, cs: CriticalSection, task: NonNull<TaskHeader>) {
+        #[cfg(feature = "rtos-trace")]
+        trace::task_ready_begin(task.as_ptr() as u32);
+
         if self.run_queue.enqueue(cs, task) {
             (self.signal_fn)(self.signal_ctx)
         }
@@ -323,6 +328,9 @@ impl Executor {
     pub(super) unsafe fn spawn(&'static self, task: NonNull<TaskHeader>) {
         task.as_ref().executor.set(self);
 
+        #[cfg(feature = "rtos-trace")]
+        trace::task_new(task.as_ptr() as u32);
+
         critical_section::with(|cs| {
             self.enqueue(cs, task);
         })
@@ -365,9 +373,15 @@ impl Executor {
                 return;
             }
 
+            #[cfg(feature = "rtos-trace")]
+            trace::task_exec_begin(p.as_ptr() as u32);
+
             // Run the task
             task.poll_fn.read()(p as _);
 
+            #[cfg(feature = "rtos-trace")]
+            trace::task_exec_end();
+
             // Enqueue or update into timer_queue
             #[cfg(feature = "integrated-timers")]
             self.timer_queue.update(p);
@@ -381,6 +395,9 @@ impl Executor {
             let next_expiration = self.timer_queue.next_expiration();
             driver::set_alarm(self.alarm, next_expiration.as_ticks());
         }
+
+        #[cfg(feature = "rtos-trace")]
+        trace::system_idle();
     }
 
     /// Get a spawner that spawns tasks in this executor.
@@ -426,3 +443,21 @@ unsafe fn _embassy_time_schedule_wake(at: Instant, waker: &core::task::Waker) {
     let expires_at = task.expires_at.get();
     task.expires_at.set(expires_at.min(at));
 }
+
+#[cfg(feature = "rtos-trace")]
+impl rtos_trace::RtosTraceOSCallbacks for Executor {
+    fn task_list() {
+        // We don't know what tasks exist, so we can't send them.
+    }
+    #[cfg(feature = "integrated-timers")]
+    fn time() -> u64 {
+        Instant::now().as_micros()
+    }
+    #[cfg(not(feature = "integrated-timers"))]
+    fn time() -> u64 {
+        0
+    }
+}
+
+#[cfg(feature = "rtos-trace")]
+rtos_trace::global_os_callbacks! {Executor}

embassy-macros/src/macros/cortex_m_interrupt_take.rs

@@ -19,7 +19,13 @@ pub fn run(name: syn::Ident) -> Result<TokenStream, TokenStream> {
                 let func = HANDLER.func.load(interrupt::_export::atomic::Ordering::Relaxed);
                 let ctx = HANDLER.ctx.load(interrupt::_export::atomic::Ordering::Relaxed);
                 let func: fn(*mut ()) = ::core::mem::transmute(func);
-                func(ctx)
+                ::embassy_executor::rtos_trace_interrupt! {
+                    ::embassy_executor::export::trace::isr_enter();
+                }
+                func(ctx);
+                ::embassy_executor::rtos_trace_interrupt! {
+                    ::embassy_executor::export::trace::isr_exit();
+                }
             }
 
             static TAKEN: interrupt::_export::atomic::AtomicBool = interrupt::_export::atomic::AtomicBool::new(false);

examples/nrf-rtos-trace/.cargo/config.toml

@@ -0,0 +1,9 @@
+[target.'cfg(all(target_arch = "arm", target_os = "none"))']
+# replace nRF82840_xxAA with your chip as listed in `probe-run --list-chips`
+runner = "probe-run --chip nRF52840_xxAA"
+
+[build]
+target = "thumbv7em-none-eabi"
+
+[env]
+DEFMT_LOG = "trace"

examples/nrf-rtos-trace/Cargo.toml

@@ -0,0 +1,35 @@
+[package]
+edition = "2021"
+name = "embassy-nrf-rtos-trace-examples"
+version = "0.1.0"
+
+[features]
+default = ["log", "nightly"]
+nightly = ["embassy-executor/nightly", "embassy-nrf/nightly", "embassy-nrf/unstable-traits"]
+log = [
+    "dep:log",
+    "embassy-util/log",
+    "embassy-executor/log",
+    "embassy-time/log",
+    "embassy-nrf/log",
+]
+
+[dependencies]
+embassy-util = { version = "0.1.0", path = "../../embassy-util" }
+embassy-executor = { version = "0.1.0", path = "../../embassy-executor", features=["rtos-trace", "rtos-trace-interrupt", "integrated-timers"] }
+embassy-time = { version = "0.1.0", path = "../../embassy-time" }
+embassy-nrf = { version = "0.1.0", path = "../../embassy-nrf", features = ["nrf52840", "time-driver-rtc1", "gpiote", "unstable-pac"] }
+
+cortex-m = { version = "0.7.6", features = ["critical-section-single-core"] }
+cortex-m-rt = "0.7.0"
+panic-probe = { version = "0.3" }
+futures = { version = "0.3.17", default-features = false, features = ["async-await"] }
+rand = { version = "0.8.4", default-features = false }
+serde = { version = "1.0.136", default-features = false }
+rtos-trace = "0.1.3"
+systemview-target = { version = "0.1.2", features = ["callbacks-app", "callbacks-os", "log", "cortex-m"] }
+log = { version = "0.4.17", optional = true }
+
+[[bin]]
+name = "rtos_trace"
+required-features = ["nightly"]

examples/nrf-rtos-trace/build.rs

@@ -0,0 +1,36 @@
+//! This build script copies the `memory.x` file from the crate root into
+//! a directory where the linker can always find it at build time.
+//! For many projects this is optional, as the linker always searches the
+//! project root directory -- wherever `Cargo.toml` is. However, if you
+//! are using a workspace or have a more complicated build setup, this
+//! build script becomes required. Additionally, by requesting that
+//! Cargo re-run the build script whenever `memory.x` is changed,
+//! updating `memory.x` ensures a rebuild of the application with the
+//! new memory settings.
+
+use std::env;
+use std::fs::File;
+use std::io::Write;
+use std::path::PathBuf;
+
+fn main() {
+    // Put `memory.x` in our output directory and ensure it's
+    // on the linker search path.
+    let out = &PathBuf::from(env::var_os("OUT_DIR").unwrap());
+    File::create(out.join("memory.x"))
+        .unwrap()
+        .write_all(include_bytes!("memory.x"))
+        .unwrap();
+    println!("cargo:rustc-link-search={}", out.display());
+
+    // By default, Cargo will re-run a build script whenever
+    // any file in the project changes. By specifying `memory.x`
+    // here, we ensure the build script is only re-run when
+    // `memory.x` is changed.
+    println!("cargo:rerun-if-changed=memory.x");
+
+    println!("cargo:rustc-link-arg-bins=--nmagic");
+    println!("cargo:rustc-link-arg-bins=-Tlink.x");
+    #[cfg(feature = "defmt")]
+    println!("cargo:rustc-link-arg-bins=-Tdefmt.x");
+}

examples/nrf-rtos-trace/memory.x

@@ -0,0 +1,7 @@
+MEMORY
+{
+  /* NOTE 1 K = 1 KiBi = 1024 bytes */
+  /* These values correspond to the NRF52840 with Softdevices S140 7.0.1 */
+  FLASH : ORIGIN = 0x00000000, LENGTH = 1024K
+  RAM : ORIGIN = 0x20000000, LENGTH = 256K
+}

examples/nrf-rtos-trace/src/bin/rtos_trace.rs

@@ -0,0 +1,69 @@
+#![no_std]
+#![no_main]
+#![feature(type_alias_impl_trait)]
+
+use core::task::Poll;
+
+use embassy_executor::Spawner;
+use embassy_time::{Duration, Instant, Timer};
+#[cfg(feature = "log")]
+use log::*;
+use panic_probe as _;
+// N.B. systemview_target cannot be used at the same time as defmt_rtt.
+use rtos_trace;
+use systemview_target::SystemView;
+
+static LOGGER: systemview_target::SystemView = systemview_target::SystemView::new();
+rtos_trace::global_trace! {SystemView}
+
+struct TraceInfo();
+
+impl rtos_trace::RtosTraceApplicationCallbacks for TraceInfo {
+    fn system_description() {}
+    fn sysclock() -> u32 {
+        64000000
+    }
+}
+rtos_trace::global_application_callbacks! {TraceInfo}
+
+#[embassy_executor::task]
+async fn run1() {
+    loop {
+        #[cfg(feature = "log")]
+        info!("DING DONG");
+        #[cfg(not(feature = "log"))]
+        rtos_trace::trace::marker(13);
+        Timer::after(Duration::from_ticks(16000)).await;
+    }
+}
+
+#[embassy_executor::task]
+async fn run2() {
+    loop {
+        Timer::at(Instant::from_ticks(0)).await;
+    }
+}
+
+#[embassy_executor::task]
+async fn run3() {
+    futures::future::poll_fn(|cx| {
+        cx.waker().wake_by_ref();
+        Poll::<()>::Pending
+    })
+    .await;
+}
+
+#[embassy_executor::main]
+async fn main(spawner: Spawner) {
+    let _p = embassy_nrf::init(Default::default());
+    LOGGER.init();
+    #[cfg(feature = "log")]
+    {
+        ::log::set_logger(&LOGGER).ok();
+        ::log::set_max_level(::log::LevelFilter::Trace);
+    }
+
+    spawner.spawn(run1()).unwrap();
+    spawner.spawn(run2()).unwrap();
+    spawner.spawn(run3()).unwrap();
+}