Re: [PATCH v4] printk: Add line-buffered printk() API.

[Petr Mladek]

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