Today we are thrilled to announce the public release of defmt ("de format"). defmt stands for "deferred formatting" and it's a highly efficient logging framework. As we covered in our blog post about embedded tooling for the 21st century we hope defmt will serve as the base for features like data visualization and interactive logging front-ends. In this post we'll cover how to use defmt with probe-rs supported devices and what you can do with defmt today.

Setup

We have created a Cargo project template to make the setup easier.

⚠️ EDIT: You can find the most up-to-date setup instructions in the template's README. The following steps 0.-5. have been preserved here for archiving purposes and may become outdated.

Here are the setup steps.

0. Install the git version of probe-run, a custom Cargo runner that lets you run embedded apps if they were native apps. Be sure to enable the defmt Cargo feature!

$ cargo install \
    --git https://github.com/knurling-rs/probe-run \
    --branch main \
    --features defmt

1. Either initialize the project template with cargo-generate or fetch a copy and initialize the Cargo.toml manually.

$ cargo generate \
    --git https://github.com/knurling-rs/app-template \
    --branch main \
    --name my-app

If you are not using cargo-generate you'll need to manually enter the author and name fields in Cargo.toml.

 # Cargo.toml
 [package]
-# authors = ["{{authors}}"]
-# name = "{{project-name}}"
+name = "my-app"

After that there are a few TODOs in the template. You can ripgrep for the word TODO (rg TODO .cargo .) to find them but we'll walk you through all of them in this blog post.

2. Pick a chip from probe-run --list-chips and enter it into .cargo/config.toml.

If, for example, you have a nRF52840 Development Kit from one of our workshops then replace {{chip}} with nRF52840_xxAA.

 # .cargo/config.toml
 [target.'cfg(all(target_arch = "arm", target_os = "none"))']
-runner = "probe-run --chip {{chip}} --defmt"
+runner = "probe-run --chip nRF52840_xxAA --defmt"

3. Adjust the compilation target in .cargo/config.toml.

For the nRF52840 chip you'll want to use the thumbv7em-none-eabihf target.

 # .cargo/config.toml
 [build]
-target = "thumbv6m-none-eabi"    # Cortex-M0 and Cortex-M0+
-# target = "thumbv7m-none-eabi"    # Cortex-M3
-# target = "thumbv7em-none-eabi"   # Cortex-M4 and Cortex-M7 (no FPU)
-# target = "thumbv7em-none-eabihf" # Cortex-M4F and Cortex-M7F (with FPU)
+target = "thumbv7em-none-eabihf" # Cortex-M4F (with FPU)

4. Add a HAL as a dependency.

For the nRF52840 you'll want to use the nrf52840-hal.

 # Cargo.toml
 [dependencies]
-# some-hal = "1.2.3"
+nrf52840-hal = "0.11.0"

5. Now that you have selected a HAL fix the HAL import in src/lib.rs

 // my-app/src/lib.rs
-// use some_hal as _; // memory layout
+use nrf52840_hal as _; // memory layout

Hello defmt

You are now all set to cargo-run your first defmt-powered application! There are some examples in the src/bin directory.

// my-app/src/bin/hello.rs

#![no_main]
#![no_std]

use my_app as _; // global logger + panicking-behavior + memory layout

#[cortex_m_rt::entry]
fn main() -> ! {
    defmt::info!("Hello, world!");

    my_app::exit()
}

cargo run-ning this program produces the classic "Hello, world!" output.

$ # `rb` is an alias for `run --bin`
$ cargo rb hello
    Finished dev [optimized + debuginfo] target(s) in 0.03s
flashing program ..
DONE
resetting device
0.000000 INFO Hello, world!
(..)

$ echo $?
0

Or if you are using VS code + Rust-Analyzer, instead, you can open the src/bin/hello.rs file and click the "Run" button as we demonstrated in a previous blog post.

Now let's take a closer look at the features of the framework. This post will be a quick overview. For more details check out the defmt book.

Panics

We have wired the panic_handler to defmt to make panicking much cheaper. Consider this example, which is part of the project template:

// my-app/src/bin/panic.rs

#[cortex_m_rt::entry]
fn main() -> ! {
    defmt::info!("main");

    panic!()
}

It produces this output:

$ cargo rb panic
0.000000 INFO main
0.000001 ERROR panicked at src/bin/panic.rs:11:5
stack backtrace:
   0: 0x00000554 - __bkpt
   1: 0x00000524 - template::exit
   2: 0x00000514 - rust_begin_unwind
   3: 0x000001c8 - core::panicking::panic_fmt
   4: 0x000001a2 - core::panicking::panic
   5: 0x00000164 - panic::__cortex_m_rt_main
   6: 0x00000108 - main
   7: 0x00000238 - ResetTrampoline
   8: 0x00000214 - Reset

As you may have seen from our previous posts with probe-run you get a stack backtrace for free!

