[Solved] Saving "printf" arguments for later? Real-time on slow processor.

[incf]

I've got a situation where I am running a very slow processor that happens to have a lot of spare RAM. The CPU sits idle half of the time. It has some real time processing that it must do on time every handful of seconds. It is just barely fast enough to do its real time work without printfs.

The device firmware interfaces with a huge complicated third party library. This library implements a "debug mode" where it calls printf in various places.

In debug mode it easily generates several kilobytes of formatted number containing text per minute. And, what the library does is so complicated that we really need the debug output to be generated all of the time (both in development and production).

Unfortunately, It turns out that printf is so slow that it causes the system to fail in a variety of subtle yet completely catastrophic ways. (due to it missing real time deadlines and not being able to detect that it has missed them)

Has anyone dealt with this before?

I've reached the conclusion that my best bet is to write a wrapper for printf.
The wrapper would save the printf format string, and variadic arguments to a buffer so that I can process the printfs later when the CPU is idle.
I think I can get away with this since all of the printfs just contain (formatted) numbers and short strings.

I'd be interested to hear other people's thoughts and experiences with this sort of problem.

footnote: it is a shame I can't just spit the format string and raw stack values out the serial port to be interpreted by a PC program later. Have to parse the format string.

Edit: CPU is a ARM Cortex-M0+

edit: see last post, after implementing everything, a test printf with 8 arguments takes 600 cpu clock cycles

[tggzzz]

If printf is too slow, then don't printf so often nor so much. Don't bother wrapping printf.

Store the information in a RAM buffer fast. Information might be the bytes representing a number (not the human readable version thereof), or for predefined text simply store an integer indexing the text or a pointer to the text, or for an FSM state a pointer to the class implementing the state logic, or for an FSM event, an integer representing the type of the event plus the information in the event arguments.

When time allows, either transmit that information to another processor, or convert that information into a human readable format and then discard the information.

[incf]

I don't have any control over the third party library. It uses printf*, and all of it's debugging functionality is either "on", or "off."

*or rather, it calls a function that I supply that is expected to behave like printf

[Siwastaja]

Did you see this thread, it mentioned some ideas:

https://www.eevblog.com/forum/microcontrollers/low-footprint-printf-replacement-for-embedded-dev/?all

[DavidAlfa]

Write a wrapper to _write that copies the string to a queue and runs the uart in the backgroung in interrupt mode, or in main() but sending only one byte at a time, so it doesn't block the program execution.
Also, try increasing the baudrate, it's likely causing a bottleneck.

[incf]

Write a wrapper to _write which copies the data to a queue and runs the uart in the background in interrupt mode.
That won't block the program execution like now.
Also, try increasing the baudrate which is likely the culprit.

I already added buffering to _write and it still was too slow! It is a multi-threaded "real time" system that has a dedicated thread for the UART. I ended up giving each thread its own buffer to avoid contention, but even after that it was still too slow.

Parsing the format string and generating decimal digits in strings appears to be the culprit in terms of CPU cycle usage.

[incf]

Did you see this thread, it mentioned some ideas:

https://www.eevblog.com/forum/microcontrollers/low-footprint-printf-replacement-for-embedded-dev/?all

That is a good reference. I will likely refer to it when writing a format string parser.

[langwadt]

Write a wrapper to _write which copies the data to a queue and runs the uart in the background in interrupt mode.
That won't block the program execution like now.
Also, try increasing the baudrate which is likely the culprit.

I already added buffering to _write and it still was too slow! It is a multi-threaded "real time" system that has a dedicated thread for the UART. I ended up giving each thread its own buffer to avoid contention, but even after that it was still too slow.

Parsing the format string and generating decimal digits in strings appears to be the culprit in terms of CPU cycle usage.

do you really need the numbers in decimal or can you cheat and just print all the numbers in hex?

[tggzzz]

I don't have any control over the third party library. It uses printf*, and all of it's debugging functionality is either "on", or "off."

*or rather, it calls a function that I supply that is expected to behave like printf

You might have to ditch debugging inside the library, or ditch the library, or use two different debugging mechanisms. All of those would suck.

Does the library "play well" in a multithread/multicore environment? If not, that would be another reason to ditch the library.

