julia's space

defmt, but in C

who says you need rust macros?

defmt is a logging library designed not to serialise the formatted string over the link, but instead just the minimal information necessary.

defmt ("de format", short for "deferred formatting") is a highly efficient logging framework that targets resource-constrained devices, like microcontrollers. — Ferrous Systems, "defmt"

Being able to skip the dynamic interpretation of printf() arguments at runtime also helps lower the overhead of debug printing. There is no need to know how to format %.2f as human-readable bytes for the log emitter. Instead, this is the responsibility of someone else, all you need to do is send the data bytes.

For an example, consider:

uint8_t a = 232, b = 18, c = 55;
uint64_t d = 100040;
printf("The values are %d, %d, %d, %lu\n", a, b, c, d);

An implementation of printf needs to:

  1. Iterate through fmt until reaching % (then emit The values are )
  2. Read %d and then emit the first argument, in base 10 (not easy!)
  3. Iterate through to the next %, (then emit , )
  4. Repeat a few more times.

In contrast, defmt-style loggers - by virtue of not formatting the string - simply can emit the arguments, i.e.:

  1. Emit a string index e.g. 02 00 (defmt uses 16-bit little-endian)
  2. Emit the first argument e8 (single byte)
  3. Repeat a few more times.
  4. Emit the last argument, c8 86 01 00 00 00 00 00. (8 bytes)

huh? #

Basically, we can do this:

int main(void) {
  DEFMT_DEBUG(".. DONE");
  DEFMT_DEBUG("HELLO: {0=i32} {1=u32}", 5, 7);
  DEFMT_DEBUG("HELLO: {0=i32} {1=u8} 0x{2=u32:x}", 5, (uint8_t)7, 35);
  DEFMT_ERROR("HELLO: {0=u64}", (uint64_t)5);
  DEFMT_WARN("Hello \"\\\" World ({0=i8})\n", (int8_t)-1);

  return 0;
}
$ ./build/demo | hexdump -C
00000000  02 00 03 00 05 00 00 00  07 00 00 00 04 00 05 00
00000010  00 00 07 23 00 00 00 06  00 05 00 00 00 00 00 00
00000020  00 05 00 ff
00000024
$ ./build/demo | defmt-print -e build/demo
DEBUG .. DONE
DEBUG HELLO: 5 7
DEBUG HELLO: 5 7 0x23
ERROR HELLO: 5
WARN  Hello "\" World (-1)

The main advantage lies in not having to encode the long strings themselves.

how does this work? #

Export a symbol with the name of the symbol containing JSON-encoded information about each log. Here's the symbol table for the .defmt section.

|   VIRT ADDR   |  OBJECT SIZE  | SYMBOL NAME
0000000000000002 0000000000000000 __DEFMT_MARKER_TRACE_START
0000000000000002 0000000000000000 __DEFMT_MARKER_TRACE_END
0000000000000002 0000000000000000 __DEFMT_MARKER_DEBUG_START
0000000000000002 0000000000000001 {"package":"../src/main.c","tag":"defmt_debug","data":".. DONE","disambiguator":"18"}
0000000000000003 0000000000000001 {"package":"../src/main.c","tag":"defmt_debug","data":"HELLO: {0=i32} {1=u32}","disambiguator":"19"}
0000000000000004 0000000000000001 {"package":"../src/main.c","tag":"defmt_debug","data":"HELLO: {0=i32} {1=u8} {2=u32:x}","disambiguator":"20"}
0000000000000005 0000000000000000 __DEFMT_MARKER_DEBUG_END
0000000000000005 0000000000000000 __DEFMT_MARKER_INFO_START
0000000000000005 0000000000000000 __DEFMT_MARKER_INFO_END
0000000000000005 0000000000000000 __DEFMT_MARKER_WARN_START
0000000000000005 0000000000000001 {"package":"../src/main.c","tag":"defmt_warn","data":"Hello \"\\\" World ({0=i8})\n","disambiguator":"22"}
0000000000000006 0000000000000000 __DEFMT_MARKER_WARN_END
0000000000000006 0000000000000000 __DEFMT_MARKER_ERROR_START
0000000000000006 0000000000000001 {"package":"../src/main.c","tag":"defmt_error","data":"HELLO: {0=u64}","disambiguator":"21"}
0000000000000007 0000000000000000 __DEFMT_MARKER_ERROR_END
0000000000000007 0000000000000001 _defmt_version_ = 4
0000000000000008 0000000000000001 _defmt_encoding_ = raw
0000000000000009 0000000000000000 __DEFMT_MARKER_END

no, but really? #

[insert crimes]

The code is available on git here.

