defmt

defmt is a highly efficient logging framework that targets resource-constrained devices, like microcontrollers.

Features

  • println!-like formatting
  • Multiple logging levels: error, info, warn, debug, trace
  • Crate-level logging level filters
  • Timestamped logs

Current limitations

  • Output object format must be ELF
  • Custom linking (linker script) is required
  • Single, global logger instance (but using multiple channels is possible)

Intended use

In its current iteration defmt mainly targets tiny embedded devices that have no mean to display information to the developer, e.g. a screen. In this scenario logs need to be transferred to a second machine, usually a PC/laptop, before they can be displayed to the developer/end-user.

defmt operating principles, however, are applicable to beefier machines and could be use to improve the logging performance of x86 web server applications and the like.

Operating principle

defmt achieves high performance using deferred formatting and string compression.

Deferred formatting means that formatting is not done on the machine that's logging data but on a second machine. That is, instead of formatting 255u8 into "255" and sending the string, the single-byte binary data is sent to a second machine, the host, and the formatting happens there.

defmt's string compression consists of building a table of string literals, like "Hello, world" or "The answer is {:?}", at compile time. At runtime the logging machine sends indices instead of complete strings.

User guide

Unless indicated otherwise these sections apply to the use of defmt both in libraries and applications.

Setup

Before you use the defmt crate some setup may be necessary. The setup steps depends on whether you are using defmt from a library or an application.

Library setup

If your library will use any of the logging macros (trace!, debug!, info!, warn!, error!) then you'll need to add these Cargo features to your library's Cargo.toml:

# under the features section, copy these
[features]
# ↓↓↓↓↓
defmt-default = []
defmt-trace = []
defmt-debug = []
defmt-info = []
defmt-warn = []
defmt-error = []
# ↑↑↑↑↑

You do not need to add these features if you are only going to use the #[derive(Format)] attribute.

Application setup

NOTE the preferred way to create a new defmt application is to use our app-template. These steps are for using defmt on an existing application.

Cargo features

Add these Cargo features to your app's Cargo.toml:

# Cargo.toml
# under the features section, copy these
[features]
# ↓↓↓↓↓
defmt-default = []
defmt-trace = []
defmt-debug = []
defmt-info = []
defmt-warn = []
defmt-error = []
# ↑↑↑↑↑

Linker script

The application must be linked using a custom linking process that includes the defmt.x linker script. Custom linking is usual for embedded applications and configured in the .cargo/config file. To pass defmt.x to the linker add the -C link-arg=-Tdefmt.x flag to the rustflags section of .cargo/config.

# .cargo/config
[target.thumbv7m-none-eabi]
rustflags = [
  # likely, there's another `link-arg` flag already there; KEEP it
  "-C", "link-arg=-Tlink.x",
  "-C", "link-arg=-Tdefmt.x", # <- ADD this one
]

#[global_logger]

The application must link to or define a global_logger. The global_logger specifies how logs are sent from the device running the app to the host where the logs are displayed. The application must link to exactly one global_logger. The global_logger can appear anywhere in the dependency graph and usually it will be its own crate. The following global_loggers are provided as part of the project:

  • defmt-rtt, logs over RTT. Note that this crate can not be used together with rtt-target.
  • defmt-semihosting, logs over semihosting. Meant only for testing defmt on a virtual Cortex-M device (QEMU).

Information about how to write a global_logger can be found in the #[global_logger] section.

Enabling logging

All logging is disabled by default. Logging can be enabled at the crate level. At the very least you'll want to enable logging for the top level application crate so we recommend adding defmt-default to your crate's default feature.

# Cargo.toml
[features]
default = [
  "defmt-default", # <- ADD this feature
]

More information about log filtering can be found in the Filtering section.

Logging macros

Logging is done using the error, warn, info, debug and trace macros. Each macro logs at the logging level indicated in its name. The syntax of these macros is roughly the same as the println macro. Positional parameters are supported but named parameters are not. Escaping rules are the same: the characters { and } are escaped as {{ and }}. The biggest different is in the supported formatting parameters (:?, :>4, :04).


#![allow(unused)]
fn main() {
extern crate defmt;
let len = 80u8;
// -> INFO:  message arrived (length=80)
defmt::info!(
    "message arrived (length={:?})",
    len /*: usize */,
);

struct Message;
impl Message { fn header(&self) -> u8 { 0 } }
let message = Message;
// -> DEBUG: Header { source: 2, destination: 3, sequence: 16 }
defmt::debug!("{:?}", message.header() /*: Header */);
}

Unlike core::fmt which has several formatting traits (Debug, Display), defmt has a single formatting trait called Format. The :? formatting parameter indicates that the Format trait will be used. When :? is used the corresponding argument must implement the Format trait.


#![allow(unused)]
fn main() {
extern crate defmt;
let x = 0;
defmt::trace!("{:?}", x);
//                     ^ must implement the `Format` trait
}

Primitives

In addition to :? there are formatting parameters for several primitive types. These parameters follow the syntax :<type>, for example: :u8, :bool. This type information lets the framework further compress the logs resulting in higher throughput.


#![allow(unused)]
fn main() {
extern crate defmt;
let enabled = false;
let ready = false;
let timeout = false;
// arguments can be compressed into a single byte
defmt::info!(
    "enabled: {:bool}, ready: {:bool}, timeout: {:bool}",
    enabled, ready, timeout,
);

let x = 0u16;
// arguments will be type checked
defmt::trace!("{:u16}", x);
//                      ^ must have type `u16`
}

