[PATCH] printk: introduce should_ignore_loglevel()

[PATCH] printk: introduce should_ignore_loglevel()

[Sergey Senozhatsky]

Due to deferred printing, console log level is inspected when the actual
printing occurs, which may provoke console_unlock() and console_cont_flush()
to waste CPU cycles on every message that has loglevel above the current
console_loglevel.

Schematically, console_unlock() does the following:

console_unlock()
{
	...
	for (;;) {
		...
		raw_spin_lock_irqsave(&logbuf_lock, flags);
skip:
		msg = log_from_idx(console_idx);

		if (msg->flags & LOG_NOCONS) {
			...
			goto skip;
		}

		level = msg->level;
		len += msg_print_text();			>> sprintfs
								   memcpy,
								   etc.

		if (nr_ext_console_drivers) {
			ext_len = msg_print_ext_header();	>> scnprintf
			ext_len += msg_print_ext_body();	>> scnprintfs
								   etc.
		}
		...
		raw_spin_unlock(&logbuf_lock);

		call_console_drivers(level, ext_text, ext_len, text, len)
		{
			if (level >= console_loglevel &&	>> drop the message
					!ignore_loglevel)
				return;

			console->write(...);
		}

		local_irq_restore(flags);
	}
	...
}

The thing here is this deferred `level >= console_loglevel' check. We are
wasting CPU cycles on sprintfs/memcpy/etc. preparing the messages that we
will eventually drop.

This can be huge when we register a new CON_PRINTBUFFER console, for
instance. For every such a console register_console() resets the
	console_seq, console_idx, console_prev
and sets a `exclusive console' pointer to replay the log buffer to that
just-registered console. And there can be a lot of messages to replay, in
the worst case most of which can be dropped after console_loglevel test.


We know messages' levels long before we call msg_print_text() and friends,
so we can just move console_loglevel check out of call_console_drivers()
and format a new message only if we are sure that it won't be dropped.

The patch factors out loglevel check into should_ignore_loglevel() function
and tests message->level and console_loglevel before formatting functions
in console_unlock() and console_cont_flush() are getting executed.

This improves things not only for exclusive CON_PRINTBUFFER consoles,
but for every console_unlock() that attempts to print a message of level
above the console_loglevel.

Signed-off-by: Sergey Senozhatsky <sergey.senozhatsky@gmail.com>
---
 kernel/printk/printk.c | 25 +++++++++++++++++++------
 1 file changed, 19 insertions(+), 6 deletions(-)

diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
index 414a89f..bfb766b 100644
--- a/kernel/printk/printk.c
+++ b/kernel/printk/printk.c
@@ -987,6 +987,11 @@ module_param(ignore_loglevel, bool, S_IRUGO | S_IWUSR);
 MODULE_PARM_DESC(ignore_loglevel,
 		 "ignore loglevel setting (prints all kernel messages to the console)");
 
+static bool should_ignore_loglevel(int level)
+{
+	return (level >= console_loglevel && !ignore_loglevel);
+}
+
 #ifdef CONFIG_BOOT_PRINTK_DELAY
 
 static int boot_delay; /* msecs delay after each printk during bootup */
@@ -1016,7 +1021,7 @@ static void boot_delay_msec(int level)
 	unsigned long timeout;
 
 	if ((boot_delay == 0 || system_state != SYSTEM_BOOTING)
-		|| (level >= console_loglevel && !ignore_loglevel)) {
+		|| should_ignore_loglevel(level)) {
 		return;
 	}
 
