#45 Software Tracing with printf

This lesson explains "debugging by printf" as the most common software tracing technique. You'll learn how to implement printf on the TivaC LaunchPad board, as well as NUCLEO-L152. You'll also explore some shortcomings of this primitive technique.

Contents with Timestamps:
-------------------------
3:18 Adding printf tracing to the BSP code
4:25 Attempts to run and the hardcoded breakpoints
6:00 MicroLIB and the fputc() function
7:25 Instrumentation Trace Macrocell (ITM)
8:00 Demonstration of STM32 NUCLEO board
8:50 Sending output via ITM
9:40 Setting up ST-LINK for tracing with ITM
9:55 Opening view "Debug (printf) Viewer"
10:58 Universal Asynchronous Receiver and Transmitter (UART)
12:11 Code for sending printf output via UART in TivaC
14:19 Opening and connecting serial terminal (Termite)
16:25 Tracing macros (variadic macros and __VA_ARGS__)
19:42 Build Configurations
20:18 Creating the "spy" build configuration for software tracing
22:35 Costs and overheads of printf tracing
23:40 Impact of floating-point format specification
24:45 Impact of printf tracing on execution time

End Notes:
----------
Companion web-page to this video course

Project download for this lesson:

GitHub repository for projects for this video course:

Transcript of this lesson:

References resources:
---------------------
Termite -- a simple RS232 terminal:

STM NUCLEO-L152RE board

Instrumentation Trace Macrocell

Music credits:
--------------
The background music comes from:

[zhitailiu]

Usually embedded designers use uart plus DMA to greatly reduce the cost of execution time.
However, the ASCII-printf style of software tracing simply carries too little information per byte.
Something way more cleaver, like QSpy, must be utilised.
Thx, Miro, always high quality video!

[TheEmbeddedHobbyist]

As you point out using printf to debug screws your real time performance. It also moves your code around in memory so there is a chance that it will run when debugging but give issues then they are removed. I liked it when I could use emulators for the processor and had far greater control. If I have spare io I will use them to go high when entering a subprocess and low again when leaving. This might only take up a few clock cycles so helps with timing as well. Nice video thanks.

[stevenlathrop]

As usual, I learn something with every episode – Thank you so much for this body of work.

As someone who works with processes timed in nanoseconds and microseconds, printf is excessively costly in time to be useful for software tracing. Tracing stuff going on in interrupt handlers can also be problematic.

Since I have not had the luxury of debuggers like the one that you have shown, I have had to create logging functions on my own. What has worked for me is a singleton that accepts a string, prepends a unique ascending counter value to it, and adds it to an array that you dump to a text file when it gets full. Actually two arrays, since one has to be available for writing while the other is being written to a file, which is time consuming. Any other formatting I do it after the log file is complete. (The logging procedure must be protected from interruption, especially in a multi-threaded environment. A call to a singleton function seems to prevents this.) (This is much easier to implement in Ada than in C/C++, but it can be done.)

To create a call stack-like trace, each file gets a variable that contains the APP name and Module Name, and each named body of code gets a variable with its name. That allows strings like “App.Module.Procedure.Start” and “App.Module.Procedure.End” to be composed on the fly, which you add to the beginning and end of a body of code. As already shown, this technique can be used to trace state transitions if a log entry is made for each state Entry and Exit.

If you have a program that halts, add an integer variable called “last_line” to your code and add “last_line = <<ascending unique number>>; before each executable statement. In any exception handling, dump the value of “last_line” to identify the last successfully run line of code. (This is very easy to do in Ada, and tougher in C/C++)

If the problem is identifying what happened up to a point, interleave problematic code with an exact copy of the code that follows it as the log entry rather than any other text. The trace output will then be a complete trace of the code that was run during a test. It will not solve the problem of code optimization reorganizing the code, but it will help if the code unexpectedly takes paths that programmer did not expect.

Lastly, give yourself a way to turn logging on and off while processing. I pass a Boolean flag called Trace to each call. When Trace is true, add logging, when Trace is false, do not log. Since Trace is passed to each function and procedure, turning on logging at a higher level of abstraction means every function or procedure below it will log without any other work. Once the questionable code has been identified, the logging can be tuned down to just the section that needs to be traced.

I have a feeling that all of this will be shown eloquently in the next lesson, which I am looking forward to.

Again, thanks for the lessons so far.

[ThePing]

thanks for the video, is using DMA with UART will be a solution for the printf problem, because there are some cases when it is hard to use the debugger, for example, I was working the nrf52 and as soon as I stop the code the BLE stop working, also printf if useful when you try to collect a streaming set of data for further analysis

[MrSebkilou]

Better if you add flush, like this: #definition MY_PRINTF(format, ...) printf(format_, ##__VA_ARGS__); flush()
Important if you're looking for a line of code that crashes. Otherwise your message contained in printf not followed by flush may not appear if the next line of code crashes.