Binary size

What I wanted to highlight here is the binary size. Here's the output of cargo-size (part of the cargo-binutils project).

$ cargo size --bin panic -- -A
section              size        addr
.text                1272       0x100
.rodata               360       0x600

An here's the output of cargo-bloat

$ cargo bloat -n 5 --bin panic
File  .text   Size     Crate Name
0.4%  14.2%   180B defmt_rtt <defmt_rtt::Logger as defmt::Write>::write
0.3%  12.9%   164B     defmt defmt::Formatter::leb64
0.3%  12.3%   156B  template rust_begin_unwind
0.2%   9.6%   122B [Unknown] __aeabi_memcpy
0.2%   8.2%   104B     panic panic::__cortex_m_rt_main
1.0%  40.4%   514B           And 22 smaller methods. Use -n N to show more.
2.5% 100.0% 1.2KiB           .text section size, the file size is 49.0KiB

There are no core::fmt function calls there and that's what makes the binary so small.

vs rprintln!

Let's compare against a program that uses rtt_target::rprintln, which is hard-wired to core::fmt.

#[cortex_m_rt::entry]
fn main() -> ! {
    rtt_target::rtt_init_print!();
    panic!()
}

#[panic_handler]
fn panic(info: &core::panic::PanicInfo) -> ! {
    rtt_target::rprintln!("{:?}", info);
    my_app::exit()
}

cargo-size output:

$ cargo size --bin panic-rprintln -- -A
section              size        addr
.text               10348       0x400
.rodata              3840      0x2c70

cargo-bloat output:

$ cargo bloat -n 5 --bin panic-rprintln
File  .text    Size Crate Name
0.6%   7.4%    768B   std core::str::slice_error_fail
0.6%   7.4%    768B   std core::fmt::Formatter::pad
0.6%   7.2%    748B   std <&T as core::fmt::Debug>::fmt
0.5%   6.6%    680B   std core::unicode::printable::is_printable
0.5%   5.9%    608B   std <&T as core::fmt::Debug>::fmt
5.2%  65.2%  6.6KiB       And 60 smaller methods. Use -n N to show more.
8.0% 100.0% 10.1KiB       .text section size, the file size is 127.1KiB

The biggest functions are core::fmt related. The defmt-powered panic uses 1.59 KB of Flash (.text + .rodata); panic-rprintln uses 13.85 KB. That's almost a whopping 9x savings. See the table below for the complete breakdown:

programs compiled with -Oz and lto=fat

Now you can panic without reservation: panic messages are no longer binary-size expensive. Also, no more need to reach out for crates that discard panic information, like panic-halt, to keep the binary size low.

Logging levels

If you have used the log crate before you know that it supports 5 logging levels: trace, debug, info, warn and error – sorted from lowest severity to highest. defmt supports the same five levels through 5 logging macros: trace!, debug!, info!, warn! and error!. Let's see them in action:

// my-app/src/bin/levels.rs

#[cortex_m_rt::entry]
fn main() -> ! {
    defmt::info!("info");
    defmt::trace!("trace");
    defmt::warn!("warn");
    defmt::debug!("debug");
    defmt::error!("error");

    my_app::exit()
}

This is the output:

$ cargo rb levels
0.000000 INFO info
0.000001 TRACE trace
0.000002 WARN warn
0.000003 DEBUG debug
0.000004 ERROR error

Not shown above but the logging level (e.g. INFO) gets nicely colored in the terminal output.

Filters

The main reason for having logging levels is to be able to filter some of them out. If we re-run the levels example but compile it using the release profile we get less output:

$ # `rrb` is an alias for `run --release --bin`
$ cargo rrb levels
0.000000 INFO info
0.000001 WARN warn
0.000002 ERROR error

This is because the project template has been configured to report all logging levels when the dev profile is used, but only INFO and higher severity logs when the release profile is used.

defmt defaults to logging nothing (filtering everything out) but this behavior can be configured via Cargo features.

If you look at the project template's Cargo.toml you'll see that the defmt-default feature is enabled for the top crate (my-app):

[features]
default = [
  "defmt-default",
# "dependency-a/defmt-trace",
]

The defmt-default behavior logs at TRACE level and higher severity if profile is dev and log INFO and up if profile is release. The other features like defmt-warning enable logging at the specified level (WARN) and up regardless of the compilation profile (dev or release).

Logging filters can be configured per crate using Cargo features. If you have used the env_logger crate you may have used the RUST_LOG environment variable to enable logging in dependencies. With env_logger you use RUST_LOG=dep-a=debug,dep-b=info to enable DEBUG logging in dep-a and INFO logging in dep-b. With defmt that configuration is done in the top crate's Cargo.toml as shown below:

 # Cargo.toml
 [features]
 default = [
   "defmt-default",
-# "dependency-a/defmt-trace",
+  "dep-a/defmt-debug",
+  "dep-b/defmt-info",
 ]

