Re: [PATCH v2] printk: introduce suppress_message_printing()

[Sergey Senozhatsky]

On (06/27/16 22:50), Sergey Senozhatsky wrote:
> Messages' levels and console log level are 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:

Hello Andrew,

just in case if you missed this one. the patch is fine.

the cont printk problem I talked about in the v1 thread
is not related to this patch, but to *async* printk (which
is not in the mainline... yet. hm... shall we discuss it
on the kernel summit?)

	-ss

> 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 suppress_message_printing()
> 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@xxxxxxxxx>
> Reviewed-by: Petr Mladek <pmladek@xxxxxxxx>
> ---
> 
> v2: rename function to suppress_message_printing()
> 
>  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..33957d2 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 suppress_message_printing(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)) {
> +		|| suppress_message_printing(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 suppress_message_printing(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 (suppress_message_printing(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) ||
> +				suppress_message_printing(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.37.g6d523a3
>