The available types are:

  • :bool, boolean
  • :{i,u}{8,16,32,64}, standard integer types
  • :{i,u}24, 32-bit integer truncated to 24 bits
  • :f32, 32-bit floating point type
  • :[u8; N], byte array
  • :[u8], byte slice
  • :str, string slice

Bitfields

:m..n is the bitfield formatting parameter. When paired with a positional parameter it can be used to display the bitfields of a register.


#![allow(unused)]
fn main() {
extern crate defmt;
let pcnf1 = 0u32;
// -> TRACE: PCNF1 { MAXLEN: 125, STATLEN: 3, BALEN: 0b010 }
defmt::trace!(
    "PCNF1: {{ MAXLEN: {0:0..8}, STATLEN: {0:8..16}, BALEN: {0:16..19} }}",
    //                  ^                  ^                 ^ same argument
    pcnf1, // <- type must be `u32`
);
}

The bitfield argument is expected to be a fully typed, unsigned integer that's large enough to contain the bitfields. For example, if bitfield ranges only cover up to bit 11 (e.g. :8..12) then the argument must be u16.

Bit indices are little-endian: the 0th bit is the rightmost bit.

Bitfields are not range inclusive, e.g.


#![allow(unused)]
fn main() {
extern crate defmt;
defmt::trace!("first two bits: {0:0..3}", 254u32);
}

will evaluate to 0b10.

⚠️ You can not reuse the same argument in a bitfield- and a non bitfield parameter. This will not compile:


#![allow(unused)]
fn main() {
extern crate defmt;
defmt::trace!("{0:5..13} {0:u16}", 256u16);
}

Interned strings

The {:istr} formatting parameter is used for interned strings. Compared to the {:str} parameter, which transmits a complete string, {:istr} saves bandwidth by sending only a string index. The {:istr} parameter expects an argument with type defmt::Str. A Str value is created using the intern! macro; the argument to this macro must be a string literal.


#![allow(unused)]
fn main() {
extern crate defmt;
let s = "The quick brown fox jumps over the lazy dog";
defmt::info!("{:str}", s);
//                      ^ bandwidth-use = 43 bytes

use defmt::Str;
let interned: Str = defmt::intern!("The quick brown fox jumps over the lazy dog");
defmt::info!("{:istr}", interned);
//                       ^^^^^^^^ bandwidth-use <= 2 bytes
}

This was a contrived example to show the difference in bandwidth use. In practice you should use:


#![allow(unused)]
fn main() {
extern crate defmt;
defmt::info!("The quick brown fox jumps over the lazy dog");
}

which also interns the log string and uses as little bandwidth as the {:istr} version.

Format slices / arrays

The {:[?]} parameter can be used to log a slices of values that implement the Format trait. The expected argument is a slice.


#![allow(unused)]
fn main() {
extern crate defmt;
use defmt::{Format, info};
#[derive(Format)]
struct X {
    y: u16,
    z: u8,
}
let xs: &[X] = &[/* .. */];
info!("xs={:[?]}", xs);
}

Note that for slices of bytes {:[u8]} should be preferred as it's better compressed. [T] where T: Format also implements the Format trait so it's possible to format [T] with {:?} but {:[?]} uses slightly less bandwidth.

If you have an array of types that implement the Format trait, instead of a slice. You should use the {:[?; N]} parameter (where N is a number); this saves bandwidth compared to {:[?]}.


#![allow(unused)]
fn main() {
extern crate defmt;
use defmt::{Format, info};
#[derive(Format)]
struct X {
    y: u16,
    z: u8,
}
let xs: [X; 2] = [
X { y: 1, z: 2 },
X { y: 3, z: 4 },
    // ..
];
info!("xs={:[?; 2]}", xs);
}

Implementing Format

#[derive(Format)]

The easiest way to implement the Format trait for a struct or enum is to use the derive attribute.


#![allow(unused)]
fn main() {
extern crate defmt;
use defmt::Format;

#[derive(Format)]
struct Header {
    source: u8,
    destination: u8,
    sequence: u16,
}

#[derive(Format)]
struct Descriptor;
#[derive(Format)]
enum Request {
    GetDescriptor { descriptor: Descriptor, length: u16 },
    SetAddress { address: u8 },
}
}

NOTE: Like built-in derives like #[derive(Debug)], #[derive(Format)] will add Format bounds to the generic type parameters of the struct.

NOTE: Do not use the API used by the expansion of the derive(Format) macro; it is unstable.

write!

NOTE write! is available in defmt v0.1.2+

It is also possible to implement the Format trait manually. This trait has a single required method: format. In this method you need to format the value (self) into the given Formatter argument using the defmt::write! macro. Example below:


#![allow(unused)]
fn main() {
extern crate defmt;
// value read from a MMIO register named "CRCCNF"
struct CRCCNF {
   bits: u32,
}

impl defmt::Format for CRCCNF {
    fn format(&self, f: &mut defmt::Formatter) {
        // format the bitfields of the register as struct fields
        defmt::write!(
           f,
           "CRCCNF {{ LEN: {0:0..2}, SKIPADDR: {0:8..10} }}",
           self.bits,
        )
    }
}
}

