[PATCH next v3 0/3] printk: remove logbuf_lock protection of ringbuffer

[PATCH next v3 0/3] printk: remove logbuf_lock protection of ringbuffer

[John Ogness]

Hello,

Here is a v3 of the series to remove logbuf_lock. v2 is
here[0]. Rather than completely removing logbuf_lock, this
version only removes logbuf_lock usage protecting the
ringbuffer. I have tried to keep the changes minimal so that
we can feel comfortable for the upcoming 5.11 merge window.

Although small, this series is significant because it allows
printk callers direct lockless access to the ringbuffer and
it replaces the use of a temporary static sprint buffer with
sprint'ing directly to the reserved ringbuffer data block.

The other changes from v2 (recursion limiting, introduction
of syslog_lock, using clear_seq as seqcount_latch, and full
removal of logbuf_lock) will be included in a later series,
which may or may not make the 5.11 merge window.

This series is based on next-20201207.

John Ogness

[0] https://lkml.kernel.org/r/20201201205341.3871-1-john.ogness@linutronix.de

John Ogness (3):
  printk: inline log_output(),log_store() in vprintk_store()
  printk: define CONSOLE_LOG_MAX in printk.h
  printk: remove logbuf_lock protection for ringbuffer

 include/linux/printk.h      |   1 +
 kernel/printk/printk.c      | 248 +++++++++++++++++++++---------------
 kernel/printk/printk_safe.c |  18 +--
 3 files changed, 149 insertions(+), 118 deletions(-)

-- 
2.20.1

[PATCH next v3 1/3] printk: inline log_output(),log_store() in vprintk_store()

[John Ogness]

In preparation for removing logbuf_lock, inline log_output()
and log_store() into vprintk_store(). This will simplify dealing
with the various code branches and fallbacks that are possible.

Signed-off-by: John Ogness <john.ogness@linutronix.de>
Reviewed-by: Petr Mladek <pmladek@suse.com>
Reviewed-by: Sergey Senozhatsky <sergey.senozhatsky@gmail.com>
---
 kernel/printk/printk.c | 145 +++++++++++++++++++----------------------
 1 file changed, 67 insertions(+), 78 deletions(-)

diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
index f279d4fbd9dd..bf5fd2be3a05 100644
--- a/kernel/printk/printk.c
+++ b/kernel/printk/printk.c
@@ -491,52 +491,6 @@ static void truncate_msg(u16 *text_len, u16 *trunc_msg_len)
 		*trunc_msg_len = 0;
 }
 
-/* insert record into the buffer, discard old ones, update heads */
-static int log_store(u32 caller_id, int facility, int level,
-		     enum log_flags flags, u64 ts_nsec,
-		     const struct dev_printk_info *dev_info,
-		     const char *text, u16 text_len)
-{
-	struct prb_reserved_entry e;
-	struct printk_record r;
-	u16 trunc_msg_len = 0;
-
-	prb_rec_init_wr(&r, text_len);
-
-	if (!prb_reserve(&e, prb, &r)) {
-		/* truncate the message if it is too long for empty buffer */
-		truncate_msg(&text_len, &trunc_msg_len);
-		prb_rec_init_wr(&r, text_len + trunc_msg_len);
-		/* survive when the log buffer is too small for trunc_msg */
-		if (!prb_reserve(&e, prb, &r))
-			return 0;
-	}
-
-	/* fill message */
-	memcpy(&r.text_buf[0], text, text_len);
-	if (trunc_msg_len)
-		memcpy(&r.text_buf[text_len], trunc_msg, trunc_msg_len);
-	r.info->text_len = text_len + trunc_msg_len;
-	r.info->facility = facility;
-	r.info->level = level & 7;
-	r.info->flags = flags & 0x1f;
-	if (ts_nsec > 0)
-		r.info->ts_nsec = ts_nsec;
-	else
-		r.info->ts_nsec = local_clock();
-	r.info->caller_id = caller_id;
-	if (dev_info)
-		memcpy(&r.info->dev_info, dev_info, sizeof(r.info->dev_info));
-
-	/* A message without a trailing newline can be continued. */
-	if (!(flags & LOG_NEWLINE))
-		prb_commit(&e);
-	else
-		prb_final_commit(&e);
-
-	return (text_len + trunc_msg_len);
-}
-
 int dmesg_restrict = IS_ENABLED(CONFIG_SECURITY_DMESG_RESTRICT);
 
 static int syslog_action_restricted(int type)
@@ -1907,44 +1861,28 @@ static inline u32 printk_caller_id(void)
 		0x80000000 + raw_smp_processor_id();
 }
 
