Re: [PATCH v8 01/21] printk: Fully resolve loglevel before deciding printk delay suppression

[Petr Mladek <pmladek@suse.com>]

On Tue 2025-12-09 17:40:11, Petr Mladek wrote:
> On Fri 2025-11-28 03:43:12, Chris Down wrote:
> > When printk_delay() is called from vprintk_emit(), the level argument
> > may be LOGLEVEL_DEFAULT (-1) if the loglevel was not explicitly provided
> > by the caller.
> > 
> > If printk_delay() relies on comparing level against the console loglevel
> > (e.g. for suppression), receiving -1 results in incorrect behaviour
> > because -1 is treated as a high priority (so not suppressed), causing
> > unnecessary delays for default-level messages.
> 
> Great catch!
> 
> > Parse the format string prefix to resolve the actual loglevel before
> > passing it to printk_delay().
> > 
> > --- a/kernel/printk/printk.c
> > +++ b/kernel/printk/printk.c
> > @@ -2179,6 +2179,32 @@ u16 printk_parse_prefix(const char *text, int *level,
> >  	return prefix_len;
> >  }
> >  
> > +/**
> > + * printk_resolve_loglevel - Resolve the effective loglevel for a message
> > + *
> > + * @facility:	The log facility (0 for kernel messages)
> > + * @level:	The initial loglevel, may be LOGLEVEL_DEFAULT
> > + * @fmt:	The format string, potentially containing a loglevel prefix
> > + *
> > + * Determines the actual loglevel to use for a printk message. If the level
> > + * is LOGLEVEL_DEFAULT and the facility indicates a kernel message, parses
> > + * the format string prefix to extract an embedded loglevel. If no loglevel
> > + * is found, falls back to the default_message_loglevel.
> > + *
> > + * Return: The resolved loglevel value
> > + */
> > +static inline int printk_resolve_loglevel(int facility, int level,
> > +					  const char *fmt)
> > +{
> > +	if (facility == 0 && level == LOGLEVEL_DEFAULT && fmt)
> > +		printk_parse_prefix(fmt, &level, NULL);
> > +
> > +	if (level == LOGLEVEL_DEFAULT)
> > +		level = default_message_loglevel;
> 
> This is not ideal:
> 
>  1. It more or less duplicates the code from vprintk_store().
> 
>  2. It does not handle loglevel passed via parameter, for example, see
>     _btrfs_printk() which calls _printk("%sBTRFS %s: %pV\n", lvl, type, &vaf).
>     Note that vprintk_store() calls vsnprintf() before checking the loglevel.
> 
> > +	return level;
> > +}
> 
> Alternative solutions:
> 
>   A. We might call vsnprintf() one more times here.
> 
>      It is ugly but we could do it only when anyone wants a delay.
>      Also this is not easy because we would need to check printk_delay_msec,
>      boot_delay, and system_state.
> 
>      Anyway, this solution would need some refactoring in printk_delay()
>      and vprintk_store() to avoid code duplication.

Even more duplicated code was added by later patches.

I tried to implement this alternative solution and remove all code
duplication. But I think that this is a wrong way after all,
see the patch below for more details.

>   B. We could move printk_delay().
> 
>      It should be called before storing the message. Otherwise, we
>      would need to call it from various console flush calls. And there
>      are many flush paths. Also the message might get lost when
>      consoles fall far behind.
> 
>      I though about moving printk_delay() into vprintk_store(). But
>      we would need to temporary release IRQs disabled by
>      printk_enter_irqsave(recursion_ptr, irqflags). But then the
>      process might get migrated to another CPU. And the message
>      generated by printk_sprint() need not fit into the reserved space.
> 
> I personally prefer the alternative solution A. But I am not sure if
> it is worth it.

I have changed my mind. I think that B is a better way. I am going
to explain it in a separate reply.

Here is the patch implementing variant A. It can be applied on top of
this patchset:

From 5bb33b699fc1668920f1418978589b4a2c2d151f Mon Sep 17 00:00:00 2001
From: Petr Mladek <pmladek@suse.com>
Date: Thu, 11 Dec 2025 13:27:32 +0100
Subject: [POC] printk: Remove code duplication in printk_delay() and
 properly resolve loglevel

This is an attempt to clean up several changes related to printk_delay()
done by this patchset:

  + Remove various code duplication.
  + Use only one READ_ONCE().
  + Properly resolve the loglevel even when passed via parameter.