NOTE: in defmt v0.1.x the write! macro must be invoked at most once within the implementation of the fmt method. Invoking the method more than once will produce a panic

Newtypes

If you need to implement Format for some "newtype" struct you can delegate the formatting to the inner type. Example below:


#![allow(unused)]
fn main() {
extern crate defmt;
struct MyU8 { inner: u8 }

impl defmt::Format for MyU8 {
    fn format(&self, f: &mut defmt::Formatter) {
        self.inner.format(f)
    }
}
}

WARNING never call format more than once, since this will corrupt the data stream!

Filtering

defmt supports 5 different logging levels listed below from lowest severity to highest severity:

  • TRACE
  • DEBUG
  • INFO
  • WARN
  • ERROR

By default all logging is disabled. The amount of logging to perform can be controlled at the crate level using the following Cargo features:

  • defmt-default, log at INFO, or TRACE, level and up
  • defmt-trace, log at TRACE level and up
  • defmt-debug, log at DEBUG level and up
  • defmt-info, log at INFO level and up
  • defmt-warn, log at WARN level and up
  • defmt-error, log at ERROR level

These features must only be enabled by the top level application crate as shown below.

# Cargo.toml
[package]
name = "app"

[dependencies]
usb-device = "0.3.0"

[features]
default = [
  # enable logs of the `usb-device` dependency at the TRACE/INFO level
  "usb-device/defmt-default",

  # enable logs of this crate (`app`) at the TRACE level
  "defmt-trace",
]

When only the defmt-default feature is enabled for a crate, that crate will:

  • log at the TRACE level and up if debug-assertions = true (dev profile), or
  • log at the INFO level and up if debug-assertions = false (release profile)

When any of the other features is enabled the crate will log at that, and higher, severity regardless of the state of debug-assertions or defmt-default.

#[timestamp]

Applications that, directly or transitively, use any of defmt logging macros may define a #[timestamp] function or include one in their dependency graph.

All logs are timestamped. The #[timestamp] function specifies how the timestamp is computed. By default (if no #[timestamp] function is provided), a timestamp of 0 will be used. This function must have signature fn() -> u64 and on each invocation should return a non-decreasing value. The function is not unsafe meaning that it must be thread-safe and interrupt-safe.

No timestamp (default behavior)

When no #[timestamp] function is used, defmt will use one equivalent to this:


#![allow(unused)]
fn main() {
extern crate defmt;
#[defmt::timestamp]
fn timestamp() -> u64 {
    0
}
}

Atomic timestamp

A simple timestamp function that does not depend on device specific features and is good enough for development is shown below:


#![allow(unused)]
fn main() {
extern crate defmt;
use std::sync::atomic::{AtomicUsize, Ordering};
// WARNING may overflow and wrap-around in long lived apps
#[defmt::timestamp]
fn timestamp() -> u64 {
    static COUNT: AtomicUsize = AtomicUsize::new(0);
    COUNT.fetch_add(1, Ordering::Relaxed) as u64
}
}

Hardware timestamp

A timestamp function that uses a device-specific monotonic timer can directly read a MMIO register. It's OK if the function returns 0 while the timer is disabled.

extern crate defmt;
fn monotonic_timer_counter_register() -> *mut u32 {
    static mut X: u32 = 0;
    unsafe { &mut X as *mut u32 }
}
// WARNING may overflow and wrap-around in long lived apps
#[defmt::timestamp]
fn timestamp() -> u64 {
    // NOTE(interrupt-safe) single instruction volatile read operation
    unsafe { monotonic_timer_counter_register().read_volatile() as u64 }
}

fn enable_monotonic_counter() {}
fn main() {
    defmt::info!(".."); // timestamp = 0
    defmt::debug!(".."); // timestamp = 0
    enable_monotonic_counter();
    defmt::info!(".."); // timestamp >= 0
    // ..
}

64-bit extension

Microcontrollers usually have only 32-bit counters / timers. Some of them may provide functionality to make one 32-bit counter increase the count of a second 32-bit counter when the first one wraps around. Where that functionality is not available, a 64-bit counter can be emulated using interrupts:


#![allow(unused)]
fn main() {
use std::sync::atomic::{AtomicU32, Ordering};

// the hardware counter is the "low (32-bit) counter"

// this atomic variable is the "high (32-bit) counter"
static OVERFLOW_COUNT: AtomicU32 = AtomicU32::new(0);

// this is an interrupt handler running at highest priority
fn on_first_counter_overflow() {
    let ord = Ordering::Relaxed;
    OVERFLOW_COUNT.store(OVERFLOW_COUNT.load(ord) + 1, ord);
}
}

To read the 64-bit value in a lock-free manner the following algorithm can be used (pseudo-code):

do {
  high1: u32 <- read_high_count()
  low : u32<- read_low_count()
  high2 : u32<- read_high_count()
} while (high1 != high2)
count: u64 <- (high1 << 32) | low

The loop should be kept as tight as possible and the read operations must be single-instruction operations.

#[global_logger]

Applications that, directly or transitively, use any of defmt logging macros need to define a #[global_logger] or include one in their dependency graph. This is similar to how the alloc crate depends on a #[global_allocator].

The global_logger defines how data is moved from the device, where the application runs, to the host, where logs will be formatted and displayed. global_logger is transport agnostic: you can use a serial interface, serial over USB, RTT, semihosting, Ethernet, 6LoWPAN, etc. to transfer the data.

