Printf using printf-stdarg.c (2022)

Kernel
1

I have seen printf using printf-stdarg.c however, I’m still not sure if it is applicable to my project.

I am using FreeRTOS SMP with RP2040/Pico; and I use the default printf there (pico-sdk), to print to the USB serial port the RP2040 app creates.

Eventually, my code grew, so it now often does a isr_hardfault (or other deadlocks) when there is a lot of printing, and typically a gdb backtrace will reveal that at least one of the cores has been running a printf related function at time of hardfault/deadlock.

Then, I noticed https://github.com/FreeRTOS/FreeRTOS-Kernel/blob/main/include/task.h :

An alternative, tiny, third party, and limited  
* functionality implementation of sprintf() is provided in many of the  
* FreeRTOS/Demo sub-directories in a file called printf-stdarg.c (note 
* printf-stdarg.c does not provide a full snprintf() implementation!).

Well, that’s great - I’d really like to try a tiny sprintf() :)

However, I cannot really tell - can I?

The thing is - the pico-sdk already defines a printf, that defaults to printing to the USB serial port. So, I’d have to somehow override it.

Then, looking at where this file is found in GitHub - FreeRTOS/FreeRTOS: 'Classic' FreeRTOS distribution. Started as Git clone of FreeRTOS SourceForge SVN repo. Submodules the kernel., and which projects have a related Makefile for gcc (since that is how I build by FreeRTOS + pico-sdk code):

$ find FreeRTOS -name '*stdarg.c' | while read f; do ls -la "$f" ; find $(dirname "$f")/ -name Makefile -exec printf "  %s\n"  {} \; ; done
-rw-r--r-- 1 user None 6.8K Jul  8 09:26 FreeRTOS/FreeRTOS/Demo/ColdFire_MCF52221_CodeWarrior/sources/printf-stdarg.c
-rw-r--r-- 1 user None 6.8K Jul  8 09:26 FreeRTOS/FreeRTOS/Demo/ColdFire_MCF52259_CodeWarrior/printf-stdarg.c
-rw-r--r-- 1 user None 7.6K Jul  8 09:25 FreeRTOS/FreeRTOS/Demo/CORTEX_A9_Cyclone_V_SoC_DK/printf-stdarg.c
-rw-r--r-- 1 user None 6.8K Jul  8 09:25 FreeRTOS/FreeRTOS/Demo/CORTEX_AT91SAM3U256_IAR/printf-stdarg.c
-rw-r--r-- 1 user None 7.3K Jul  8 09:25 FreeRTOS/FreeRTOS/Demo/CORTEX_LM3S6965_GCC_QEMU/LocalDemoFiles/printf-stdarg.c
-rw-r--r-- 1 user None 6.8K Jul  8 09:25 FreeRTOS/FreeRTOS/Demo/CORTEX_M0+_Atmel_SAMD20_XPlained/RTOuseremo/src/printf-stdarg.c
-rw-r--r-- 1 user None 7.6K Jul  8 09:25 FreeRTOS/FreeRTOS/Demo/CORTEX_M4F_MSP432_LaunchPad_IAR_CCS_Keil/system/CCS/printf-stdarg.c
-rw-r--r-- 1 user None 7.6K Jul  8 09:26 FreeRTOS/FreeRTOS/Demo/CORTEX_M4_SimpleLink_CC3220SF_CCS/printf-stdarg.c
-rw-r--r-- 1 user None 7.4K Jul  8 09:26 FreeRTOS/FreeRTOS/Demo/CORTEX_MPS2_QEMU_IAR_GCC/build/gcc/printf-stdarg.c
  FreeRTOS/FreeRTOS/Demo/CORTEX_MPS2_QEMU_IAR_GCC/build/gcc/Makefile
-rw-r--r-- 1 user None 6.4K Jul  8 09:26 FreeRTOS/FreeRTOS/Demo/CORTEX_STM32F103_Primer_GCC/printf-stdarg.c
-rw-r--r-- 1 user None 6.6K Jul  8 09:26 FreeRTOS/FreeRTOS/Demo/IA32_flat_GCC_Galileo_Gen_2/Support_Files/printf-stdarg.c
-rw-r--r-- 1 user None 8.5K Jul  8 09:27 FreeRTOS/FreeRTOS/Demo/lwIP_AVR32_UC3/printf-stdarg.c
  FreeRTOS/FreeRTOS/Demo/lwIP_AVR32_UC3/AT32UC3A/GCC/Makefile
