[printk,v2,7/7] printk: Handle dropped message smarter

  From: Thomas Gleixner <tglx@linutronix.de>

If a 'dropped message' is to be printed, move the record text to be
directly appended to the 'dropped message' and let console->write()
output it in one go.

Signed-off-by: Thomas Gleixner <tglx@linutronix.de>
Signed-off-by: John Ogness <john.ogness@linutronix.de>
---
 kernel/printk/printk.c | 125 +++++++++++++++++++++++++++--------------
 1 file changed, 82 insertions(+), 43 deletions(-)
  

On Thu 2022-11-24 00:20:00, John Ogness wrote:
> From: Thomas Gleixner <tglx@linutronix.de>
> 
> If a 'dropped message' is to be printed, move the record text to be
> directly appended to the 'dropped message' and let console->write()
> output it in one go.
>
> --- a/kernel/printk/printk.c
> +++ b/kernel/printk/printk.c
> @@ -2741,6 +2712,60 @@ static void __console_unlock(void)
>  	up_console_sem();
>  }
>  
> +/*
> + * A maximum dropped message together with a maximum regular message
> + * must be able to fit within console_buffers->ext_text.
> + */
> +#if DROPPED_TEXT_MAX > (CONSOLE_EXT_LOG_MAX - CONSOLE_LOG_MAX)
> +#error "DROPPED_TEXT_MAX too large for console_buffers->ext_text"
> +#endif
> +
> +/**
> + * msg_print_dropped - Prepend a "dropped message" if required
> + * @desc:	Pointer to the output descriptor
> + * @dropped:	The number of dropped messages to report
> + *
> + * Inserts the "dropped message" into the output buffer if @dropped is
> + * not 0 and the regular format is requested. Extended format does not
> + * need this message because it prints the sequence numbers.
> + *
> + * In regular format, the extended message buffer is not in use. So
> + * string-print the dropped message there and move the record text to be
> + * appended to the dropped message. The extended message buffer is much
> + * larger and can accommodate both messages.
> + *
> + * In case a dropped message is needed, this returns with @desc->outbuf
> + * and @desc->len updated. The caller is responsible for tracking and
> + * resetting the dropped count. If no dropped message is required then
> + * @desc is not modified.
> + */
> +static void msg_print_dropped(struct console_message *cmsg, unsigned long dropped)
> +{
> +	struct console_buffers *cbufs = cmsg->cbufs;
> +	char *ext_text = &cbufs->ext_text[0];
> +	size_t len;
> +
> +	if (!dropped || cmsg->is_extmsg)
> +		return;
> +
> +	if (WARN_ON_ONCE(cmsg->outbuf != &cbufs->text[0]))
> +		return;
> +
> +	/* Print it into ext_text, which is unused. */
> +	len = snprintf(ext_text, DROPPED_TEXT_MAX,
> +		       "** %lu printk messages dropped **\n", dropped);
> +

I would feel better if we check here that the text fits into the rest
of the buffer.

	if (WARN_ON_ONCE(len + cmsg->outbuf_len < sizeof(cbufs->ext_text)))
		return;

I know that it is kind-of guaranteed by the above compilation check
of the *_MAX values. But there might be a bug and cmsg->outbuf_len
might contains a garbage.


> +	/*
> +	 * Append the record text to the dropped message so that it
> +	 * goes out with one write.
> +	 */
> +	memcpy(ext_text + len, &cbufs->text[0], cmsg->outbuf_len);
> +
> +	/* Update the output buffer descriptor. */
> +	cmsg->outbuf = ext_text;
> +	cmsg->outbuf_len += len;

I still think that it would be better to rename the buffers in
struct console_message and avoid the switches of the purpose
of the two buffers.

We could print the message about dropped text into a local buffer
on stack. IMHO, 64 bytes are acceptable. And we could insert it
into the outbuf by shuffling the existing text. Something like:

static void msg_print_dropped(struct console_message *cmsg,
			      unsinged long dropped)
{
	char dropped_msg[DROPPED_TEXT_MAX];
	int dropped_len;

	if (!con->dropped)
		return 0;

	/* Print it into ext_text, which is unused. */
	dropped_len = snprintf(dropped_msg, sizeof(dropped_msg),
		       "** %lu printk messages dropped **\n", con->dropped);

	/*
	 * The buffer might already be full only where the message consist
	 * of many very short lines. It is not much realistic.
	 */
	if (cmsg->outbuf_len + dropped_len + 1 > sizeof(cmsg->outbuf)) {
		/* Should never happen. */
		if (WARN_ON_ONCE(dropped_len + 1 > sizeof(cmsg->outbuf)))
			return;

		/* Trunk the message like in record_print_text() */
		cmsg->outbuf_len = sizeof(cmsg->outbuf) - dropped_len;
		cmsg->outbuf[cmsg->outbuf_len] = '\0';
	}

	memmove(cmsg->outbuf + dropped_len, cmsg->outbuf, cmsg->outbuf_len + 1);
	memcpy(cmsg->outbuf, dropped_msg, dropped_len);
}

The handling of the full buffer is a bit ugly. I though about other
alternatives. For example, returning -ENOMEM, so that the caller
could print the line later. Or just using WARN_ON_ONCE() and return.

Any solution has its pros and cons. But is a corner case. It need
not be perfect. I solved it the same way as we already do in
record_print_text().

Otherwise, the move of the code makes sense.

Best Regards,
Petr
  

On 2022-12-07, Petr Mladek <pmladek@suse.com> wrote:
>> +	/* Print it into ext_text, which is unused. */
>> +	len = snprintf(ext_text, DROPPED_TEXT_MAX,
>> +		       "** %lu printk messages dropped **\n", dropped);
>> +
>
> I would feel better if we check here that the text fits into the rest
> of the buffer.
>
> 	if (WARN_ON_ONCE(len + cmsg->outbuf_len < sizeof(cbufs->ext_text)))
> 		return;
>
> I know that it is kind-of guaranteed by the above compilation check
> of the *_MAX values. But there might be a bug and cmsg->outbuf_len
> might contains a garbage.

OK.

>> +	/*
>> +	 * Append the record text to the dropped message so that it
>> +	 * goes out with one write.
>> +	 */
>> +	memcpy(ext_text + len, &cbufs->text[0], cmsg->outbuf_len);
>> +
>> +	/* Update the output buffer descriptor. */
>> +	cmsg->outbuf = ext_text;
>> +	cmsg->outbuf_len += len;
>
> I still think that it would be better to rename the buffers in
> struct console_message and avoid the switches of the purpose
> of the two buffers.
>
> We could print the message about dropped text into a local buffer
> on stack. IMHO, 64 bytes are acceptable. And we could insert it
> into the outbuf by shuffling the existing text. Something like:
>
> static void msg_print_dropped(struct console_message *cmsg,
> 			      unsinged long dropped)
> {
> 	char dropped_msg[DROPPED_TEXT_MAX];
> 	int dropped_len;
>
> 	if (!con->dropped)
> 		return 0;
>
> 	/* Print it into ext_text, which is unused. */
> 	dropped_len = snprintf(dropped_msg, sizeof(dropped_msg),
> 		       "** %lu printk messages dropped **\n", con->dropped);
>
> 	/*
> 	 * The buffer might already be full only where the message consist
> 	 * of many very short lines. It is not much realistic.
> 	 */
> 	if (cmsg->outbuf_len + dropped_len + 1 > sizeof(cmsg->outbuf)) {
> 		/* Should never happen. */

This certainly can happen. @text is size CONSOLE_LOG_MAX, which is
LOG_LINE_MAX+PREFIX_MAX. So a totally legal formatted message of length
LOG_LINE_MAX-1 and a prefix will suddenly become truncated.

> 		if (WARN_ON_ONCE(dropped_len + 1 > sizeof(cmsg->outbuf)))
> 			return;
>
> 		/* Trunk the message like in record_print_text() */
> 		cmsg->outbuf_len = sizeof(cmsg->outbuf) - dropped_len;
> 		cmsg->outbuf[cmsg->outbuf_len] = '\0';
> 	}
>
> 	memmove(cmsg->outbuf + dropped_len, cmsg->outbuf, cmsg->outbuf_len + 1);
> 	memcpy(cmsg->outbuf, dropped_msg, dropped_len);
> }

I do not like the idea of increasing stack usage, possibly cutting off
messages, and performing extra memory operations all because of some
variable naming. There is literally a larger unused buffer just sitting
there.

I want struct console_buffers to be a black box of working buffers used
to process the different types of messages. console_get_next_message()
is the only function that should go inside that black box because it is
responsible for creating the actual message.

The caller does not care what is in the black box or how those internal
working buffers are named. The caller just cares about cmsg->outbuf and
cmsg->outbuf_len, which will point to the data that needs to be written
out.

For v3 I would like to try my approach one more time. I will give the
internal buffers new names so as not to mislead their roles. I will
clearly document the black box nature of struct console_buffers.

John Ogness
  

On Wed 2022-12-07 18:04:56, John Ogness wrote:
> On 2022-12-07, Petr Mladek <pmladek@suse.com> wrote:
> >> +	/*
> >> +	 * Append the record text to the dropped message so that it
> >> +	 * goes out with one write.
> >> +	 */
> >> +	memcpy(ext_text + len, &cbufs->text[0], cmsg->outbuf_len);
> >> +
> >> +	/* Update the output buffer descriptor. */
> >> +	cmsg->outbuf = ext_text;
> >> +	cmsg->outbuf_len += len;
> >
> > I still think that it would be better to rename the buffers in
> > struct console_message and avoid the switches of the purpose
> > of the two buffers.
> >
> > We could print the message about dropped text into a local buffer
> > on stack. IMHO, 64 bytes are acceptable. And we could insert it
> > into the outbuf by shuffling the existing text. Something like:
> >
> > static void msg_print_dropped(struct console_message *cmsg,
> > 			      unsinged long dropped)
> > {
> > 	char dropped_msg[DROPPED_TEXT_MAX];
> > 	int dropped_len;
> >
> > 	if (!con->dropped)
> > 		return 0;
> >
> > 	/* Print it into ext_text, which is unused. */
> > 	dropped_len = snprintf(dropped_msg, sizeof(dropped_msg),
> > 		       "** %lu printk messages dropped **\n", con->dropped);
> >
> > 	/*
> > 	 * The buffer might already be full only where the message consist
> > 	 * of many very short lines. It is not much realistic.
> > 	 */
> > 	if (cmsg->outbuf_len + dropped_len + 1 > sizeof(cmsg->outbuf)) {
> > 		/* Should never happen. */
> 
> This certainly can happen. @text is size CONSOLE_LOG_MAX, which is
> LOG_LINE_MAX+PREFIX_MAX. So a totally legal formatted message of length
> LOG_LINE_MAX-1 and a prefix will suddenly become truncated.
> 
> > 		if (WARN_ON_ONCE(dropped_len + 1 > sizeof(cmsg->outbuf)))
> > 			return;
> >
> > 		/* Trunk the message like in record_print_text() */
> > 		cmsg->outbuf_len = sizeof(cmsg->outbuf) - dropped_len;
> > 		cmsg->outbuf[cmsg->outbuf_len] = '\0';
> > 	}
> >
> > 	memmove(cmsg->outbuf + dropped_len, cmsg->outbuf, cmsg->outbuf_len + 1);
> > 	memcpy(cmsg->outbuf, dropped_msg, dropped_len);
> > }
> 
> I do not like the idea of increasing stack usage, possibly cutting off
> messages, and performing extra memory operations all because of some
> variable naming. There is literally a larger unused buffer just sitting
> there.

Sigh. Your approach is copying buffers:

    DROPPED_LOG_MAX + CONSOLE_LOG_MAX -> CONSOLE_EXT_LOG_MAX

which means:

    64 + 1024 -> 8182

The important thing is that it will shrink the text in
record_print_text() to 1024.

With my approach, it would shrink the text here to 8182 - 64 = 8118.

> I want struct console_buffers to be a black box of working buffers used
> to process the different types of messages. console_get_next_message()
> is the only function that should go inside that black box because it is
> responsible for creating the actual message.
> 
> The caller does not care what is in the black box or how those internal
> working buffers are named. The caller just cares about cmsg->outbuf and
> cmsg->outbuf_len, which will point to the data that needs to be written
> out.
> 
> For v3 I would like to try my approach one more time. I will give the
> internal buffers new names so as not to mislead their roles. I will
> clearly document the black box nature of struct console_buffers.

This is probably my last mail on this matter[*]. I do not want to get
stuck here. But I really do not see any advantage in your approach:

    + The risk of shrinking the text is bigger.

    + The buffer is accessed via one more dereference that might
      eventually point to a wrong buffer if there is a bug.

    + The size of the buffer is not clear via the dereference
      and might be wrong if there is a bug.

    + The more layers, the more code complexity, like more names.


The only argument might be the 64B on stack. But it is nothing against
namebuf[KSYM_NAME_LEN] that is used in kallsyms code that might be
called via vsprintf.c. It is 512B on the stack. So I do not take it.

Another argument might be if you wanted to use the buffers yet another
way in the atomic consoles. But I guess (hope) that they will always
work only with the "outbuf".

[*] I think that I'll learn how to live with whatever you use in v3 :-)

Best Regards,
Petr