[TW#12145] Replacement of standard printf() functionality

[ammaree]

We use a modular but fully functional ??printf() module (with non standard extensions) throughout our applications and on a variety of platforms. It has been tested on the CC3200, Particle Photon and to some extent on the ESP32 platform.

Currently the ESP-IDF uses the standard printf() in all LOGx and various other functions. Can a kconfig option be provided to replace the standard library printf()?

Alternatively, is there an option or mechanism to specify that our x[snf]printf() functions, using the alias mechanism, replace the standard [snf]printf functions?

[igrr]

You can set custom vprintf-like function for log output at run time:
http://esp-idf.readthedocs.io/en/latest/api/system/log.html#_CPPv219esp_log_set_vprintf14vprintf_like_t

Currently there is no mechanism which would allow substituting printf implementation. It is not clear to me how such replacement could work. Printf implementation needs to know about specifics of stdio streams, stdio locking facilities, and reentrancy support. This means that your printf library needs to use private header files from newlib, to pull out definitions of newlib internal structures. Is this how it works now?

[igrr]

@ammaree does the above answer your question, or would you like to comment on the possible printf replacement mechanism for newlib?

[ammaree]

@igrr it seems my email answer on the thread disappeared into the ether, so let me recap and provide some background.

A couple of issues arise around printf(), the LOGx functionality and the UART.

Firstly (and hopefully easiest to solve, there seems to be a baudrate issue around the initial baudrate used for UART output not being equal to the kconfig specified baudrate. This causes consistent garbled output between boot and a later point where the actual baudrate is changed.

Secondly, The [fnsv]printf() implementation seems to be very heavy on stack. Posting an application from CC3200/FreeRTOS using our own syslog/printf functionality to ESP32/FreeRTOS using LOGx functionality increase stack usage from a comfortable 2kbytes to a cramped 5kbytes, without the syslog functionality. The main culprit seems to be the printf().

Mechanism for replacement could take the format of a user supplied “user_config_xx.h” type file in selected modules to override certain defaults. This override functionality will also be of great value in FreeRTOSConfig.h to provide the necessary flexibility to make some features work such as the RTOS task statistics.

The esp_log_set_vprintf() functionality unfortunately only comes into play when the main application starts, in which case all the earlier ESP_LOGx() calls would already have ensured the inclusion of the standard printf library, hence bloating the size of the application and complicating debugging.

More important, is the absence of proper syslog functionality. LOGx() seems to follow some syslog type reasoning but with key limitations being no actual network syslog support.What we have done, and suggest be considered here, is as follows:

a) The x_syslog() function takes a number of parameters such as:

• a task handle (if NULL used current task handle),
• required priority (=severity & facility)
• message ID, often a calling function or module name
• printf style format string
• variable list of parameters.
  b) If a syslog host name/address specified at compile time can be resolved it will attempt to establish a connection.
  c) It will build an RFC compliant header and message using all the supplied parameters into a small static buffer.
  d) If it was successful opening a connection to a syslog server, and depending on a default (but dynamically changeable) syslog threshold priority, it will sendto() the complete message to the syslog host.
  e) In all cases it will output a slightly truncated message to the "console"
  f) Currently we have not added the color functionality for severity 0 to 4, but this can easily be done.
  g) This mechanism removes the need to the TAG and surrounding logic, adds true [optional] syslog capability,

The reference to "console" is intentionally vague since we have a very small layer of abstraction to allow for a "console" channel to be UARTx, ITM or SWO if in an ARM Cortex environment or Segger RTT. Currently, in the ESP32 space, it seems as if we will be limited to a UART since an ITM nor SWD is supported/available.

On the printf side, here is some background on our functionality.
Our experience with newlib is limited but without having made any specific adjustment for newlib we have tested our replacement module successfully, even accessed from multiple tasks concurrently. Let me try to explain the architecture of our xprintf() and the associated stdio and retargeting subsystem.

The xprintf module support the following:

• printf, sprintf, snprintf, fprintf and all the v??printf equivalents.
• Fully re-entrant with no static memory variables
• No dynamic memory allocation
• Support signed and unsigned long and optional long long
• Optional support single and double precision float with (compile time) rounding selection to 1 to 15 digits accuracy
• Supports standard IO streams being console, string and file (stdout and/or stderr)
• Optional binary, time, date, hexdump, IP and MAC address format specifiers

