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

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

[Tetsuo Handa]

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.

Details:

  A structure named "struct printk_buffer" is introduced for buffering
  up to LOG_LINE_MAX bytes of printk() output which did not end with '\n'.

  get_printk_buffer() tries to assign a "struct printk_buffer" from
  statically preallocated array. get_printk_buffer() returns NULL if
  all "struct printk_buffer" are in use, but the caller does not need to
  check for NULL.

  put_printk_buffer() flushes and releases the "struct printk_buffer".
  put_printk_buffer() must match corresponding get_printk_buffer() as with
  rcu_read_unlock() must match corresponding rcu_read_lock().

  Three functions buffered_vprintk(), buffered_printk() and
  flush_printk_buffer() are provided for using "struct printk_buffer".
  These are like vfprintf(), fprintf(), fflush() except that these receive
  "struct printk_buffer *" for the first argument.

  buffered_vprintk() and buffered_printk() behave like vprintk() and
  printk() respectively if "struct printk_buffer *" argument is NULL.
  flush_printk_buffer() and put_printk_buffer() become no-op if
  "struct printk_buffer *" argument is NULL. Therefore, the caller of
  get_printk_buffer() does not need to check for NULL.

How to configure this API:

  For those who want to save memory footprint, this API is enabled only
  if CONFIG_PRINTK_LINE_BUFFERED option is selected.

  For those who want to tune the number of statically preallocated
  buffers, CONFIG_PRINTK_NUM_LINE_BUFFERS option is available. The default
  value is 16. Since "struct printk_buffer" makes difference only when
  there are multiple threads concurrently calling printk() which does not
  end with '\n', and this API will fallback to normal printk() when all
  CONFIG_PRINTK_NUM_LINE_BUFFERS buffers are in use, you won't need to
  specify a large number.

  But somebody might forget to call put_printk_buffer(). For those who
  want to know why all CONFIG_PRINTK_NUM_LINE_BUFFERS buffers are in use,
  CONFIG_PRINTK_REPORT_OUT_OF_LINE_BUFFERS option is available.
  This option reports when/where get_printk_buffer() was called and
  put_printk_buffer() is not yet called, up to once per a minute.

How to use this API:

  (1) Call get_printk_buffer() and acquire "struct printk_buffer *".

  (2) Rewrite printk() calls in the following way. The "ptr" is
      "struct printk_buffer *" obtained in step (1).

      printk(fmt, ...)     => buffered_printk(ptr, fmt, ...)
      vprintk(fmt, args)   => buffered_vprintk(ptr, fmt, args)
      pr_emerg(fmt, ...)   => bpr_emerg(ptr, fmt, ...)
      pr_alert(fmt, ...)   => bpr_alert(ptr, fmt, ...)
      pr_crit(fmt, ...)    => bpr_crit(ptr, fmt, ...)
      pr_err(fmt, ...)     => bpr_err(ptr, fmt, ...)
      pr_warning(fmt, ...) => bpr_warning(ptr, fmt, ...)
      pr_warn(fmt, ...)    => bpr_warn(ptr, fmt, ...)
      pr_notice(fmt, ...)  => bpr_notice(ptr, fmt, ...)
      pr_info(fmt, ...)    => bpr_info(ptr, fmt, ...)
      pr_cont(fmt, ...)    => bpr_cont(ptr, fmt, ...)

  (3) Release "struct printk_buffer" by calling put_printk_buffer().

Note that since "struct printk_buffer" buffers only up to one line, there
is no need to rewrite if it is known that the "struct printk_buffer" is
empty and printk() ends with '\n'.

  Good example:

    printk("Hello ");    =>  buf = get_printk_buffer();
    pr_cont("world.\n");     buffered_printk(buf, "Hello ");
                             buffered_printk(buf, "world.\n");
                             put_printk_buffer(buf);

  Pointless example:

    printk("Hello\n");   =>  buf = get_printk_buffer();
    printk("World.\n");      buffered_printk(buf, "Hello\n");
                             buffered_printk(buf, "World.\n");
                             put_printk_buffer(buf);