Essentially:

  1. Make a symbol in the same manner that defmt does:

    #define _DEFMT_SYMBOL_INTERN(variable, level, symbol_name)                     \
  do {                                                                         \
    const static uint8_t symbol _DEFMT_EXPORT_SYMBOL_NAME(symbol_name)         \
        _DEFMT_KEEP _DEFMT_SECTION(level);                                     \
    /* Linker script places starting from vaddr 0 in info section <=> ID */    \
    *(variable) = (uint16_t)(uintptr_t)(&symbol);                              \
  } while (0)

    To do the equivalent of Rusts' [export_name] in C, we can use the asm() attribute on a symbol name. Of course, Clang and GCC differ in their behaviour; Clang escapes spaces for you, whereas GCC does not. See issue #62101 and also a fun bug I discovered where -save-temps behaviour in Clang differed than without it: #138390.

  2. For each argument to the log macro, call an appropriate function to encode the output.

    For this, we use the preprocessor _Generic:

    #define _DEFMT_LOG_ENCODE_ONE(value)                                           \
  _Generic((value),                                                            \
      uint64_t: _defmt_c_write_uint64_t,                                       \
      uint32_t: _defmt_c_write_uint32_t,                                       \
      uint16_t: _defmt_c_write_uint16_t,                                       \
      uint8_t: _defmt_c_write_uint8_t,                                         \
      int64_t: _defmt_c_write_int64_t,                                         \
      int32_t: _defmt_c_write_int32_t,                                         \
      int16_t: _defmt_c_write_int16_t,                                         \
      int8_t: _defmt_c_write_int8_t)(_defmt_write, (value));

    _defmt_write corresponds to the same function that Rust uses; so should be for the most part compatible with mixed Rust and C.

This is of course, delightfully cursed. Just like printf, if you mess up the specification of the types in the format-string compared to passed to the macro, things will subtly break. At least it won't be undefined behaviour, as all the formatting is done by a decoder elsewhere.

The statement below expands as:

// This
DEFMT_ERROR("HELLO: {0=u64}", (uint64_t)5);
// expands as...
do {
  uint16_t id;
  do {
    const static uint8_t symbol asm(
        "{" "\"package\"" ":" "\"/home/julia/code/defmt-for-c/src/main.c\""
        "," "\"tag\"" ":" "\"defmt_error\""
        "," "\"data\"" ":" "\"HELLO: {0=u64}\""
        "," "\"disambiguator\"" ":" "\"21\""
        "}") __attribute__((used)) __attribute__((section(".defmt." "error" ".")));
    *(&id) = (uint16_t)(uintptr_t)(&symbol);
  } while (0);
  do {
    _defmt_acquire();
    _Generic((id),
        uint64_t: _defmt_c_write_uint64_t,
        uint32_t: _defmt_c_write_uint32_t,
        uint16_t: _defmt_c_write_uint16_t,
        uint8_t: _defmt_c_write_uint8_t,
        int64_t: _defmt_c_write_int64_t,
        int32_t: _defmt_c_write_int32_t,
        int16_t: _defmt_c_write_int16_t,
        int8_t: _defmt_c_write_int8_t)(_defmt_write, (id));
    _Generic(((uint64_t)5),
        uint64_t: _defmt_c_write_uint64_t,
        uint32_t: _defmt_c_write_uint32_t,
        uint16_t: _defmt_c_write_uint16_t,
        uint8_t: _defmt_c_write_uint8_t,
        int64_t: _defmt_c_write_int64_t,
        int32_t: _defmt_c_write_int32_t,
        int16_t: _defmt_c_write_int16_t,
        int8_t: _defmt_c_write_int8_t)(_defmt_write, ((uint64_t)5));
    ;
    _defmt_release();
  } while (0);
} while (0);

This (on x86_64) expands to:

; ./src/main.c:21
;   DEFMT_ERROR("HELLO: {0=u64}", (uint64_t)5);
4005df: b8 06 00 00 00                movl    $0x6, %eax
4005e4: 66 89 45 f8                   movw    %ax, -0x8(%rbp)
4005e8: e8 c9 fe ff ff                callq   0x4004b6 <_defmt_acquire>
4005ed: 0f b7 45 f8                   movzwl  -0x8(%rbp), %eax
4005f1: 0f b7 c0                      movzwl  %ax, %eax
4005f4: 89 c6                         movl    %eax, %esi
4005f6: bf c4 04 40 00                movl    $0x4004c4, %edi         # imm = 0x4004C4
4005fb: e8 80 fd ff ff                callq   0x400380 <_defmt_c_write_uint16_t@plt>
400600: be 05 00 00 00                movl    $0x5, %esi
400605: bf c4 04 40 00                movl    $0x4004c4, %edi         # imm = 0x4004C4
40060a: e8 81 fd ff ff                callq   0x400390 <_defmt_c_write_uint64_t@plt>
40060f: e8 a9 fe ff ff                callq   0x4004bd <_defmt_release>

It's possible that there's a better way to handle the _defmt_c_write_int32_t functions - I ran into the problem where linking this as a library meant that directly calling _defmt_write would call the wrong / non-existent function; I didn't spend much time on this because it's easily fixable.

void _defmt_c_write_int32_t(_defmt_write_fn_t *write_fn, int32_t v) {
  write_fn((struct slice){.ptr = (uint8_t *)&v, 4});
}

limitations #