-static size_t log_output(int facility, int level, enum log_flags lflags,
-			 const struct dev_printk_info *dev_info,
-			 char *text, size_t text_len)
-{
-	const u32 caller_id = printk_caller_id();
-
-	if (lflags & LOG_CONT) {
-		struct prb_reserved_entry e;
-		struct printk_record r;
-
-		prb_rec_init_wr(&r, text_len);
-		if (prb_reserve_in_last(&e, prb, &r, caller_id, LOG_LINE_MAX)) {
-			memcpy(&r.text_buf[r.info->text_len], text, text_len);
-			r.info->text_len += text_len;
-			if (lflags & LOG_NEWLINE) {
-				r.info->flags |= LOG_NEWLINE;
-				prb_final_commit(&e);
-			} else {
-				prb_commit(&e);
-			}
-			return text_len;
-		}
-	}
-
-	/* Store it in the record log */
-	return log_store(caller_id, facility, level, lflags, 0,
-			 dev_info, text, text_len);
-}
-
 /* Must be called under logbuf_lock. */
 int vprintk_store(int facility, int level,
 		  const struct dev_printk_info *dev_info,
 		  const char *fmt, va_list args)
 {
+	const u32 caller_id = printk_caller_id();
 	static char textbuf[LOG_LINE_MAX];
-	char *text = textbuf;
-	size_t text_len;
+	struct prb_reserved_entry e;
 	enum log_flags lflags = 0;
+	struct printk_record r;
+	u16 trunc_msg_len = 0;
+	char *text = textbuf;
+	u16 text_len;
+	u64 ts_nsec;
+
+	/*
+	 * Since the duration of printk() can vary depending on the message
+	 * and state of the ringbuffer, grab the timestamp now so that it is
+	 * close to the call of printk(). This provides a more deterministic
+	 * timestamp with respect to the caller.
+	 */
+	ts_nsec = local_clock();
 
 	/*
 	 * The printf needs to come first; we need the syslog
@@ -1983,7 +1921,58 @@ int vprintk_store(int facility, int level,
 	if (dev_info)
 		lflags |= LOG_NEWLINE;
 
-	return log_output(facility, level, lflags, dev_info, text, text_len);
+	if (lflags & LOG_CONT) {
+		prb_rec_init_wr(&r, text_len);
+		if (prb_reserve_in_last(&e, prb, &r, caller_id, LOG_LINE_MAX)) {
+			memcpy(&r.text_buf[r.info->text_len], text, text_len);
+			r.info->text_len += text_len;
+
+			if (lflags & LOG_NEWLINE) {
+				r.info->flags |= LOG_NEWLINE;
+				prb_final_commit(&e);
+			} else {
+				prb_commit(&e);
+			}
+
+			return text_len;
+		}
+	}
+
+	/*
+	 * Explicitly initialize the record before every prb_reserve() call.
+	 * prb_reserve_in_last() and prb_reserve() purposely invalidate the
+	 * structure when they fail.
+	 */
+	prb_rec_init_wr(&r, text_len);
+	if (!prb_reserve(&e, prb, &r)) {
+		/* truncate the message if it is too long for empty buffer */
+		truncate_msg(&text_len, &trunc_msg_len);
+
+		prb_rec_init_wr(&r, text_len + trunc_msg_len);
+		if (!prb_reserve(&e, prb, &r))
+			return 0;
+	}
+
+	/* fill message */
+	memcpy(&r.text_buf[0], text, text_len);
+	if (trunc_msg_len)
+		memcpy(&r.text_buf[text_len], trunc_msg, trunc_msg_len);
+	r.info->text_len = text_len + trunc_msg_len;
+	r.info->facility = facility;
+	r.info->level = level & 7;
+	r.info->flags = lflags & 0x1f;
+	r.info->ts_nsec = ts_nsec;
+	r.info->caller_id = caller_id;
+	if (dev_info)
+		memcpy(&r.info->dev_info, dev_info, sizeof(r.info->dev_info));
+
+	/* A message without a trailing newline can be continued. */
+	if (!(lflags & LOG_NEWLINE))
+		prb_commit(&e);
+	else
+		prb_final_commit(&e);
+
+	return (text_len + trunc_msg_len);
 }
 
 asmlinkage int vprintk_emit(int facility, int level,
-- 
2.20.1

[PATCH next v3 2/3] printk: define CONSOLE_LOG_MAX in printk.h

[John Ogness]

CONSOLE_EXT_LOG_MAX for extended console messages is already defined
in printk.h. Define CONSOLE_LOG_MAX there as well so that future
changes can make use of the constant for non-extended console
messages.

Signed-off-by: John Ogness <john.ogness@linutronix.de>
---
 include/linux/printk.h | 1 +
 kernel/printk/printk.c | 2 +-
 2 files changed, 2 insertions(+), 1 deletion(-)

diff --git a/include/linux/printk.h b/include/linux/printk.h
index fe7eb2351610..6d8f844bfdff 100644
--- a/include/linux/printk.h
+++ b/include/linux/printk.h
@@ -45,6 +45,7 @@ static inline const char *printk_skip_headers(const char *buffer)
 }
 
 #define CONSOLE_EXT_LOG_MAX	8192
+#define CONSOLE_LOG_MAX		1024
 
 /* printk's without a loglevel use this.. */
 #define MESSAGE_LOGLEVEL_DEFAULT CONFIG_MESSAGE_LOGLEVEL_DEFAULT
diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
index bf5fd2be3a05..e1f068677a74 100644
--- a/kernel/printk/printk.c
+++ b/kernel/printk/printk.c
@@ -410,7 +410,7 @@ static u64 clear_seq;
 #else
 #define PREFIX_MAX		32
 #endif
-#define LOG_LINE_MAX		(1024 - PREFIX_MAX)
+#define LOG_LINE_MAX		(CONSOLE_LOG_MAX - PREFIX_MAX)
 
 #define LOG_LEVEL(v)		((v) & 0x07)
 #define LOG_FACILITY(v)		((v) >> 3 & 0xff)
-- 
2.20.1

[PATCH next v3 3/3] printk: remove logbuf_lock protection for ringbuffer

[John Ogness]

Since the ringbuffer is lockless, there is no need for it to be
protected by @logbuf_lock. Remove @logbuf_lock protection of the
ringbuffer.

This means that printk_nmi_direct and printk_safe_flush_on_panic()
no longer need to acquire any lock to run.

Without @logbuf_lock it is no longer possible to use the single
static buffer for temporarily sprint'ing the message. Instead,
use vsnprintf() to determine the length and perform the real
vscnprintf() using the area reserved from the ringbuffer. This
leads to suboptimal packing of the message data, but will
result in less wasted storage than multiple per-cpu buffers to
support lockless temporary sprint'ing.

Signed-off-by: John Ogness <john.ogness@linutronix.de>
---
 kernel/printk/printk.c      | 131 +++++++++++++++++++++++++-----------
 kernel/printk/printk_safe.c |  18 +----
 2 files changed, 95 insertions(+), 54 deletions(-)

diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
index e1f068677a74..f3c0fcc3163f 100644
--- a/kernel/printk/printk.c
+++ b/kernel/printk/printk.c
@@ -1068,7 +1068,6 @@ void __init setup_log_buf(int early)
 	struct printk_record r;
 	size_t new_descs_size;
 	size_t new_infos_size;
-	unsigned long flags;
 	char *new_log_buf;
 	unsigned int free;
 	u64 seq;
@@ -1126,8 +1125,6 @@ void __init setup_log_buf(int early)
 		 new_descs, ilog2(new_descs_count),
 		 new_infos);
 
-	logbuf_lock_irqsave(flags);
-
 	log_buf_len = new_log_buf_len;
 	log_buf = new_log_buf;
 	new_log_buf_len = 0;
@@ -1143,8 +1140,6 @@ void __init setup_log_buf(int early)
 	 */
 	prb = &printk_rb_dynamic;
 
-	logbuf_unlock_irqrestore(flags);
-
 	if (seq != prb_next_seq(&printk_rb_static)) {
 		pr_err("dropped %llu messages\n",
 		       prb_next_seq(&printk_rb_static) - seq);
@@ -1861,19 +1856,91 @@ static inline u32 printk_caller_id(void)
 		0x80000000 + raw_smp_processor_id();
 }
 
