lib: cbprintf: add support for deferred formatting

[pabigot]

In applications like logging the call site where arguments to formatting are available may not be suitable for performing the formatting, e.g. when the output operation can sleep. Add API that supports capturing transient formatting data into a buffer.
Also API that produces the output later using the packaged data.

These changes increase stack requirements on the vprintk path from 152 bytes to 208 bytes on ARM, in part because code that could formerly be inlined must now be a separate function as it can be invoked from multiple locations. Other architectures have different magnitude changes, particularly SPARC which incurs a 96 byte cost for every nested call.

Storing the data could be changed fairly easily to use a ring buffer if that's preferred.

Relates to #30353 (comment).

[nordic-krch]

@pabigot thanks for posting this, looks very good. I think that it could be extended with 2 macros:

• macro for deciding if static package generation is possible. It will basically check if there are any char * arguments. Additionally, it should have skip argument which will indicate how many char * are still OK. This will be applied in cases when log message contains known, fixed strings like function name. CBPRINTF_CAN_STATIC_PACK(skip, ...)
• macro for statically building a package CBPRINTF_STATIC_PACK(buf, len, ...). Same as in function version, if buf is null only length is calculated.

I can look into static packing as i think that it will give significant performance boost. Currently it takes 22us to pack "test %d %d" on nrf52, expecting to be almost instant with static packing.

[pabigot]

I don't understand how static package generation could work since you have to know what the formatting is going to do to determine what value gets packed.

Also the format specifier itself is a const char* which could point to a user-provided format string, so checking for format arguments that are strings doesn't cover all potential legal uses.

But go ahead and put together what you have in mind so it's more clear.

[nordic-krch]

@pabigot please take a look at https://github.com/nordic-krch/zephyr/commits/nordic/20201211b
I've added macro: nordic-krch@d32f351
and modified the test to validate configuration with static packaging: nordic-krch@932f8a2
with minor modifications to cbprintf_complete.c test is passing for all configurations.

[pabigot]

Thanks. I've fixed the swapped ldbl/dbl packing in this PR.

I've also adopted your fix for wint_t, which was indeed incorrectly handled, but modified it slightly to do the right thing for pull_va_args() and to treat wint_t as signed (because char is documented and treated as signed in the current implementation; for char it doesn't matter, and I can't convince myself it matters for wchar_t either).

Two requests for when you move to a PR for the log infrastructure:

• Add test cases for packing float arguments. These are unnecessary currently because all arguments go through standard argument promotions, but since the _Generic() approach can tell the difference between 1.2F and 1.2 it needs to be tested.
• Related, when static packing can be performed please add a test that cbprintf_package() actually does produce exactly the same buffer, since that's the documented behavior. It would be nice if this was automatically done when USE_PACKAGED is selected rather than adding a whole new test axis (i.e. just check whether static packaging would work, and if so verify the cbprintf_package() results against it with memcmp).

[pabigot]

Updated with some fixes from #31102 and rebased after #30665 merged.

[pabigot]

Rebased on #31133; handling wchar_t cross-platform was nastier than I'd thought.

[npitre]

I'm looking at this PR and something makes me feel uneasy. Let me explain.

I don't dispute the need for deferred printouts, either for log gathering or
because the context where the print is generated doesn't accommodate actual
output. But to my unacquainted view this seems to be the wrong approach.

Firstly is code complexity. This is using non negligible code footprint and
additional stack usage. And I'm not even talking about understanding and
maintaining the code itself.

Secondly I think the cbprintf_package() is doing too much parsing and
validation. If this is meant to be used where sleeping can't happen this
usually means IRQ context. Therefore it better do as little processing as
possible, and leave the actual parsing and validation to the consumer side.

Lastly this makes coupling between the log facility and the print facility
a bit too intimate. The fact that nano can't simply be substituted to complete
feels wrong in that regard.

Now here's what I think could be done. I might be completely in the weeds
about this and if so please tell me.

Each pieces should be optimized to do only one thing and do it well.
The printing facility should be left at that and only that. It shouldn't
get involved in the logging business.

The logging facility should do just that: gathering data, store it
efficiently and restore the original data for later consumption.

Coupling between those two should be as small as possible so any of those parts
can be exchanged for another (e.g. nano vs complete).

So what the logging facility should gather is actually the format string
(or possibly a pointer to it if it lives in ROM) and the entire va_list
content. So yeah, some parsing of the format string is necessary, but
not that much. A much simpler state machine is needed to find out how much
of the va_list needs to be copied over and stuffed in the log record,
likely smaller than the code footprint of what is proposed now. This has to
be quick and simple. There is only one case where this might be suboptimal
i.e. "%.*s" where the actual string length is limited, but that should be
quite rare for such strings to be in non ROM, and is probably be worth the
compromize of storing the entire string in the log otherwise.

