Re: [PATCH] printk: avoid prb_first_valid_seq() where possible

Petr Mladek
2021-02-09T18:45:41Z

On Fri 2021-02-05 15:23:28, John Ogness wrote:
> If message sizes average larger than expected (more than 32
> characters), the data_ring will wrap before the desc_ring. Once the
> data_ring wraps, it will start invalidating descriptors. These
> invalid descriptors hang around until they are eventually recycled
> when the desc_ring wraps. Readers do not care about invalid
> descriptors, but they still need to iterate past them. If the
> average message size is much larger than 32 characters, then there
> will be many invalid descriptors preceding the valid descriptors.
>
> The function prb_first_valid_seq() always begins at the oldest
> descriptor and searches for the first valid descriptor. This can
> be rather expensive for the above scenario. And, in fact, because
> of its heavy usage in /dev/kmsg, there have been reports of long
> delays and even RCU stalls.
>
> For code that does not need to search from the oldest record,
> replace prb_first_valid_seq() usage with prb_read_valid_*()
> functions, which provide a start sequence number to search from.
>
> Fixes: 896fbe20b4e2333fb55 ("printk: use the lockless ringbuffer")
> Reported-by: kernel test robot <oliver.sang@intel.com>
> Reported-by: J. Avila <elavila@google.com>
> Signed-off-by: John Ogness <john.ogness@linutronix.de>
> ---
> patch against next-20210205
>
> kernel/printk/printk.c | 29 ++++++++++++++++++-----------
> 1 file changed, 18 insertions(+), 11 deletions(-)
>
> diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
> index 5a95c688621f..035aae771ea1 100644
> --- a/kernel/printk/printk.c
> +++ b/kernel/printk/printk.c
> @@ -1559,6 +1560,7 @@ static void syslog_clear(void)
>
> int do_syslog(int type, char __user *buf, int len, int source)
> {
> + struct printk_info info;
> bool clear = false;
> static int saved_console_loglevel = LOGLEVEL_DEFAULT;
> int error;
> @@ -1629,9 +1631,13 @@ int do_syslog(int type, char __user *buf, int len, int source)
> /* Number of chars in the log buffer */
> case SYSLOG_ACTION_SIZE_UNREAD:
> logbuf_lock_irq();
> - if (syslog_seq < prb_first_valid_seq(prb)) {
> - /* messages are gone, move to first one */
> - syslog_seq = prb_first_valid_seq(prb);
> + if (prb_read_valid_info(prb, syslog_seq, &info, NULL)) {
> + if (info.seq != syslog_seq) {
> + /* messages are gone, move to first one */
> + syslog_seq = info.seq;
> + syslog_partial = 0;
> + }
> + } else {
> syslog_partial = 0;

I am scratching my head when prb_read_valid_info(prb,
syslog_seq, &info, NULL)) might fail.

It might fail when syslog_seq points to the next message
after the last valid one. In this case, we could return
immediately (after releasing the lock) because there are
zero unread messages.

Anyway, syslog_partial must be zero in this case. syslog_seq
should stay when the last read was partial. And there should
always be at least one valid message in the log buffer
be design.

Do I get it correctly, please?

IMHO, it would deserve a comment and maybe even a warning.
What about something like?

/* Number of chars in the log buffer */
case SYSLOG_ACTION_SIZE_UNREAD:
logbuf_lock_irq();
if (!prb_read_valid_info(prb, syslog_seq, &info, NULL)) {
/* No unread message */
if (syslog_partial) {
/* This should never happen. */
pr_err_once("Unable to read any message even when the last syslog read was partial: %zu", syslog_partial);
syslog_partial = 0;
}
logbuf_unlock_irq();
return 0;
}
if (info.seq != syslog_seq) {
/* messages are gone, move to first one */
syslog_seq = info.seq;
syslog_partial = 0;
}
if (source == SYSLOG_FROM_PROC) {
/*
* Short-cut for poll(/"proc/kmsg") which simply checks
[...]

Best Regards,
Petr