Note that bpr_devel() and bpr_debug() are not defined. This is
because pr_devel()/pr_debug() should not be followed by pr_cont()
because pr_devel()/pr_debug() are conditionally enabled; output from
pr_devel()/pr_debug() should always end with '\n'.

Signed-off-by: Tetsuo Handa <penguin-kernel@I-love.SAKURA.ne.jp>
---
 include/linux/printk.h |  41 +++++++++
 init/Kconfig           |  31 +++++++
 kernel/printk/printk.c | 239 +++++++++++++++++++++++++++++++++++++++++++++++++
 3 files changed, 311 insertions(+)

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
+
 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__)
 /*
  * 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'.
+
+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.
+
+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.
+
 #
 # 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;
+
+static void reset_holdoff_flag(struct timer_list *timer)
+{
+	buffer_users_report_scheduled = 0;
+}
+static DEFINE_TIMER(buffer_users_holdoff_timer, reset_holdoff_flag);
+
+static void report_buffer_users(struct work_struct *work)
+{
+	long i;
+	unsigned int j;
+
+	/*
+	 * This report is racy. But it does not worth introducing a lock
+	 * dependency.
+	 */
+	pr_info("printk: All line buffers are in use.\n");
+	for (i = 0; i < CONFIG_PRINTK_NUM_LINE_BUFFERS; i++) {
+		if (!test_bit(i, printk_buffers_in_use))
+			continue;
+		pr_info("buffer[%lu] was reserved %lu jiffies ago by\n",
+			i, jiffies - printk_buffers_dump[i].stamp);
+		for (j = 0; j < printk_buffers_dump[i].trace.nr_entries; j++)
+			pr_info("  %pS\n", (void *)
+				printk_buffers_dump[i].entries[j]);
+		cond_resched();
+	}
+	/* Wait for at least 60 seconds before reporting again. */
+	mod_timer(&buffer_users_holdoff_timer, jiffies + 60 * HZ);
+}
+#endif
+
+/**
+ * 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)
+{
+#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))
+			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;
+		printk_buffers_dump[i].trace.skip = 0;
+		save_stack_trace(&printk_buffers_dump[i].trace);
+#endif
+		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);
+#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;
+			} 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);
+	}
+ unbuffered:
+	return vprintk(fmt, args);
+}
+
+/**
+ * buffered_printk - Try to printk() in line buffered mode.
+ *
+ * @ptr:  Pointer to "struct printk_buffer". It can be NULL.
+ * @fmt:  printk() format string, followed by arguments.
+ *
+ * Returns the return value of printk().
+ *
+ * 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_printk(struct printk_buffer *ptr, const char *fmt, ...)
+{
+	va_list args;
+	int r;
+
+	va_start(args, fmt);
+	r = buffered_vprintk(ptr, fmt, args);
+	va_end(args);
+	return r;
+}
+EXPORT_SYMBOL(buffered_printk);
+
+/**
+ * flush_printk_buffer - Flush incomplete line in printk_buffer.
+ *
+ * @ptr: Pointer to "struct printk_buffer". It can be NULL.
+ *
+ * Returns nothing.
+ *
+ * Flush if @ptr contains partial data. But usually there is no need to call
+ * this function because @ptr is flushed by put_printk_buffer().
+ */
+void flush_printk_buffer(struct printk_buffer *ptr)
+{
+	if (!ptr || !ptr->used)
+		return;
+	/* buffered_vprintk() keeps 0 <= ptr->used < sizeof(ptr->buf) true. */
+	ptr->buf[ptr->used] = '\0';
+	printk("%s", ptr->buf);
+	ptr->used = 0;
+}
+EXPORT_SYMBOL(flush_printk_buffer);
+
+/**
+ * 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;
+	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);
+}
+EXPORT_SYMBOL(put_printk_buffer);
+
+#endif
+
 int vprintk_default(const char *fmt, va_list args)
 {
 	int r;
-- 
1.8.3.1

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

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

[Tetsuo Handa]

Petr Mladek wrote:
> On Sat 2018-10-13 13:39:40, Tetsuo Handa wrote:
> > +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.

We need this dummy version anyway because CONFIG_PRINTK_LINE_BUFFERED
depends on CONFIG_PRINTK=y.

Even with CONFIG_PRINTK=y, until the cont buffer is removed in future, some
embedded users might want to save memory footprint for printk_buffers.

> > @@ -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.

But embedded users might have very low traffic where buffering is not useful.



> > +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).

I think that we don't need kernel command line parameters for tuning this number.
But having a kernel config option will help encouraging people to try this API,
for there might be some users who can't try this API without a lot of printk
buffers (syzbot-like systems or huge systems which generate huge traffic).



> > +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.

I didn't get what "the configurable debug functionality" means. You mean
enable/disable via debugfs entry? We can later hear from users whether we
want to allow enable/disable at kernel boot command line and/or debugfs entry.



> > +/**
> > + * 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;

After this API is accepted, I will try thinking how we can inject caller
information when printk() is called. That's the origin of this thread.

To do that, we need to make sure that one line is stored (with caller
information) whenever printk() is called, which means that we can't count on
implicit line buffering provided for printk_safe() or printk_nmi() context.

Therefore, this buffering makes sense even if the caller is known to be
already printk_safe() or printk_nmi() context.



> > +#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().

Really? I think this is accurate enough.

get_printk_buffer() tolerates race window, as long as get_printk_buffer()
does not return same buffer to multiple callers. For example, when
get_printk_buffer() checks for printk_buffers[1] after
checking printk_buffers[0] is in use, put_printk_buffer() might set
printk_buffers[0] as free. get_printk_buffer() will return NULL if
printk_buffers[0] was the only buffer which became available in this
race window, but it is not a critical problem.

Likewise, put_printk_buffer() tolerates race window, as long as writing
to printk_buffer[i] completes before printk_buffer[i] becomes visible to
get_printk_buffer().

And since test_and_set_bit() and clear_bit() are atomic, I think that
there is no possibility that

  (1) get_printk_buffer() from CPU0 finds that
      test_bit(0, printk_buffers_in_use) is false.

  (2) get_printk_buffer() from CPU1 finds that
      test_bit(0, printk_buffers_in_use) is false.

  (3) get_printk_buffer() from CPU0 finds that
      test_and_set_bit(0, printk_buffers_in_use) is false.

  (4) get_printk_buffer() from CPU1 finds that
      test_and_set_bit(0, printk_buffers_in_use) is true.

  (5) put_printk_buffer() from CPU0 calls
      clear_bit(0, printk_buffers_in_use).

  (6) get_printk_buffer() from CPU1 leaves
      test_bit(0, printk_buffers_in_use) true due to (4),
      which results in leaking printk_buffers[0].

happens.



> > +#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.

These reports will have at least 60 seconds interval.

> 
> 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

I think we can know "when CONFIG_DEBUG_BUFFERED_PRINTK=y makes sense"
when partial lines are printed frequent enough to suspect permanently
out of buffers.



> > +/**
> > + * 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;
> 

Don't we need to care about vprintk(fmt, args) fallback path? That is,

   const int fmt_offset = (printk_get_level(fmt) == 'c') ? 2 : 0;
   r = vsnprintf(text, sizeof(ptr->buf) - pos, fmt + fmt_offset, tmp_args);

for now?

But hmm, unconditionally triminng KERN_CONT is OK as long as ptr != NULL because
"we have to use vprintk(fmt, args) fallback path when ptr != NULL" implies that
"the output is too long to store into global buffer (if not in safe/nmi context)
or per-CPU buffers (if in safe/nmi context) from vprintk(), and thus KERN_CONT
won't work as expected after all" ?

> > +			} 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.

OK.

		if (i || flush_printk_buffer(ptr) == 0)
			break;

will work.

> 
> 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;

Doesn't it disable possible optimization by the compiler (e.g. unroll
the for() loop if the compiler thinks it worth doing)? Since this "ptr"
is dedicated to the caller, there is no possibility of executing
"goto try_again" twice in one buffered_vprintk() call.



> > +	}
> > + 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.

The reason I changed to split printk_buffers_in_use out of printk_buffer
is that some architectures do not support cmpxchg() on "bool", and thus
we need to assign "int" for in_use flag. If that is not a problem (even
if we allow use of dynamically allocated or on-stack buffers in future),
I can bring in_use flag back to printk_buffer. Which choice do you prefer?

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

[Petr Mladek]

On Wed 2018-10-17 18:54:52, Tetsuo Handa wrote:
> Petr Mladek wrote:
> > On Sat 2018-10-13 13:39:40, Tetsuo Handa wrote:
> > > +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.
> 
> We need this dummy version anyway because CONFIG_PRINTK_LINE_BUFFERED
> depends on CONFIG_PRINTK=y.

Good point.

> Even with CONFIG_PRINTK=y, until the cont buffer is removed in future, some
> embedded users might want to save memory footprint for printk_buffers.

printk_safe and printk_nmi have big memory foot print as well and
nobody has complained yet. Let's keep it easy in the beginning.


> > > @@ -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.
> 
> But embedded users might have very low traffic where buffering is not useful.

I prefer to keep it simple. Embedded people will speak if it matters.


> > > +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).
> 
> I think that we don't need kernel command line parameters for tuning this number.
> But having a kernel config option will help encouraging people to try this API,
> for there might be some users who can't try this API without a lot of printk
> buffers (syzbot-like systems or huge systems which generate huge traffic).

We need to get it working on all systems. I really would like to get
rid of the current cont buffer.


> > > +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.
> 
> I didn't get what "the configurable debug functionality" means. You mean
> enable/disable via debugfs entry? We can later hear from users whether we
> want to allow enable/disable at kernel boot command line and/or debugfs entry.

All new functions are called *printk_buffered() or pbf_*(). It might help
if the configure option would use PRINTK_BUFFERED as well. In addition,
I have troubles to parse it. It might mean also buffer overflow...

Now, this option will be used to debug problems with buffered_printk().
It currently prints some messages when we are out of buffers. But we
might need more. Nobody wants zillions of configure options. One
should be enough.

DEBUG_SOME_FEATURE is a commonly used pattern to enable extra
checks and reports for debugging a feature. I believe that
CONFIG_DEBUG_BUFFERED_PRINTK is more self-explaining.


> > > +/**
> > > + * 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;
> 
> After this API is accepted, I will try thinking how we can inject caller
> information when printk() is called. That's the origin of this thread.
> 
> To do that, we need to make sure that one line is stored (with caller
> information) whenever printk() is called, which means that we can't count on
> implicit line buffering provided for printk_safe() or printk_nmi() context.

Single time stamp is enough for the entire line. And the time
when the line is flushed is enough.

Are there any other information that would need to get stored, please?


> > > +#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().
> 
> Really? I think this is accurate enough.
> 
> get_printk_buffer() tolerates race window, as long as get_printk_buffer()
> does not return same buffer to multiple callers. For example, when
> get_printk_buffer() checks for printk_buffers[1] after
> checking printk_buffers[0] is in use, put_printk_buffer() might set
> printk_buffers[0] as free. get_printk_buffer() will return NULL if
> printk_buffers[0] was the only buffer which became available in this
> race window, but it is not a critical problem.

No, it is not enough. We need a barrier that will make sure that
the previous user read (copied) the entire buffer and that we will
read the right value in ptr->used here. In fact, we need a full barrier.

Also all barriers work only in pairs. You could sometimes omit
one if it is already included in some other call. But this is
not the case here.

I am personally very happy for all predefined _lock()/_unlock()
operations. And I do not try to be more clever that Paul E. McKenney.
There is a high chance that I would be wrong ;-)


> > > +#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.
> 
> These reports will have at least 60 seconds interval.

The report is too long. There is a high chance that there will be none
or many occurrences. People will surely see the one instance and would
want to get rid of it (report/send a fix). This is what we want.

On the other hand, this feature is not important enough to mess
the log completely.

The only-once approach is trivial and is a good start. We could always
extend it when needed.


> > 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
> 
> I think we can know "when CONFIG_DEBUG_BUFFERED_PRINTK=y makes sense"
> when partial lines are printed frequent enough to suspect permanently
> out of buffers.

People will not notice when the current cont buffer is used as
a fallback. We need to know when buffered_printk() fails
to be able to get rid of the fallback.

       printk_once("Out of printk buffers. Please, consider enabling with CONFIG_DEBUG_BUFFERED_PRINTK\n");

The description of CONFIG_DEBUG_BUFFERED_PRINTK might then contains
tips how to deal with this warning. There might be missing
put_printk_buffer() call. More buffers are needed. Or...


> > > +/**
> > > + * 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;
> > 
> 
> Don't we need to care about vprintk(fmt, args) fallback path? That is,
>
>    const int fmt_offset = (printk_get_level(fmt) == 'c') ? 2 : 0;
>    r = vsnprintf(text, sizeof(ptr->buf) - pos, fmt + fmt_offset, tmp_args);
> 
> for now?
> 
> But hmm, unconditionally triminng KERN_CONT is OK as long as ptr != NULL because
> "we have to use vprintk(fmt, args) fallback path when ptr != NULL" implies that
> "the output is too long to store into global buffer (if not in safe/nmi context)
> or per-CPU buffers (if in safe/nmi context) from vprintk(), and thus KERN_CONT
> won't work as expected after all" ?

Good point, we need to use the original pointer in the fallback.
Anyway, we still could trim KERN_CONT for the internal vsnprintf()
and get rid of the memmove().


> > > +			} 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);

One more idea. We do not need to printk more lines separately. Even
the normal printk() does not store the lines separately.

I would just flush the entire buffer when we find '\n' and get rid even
of this 2nd memmove(). Reasonable code will not use '\n' in the middle
of a continuous line. Unreasonable printk() will get what it deserves.


> > > +			}
> > > +			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.
> 
> OK.
> 
> 		if (i || flush_printk_buffer(ptr) == 0)
> 			break;
> 
> will work.
> 
> > 
> > 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;
> 
> Doesn't it disable possible optimization by the compiler (e.g. unroll
> the for() loop if the compiler thinks it worth doing)? Since this "ptr"
> is dedicated to the caller, there is no possibility of executing
> "goto try_again" twice in one buffered_vprintk() call.

This is a slow path. It does not need to be super optimal. The code
readability is more important here. And the cycle hides the logic
unnecessarily.


> > > +	}
> > > + 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.
> 
> The reason I changed to split printk_buffers_in_use out of printk_buffer
> is that some architectures do not support cmpxchg() on "bool", and thus
> we need to assign "int" for in_use flag. If that is not a problem (even
> if we allow use of dynamically allocated or on-stack buffers in future),
> I can bring in_use flag back to printk_buffer. Which choice do you prefer?


I do not have a strong opinion. We could use u8 instead of the
bool to get over the cmpxchg() limitation. But the bitmap looks
good as well. It even makes sense because it is related to both
printk_buffers and printk_buffers_dump arrays.

Anyway, please add a warning when the array is out of bounds.
I would help us to catch eventual bugs. We could always remove
it when we add support for on-stack buffers. Or it is possible that
we would want to distinguish them another way.

Best Regards,
Petr