Using defmt to trace function execution

[mattico]

https://user-images.githubusercontent.com/853158/123317587-cd36e380-d4f3-11eb-938c-1e478464a0fb.mp4

I've hacked together function tracing for a private project which works surprisingly well. I think it's something that we could support with a reasonable amount of effort. I'll describe what I've done and comment on changes that could help polish this up.

Background

I have an STM32H7 running RTIC firmware which has different tasks at different interrupt priority levels. Lots of free RAM (512KB AXI SRAM). Lots of idle CPU (~50%). Can't block or disable interrupts for sync as I have to respond to an interrupt very consistently within microseconds.

I believe this could be made to work for other systems with different requirements. If there's little free RAM the tracing could be triggered at runtime and run until the buffer is full. Systems with less stringent latency requirements could submit smaller buffers more frequently. Selectively enabling tracing (https://github.com/knurling-rs/defmt/pull/519) would help reduce bandwidth requirements. Lower priority messages could be dropped to create space for newer higher priority messages.

Logger

I have a framed BBQueue per thread priority so logging never blocks. If the queue is full we skip the message and increment a counter for warning later. In the idle subroutine I copy frames from the thread queues to a large buffer, encode with rzCOBS, and transmit over a UART with DMA at 2Mbps. The Logger waits for the host to transmit a character before it begins sending the logs to avoid losing data.

Wire Format 2.0 (https://github.com/knurling-rs/defmt/issues/492) is already implementing rzCOBS framing. We could add a generic BBQueue logger implementation (https://github.com/knurling-rs/defmt/issues/460#issuecomment-827116010) to help support various transports. It would be helpful to know ahead of time how much space is required for a log message but that is probably difficult in general.

Function Tracing

I'm using the trace crate attribute macro to easily generate function enter/exit messages. I've modified it lightly to not use thread local storage (no indentation) and to use defmt. I manually add TASK: to RTIC task function names to help understand task switching.

Theoretically we could do sample-based profiling as well by periodically recording the program counter, but I haven't implemented this.

Host Recording

I've modified probe-run and defmt-print to support serial port reading and rzCOBS decoding. You can enable an output log file and can use a log level filter for the console output separate from the log file.

I think it would be nice for probe-run to support serial ports, but perhaps the data could be piped into defmt-print. It's nice having it all integrated, though, especially since probe-run can tell the target when its ready for log data.

Profile Viewing

I wrote a small program that parses the log file to create a Firefox Profiler (https://profiler.firefox.com/) compatible output. I initially targeted Trace Compass (https://www.eclipse.org/tracecompass/), but it was trickier to integrate since it's designed for the complex Linux tracing ecosystem. The Firefox profiler is obviously designed for multi-thread multi-process C and Javascript profiles but it's flexible enough to work pretty well for this use case. The program sorts the log lines (they may have been reordered by the priority queues) and uses regexes to parse function trace messages. It keeps track of call stacks and task switching to output profiler samples.

Having custom message tags (https://github.com/knurling-rs/defmt/issues/182) for function call/return and variable value watches would be less of a hack than parsing log messages as text. The custom messages could possibly use a purpose-built efficient encoding, but defmt is already pretty good at sending interned strings.

---

defmt already works pretty well for this use case, and many of the improvements that are being worked on will help as well. We can at least keep it in mind as we think about changes for the future. I'll see how much of this I can polish up and open source.