[RFC] Need for buffered printk() output

[pfalcon]

There were multiple experiences and reports from different people that enabling debug logging affects the behavior of non-trivial (e.g. time-sensitive code). That's because debug logging happens via printk(), which (by default) uses polled UART output. For typical 115200 UART speed, that means 11.5KB/s throughput, and then even for 10 char output, 1ms is spent in polling, and most of logging messages are times longer. Overall, such logging affects real-time code noticeably, usually masking any concurrency and subtle-timing issues.

So, we'd need to implement some kind of buffered output to alleviate this issue. There're 2 approaches to this:

1. Implement interrupt-driven UART for printk, so logging output hopefully takes negligible (for many uses) amount of CPU time.
2. Implement an in-memory buffer for output, with some adhoc support for flushing to the underlying output device (usually still UART), e.g. on buffer becoming full or using an API call a user will need to sprinkle in the code at appropriate places to get the output.

Both approaches has benefits and drawbacks:

1. Requires interrupt-driven UART, which is not supported on all platforms. One big benefit is that the output is still "realtime" (immediately visible to the user). Of course, there's a concern that on buffer overflow it'll stop being so, but that can be handled by configuring buffer size (to an arbitrary value, include tens and hundreds of KBs). This method still has non-zero overhead, so might affect tight realtime code.

2. The output is not visible to the user by default, so it's "collect and stop the world" approach. As such, it'll be much harder to use. At the same time, it's more compatible and allows to achieve absolutely minimal overhead during the "collection" phase.

[pfalcon]

@nashif, @mike-scott, @jukkar, @tbursztyka, @rlubos: Comments are welcome. The main usecase for me is debugging IP stack, where each of us saw enabling logging skew the outcome of the debugging session, up to complete masking of the issues seen otherwise.

[mike-scott]

I hit this issue all the time. I was dealing with this while looking at the scheduler.

Certainly a useful issue to track / work on.

It can be quite complex:

• panic / aborts need to flush the buffer
• buffer overflows in critical portions of the code(?)
• multi-threaded behavior makes the buffered output look odd
• etc.

[nashif]

isn't this the same as #6186 and the logging system/printk overhaul?

[pfalcon]

isn't this the same as #6186 and the logging system/printk overhaul?

Well, this issue is definitely not about "overhaul" or (as #8023 linked from #6186) "major redesign". Those tickets definitely affect this issue, though looking at #8023, I'm not sure if it's ready for prime time.

So, it's mostly to collect opinions from folks to @mike-scott and @jukkar who suffer from this issue daily, to see if they think that even partial/interim solution would be helpful (or maybe they have some hack already ;-) ).

[jukkar]

I am personally waiting #6186 to finish, then we can start to look if there is anything else to do to make debug prints usable.

[nashif]

I'm not sure if it's ready for prime time.

not sure what that means. This is planned for 1.13 and we have this already submitted and being reviewed before even 1.13 has started. Sure there is still lot to do, but the skeleton and framework for adding more backends will be merged soonish.

So, I am not sure what you are suggesting here, do you have another solution to all of this that does not conflict with the efforts being done in #6186?

[pfalcon]

@nashif

not sure what that means. This is planned for 1.13 and we have this already submitted and being reviewed before even 1.13 has started.

I see that #8023 is the only proposed solution for #6186. And even from cursory look I gave to it, I found a bunch of smallish issues which need to be fixed before it can be merged. And that's without talking about higher-level design and architecture questions. (Which I'm sure were discussed already, and concerns with the design were, well, rejected. But that doesn't mean they aren't valid).

So, I am not sure what you are suggesting here, do you have another solution to all of this that does not conflict with the efforts being done in #6186?

Well, this is definitely an RFC. It was a long-time concern that logging affects network debugging, and somehow just now it should be clear that we can't have good progress in debugging non-deterministic issues without improved debug output support. So, this issue is to ask what other people think or maybe even do about it.

"Sit and wait for #6186" is already a good response. I have to admit that I'm not much thrilled by it, because it's either typical "sit and wait" approach (which can go for years), or "go into levels of recursion - when you want to debug X, you need to debug Y, Z, ... etc. first". So, I'm keen to explore possibilities while #6186 is in works (that also has added benefit of better understanding the architecture we have - we have layers, what each of them can do?)