-rw-r--r-- 1 user None 6.7K Jul  8 09:26 FreeRTOS/FreeRTOS/Demo/MB91460_Softune/SRC/utility/printf-stdarg.c
-rw-r--r-- 1 user None 6.7K Jul  8 09:26 FreeRTOS/FreeRTOS/Demo/MB96340_Softune/FreeRTOS_96348hs_SK16FX100PMC/Src/utility/printf_stdarg.c
-rw-r--r-- 1 user None 6.7K Jul  8 09:26 FreeRTOS/FreeRTOS/Demo/MicroBlaze_Kintex7_EthernetLite/RTOuseremo/src/printf-stdarg.c
-rw-r--r-- 1 user None 6.8K Jul  8 09:26 FreeRTOS/FreeRTOS/Demo/MSP430X_MSP430F5438_CCS/Demo_Source/printf-stdarg.c
-rw-r--r-- 1 user None 7.6K Jul  8 09:26 FreeRTOS/FreeRTOS/Demo/MSP430X_MSP430FR5969_LaunchPad_IAR_CCS/printf-stdarg.c
-rw-r--r-- 1 user None 6.7K Jul  8 09:26 FreeRTOS/FreeRTOS/Demo/PIC32MX_MPLAB/printf-stdarg.c
  FreeRTOS/FreeRTOS/Demo/PIC32MX_MPLAB/RTOuseremo.X/Makefile
-rw-r--r-- 1 user None 7.4K Jul  8 09:26 FreeRTOS/FreeRTOS/Demo/RISC-V_RV32_QEMU_VIRT_GCC/build/gcc/printf-stdarg.c
  FreeRTOS/FreeRTOS/Demo/RISC-V_RV32_QEMU_VIRT_GCC/build/gcc/Makefile
-rw-r--r-- 1 user None 6.8K Jul  8 09:26 FreeRTOS/FreeRTOS/Demo/RX100-RSK_GCC_e2studio/RTOuseremo/printf-stdarg.c
-rw-r--r-- 1 user None 18K Jul  8 09:25 FreeRTOS/FreeRTOS-Plus/Demo/AWS/Device_Shadow_Windows_Simulator/Common/printf-stdarg.c
-rw-r--r-- 1 user None 14K Jul  8 09:25 FreeRTOS/FreeRTOS-Plus/Demo/FreeRTOS_Plus_TCP_Minimal_Windows_Simulator/printf-stdarg.c

… I can see that:

  • None of these hits are in the directory ./FreeRTOS/Demo/ThirdParty/Community-Supported/CORTEX_M0+_RP2040, which would be the one for the MCU I use
  • All printf-stdargs.c files that otherwise exist have file sizes that differ, so they’re likely platform specific
  • Only the demo projects for CORTEX_MPS2_QEMU_IAR_GCC, lwIP_AVR32_UC3, AT32UC3A, PIC32MX_MPLAB, and RISC-V_RV32_QEMU_VIRT_GCC also have a Makefile

I looked briefly at the Makefile - config.mk - of lwIP_AVR32_UC3, and all I could see was that printf-stdargs.c was added last to the list of source files to be compiled, and I did not notice any special linker switches.

So I tried the same - added a printf-stdargs.c to my RP2040 FreeRTOS project, with the contents:

#include "stddef.h"

int printf( char *apBuf, size_t aMaxLen, const char *apFmt, ... )
{
	return 0;
}

… and rebuilt; it went fine, but trying to look in the result with readelf:

$ arm-none-eabi-readelf -s my_program.elf | grep 'stdarg'
$

… no filename containing stdarg is listed among the source files recorded in the .elf binary.

Then again, if I look into the symbols of the binary .elf:

$ arm-none-eabi-nm -a my_program.elf | grep 'printf'
1000e01c T __wrap_printf
1000ce5c T __wrap_snprintf
1000dfd8 T __wrap_vprintf
1000c838 t _vsnprintf
00000000 a printf.c
1000ce84 T vfctprintf

… there is no actual symbol printf – there is only __wrap_printf; and if I read the nm output correctly (i.e. listed .c. files are followed by symbols defined in them), then __wrap_printf comes from __call_atexit.c, and I cannot tell where that comes from.

