Delayed "printf"

Sometimes it's necessary to float a notion just so that someone can 
affirm your suspicion that yes, you really are an idiot.

On the off chance that I'm a genius, though, here goes:

I don't like putting "printf" in fast tasks for obvious reasons -- even 
with infinite spooling, it can take time to process a format string.  In 
my usual context, this can result in audible sounds from motors when I 
print some bit of debugging information from a high-priority task.  The 
problem can't be alleviated by spooling the output of the printf, because 
it's the execution time of the printf itself that's the problem.

Just how dumb is it to have "printf" queue up the format string AND the 
parameters into a buffer, to be printed out in some low-priority task?  
For a system with sufficient memory, this seems like an astonishingly 
sensible thing to me.

Clearly you'd have to wrap it up somehow so that if the buffer was full 
no printf at all would happen -- but I'm kinda liking the notion.

So -- whatcha think?

-- 

Tim Wescott
Wescott Design Services
http://www.wescottdesign.com

I'm looking for work -- see my website!

On 4/24/2017 5:42 PM, Tim Wescott wrote:
> Sometimes it's necessary to float a notion just so that someone can
> affirm your suspicion that yes, you really are an idiot.
>
> On the off chance that I'm a genius, though, here goes:
>
> I don't like putting "printf" in fast tasks for obvious reasons -- even
> with infinite spooling, it can take time to process a format string.  In
> my usual context, this can result in audible sounds from motors when I
> print some bit of debugging information from a high-priority task.  The
> problem can't be alleviated by spooling the output of the printf, because
> it's the execution time of the printf itself that's the problem.

... because the printf() is "in series" with some other "time-dependent"
activity.

> Just how dumb is it to have "printf" queue up the format string AND the
> parameters into a buffer, to be printed out in some low-priority task?
> For a system with sufficient memory, this seems like an astonishingly
> sensible thing to me.

Of course, you couldn't rely on any side-effects of the printf()
in code following the point at which you "emit" the data to be
"printed".  Nor can you alter the parameters until you know
(for sure) that they've been captured by the followup process.

I use a crude interface to pass (unformatted) "data" to the "black boxes"
(think: "flight recorder") in my efforts logging -- even in ISRs.
Then, move the "smarts" into the routines that examine the BB contents.

E.g., log(blackbox, timestamp, messageID, ...)

This allows each message type to have its own notions of the parameters
of interest (e.g., message ID #4 might take two doubles and an 8 character
array while message ID #9 takes a long int and a float; each might pretty-up
the presentation of the data with some suitable text).

Doing so lets me keep the size of each blackbox small as it doesn't need to
store the data in a form suitable for human consumption -- in much the same
way that "error 27" tells a user all he needs to know (via a cheat sheet).

Of course, the interface has to be value driven instead of reference
(unless the referenced objects are immutable) as they won't be "resolved"
(dereferenced) until much later in time.

> Clearly you'd have to wrap it up somehow so that if the buffer was full
> no printf at all would happen -- but I'm kinda liking the notion.

Why the restriction?  Do you value previously generated "output" more than
"more recent" output?  (I guess that's conceivable)

> So -- whatcha think?

Tim Wescott <seemywebsite@myfooter.really> writes:
> Just how dumb is it to have "printf" queue up the format string AND the 
> parameters into a buffer, to be printed out in some low-priority task?  

It's fine, just be sure that if there are pointer parameters (like for
%s in the format string) that the objects they point to survive long
enough for the logging task to print them.  

On Mon, 24 Apr 2017 18:51:18 -0700, Don Y wrote:

> On 4/24/2017 5:42 PM, Tim Wescott wrote:
>> Sometimes it's necessary to float a notion just so that someone can
>> affirm your suspicion that yes, you really are an idiot.
>>
>> On the off chance that I'm a genius, though, here goes:
>>
>> I don't like putting "printf" in fast tasks for obvious reasons -- even
>> with infinite spooling, it can take time to process a format string. 
>> In my usual context, this can result in audible sounds from motors when
>> I print some bit of debugging information from a high-priority task. 
>> The problem can't be alleviated by spooling the output of the printf,
>> because it's the execution time of the printf itself that's the
>> problem.
> 
> ... because the printf() is "in series" with some other "time-dependent"
> activity.

That is implied by "fast task", yes.

>> Just how dumb is it to have "printf" queue up the format string AND the
>> parameters into a buffer, to be printed out in some low-priority task?
>> For a system with sufficient memory, this seems like an astonishingly
>> sensible thing to me.
> 
> Of course, you couldn't rely on any side-effects of the printf()
> in code following the point at which you "emit" the data to be
> "printed". 