-/* Must be called under logbuf_lock. */
+/**
+ * parse_prefix - Parse level and control flags.
+ *
+ * @text:     The text message.
+ * @text_len: A pointer to a value of strlen(@text), will be updated.
+ * @level:    A pointer to the current level value, will be updated.
+ * @lflags:   A pointer to the current log flags, will be updated.
+ *
+ * The variable pointed to by @text_len is updated to the message length
+ * when subtracting the parsed level and control flag length.
+ *
+ * @level may be NULL if the caller is not interested in the parsed value.
+ * Otherwise the variable pointed to by @level must be set to
+ * LOGLEVEL_DEFAULT in order to be updated with the parsed value.
+ *
+ * @lflags may be NULL if the caller is not interested in the parsed value.
+ * Otherwise the variable pointed to by @lflags will be OR'd with the parsed
+ * value.
+ *
+ * Return: The text message with the parsed level and control flags skipped.
+ */
+static char *parse_prefix(char *text, u16 *text_len, int *level, enum log_flags *lflags)
+{
+	int kern_level;
+
+	while (*text_len >= 2) {
+		kern_level = printk_get_level(text);
+		if (!kern_level)
+			break;
+
+		switch (kern_level) {
+		case '0' ... '7':
+			if (level && *level == LOGLEVEL_DEFAULT)
+				*level = kern_level - '0';
+			break;
+		case 'c':	/* KERN_CONT */
+			if (lflags)
+				*lflags |= LOG_CONT;
+		}
+
+		*text_len -= 2;
+		text += 2;
+	}
+
+	return text;
+}
+
+static u16 printk_sprint(char *text, u16 size, int facility, enum log_flags *lflags,
+			 const char *fmt, va_list args)
+{
+	char *orig_text = text;
+	u16 text_len;
+
+	text_len = vscnprintf(text, size, fmt, args);
+
+	/* Mark and strip a trailing newline. */
+	if (text_len && text[text_len - 1] == '\n') {
+		text_len--;
+		*lflags |= LOG_NEWLINE;
+	}
+
+	/* Strip log level and control flags. */
+	if (facility == 0) {
+		text = parse_prefix(text, &text_len, NULL, NULL);
+		if (text != orig_text)
+			memmove(orig_text, text, text_len);
+	}
+
+	return text_len;
+}
+
+__printf(4, 0)
 int vprintk_store(int facility, int level,
 		  const struct dev_printk_info *dev_info,
 		  const char *fmt, va_list args)
 {
 	const u32 caller_id = printk_caller_id();
-	static char textbuf[LOG_LINE_MAX];
 	struct prb_reserved_entry e;
 	enum log_flags lflags = 0;
 	struct printk_record r;
 	u16 trunc_msg_len = 0;
-	char *text = textbuf;
+	char prefix_buf[8];
+	va_list args2;
 	u16 text_len;
+	int ret = 0;
 	u64 ts_nsec;
 
 	/*
@@ -1884,35 +1951,21 @@ int vprintk_store(int facility, int level,
 	 */
 	ts_nsec = local_clock();
 
+	va_copy(args2, args);
+
 	/*
 	 * The printf needs to come first; we need the syslog
 	 * prefix which might be passed-in as a parameter.
 	 */
-	text_len = vscnprintf(text, sizeof(textbuf), fmt, args);
+	text_len = vsnprintf(&prefix_buf[0], sizeof(prefix_buf), fmt, args) + 1;
+	if (text_len > CONSOLE_LOG_MAX)
+		text_len = CONSOLE_LOG_MAX;
 
-	/* mark and strip a trailing newline */
-	if (text_len && text[text_len-1] == '\n') {
-		text_len--;
-		lflags |= LOG_NEWLINE;
-	}
-
-	/* strip kernel syslog prefix and extract log level or control flags */
+	/* Extract log level or control flags. */
 	if (facility == 0) {
-		int kern_level;
-
-		while ((kern_level = printk_get_level(text)) != 0) {
-			switch (kern_level) {
-			case '0' ... '7':
-				if (level == LOGLEVEL_DEFAULT)
-					level = kern_level - '0';
-				break;
-			case 'c':	/* KERN_CONT */
-				lflags |= LOG_CONT;
-			}
+		u16 tmplen = sizeof(prefix_buf);
 
-			text_len -= 2;
-			text += 2;
-		}
+		parse_prefix(&prefix_buf[0], &tmplen, &level, &lflags);
 	}
 
 	if (level == LOGLEVEL_DEFAULT)
@@ -1924,7 +1977,8 @@ int vprintk_store(int facility, int level,
 	if (lflags & LOG_CONT) {
 		prb_rec_init_wr(&r, text_len);
 		if (prb_reserve_in_last(&e, prb, &r, caller_id, LOG_LINE_MAX)) {
-			memcpy(&r.text_buf[r.info->text_len], text, text_len);
+			text_len = printk_sprint(&r.text_buf[r.info->text_len], text_len,
+						 facility, &lflags, fmt, args2);
 			r.info->text_len += text_len;
 
 			if (lflags & LOG_NEWLINE) {
@@ -1934,7 +1988,8 @@ int vprintk_store(int facility, int level,
 				prb_commit(&e);
 			}
 
-			return text_len;
+			ret = text_len;
+			goto out;
 		}
 	}
 
@@ -1950,11 +2005,11 @@ int vprintk_store(int facility, int level,
 
 		prb_rec_init_wr(&r, text_len + trunc_msg_len);
 		if (!prb_reserve(&e, prb, &r))
-			return 0;
+			goto out;
 	}
 
 	/* fill message */
-	memcpy(&r.text_buf[0], text, text_len);
+	text_len = printk_sprint(&r.text_buf[0], text_len, facility, &lflags, fmt, args2);
 	if (trunc_msg_len)
 		memcpy(&r.text_buf[text_len], trunc_msg, trunc_msg_len);
 	r.info->text_len = text_len + trunc_msg_len;
@@ -1972,7 +2027,10 @@ int vprintk_store(int facility, int level,
 	else
 		prb_final_commit(&e);
 
-	return (text_len + trunc_msg_len);
+	ret = text_len + trunc_msg_len;
+out:
+	va_end(args2);
+	return ret;
 }
 
 asmlinkage int vprintk_emit(int facility, int level,
@@ -1995,10 +2053,7 @@ asmlinkage int vprintk_emit(int facility, int level,
 	boot_delay_msec(level);
 	printk_delay();
 
-	/* This stops the holder of console_sem just where we want him */
-	logbuf_lock_irqsave(flags);
 	printed_len = vprintk_store(facility, level, dev_info, fmt, args);
-	logbuf_unlock_irqrestore(flags);
 
 	/* If called from the scheduler, we can not call up(). */
 	if (!in_sched) {
diff --git a/kernel/printk/printk_safe.c b/kernel/printk/printk_safe.c
index a0e6f746de6c..7248b6e3df6c 100644
--- a/kernel/printk/printk_safe.c
+++ b/kernel/printk/printk_safe.c
@@ -266,18 +266,6 @@ void printk_safe_flush(void)
  */
 void printk_safe_flush_on_panic(void)
 {
-	/*
-	 * Make sure that we could access the main ring buffer.
-	 * Do not risk a double release when more CPUs are up.
-	 */
-	if (raw_spin_is_locked(&logbuf_lock)) {
-		if (num_online_cpus() > 1)
-			return;
-
-		debug_locks_off();
-		raw_spin_lock_init(&logbuf_lock);
-	}
-
 	printk_safe_flush();
 }
 
@@ -371,17 +359,15 @@ __printf(1, 0) int vprintk_func(const char *fmt, va_list args)
 	 * Try to use the main logbuf even in NMI. But avoid calling console
 	 * drivers that might have their own locks.
 	 */
-	if ((this_cpu_read(printk_context) & PRINTK_NMI_DIRECT_CONTEXT_MASK) &&
-	    raw_spin_trylock(&logbuf_lock)) {
+	if ((this_cpu_read(printk_context) & PRINTK_NMI_DIRECT_CONTEXT_MASK)) {
 		int len;
 
 		len = vprintk_store(0, LOGLEVEL_DEFAULT, NULL, fmt, args);
-		raw_spin_unlock(&logbuf_lock);
 		defer_console_output();
 		return len;
 	}
 
-	/* Use extra buffer in NMI when logbuf_lock is taken or in safe mode. */
+	/* Use extra buffer in NMI or in safe mode. */
 	if (this_cpu_read(printk_context) & PRINTK_NMI_CONTEXT_MASK)
 		return vprintk_nmi(fmt, args);
 
-- 
2.20.1

Re: [PATCH next v3 1/3] printk: inline log_output(),log_store() in vprintk_store()

[Joe Perches]

On Mon, 2020-12-07 at 23:26 +0106, John Ogness wrote:
> In preparation for removing logbuf_lock, inline log_output()
> and log_store() into vprintk_store(). This will simplify dealing
> with the various code branches and fallbacks that are possible.

One nicety would be to add various pr_<level> functions.

From several years ago, (and this should work properly now)

https://lore.kernel.org/lkml/1466739971-30399-1-git-send-email-joe@perches.com/

Re: [PATCH next v3 2/3] printk: define CONSOLE_LOG_MAX in printk.h

[John Ogness]

On 2020-12-07, John Ogness <john.ogness@linutronix.de> wrote:
> CONSOLE_EXT_LOG_MAX for extended console messages is already defined
> in printk.h. Define CONSOLE_LOG_MAX there as well so that future
> changes can make use of the constant for non-extended console
> messages.

Actually this patch is not necessary for this series. Also, this patch
should probably modify all the "LOG_LINE_MAX + PREFIX_MAX" calls as
well.

John Ogness

Re: [PATCH next v3 3/3] printk: remove logbuf_lock protection for ringbuffer

[John Ogness]

On 2020-12-07, John Ogness <john.ogness@linutronix.de> wrote:
> diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
> index e1f068677a74..f3c0fcc3163f 100644
> --- a/kernel/printk/printk.c
> +++ b/kernel/printk/printk.c
[...]
>  int vprintk_store(int facility, int level,
>  		  const struct dev_printk_info *dev_info,
>  		  const char *fmt, va_list args)
>  {
>  	const u32 caller_id = printk_caller_id();
> -	static char textbuf[LOG_LINE_MAX];
>  	struct prb_reserved_entry e;
>  	enum log_flags lflags = 0;
>  	struct printk_record r;
>  	u16 trunc_msg_len = 0;
> -	char *text = textbuf;
> +	char prefix_buf[8];
> +	va_list args2;
>  	u16 text_len;
> +	int ret = 0;
>  	u64 ts_nsec;
>  
>  	/*
> @@ -1884,35 +1951,21 @@ int vprintk_store(int facility, int level,
>  	 */
>  	ts_nsec = local_clock();
>  
> +	va_copy(args2, args);
> +
>  	/*
>  	 * The printf needs to come first; we need the syslog
>  	 * prefix which might be passed-in as a parameter.
>  	 */
> -	text_len = vscnprintf(text, sizeof(textbuf), fmt, args);
> +	text_len = vsnprintf(&prefix_buf[0], sizeof(prefix_buf), fmt, args) + 1;
> +	if (text_len > CONSOLE_LOG_MAX)
> +		text_len = CONSOLE_LOG_MAX;

LOG_LINE_MAX should be the limit. That was the size of the static
@textbuf.

John Ogness

Re: [PATCH next v3 3/3] printk: remove logbuf_lock protection for ringbuffer

[Petr Mladek]

On Mon 2020-12-07 23:26:20, John Ogness wrote:
> Since the ringbuffer is lockless, there is no need for it to be
> protected by @logbuf_lock. Remove @logbuf_lock protection of the
> ringbuffer.

This patch removes the protection only on the write part. Please,
make it clear here and also in the subject.

> This means that printk_nmi_direct and printk_safe_flush_on_panic()
> no longer need to acquire any lock to run.
> 
> Without @logbuf_lock it is no longer possible to use the single
> static buffer for temporarily sprint'ing the message. Instead,
> use vsnprintf() to determine the length and perform the real
> vscnprintf() using the area reserved from the ringbuffer. This
> leads to suboptimal packing of the message data, but will
> result in less wasted storage than multiple per-cpu buffers to
> support lockless temporary sprint'ing.
> 
> Signed-off-by: John Ogness <john.ogness@linutronix.de>
> ---
>  kernel/printk/printk.c      | 131 +++++++++++++++++++++++++-----------
>  kernel/printk/printk_safe.c |  18 +----
>  2 files changed, 95 insertions(+), 54 deletions(-)
> 
> diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
> index e1f068677a74..f3c0fcc3163f 100644
> --- a/kernel/printk/printk.c
> +++ b/kernel/printk/printk.c
> @@ -1861,19 +1856,91 @@ static inline u32 printk_caller_id(void)
>  		0x80000000 + raw_smp_processor_id();
>  }
>  
> -/* Must be called under logbuf_lock. */
> +/**
> + * parse_prefix - Parse level and control flags.
> + *
> + * @text:     The text message.
> + * @text_len: A pointer to a value of strlen(@text), will be updated.
> + * @level:    A pointer to the current level value, will be updated.
> + * @lflags:   A pointer to the current log flags, will be updated.
> + *
> + * The variable pointed to by @text_len is updated to the message length
> + * when subtracting the parsed level and control flag length.
> + *
> + * @level may be NULL if the caller is not interested in the parsed value.
> + * Otherwise the variable pointed to by @level must be set to
> + * LOGLEVEL_DEFAULT in order to be updated with the parsed value.
> + *
> + * @lflags may be NULL if the caller is not interested in the parsed value.
> + * Otherwise the variable pointed to by @lflags will be OR'd with the parsed
> + * value.
> + *
> + * Return: The text message with the parsed level and control flags skipped.
> + */
> +static char *parse_prefix(char *text, u16 *text_len, int *level, enum log_flags *lflags)
> +{
> +	int kern_level;
> +
> +	while (*text_len >= 2) {
> +		kern_level = printk_get_level(text);
> +		if (!kern_level)
> +			break;
> +
> +		switch (kern_level) {
> +		case '0' ... '7':
> +			if (level && *level == LOGLEVEL_DEFAULT)
> +				*level = kern_level - '0';
> +			break;
> +		case 'c':	/* KERN_CONT */
> +			if (lflags)
> +				*lflags |= LOG_CONT;
> +		}
> +
> +		*text_len -= 2;
> +		text += 2;
> +	}
> +
> +	return text;
> +}
> +
> +static u16 printk_sprint(char *text, u16 size, int facility, enum log_flags *lflags,
> +			 const char *fmt, va_list args)
> +{
> +	char *orig_text = text;
> +	u16 text_len;
> +
> +	text_len = vscnprintf(text, size, fmt, args);
> +
> +	/* Mark and strip a trailing newline. */
> +	if (text_len && text[text_len - 1] == '\n') {
> +		text_len--;
> +		*lflags |= LOG_NEWLINE;
> +	}
> +
> +	/* Strip log level and control flags. */
> +	if (facility == 0) {
> +		text = parse_prefix(text, &text_len, NULL, NULL);
> +		if (text != orig_text)
> +			memmove(orig_text, text, text_len);
> +	}
> +
> +	return text_len;
> +}
> +
> +__printf(4, 0)
>  int vprintk_store(int facility, int level,
>  		  const struct dev_printk_info *dev_info,
>  		  const char *fmt, va_list args)
>  {
>  	const u32 caller_id = printk_caller_id();
> -	static char textbuf[LOG_LINE_MAX];
>  	struct prb_reserved_entry e;
>  	enum log_flags lflags = 0;
>  	struct printk_record r;
>  	u16 trunc_msg_len = 0;
> -	char *text = textbuf;
> +	char prefix_buf[8];
> +	va_list args2;
>  	u16 text_len;
> +	int ret = 0;
>  	u64 ts_nsec;
>  
>  	/*
> @@ -1884,35 +1951,21 @@ int vprintk_store(int facility, int level,
>  	 */
>  	ts_nsec = local_clock();
>  
> +	va_copy(args2, args);
> +
>  	/*
>  	 * The printf needs to come first; we need the syslog
>  	 * prefix which might be passed-in as a parameter.
>  	 */
> -	text_len = vscnprintf(text, sizeof(textbuf), fmt, args);
> +	text_len = vsnprintf(&prefix_buf[0], sizeof(prefix_buf), fmt, args) + 1;

The "+ 1" confused me a lot.

I guess that you added "+ 1" because we need to reserve the space also
for the trailing "\0". Otherwise, the later vscnprintf() would shrink
the string.

But the same variable is later used for the lenghth wihtout the trailing
newline after the second vscnprintf().

It is very confusing and error prone.

Please, use two variables:

    + reserve_size: as a return from the first vsnprintf() + 1. And use
	it to reserve the size.

    + text_len: as a return from printk_sprint().

I though about using "buf_size" but it might be confused with the size
of prefix_buf. IMHO, reserve_size is more informative.

+	if (text_len > CONSOLE_LOG_MAX)
+		text_len = CONSOLE_LOG_MAX;

As you wrote, this should check/set LOG_LINE_MAX.


> -	/* mark and strip a trailing newline */
> -	if (text_len && text[text_len-1] == '\n') {
> -		text_len--;
> -		lflags |= LOG_NEWLINE;
> -	}
> -
> -	/* strip kernel syslog prefix and extract log level or control flags */
> +	/* Extract log level or control flags. */
>  	if (facility == 0) {
> -		int kern_level;
> -
> -		while ((kern_level = printk_get_level(text)) != 0) {
> -			switch (kern_level) {
> -			case '0' ... '7':
> -				if (level == LOGLEVEL_DEFAULT)
> -					level = kern_level - '0';
> -				break;
> -			case 'c':	/* KERN_CONT */
> -				lflags |= LOG_CONT;
> -			}

> +		u16 tmplen = sizeof(prefix_buf);

We are not really interested into tmplen here.
BTW: The name is confusing ;-)

What about updating parse_prefix() to return the length of the prefix
string. Then we could do here:


	if (facility == 0)
		parse_prefix(&prefix_buf[0], &level, &lflags);

In printk_sprint(), we could do:

	if (facility == 0) {
		u16 prefix_len;

		prefix_len = parse_prefix(text, NULL, NULL);
		if (prefix_len) {
			text_len -= prefix_len;
			text = memmove(text, text + prefix_len,	text_len);
		}
	}

> -			text_len -= 2;
> -			text += 2;
> -		}
> +		parse_prefix(&prefix_buf[0], &tmplen, &level, &lflags);
>  	}
>  
>  	if (level == LOGLEVEL_DEFAULT)
> @@ -1972,7 +2027,10 @@ int vprintk_store(int facility, int level,
>  	else
>  		prb_final_commit(&e);
>  
> -	return (text_len + trunc_msg_len);
> +	ret = text_len + trunc_msg_len;
> +out:
> +	va_end(args2);

I suggest to use args2 for the first vsnprintf(). I mean:

	va_copy(args2, args);
	reserve_size = vsnprintf(&prefix_buf[0], sizeof(prefix_buf),fmt, args) + 1;
	va_end(args2)

Then we could avoid the churn with "out" label.


> +	return ret;
>  }
>  
>  asmlinkage int vprintk_emit(int facility, int level,
> @@ -1995,10 +2053,7 @@ asmlinkage int vprintk_emit(int facility, int level,
>  	boot_delay_msec(level);
>  	printk_delay();
>  
> -	/* This stops the holder of console_sem just where we want him */
> -	logbuf_lock_irqsave(flags);
>  	printed_len = vprintk_store(facility, level, dev_info, fmt, args);
> -	logbuf_unlock_irqrestore(flags);

It will not longer prevent an infinite recursion via the printk_safe() code.
We either need to prevent the recursion another way or use:

	printk_safe_enter_irqsave(flags);
	printed_len = vprintk_store(facility, level, dev_info, fmt, args);
	printk_safe_exit_irqrestore(flags);

>  
>  	/* If called from the scheduler, we can not call up(). */
>  	if (!in_sched) {
> diff --git a/kernel/printk/printk_safe.c b/kernel/printk/printk_safe.c
> index a0e6f746de6c..7248b6e3df6c 100644
> --- a/kernel/printk/printk_safe.c
> +++ b/kernel/printk/printk_safe.c
> @@ -266,18 +266,6 @@ void printk_safe_flush(void)
>   */
>  void printk_safe_flush_on_panic(void)
>  {
> -	/*
> -	 * Make sure that we could access the main ring buffer.
> -	 * Do not risk a double release when more CPUs are up.
> -	 */
> -	if (raw_spin_is_locked(&logbuf_lock)) {
> -		if (num_online_cpus() > 1)
> -			return;

This has to stay until we remove logbuf_lock from any code that
might be called in panic(). Otherwise, the lock might stay locked
and cause deadlock in these other code paths.


> -
> -		debug_locks_off();
> -		raw_spin_lock_init(&logbuf_lock);
> -	}
> -
>  	printk_safe_flush();
>  }
>  
> @@ -371,17 +359,15 @@ __printf(1, 0) int vprintk_func(const char *fmt, va_list args)
>  	 * Try to use the main logbuf even in NMI. But avoid calling console
>  	 * drivers that might have their own locks.
>  	 */
> -	if ((this_cpu_read(printk_context) & PRINTK_NMI_DIRECT_CONTEXT_MASK) &&
> -	    raw_spin_trylock(&logbuf_lock)) {
> +	if ((this_cpu_read(printk_context) & PRINTK_NMI_DIRECT_CONTEXT_MASK)) {
>  		int len;
>  
>  		len = vprintk_store(0, LOGLEVEL_DEFAULT, NULL, fmt, args);
> -		raw_spin_unlock(&logbuf_lock);

Just for record. This was not safe against an infinite recursion.
Also it was not safe against double unlock. It is great that
it will be gone soon.

Well, I would prefer to keep it as is until we remove logbuf_lock from
other code paths. It probably is not strictly necessary because
we are just storing the messages here. But there might theoretically
be a panic_notifier that tries to call a dumper() or so.
Better be on the safe side to avoid regression.


>  		defer_console_output();
>  		return len;
>  	}
>  
> -	/* Use extra buffer in NMI when logbuf_lock is taken or in safe mode. */
> +	/* Use extra buffer in NMI or in safe mode. */
>  	if (this_cpu_read(printk_context) & PRINTK_NMI_CONTEXT_MASK)
>  		return vprintk_nmi(fmt, args);
>  
> -- 
> 2.20.1

Re: [PATCH next v3 2/3] printk: define CONSOLE_LOG_MAX in printk.h

[Petr Mladek]

On Tue 2020-12-08 08:48:57, John Ogness wrote:
> On 2020-12-07, John Ogness <john.ogness@linutronix.de> wrote:
> > CONSOLE_EXT_LOG_MAX for extended console messages is already defined
> > in printk.h. Define CONSOLE_LOG_MAX there as well so that future
> > changes can make use of the constant for non-extended console
> > messages.
> 
> Actually this patch is not necessary for this series. Also, this patch
> should probably modify all the "LOG_LINE_MAX + PREFIX_MAX" calls as
> well.

+1

Best Regards,
Petr

Re: [PATCH next v3 0/3] printk: remove logbuf_lock protection of ringbuffer

[Petr Mladek]

On Mon 2020-12-07 23:26:17, John Ogness wrote:
> Hello,
> 
> Here is a v3 of the series to remove logbuf_lock. v2 is
> here[0]. Rather than completely removing logbuf_lock, this
> version only removes logbuf_lock usage protecting the
> ringbuffer. I have tried to keep the changes minimal so that
> we can feel comfortable for the upcoming 5.11 merge window.
> 
> Although small, this series is significant because it allows
> printk callers direct lockless access to the ringbuffer and
> it replaces the use of a temporary static sprint buffer with
> sprint'ing directly to the reserved ringbuffer data block.

Yes, it might allow to see eventual races in the ring buffer
code. It is great that we do the switch in many "small" steps.

> The other changes from v2 (recursion limiting, introduction
> of syslog_lock, using clear_seq as seqcount_latch, and full
> removal of logbuf_lock) will be included in a later series,
> which may or may not make the 5.11 merge window.

I am slightly nervous when such changes could not spend longer
time in linux-next. On the other hand, I do not want to block
it too much. The races will hopefully be hard to hit if there
are any. And it is good that there are no other big changes
waiting for 5.11.

Let's see how the patches look like in the end...

Best Regards,
Petr

Re: [PATCH next v3 3/3] printk: remove logbuf_lock protection for ringbuffer

[Sergey Senozhatsky]

On (20/12/07 23:26), John Ogness wrote:
> diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
> index e1f068677a74..f3c0fcc3163f 100644
> --- a/kernel/printk/printk.c
> +++ b/kernel/printk/printk.c
> @@ -1068,7 +1068,6 @@ void __init setup_log_buf(int early)
>  	struct printk_record r;
>  	size_t new_descs_size;
>  	size_t new_infos_size;
> -	unsigned long flags;
>  	char *new_log_buf;
>  	unsigned int free;
>  	u64 seq;
> @@ -1126,8 +1125,6 @@ void __init setup_log_buf(int early)
>  		 new_descs, ilog2(new_descs_count),
>  		 new_infos);
>  
> -	logbuf_lock_irqsave(flags);
> -
>  	log_buf_len = new_log_buf_len;
>  	log_buf = new_log_buf;
>  	new_log_buf_len = 0;
> @@ -1143,8 +1140,6 @@ void __init setup_log_buf(int early)
>  	 */
>  	prb = &printk_rb_dynamic;
>  
> -	logbuf_unlock_irqrestore(flags);

logbuf_lock_irqsave() does two things - it locks the logbuf lock and
enables the printk_safe gating. While we can drop the former, the
latter one must stay until we have a complete replacement.

Looking more:

> ---
>	logbuf_lock_irqsave(flags);
>
>	log_buf_len = new_log_buf_len;
>	log_buf = new_log_buf;
>	new_log_buf_len = 0;
>
>	free = __LOG_BUF_LEN;
>	prb_for_each_record(0, &printk_rb_static, seq, &r)
>		free -= add_to_rb(&printk_rb_dynamic, &r);
>
>	/*
>	 * This is early enough that everything is still running on the
>	 * boot CPU and interrupts are disabled. So no new messages will
>	 * appear during the transition to the dynamic buffer.
>	 */
>	prb = &printk_rb_dynamic;
>
>	logbuf_unlock_irqrestore(flags);
---

I'd say that I'd prefer to keep logbuf initialisation under printk_safe(),
per-CPU buffer can be already initialised at this point. Strictly speaking
we can have new message during transition to the dynamic buffer - there are
functions there that can pr_err/warn while we prb_for_each_record/add_to_rb.

>	-ss