So, my questions are:

  • Can I use a printf-stdarg.c approach to override (s)printf for RP2040, or not?
    • If not, how could I have judged that from existing examples? (e.g. maybe those platforms where there is a demo with printf-stdarg.c, do not provide a default stdio/printf like pico-sdk does, and that is why they can use this approach?)
    • If yes, what is the approach: is it “just” add the source file “last” in the list of source files to be sure it is compiled (well, probably not, judging from my results above) - or does one also have to do additional steps (maybe change linking order of object files; or add some additional code in my main.c; or add special linker flags)? If there is a need for additional steps - what are those?
      • And if yes, what would be the best project to look at, for an example of everything that would have to be changed in a printf-stdarg.c, so I can use it on RP2040? (my guess is CORTEX_M0+_Atmel_SAMD20_XPlained, since the RP2040 is also Cortex M0+, but IDK)
2

The module printf-stdarg.c has been borrowed in many demo projects. It has a couple of advantages above the use of the standard implementations of the [v][s][n]printf() family.

I used the module already for a long time, and adapted it through time.

Please find printf-stdarg.c on my Github. It is compatible with many platforms.

● The functions use a minimal amount of stack
● The functions are interrupt-safe
● All functions are re-entrant, i.e. need no mutex protection
● None of the functions uses the heap

Note that it has two call-backs:

extern void vOutputChar( const char cChar,
                         const TickType_t xTicksToWait );
extern BaseType_t xApplicationMemoryPermissions( uint32_t aAddress );

These are explained within the module.

The function xApplicationMemoryPermissions() can help avoid a crash when the format %s is used. When an invalid pointer is provided, the function will print the string "INV_MEM" in stead of throwing an exception.

I do not recommend to use vOutputChar(), because it is much too slow.

Floating formatting is not yet supported. You’d have to do some tricks there, like casting to int values.

About linking: these functions will be compiled as C-functions (not C++), and they will replace the functions with equal names, provided by the compiler.

Personally, I never like to mis-use printf, it sends bytes to stdout, which we often don’t have.

FreeRTOS demo projects usually define their own functions for logging:

int lUDPLoggingPrintf( const char *pcFormatString, ... );
int lUDPLoggingVPrintf( const char *pcFormatString, va_list xArgs );
#define FreeRTOS_printf( X )         lUDPLoggingPrintf( X )
#define FreeRTOS_debug_printf( X )   lUDPLoggingPrintf( X )

Mentioned functions can be called without the protection of a mutex.

I don’t have RP2040 here, and so I can not test it with printf-stdarg.c. I my projects it may appear in any position, because none of the modules defines equal function, except for the standard C libraries.

EDIT : one more thing to mention, the functions in mentioned printf-stdarg.c won’t do anything that is not allowed within a critical section, beside using some CPU time.

3

Many thanks for the response, @htibosch - much appreciated!

However, I still have things that are a bit unclear to me - so I hope I will get some further guidance…

Something ended up wrong in that link, since I couldn’t click it - thankfully I could look at the source of your post thanks to the edit, and I could see the Markdown link starts with E:\Home\amazon-freertos....i.e. it was local.

I searched a bit on the forum, and I think the actual URL to the file on your github is:

https://github.com/htibosch/freertos_plus_projects/blob/master/plus/Common/Utilities/printf-stdarg.c

Is that correct?

About linking: these functions will be compiled as C-functions (not C++), and they will replace the functions with equal names, provided by the compiler.

I don’t have RP2040 here, and so I can not test it with printf-stdarg.c. I[n] my projects it may appear in any position, because none of the modules defines equal function, except for the standard C libraries.

Thanks for mentioning this - I believe it is here where the problem with RP2040’s pico-sdk occurs.

I have tried making an example FreeRTOS project called rp2040_fros_printf_test, compiled against pico-sdk FreeRTOS SMP branch; the gist is here:

https://gist.github.com/sdbbs/1927fbb4c4c71b3094dcee387dcfc7b7/e36e25e5992bcecc9f8964ac8468d16abbbbf948

This project can be cloned, then just a build subdirectory needs to be created (GitHub gists do not support subdirectories), and them cmake .... and make can be executed there, to compile the project, and get binary files such as rp2040_fros_printf_test.elf.

The main.c defines two tasks that run continuously: the one running on core 0 prints stuff, then goes to sleep with varying vTaskDelay before it loops; the one running on core 1 prints stuff, then does 10 ms of busy wait before it loops. The program seems to run fine (i.e. I cannot see deadlocks that I mentioned in the OP, that I’ve seen elsewhere).