The global_logger interface comprises two traits, Write and Logger, and one attribute, #[global_logger].

The Write trait specifies how the data is put on the wire. The write method is not allowed to fail. Buffering, rather than waiting on I/O, is recommended. If using buffering write should not overwrite old data as this can corrupt log frames and most printers cannot deal with incomplete log frames.

The Logger specifies how to acquire and release a handle to a global logger. See the API documentation for more details about the safety requirements of the acquire-release mechanism.

Finally, #[global_logger] specifies which Logger implementation will be used by the application. #[global_logger] must be used on a unit struct, a struct with no fields. This struct must implement the Logger trait. It's recommended that this struct is kept private. Only a single #[global_logger] struct can appear in the dependency graph of an application. The global_logger should be selected at the top of the dependency graph, that is in the application crate.

There are two general ways to implement a global_logger.

Single logging channel

The first form uses a single channel. This means that all execution contexts (i.e. threads OR main + interrupt handlers) use the same logging channel. In an application that uses interrupts this means that acquire must disable interrupts and release must re-enable interrupts. This synchronizes access to the single channel, from contexts running at different priority levels.

defmt-semihosting is an example of this single logging channel approach.

Multiple logging channels

The other approach uses multiple logging channels: e.g. one for each priority level in an application that uses interrupts. With this approach logging can be made lock-free: interrupts are not disabled while logging data. This approach requires channel multiplexing in the transport layer. RTT, for example, natively supports multiple channels so this is not an issue, but other transports, like ITM, will require that each log frame to be tagged with the channel it belongs to (e.g. one logging channel = ITM channel). The trade-offs of using more channels are:

  • Lock-freedom
  • higher memory usage on the target, for buffering
  • lower overall throughput, as either different channels need to be polled from the host or the log frames need to be tagged with the channel they belong to

panic! and assert!

NOTE all these macros are available in defmt v0.1.2+

The defmt crate provides its own version of panic!-like and assert!-like macros. The defmt version of these macros will log the panic message using defmt and then call core::panic! (by default). Because the panic message is formatted using defmt! the format string must use the same syntax as the logging macros (e.g. info!).

#[defmt::panic_handler]

Because defmt::panic! invokes core::panic! this can result in the panic message being printed twice if your #[core::panic_handler] also prints the panic message. This is the case if you use panic-probe with the print-defmt feature enabled but not an issue if you are using the panic-abort crate, for example.

To avoid this issue you can use the #[defmt::panic_handler] to override the panicking behavior of defmt::panic-like and defmt::assert-like macros. This attribute must be placed on a function with signature fn() -> !. In this function you'll want to replicate the panicking behavior of the Rust #[panic_handler] but leave out the part that prints the panic message. For example:

#[panic_handler] // built-in ("core") attribute
fn core_panic(info: &core::panic::PanicInfo) -> ! {
    print(info); // e.g. using RTT
    reset()
}

#[defmt::panic_handler] // defmt's attribute
fn defmt_panic() -> ! {
    // leave out the printing part here
    reset()
}

If you are using the panic-probe crate then you should "abort" (call cortex_m::asm::udf) from #[defmt::panic_handler] to match its behavior.

NOTE: even if you don't run into the "double panic message printed" issue you may still want to use #[defmt::panic_handler] because this way defmt::panic and defmt::assert will not go through the core::panic machinery and that may reduce code size (we recommend you measure the effect of the change).

Printers

Printers are host programs that receive log data, format it and display it. The following printers are currently available:

  • qemu-run, parses data sent by QEMU over semihosting (ARM Cortex-M only). NOTE: used for internal testing; won't be published to crates.io
  • probe-run, parses data sent over RTT (ARM Cortex-M only). NOTE: make sure you install the tool from git (not crates.io) and enable the "defmt" Cargo feature.

Migrating from git defmt to stable defmt

On 2020-11-11, a stable version of defmt became available on crates.io. If you are still using the git version you are encouraged to migrate your project to the crates.io version! Two things need to be done to use the crates.io version of defmt:

  1. change defmt, defmt-rtt and panic-probe dependencies from git to version "0.1.0" in relevant Cargo.toml-s
  2. install version v0.1.4 (or newer) of probe-run

Here's are the exact steps for migrating an app-template project.

  1. In your app-template project, change the root Cargo.toml as shown below:
 [workspace]
 members = ["testsuite"]

-[dependencies.defmt]
-git = "https://github.com/knurling-rs/defmt"
-branch = "main"
-
-[dependencies.defmt-rtt]
-git = "https://github.com/knurling-rs/defmt"
-branch = "main"
-
-[dependencies.panic-probe]
-git = "https://github.com/knurling-rs/probe-run"
-branch = "main"
-
 [dependencies]
+defmt = "0.1.0"
+defmt-rtt = "0.1.0"
+panic-probe = { version = "0.1.0", features = ["print-defmt"] }
 cortex-m = "0.6.4"
 cortex-m-rt = "0.6.13"
  1. In your app-template project, also change the testsuite/Cargo.toml as shown below:
 name = "test"
 harness = false

-[dependencies.defmt]
-git = "https://github.com/knurling-rs/defmt"
-branch = "main"
-
-[dependencies.defmt-rtt]
-git = "https://github.com/knurling-rs/defmt"
-branch = "main"
-
-[dependencies.panic-probe]
-git = "https://github.com/knurling-rs/probe-run"
-branch = "main"
-# enable the `print-defmt` feature for more complete test output
-features = ["print-defmt"]
-
 [dependencies]