@@ -1506,8 +1511,6 @@ static void call_console_drivers(int level,
 
 	trace_console(text, len);
 
-	if (level >= console_loglevel && !ignore_loglevel)
-		return;
 	if (!console_drivers)
 		return;
 
@@ -1955,6 +1958,7 @@ static void call_console_drivers(int level,
 static size_t msg_print_text(const struct printk_log *msg, enum log_flags prev,
 			     bool syslog, char *buf, size_t size) { return 0; }
 static size_t cont_print_text(char *text, size_t size) { return 0; }
+static bool should_ignore_loglevel(int level) { return false; }
 
 /* Still needs to be defined for users */
 DEFINE_PER_CPU(printk_func_t, printk_func);
@@ -2234,6 +2238,13 @@ static void console_cont_flush(char *text, size_t size)
 	if (!cont.len)
 		goto out;
 
+	if (should_ignore_loglevel(cont.level)) {
+		cont.cons = cont.len;
+		if (cont.flushed)
+			cont.len = 0;
+		goto out;
+	}
+
 	/*
 	 * We still queue earlier records, likely because the console was
 	 * busy. The earlier ones need to be printed before this one, we
@@ -2337,10 +2348,13 @@ skip:
 			break;
 
 		msg = log_from_idx(console_idx);
-		if (msg->flags & LOG_NOCONS) {
+		level = msg->level;
+		if ((msg->flags & LOG_NOCONS) ||
+				should_ignore_loglevel(level)) {
 			/*
 			 * Skip record we have buffered and already printed
-			 * directly to the console when we received it.
+			 * directly to the console when we received it, and
+			 * record that has level above the console loglevel.
 			 */
 			console_idx = log_next(console_idx);
 			console_seq++;
@@ -2354,7 +2368,6 @@ skip:
 			goto skip;
 		}
 
-		level = msg->level;
 		len += msg_print_text(msg, console_prev, false,
 				      text + len, sizeof(text) - len);
 		if (nr_ext_console_drivers) {
-- 
2.9.0

Re: [PATCH] printk: introduce should_ignore_loglevel()

[Petr Mladek]

On Fri 2016-06-24 01:33:02, Sergey Senozhatsky wrote:
> The thing here is this deferred `level >= console_loglevel' check. We are
> wasting CPU cycles on sprintfs/memcpy/etc. preparing the messages that we
> will eventually drop.
> 
> Signed-off-by: Sergey Senozhatsky <sergey.senozhatsky@gmail.com>
> ---
>  kernel/printk/printk.c | 25 +++++++++++++++++++------
>  1 file changed, 19 insertions(+), 6 deletions(-)
> 
> diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
> index 414a89f..bfb766b 100644
> --- a/kernel/printk/printk.c
> +++ b/kernel/printk/printk.c
> @@ -987,6 +987,11 @@ module_param(ignore_loglevel, bool, S_IRUGO | S_IWUSR);
>  MODULE_PARM_DESC(ignore_loglevel,
>  		 "ignore loglevel setting (prints all kernel messages to the console)");
>  
> +static bool should_ignore_loglevel(int level)
> +{
> +	return (level >= console_loglevel && !ignore_loglevel);

The patch looks fine. It is nice optimization.

I was just quite confused by the name of this function. A function
called should_ignore_loglevel() should not return false when
ignore_loglevel variable is true.

I would call it ignore_message() or ignore_message_on_console() or so.

Best Regards,
Petr

Re: [PATCH] printk: introduce should_ignore_loglevel()

[Sergey Senozhatsky]

On (06/24/16 18:05), Petr Mladek wrote:
[..]
> > +static bool should_ignore_loglevel(int level)
> > +{
> > +	return (level >= console_loglevel && !ignore_loglevel);
> 
> The patch looks fine. It is nice optimization.
> 
> I was just quite confused by the name of this function. A function
> called should_ignore_loglevel() should not return false when
> ignore_loglevel variable is true.
> 
> I would call it ignore_message() or ignore_message_on_console() or so.

Hello Petr, you are right.

I was thinking about

s/should_ignore_loglevel/suppress_message/g
or.... s/should_ignore_loglevel/suppress_message_by_level/g
s/should_ignore_loglevel/suppress_message_printing/g

suppress_message_printing() is probably fine.

will it work for you guys?

	-ss

Re: [PATCH] printk: introduce should_ignore_loglevel()

[Petr Mladek]

On Sat 2016-06-25 14:22:37, Sergey Senozhatsky wrote:
> On (06/24/16 18:05), Petr Mladek wrote:
> [..]
> > > +static bool should_ignore_loglevel(int level)
> > > +{
> > > +	return (level >= console_loglevel && !ignore_loglevel);
> > 
> > The patch looks fine. It is nice optimization.
> > 
> > I was just quite confused by the name of this function. A function
> > called should_ignore_loglevel() should not return false when
> > ignore_loglevel variable is true.
> > 
> > I would call it ignore_message() or ignore_message_on_console() or so.
> 
> Hello Petr, you are right.
> 
> I was thinking about
> 
> s/should_ignore_loglevel/suppress_message/g
> or.... s/should_ignore_loglevel/suppress_message_by_level/g
> s/should_ignore_loglevel/suppress_message_printing/g
> 
> suppress_message_printing() is probably fine.

All variants look fine to me. After renaming, feel free to
add:

Reviewed-by: Petr Mladek <pmladek@suse.com>

Best Regards,
Petr


PS: The ignore_loglevel handling is a bit racy in some situations.
For example, uv_nmi_dump_state() or __handle_sysrq() set another
level, print some messages, and restore the original level. They
do not wait until all the printed messages appear on the console.
Also they do not synchronize against each other.

I am not sure if we have already discussed this. It is not critical
and it works well most of the time. I just want to make sure that
you know about it as you have more plans with the printk/console code.

Re: [PATCH] printk: introduce should_ignore_loglevel()

[Sergey Senozhatsky]

On (06/27/16 11:26), Petr Mladek wrote:
> On Sat 2016-06-25 14:22:37, Sergey Senozhatsky wrote:
> > On (06/24/16 18:05), Petr Mladek wrote:
> > [..]
> > > > +static bool should_ignore_loglevel(int level)
> > > > +{
> > > > +	return (level >= console_loglevel && !ignore_loglevel);
> > > 
> > > The patch looks fine. It is nice optimization.
> > > 
> > > I was just quite confused by the name of this function. A function
> > > called should_ignore_loglevel() should not return false when
> > > ignore_loglevel variable is true.
> > > 
> > > I would call it ignore_message() or ignore_message_on_console() or so.
> > 
> > Hello Petr, you are right.
> > 
> > I was thinking about
> > 
> > s/should_ignore_loglevel/suppress_message/g
> > or.... s/should_ignore_loglevel/suppress_message_by_level/g
> > s/should_ignore_loglevel/suppress_message_printing/g
> > 
> > suppress_message_printing() is probably fine.
> 
> All variants look fine to me. After renaming, feel free to
> add:
> 
> Reviewed-by: Petr Mladek <pmladek@suse.com>
> 

thanks.

> PS: The ignore_loglevel handling is a bit racy in some situations.
> For example, uv_nmi_dump_state() or __handle_sysrq() set another
> level, print some messages, and restore the original level. They
> do not wait until all the printed messages appear on the console.
> Also they do not synchronize against each other.
>

__handle_sysrq() also assumes that only cpu printk-s, so it does
KERN_CONT printks in SMP mode. and there are billions of places
that do things like this.

as of deferred loglevel check, we probably can add "console_loglevel:3;"
to 'struct printk_log' and `static struct cont', and keep there
console_loglevel actual at the time the was appeneded to the log
buffer. so then suppress_message_printing() will have one extra param

bool suppress_message_printing(int leve, int cons_loglevel)
{
	return (level >= cons_loglevel ...);
}


speaking of KERN_CONT, I've found one regression with async printk,
and I think I now have some idea what's going on there, will post
some-sort-of-a-patch today or tomorrow.


> I am not sure if we have already discussed this. It is not critical
> and it works well most of the time. I just want to make sure that
> you know about it as you have more plans with the printk/console code.

thanks, I'll put in on a list; not sure we discussed this either.

	-ss