Good point.  printf returns a value that depends on what's printed, IIRC 
-- you'd want a "printf_later" command, I guess.

> Nor can you alter the parameters until you know (for sure)
> that they've been captured by the followup process.

I was thinking along the lines of capturing them.  Which means parsing 
the string so you can capture values of numbers and contents of strings, 
which probably means it was a dumb idea after all -- dammit.

> I use a crude interface to pass (unformatted) "data" to the "black
> boxes" (think: "flight recorder") in my efforts logging -- even in ISRs.
> Then, move the "smarts" into the routines that examine the BB contents.
> 
> E.g., log(blackbox, timestamp, messageID, ...)
> 
> This allows each message type to have its own notions of the parameters
> of interest (e.g., message ID #4 might take two doubles and an 8
> character array while message ID #9 takes a long int and a float; each
> might pretty-up the presentation of the data with some suitable text).
> 
> Doing so lets me keep the size of each blackbox small as it doesn't need
> to store the data in a form suitable for human consumption -- in much
> the same way that "error 27" tells a user all he needs to know (via a
> cheat sheet).
> 
> Of course, the interface has to be value driven instead of reference
> (unless the referenced objects are immutable) as they won't be
> "resolved" (dereferenced) until much later in time.
> 
>> Clearly you'd have to wrap it up somehow so that if the buffer was full
>> no printf at all would happen -- but I'm kinda liking the notion.
> 
> Why the restriction?  Do you value previously generated "output" more
> than "more recent" output?  (I guess that's conceivable)

If you're pumping stuff into it faster than it can be printed out, 
something has to give, and you'd want it to give as gracefully as 
possible.

-- 
Tim Wescott
Control systems, embedded software and circuit design
I'm looking for work!  See my website if you're interested
http://www.wescottdesign.com

On 25/04/17 10:42, Tim Wescott wrote:
> Sometimes it's necessary to float a notion just so that someone can
> affirm your suspicion that yes, you really are an idiot.
>
> On the off chance that I'm a genius, though, here goes:
>
> I don't like putting "printf" in fast tasks for obvious reasons -- even
> with infinite spooling, it can take time to process a format string.  In
> my usual context, this can result in audible sounds from motors when I
> print some bit of debugging information from a high-priority task.  The
> problem can't be alleviated by spooling the output of the printf, because
> it's the execution time of the printf itself that's the problem.
>
> Just how dumb is it to have "printf" queue up the format string AND the
> parameters into a buffer, to be printed out in some low-priority task?
> For a system with sufficient memory, this seems like an astonishingly
> sensible thing to me.
>
> Clearly you'd have to wrap it up somehow so that if the buffer was full
> no printf at all would happen -- but I'm kinda liking the notion.
>
> So -- whatcha think?

We did this with an error message system in an enterprise system
written mostly in C++. I had produced a type-safe ArgList class,
which allowed you to << any supported data type to append to the
list. Supporting printf-style formats with positional argument
numbers allowed us to fetch the format text translated into
foreign languages. Having an allocated copy of the typed argument
list made printf type-safe, but also meant that we could ship the
format and the arguments across a network interface, to be
rendered using an international format string in the language of
the client's locale.

It was very nice, if rather a lot of work (mostly by me)

Clifford Heath

On 4/24/2017 7:54 PM, Tim Wescott wrote:
> On Mon, 24 Apr 2017 18:51:18 -0700, Don Y wrote:
>
>> On 4/24/2017 5:42 PM, Tim Wescott wrote:
>>> Sometimes it's necessary to float a notion just so that someone can
>>> affirm your suspicion that yes, you really are an idiot.
>>>
>>> On the off chance that I'm a genius, though, here goes:
>>>
>>> I don't like putting "printf" in fast tasks for obvious reasons -- even
>>> with infinite spooling, it can take time to process a format string.
>>> In my usual context, this can result in audible sounds from motors when
>>> I print some bit of debugging information from a high-priority task.
>>> The problem can't be alleviated by spooling the output of the printf,
>>> because it's the execution time of the printf itself that's the
>>> problem.
>>
>> ... because the printf() is "in series" with some other "time-dependent"
>> activity.
>
> That is implied by "fast task", yes.

I was trying to draw attention to the fact that you *could* have had
printf() working "in parallel" with the task.

>>> Just how dumb is it to have "printf" queue up the format string AND the
>>> parameters into a buffer, to be printed out in some low-priority task?
>>> For a system with sufficient memory, this seems like an astonishingly
>>> sensible thing to me.
>>
>> Of course, you couldn't rely on any side-effects of the printf()
>> in code following the point at which you "emit" the data to be
>> "printed".
>
> Good point.  printf returns a value that depends on what's printed, IIRC
> -- you'd want a "printf_later" command, I guess.

Typically, one ignores the return value of printf().

But, you can use things like "%n" (with an associated int*) to get
other "output" from a format string (folks tend to not use this much,
either).

You just need to be aware of this when you finally "evaluate"
the function.

>> Nor can you alter the parameters until you know (for sure)
>> that they've been captured by the followup process.
>
> I was thinking along the lines of capturing them.  Which means parsing
> the string so you can capture values of numbers and contents of strings,
> which probably means it was a dumb idea after all -- dammit.

No, just capture them in a lower-level form.  E.g., my blackbox
mechanism just captures sets of bytes.  The "post processor"
figures out what they are intended to mean.

Its like marshalling arguments for an IPC -- and imposing the
"typing" later.

The drawback to my scheme is that it has limited flexibility
and is less "intuitive" than printf() stubs.  E.g., I can't
arbitrarily decide that I want to preserve A, B and C -- without
knowing their sizes, etc.

But, chances are, you have some (small) fixed number of printf() format
strings; your code isn't *synthesizing* arbitrary strings!  So, you
nail those down, give each a "message ID" and a corresponding decoder
"later".

>> I use a crude interface to pass (unformatted) "data" to the "black
>> boxes" (think: "flight recorder") in my efforts logging -- even in ISRs.
>> Then, move the "smarts" into the routines that examine the BB contents.
>>
>> E.g., log(blackbox, timestamp, messageID, ...)
>>
>> This allows each message type to have its own notions of the parameters
>> of interest (e.g., message ID #4 might take two doubles and an 8
>> character array while message ID #9 takes a long int and a float; each
>> might pretty-up the presentation of the data with some suitable text).
>>
>> Doing so lets me keep the size of each blackbox small as it doesn't need
>> to store the data in a form suitable for human consumption -- in much
>> the same way that "error 27" tells a user all he needs to know (via a
>> cheat sheet).
>>
>> Of course, the interface has to be value driven instead of reference
>> (unless the referenced objects are immutable) as they won't be
>> "resolved" (dereferenced) until much later in time.
>>
>>> Clearly you'd have to wrap it up somehow so that if the buffer was full
>>> no printf at all would happen -- but I'm kinda liking the notion.
>>
>> Why the restriction?  Do you value previously generated "output" more
>> than "more recent" output?  (I guess that's conceivable)
>
> If you're pumping stuff into it faster than it can be printed out,
> something has to give, and you'd want it to give as gracefully as
> possible.

Of course!  In my case, I'm interested in the most recent history;
I want a continuous record from "now" backwards in time -- to whatever
extent the blackboxes size will accommodate.  Of course, if I have
emitted a lot of LONG messages (in terms of their raw forms, not
their "post processed" forms), then I have fewer complete messages
available.  But, there are no gaps within them.

If you allow *some* printf_later()'s to produce NO output, then you
risk having holes in your "printf stream".

(that may be acceptable to you)

On Mon, 24 Apr 2017 19:42:30 -0500, Tim Wescott
<seemywebsite@myfooter.really> wrote:

>Sometimes it's necessary to float a notion just so that someone can 
>affirm your suspicion that yes, you really are an idiot.
>
>On the off chance that I'm a genius, though, here goes:
>
>I don't like putting "printf" in fast tasks for obvious reasons -- even 
>with infinite spooling, it can take time to process a format string.  In 
>my usual context, this can result in audible sounds from motors when I 
>print some bit of debugging information from a high-priority task.  The 
>problem can't be alleviated by spooling the output of the printf, because 
>it's the execution time of the printf itself that's the problem.
>
>Just how dumb is it to have "printf" queue up the format string AND the 
>parameters into a buffer, to be printed out in some low-priority task?  
>For a system with sufficient memory, this seems like an astonishingly 
>sensible thing to me.
>
>Clearly you'd have to wrap it up somehow so that if the buffer was full 
>no printf at all would happen -- but I'm kinda liking the notion.
>
>So -- whatcha think?


A problem is that finding all the input parameters, and copying them
someplace, may well be a considerable amount of work.  *Output*
parameters (%n, the return value), have already been mentioned, and
pose significant additional problems.

While copying something like an integer or float is going to be fairly
quick (assuming you have some place to put them already allocated),
and likely rather faster than than actually formatting them, you're
still going to have to do a non-trivial amount of parsing to actually
*find* those parameters.  And remember you have not just the
parameters, but the precision and min size can be specified as a
parameter ("*").  With strings, you have a worse allocation problem,
and copying the strings to a temporary area is going to be as much
work as actually processing them.

So at best, you're likely to only save a modest amount of CPU time in
the issuing thread formatting the output string, and quite possibly
that CPU usage in the main thread may be a non-trivial amount worse.
Overall CPU usage will certainly be worsened considerably.

OTOH, your real goal is to prevent the printf from blocking because it
lacks output space.

A simple way to do that is to perform an snprintf to a pre-allocated,
and fairly fixed size, buffer, and then pass *that* buffer to a
separate thread for output.  A better option may be to issue an
asynchronous I/O request (although you'll have to step outside of C
streams at that point).  If the available buffer is too small, you
have the choice of ignoring the output, or truncating it, and you have
several options for dealing with a new output request from the main
thread that happenes before the old buffer is disposed of (ignore,
block, have multiple available output buffers).

An advantage of doing the snprintf in the main thread, is that you
largely leave the semantics of printf unchanged.

You can sometimes also check (OS dependent) if there is space in the
stream output buffer (__fbufsize and __fpending in *nix, for example),
and use that to judge whether you're going to have room for the output
(you could do a trial with snprintf and a zero length buffer to get
the length required, for example).  You then need to compensate for
things like expansion of newlines (OS dependent, of course, not an
issue in *nix*).

Il giorno martedì 25 aprile 2017 02:42:38 UTC+2, Tim Wescott ha scritto:

> Clearly you'd have to wrap it up somehow so that if the buffer was full 
> no printf at all would happen -- but I'm kinda liking the notion.
> 
> So -- whatcha think?

Freescale has a tool, called Freemaster, that allow to read/write directly the RAM of a uC (it also read the elf file, so you have the name of the variables, and not only the addresses).
It's really handy and trasparent to the processor (if it can connect using the programming interface: JTAG or whatever, else a small UART driver is needed).
Even on other processor it's usually very easy to write a small communication protocol to r/w RAM, and a GUI with python is done in half a day.
Much better than printf.

Bye Jack

On 25/04/17 01:42, Tim Wescott wrote:
> Sometimes it's necessary to float a notion just so that someone can
> affirm your suspicion that yes, you really are an idiot.
>
> On the off chance that I'm a genius, though, here goes:
>
> I don't like putting "printf" in fast tasks for obvious reasons -- even
> with infinite spooling, it can take time to process a format string.  In
> my usual context, this can result in audible sounds from motors when I
> print some bit of debugging information from a high-priority task.  The
> problem can't be alleviated by spooling the output of the printf, because
> it's the execution time of the printf itself that's the problem.
>
> Just how dumb is it to have "printf" queue up the format string AND the
> parameters into a buffer, to be printed out in some low-priority task?
> For a system with sufficient memory, this seems like an astonishingly
> sensible thing to me.
>
> Clearly you'd have to wrap it up somehow so that if the buffer was full
> no printf at all would happen -- but I'm kinda liking the notion.
>
> So -- whatcha think?


Where execution time/latency is important, I have used
combinations of these techniques as appropriate:
- rapid determination that printing isn't necessary (e.g.
   conditional logging of non-fatal conditions)

- pass parameter by value, not reference/pointer, so it
   remains unchanged

- output parameters directly, to be parsed/prettyprinted
   by a logging process on a different machine (e.g. FSM
   state/event encoded as a byte, not a string)

- message boxes or FIFOs between the data source and data
   consumer threads, depending on relative thread speeds,
   data rates, and whether the data source needs to ensure
   message delivery

- async callbacks to the data source, indicating completion
   (whatever that means) of logging

Tim Wescott <seemywebsite@myfooter.really> writes:

> Sometimes it's necessary to float a notion just so that someone can 
> affirm your suspicion that yes, you really are an idiot.
>
> On the off chance that I'm a genius, though, here goes:
>
> I don't like putting "printf" in fast tasks for obvious reasons -- even 
> with infinite spooling, it can take time to process a format string.  In 
> my usual context, this can result in audible sounds from motors when I 
> print some bit of debugging information from a high-priority task.  The 
> problem can't be alleviated by spooling the output of the printf, because 
> it's the execution time of the printf itself that's the problem.
>
> Just how dumb is it to have "printf" queue up the format string AND the 
> parameters into a buffer, to be printed out in some low-priority task?  
> For a system with sufficient memory, this seems like an astonishingly 
> sensible thing to me.
>
> Clearly you'd have to wrap it up somehow so that if the buffer was full 
> no printf at all would happen -- but I'm kinda liking the notion.
>
> So -- whatcha think?

I think it's a good idea... the format string would normally be in flash
so it would only be a pointer in the buffer AFAICT.

Not quite what you asked, but relevant - an interesting video from
mikeselectricstuff about using a scopes serial decode for non-intrusive
real time debugging / high speed debug messaging.

<https://www.youtube.com/watch?v=EdfHzpEKtZQ>



-- 

John Devereux