Namely, it does:

  + Replace boot_delay_active local value with helper function.
  + Read printk_delay_msec only once and use the same variable everywhere.
  + Move code which resolves the loglevel into vprintk_analyze()
    helper function and use it in both printk_delay() and vprintk_store().
  + Remove obsolete printk_resolve_loglevel().

But the solution is not good:

  + It adds a lot of code complexity and one more vscnprintf() is needed.

  + One more vscnprintf() call is needed.

  + It still does not work properly. For example, backtraces from
    all CPUs (SysRq l) prints the entire backtrace at once because
    the console flush is delayed. The same problem will happen for
    any delayed messages, e.g. during early boot before the 1st console
    is registered.

A better solution would be to call printk_delay() in the console code
path.

Signed-off-by: Petr Mladek <pmladek@suse.com>
---
 kernel/printk/printk.c | 118 +++++++++++++++++++++++------------------
 1 file changed, 67 insertions(+), 51 deletions(-)

diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
index 8af5b1b0023b..ff9c8bd483bc 100644
--- a/kernel/printk/printk.c
+++ b/kernel/printk/printk.c
@@ -1463,14 +1463,16 @@ static int __init boot_delay_setup(char *str)
 }
 early_param("boot_delay", boot_delay_setup);
 
+static bool boot_delay_active(void)
+{
+	return (boot_delay && system_state < SYSTEM_RUNNING);
+}
+
 static void boot_delay_msec(void)
 {
 	unsigned long long k;
 	unsigned long timeout;
 
-	if (boot_delay == 0 || system_state >= SYSTEM_RUNNING)
-		return;
-
 	k = (unsigned long long)loops_per_msec * boot_delay;
 
 	timeout = jiffies + msecs_to_jiffies(boot_delay);
@@ -1488,6 +1490,10 @@ static void boot_delay_msec(void)
 	}
 }
 #else
+static bool boot_delay_active(void)
+{
+	return false;
+}
 static inline void boot_delay_msec(void)
 {
 }
@@ -2309,31 +2315,37 @@ static u8 *__printk_recursion_counter(void)
 
 int printk_delay_msec __read_mostly;
 
