From mboxrd@z Thu Jan 1 00:00:00 1970 Return-Path: Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand id S932964AbcGICF2 (ORCPT ); Fri, 8 Jul 2016 22:05:28 -0400 Received: from mail-pa0-f68.google.com ([209.85.220.68]:36187 "EHLO mail-pa0-f68.google.com" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP id S932486AbcGICFV (ORCPT ); Fri, 8 Jul 2016 22:05:21 -0400 Date: Sat, 9 Jul 2016 11:05:24 +0900 From: Sergey Senozhatsky To: Andrew Morton Cc: Sergey Senozhatsky , Petr Mladek , Tejun Heo , Jan Kara , Calvin Owens , linux-kernel@vger.kernel.org, Sergey Senozhatsky Subject: Re: [PATCH v2] printk: introduce suppress_message_printing() Message-ID: <20160709020524.GA422@swordfish> References: <20160627135012.8229-1-sergey.senozhatsky@gmail.com> MIME-Version: 1.0 Content-Type: text/plain; charset=us-ascii Content-Disposition: inline In-Reply-To: <20160627135012.8229-1-sergey.senozhatsky@gmail.com> User-Agent: Mutt/1.6.2 (2016-07-01) Sender: linux-kernel-owner@vger.kernel.org List-ID: X-Mailing-List: linux-kernel@vger.kernel.org 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 > Reviewed-by: Petr Mladek > --- > > 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 >