Formatting

So far we have only logged string literals in our examples but defmt also supports formatting arguments. core::write! supports a variety of formatting parameters, each one associated to a formatting trait: {:?} (Debug), {} (Display), {:x} (Hex). defmt has a single formatting trait: Format, which is associated to the {:?} formatting parameter.

{:?} expects a type that implements the Format trait. Format is implemented for primitives like integers and slices. To implement Format for user-defined types (structs or enums) use the #[derive(Format)] attribute.

In addition to {:?}, there are formatting parameters for some primitives: e.g. {:u8}, {:bool}. Prefer these parameters for primitives as they compress the data better.

Here's a formatting example:

// src/bin/format.rs

use defmt::Format; // <- derive attribute

#[derive(Format)]
struct S1<T> { x: u8, y: T }

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

#[cortex_m_rt::entry]
fn main() -> ! {
    let s = S1 { x: 42, y: S2 { z: 43 } };
    defmt::info!("s={:?}", s);

    let x = 42;
    defmt::info!("x={:u8}", x);

    my_app::exit()
}

Output:

$ cargo rb format
(..)
0.000000 INFO s=S1 { x: 42, y: S2 { z: 43 } }
0.000001 INFO x=42

Bitfields

There's a formatting parameter for printing "bitfield views" of a unsigned integer. This feature is aimed towards easing the visualization of MMIO registers on the console and it's easier to explain with an example.

// my-app/src/bin/bitfield.rs

#[cortex_m_rt::entry]
fn main() -> ! {
    // value of the FREQUENCY register (nRF52840 device; RADIO peripheral)
    let frequency: u32 = 276;
    defmt::debug!("FREQUENCY: {0:0..7}, MAP: {0:8..9}", frequency);
    //                         ^same  argument^

    my_app::exit()
}

Output:

$ cargo rb bitfield
0.000000 DEBUG FREQUENCY: 20, MAP: 0b1

In this example we are printing the value of the FREQUENCY register. This register is 32-bit in size but only 8 bits contain data: the 7-bit bitfield 0..7 (bit 7 excluded) and bit 8. Instead of displaying the full 32-bit value which includes 24 bits of reserved (read as zero) data we use the bitfield feature to display only the relevant data.

Timestamps

All log statements are timestamped. How the timestamp is computed or read can be configured using the #[timestamp] attribute. The template ships with a dummy implementation that increases an atomic counter on each invocation and uses that as the timestamp. That implementation is a good starting point compatible with all Cortex-M devices but you'll eventually want to swap it with a device-specific implementation that reads a hardware timer.

Right now the timestamp must be absolute uptime (time elapsed since the start of the application) and must be a 64-bit value in microseconds. In the future, we want to provide a mechanism to be able to completely remove the timestamp (to reduce bandwidth usage) or switch to timestamp in human units (date + time + timezone). Other improvements include looking into delta encoding the timestamp to reduce bandwidth usage.

Transport agnostic

One of defmts core features is that it is transport agnostic. This means that logs can be transferred from the target device to the developer's PC/laptop over any transport. In this first public release we are including a RTT (Real Time Transfer) transport: defmt-rtt. RTT is supported by probe-rs so it fits nicely with the probe-run tool.

As convenient as RTT is, it requires a probe (AKA hardware debugger) between to the target microcontroller and the developer's PC. Not all development boards ship with on-board debuggers and production boards are likely to leave out the probe (for cost and security reasons) so, in the future, we expect we'll see defmt over other transports like serial interface, USB and maybe as circular logs persisted to a microSD card or similar.

What's next?

That was a quick tour of what defmt can do today. For more details please check out the book.

We haven't talked about performance of defmt in this blog post; we'll leave that as an exercise for the reader! How does it fare against rprintln!, core::fmt or ufmt? Let us know!

We still owe you a blog post about using probe-run and a custom panic handler for unit testing (we have not forgotten!). Now that we have a Cargo project template we are looking into extending it so that it ships with unit testing functionality.

We'll continue working on defmt with the goal of a 1.0 release. We haven't finalized the binary format that defmt uses and that's the main blocker for a 1.0 release. We need to ensure that the binary format is rich enough to support features like data visualization on the host.

We expect several bugs will pop up once defmt gets more wider use so please try out defmt and test it beyond its limits. We also expect some more breaking changes to the wire format in the near future. These will most likely go unnoticed so long you keep probe-run and defmt in sync (defmt is a git dependency of probe-run). Worry not, probe-run will let you know when things go out of sync and it's time to update it.

Sponsor this work

probe-run is a Knurling project and can be funded through GitHub sponsors. Sponsors get early access to other tools we are building. Thank you to all of the people already sponsoring our work through the Knurling project!