+defmt = "0.1.0"
+defmt-rtt = "0.1.0"
+panic-probe = { version = "0.1.0", features = ["print-defmt"] }
 cortex-m = "0.6.3"
 cortex-m-rt = "0.6.12"
  1. Finally, install probe-run version v0.1.4 (or newer)
$ cargo install probe-run -f

Now you can resume working on your project!

Design & impl notes

Unstructured, braindump-ish notes about the design and implementation of defmt

WARNING the notes here may not accurately reflect the current implementation. This document is synchronized with the implementation at a best effort basis.

Optimization goals

defmt optimizes for data throughput first and then for runtime cost.

Constraints

No double compilation

Say you want print logs from target/device app that uses crate foo. That crate foo uses the Format trait on some of its data structures. In this scenario we want to avoid having to compile foo for the host. In other words, foo should only be (cross) compiled for the target device.

This is the biggest difference between defmt and some serde library that does binary serialization. The serde library requires a Deserialize step that requires compiling foo for the host (see derive(Serialize)). defmt avoids this by placing all the required information for formatting in a "side table" (see the interning section).

This comes with the downside that the host can only perform limited actions on the data it receives from the device: namely formatting. The host cannot invoke foo::Struct.method() for example but that may not even be a sensible operation on the host anyways, e.g. foo::USB::RegisterValue.store_volatile() would make the host crash.

We want to avoid this "double" compilation (cross compile for the target and compile for the host) because:

  • it doubles compilation time (wait time)
  • compiling device-specific code for the host can become a headache quickly: see inline/external assembly, build scripts, etc.

Interning

All string literals are interned in a custom ELF section. This has proven to be the way that requires the less post-processing and implementation work. It is not without downsides as we'll see.

The basic pattern for interning a string is this:


#![allow(unused)]
fn main() {
#[export_name = "the string that will be interned"]
#[link_section = ".my_custom_section.some_unique_identifier"]
//             ^ this is the INPUT linker section
static SYM: u8 = 0;

// index of the interned string
let index = &SYM as *const u8 as usize;
}

A linker script is required to group all these strings into a single OUTPUT linker section:

SECTIONS
{
  /* NOTE: simplified */
  .my_custom_section /* <- name of the OUTPUT linker section */
    (INFO) /* <- metadata section: not placed in Flash */
    : 0 /* <- start address of this section */
  {
    *(.my_custom_section.*); /* <- name of the INPUT linker section */
  /*^                    ^ glob pattern */
  /*^ from any object file (~= crate) */
  }
}

With this linker script the linker will tightly pack all the interned strings in the chosen linker section. The linker will also discard strings that end no being used in the final binary AKA "garbage collection". Garbage collection will only work correctly if every string is placed in a different INPUT linker section.

After you have linked the program you can display the interned strings using the nm tool.

$ arm-none-eabi-nm -CSn elf-file
00000000 00000001 N USB controller is ready
00000001 00000001 N entering low power mode
00000002 00000001 N leaving low power mode
(..)

The nm shows all the symbols in the ELF file. In ELF files one function = one symbol and one static variable = one symbol. So function foo will show as crate_name::module_name::foo in the nm output; same thing with a static variable X.

The four columns in the output, from left to right, contain:

  • the address of the symbol
  • the size of the symbol in bytes
  • the type of the symbol
  • the symbol name

As you can see the interned string is the symbol name. Although we cannot write:

static "USB controller is ready": u8 = 0;

We can write:


#![allow(unused)]
fn main() {
#[export_name = "USB controller is ready"]
static SYM: u8 = 0;
}

The next thing to note is that each interned string symbol is one byte in size (because static SYM has type u8). Thanks to this the addresses of the symbols are consecutive: 0, 1, 2, etc.

Dealing with duplicates

The linker hates it when it finds two symbol that have the same name. For example, this is an error:


#![allow(unused)]
fn main() {
#[no_mangle]
static X: u32 = 0;

#[export_name = "X"]
static Y: u32 = 0; //~ error: symbol `X` is already defined
}

This produces two symbols with the name "X". rustc catches this issue early and reports an error at compile time.

How can this occur in logging? The user may write:


#![allow(unused)]
fn main() {
extern crate defmt;
fn foo() {
    defmt::info!("foo started ..");
    // ..
    defmt::info!(".. DONE"); // <-
}

fn bar() {
    defmt::info!("bar started ..");
    // ..
    defmt::info!(".. DONE"); // <-
}
}

Because macros are expanded in isolation each info!(".. DONE") statement will produce this to intern its string:


#![allow(unused)]
fn main() {
#[export_name = ".. DONE"]
#[link_section = ".."]
static SYM: u8 = 0;
}

which results in a collision.

To avoid this issue we store each interned string as a JSON object with 3 fields: the message itself, the name of the crate that invoked the macro, and a 64-bit integer "discriminator". The discriminator is a hash of the source code location of the log statement so it should be unique per crate. Now these two macro invocations will produce something like this:


#![allow(unused)]
fn main() {
// first info! invocation
{
    #[export_name = "{ \"package\": \"my-app\", \"data\": \".. DONE\", \"discriminator\": \"1379186119\" }"]
    #[link_section = ".."]
    static SYM: u8 = 0;
}

// ..

// second info! invocation
{
    #[export_name = "{ \"package\": \"my-app\", \"data\": \".. DONE\", \"discriminator\": \"346188945\" }"]
    #[link_section = ".."]
    static SYM: u8 = 0;
}
}