On the log consumption side then we only need to reconstruct the va_list
context and call whatever regular printf variant we want with no compromize
on efficiency this time.

Am I missing something obvious?

[pabigot]

I'm looking at this PR and something makes me feel uneasy.

The whole thing makes me uneasy.

So yeah, some parsing of the format string is necessary, but
not that much. A much simpler state machine is needed to find out how much
of the va_list needs to be copied over and stuffed in the log record,
likely smaller than the code footprint of what is proposed now.

I'm not sure that's true, but I'm happy to withdraw this and have somebody else come up with an alternative.

[npitre]

On Wed, 23 Feb 2021, Peter A. Bigot wrote: I'm not sure that's true, but I'm happy to withdraw this and have somebody else come up with an alternative.

I'll try to prototype something to validate the idea.

[nordic-krch]

@npitre please not that this PR is followed by #31102 which introduces "static" packaging (with the one here would be called "runtime"). Static packaging is attempting to form a package at compile time as simple assignments to an array. It is utilizing _Generic C11 keyword to handle promotions (e.g. store float as double). Additionally, static packaging extension adds macro for detecting at compile time if it can be applied. Basically, runtime packaging is required if there is a possibility that there is a string argument that needs to be stored by value in the package. Detection searches for any char pointers then but does not inspect format specifiers in the string so there might be some false positive like "%p", (char *)p". I consider a runtime method as a fallback to be used whenever static packaging cannot be used (presence of string arguments or lack of support for C11 compiler, see #30105).

Before @pabigot proposed that i was experimenting with just dumping va_list since it is on the stack but there are two main issues there:

• platform dependency, in case of 86_64 it is not even continues array on the stack
• storing string arguments by value cannot be done. It is very important from deferred logging perspective to have string arguments in self-contained package

[pabigot]

Also when pursuing alternative solutions keep in mind #32373 which identifies that va_arg must be used in some cases to pull off floating point values as floating point values, not arbitrary blobs of memory.

[npitre]

On Wed, 24 Feb 2021, Krzysztof Chruscinski wrote: Before @pabigot proposed that i was experimenting with just dumping va_list since it is on the stack but there are two main issues there: - platform dependency, in case of 86_64 it is not even continues array on the stack

Yeah... same thing on Aarch64. That's a real abomination! However there is a way around it. You could do: ``` aarch64_va_list_packer(int a, int b, int c, int d, int e, int f, int g, char *fmt, ...) { va_list ap; va_start(ap, fmt); void content = ap.__stack; ... } #define va_list_packer(fmt, ...) \ aarch64_va_list_packer(0, 0, 0, 0, 0, 0, 0, fmt, __VA_ARGS__) } ``` This way all arguments are overflowed to the stack. I'm sure a similar trick can be used on x86-64.

- storing string arguments by value cannot be done. It is very important from deferred logging perspective to have string arguments in self-contained package

The trick of only storing pointers to strings when they live in read-only memory is a nice one. Otherwise you may still append those strings to the va_list blob, and prefix them with an offset value indicating where the pointer to those string is located in the va_list blob. This way, when unpacking you just have to stuff the new string location at the indicated va_list position and the va_list consumer won't care. And if you want to compact things further, you could even remove string pointers from the va_list buffer since you would already have the information about where to re-insert them (although this would need a some memmove() cycles). Is this worth it? The code for this would be rather simple. Something along those lines: ``` int length = 0; signed char mode = -1; while (*++fmt) { if (mode < 0) { if (*fmt == '%') { mode = 0; } continue; } else { switch (*fmt) { case '%': mode = -1; continue; case 'd': case 'u': case 'x': case 'c': mode = -1; case '*': length += sizeof(int); continue; case 'f': case 'g': length = ROUND_UP(__alignof(double)); length += sizeof(double); break; case 'l': if (fmt[1] == 'l') { ALIGN_SIZE(length, long long); fmt++; } else { ALIGN_SIZE(length, long); } break; case 's': char *s = va_list.__stack + length; queue_string(s); ... break; } mode = -1; } } memcpy(buffer, va_list.__stack, length); length += append_queued_strings(buffer + length); return length; ``` What do you think?

[npitre]

OK! As always this wasn't as simple as anticipated, but I think I managed something that isn't too bad. Please see PR #32734 for an alternative to this one.

[pabigot]

Superseded by #32734