* [PATCH v2] printk: introduce suppress_message_printing()
@ 2016-06-27 13:50 Sergey Senozhatsky
2016-07-09 2:05 ` Sergey Senozhatsky
0 siblings, 1 reply; 2+ messages in thread
From: Sergey Senozhatsky @ 2016-06-27 13:50 UTC (permalink / raw)
To: Andrew Morton
Cc: Petr Mladek, Tejun Heo, Jan Kara, Calvin Owens, linux-kernel,
Sergey Senozhatsky, Sergey Senozhatsky
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:
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@gmail.com>
Reviewed-by: Petr Mladek <pmladek@suse.com>
---
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
^ permalink raw reply related [flat|nested] 2+ messages in thread
* Re: [PATCH v2] printk: introduce suppress_message_printing()
2016-06-27 13:50 [PATCH v2] printk: introduce suppress_message_printing() Sergey Senozhatsky
@ 2016-07-09 2:05 ` Sergey Senozhatsky
0 siblings, 0 replies; 2+ messages in thread
From: Sergey Senozhatsky @ 2016-07-09 2:05 UTC (permalink / raw)
To: Andrew Morton
Cc: Sergey Senozhatsky, Petr Mladek, Tejun Heo, Jan Kara,
Calvin Owens, linux-kernel, 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@gmail.com>
> Reviewed-by: Petr Mladek <pmladek@suse.com>
> ---
>
> 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
>
^ permalink raw reply [flat|nested] 2+ messages in thread
end of thread, other threads:[~2016-07-09 2:05 UTC | newest]
Thread overview: 2+ messages (download: mbox.gz / follow: Atom feed)
-- links below jump to the message on this page --
2016-06-27 13:50 [PATCH v2] printk: introduce suppress_message_printing() Sergey Senozhatsky
2016-07-09 2:05 ` Sergey Senozhatsky
This is an external index of several public inboxes,
see mirroring instructions on how to clone and mirror
all data and code used by this external index.