Messages in this thread | | | Date | Tue, 16 Oct 2018 16:07:44 +0200 | From | Petr Mladek <> | Subject | Re: [PATCH v4] printk: Add line-buffered printk() API. |
| |
On Sat 2018-10-13 13:39:40, Tetsuo Handa wrote: > Sometimes we want to print a whole line without being disturbed by > concurrent printk() from interrupts and/or other threads, for printk() > which does not end with '\n' can be disturbed. > > Mixed printk() output makes it hard to interpret. Assuming that we will go > to a direction that we allow prefixing context identifier to each line of > printk() output (so that we can group multiple lines into one block when > parsing), this patch introduces API for line-buffered printk() output > (so that we can make sure that printk() ends with '\n'). > > Since functions introduced by this patch are merely wrapping > printk()/vprintk() calls in order to minimize possibility of using > "struct cont", it is safe to replace printk()/vprintk() with this API.
> diff --git a/include/linux/printk.h b/include/linux/printk.h > index cf3eccf..f93d9c8 100644 > --- a/include/linux/printk.h > +++ b/include/linux/printk.h > @@ -286,6 +286,30 @@ static inline void printk_safe_flush_on_panic(void) > } > #endif > > +struct printk_buffer; > +#if defined(CONFIG_PRINTK_LINE_BUFFERED) > +struct printk_buffer *get_printk_buffer(void); > +void flush_printk_buffer(struct printk_buffer *ptr); > +__printf(2, 3) > +int buffered_printk(struct printk_buffer *ptr, const char *fmt, ...); > +__printf(2, 0) > +int buffered_vprintk(struct printk_buffer *ptr, const char *fmt, va_list args); > +void put_printk_buffer(struct printk_buffer *ptr); > +#else > +static inline struct printk_buffer *get_printk_buffer(void) > +{ > + return NULL; > +} > +static inline void flush_printk_buffer(struct printk_buffer *ptr) > +{ > +} > +#define buffered_printk(ptr, fmt, ...) printk(fmt, ##__VA_ARGS__) > +#define buffered_vprintk(ptr, fmt, args) vprintk(fmt, args) > +static inline void put_printk_buffer(struct printk_buffer *ptr) > +{ > +} > +#endif
Is there any reason to allow to disable this feature? The current cont buffer is always enabled.
> extern int kptr_restrict; > > #ifndef pr_fmt > @@ -300,19 +324,34 @@ static inline void printk_safe_flush_on_panic(void) > */ > #define pr_emerg(fmt, ...) \ > printk(KERN_EMERG pr_fmt(fmt), ##__VA_ARGS__) > +#define bpr_emerg(ptr, fmt, ...) \ > + buffered_printk(ptr, KERN_EMERG pr_fmt(fmt), ##__VA_ARGS__) > #define pr_alert(fmt, ...) \ > printk(KERN_ALERT pr_fmt(fmt), ##__VA_ARGS__) > +#define bpr_alert(ptr, fmt, ...) \ > + buffered_printk(ptr, KERN_ALERT pr_fmt(fmt), ##__VA_ARGS__) > #define pr_crit(fmt, ...) \ > printk(KERN_CRIT pr_fmt(fmt), ##__VA_ARGS__) > +#define bpr_crit(ptr, fmt, ...) \ > + buffered_printk(ptr, KERN_CRIT pr_fmt(fmt), ##__VA_ARGS__) > #define pr_err(fmt, ...) \ > printk(KERN_ERR pr_fmt(fmt), ##__VA_ARGS__) > +#define bpr_err(ptr, fmt, ...) \ > + buffered_printk(ptr, KERN_ERR pr_fmt(fmt), ##__VA_ARGS__) > #define pr_warning(fmt, ...) \ > printk(KERN_WARNING pr_fmt(fmt), ##__VA_ARGS__) > +#define bpr_warning(ptr, fmt, ...) \ > + buffered_printk(ptr, KERN_WARNING pr_fmt(fmt), ##__VA_ARGS__) > #define pr_warn pr_warning > +#define bpr_warn bpr_warning > #define pr_notice(fmt, ...) \ > printk(KERN_NOTICE pr_fmt(fmt), ##__VA_ARGS__) > +#define bpr_notice(ptr, fmt, ...) \ > + buffered_printk(ptr, KERN_NOTICE pr_fmt(fmt), ##__VA_ARGS__) > #define pr_info(fmt, ...) \ > printk(KERN_INFO pr_fmt(fmt), ##__VA_ARGS__) > +#define bpr_info(ptr, fmt, ...) \ > + buffered_printk(ptr, KERN_INFO pr_fmt(fmt), ##__VA_ARGS__)
Nitpick: Please, put bpr_* definitions into a separate paragraph. The above is very hard to read.
> /* > * Like KERN_CONT, pr_cont() should only be used when continuing > * a line with no newline ('\n') enclosed. Otherwise it defaults > @@ -320,6 +359,8 @@ static inline void printk_safe_flush_on_panic(void) > */ > #define pr_cont(fmt, ...) \ > printk(KERN_CONT fmt, ##__VA_ARGS__) > +#define bpr_cont(ptr, fmt, ...) \ > + buffered_printk(ptr, KERN_CONT fmt, ##__VA_ARGS__) > > /* pr_devel() should produce zero code unless DEBUG is defined */ > #ifdef DEBUG > diff --git a/init/Kconfig b/init/Kconfig > index 1e234e2..1fb01de 100644 > --- a/init/Kconfig > +++ b/init/Kconfig > @@ -604,6 +604,37 @@ config PRINTK_SAFE_LOG_BUF_SHIFT > 13 => 8 KB for each CPU > 12 => 4 KB for each CPU > > +config PRINTK_LINE_BUFFERED > + bool "Allow line buffered printk()" > + default y > + depends on PRINTK > + help > + The line buffered printk() tries to buffer printk() output up to '\n' > + so that incomplete lines won't be mixed when there are multiple > + threads concurrently calling printk() which does not end with '\n'.
I would prefer to always enable it.
> +config PRINTK_NUM_LINE_BUFFERS > + int "Number of buffers for line buffered printk()" > + range 1 4096 > + default 16 > + depends on PRINTK_LINE_BUFFERED > + help > + Specify the number of statically preallocated "struct printk_buffer" > + for line buffered printk(). You don't need to specify a large number > + here because "struct printk_buffer" makes difference only when there > + are multiple threads concurrently calling printk() which does not end > + with '\n', and line buffered printk() will fallback to normal > + printk() when out of statically preallocated "struct printk_buffer" > + happened.
I would prefer to start with a hard-coded number. There is a sane fallback. We need to motivate people to send feedback so that we could tune it and eventually remove the fallback (current cont buffer code).
> +config PRINTK_REPORT_OUT_OF_LINE_BUFFERS > + bool "Report out of buffers for line buffered printk()" > + default n > + depends on PRINTK_LINE_BUFFERED && STACKTRACE > + help > + Select this if you want to know who is using statically preallocated > + "struct printk_buffer" when out of "struct printk_buffer" happened. > +
I like this approach with the configurable debug functionality. It is safe and straightforward.
Just please, move it into a separate patch. It would help a lot with review and discussion.
Nitpick: I suggest to make it a bit shorter, e.g. DEBUG_BUFFERED_PRINTK.
> # > # Architectures with an unreliable sched_clock() should select this: > # > diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c > index 9bf5404..afc8bed 100644 > --- a/kernel/printk/printk.c > +++ b/kernel/printk/printk.c > @@ -1949,6 +1949,245 @@ asmlinkage int printk_emit(int facility, int level, > } > EXPORT_SYMBOL(printk_emit); > > +#ifdef CONFIG_PRINTK_LINE_BUFFERED > +/* > + * A structure for line-buffered printk() output. > + */ > +static struct printk_buffer { > + unsigned short int used; /* Valid bytes in buf[]. */ > + char buf[LOG_LINE_MAX]; > +} printk_buffers[CONFIG_PRINTK_NUM_LINE_BUFFERS] __aligned(1024); > +static DECLARE_BITMAP(printk_buffers_in_use, CONFIG_PRINTK_NUM_LINE_BUFFERS); > + > + > +#ifdef CONFIG_PRINTK_REPORT_OUT_OF_LINE_BUFFERS > +static struct { > + unsigned long stamp; > + struct stack_trace trace; > + unsigned long entries[20]; > +} printk_buffers_dump[CONFIG_PRINTK_NUM_LINE_BUFFERS]; > +static int buffer_users_report_scheduled;
[...] > +/** > + * get_printk_buffer - Try to get printk_buffer. > + * > + * Returns pointer to "struct printk_buffer" on success, NULL otherwise. > + * > + * If this function returned "struct printk_buffer", the caller is responsible > + * for passing it to put_printk_buffer() so that "struct printk_buffer" can be > + * reused in the future. > + * > + * Even if this function returned NULL, the caller does not need to check for > + * NULL, for passing NULL to buffered_printk() simply acts like normal printk() > + * and passing NULL to flush_printk_buffer()/put_printk_buffer() is a no-op. > + */ > +struct printk_buffer *get_printk_buffer(void) > +{
It does not make much sense to use the buffered printk in context where printk_safe() or printk_nmi() is used. I suggest to define something like:
static inline bool in_printk_safe_buffered_context(void) { int this_printk_context = this_cpu_read(printk_context);
if (this_printk_context && PRINTK_NMI_DIRECT_CONTEXT_MASK) return false;
if (this_printk_context && (PRINTK_SAFE_CONTEXT_MASH || PRINTK_NMI_CONTEXT_MASK)) return true;
return true;
and do
/* * Messages are already concatenated when temporary * stored into the safe per-CPU buffers. */ if (in_printk_safe_buffered_context()) return NULL;
> +#ifdef CONFIG_PRINTK_REPORT_OUT_OF_LINE_BUFFERS > + static DECLARE_WORK(work, report_buffer_users); > +#endif > + long i; > + > + for (i = 0; i < CONFIG_PRINTK_NUM_LINE_BUFFERS; i++) { > + if (test_bit(i, printk_buffers_in_use) || > + test_and_set_bit(i, printk_buffers_in_use))
I would use test_and_set_bit_lock() to make it more likely that the barriers are right. Otherwise, there is missing the complementary barrier with clear_bit() in put_printk_buffer().
> + continue; > + printk_buffers[i].used = 0; > +#ifdef CONFIG_PRINTK_REPORT_OUT_OF_LINE_BUFFERS > + printk_buffers_dump[i].stamp = jiffies; > + printk_buffers_dump[i].trace.nr_entries = 0; > + printk_buffers_dump[i].trace.entries = > + printk_buffers_dump[i].entries; > + printk_buffers_dump[i].trace.max_entries = 20;
#define PRINTK_BUFFERS_MAX_TRACE_ENTRIES 20
> + printk_buffers_dump[i].trace.skip = 0; > + save_stack_trace(&printk_buffers_dump[i].trace); > +#endif
Please, put this into a helper function to avoid bloating get_printk_buffer().
> + return &printk_buffers[i]; > + }
> +#ifdef CONFIG_PRINTK_REPORT_OUT_OF_LINE_BUFFERS > + /* > + * Oops, out of "struct printk_buffer" happened. Fallback to normal > + * printk(). You might notice it by partial lines being printed. > + * > + * If you think that it might be due to missing put_printk_buffer() > + * calls, you can enable CONFIG_PRINTK_REPORT_OUT_OF_LINE_BUFFERS. > + * Then, who is using the buffers will be reported (from workqueue > + * context because reporting CONFIG_PRINTK_NUM_LINE_BUFFERS entries > + * from atomic context might be too slow). If it does not look like > + * missing put_printk_buffer() calls, you might want to increase > + * CONFIG_PRINTK_NUM_LINE_BUFFERS. > + * > + * But if it turns out that allocating "struct printk_buffer" on stack > + * or in .bss section or from kzalloc() is more suitable than tuning > + * CONFIG_PRINTK_NUM_LINE_BUFFERS, we can update to do so. > + */ > + if (!in_nmi() && !cmpxchg(&buffer_users_report_scheduled, 0, 1)) > + queue_work(system_unbound_wq, &work);
We should limit the number of this reports especially when the buffers leaked and are never released again. I would either limit the total count of these reports or I would allow scheduling only when any get_printk_buffer() succeeded in the meantime.
Also we should know when the debugging makes sense. Therefore, we should write something even when the debugging is off. Something like:
#else printk_once("Out of printk buffers. Please, consider enabling with CONFIG_DEBUG_BUFFERED_PRINTK\n"); #endif
> + return NULL; > +} > +EXPORT_SYMBOL(get_printk_buffer); > + > +/** > + * buffered_vprintk - Try to vprintk() in line buffered mode. > + * > + * @ptr: Pointer to "struct printk_buffer". It can be NULL. > + * @fmt: printk() format string. > + * @args: va_list structure. > + * > + * Returns the return value of vprintk(). > + * > + * Try to store to @ptr first. If it fails, flush @ptr and then try to store to > + * @ptr again. If it still fails, use unbuffered printing. > + */ > +int buffered_vprintk(struct printk_buffer *ptr, const char *fmt, va_list args) > +{ > + va_list tmp_args; > + unsigned short int i; > + int r; > + > + if (!ptr) > + goto unbuffered; > + for (i = 0; i < 2; i++) {
> + unsigned int pos = ptr->used; > + char *text = ptr->buf + pos; > + > + va_copy(tmp_args, args); > + r = vsnprintf(text, sizeof(ptr->buf) - pos, fmt, tmp_args); > + va_end(tmp_args); > + if (r + pos < sizeof(ptr->buf)) { > + /* > + * Eliminate KERN_CONT at this point because we can > + * concatenate incomplete lines inside printk_buffer. > + */ > + if (r >= 2 && printk_get_level(text) == 'c') { > + memmove(text, text + 2, r - 2); > + ptr->used += r - 2;
I believe that KERN_CONT is always passed via @fmt parameter. Therefore we could skip it already in fmt and avoid this memmove. Also note that printk_get_level() is safe even for empty string. The following should work:
if (printk_get_level(fmt) == 'c') fmt += 2;
> + } else { > + ptr->used += r; > + } > + /* Flush already completed lines if any. */ > + while (1) { > + char *cp = memchr(ptr->buf, '\n', ptr->used); > + > + if (!cp) > + break; > + *cp = '\0'; > + printk("%s\n", ptr->buf); > + i = cp - ptr->buf + 1; > + ptr->used -= i; > + memmove(ptr->buf, ptr->buf + i, ptr->used); > + } > + return r; > + } > + if (i) > + break; > + flush_printk_buffer(ptr);
It makes sense to repeat the cycle only when something was flushed. I would would modify flush_printk_buffer() to return the number of flushed characters.
Also it might be easier to read with goto, I mean to use:
try_again: instead of for (i = 0; i < 2; i++) {
and then
if (flush_printk_buffer(ptr)) goto try_again;
> + } > + unbuffered: > + return vprintk(fmt, args); > +} > + > + > +/** > + * put_printk_buffer - Release printk_buffer. > + * > + * @ptr: Pointer to "struct printk_buffer". It can be NULL. > + * > + * Returns nothing. > + * > + * Flush and release @ptr. > + */ > +void put_printk_buffer(struct printk_buffer *ptr) > +{ > + long i = ptr - printk_buffers; > + > + if (!ptr || i < 0 || i >= CONFIG_PRINTK_NUM_LINE_BUFFERS) > + return;
It would deserve a warning when i is out of bounds.
> + if (ptr->used) > + flush_printk_buffer(ptr); > + /* Make sure in_use flag is cleared after setting ptr->used = 0. */ > + wmb(); > + clear_bit(i, printk_buffers_in_use);
I would replace this with clear_bit_lock(). It would do the barrier correctly.
In each case, the comment in arch/x86/include/asm/bitops.h above clear_bit() talks about smp_mb__before_atomic() and/or smp_mb__after_atomic().
Finally, I would prefer to put the buffered_printk code into a separate source file, e.g. kernel/printk/buffered_printk.c.
Best Regards, Petr
| |