-static inline void printk_delay(int level)
+__printf(5, 0)
+void vprintk_analyze(int facility, u16 *size, int *level,
+		     enum printk_info_flags *flags,
+		     const char *fmt, va_list args);
+
+static inline void printk_delay(int facility, int level,
+				const char *fmt, va_list args)
 {
-	bool boot_delay_active = false;
-	int m;
+	int delay;
 
-#ifdef CONFIG_BOOT_PRINTK_DELAY
-	boot_delay_active = boot_delay && system_state < SYSTEM_RUNNING;
-#endif
+	/* Prevent re-reading (optimization) in the loop decrementing it. */
+	delay = READ_ONCE(printk_delay_msec);
 
-	if (!boot_delay_active && !READ_ONCE(printk_delay_msec))
+	if (!boot_delay_active() && !delay)
 		return;
 
+	/* Format the message and resolve the effective message level. */
+	vprintk_analyze(facility, NULL, &level, NULL, fmt, args);
+
 	/* If the message is forced (e.g. panic), we must delay */
 	if (!is_printk_force_console() &&
 	    suppress_message_printing_everywhere(level))
 		return;
 
-	if (boot_delay_active)
+	if (boot_delay_active())
 		boot_delay_msec();
 
-	m = READ_ONCE(printk_delay_msec);
-	if (!m)
+	if (!delay)
 		return;
 
-	while (m--) {
+	while (delay--) {
 		mdelay(1);
 		touch_nmi_watchdog();
 	}
@@ -2391,29 +2403,50 @@ u16 printk_parse_prefix(const char *text, int *level,
 }
 
 /**
- * printk_resolve_loglevel - Resolve the effective loglevel for a message
+ * vprintk_analyze - Analyze the formatted message and return its size,
+ *		     loglevel, and flags.
  *
- * @facility:	The log facility (0 for kernel messages)
- * @level:	The initial loglevel, may be LOGLEVEL_DEFAULT
- * @fmt:	The format string, potentially containing a loglevel prefix
+ * @facility:	Log facility (0 for kernel messages) (input)
+ * @size:	Size of the formatted message, including the trailing '\0'
+ *		(output, optional)
+ * @level:	Initial loglevel, may be LOGLEVEL_DEFAULT. It will get updated
+ *		by the message prefix and system defaults.
+ *		(input/output, required)
+ * @flags:	Internal flags are updated by analyzing the message prefix,
+ *		namely LOG_CONT. (input/output, optional)
+ * @fmt:	Format string, potentially containing a loglevel prefix (input)
+ * @args:	Arguments for the format string. (input)
  *
- * Determines the actual loglevel to use for a printk message. If the level
- * is LOGLEVEL_DEFAULT and the facility indicates a kernel message, parses
- * the format string prefix to extract an embedded loglevel. If no loglevel
- * is found, falls back to the default_message_loglevel.
- *
- * Return: The resolved loglevel value
+ * Format the message. Return its size. Update @level, and @flags by analyzing
+ * the message prefix.
  */
-static inline int printk_resolve_loglevel(int facility, int level,
-					  const char *fmt)
+__printf(5, 0)
+void vprintk_analyze(int facility, u16 *size, int *level,
+		     enum printk_info_flags *flags,
+		     const char *fmt, va_list args)
 {
-	if (facility == 0 && level == LOGLEVEL_DEFAULT && fmt)
-		printk_parse_prefix(fmt, &level, NULL);
+	char prefix_buf[8];
+	va_list args2;
+	int len;
 
-	if (level == LOGLEVEL_DEFAULT)
-		level = default_message_loglevel;
+	if (WARN_ON_ONCE(!level))
+		return;
 
-	return level;
+	/* The syslog prefix might be passed in as a parameter. */
+	va_copy(args2, args);
+	len = vsnprintf(&prefix_buf[0], sizeof(prefix_buf), fmt, args2);
+	va_end(args2);
+
+	/* The trailing '\0' is not counted by vsnprintf(). */
+	if (size)
+		*size = len + 1;
+
+	/* Extract log level or control flags. */
+	if (facility == 0)
+		printk_parse_prefix(&prefix_buf[0], level, flags);
+
+	if (*level == LOGLEVEL_DEFAULT)
+		*level = default_message_loglevel;
 }
 
 __printf(5, 0)
@@ -2452,15 +2485,13 @@ int vprintk_store(int facility, int level,
 		  const struct dev_printk_info *dev_info,
 		  const char *fmt, va_list args)
 {
-	struct prb_reserved_entry e;
 	enum printk_info_flags flags = 0;
+	struct prb_reserved_entry e;
 	struct printk_record r;
 	unsigned long irqflags;
 	u16 trunc_msg_len = 0;
-	char prefix_buf[8];
 	u8 *recursion_ptr;
 	u16 reserve_size;
-	va_list args2;
 	u32 caller_id;
 	u16 text_len;
 	int ret = 0;
@@ -2479,26 +2510,11 @@ int vprintk_store(int facility, int level,
 
 	caller_id = printk_caller_id();
 
-	/*
-	 * The sprintf needs to come first since the syslog prefix might be
-	 * passed in as a parameter. An extra byte must be reserved so that
-	 * later the vscnprintf() into the reserved buffer has room for the
-	 * terminating '\0', which is not counted by vsnprintf().
-	 */
-	va_copy(args2, args);
-	reserve_size = vsnprintf(&prefix_buf[0], sizeof(prefix_buf), fmt, args2) + 1;
-	va_end(args2);
+	vprintk_analyze(facility, &reserve_size, &level, &flags, fmt, args);
 
 	if (reserve_size > PRINTKRB_RECORD_MAX)
 		reserve_size = PRINTKRB_RECORD_MAX;
 
-	/* Extract log level or control flags. */
-	if (facility == 0)
-		printk_parse_prefix(&prefix_buf[0], &level, &flags);
-
-	if (level == LOGLEVEL_DEFAULT)
-		level = default_message_loglevel;
-
 	if (dev_info)
 		flags |= LOG_NEWLINE;
 
@@ -2631,7 +2647,7 @@ asmlinkage int vprintk_emit(int facility, int level,
 		ft.legacy_direct = false;
 	}
 
-	printk_delay(printk_resolve_loglevel(facility, level, fmt));
+	printk_delay(facility, level, fmt, args);
 
 	printed_len = vprintk_store(facility, level, dev_info, fmt, args);
 
-- 
2.52.0