Re: [PATCH] printk: introduce should_ignore_loglevel()
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> 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
Re: [PATCH] printk: introduce should_ignore_loglevel()
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 > 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
Re: [PATCH] printk: introduce should_ignore_loglevel()
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 MladekBest 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()
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 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()
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()
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()
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> --- > 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()
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 > --- > 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
[PATCH] printk: introduce should_ignore_loglevel()
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(_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(_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--- 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 *
[PATCH] printk: introduce should_ignore_loglevel()
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(_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(_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 --- 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