"behave like printf" presumably means varargs and the return value, and nothing else. That's the only printf() behaviour visible within that library.

About 40 years ago I re-wrote _putc() so that printf() could be used in a hard realtime system. That system was, however, very well disciplined w.r.t. threads and priorities. I don't think it is a general purpose solution, but with discipline it worked.

Hasn't somebody written a C equivalent of the Java log4j library yet? That enables two-dimensional fine-grained logging to be turned on/off while running. Virtually zero overhead for the bits that are off.

[tggzzz]

Write a wrapper to _write which copies the data to a queue and runs the uart in the background in interrupt mode.
That won't block the program execution like now.
Also, try increasing the baudrate which is likely the culprit.

I already added buffering to _write and it still was too slow! It is a multi-threaded "real time" system that has a dedicated thread for the UART. I ended up giving each thread its own buffer to avoid contention, but even after that it was still too slow.

Parsing the format string and generating decimal digits in strings appears to be the culprit in terms of CPU cycle usage.

do you really need the numbers in decimal or can you cheat and just print all the numbers in hex?

Store the bits in the foreground threads, mutate them into decimal digits in a background thread. Basic point: printf() sucks rocks in constrained environments; hence printk().

You'll have to be inventive with "behaves like printf" in the foreground threads, but that's not difficult.

[incf]

.. ditch the library ..

The device's sole purpose is to run this library. The library is very nearly a "black box" from the perspective of the device.

Does the library "play well"

No, it is badly behaved and brittle. It does not tolerate even fractional millisecond delays generated by printf string processing. But it is effectively the only and highest priority thing running, higher priority than even things like the UART,

I fear even the small amount of time spent in timer interrupts (systick) might be too large for the library's thread when it is doing real-time work.

[incf]

do you really need the numbers in decimal or can you cheat and just print all the numbers in hex?

Unfortunately, most have to be formatted decimal to be of any value in system diagnostics.

[incf]

... Basic point: printf() sucks rocks in constrained environments; hence printk(). ...

Does printk save the variadic arguments/actually generating the string, for later?

[tggzzz]

... Basic point: printf() sucks rocks in constrained environments; hence printk(). ...

Does printk save the variadic arguments/actually generating the string, for later?

No idea; RTFM. Probably irrelevant for your application.

[ejeffrey]

Does it have to be formatted on device? Can you send binary data and format strings over the uart and have the host do the formatting?

Otherwise processing in a background thread will probably work as long as your CPU is actually fast enough to keep up.  If you already have a preemptive multitasking RTOS it shouldn't be that difficult to implement.

[tggzzz]

.. ditch the library ..

The device's sole purpose is to run this library. The library is very nearly a "black box" from the perspective of the device.

Does the library "play well"

No, it is badly behaved and brittle. It does not tolerate even fractional millisecond delays generated by printf string processing. But it is effectively the only and highest priority thing running, higher priority than even things like the UART,

I fear even the small amount of time spent in timer interrupts (systick) might be too large for the library's thread when it is doing real-time work.

With a library that is so brittle in a realtime environment, you need to ditch that library.

If you don't, you will be playing whack-a-mole in the field.

[incf]

Does it have to be formatted on device? Can you send binary data and format strings over the uart and have the host do the formatting?

Otherwise processing in a background thread will probably work as long as your CPU is actually fast enough to keep up.  If you already have a preemptive multitasking RTOS it shouldn't be that difficult to implement.

I'm free to do anything I want, but only after it calls the printf function that I supply to the library.

It's just a matter of getting the formatting string and all of the arguments out into a buffer someplace fast enough so that I can process it later (either in another thread, or on the PC).

[incf]

With a library that is so brittle in a realtime environment, you need to ditch that library.

If you don't, you will be playing whack-a-mole in the field.

I have no choice in the mater. The library, the processor, and the realtime-requirements are not changable in this application.

Best I can do is work diligently to ensure that worse case timing margins are as large as possible

[incf]

... two-dimensional fine-grained logging to be turned on/off while running. ...

While I can't change my library. I am curious what is "two-dimensional logging" ? Wiki page for log4j is silent on the matter.

[Analog Kid]

My (possibly naive) suggestion, which of course you're free to ignore if it's not possible or useful to you:

It sounds as if you can substitute your own printf() function for the one the library uses.
If so, good: what I'd do is in your replacement function, save the printf() arguments to your RAM, in a globally-accessible location.
You'll need a little data structure that includes the # of arguments, easy to implement.
When your printf() gets called, set a global flag indicating "there's data that needs to be printed".
Then, in another process or loop that runs when the CPU is idle, go through your list (array) of data structures and print them with the "back half" of your printf(), the one that actually outputs the data.

Let me know if I'm just plain wrong about this. (Wouldn't be the first time.)

[incf]

My (possibly naive) suggestion, which of course you're free to ignore if it's not possible or useful to you:

It sounds as if you can substitute your own printf() function for the one the library uses.
If so, good: what I'd do is in your replacement function, save the printf() arguments to your RAM, in a globally-accessible location.
You'll need a little data structure that includes the # of arguments, easy to implement.
When your printf() gets called, set a global flag indicating "there's data that needs to be printed".
Then, in another process or loop that runs when the CPU is idle, go through your list (array) of data structures and print them with the "back half" of your printf(), the one that actually outputs the data.

Let me know if I'm just plain wrong about this. (Wouldn't be the first time.)

You are correct, I think. I posted this thread to ask about the exact approach you suggested.

Really, I was hoping someone might have insight on making that process as fast as possible.

For example, if it might be possible to copy a chunk of the printf stack? Having to parse the format string (to get the number and type of arguments) and copy the variadic arguments one by one is a step that I would not mind pushing off to a background thread. But I'm not sure if it is even possible.

Edit: if I understand correctly, on gcc, variadic arguments appear to be stored on just like regular function arguments on the stack. Although I don't really understand the specifics, like how a printf like function would get the stack pointer back to where it should be if it doesn't know the number of arguments.



Edit 2: https://stackoverflow.com/a/36881737

I don't think I can make an array of va_list in C.

[edavid]

If the library uses all or mostly static format strings, you could hash the format string address to access a lookup table with the number of arguments etc.  That should be faster than parsing the format string.  Of course you would have to regenerate the hash table when the library was updated.

Or if you only/mostly need to handle numeric arguments rather than strings, you could do some tracing to figure out the maximum number of arguments, then always save that many.

P.S. Is there any way to upgrade your CPU, or add a "printf coprocessor" to the system?

P.P.S. Have you tried telling your management that the library doesn't work right?

[tggzzz]

... two-dimensional fine-grained logging to be turned on/off while running. ...

While I can't change my library. I am curious what is "two-dimensional logging" ? Wiki page for log4j is silent on the matter.

One dimension is the logging level, i.e. note, warning, error, panic and similar.

The other dimension is a hierarchical tree of components/subsystems, so a "comms" subsystem might have "uart", "ethernet", "led", lcd" sub components.

Each dimension is independent, so you might have "panic" turned on for all everything, "warning" (and worse) for ethernet and uart, and "note" for lcd.

If a level isn't turned on for a component, the only time penalty is a function call and testing a flag.

[tggzzz]

With a library that is so brittle in a realtime environment, you need to ditch that library.

If you don't, you will be playing whack-a-mole in the field.

I have no choice in the mater. The library, the processor, and the realtime-requirements are not changable in this application.

Best I can do is work diligently to ensure that worse case timing margins are as large as possible

The only system where I know that can be correctly done in a hard realtime system is xC running on xCORE. The IDE inspects the optimised binaries to tell you the max number of cycles between here and there. None of this "run and hope I've spotted the worst case" rubbish. "Hope" because interrupts and cache misses make the instruction timing in (other) modern processors very variable. The xC+xCORE system has no interrupts, no caches, up to 4000MIPS 32 cores/chip (expandable).

There is a very solid theoretical underpinning to the hardware and software, dating back to the 1980s (hardware, Transputer) and 1970s (software, CSP, Occam).  Buy them at DigiKey. I found them very easy to use, e.g. short manual without errata.

In your system, I hope you can guarantee thread safety, e.g. that printf being called from multiple threads doesn't cause characters to be interleaved in the output stream.

[tggzzz]

P.P.S. Have you tried telling your management that the library doesn't work right?

I fear the customers will report intermittent unreproducible errors.