3 ms·

What do other realtime OS kernels do when printing from various places? It almost seems like this should be done in hardware because it's such a difficult probl

What do other realtime OS kernels do when printing from various places? It almost seems like this should be done in hardware because it's such a difficult problem to not lose messages but also have them on a different OS thread in most cases.

EdSchouten 3y ago
Another option is simply to print less, but expose more events in the form of counters. Unfortunately, within a kernel that’s as big as Linux, that would leave you with many, many, many counters. All of which need to be exported and monitored somehow.
- taeric 3y ago
  This seems to imply you would have more counters than messages? Why would that be? That is, I would expect moving to counters to be less information, period. That not the case?
  - nraynaud 3y ago
    My guess is that each counter would need to have a discovery point, a regular update mechanism and a documentation, while you can send obscure messages willy-nilly in the log? And also they become an Application Interface with a life cycle while (hopefully) not too many people will go parse the log as an API.
    - taeric 3y ago
      I think that makes sense, though I would still expect counters to be more dense than logs. I'm definitely interested in any case studies on this.
ajross 3y ago
It's just hard, and there's no single answer. In Zephyr, we have a synchronous printk() too, as for low-level debugging and platform bringup that's usually desirable (i.e. I'd like to see the dump from just before the panic please!). For production logging use, though, there is a fancier log system[1] designed around latency boundaries that essentially logs a minimally processed stream to a buffer than then gets flushed from a low priority thread. And this works, and avoids the kinds of problems detailed in the linked article. But it's fiddly to configure, expensive in an RTOS environment (you need RAM for that thread stack and the buffer), depends on having a I/O backend that is itself async/low-latency, and has the mentioned misfeature where when things blow up, it's usually failed to flush the information you need out of its buffer. [1] Somewhat but not completely orthogonal with printk. Both can be implemented in terms of each others, mostly. Sometimes.
- vlovich123 3y ago
  What if the lower priority thread is starved and the buffer is full? Do you start dropping messages? Or overwrite the oldest ones and skip messages?
  - ajross 3y ago
    It drops messages. That's almost always the desired behavior: you never want your logging system to be doing work when the system is productively tasked with other things. I know there was some level of argument about whether it's best to overwrite older content (ring-buffer-style, probably keeps the most important stuff) or drop messages at input time (faster, probably fewer messages dropped overall). But logging isn't my area of expertise and I forget the details. But again, the general point being that this is a complicated problem with tradeoffs, where most developers up the stack tend to think of it as a fixed facility that shouldn't ever fail or require developer bandwidth. And it's not, it's hard.
Kenji 3y ago
[dead]
xenadu02 3y ago
In many problem spaces you can optimize for the common success and failure paths if you accept certain losses on long-tail failure scenarios. A common logging strategy is to use a ring buffer with a separate isolated process reading from the ring. The vast majority of the time the ring buffer handles temporary disruptions (eg slow disk I/O to write messages to disk) but in the rare failure scenarios you simply overwrite events in the buffer and increment an atomic overwritten event counter. Events do not get silently dropped but you prioritize forward progress at the cost of data loss in rare scenarios. Microkernels and pushing everything to userspace just moves the tradeoffs around. If your driver is in userspace and blocks writing a log message because the log daemon is blocked or the I/O device it is writing the log to is overloaded it does the same thing. Your realtime thread won't get what it needs from the driver within your time limit. It all comes down to CAP theorem stuff. If you always want the kernel (or any other software) to be able to make forward progress within specific time limits then you must be willing to tolerate some data loss in failure scenarios. How much and how often it happens depends on specific design factors, memory usage, etc.

EdSchouten 3y ago

Another option is simply to print less, but expose more events in the form of counters. Unfortunately, within a kernel that’s as big as Linux, that would leave you with many, many, many counters. All of which need to be exported and monitored somehow.

taeric 3y ago
This seems to imply you would have more counters than messages? Why would that be? That is, I would expect moving to counters to be less information, period. That not the case?
- nraynaud 3y ago
  My guess is that each counter would need to have a discovery point, a regular update mechanism and a documentation, while you can send obscure messages willy-nilly in the log? And also they become an Application Interface with a life cycle while (hopefully) not too many people will go parse the log as an API.
  - taeric 3y ago
    I think that makes sense, though I would still expect counters to be more dense than logs. I'm definitely interested in any case studies on this.

ajross 3y ago

It's just hard, and there's no single answer. In Zephyr, we have a synchronous printk() too, as for low-level debugging and platform bringup that's usually desirable (i.e. I'd like to see the dump from just before the panic please!). For production logging use, though, there is a fancier log system[1] designed around latency boundaries that essentially logs a minimally processed stream to a buffer than then gets flushed from a low priority thread. And this works, and avoids the kinds of problems detailed in the linked article. But it's fiddly to configure, expensive in an RTOS environment (you need RAM for that thread stack and the buffer), depends on having a I/O backend that is itself async/low-latency, and has the mentioned misfeature where when things blow up, it's usually failed to flush the information you need out of its buffer. [1] Somewhat but not completely orthogonal with printk. Both can be implemented in terms of each others, mostly. Sometimes.

vlovich123 3y ago
What if the lower priority thread is starved and the buffer is full? Do you start dropping messages? Or overwrite the oldest ones and skip messages?
- ajross 3y ago
  It drops messages. That's almost always the desired behavior: you never want your logging system to be doing work when the system is productively tasked with other things. I know there was some level of argument about whether it's best to overwrite older content (ring-buffer-style, probably keeps the most important stuff) or drop messages at input time (faster, probably fewer messages dropped overall). But logging isn't my area of expertise and I forget the details. But again, the general point being that this is a complicated problem with tradeoffs, where most developers up the stack tend to think of it as a fixed facility that shouldn't ever fail or require developer bandwidth. And it's not, it's hard.

Kenji 3y ago

[dead]

xenadu02 3y ago

In many problem spaces you can optimize for the common success and failure paths if you accept certain losses on long-tail failure scenarios. A common logging strategy is to use a ring buffer with a separate isolated process reading from the ring. The vast majority of the time the ring buffer handles temporary disruptions (eg slow disk I/O to write messages to disk) but in the rare failure scenarios you simply overwrite events in the buffer and increment an atomic overwritten event counter. Events do not get silently dropped but you prioritize forward progress at the cost of data loss in rare scenarios. Microkernels and pushing everything to userspace just moves the tradeoffs around. If your driver is in userspace and blocks writing a log message because the log daemon is blocked or the I/O device it is writing the log to is overloaded it does the same thing. Your realtime thread won't get what it needs from the driver within your time limit. It all comes down to CAP theorem stuff. If you always want the kernel (or any other software) to be able to make forward progress within specific time limits then you must be willing to tolerate some data loss in failure scenarios. How much and how often it happens depends on specific design factors, memory usage, etc.