In any case, besides main.c, I have also included your printf-stdarg.c in the project; this file does get compiled, and linking stage passes - however, I cannot confirm that the executable ends up with any of the symbols from printf-stdarg.c. I have noted earlier:

if I read the nm output correctly (i.e. listed .c. files are followed by symbols defined in them), then __wrap_printf comes from __call_atexit.c, and I cannot tell where that comes from.

That turned out to be wrong - after closer inspection, it turns out that the output of nm -a sorts symbols and filenames alphabetically! However, I found elf - nm: some symbols are not related to any source file - Stack Overflow which had the correct nm invocation to find C source files where symbols come from; and for the example project binary rp2040_fros_printf_test.elf I get:

$ arm-none-eabi-nm -a -l -n -t x --print-size rp2040_fros_printf_test.elf | grep printf
00000000 a printf.c
100002e4 00000018 t prvSetupHardware    C:/path/to/rp2040_fros_printf_test/main.c:51
100002fc 0000009c t init_freertos_tasks C:/path/to/rp2040_fros_printf_test/main.c:60
10000398 00000080 T task_one    C:/path/to/rp2040_fros_printf_test/main.c:103
10000418 0000005c T task_two    C:/path/to/rp2040_fros_printf_test/main.c:133
10000474 00000012 T main        C:/path/to/rp2040_fros_printf_test/main.c:33
10000488 0000001c T vApplicationStackOverflowHook       C:/path/to/rp2040_fros_printf_test/main.c:148
100004a4 0000001c T vApplicationMallocFailedHook        C:/path/to/rp2040_fros_printf_test/main.c:154
10005234 00000008 t _out_buffer C:/path/to/pico-sdk/src/rp2_common/pico_printf/printf.c:137
1000523c 00000002 t _out_null   C:/path/to/pico-sdk/src/rp2_common/pico_printf/printf.c:144
1000523e 0000000e t _out_fct    C:/path/to/pico-sdk/src/rp2_common/pico_printf/printf.c:163
1000524c 00000024 t _atoi       C:/path/to/pico-sdk/src/rp2_common/pico_printf/printf.c:190
10005270 000000ae t _out_rev    C:/path/to/pico-sdk/src/rp2_common/pico_printf/printf.c:200
1000531e 00000112 t _ntoa_format        C:/path/to/pico-sdk/src/rp2_common/pico_printf/printf.c:228
10005430 000000bc t _ntoa_long  C:/path/to/pico-sdk/src/rp2_common/pico_printf/printf.c:279
100054ec 000000e2 t _ntoa_long_long     C:/path/to/pico-sdk/src/rp2_common/pico_printf/printf.c:305
100055d0 00000412 t _etoa       C:/path/to/pico-sdk/src/rp2_common/pico_printf/printf.c:467
100059e4 00000354 t _ftoa       C:/path/to/pico-sdk/src/rp2_common/pico_printf/printf.c:342
10005d38 00000624 t _vsnprintf  C:/path/to/pico-sdk/src/rp2_common/pico_printf/printf.c:581
1000635c 00000028 T __wrap_snprintf     C:/path/to/pico-sdk/src/rp2_common/pico_printf/printf.c:904
10006384 00000020 T vfctprintf  C:/path/to/pico-sdk/src/rp2_common/pico_printf/printf.c:916
100074bc 00000044 T __wrap_vprintf      C:/path/to/pico-sdk/src/rp2_common/pico_stdio/stdio.c:230
10007500 00000018 T __wrap_printf       C:/path/to/pico-sdk/src/rp2_common/pico_stdio/stdio.c:256

So, if there was a symbol stemming from printf-stdarg.c, that filename should have showed up in the output above, but it doesn’t - in fact, it seems that most of the printf-related stuff comes from pico-sdk’s pico_printf/printf.c.

The good thing is, that I can run make VERBOSE=1, and it will dump the full command lines that are used to compile main.c and link the executable; these can be seen in the files cmdline_compile.txt, and cmdline_link.txt
in the gist. There I can see:

  • -DLIB_PICO_PRINTF=1 -DLIB_PICO_PRINTF_PICO=1 used in compile line
  • -Wl,--wrap=printf -Wl,--wrap=vprintf used in linker line

Finally, I can add the switches -E -dD to the gcc call in the compile line, rerun it, and obtain the preprocessed source output. There I can see:

# 114 "c:\\msys64\\mingw64\\arm-none-eabi\\include\\stdio.h" 3
#define _IOFBF 0
...
#define stdin (_REENT->_stdin)
#define stdout (_REENT->_stdout)
#define stderr (_REENT->_stderr)
...
int printf (const char *restrict, ...)
               __attribute__ ((__format__ (__printf__, 1, 2)));
...
int snprintf (char *restrict, size_t, const char *restrict, ...)
               __attribute__ ((__format__ (__printf__, 3, 4)));

So, prototypes for printf in this program do come ultimately from stdio.h of arm-none-eabi (not of pico-sdk’s pico_stdio, as I thought earlier !) - but otherwise, the preprocessed code keeps printf/snprintf as they are.

However, if I look into the assembly output with objdump, with interleaved source lines, I can see:

$ arm-none-eabi-objdump -S rp2040_fros_printf_test.elf
...
100003d0:       db11            blt.n   100003f6 <task_one+0x5e>
    printf( "%"PRIu64 ": %s\n", get_absolute_time(), report );
100003d2:       a902            add     r1, sp, #8
100003d4:       9100            str     r1, [sp, #0]
100003d6:       480c            ldr     r0, [pc, #48]   ; (10000408 <task_one+0x70>)
100003d8:       f007 f892       bl      10007500 <__wrap_printf>
...

… so the call to printf in C source, has ended up as call to __wrap_printf in the binary output! Maybe this is due to the -Wl,--wrap=printf linker switch, but I am not sure …

So, I’m not sure what I need to change in my project, in order for the functions in printf-stdarg.c to be used instead - or if it is possible (well, I’m sure it is ultimately “possible”, though maybe changes will not be trivial, so maybe such an undertaking will not be worth the effort?)

Thanks for this - now that you’ve mentioned them, I recall having seen something like this earlier, but have not taken a deeper look at these …

One thing I am not certain about: if I lookup, say, FreeRTOS_printf the only documentation I get is TCP/IP stack configuration parameters :

Some of the TCP/IP stack demo applications generate output messages. The TCP/IP stack outputs these messages by calling the FreeRTOS_printf macro. To obtain the demo application messages set ipconfigHAS_PRINTF to 1, then define FreeRTOS_printf() to a function that takes a printf() style format string and variable number of inputs, and sends the formatted messages to an output of your choice.

So, FreeRTOS_printf is not a formal macro on the level of FreeRTOS library (like the FreeRTOS Trace Hook Macros are) - rather, it is a somewhat “arbitrary” macro defined on the level of demo applications, and then we still need to provide our own implementation for the functions the macros refer to; is that correct?

On the other hand, I can see in my preprocessor output:

# 1004 "C:/path/to/FreeRTOS-Kernel-SMP/include/FreeRTOS.h"
#define configPRINTF(X)

… a macro configPRINTF, which is empty, however.

Another thing I’d want to clarify: I can see UDP in lUDPLoggingPrintf; however, the RP2040 Pico board that I work with, only has a USB connector, which in the default examples appears as a USB serial port, through which printf is redirected. And so far, I haven’t found any examples for Pico/RP2040 regarding a “UDP printf” (now that there is a “Pico W” board with a Wi-Fi chip, that might change - but it will still not be applicable to the plain Pico).

So, I guess, if I want to have an “UDP printf” on the plain Pico, I’d first need to have the Pico appear as a network adapter over USB, and that works (see Setting up Windows 10 network connection, for device network adapter via USB (RNDIS)? · Discussion #1550 · hathach/tinyusb). However, how do I go from here? Would I need to compile FreeRTOS+TCP configuration, along with the network adapter setup? Does the entire TCP stack need to be compiled, even if I only want to use UDP?

4

Hi again,

Ok, I think I got somewhere - I managed to implement two approaches in overriding (well, sort of) printf with functions in printf-stdarg.c, which can be compiled and ran on a Pico/RP2040, and output to USB serial port using pico-sdk stdio.

Please take a look at the following commit in the gist referred to in previous post, where these are implemented:

https://gist.github.com/sdbbs/1927fbb4c4c71b3094dcee387dcfc7b7/80052140c8c72f755d26abe519ae627c8d519092

These two approaches are briefly outlined below - since I’d really like to hear some comments, if they at least make sense to others … but before that:

A bit about pico-sdk printf:

  • The printf function itself is defined in rp2_common/pico_stdio/stdio.c - not in rp2_common/pico_printf/printf.c (but it uses functions from there)
  • In compiled code, this function ends up as symbol __wrap_printf - possibly because of the aforementioned -Wl,--wrap=printf linker switch
  • there is a switch PICO_STDIO_ENABLE_CRLF_SUPPORT which automatically converts line endings

First, I focused on just using snprintf from printf-stdarg.s, because at least snprintf does not deal with I/O, only in-memory work. The problem is that it has the same name as the pico-sdk function, so I cannot just #define it myself. I could rename the function directly in the printf-stdarg.c file, but I really would not like to mess with this file.

It turns out (c - How to deal with symbol collisions between statically linked libraries? - Stack Overflow), for GCC, one can use objcopy to prefix/replace symbol names in libraries, so the CMakeLists.txt got modified to run objcopy with this purpose before linking, and replace the snprintf symbol in the printf-stdarg.c.obj object file with _stdarg_sprintf; and then, since the FreeRTOS_printf macro is somewhat arbitrary anyways, I intruduced my own FreeRTOS_snprintf macro like this:

extern int _stdarg_snprintf( char * apBuf, size_t aMaxLen, const char * apFmt, ... );
#define FreeRTOS_snprintf( apBuf, ... ) _stdarg_snprintf( apBuf, ##__VA_ARGS__ )

Then I replaced all my calls to snprintf() with FreeRTOS_snprintf() - and this finally compiled and linked, and I could confirm with nm and objdump that indeed I am using the snprintf from printf-stdarg.c now (although, at first, I used it its output with the printf from pico-sdk).

Now, the printf.

I always had the impression that printf is a “beast” - but I really got the feeling for how much of a “beast” it is, after reading http://blog.hostilefork.com/where-printf-rubber-meets-road/ - which outlines a ton of indirections and code, before even considering output hardware!

While the example project here is not Linux, printf still has to talk to an output hardware, which I found a bit tricky to identify.

first approach - tiny_printf

Looking at printf-stdarg.c, I was first suprised there is only a printf definition for _MSC_VER, that is Microsoft compiler, and I wondered what else should I use.

Then I realized there is a tiny_printf function in printf-stdarg.c, which follows the printf function structure, and ultimately calls tiny_printf → tiny_print → strbuf_printchar_inline → vOutputChar; and having been informed by @htibosch previously that vOutputChar is a callback that I should overload, I decided to try this (even with the warning that vOutputChar is much too slow).

In any case, vOutputChar seems kind of an obvious naming for a glue, that we want to output a character to an output hardware - this case USB serial port - and the easiest for me was to look into pico-sdk stdio, and realize that the putchar there does that.

So, since in this project, the symbol name tiny_printf is unique and does need prefixing, I just added this to the main code:

// tiny_printf -> tiny_print -> strbuf_printchar_inline -> vOutputChar
extern int tiny_printf( const char * format, ... );
#define FreeRTOS_printf( format, ... ) tiny_printf( format, ##__VA_ARGS__ )

// vOutputChar is __attribute__( ( weak ) ) in printf-stdarg.c,
// so we should be able to override with this
void vOutputChar( const char cChar, const TickType_t xTicksToWait ) {
  // use pico-sdk/src/rp2_common/pico_stdio/stdio.c putchar
  //  -> stdio_put_string -> out_func( driver->out_chars (==stdio_usb_out_chars))
  // putchar accepts int, cChar should be coerced into it
  putchar(cChar);
}

I found doing my own implementation of the xApplicationMemoryPermissions() also tricky, because most of the examples just return 0x03. The only example I found (after a while) that actually manages it is freertos_plus_projects/plus/sam4e/src/main.c, and then I found corresponding memory region macros in pico-sdk.

Finally, i then replaced every call to printf() in my code with FreeRTOS_printf() - and it worked. Note that printf-stdarg.c needs to be compiled with SPRINTF_LONG_LONG defined to 1, otherwise it cannot print 64-bit timestamp of pico-sdk.

In a sense expected, the output of the program in this approach looks like this:

...
47276357: Task two at step 3942 (core 1); busy-waiting for 10 ms
47283538: Task one at step 161 (core 0); task delay/sleep for 32 ms
47292728: Task two at step 3943 (core 1); busy-waiting for 10 ms
47309232: Task two at step 3944 (core 1); busy-waiting for 10 ms
47322533: Task one at st47325267: Task two at step 3945 (core 1); busy-waiting for 10 ms
ep 162 (core 0); task delay/sleep for 16 ms
47344566: Task two at step 3946 (core 1); busy-waiting for 10 ms
47354531: Task one at step 163 (core 0); task delay/sleep for 847360843: Task two at step 3947 (core 1); busy-waiting for  ms10 ms

47378526: Task one at s4738tep 10861: Task two at step 3948 (core 1); busy-waiting for 10 ms
64 (core 0); task delay/sleep for 4 ms
47398533: Task one at step 147401278: Task65 (co re 0); two at step 3949 (core 1); busy-waiting for 10 ms
task delay/sleep for 2 ms
47417536: Task one at step 166 (core 0); task delay/s47422995: Task two at stlep 3950 (core 1); busy-waiting foeer 10 ms
p for 1 ms
47435545: Task one at step 167 (core 0); task delay/sleep for 2 ms
...

… that is, once the tough gets going in CPU land, we start seeing characters being interleaved.

To get this behavior from the example project program, keep //#define USE_SERIAL_LOGGING_PRINTF commented in main.c.

second approach - serialLogging

I was lucky, to eventually have stumbled upon freertos_plus_projects/Ultrascale/FZ3_app/src/main.c, because it has a FreeRTOS_printf implementation function serialLogging, which:

  • seems to “lock” the printout similarly to pico-sdk printf, but using a FreeRTOS semaphore (where pico-sdk printf might use a mutex)
  • seems to output to both serial port, and UDP - but keeps the serial write within the lock, while the UDP write is outside

So, this encouraged me to try an approach, where I use the same mechanism as in serialLogging for serial port write, but using pico-sdk functions to do the USB serial write.

I tried first copying functions from pico-sdk stdio directly (the same ones used in its printf), but realized there is a LOT to copy and duplicate symbols might emerge; and since in the end we do have a full string, I ended up just using pico-sdk’s puts_raw() to write the buffer towards USB serial.

Note that this seems to bypass CRLF conversion which otherwise seems to be default for pico-sdk USB serial stdio, so now my \n in printout came out as actual \n → which messed up viewing of printouts in MSYS2/MINGW64 shells, until I piped the serial output to unix2dos.

This is the output of this approach:

...
1250592559: Task two at step 122717 (core 1); busy-waiting for
1250593431: Task one at step 4472 (core 0); task delay/sleep fo
1250602907: Task two at step 122718 (core 1); busy-waiting for
1250613359: Task two at step 122719 (core 1); busy-waiting for
1250623732: Task two at step 122720 (core 1); busy-waiting for
1250634076: Task two at step 122721 (core 1); busy-waiting for
1250644439: Task two at step 122722 (core 1); busy-waiting for
1250654968: Task two at step 122723 (core 1); busy-waiting for
1250657429: Task one at step 4473 (core 0); task delay/sleep fo
1250665340: Task two at step 122724 (core 1); busy-waiting for
1250675737: Task two at step 122725 (core 1); busy-waiting for
1250686203: Task two at step 122726 (core 1); busy-waiting for
1250689429: Task one at step 4474 (core 0); task delay/sleep fo
1250696601: Task two at step 122727 (core 1); busy-waiting for
1250705498: Task one at step 4475 (core 0); task delay/sleep fo
1250706943: Task two at step 122728 (core 1); busy-waiting for
1250713498: Task one at step 4476 (core 0); task delay/sleep fo
1250717316: Task two at step 122729 (core 1); busy-waiting for
1250717420: Task one at step 4477 (core 0); task delay/sleep fo
...

Good to there is no more character interleaving, even when the going gets tough :). Also, it is noticeable strings are truncated at 64 characters - and the reason for that is PICO_STDIO_STACK_BUFFER_SIZE: the reason I’ve never seen it in effect before, is that pico-sdk’s printf seems to chunk whatever string size to this one, and then writes these chunks to USB serial port in a loop. (And it actually might be good that the printout now is explicitly truncated/limited in max size)

To get this behavior from the example project program, keep #define USE_SERIAL_LOGGING_PRINTF uncommented in main.c.

In any case, this works as well, and I think I have enough of an understanding now of the printf to USB serial port mechanisms, to try and get rid of my deadlocks … though I’d certainly appreciate comments.

(having an UDP printf example for pico/RP2040 would have also been great, but for now I’m happy I’ve at least got some better understanding of workarounds possible for the (USB) serial one…)

1 Like