[PATCH 1/3] printk: Introduce per-console loglevel setting
Not all consoles are created equal: depending on the actual hardware,
the latency of a printk() call can vary dramatically. The worst examples
are serial consoles, where it can spin for tens of milliseconds banging
the UART to emit a message, which can cause application-level problems
when the kernel spews onto the console.
At Facebook we use netconsole to monitor our fleet, but we still have
serial consoles attached on each host for live debugging, and the latter
has caused problems. An obvious solution is to disable the kernel
console output to ttyS0, but this makes live debugging frustrating,
since crashes become silent and opaque to the ttyS0 user. Enabling it on
the fly when needed isn't feasible, since boxes you need to debug via
serial are likely to be borked in ways that make this impossible.
That puts us between a rock and a hard place: we'd love to set
kernel.printk to KERN_INFO and get all the logs. But while netconsole is
fast enough to permit that without perturbing userspace, ttyS0 is not,
and we're forced to limit console logging to KERN_WARNING and higher.
This patch introduces a new per-console loglevel setting, and changes
console_unlock() to use max(global_level, per_console_level) when
deciding whether or not to emit a given log message.
This lets us have our cake and eat it too: instead of being forced to
limit all consoles verbosity based on the speed of the slowest one, we
can "promote" the faster console while still using a conservative system
loglevel setting to avoid disturbing applications.
Cc: Petr Mladek
Cc: Steven Rostedt
Cc: Sergey Senozhatsky
Signed-off-by: Calvin Owens
---
(V1: https://lkml.org/lkml/2017/4/4/783)
Changes in V2:
* Honor the ignore_loglevel setting in all cases
* Change semantics to use max(global, console) as the loglevel
for a console, instead of the previous patch where we treated
the per-console one as a filter downstream of the global one.
include/linux/console.h | 1 +
kernel/printk/printk.c | 38 +++---
2 files changed, 20 insertions(+), 19 deletions(-)
diff --git a/include/linux/console.h b/include/linux/console.h
index b8920a0..a5b5d79 100644
--- a/include/linux/console.h
+++ b/include/linux/console.h
@@ -147,6 +147,7 @@ struct console {
int cflag;
void*data;
struct console *next;
+ int level;
};
/*
diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
index 512f7c2..3f1675e 100644
--- a/kernel/printk/printk.c
+++ b/kernel/printk/printk.c
@@ -1141,9 +1141,14 @@ 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)
+static int effective_loglevel(struct console *con)
{
- return (level >= console_loglevel && !ignore_loglevel);
+ return max(console_loglevel, con ? con->level : LOGLEVEL_EMERG);
+}
+
+static bool suppress_message_printing(int level, struct console *con)
+{
+ return (level >= effective_loglevel(con) && !ignore_loglevel);
}
#ifdef CONFIG_BOOT_PRINTK_DELAY
@@ -1175,7 +1180,7 @@ static void boot_delay_msec(int level)
unsigned long timeout;
if ((boot_delay == 0 || system_state >= SYSTEM_RUNNING)
- || suppress_message_printing(level)) {
+ || suppress_message_printing(level, NULL)) {
return;
}
@@ -1549,7 +1554,7 @@ SYSCALL_DEFINE3(syslog, int, type, char __user *, buf,
int, len)
* The console_lock must be held.
*/
static void call_console_drivers(const char *ext_text, size_t ext_len,
-const char *text, size_t len)
+const char *text, size_t len, int level)
{
struct console *con;
@@ -1568,6 +1573,8 @@ static void call_console_drivers(const char *ext_text,
size_t ext_len,
if (!cpu_online(smp_processor_id()) &&
!(con->flags & CON_ANYTIME))
continue;
+ if (suppress_message_printing(level, con))
+ continue;
if (con->flags & CON_EXTENDED)
con->write(con, ext_text, ext_len);
else
@@ -1856,10 +1863,9 @@ static ssize_t msg_print_ext_body(char *buf, size_t size,
char *dict, size_t dict_len,
char *text, size_t text_len) { return 0; }
static void call_console_drivers(const char *ext_text, size_t ext_len,
-const char *text, size_t len) {}
+const char *text, size_t len, int level) {}
static size_t msg_print_text(const struct printk_log *msg,
bool syslog, char *buf, size_t size) { return 0; }
-static bool suppress_message_printing(int level) { return false; }
#endif
Re: [PATCH 1/3] printk: Introduce per-console loglevel setting
On 09/28/2017 05:43 PM, Calvin Owens wrote:
Not all consoles are created equal: depending on the actual hardware,
the latency of a printk() call can vary dramatically. The worst examples
are serial consoles, where it can spin for tens of milliseconds banging
the UART to emit a message, which can cause application-level problems
when the kernel spews onto the console.
Any thoughts on this series? Happy to resend again, but if there are no
objections I'd love to see it merged sooner rather than later :)
Happy to resend too, just let me know.
Thanks,
Calvin
At Facebook we use netconsole to monitor our fleet, but we still have
serial consoles attached on each host for live debugging, and the latter
has caused problems. An obvious solution is to disable the kernel
console output to ttyS0, but this makes live debugging frustrating,
since crashes become silent and opaque to the ttyS0 user. Enabling it on
the fly when needed isn't feasible, since boxes you need to debug via
serial are likely to be borked in ways that make this impossible.
That puts us between a rock and a hard place: we'd love to set
kernel.printk to KERN_INFO and get all the logs. But while netconsole is
fast enough to permit that without perturbing userspace, ttyS0 is not,
and we're forced to limit console logging to KERN_WARNING and higher.
This patch introduces a new per-console loglevel setting, and changes
console_unlock() to use max(global_level, per_console_level) when
deciding whether or not to emit a given log message.
This lets us have our cake and eat it too: instead of being forced to
limit all consoles verbosity based on the speed of the slowest one, we
can "promote" the faster console while still using a conservative system
loglevel setting to avoid disturbing applications.
Cc: Petr Mladek
Cc: Steven Rostedt
Cc: Sergey Senozhatsky
Signed-off-by: Calvin Owens
---
(V1: https://lkml.org/lkml/2017/4/4/783)
Changes in V2:
* Honor the ignore_loglevel setting in all cases
* Change semantics to use max(global, console) as the loglevel
for a console, instead of the previous patch where we treated
the per-console one as a filter downstream of the global one.
include/linux/console.h | 1 +
kernel/printk/printk.c | 38 +++---
2 files changed, 20 insertions(+), 19 deletions(-)
diff --git a/include/linux/console.h b/include/linux/console.h
index b8920a0..a5b5d79 100644
--- a/include/linux/console.h
+++ b/include/linux/console.h
@@ -147,6 +147,7 @@ struct console {
int cflag;
void*data;
struct console *next;
+ int level;
};
/*
diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
index 512f7c2..3f1675e 100644
--- a/kernel/printk/printk.c
+++ b/kernel/printk/printk.c
@@ -1141,9 +1141,14 @@ 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)
+static int effective_loglevel(struct console *con)
{
- return (level >= console_loglevel && !ignore_loglevel);
+ return max(console_loglevel, con ? con->level : LOGLEVEL_EMERG);
+}
+
+static bool suppress_message_printing(int level, struct console *con)
+{
+ return (level >= effective_loglevel(con) && !ignore_loglevel);
}
#ifdef CONFIG_BOOT_PRINTK_DELAY
@@ -1175,7 +1180,7 @@ static void boot_delay_msec(int level)
unsigned long timeout;
if ((boot_delay == 0 || system_state >= SYSTEM_RUNNING)
- || suppress_message_printing(level)) {
+ || suppress_message_printing(level, NULL)) {
return;
}
@@ -1549,7 +1554,7 @@ SYSCALL_DEFINE3(syslog, int, type, char __user *, buf, int, len)
* The console_lock must be held.
*/
static void call_console_drivers(const char *ext_text, size_t ext_len,
-const char *text, size_t len)
+const char *text, size_t len, int level)
{
struct console *con;
@@ -1568,6 +1573,8 @@ static void call_console_drivers(const char *ext_text, size_t ext_len,
if (!cpu_online(smp_processor_id()) &&
!(con->flags & CON_ANYTIME))
continue;
+ if (suppress_message_printing(level, con))
+ continue;
if (con->flags & CON_EXTENDED)
con->write(con, ext_text, ext_len);
else
@@ -1856,10 +1863,9 @@ static ssize_t msg_print_ext_body(char *buf, size_t size,
char *dict, size_t dict_len,
char *text, size_t text_len) { return 0; }
static void call_console_drivers(const char *ext_text, size_t ext_len,
-const char *text, size_t len) {}
+
Re: [PATCH 1/3] printk: Introduce per-console loglevel setting
On Thu 2017-10-19 16:40:45, Calvin Owens wrote: > On 09/28/2017 05:43 PM, Calvin Owens wrote: > >Not all consoles are created equal: depending on the actual hardware, > >the latency of a printk() call can vary dramatically. The worst examples > >are serial consoles, where it can spin for tens of milliseconds banging > >the UART to emit a message, which can cause application-level problems > >when the kernel spews onto the console. > > Any thoughts on this series? Happy to resend again, but if there are no > objections I'd love to see it merged sooner rather than later :) > > Happy to resend too, just let me know. There is no need to resend the patch. It is on my radar and I am going to look at it. Please, be patient, you hit conference, illness, after vacation season. We do not want to unnecessarily delay it but it is not a trivial change that might be accepted within minutes. Best Regards, Petr -- To unsubscribe from this list: send the line "unsubscribe linux-doc" in the body of a message to majord...@vger.kernel.org More majordomo info at http://vger.kernel.org/majordomo-info.html
Re: [PATCH 1/3] printk: Introduce per-console loglevel setting
On 10/20/2017 01:05 AM, Petr Mladek wrote: On Thu 2017-10-19 16:40:45, Calvin Owens wrote: On 09/28/2017 05:43 PM, Calvin Owens wrote: Not all consoles are created equal: depending on the actual hardware, the latency of a printk() call can vary dramatically. The worst examples are serial consoles, where it can spin for tens of milliseconds banging the UART to emit a message, which can cause application-level problems when the kernel spews onto the console. Any thoughts on this series? Happy to resend again, but if there are no objections I'd love to see it merged sooner rather than later :) Happy to resend too, just let me know. There is no need to resend the patch. It is on my radar and I am going to look at it. Please, be patient, you hit conference, illness, after vacation season. We do not want to unnecessarily delay it but it is not a trivial change that might be accepted within minutes. No worries, just wanted to make sure it hadn't been missed :) Thanks, Calvin Best Regards, Petr -- To unsubscribe from this list: send the line "unsubscribe linux-doc" in the body of a message to majord...@vger.kernel.org More majordomo info at http://vger.kernel.org/majordomo-info.html
Re: [PATCH 1/3] printk: Introduce per-console loglevel setting
On Thu 2017-09-28 17:43:55, Calvin Owens wrote:
> This patch introduces a new per-console loglevel setting, and changes
> console_unlock() to use max(global_level, per_console_level) when
> deciding whether or not to emit a given log message.
> diff --git a/include/linux/console.h b/include/linux/console.h
> index b8920a0..a5b5d79 100644
> --- a/include/linux/console.h
> +++ b/include/linux/console.h
> @@ -147,6 +147,7 @@ struct console {
> int cflag;
> void*data;
> struct console *next;
> + int level;
I would make the meaning more clear and call this min_loglevel.
> };
>
> /*
> diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
> index 512f7c2..3f1675e 100644
> --- a/kernel/printk/printk.c
> +++ b/kernel/printk/printk.c
> @@ -1141,9 +1141,14 @@ 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)
> +static int effective_loglevel(struct console *con)
> {
> - return (level >= console_loglevel && !ignore_loglevel);
> + return max(console_loglevel, con ? con->level : LOGLEVEL_EMERG);
> +}
> +
> +static bool suppress_message_printing(int level, struct console *con)
> +{
> + return (level >= effective_loglevel(con) && !ignore_loglevel);
> }
We need to be more careful here:
First, there is one ugly level called CONSOLE_LOGLEVEL_SILENT. Fortunately,
it is used only by vkdb_printf(). I guess that the purpose is to store
messages into the log buffer and do not show them on consoles.
It is hack and it is racy. It would hide the messages only when the
console_lock() is not already taken. Similar hack is used on more
locations, e.g. in __handle_sysrq() and these are racy as well.
We need to come up with something better in the future but this
is a task for another patchset.
Second, this functions are called with NULL when we need to take
all usable consoles into account. You simplified it by ignoring
the per-console setting. But it is not correct. For example,
you might need to delay the printing in boot_delay_msec()
also on the fast console. Also this was the reason to remove
one optimization in console_unlock().
I thought about a reasonable solution and came up with something like:
static bool suppress_message_printing(int level, struct console *con)
{
int callable_loglevel;
if (ignore_loglevel || console_loglevel == CONSOLE_LOGLEVEL_MOTORMOUTH)
return false;
/* Make silent even fast consoles. */
if (console_loglevel == CONSOLE_LOGLEVEL_SILENT)
return true;
if (con)
callable_loglevel = con->min_loglevel;
else
callable_loglevel = max_custom_console_loglevel;
/* Global setting might make all consoles more verbose. */
if (callable_loglevel < console_loglevel)
callable_loglevel = console_loglevel;
return level >= callable_loglevel();
}
Yes, it is complicated. But the logic is complicated. IMHO, this has
the advantage that we do most of the decisions on a single place
and it might be easier to get the picture.
Anyway, max_custom_console_loglevel would be a global variable
defined as:
/*
* Minimum loglevel of the most talkative registered console.
* It is a maximum of all registered con->min_logvevel values.
*/
static int max_custom_console_loglevel = LOGLEVEL_EMERG;
The value should get updated when any console is registered
and when a registered console is manipulated. It means in
register_console(), unregister_console(), and the sysfs
write callbacks.
> #ifdef CONFIG_BOOT_PRINTK_DELAY
> @@ -2199,22 +2205,11 @@ void console_unlock(void)
> } else {
> len = 0;
> }
> -skip:
> +
> if (console_seq == log_next_seq)
> break;
>
> msg = log_from_idx(console_idx);
> - if (suppress_message_printing(msg->level)) {
> - /*
> - * Skip record we have buffered and already printed
> - * 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++;
> - goto skip;
> - }
I would like to keep this code. It does not make sense to prepare the
text buffer if it won't be used at all. It would work with the change
that I proposed above.
> len += msg_print_text(msg, false, text + len, sizeof(text) -
> len);
> if (nr_ext_console_drivers) {
> ext_len = msg_print_ext_header(ext_text,
> @@ -2230,7 +2225,7 @@ void console_unlock(void)
> raw_spin_unlock(&logbuf_lock);
>
>
Re: [PATCH 1/3] printk: Introduce per-console loglevel setting
On Fri, 3 Nov 2017 13:00:05 +0100
Petr Mladek wrote:
> On Thu 2017-09-28 17:43:55, Calvin Owens wrote:
> > This patch introduces a new per-console loglevel setting, and changes
> > console_unlock() to use max(global_level, per_console_level) when
> > deciding whether or not to emit a given log message.
>
> > diff --git a/include/linux/console.h b/include/linux/console.h
> > index b8920a0..a5b5d79 100644
> > --- a/include/linux/console.h
> > +++ b/include/linux/console.h
> > @@ -147,6 +147,7 @@ struct console {
> > int cflag;
> > void*data;
> > struct console *next;
> > + int level;
>
> I would make the meaning more clear and call this min_loglevel.
Or just loglevel, as those of us dealing with printk should understand.
This is just a per console loglevel, and if we call it min_loglevel, it
may be confusing because there is no "min_loglevel" that is currently
used.
[ Just read what you did below, maybe min is OK ]
>
> > };
> >
> > /*
> > diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
> > index 512f7c2..3f1675e 100644
> > --- a/kernel/printk/printk.c
> > +++ b/kernel/printk/printk.c
> > @@ -1141,9 +1141,14 @@ 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)
> > +static int effective_loglevel(struct console *con)
> > {
> > - return (level >= console_loglevel && !ignore_loglevel);
> > + return max(console_loglevel, con ? con->level : LOGLEVEL_EMERG);
> > +}
> > +
> > +static bool suppress_message_printing(int level, struct console *con)
> > +{
> > + return (level >= effective_loglevel(con) && !ignore_loglevel);
> > }
>
> We need to be more careful here:
>
> First, there is one ugly level called CONSOLE_LOGLEVEL_SILENT. Fortunately,
> it is used only by vkdb_printf(). I guess that the purpose is to store
> messages into the log buffer and do not show them on consoles.
Unfortunately, it is also used by
arch/mn10300/kernel/mn10300-watchdog.c.
Which calls console_silent().
>
> It is hack and it is racy. It would hide the messages only when the
> console_lock() is not already taken. Similar hack is used on more
> locations, e.g. in __handle_sysrq() and these are racy as well.
> We need to come up with something better in the future but this
> is a task for another patchset.
Agreed.
>
>
> Second, this functions are called with NULL when we need to take
> all usable consoles into account. You simplified it by ignoring
> the per-console setting. But it is not correct. For example,
> you might need to delay the printing in boot_delay_msec()
> also on the fast console. Also this was the reason to remove
> one optimization in console_unlock().
>
> I thought about a reasonable solution and came up with something like:
>
> static bool suppress_message_printing(int level, struct console *con)
> {
> int callable_loglevel;
>
> if (ignore_loglevel || console_loglevel == CONSOLE_LOGLEVEL_MOTORMOUTH)
> return false;
>
> /* Make silent even fast consoles. */
> if (console_loglevel == CONSOLE_LOGLEVEL_SILENT)
> return true;
>
> if (con)
> callable_loglevel = con->min_loglevel;
> else
> callable_loglevel = max_custom_console_loglevel;
>
> /* Global setting might make all consoles more verbose. */
> if (callable_loglevel < console_loglevel)
> callable_loglevel = console_loglevel;
>
> return level >= callable_loglevel();
> }
>
> Yes, it is complicated. But the logic is complicated. IMHO, this has
> the advantage that we do most of the decisions on a single place
> and it might be easier to get the picture.
It's not that complex, and it also has the benefit to document exactly
what the console_loglevel is doing.
>
> Anyway, max_custom_console_loglevel would be a global variable
> defined as:
>
> /*
> * Minimum loglevel of the most talkative registered console.
> * It is a maximum of all registered con->min_logvevel values.
> */
> static int max_custom_console_loglevel = LOGLEVEL_EMERG;
Ah, that is why you added min_loglevel.
-- Steve
>
> The value should get updated when any console is registered
> and when a registered console is manipulated. It means in
> register_console(), unregister_console(), and the sysfs
> write callbacks.
>
--
To unsubscribe from this list: send the line "unsubscribe linux-doc" in
the body of a message to majord...@vger.kernel.org
More majordomo info at http://vger.kernel.org/majordomo-info.html
Re: [PATCH 1/3] printk: Introduce per-console loglevel setting
On (09/28/17 17:43), Calvin Owens wrote: > Not all consoles are created equal: depending on the actual hardware, > the latency of a printk() call can vary dramatically. The worst examples > are serial consoles, where it can spin for tens of milliseconds banging > the UART to emit a message, which can cause application-level problems > when the kernel spews onto the console. > > At Facebook we use netconsole to monitor our fleet, but we still have > serial consoles attached on each host for live debugging, and the latter > has caused problems. An obvious solution is to disable the kernel > console output to ttyS0, but this makes live debugging frustrating, > since crashes become silent and opaque to the ttyS0 user. Enabling it on > the fly when needed isn't feasible, since boxes you need to debug via > serial are likely to be borked in ways that make this impossible. > > That puts us between a rock and a hard place: we'd love to set > kernel.printk to KERN_INFO and get all the logs. But while netconsole is > fast enough to permit that without perturbing userspace, ttyS0 is not, > and we're forced to limit console logging to KERN_WARNING and higher. > > This patch introduces a new per-console loglevel setting, and changes > console_unlock() to use max(global_level, per_console_level) when > deciding whether or not to emit a given log message. > > This lets us have our cake and eat it too: instead of being forced to > limit all consoles verbosity based on the speed of the slowest one, we > can "promote" the faster console while still using a conservative system > loglevel setting to avoid disturbing applications. Hi Calvin, Do you have time to address the review feedback and re-spin v2? -ss
Re: [PATCH 1/3] printk: Introduce per-console loglevel setting
On Friday 10/19 at 09:04 +0900, Sergey Senozhatsky wrote: > On (09/28/17 17:43), Calvin Owens wrote: > > Not all consoles are created equal: depending on the actual hardware, > > the latency of a printk() call can vary dramatically. The worst examples > > are serial consoles, where it can spin for tens of milliseconds banging > > the UART to emit a message, which can cause application-level problems > > when the kernel spews onto the console. > > > > At Facebook we use netconsole to monitor our fleet, but we still have > > serial consoles attached on each host for live debugging, and the latter > > has caused problems. An obvious solution is to disable the kernel > > console output to ttyS0, but this makes live debugging frustrating, > > since crashes become silent and opaque to the ttyS0 user. Enabling it on > > the fly when needed isn't feasible, since boxes you need to debug via > > serial are likely to be borked in ways that make this impossible. > > > > That puts us between a rock and a hard place: we'd love to set > > kernel.printk to KERN_INFO and get all the logs. But while netconsole is > > fast enough to permit that without perturbing userspace, ttyS0 is not, > > and we're forced to limit console logging to KERN_WARNING and higher. > > > > This patch introduces a new per-console loglevel setting, and changes > > console_unlock() to use max(global_level, per_console_level) when > > deciding whether or not to emit a given log message. > > > > This lets us have our cake and eat it too: instead of being forced to > > limit all consoles verbosity based on the speed of the slowest one, we > > can "promote" the faster console while still using a conservative system > > loglevel setting to avoid disturbing applications. > > Hi Calvin, > > Do you have time to address the review feedback and re-spin v2? Hi Sergey, It's in-progress, I'm sorry it hasn't happened sooner. By embedding the kobject in the console struct, we end up needing to refactor the console drivers to use the kobject refcount instead of simply calling kfree(), which is what I'm working on. It ends up being tedious but not particularly complicated, my goal is to have this up soon :) Thanks, Calvin
Re: [PATCH 1/3] printk: Introduce per-console loglevel setting
On (10/19/18 22:03), Calvin Owens wrote: > Hi Sergey, > > It's in-progress, I'm sorry it hasn't happened sooner. Great! > By embedding the kobject in the console struct, we end up needing to refactor > the console drivers to use the kobject refcount instead of simply calling > kfree(), which is what I'm working on. It ends up being tedious but not > particularly complicated, my goal is to have this up soon :) OK :) -ss