The xprintf functions does not do any semaphore locking, instead if “locking” is required xfprintf(stdout,..) should be used in which case the x_stdio replacement module will implement very basic locking for stdin/out/err. Using xprintf() will directly call the console driver which could result in garbled output if called from multiple tasks simultaneously.

If interested, happy to offer the syslog() and printf() code for inclusion as a module.

[igrr]

Okay, so in order for replacement to work, you would need to:

1. remove newlib's stdio.h from the include path and add your custom stdio.h into the include path,
2. remove newlib's object files (which provide implementations of stdio functions) from the linker input object list,

is this correct?

Comments about other points you have made:

there seems to be a baudrate issue around the initial baudrate used for UART output not being equal to the kconfig specified baudrate

ROM bootloader will always print some initial output at 115200 baud, as the ROM does not know anything about the application, kconfig, and so on. ROM bootloader output can be disabled using a bootstrapping pin, please check "ESP32 chip pin list" document.
Starting from the second stage bootloader (the one which is placed at 0x1000 in flash), baud rate should be exactly what you specify in sdkconfig. If this is not the case, please open an issue...

increase stack usage from a comfortable 2kbytes to a cramped 5kbytes

Since you already have a printf replacement this will likely not be a compelling option, but have you tried building with "Enable 'nano' formatting options for printf/scanf family" enabled in menuconfig? This should reduce the required stack size by approximately 1k.

Regarding syslog support these are all very good suggestions. We now have a work-in-progress change which enables logging via OCD interface (and JTAG) to the PC. Once this is done, we also plan to add an example which shows how to stream ESP_LOG output over network.

[ammaree]

As far as the newlib/stdio suggestions, we might have to experiment with options. Ultimately we need want to replace ALL references to ALL variants of ???printf() functionality, and redirect/ replace the LOGx() functionality throughout ESP-IDF...

My suggestion is that a mechanism is implemented for the developer to provide an alternative (maybe the suggested user provided include file) to replace all LOGx functionality transparently at compile time. Properly implemented, this should remove/replace all newlib [fnsv]printf() calls as well

ROM bootloader, thanks, that explains the garbled UART output.

Stack use, problem will slowly solve itself (we hope) as we simplify the environment. Our printf has significant extensions for embedded/debug use (hence nano will not work) with minimal stack and no dynamic memory allocation.

[igrr]

I don't think replacing LOGx functionality via a header file will be sufficient (as a bunch of components use snprintf, for instance, which is not log-related).

On the other hand, if we replace newlib-provided stdio.h with custom stdio.h, and remove newlib's stdio implementation at link time, all the components will use custom versions of [vsnf]printf provided by your library. Does this make sense?

[ammaree]

sounds good, maybe the mechanism should be an option to specify an alternative (x_stdio.h in our case) using kconfig ?

[ammaree]

@igrr an update.

I have been able to make most of the printf substitution/replacement work except for 2 functions so far. By swapping the sequence of definition and alias around the linker complains only about the following 2 functions:

make -j8
CC x_printf.o
AR libcommon.a
LD esp-ota-https.elf
C:/Dropbox/devs/ws/esp32/esp-ota-https/build/common\libcommon.a(x_printf.o): In function vprintf': C:/Dropbox/devs/ws/z-support/common/x_printf.c:1164: multiple definition of vprintf'
C:/Dropbox/devs/ws/z-sdk/esp-idf/components/newlib/lib/libc.a(lib_a-vprintf.o):/Users/ivan/e/newlib_xtensa-2.2.0-bin/newlib_xtensa-2.2.0/xtensa-esp32-elf/newlib/libc/stdio/../../../.././newlib/libc/stdio/vprintf.c:35: first defined here
C:/Dropbox/devs/ws/esp32/esp-ota-https/build/common\libcommon.a(x_printf.o): In function vfprintf': x_printf.c:(.text.vfprintf+0x0): multiple definition of vfprintf'
C:/Dropbox/devs/ws/z-sdk/esp-idf/components/newlib/lib/libc.a(lib_a-vfprintf.o):/Users/ivan/e/newlib_xtensa-2.2.0-bin/newlib_xtensa-2.2.0/xtensa-esp32-elf/newlib/libc/stdio/../../../.././newlib/libc/stdio/vfprintf.c:655: first defined here
collect2.exe: error: ld returned 1 exit status
make: *** [C:/Dropbox/devs/ws/z-sdk/esp-idf/make/project.mk:323: /c/Dropbox/devs/ws/esp32/esp-ota-https/build/esp-ota-https.elf] Error 1

