cortex-m-funnel

A lock-free, wait-free, block-free logger for the ARM Cortex-M architecture

(lock-free as in logging doesn't block interrupt handlers; wait-free as in there's no spinning (e.g. CAS loop) to get a handle; and block-free as in the logger never waits for an I/O transfer (e.g. ITM, UART, etc.) to complete)

Status: ☢️ Experimental ☢️ (ALPHA PRE-RELEASE)

Documentation

License

Licensed under either of

• Apache License, Version 2.0 (LICENSE-APACHE or http://www.apache.org/licenses/LICENSE-2.0)
• MIT license (LICENSE-MIT or http://opensource.org/licenses/MIT)

at your option.

Contribution

Unless you explicitly state otherwise, any contribution intentionally submitted for inclusion in the work by you, as defined in the Apache-2.0 license, shall be dual licensed as above, without any additional terms or conditions.

lib.rs:

A lock-free, wait-free, block-free logger for the ARM Cortex-M architecture

(lock-free as in logging doesn't block interrupt handlers; wait-free as in there's no spinning (e.g. CAS loop) to get a handle; and block-free as in the logger never waits for an I/O transfer (e.g. ITM, UART, etc.) to complete)

Status: ☢️ Experimental ☢️ (ALPHA PRE-RELEASE)

SUPER IMPORTANT Using this crate in a threaded environment will result in an unsound program! You have been warned! Also, multi-core support has not been thought out at all so this is likely wrong when used in multi-core context.

Working principle

There's one ring buffer per priority level. Logging from an interrupt / exception handler will simply write the message into one of these ring buffers. Thus logging is effectively 'I/O less' and as fast as a memcpy. Only the 'thread handler' (AKA main or idle in RTFM apps) can drain these ring buffers into an appropriate I/O sink (e.g. the ITM).

Nothing is without trade-offs in this life; this logger uses plenty of static memory (i.e. RAM) in exchange for fast and predictable logging performance. Also, compared to loggers that directly do I/O this logger will, in overall, spend more CPU cycles to log the same amount of data but most of the work will be done at the lowest priority making logging in interrupt handlers much faster.

Examples

Usual setup

Application crate:

// aligned = "0.3.2"
use aligned::Aligned;
use cortex_m::itm;

use funnel::{Drain, funnel, info, trace};

// `NVIC_PRIO_BITS` is the number of priority bits supported by the device
//
// The `NVIC_PRIO_BITS` value can be a literal integer (e.g. `3`) or a path to a constant
// (`stm32f103xx::NVIC_PRIO_BITS`)
//
// This macro call can only appear *once* in the dependency graph and *must* appear if any
// of the `funnel` macros or the `Logger::get()` API is used anywhere in the dependency graph
funnel!(NVIC_PRIO_BITS = 3, {
     // syntax: $logical_priority : $ring_buffer_size_in_bytes
     // to get better performance use sizes that are a power of 2
     1: 32,
     2: 64,

     // not listing a priority here disables logging at that priority level
     // entering the wrong NVIC_PRIO_BITS value will disable most loggers
});

#[entry]
fn main() -> ! {
    // ..
    let mut itm: ITM = /* .. */;

    let drains = Drain::get_all();

    let mut buf = Aligned([0; 32]); // 4-byte aligned buffer
    loop {
        for (i, drain) in drains.iter().enumerate() {
            'l: loop {
                let n = drain.read(&mut buf).len();

                // this drain is empty
                if n == 0 {
                    break 'l;
                }

                // we need this coercion or the slicing below won't do the right thing
                let buf: &Aligned<_, [_]> = &buf;

                // will send data in 32-bit chunks
                itm::write_aligned(&mut itm.stim[i], &buf[..n]);
            }
        }
    }
}

// logical_priority = 1 (nvic_priority = 224)
#[interrupt]
fn GPIOA() {
    info!("GPIOA");
    foo(0);
    // ..
}

// logical_priority = 2 (nvic_priority = 192)
#[interrupt]
fn GPIOB() {
    info!("GPIOB");
    foo(1);
    // ..
}

fn foo(x: i32) {
    // this macro can appear in libraries
    trace!("foo({})", x);
    // ..
}

Logger

The overhead of each macro call can be reduced using one of the uwrite! macros on a Logger. A Logger can only be obtained using the Logger::get() constructor.

use funnel::{Logger, log_enabled};

#[interrupt]
fn GPIOC() {
    if let Some(mut logger) = Logger::get() {
         if log_enabled!(Info) {
             uwriteln!(logger, "{}", 100).ok();
             uwriteln!(logger, "{:?}", some_value).ok();
         }
    }
}

Logging levels

funnel supports 5 logging level: Trace, Debug, Info, Warn and Error, sorted in increasing level of severity. Each of these logging level has an associated logging macro: trace!, debug!, info!, warn! and error!.

Logs of lesser severity can be statically disabled using of these Cargo features.

• max_level_trace
• max_level_debug
• max_level_info
• max_level_warn
• max_level_error
• max_level_off
• release_max_level_trace
• release_max_level_debug
• release_max_level_info
• release_max_level_warn
• release_max_level_error
• release_max_level_off

Enabling the max_level_info feature will disable the Debug and Trace logging levels; max_level_off will disable all logging levels. The release_* features apply when the application is compiled using the 'release' profile; the other features apply when the 'dev' profile is used. To check if a logging level is enabled or disabled in code use the log_enabled! macro.

Benchmarks

Ran on Cortex-M3 core clocked at 8 MHz and configured with 0 Flash wait cycles.

Where S is a 45-byte long string, N = usize::max_value(), the drain function is ptr::read_volatile-ing each byte and the ITM was clocked at 2 MHz.

Potential improvements / alternatives

Instead of draining the ring buffers at the lowest priority one could drain the buffers using the debugger using something like SEGGER's Real Time Transfer mechanism. The implementation would need to change to properly support this form of parallel draining.