These symbols do not collide because their discriminator fields are different so the program will link correctly.

Because duplicate strings are kept in the final binary this linker-based interner is not really an interner. A proper interner returns the same index when the same string is interned several times.

However, two log statements that log the same string will often have different source code locations. Assigning a different interner index to each log statement means we can distinguish between the two thus we can report their correct source code location.

Logging levels

defmt supports several logging levels. To avoid serializing the logging level at runtime (that would reduce throughput), interned strings are clustered by logging level.

The defmt linker script looks closer to this:

SECTIONS
{
  .defmt (INFO) : 0
  {
    *(.defmt.error.*); /* cluster of ERROR level log strings */

    _defmt_warn = .; /* creates a symbol between the clusters */

    *(.defmt.warn.*); /* cluster of WARN level log strings */

    _defmt_info = .;
    *(.defmt.info.*);

    _defmt_debug = .;
    *(.defmt.debug.*);

    _defmt_trace = .;
    *(.defmt.trace.*);
  }
}

And the string interning that each logging macro does uses a different input linker section. So this code:


#![allow(unused)]
fn main() {
extern crate defmt;
defmt::warn!("Hello");
defmt::warn!("Hi");

defmt::error!("Good");
defmt::error!("Bye");
}

Would expand to this:


#![allow(unused)]
fn main() {
// first warn! invocation
{
    #[export_name = "Hello@1379186119"]
    #[link_section = ".defmt.warn.1379186119"]
    static SYM: u8 = 0;
}

// ..

// first error! invocation
{
    #[export_name = "Bye@346188945"]
    #[link_section = ".defmt.error.346188945"]
    static SYM: u8 = 0;
}
}

Then after linking we'll see something like this in the output of nm:

$ arm-none-eabi-nm -CSn elf-file
00000000 00000001 N Bye
00000001 00000001 N Good
00000002 00000000 N _defmt_warn
00000002 00000001 N Hi
00000003 00000001 N Hello
00000003 00000000 N _defmt_info
(..)

There you can see that ERROR level logs are clustered at the beginning. After that cluster comes the cluster of WARN level logs. Between the two clusters you see the zero-sized _defmt_warn symbol.

We know before-hand the name of the _defmt_* symbols which are used as delimiters. We can look their addresses first and when we lookup a string index in this table we can compare it to those addresses to figure the logging level it corresponds to.

  • if index < indexof(_defmt_warm) then ERROR log level
  • if indexof(_defmt_warn) <= index < indexof(_defmt_info) then WARN log level

And so on so forth.

Serialization

In this section we'll see how log data is "put on the wire".

Interned strings

Let's ignore timestamps for now and also ignore how access to the global logger is synchronized. This is the simplest case: logging a string literal with no formatting.


#![allow(unused)]
fn main() {
extern crate defmt;
defmt::info!("Hello, world!");
}

As we saw in the previous section this string will get interned. Interning converts the string into a usize index. This usize index will be further compressed using LEB128. Some examples: (values on the right are u8 arrays)

  • 1usize -> [1]
  • 127usize -> [127]
  • 128usize -> [128, 1]
  • 255usize -> [255, 1]

Because string indices start at zero and it's unlikely that a program will intern more than 2^14 strings string literals will be serialized as 1 or 2 bytes indices.

Integers

Integers will be serialized in little endian order using to_le_bytes(). usize and isize values will be subject to LEB128 compression.


#![allow(unused)]
fn main() {
extern crate defmt;
defmt::error!("The answer is {:i16}!", 300);
// on the wire: [3, 44, 1]
//  string index ^  ^^^^^ `300.to_le_bytes()`
//  ^ = intern("The answer is {:i16}!")

defmt::error!("The answer is {:u24}!", 131000);
// on the wire: [4, 184, 255, 1]
//                  ^^^^^^^^^^^ 131000.to_le_bytes()[..3]

defmt::error!("The answer is {:usize}!", 131000);
// on the wire: [4, 184, 255, 1]
//                  ^^^^^^^^^^^ 131000.to_le_bytes()[..3]
}

NOTE(japaric) unclear to me if LEB128 encoding (more compression but more) u16 and u32 is worth the trade-off

TODO(japaric) evaluate zigzag encoding for isize?

Slices

For slices ({:[u8]}) the length is LEB128 encoded and serialized first and then followed by the slice data.


#![allow(unused)]
fn main() {
extern crate defmt;
defmt::error!("Data: {:[u8]}!", [0, 1, 2]);
// on the wire: [1, 3, 0, 1, 2]
//  string index ^  ^  ^^^^^^^ the slice data
//   LEB128(length) ^
}

Strings

Strings that are passed directly (i.e. not as indices of interned strings) as format string parameters ({:str}) must be prefixed with their LEB128 encoded length. This behavior is analogous to that of Slices.


#![allow(unused)]
fn main() {
extern crate defmt;
defmt::error!("Hello, {:str}!", "world");
// on the wire: [1, 5, 199, 111, 114, 108, 100]
//  string index ^  ^  ^^^^^^^^^^^^^^^^^^^^^^^ the slice data
//   LEB128(length) ^
}

Arrays

