Message ID | 1430318704-32374-4-git-send-email-tj@kernel.org |
---|---|
State | Not Applicable, archived |
Delegated to: | David Miller |
Headers | show |
On Wed, 29 Apr 2015 10:45:04 -0400 Tejun Heo <tj@kernel.org> wrote: > printk log_buf keeps various metadata for each message including its > sequence number and timestamp. The metadata is currently available > only through /dev/kmsg and stripped out before passed onto console > drivers. We want this metadata to be available to console drivers too > so that console consumers can get full information including the > metadata and dictionary, which among other things can be used to > detect whether messages got lost in transit. > > This patch implements support for extended console drivers. Consoles > can indicate that they want extended messages by setting the new > CON_EXTENDED flag and they'll be fed messages formatted the same way > as /dev/kmsg. > > "<level>,<sequnum>,<timestamp>,<contflag>;<message text>\n" > > If extended consoles exist, in-kernel fragment assembly is disabled. > This ensures that all messages emitted to consoles have full metadata > including sequence number. The contflag carries enough information to > reassemble the fragments from the reader side trivially. Note that > this only affects /dev/kmsg. Regular console and /proc/kmsg outputs > are not affected by this change. > > * Extended message formatting for console drivers is enabled iff there > are registered extended consoles. > > * Comment describing /dev/kmsg message format updated to add missing > contflag field and help distinguishing variable from verbatim terms. So if I'm understanding this correctly, the /dev/kmsg output is altered (different cont handling) if some console registers with CON_EXTENDED (and there are no such consoles yet, so the patch is a no-op). If correct, this seems undesirable - registration of a CON_EXTENDED console collaterally damages the /dev/kmsg interface? If the user has an app which depends on the original /dev/kmsg format then they'll be wondered what-the-heck-just-happened? -- To unsubscribe from this list: send the line "unsubscribe netdev" in the body of a message to majordomo@vger.kernel.org More majordomo info at http://vger.kernel.org/majordomo-info.html
Hello, Andrew. On Thu, Apr 30, 2015 at 02:31:28PM -0700, Andrew Morton wrote: > So if I'm understanding this correctly, the /dev/kmsg output is altered > (different cont handling) if some console registers with CON_EXTENDED > (and there are no such consoles yet, so the patch is a no-op). Yeah, that's mostly right. /dev/kmsg output already has "continuation" flag which indicates whether a message should be concatenated which gets triggered occassionally currently. This would make use of that behavior a lot more frequently. > If correct, this seems undesirable - registration of a CON_EXTENDED > console collaterally damages the /dev/kmsg interface? If the user has > an app which depends on the original /dev/kmsg format then they'll be > wondered what-the-heck-just-happened? For applications which ignore the continuation flags, this would lead to a different output. We can fake it for /dev/kmsg (concatenate from the kernel side and then output empty message for the later fragments) but that'd be piling more hacks on top of already unnecessary hack which is the cont buffer. We can generate a log message indicating that the new mode is enabled to make it easier to figure out why it changed. Given that this is not an entirely new behavior and the usage of extended console is likely to stay fairly specific, transitioning this way is unlikely to cause too much trouble especially given that most traditional tools use the older interfaces w/o metadata which aren't affected by this change. What do you think? Thanks.
On Thu, 30 Apr 2015 18:12:31 -0400 Tejun Heo <tj@kernel.org> wrote: > Hello, Andrew. > > On Thu, Apr 30, 2015 at 02:31:28PM -0700, Andrew Morton wrote: > > So if I'm understanding this correctly, the /dev/kmsg output is altered > > (different cont handling) if some console registers with CON_EXTENDED > > (and there are no such consoles yet, so the patch is a no-op). > > Yeah, that's mostly right. /dev/kmsg output already has > "continuation" flag which indicates whether a message should be > concatenated which gets triggered occassionally currently. This would > make use of that behavior a lot more frequently. OK, sounds reasonable. > > If correct, this seems undesirable - registration of a CON_EXTENDED > > console collaterally damages the /dev/kmsg interface? If the user has > > an app which depends on the original /dev/kmsg format then they'll be > > wondered what-the-heck-just-happened? > > For applications which ignore the continuation flags, this would lead > to a different output. We can fake it for /dev/kmsg (concatenate from > the kernel side and then output empty message for the later fragments) > but that'd be piling more hacks on top of already unnecessary hack > which is the cont buffer. > > We can generate a log message indicating that the new mode is enabled > to make it easier to figure out why it changed. Given that this is > not an entirely new behavior and the usage of extended console is > likely to stay fairly specific, transitioning this way is unlikely to > cause too much trouble especially given that most traditional tools > use the older interfaces w/o metadata which aren't affected by this > change. > > What do you think? Yes, I suppose a printk is worthwhile. Maybe a paragraph in Documentation/ABI/testing/dev-kmsg also. -- To unsubscribe from this list: send the line "unsubscribe netdev" in the body of a message to majordomo@vger.kernel.org More majordomo info at http://vger.kernel.org/majordomo-info.html
Hi Tejun, On Wed, Apr 29, 2015 at 4:45 PM, Tejun Heo <tj@kernel.org> wrote: > --- a/kernel/printk/printk.c > +++ b/kernel/printk/printk.c > @@ -2196,6 +2227,7 @@ out: > */ > void console_unlock(void) > { > + static char ext_text[CONSOLE_EXT_LOG_MAX]; Can you please a) make this feature optional, b) (de)allocate this buffer dynamically when the first/last console with CON_EXTENDED set is (un)registered? Your patch is at the top of the bloat-o-meter output (against v4.1): add/remove: 388/154 grow/shrink: 1309/269 up/down: 92366/-44878 (47488) function old new delta ext_text - 8192 +8192 do_con_trol - 4824 +4824 path_openat 1416 4224 +2808 tvec_bases 4 2080 +2076 ip_do_fragment - 1824 +1824 unix_stream_read_generic - 1452 +1452 ext4_ext_shift_extents - 1350 +1350 ext4_insert_range - 1174 +1174 bpf_prepare_filter 264 1430 +1166 proc_pid_cmdline_read - 1020 +1020 and unlike the others, this one is not that difficult to fix. Thanks! Gr{oetje,eeting}s, Geert -- Geert Uytterhoeven -- There's lots of Linux beyond ia32 -- geert@linux-m68k.org In personal conversations with technical people, I call myself a hacker. But when I'm talking to journalists I just say "programmer" or something like that. -- Linus Torvalds -- To unsubscribe from this list: send the line "unsubscribe netdev" in the body of a message to majordomo@vger.kernel.org More majordomo info at http://vger.kernel.org/majordomo-info.html
Hello, On Mon, Jun 29, 2015 at 11:20:41AM +0200, Geert Uytterhoeven wrote: > On Wed, Apr 29, 2015 at 4:45 PM, Tejun Heo <tj@kernel.org> wrote: > > --- a/kernel/printk/printk.c > > +++ b/kernel/printk/printk.c > > > @@ -2196,6 +2227,7 @@ out: > > */ > > void console_unlock(void) > > { > > + static char ext_text[CONSOLE_EXT_LOG_MAX]; > > Can you please > a) make this feature optional, netconsole itself is optional & modular. I'm not sure making further splits is called for, especially given the use cases. > b) (de)allocate this buffer dynamically when the first/last console with > CON_EXTENDED set is (un)registered? But yeah, making the buffer allocated on demand should be simple enough. Will get to it. Thanks.
Hi Tejun, On Mon, Jun 29, 2015 at 5:28 PM, Tejun Heo <tj@kernel.org> wrote: > On Mon, Jun 29, 2015 at 11:20:41AM +0200, Geert Uytterhoeven wrote: >> On Wed, Apr 29, 2015 at 4:45 PM, Tejun Heo <tj@kernel.org> wrote: >> > --- a/kernel/printk/printk.c >> > +++ b/kernel/printk/printk.c >> >> > @@ -2196,6 +2227,7 @@ out: >> > */ >> > void console_unlock(void) >> > { >> > + static char ext_text[CONSOLE_EXT_LOG_MAX]; >> >> Can you please >> a) make this feature optional, > > netconsole itself is optional & modular. I'm not sure making further > splits is called for, especially given the use cases. It could be a hidden option, selected by its users (e.g. netconsole). >> b) (de)allocate this buffer dynamically when the first/last console with >> CON_EXTENDED set is (un)registered? > > But yeah, making the buffer allocated on demand should be simple > enough. Will get to it. Thanks! Gr{oetje,eeting}s, Geert -- Geert Uytterhoeven -- There's lots of Linux beyond ia32 -- geert@linux-m68k.org In personal conversations with technical people, I call myself a hacker. But when I'm talking to journalists I just say "programmer" or something like that. -- Linus Torvalds -- To unsubscribe from this list: send the line "unsubscribe netdev" in the body of a message to majordomo@vger.kernel.org More majordomo info at http://vger.kernel.org/majordomo-info.html
On Mon, Jun 29, 2015 at 05:47:49PM +0200, Geert Uytterhoeven wrote: > > netconsole itself is optional & modular. I'm not sure making further > > splits is called for, especially given the use cases. > > It could be a hidden option, selected by its users (e.g. netconsole). Hmmm... what do you mean? Thanks.
On Mon, Jun 29, 2015 at 11:49:14AM -0400, Tejun Heo wrote: > On Mon, Jun 29, 2015 at 05:47:49PM +0200, Geert Uytterhoeven wrote: > > > netconsole itself is optional & modular. I'm not sure making further > > > splits is called for, especially given the use cases. > > > > It could be a hidden option, selected by its users (e.g. netconsole). > > Hmmm... what do you mean? config PRINTK_BITS_THAT_NETCONSOLE_NEEDS (no help text or prompt) config NETCONSOLE select PRINTK_BITS_THAT_NETCONSOLE_NEEDS That would ensure that the bits added to printk don't get compiled in unless CONFIG_NETCONSOLE=y. - Josh Triplett -- To unsubscribe from this list: send the line "unsubscribe netdev" in the body of a message to majordomo@vger.kernel.org More majordomo info at http://vger.kernel.org/majordomo-info.html
On Mon, Jun 29, 2015 at 5:49 PM, Tejun Heo <tj@kernel.org> wrote: > On Mon, Jun 29, 2015 at 05:47:49PM +0200, Geert Uytterhoeven wrote: >> > netconsole itself is optional & modular. I'm not sure making further >> > splits is called for, especially given the use cases. >> >> It could be a hidden option, selected by its users (e.g. netconsole). > > Hmmm... what do you mean? init/Kconfig: config PRINTK_EXT_LOG bool drivers/net/Kconfig: config NETCONSOLE tristate "Network console logging support" select PRINTK_EXT_LOG kernel/printk/printk.c: void console_unlock(void) { #ifdef CONFIG_PRINTK_EXT_LOG static char ext_text[CONSOLE_EXT_LOG_MAX]; #endif etc. Gr{oetje,eeting}s, Geert -- Geert Uytterhoeven -- There's lots of Linux beyond ia32 -- geert@linux-m68k.org In personal conversations with technical people, I call myself a hacker. But when I'm talking to journalists I just say "programmer" or something like that. -- Linus Torvalds -- To unsubscribe from this list: send the line "unsubscribe netdev" in the body of a message to majordomo@vger.kernel.org More majordomo info at http://vger.kernel.org/majordomo-info.html
On Mon, Jun 29, 2015 at 06:11:40PM +0200, Geert Uytterhoeven wrote: > On Mon, Jun 29, 2015 at 5:49 PM, Tejun Heo <tj@kernel.org> wrote: > > On Mon, Jun 29, 2015 at 05:47:49PM +0200, Geert Uytterhoeven wrote: > >> > netconsole itself is optional & modular. I'm not sure making further > >> > splits is called for, especially given the use cases. > >> > >> It could be a hidden option, selected by its users (e.g. netconsole). > > > > Hmmm... what do you mean? > > init/Kconfig: > > config PRINTK_EXT_LOG > bool > > drivers/net/Kconfig: > > config NETCONSOLE > tristate "Network console logging support" > select PRINTK_EXT_LOG > > kernel/printk/printk.c: > > void console_unlock(void) > { > #ifdef CONFIG_PRINTK_EXT_LOG > static char ext_text[CONSOLE_EXT_LOG_MAX]; > #endif OIC, hmmm... yeah, I think doing it on-demand would be better but will try to find out which way is better. Thanks!
On Mon, Jun 29, 2015 at 12:13:55PM -0400, Tejun Heo wrote: > On Mon, Jun 29, 2015 at 06:11:40PM +0200, Geert Uytterhoeven wrote: > > On Mon, Jun 29, 2015 at 5:49 PM, Tejun Heo <tj@kernel.org> wrote: > > > On Mon, Jun 29, 2015 at 05:47:49PM +0200, Geert Uytterhoeven wrote: > > >> > netconsole itself is optional & modular. I'm not sure making further > > >> > splits is called for, especially given the use cases. > > >> > > >> It could be a hidden option, selected by its users (e.g. netconsole). > > > > > > Hmmm... what do you mean? > > > > init/Kconfig: > > > > config PRINTK_EXT_LOG > > bool > > > > drivers/net/Kconfig: > > > > config NETCONSOLE > > tristate "Network console logging support" > > select PRINTK_EXT_LOG > > > > kernel/printk/printk.c: > > > > void console_unlock(void) > > { > > #ifdef CONFIG_PRINTK_EXT_LOG > > static char ext_text[CONSOLE_EXT_LOG_MAX]; > > #endif > > OIC, hmmm... yeah, I think doing it on-demand would be better but will > try to find out which way is better. Allocating the buffer dynamically is fine, but in that case the code to do so should ideally be compiled out. Since printk is used by almost *all* kernels, while netconsole is not, it's more critical to avoid allowing printk's size to balloon. - Josh Triplett -- To unsubscribe from this list: send the line "unsubscribe netdev" in the body of a message to majordomo@vger.kernel.org More majordomo info at http://vger.kernel.org/majordomo-info.html
diff --git a/include/linux/console.h b/include/linux/console.h index 9f50fb4..bd19434 100644 --- a/include/linux/console.h +++ b/include/linux/console.h @@ -115,6 +115,7 @@ static inline int con_debug_leave(void) #define CON_BOOT (8) #define CON_ANYTIME (16) /* Safe to call when cpu is offline */ #define CON_BRL (32) /* Used for a braille device */ +#define CON_EXTENDED (64) /* Use the extended output format a la /dev/kmsg */ struct console { char name[16]; diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c index 51ce4f1..9cc2664 100644 --- a/kernel/printk/printk.c +++ b/kernel/printk/printk.c @@ -85,6 +85,18 @@ static struct lockdep_map console_lock_dep_map = { #endif /* + * Number of registered extended console drivers. + * + * If extended consoles are present, in-kernel cont reassembly is disabled + * and each fragment is stored as a separate log entry with proper + * continuation flag so that every emitted message has full metadata. This + * doesn't change the result for regular consoles or /proc/kmsg. For + * /dev/kmsg, as long as the reader concatenates messages according to + * consecutive continuation flags, the end result should be the same too. + */ +static int nr_ext_console_drivers; + +/* * Helper macros to handle lockdep when locking/unlocking console_sem. We use * macros instead of functions so that _RET_IP_ contains useful information. */ @@ -195,7 +207,7 @@ static int console_may_schedule; * need to be changed in the future, when the requirements change. * * /dev/kmsg exports the structured data in the following line format: - * "level,sequnum,timestamp;<message text>\n" + * "<level>,<sequnum>,<timestamp>,<contflag>;<message text>\n" * * The optional key/value pairs are attached as continuation lines starting * with a space character and terminated by a newline. All possible @@ -1417,7 +1429,9 @@ SYSCALL_DEFINE3(syslog, int, type, char __user *, buf, int, len) * log_buf[start] to log_buf[end - 1]. * The console_lock must be held. */ -static void call_console_drivers(int level, const char *text, size_t len) +static void call_console_drivers(int level, + const char *ext_text, size_t ext_len, + const char *text, size_t len) { struct console *con; @@ -1438,7 +1452,10 @@ static void call_console_drivers(int level, const char *text, size_t len) if (!cpu_online(smp_processor_id()) && !(con->flags & CON_ANYTIME)) continue; - con->write(con, text, len); + if (con->flags & CON_EXTENDED) + con->write(con, ext_text, ext_len); + else + con->write(con, text, len); } } @@ -1581,8 +1598,12 @@ static bool cont_add(int facility, int level, const char *text, size_t len) if (cont.len && cont.flushed) return false; - if (cont.len + len > sizeof(cont.buf)) { - /* the line gets too long, split it up in separate records */ + /* + * If ext consoles are present, flush and skip in-kernel + * continuation. See nr_ext_console_drivers definition. Also, if + * the line gets too long, split it up in separate records. + */ + if (nr_ext_console_drivers || cont.len + len > sizeof(cont.buf)) { cont_flush(LOG_CONT); return false; } @@ -1917,9 +1938,19 @@ static struct cont { u8 level; bool flushed:1; } cont; +static char *log_text(const struct printk_log *msg) { return NULL; } +static char *log_dict(const struct printk_log *msg) { return NULL; } static struct printk_log *log_from_idx(u32 idx) { return NULL; } static u32 log_next(u32 idx) { return 0; } -static void call_console_drivers(int level, const char *text, size_t len) {} +static ssize_t msg_print_ext_header(char *buf, size_t size, + struct printk_log *msg, u64 seq, + enum log_flags prev_flags) { return 0; } +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(int level, + const char *ext_text, size_t ext_len, + const char *text, size_t len) {} 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; } @@ -2172,7 +2203,7 @@ static void console_cont_flush(char *text, size_t size) len = cont_print_text(text, size); raw_spin_unlock(&logbuf_lock); stop_critical_timings(); - call_console_drivers(cont.level, text, len); + call_console_drivers(cont.level, NULL, 0, text, len); start_critical_timings(); local_irq_restore(flags); return; @@ -2196,6 +2227,7 @@ out: */ void console_unlock(void) { + static char ext_text[CONSOLE_EXT_LOG_MAX]; static char text[LOG_LINE_MAX + PREFIX_MAX]; static u64 seen_seq; unsigned long flags; @@ -2214,6 +2246,7 @@ void console_unlock(void) again: for (;;) { struct printk_log *msg; + size_t ext_len = 0; size_t len; int level; @@ -2259,13 +2292,22 @@ skip: level = msg->level; len += msg_print_text(msg, console_prev, false, text + len, sizeof(text) - len); + if (nr_ext_console_drivers) { + ext_len = msg_print_ext_header(ext_text, + sizeof(ext_text), + msg, console_seq, console_prev); + ext_len += msg_print_ext_body(ext_text + ext_len, + sizeof(ext_text) - ext_len, + log_dict(msg), msg->dict_len, + log_text(msg), msg->text_len); + } console_idx = log_next(console_idx); console_seq++; console_prev = msg->flags; raw_spin_unlock(&logbuf_lock); stop_critical_timings(); /* don't trace print latency */ - call_console_drivers(level, text, len); + call_console_drivers(level, ext_text, ext_len, text, len); start_critical_timings(); local_irq_restore(flags); } @@ -2521,6 +2563,10 @@ void register_console(struct console *newcon) newcon->next = console_drivers->next; console_drivers->next = newcon; } + + if (newcon->flags & CON_EXTENDED) + nr_ext_console_drivers++; + if (newcon->flags & CON_PRINTBUFFER) { /* * console_unlock(); will print out the buffered messages @@ -2593,6 +2639,9 @@ int unregister_console(struct console *console) } } + if (!res && (console->flags & CON_EXTENDED)) + nr_ext_console_drivers--; + /* * If this isn't the last console and it has CON_CONSDEV set, we * need to set it on the next preferred console.
printk log_buf keeps various metadata for each message including its sequence number and timestamp. The metadata is currently available only through /dev/kmsg and stripped out before passed onto console drivers. We want this metadata to be available to console drivers too so that console consumers can get full information including the metadata and dictionary, which among other things can be used to detect whether messages got lost in transit. This patch implements support for extended console drivers. Consoles can indicate that they want extended messages by setting the new CON_EXTENDED flag and they'll be fed messages formatted the same way as /dev/kmsg. "<level>,<sequnum>,<timestamp>,<contflag>;<message text>\n" If extended consoles exist, in-kernel fragment assembly is disabled. This ensures that all messages emitted to consoles have full metadata including sequence number. The contflag carries enough information to reassemble the fragments from the reader side trivially. Note that this only affects /dev/kmsg. Regular console and /proc/kmsg outputs are not affected by this change. * Extended message formatting for console drivers is enabled iff there are registered extended consoles. * Comment describing /dev/kmsg message format updated to add missing contflag field and help distinguishing variable from verbatim terms. v2: Disable in-kernel cont buffer if extended consoles are present which simplifies things quite a bit. Hinted by Petr. Signed-off-by: Tejun Heo <tj@kernel.org> Cc: Kay Sievers <kay@vrfy.org> Cc: Petr Mladek <pmladek@suse.cz> --- include/linux/console.h | 1 + kernel/printk/printk.c | 65 +++++++++++++++++++++++++++++++++++++++++++------ 2 files changed, 58 insertions(+), 8 deletions(-)