Is there anything different/strange in how these are treated in your source, or am I missing it...

[ammaree]

@igrr any news on this issue?

[igrr]

should be an option to specify an alternative (x_stdio.h in our case) using kconfig

I don't see how this would work. Many source files have an #include <stdio.h>, do you propose all these files to be modified to something like #include CONFIG_STDIO_HEADER? And if not all the files are modified, then we will still have newlib-provided functions and replacement functions side by side, which is what you are trying to avoid.

Regarding the linking error, you probably need to use xtensa-esp32-elf-ar to remove unneeded object files from libc.a. Alternatively, you may rebuild newlib from this repository: https://github.com/espressif/newlib-esp32, omitting the functions you don't need.

What probably needs to be implemented on the ESP-IDF side is a mechanism which would allow you to place your project-specific include directories and library directories in front of newlib component directories. This way your custom versions of libc.a and stdio.h will be chosen by the linker and preprocessor respectively.

[ammaree]

The objective is to try override/replace the newlib printf() functionality completely. The esp-idf components can divided into 3 categories being: * #1 : native esp-idf modules that (I believe) will all use ESP_LOGx() * #2 : 3rd party modules such as LwIP, AWS, Bluedroid, mBedTLS and others that allow printf() macro substitution * #3 : 3rd party modules that do not allow for easy printf() macro substitutions #1 are all using ESP_LOGx() so no hassle, #2 seems most (or all) have already been modified to use ESP_LOGx() so no problem here. To handle #1 and #2 we need to provide an option to specify a replacement for the ESP_LOGx() functionality, possibly a macro with alternative include file name To handle #3 I agree your solution to remove the default printf() object files from newlib is possibly the easiest. Doing this also effectively resolves #1 and #2 since the ESP_LOGx() macro will then also call the replacement xprintf() function(s).

[hwmaier]

I have done similar function level replacements in the past using the existing esp-idf build system. So I don't think any additional support is required for this rather rare use case.

Approach 1)
You can add a replacement library with your custom printf before newlib is searched using EXTRA_LDFLAGS = -lmy_printf_lib to your Makefile.

Approach 2)
A linker will always first search object files and then library files. Use this behavior to add an object file (not a library!) to your project replacing for example printf with your own version. You then useEXTRA_LDFLAGS = my_printf.o to add this object file to the link process.
If you also want to replace a system header file, then this is possible too. Have a look at the various options gcc offers to inject additional include files (-include) or to influence the include search order.

Approach 3)
You could use the -Wl,--wrap,printf linker flag to inject your own version of printf. The linker will in this case resolve all calls to printf with a call to __wrap_printf. Your replacement version is then called __wrap_printf and the old newlib's is called __real_printf. I used this technique to replace newlib's malloc and free with a thread-safe version in another project unrelated to ESP32.

[projectgus]

One other thought (after discussion on the linked issue), that I don't think I've seen mentioned yet:

If enabling newlib nano formatting reduces the stack overhead by an acceptable amount (it does make a big difference), then what about redirecting stdout & stderr rather than linking against a custom printf? This should be supported now, although I don't know if anyone has done this.

[ammaree]

The reason for the replacement of the newlib formatted print functionality is as a result of a number of things:
#1 significant additional functionality to support the printing of date and time info (both absolute and elapsed time values) in a number of industry standard formats as well as debug style dumping of memory as 8/16/32/64 bit values with a range of formatting options, and various other commonly used formats.
#2 removed the need for dynamic memory allocation completely.
#3 reduced the code size significantly (~20KB) depending of range of printf functions used.
#4 minimised stack usage with ~500 bytes and since the various printf functions are often called from multiple tasks the combined savings across all tasks can be significant.

So for now we are fine, once a new version of newlib is out we might change to use one of the suggestions by hwmaier above.