For arrays ({:[u8; N]}) the length is not serialized.


#![allow(unused)]
fn main() {
extern crate defmt;
defmt::error!("Data: {:[u8; 3]}!", [0, 1, 2]);
// on the wire: [1, 0, 1, 2]
//  string index ^  ^^^^^^^ the slice data
}

Bitfield

The integer argument is serialized in little endian format (to_le_bytes).


#![allow(unused)]
fn main() {
extern crate defmt;
let x = 0u16;
defmt::error!("l: {0:0..8}, m: {0:8..12}, h: {0:12..16}", x /*: u16*/);
// on the wire: [1, 1, 2]
//  string index ^  ^^^^ `u16::to_le_bytes(x)`
}

Leading or trailing bytes that are not needed to display a bitfield are removed during serialization:


#![allow(unused)]
fn main() {
extern crate defmt;
defmt::error!("m: {0:8..12}", 0b0110_0011_0000_1111_u32);
// on the wire: [1, 0b0110_0011]
//  string index ^  ^^^^^^^^^^ argument truncated into u8:
//                             leading and trailing byte are irrelevant
}

Bool

Booleans are compressed in bytes, bitflags-style.


#![allow(unused)]
fn main() {
extern crate defmt;
defmt::error!("x: {:bool}, y: {:bool}, z: {:bool}", false, false, true);
// on the wire: [1, 0b001]
//  string index ^  ^^^^^ the booleans: `0bxyz`
}

When mixed with other data, the first {:bool} allocates an output byte that fits up to 7 more bools.

{:bool}s in the formatting string are batched together as follows: Any non-{:bool} arguments are emitted as-is, while {:bool} arguments are collected into a byte and emitted when 8 {:bool}s have been collected. This means that for every set of 8 {:bool}s, the byte containing them will be serialized at the position of their last member. If more than 0 but less than 8 {:bool}s have been encountered at the end of the log frame, a byte containing them will be emitted last.


#![allow(unused)]
fn main() {
extern crate defmt;
defmt::error!("x: {:bool}, y: {:u8}, z: {:bool}", false, 0xff, true);
// on the wire: [1, 0xff, 0b01]
//  string index ^  ^^^^^ ^^^^ the booleans: `0bxz`
//                  |
//                  u8
}

⚠️ If the final parameter is not a {:bool} but there are yet to be compressed {:bool}s present in the format string beforehand, the final output byte containing all compressed booleans will be at the end.


#![allow(unused)]
fn main() {
extern crate defmt;
defmt::error!("x: {:bool}, y: {:u8}", false, 0xff);
// on the wire: [1, 0xff, 0b0,]
//  string index ^  ^^^^^ ^^^^ the booleans: `0bx`
//                  |
//                  u8
}

⚠️ If some {:bool}s are nested inside a struct, they will still be compressed as if they were passed as regular arguments.


#![allow(unused)]
fn main() {
extern crate defmt;
use defmt::Format;
#[derive(Format)]
struct Flags {
         a: bool,
         b: bool,
}

defmt::error!("x: {:bool}, {:?}", false, Flags { a: true, b: false });
// on the wire: [1, 2, 0b010,]
//  string index ^  ^  ^^^^ all booleans: `0bxab`
//                  |
//                  index of "Flags { a: {:bool}, b: {:bool}} "
}

Format

The untyped argument (:?) requires one level of indirection during serialization.

First let's see how a primitive implements the Format trait:


#![allow(unused)]
fn main() {
extern crate defmt;
macro_rules! internp { ($l:literal) => { 0 } }
trait Format { fn format(&self, fmt: &mut defmt::Formatter); }
impl Format for u8 {
    fn format(&self, fmt: &mut defmt::Formatter) {
        if fmt.needs_tag() {
            let t = internp!("{:u8}");
            fmt.u8(&t);
        }
        fmt.u8(self)
        // on the wire: [1, 42]
        //  string index ^  ^^ `self`
    }
}
}

Format will use the write! macro. This will send the string index of {:u8} followed by the one-byte data. In general, write! can use {:?} so Format nesting is possible.

Now let's look into a log invocation:


#![allow(unused)]
fn main() {
extern crate defmt;
defmt::error!("The answer is {:?}!", 42u8);
// on the wire: [2, 1, 42]
//  string index ^  ^^^^^ `42u8.format(/*..*/)`
//  ^ = intern("The answer is {:?}!")
}

This will send the string index of "The answer is {:?}!" and invoke the argument's Format::format method.

Format Slices

{:[?]} will serialize the length (LEB128 compressed) first, then the first element will be serialized in (recursively) tagged format. The rest of elements will be serialized untagged.

"Tagged" means that the data will be preceded by the string indices that indicate how to format the data.

Example:


#![allow(unused)]
fn main() {
extern crate defmt;
use defmt::Format;

#[derive(Format)]
struct X {
    y: Y,
}

#[derive(Format)]
struct Y {
    z: u8,
}

fn serialize() {
    let xs = [X { y: Y { z: 42 }}, X { y: Y { z: 24 }}];
    defmt::info!("{:[?]}", &xs[..]);
    // on-the-wire: [
    //     1,  // "{:[?]}"
    //     2,  // `leb(xs.len())`
    //     2,  // "X {{ y: {:?} }}"  / outer tag
    //     3,  // "Y {{ z: {:u8} }}" / inner tag
    //     42, // xs[0].y.z
    //     (no tags for the second element)
    //     24, // xs[1].y.z
    // ]
}
}

Single Format trait

core::fmt has several formatting traits, like Hex and Bin. These appear as different formatting parameters, like :x and :b, in format strings and change how integers are formatted: 15 vs 0xF vs 0b1111.

defmt does not have all these formatting traits. The rationale is that the device should not make the decision about how an integer is formatted. The formatting is done in the host so the host should pick the format. With interactive displays, e.g. web UI, it even becomes possible to change the format on demand, e.g. click the number to change from decimal to hexadecimal representation.

Timestamp

In the current implementation timestamps are absolute (time elapsed since the start of the program) and in microseconds. Timestamps are LEB128 encoded before serialization.

TODO we may want to consider using delta encoding in the future

Global logger

The global logger needs to operate correctly (be memory safe and not interleave log data) in presence of race conditions and re-entrant invocations. Race conditions can be avoided with mutexes but re-entrancy can occur even if mutexes are used and shouldn't result in deadlocks.

Re-entrancy

Where can re-entrancy occur? Turns out that with global singletons it can occur about anywhere; you don't need interrupts (preemption) to cause re-entrancy. See below:


#![allow(unused)]
fn main() {
extern crate defmt;
let x = 0u8;
defmt::info!("The answer is {:?}!", x /*: Struct */);
}

As you have seen before this will first send the string index of "The answer is {:?}!" and then call x's Format::format method. The re-entrancy issue arises if the Format implementation calls a logging macro:


#![allow(unused)]
fn main() {
extern crate defmt;
struct X;
impl defmt::Format for X {
    fn format(&self, f: &mut defmt::Formatter) {
        //           ^ this is a handle to the global logger
        defmt::info!("Hello!");
        // ..
    }
}
}

f is a handle to the global logger. The info! call inside the format method is trying to access the global logger again. If info! succeeds then you have two exclusive handles (&mut Formatter) to the logger and that's UB. If info! uses a spinlock to access the logger then this will deadlock.

Acquire-release

One solution to the re-entrancy issue that's deadlock-free is to make the log macros take the logger and hold it until it's done with it. In case of nesting any inner take attempt will silently fail.

So the log macros may expand to something like this: (let's ignore data races / race conditions for now)


#![allow(unused)]
fn main() {
struct Logger;
impl Logger {
    fn acquire() -> Option<Self> { None }
    fn serialize_interned_string_and_etc(&self) {}
}
fn release<T>(_: T) {}
if let Some(logger) = Logger::acquire() {
    logger.serialize_interned_string_and_etc();
    release(logger); // <- logger can be acquired again after this
} else {
    // silent failure: do nothing here
}
}

This means that invoking logging macros from Format implementations will silently fail. But note that allowing such operation would result in interleaving of log frames. To a decoder/parser interleaved log frames are the same as corrupted log frames. So we actually want to forbid this operation.

Evaluation order

Consider this log invocation:


#![allow(unused)]
fn main() {
extern crate defmt;
defmt::info!("x={:?}", foo());

fn foo() -> u8 {
    defmt::info!("Hello");
    42
}
}

Depending on when foo is invoked this can result in potential re-entrancy / nesting and cause info!("Hello") to be lost. So we'll make the macro evaluate format arguments before the acquire operation. Something like this: (core::fmt does a similar match operation)


#![allow(unused)]
fn main() {
struct Logger;
impl Logger {
    fn acquire() -> Option<Self> { None }
}
fn foo() -> u8 { 0 }
match (foo()) { // evaluate formatting arguments
    (_0) => {
        if let Some(logger) = Logger::acquire() {
            // serialize `_0`, etc.
        }
    }
}
}

Preemption

Preemption can also result in re-entrancy. How to deal with it? Assuming single-core systems there are two approaches:

  1. Disable interrupts in acquire; re-enable them in release. This means that the logging macros block higher priority interrupts.

  2. Have a separate logger per priority level. acquire and release are now lock-free and don't block interrupts. This requires multiplexing in the transport.

Deserialization

The host has received the log data (binary data). How to make sense of it?

Let's assume:

  • no data loss during transport (reliable transport)
  • no interleaving of log frames (no nesting of logging macros)

With these assumptions the decoder can expect the stream of log data to be a series of log frames.

Log frames

Each log statement produces one log frame. Consider this log call: (let's include the timestamp this time)


#![allow(unused)]
fn main() {
extern crate defmt;
defmt::info!("answer={:u8}", 42);
// on the wire: [2, 125, 42] <- arguments
//  string index ^  ^^^ timestamp
}

A log frame will consist of:

  • A string index that must be either of the error, warn, info, debug or trace kind.
    • String indices generated by write! (used in Format implementations) are of a different kind
  • A timestamp (LEB128 encoded)
  • Zero or more formatting arguments

To be able to decode the last component the host will have to lookup the format string, whose index is the first part of the log frame, and parse it. Parsing that string will tell the host how many and how big (in bytes) the formatting arguments are.

Lookup

We have so far looked at the string table using nm. Programmatically the table can be found in the .symtab section. Each entry in this table represents a symbol and each entry has:

  • shndx, a section header index (?). This should match the index of the .defmt section.
  • value, this is the address of the symbol. For .defmt, this is the string index
  • name, an index into some data structure full of strings. get_name returns the interned string
  • the other info is not relevant