printk: nbcon: deprecate boot_delay in favour of printk_delay

The boot_delay (BOOT_PRINTK_DELAY) kernel parameter and printk_delay sysctl are two distinct mechanisms for providing similar functionality which add a delay prior to each printed printk message.

boot_delay provides a kernel parameter for delaying printk output from kernel start through to boot (SYSTEM_RUNNING), whereas printk_delay is configurable only via sysctl and thus is only used post boot.

Let's deprecate the boot_delay feature in favour of printk_delay. In order to preserve functionality, we'll also extend printk_delay such that it can additionally configured via an early kernel parameter.

Behavior change:

The delay enabled by both "boot_delay" and "printk_delay" continues working even in SYSTEM_RUNNING state. It must be explicitly stopped by setting printk_delay=0 via sysctl.

The delay is skipped when the message is suppressed in all system states. It used to skipped only for the boot_delay.

Signed-off-by Andrew Murray <[email protected]>

Quoted 14 lines · Andrew Murray

The boot_delay (BOOT_PRINTK_DELAY) kernel parameter and printk_delay sysctl are two distinct mechanisms for providing similar functionality which add a delay prior to each printed printk message.

boot_delay provides a kernel parameter for delaying printk output from kernel start through to boot (SYSTEM_RUNNING), whereas printk_delay is configurable only via sysctl and thus is only used post boot.

Let's deprecate the boot_delay feature in favour of printk_delay. In order to preserve functionality, we'll also extend printk_delay such that it can additionally configured via an early kernel parameter.

Behavior change:

Quoted 8 lines

The delay enabled by both "boot_delay" and "printk_delay" continues working even in SYSTEM_RUNNING state. It must be explicitly stopped by setting printk_delay=0 via sysctl.

The delay is skipped when the message is suppressed in all system states. It used to skipped only for the boot_delay.

Signed-off-by Andrew Murray <[email protected]>

Looks good to me:

Reviewed-by Petr Mladek <[email protected]>

Note that Sashiko AI warns about possible problems with negative printk_delay values, see
https://sashiko.dev/#/patchset/20260630-deprecate_boot_delay-v2-0-f9883d36aa4b%40thegoodpenguin.co.uk

But they should be handled in both the early parameter and sysctl interface by the "10 * 1000" and "&ten_thousand" limits.

The only potential problem might be a warning about possible "sign" mismatch from the compiler. But I do not see any even with make W=2.

Best Regards,
Petr

Hi Petr,

Quoted 29 lines · Petr Mladek

Quoted 14 lines · Andrew Murray

The boot_delay (BOOT_PRINTK_DELAY) kernel parameter and printk_delay sysctl are two distinct mechanisms for providing similar functionality which add a delay prior to each printed printk message.

boot_delay provides a kernel parameter for delaying printk output from kernel start through to boot (SYSTEM_RUNNING), whereas printk_delay is configurable only via sysctl and thus is only used post boot.

Let's deprecate the boot_delay feature in favour of printk_delay. In order to preserve functionality, we'll also extend printk_delay such that it can additionally configured via an early kernel parameter.

Behavior change:

Quoted 8 lines

The delay enabled by both "boot_delay" and "printk_delay" continues working even in SYSTEM_RUNNING state. It must be explicitly stopped by setting printk_delay=0 via sysctl.

The delay is skipped when the message is suppressed in all system states. It used to skipped only for the boot_delay.

Signed-off-by Andrew Murray <[email protected]>

Looks good to me:

Reviewed-by Petr Mladek <[email protected]>

Quoted 7 lines

Note that Sashiko AI warns about possible problems with negative printk_delay values, see
https://sashiko.dev/#/patchset/20260630-deprecate_boot_delay-v2-0-f9883d36aa4b%40thegoodpenguin.co.uk

But they should be handled in both the early parameter and sysctl interface by the "10 * 1000" and "&ten_thousand" limits.

Yes, that was my also view.

Quoted 4 lines

The only potential problem might be a warning about possible "sign" mismatch from the compiler. But I do not see any even with make W=2.

I suspect this will come up everytime a change is made in this area, or perhaps some W=2 errors will pop up via kernelci or similar. I propose updating the patch as follows:

kernel/printk/printk.c +6 -3

index 5278d9cb19e4..fbb67f10c21e 100644
@@ -1338,10 +1338,13 @@ static inline void early_boot_delay_msec(void)
 
 static int __init printk_delay_setup(char *str)
 {
-       get_option(&str, &printk_delay_msec);
-       if (printk_delay_msec > 10 * 1000)
-               printk_delay_msec = 0;
+       int printk_delay_val = 0;
 
+       get_option(&str, &printk_delay_val);
+       if (printk_delay_val < 0 || printk_delay_val > 10 * 1000)
+               return 0;
+
+       printk_delay_msec = (unsigned int)printk_delay_val;
        printk_delay_calculate();
 
        return 0;

kernel/printk/sysctl.c +0 -0

index f15732e93c2e..f256fc05faaf 100644

This makes the cast explict, verifies the range before casting

(I guess a range of negative values could result in a postive value within the 10,000 range) and also uses the correct proc_handler.

This has the side effect of not showing the following pr_debug for the lpj calculation when a delay is not set. Though loops_per_msec is only used during boot, so I don't think there is any loss here.

        pr_debug("printk_delay: %u, preset_lpj: %ld, lpj: %lu, "
                "HZ: %d, loops_per_msec: %llu\n",
                printk_delay_msec, preset_lpj, lpj, HZ, loops_per_msec);

Can I keep your Reviewed-By with these changes?

I would change this to sizeof(unsigned int) as well.

Quoted 6 lines

                .mode           = 0644,

kernel/printk/sysctl.c +1 -1

-               .proc_handler   = proc_dointvec_minmax,
+               .proc_handler   = proc_douintvec_minmax,
                .extra1         = SYSCTL_ZERO,
                .extra2         = (void *)&ten_thousand,
        },

Otherwise, it looks good to me.

Quoted 1 line

This makes the cast explict, verifies the range before casting

Yup.

Quoted 2 lines

(I guess a range of negative values could result in a postive value within the 10,000 range) and also uses the correct proc_handler.

IMHO, this should not happen. I have never seen int smaller than 4 bytes. If I count it correctly, positive numbers should be up to 32767.

Quoted 3 lines

This has the side effect of not showing the following pr_debug for the lpj calculation when a delay is not set. Though loops_per_msec is only used during boot, so I don't think there is any loss here.

I agree that it should not harm. But please mention this in the commit message.

Quoted 5 lines

        pr_debug("printk_delay: %u, preset_lpj: %ld, lpj: %lu, "
                "HZ: %d, loops_per_msec: %llu\n",
                printk_delay_msec, preset_lpj, lpj, HZ, loops_per_msec);

Quoted 1 line

Can I keep your Reviewed-By with these changes?

Feel free to keep it. That said, please put at least the change of the ctl_table into a separate patch. I would rather put both new changes into separate file. It is never a good idea to hide such changes in a complex patch which mostly reshuffles an existing code.

Best Regards,
Petr

Quoted 3 lines

kernel/printk/printk.c +0 -0

[ ... ]

kernel/printk/printk.c static bool console_emit_next_record(struct console *con, bool *handover, int co · line 3212

Quoted 6 lines

kernel/printk/printk.c +2 -0

@@ -3211,6 +3208,8 @@ static bool console_emit_next_record(struct console *con, bool *handover, int co
 		*handover = console_lock_spinning_disable_and_check(cookie);
 		printk_safe_exit_irqrestore(flags);
 	}
+	printk_delay(true);
+

[Severity: Critical]
This isn't a bug introduced by this patch, but does the expanded delay create a use-after-free window for the con pointer in console_flush_all()?

In console_emit_next_record(), if a lock handover occurs, console_lock_spinning_disable_and_check() releases the SRCU read lock.

This patch inserts printk_delay(true) immediately after this lock release, adding a multi-millisecond busy-wait delay.

During this expanded window, another CPU can unregister and free the console because the SRCU lock is no longer held.

When console_emit_next_record() returns to console_flush_all(), it unconditionally dereferences con->seq before checking if a handover occurred:

		if (!console_emit_next_record(con, &handover, cookie))
			continue;
		printk_seq = con->seq;

Could this massive delay guarantee a use-after-free if a console is unregistered under contention?

include/linux/console.h +2 -0

index d624200cfc1708bf73925892a466efe0c95c5586..3478b556c0eb9579530409dc6fbb9b5a8bff581c 100644
@@ -290,6 +290,8 @@ struct nbcon_context {
  * @outbuf:		Pointer to the text buffer for output
  * @len:		Length to write
  * @unsafe_takeover:	If a hostile takeover in an unsafe state has occurred
+ * @emitted:		The write context attempted to emit the message. Might
+ *			be incomplete.
  * @cpu:		CPU on which the message was generated
  * @pid:		PID of the task that generated the message
  * @comm:		Name of the task that generated the message

kernel/printk/nbcon.c +2 -0

@@ -1584,6 +1593,8 @@ static int __nbcon_atomic_flush_pending_con(struct console *con, u64 stop_seq)
 			if (!nbcon_context_try_acquire(ctxt, false))
 				return -EPERM;
 
+			wctxt.emitted = 0;
+
 			/*
 			 * nbcon_emit_next_record() returns false when
 			 * the console was handed over or taken over.

Hi,

Sorry I am so late to this party.

Quoted 15 lines · Andrew Murray

include/linux/console.h +2 -0

index d624200cfc1708bf73925892a466efe0c95c5586..3478b556c0eb9579530409dc6fbb9b5a8bff581c 100644
@@ -290,6 +290,8 @@ struct nbcon_context {
  * @outbuf:		Pointer to the text buffer for output
  * @len:		Length to write
  * @unsafe_takeover:	If a hostile takeover in an unsafe state has occurred
+ * @emitted:		The write context attempted to emit the message. Might
+ *			be incomplete.
  * @cpu:		CPU on which the message was generated
  * @pid:		PID of the task that generated the message
  * @comm:		Name of the task that generated the message

@@ -298,7 +300,8 @@ struct nbcon_write_context {
 	struct nbcon_context	__private ctxt;

include/linux/console.h struct nbcon_write_context { · line 304

Quoted 5 lines

include/linux/console.h +2 -1

 	char			*outbuf;
 	unsigned int		len;
-	bool			unsafe_takeover;
+	unsigned char		unsafe_takeover : 1;
+	unsigned char		emitted		: 1;

This is the wrong structure to add this flag. This structure is for the nbcon drivers.

struct nbcon_context would be the correct structure.

Quoted 11 lines

kernel/printk/nbcon.c +2 -0

index 4b03b019cd5ee25d68e9ace84392045e91241a7f..ae45cb0589c0effafc66f1756bdaecd1c1e53ab9 100644
@@ -1525,6 +1532,8 @@ bool nbcon_legacy_emit_next_record(struct console *con, bool *handover,
 	}
 
 	progress = nbcon_emit_one(&wctxt, use_atomic);
+	if (progress && wctxt.emitted)
+		printk_delay(use_atomic);
 

kernel/printk/nbcon.c bool nbcon_legacy_emit_next_record(struct console *con, bool *handover, · line 1539

Quoted 2 lines

kernel/printk/nbcon.c +0 -0

 	if (use_atomic) {
 		start_critical_timings();

This is too deep (also pointed out by Sashiko) because it multiplies the delay times the number of consoles. For the legacy printing, it would be more appropriate to put the delay inside console_flush_all() and legacy_kthread_func().

Quoted 4 lines

This is too deep (also pointed out by Sashiko) because it multiplies the delay times the number of consoles. For the legacy printing, it would be more appropriate to put the delay inside console_flush_all() and legacy_kthread_func().

True. The question is if the proper solution is worth the complexity. We would need to pass the information down two level of the API. It would require adding a new (output) parameter to console_flush_one_record(), nbcon_legacy_emit_next_record(), and console_emit_next_record().

It is not that complicated but these functions are already hairy enough so we should be careful.

Quoted 10 lines · Petr Mladek

Quoted 4 lines

This is too deep (also pointed out by Sashiko) because it multiplies the delay times the number of consoles. For the legacy printing, it would be more appropriate to put the delay inside console_flush_all() and legacy_kthread_func().

True. The question is if the proper solution is worth the complexity. We would need to pass the information down two level of the API. It would require adding a new (output) parameter to console_flush_one_record(), nbcon_legacy_emit_next_record(), and console_emit_next_record().

Quoted 2 lines

It is not that complicated but these functions are already hairy enough so we should be careful.

Fair enough. But then it should be consistent and console_emit_next_record() should perform the delay before allowing the handover. Something like this:

kernel/printk/printk.c +2 -0

index 2fe9a963c823a..62fd6a5ebef66 100644
@@ -3161,6 +3161,8 @@ static bool console_emit_next_record(struct console *con, bool *handover, int co
 		 */
 
 		con->write(con, outbuf, pmsg.outbuf_len);
+		printk_delay(false);
+
 		con->seq = pmsg.seq + 1;
 	} else {
 		/*

kernel/printk/printk.c +0 -0

 		start_critical_timings();
 
 

John

Quoted 6 lines · John Ogness

Quoted 5 lines · Petr Mladek

Quoted 4 lines

This is too deep (also pointed out by Sashiko) because it multiplies the delay times the number of consoles. For the legacy printing, it would be more appropriate to put the delay inside console_flush_all() and legacy_kthread_func().

Quoted 7 lines

Quoted 7 lines

True. The question is if the proper solution is worth the complexity. We would need to pass the information down two level of the API. It would require adding a new (output) parameter to console_flush_one_record(), nbcon_legacy_emit_next_record(), and console_emit_next_record().

It is not that complicated but these functions are already hairy enough so we should be careful.

Quoted 4 lines

Fair enough. But then it should be consistent and console_emit_next_record() should perform the delay before allowing the handover. Something like this:

Great catch!

Quoted 8 lines

kernel/printk/printk.c +0 -0

index 2fe9a963c823a..62fd6a5ebef66 100644
@@ -3161,6 +3161,8 @@ static bool console_emit_next_record(struct console *con, bool *handover, int co
               */
 

kernel/printk/printk.c static bool console_emit_next_record(struct console *con, bool *handover, int co · line 3187

Quoted 11 lines

kernel/printk/printk.c +3 -0

              con->write(con, outbuf, pmsg.outbuf_len);
+             printk_delay(false);
+
              con->seq = pmsg.seq + 1;
      } else {
              /*

@@ -3182,6 +3184,7 @@ static bool console_emit_next_record(struct console *con, bool *handover, int co
              printk_legacy_allow_spinlock_enter();
              con->write(con, outbuf, pmsg.outbuf_len);
              printk_legacy_allow_spinlock_exit();
+             printk_delay(true);

It is pity that this is inside printk_safe context with IRQs disabled. A solution might be to call it before the write.

But maybe, this is good enough. This code path is called from vprintk_emit() and it might be in an atomic context anyway. Also it increases the chance of successful handover which might help as well.

Anyway, it would be nice to mention these pitfalls into commit message.

Quoted 6 lines

kernel/printk/printk.c +0 -0

              start_critical_timings();
 
 

John

Hi,

Sorry I am so late to this party.

Quoted 14 lines · Andrew Murray

include/linux/console.h +2 -0

index d624200cfc1708bf73925892a466efe0c95c5586..3478b556c0eb9579530409dc6fbb9b5a8bff581c 100644
@@ -290,6 +290,8 @@ struct nbcon_context {
  * @outbuf:          Pointer to the text buffer for output
  * @len:             Length to write
  * @unsafe_takeover: If a hostile takeover in an unsafe state has occurred
+ * @emitted:         The write context attempted to emit the message. Might
+ *                   be incomplete.
  * @cpu:             CPU on which the message was generated
  * @pid:             PID of the task that generated the message
  * @comm:            Name of the task that generated the message

include/linux/console.h struct nbcon_write_context { · line 304

Quoted 6 lines

include/linux/console.h +2 -1

@@ -298,7 +300,8 @@ struct nbcon_write_context {
      struct nbcon_context    __private ctxt;
      char                    *outbuf;
      unsigned int            len;
-     bool                    unsafe_takeover;
+     unsigned char           unsafe_takeover : 1;
+     unsigned char           emitted         : 1;

This is the wrong structure to add this flag. This structure is for the nbcon drivers.

struct nbcon_context would be the correct structure.

Quoted 6 lines

kernel/printk/nbcon.c +0 -0

index 4b03b019cd5ee25d68e9ace84392045e91241a7f..ae45cb0589c0effafc66f1756bdaecd1c1e53ab9 100644

kernel/printk/nbcon.c bool nbcon_legacy_emit_next_record(struct console *con, bool *handover, · line 1539

Quoted 8 lines

kernel/printk/nbcon.c +2 -0

@@ -1525,6 +1532,8 @@ bool nbcon_legacy_emit_next_record(struct console *con, bool *handover,
      }
 
      progress = nbcon_emit_one(&wctxt, use_atomic);
+     if (progress && wctxt.emitted)
+             printk_delay(use_atomic);
 
      if (use_atomic) {
              start_critical_timings();

This is too deep (also pointed out by Sashiko) because it multiplies the delay times the number of consoles. For the legacy printing, it would be more appropriate to put the delay inside console_flush_all() and legacy_kthread_func().

Quoted 10 lines

kernel/printk/nbcon.c +2 -0

@@ -1584,6 +1593,8 @@ static int __nbcon_atomic_flush_pending_con(struct console *con, u64 stop_seq)
                      if (!nbcon_context_try_acquire(ctxt, false))
                              return -EPERM;
 
+                     wctxt.emitted = 0;
+
                      /*
                       * nbcon_emit_next_record() returns false when
                       * the console was handed over or taken over.

kernel/printk/nbcon.c static int __nbcon_atomic_flush_pending_con(struct console *con, u64 stop_seq) · line 1615

Quoted 5 lines

kernel/printk/nbcon.c +2 -0

@@ -1600,6 +1611,8 @@ static int __nbcon_atomic_flush_pending_con(struct console *con, u64 stop_seq)
                      if (nbcon_seq_read(con) < stop_seq)
                              err = -ENOENT;
                      break;
+             } else if (wctxt.emitted > 0) {
+                     printk_delay(true);

@emitted is a flag:

                } else if (wctxt.emitted) {

kernel/printk/printk.c static bool console_emit_next_record(struct console *con, bool *handover, int co · line 3212

Quoted 10 lines

kernel/printk/printk.c +2 -0

index cc203327247aa4f81f55b907c66ac88f30ce6da8..5278d9cb19e4177a00998fba5c1438251e033578 100644
@@ -3211,6 +3208,8 @@ static bool console_emit_next_record(struct console *con, bool *handover, int co
              *handover = console_lock_spinning_disable_and_check(cookie);
              printk_safe_exit_irqrestore(flags);
      }
+     printk_delay(true);
+

Again, too deep. Let console_flush_all() and legacy_kthread_func() perform the delay appropriately between each message.

John Ogness

The printk_delay and boot_delay features are helpful for debugging as kernel output can be slowed down during boot allowing messages to be seen before scrolling off the screen, or to correlate timing between some physical event and console output.

However, since the introduction of nbcon and the legacy printer thread for PREEMPT_RT kernels, printk records are now emited to the console asynchronously to the caller of printk. Thus, any printk delay added by boot_delay/printk_delay continues to slow down the calling process but may not have any impact to the rate in which records are emited to the console.

Quoted 4 lines · On Tue, 30 Jun 2026 17:35:59 +0100 Andrew Murray…

The printk_delay and boot_delay features are helpful for debugging as kernel output can be slowed down during boot allowing messages to be seen before scrolling off the screen, or to correlate timing between some physical event and console output.

By now, it slows down the boot process, which is the handy part of that feature.

Quoted 6 lines

However, since the introduction of nbcon and the legacy printer thread for PREEMPT_RT kernels, printk records are now emited to the console asynchronously to the caller of printk. Thus, any printk delay added by boot_delay/printk_delay continues to slow down the calling process but may not have any impact to the rate in which records are emited to the console.

Using this feature to slow down the boot/suspend/resume process and implicit make printk() happen, is the usefull part of that feature. Imagine this sequence (which hit me on suspend/resume on i.MX after shutting down all secondary CPUs)

printk("A");
(do some stuff)
printk("B");
read from peripheral --> system got stuck here since peripheral was not clocked or powered or both any more.

The delay (and later on a ugly patch to make printk() synchrounous) helped to locate where the failed access happend. JTAG did not help, since the CPU got stuck --> no JTAG communication to that CPU.

With your purposed change you *may* see "A", but never "B". Quite challenging...

So please leave the delay on the calling side - it is helpfull there.

Regards
Bene Spranger

If you want to ensure printk is synchronous, perhaps you could call nbcon_cpu_emergency_enter() prior to your printk, or perhaps there are already printk wrappers that do somthing similar whilst debugging? Would that provide a more reliable way to guarantee output?

Quoted 26 lines · Benedikt Spranger

Quoted 4 lines · On Tue, 30 Jun 2026 17:35:59 +0100 Andrew Murray…

The printk_delay and boot_delay features are helpful for debugging as kernel output can be slowed down during boot allowing messages to be seen before scrolling off the screen, or to correlate timing between some physical event and console output.

By now, it slows down the boot process, which is the handy part of that feature.

Quoted 6 lines

However, since the introduction of nbcon and the legacy printer thread for PREEMPT_RT kernels, printk records are now emited to the console asynchronously to the caller of printk. Thus, any printk delay added by boot_delay/printk_delay continues to slow down the calling process but may not have any impact to the rate in which records are emited to the console.

Using this feature to slow down the boot/suspend/resume process and implicit make printk() happen, is the usefull part of that feature. Imagine this sequence (which hit me on suspend/resume on i.MX after shutting down all secondary CPUs)

printk("A");
(do some stuff)
printk("B");
read from peripheral --> system got stuck here since peripheral
was not clocked or powered or both any more.

Quoted 3 lines

The delay (and later on a ugly patch to make printk() synchrounous) helped to locate where the failed access happend. JTAG did not help, since the CPU got stuck --> no JTAG communication to that CPU.

I understand the use-case, you sprinkle printk's so you can find the point where a read to a register causes the CPU to stop. This requires that the printk happens before the read, and the output from the printk is printed before the read.

Quoted 2 lines

With your purposed change you *may* see "A", but never "B". Quite challenging...

At present you may see 'A' and you may see 'B'.

Prior to the changes in this patchset, and assuming an nbcon console

(which may not be your usecase, but is perhaps representative of future use-cases), then the printk delay will always happen within the call to printk (and always before emitting).

However, depending on the context, that printk call may return (and proceed to your CPU halting register read), before the message is actually emitted to the console. I.e. it's a race.

This series moves the delay to the emit side, as well as moving the delay after the emit. Thus the calling code may make progress more quickly, but depending on the context, it may also flush/emit before returning from printk.

In my view, with or without this series, there are no guarantees that you will see 'A' and 'B'. And in any case, achieving the functionality for debugging required you to modify the printk anyway.

Quoted 2 lines

So please leave the delay on the calling side - it is helpfull there.

If you want to ensure printk is synchronous, perhaps you could call nbcon_cpu_emergency_enter() prior to your printk, or perhaps there are already printk wrappers that do somthing similar whilst debugging?

Would that provide a more reliable way to guarantee output?

On Mon, 6 Jul 2026 18:05:06 +0100
Andrew Murray <[email protected]> wrote:

Hi Andrew,

Quoted 31 lines

Quoted 29 lines · Benedikt Spranger

Quoted 4 lines · On Tue, 30 Jun 2026 17:35:59 +0100 Andrew Murray…

The printk_delay and boot_delay features are helpful for debugging as kernel output can be slowed down during boot allowing messages to be seen before scrolling off the screen, or to correlate timing between some physical event and console output.

By now, it slows down the boot process, which is the handy part of that feature.

Quoted 6 lines

However, since the introduction of nbcon and the legacy printer thread for PREEMPT_RT kernels, printk records are now emited to the console asynchronously to the caller of printk. Thus, any printk delay added by boot_delay/printk_delay continues to slow down the calling process but may not have any impact to the rate in which records are emited to the console.

Using this feature to slow down the boot/suspend/resume process and implicit make printk() happen, is the usefull part of that feature. Imagine this sequence (which hit me on suspend/resume on i.MX after shutting down all secondary CPUs)

printk("A");
(do some stuff)
printk("B");
read from peripheral --> system got stuck here since peripheral
was not clocked or powered or both any more.

The delay (and later on a ugly patch to make printk() synchrounous) helped to locate where the failed access happend. JTAG did not help, since the CPU got stuck --> no JTAG communication to that CPU.

Quoted 4 lines

I understand the use-case, you sprinkle printk's so you can find the point where a read to a register causes the CPU to stop. This requires that the printk happens before the read, and the output from the printk is printed before the read.

Enabling existing debug features in the kernel was a good start.

Quoted 3 lines

Quoted 2 lines

With your purposed change you *may* see "A", but never "B". Quite challenging...

At present you may see 'A' and you may see 'B'.

That's correct.

Quoted 1 line

Prior to the changes in this patchset, and assuming an nbcon console

iMX swtched over to nbcon, so your assumption is correct.

Quoted 3 lines

(which may not be your usecase, but is perhaps representative of future use-cases), then the printk delay will always happen within the call to printk (and always before emitting).

Which is quite good, but can be better. (See the missing sync feature mentioned in Johns reply)

Quoted 3 lines

However, depending on the context, that printk call may return (and proceed to your CPU halting register read), before the message is actually emitted to the console. I.e. it's a race.

I am aware of that.

Quoted 4 lines

This series moves the delay to the emit side, as well as moving the delay after the emit. Thus the calling code may make progress more quickly, but depending on the context, it may also flush/emit before returning from printk.

Unfortunately it makes things worse.

Quoted 3 lines

In my view, with or without this series, there are no guarantees that you will see 'A' and 'B'. And in any case, achieving the functionality for debugging required you to modify the printk anyway.

The "sync" feature is on the TODO list as John mentioned.

Quoted 3 lines

Quoted 2 lines

So please leave the delay on the calling side - it is helpfull there.

Quoted 3 lines

If you want to ensure printk is synchronous, perhaps you could call nbcon_cpu_emergency_enter() prior to your printk, or perhaps there are already printk wrappers that do somthing similar whilst debugging?

As said I did an ugly hack and forced printk() to be synchronous.

Quoted 1 line

Would that provide a more reliable way to guarantee output?

It does.

To summarize this discussion:

+ Benedikt would prefer to add the synchronous mode before moving the delay from the printk() caller to the console emit code path.

+ The delay in the printk() caller code path did not guarantee the output but it increased the chance to see it.

+ The synchronous mode will be even more reliable than the delay in printk() caller path.

Please, let me know if I did not get it right,

John, did you have any plan how to add the synchronous mode, please? Does it look complicated?

I guess that we would somehow need to "mis-use" the emergency priority and force it everywhere by some global system setting.

Quoted 14 lines · Petr Mladek

To summarize this discussion:

+ Benedikt would prefer to add the synchronous mode before moving the delay from the printk() caller to the console emit code path.

+ The delay in the printk() caller code path did not guarantee the output but it increased the chance to see it.

+ The synchronous mode will be even more reliable than the delay in printk() caller path.

Please, let me know if I did not get it right,

Quoted 5 lines

John, did you have any plan how to add the synchronous mode, please? Does it look complicated?

I guess that we would somehow need to "mis-use" the emergency priority and force it everywhere by some global system setting.

The synchronous mode would rely on the driver being nbcon. I envision something like this:

kernel/printk/nbcon.c +0 -1

 		/* Bring the sequence in @ctxt up to date */
 		ctxt->seq = nbcon_seq_read(con);
 
---- END SYNC IDEA ----

BTW: The sync mode is the final piece so that PeterZ can start using mainline code for debugging by serial instead of his own workaround [0].

[0] https://git.kernel.org/pub/scm/linux/kernel/git/peterz/queue.git/log/?h=debug/experimental

Quoted 9 lines

The synchronous mode would rely on the driver being nbcon. I envision something like this:

---- BEGIN SYNC IDEA ----

kernel/printk/nbcon.c +0 -0

@@ -1200,7 +1200,7 @@ static bool nbcon_kthread_should_wakeup(struct console *con, struct nbcon_contex
 	cookie = console_srcu_read_lock();
 

kernel/printk/nbcon.c static bool nbcon_kthread_should_wakeup(struct console *con, struct nbcon_contex · line 1203

Quoted 3 lines

kernel/printk/nbcon.c +1 -1

 	flags = console_srcu_read_flags(con);
-	if (console_is_usable(con, flags, false)) {
+	if (!(flags & CON_SYNC) &&  console_is_usable(con, flags, false)) {

The dependency on con->flags means that the sync mode can be entered only in task context where synchronize_srcu() can be called. It might be good enough. But I am afraid that people are creative and would like to have even atomic variant sooner or later.

Also it will do the flush in NORMAL_PRIO which is good. But it might fail to get the context ownership when it is blocked, for example, by uart_port_lock() which might be even sleepable context in PREEMPT_RT kernel.

Quoted 9 lines · Petr Mladek

Quoted 9 lines

The synchronous mode would rely on the driver being nbcon. I envision something like this:

---- BEGIN SYNC IDEA ----

kernel/printk/nbcon.c +0 -0

@@ -1200,7 +1200,7 @@ static bool nbcon_kthread_should_wakeup(struct console *con, struct nbcon_contex
 	cookie = console_srcu_read_lock();
 

Quoted 8 lines

kernel/printk/nbcon.c static bool nbcon_kthread_should_wakeup(struct console *con, struct nbcon_contex · line 1203

Quoted 3 lines

kernel/printk/nbcon.c +1 -1

 	flags = console_srcu_read_flags(con);
-	if (console_is_usable(con, flags, false)) {
+	if (!(flags & CON_SYNC) &&  console_is_usable(con, flags, false)) {

The dependency on con->flags means that the sync mode can be entered only in task context where synchronize_srcu() can be called. It might be good enough. But I am afraid that people are creative and would like to have even atomic variant sooner or later.

You mean it can only be _modified_ in task context. Yes. I expect it is either specified as a boot arg or modified via some sysfs interface.

Quoted 4 lines

Also it will do the flush in NORMAL_PRIO which is good. But it might fail to get the context ownership when it is blocked, for example, by uart_port_lock() which might be even sleepable context in PREEMPT_RT kernel.

Indeed. This is the same limitation of the atomic printing in general. But I do not think this can be worked around during normal operation. Ignoring locks is not an option.

Now, the question is how to move forward. It would be nice to have the sync mode available before we add this boot/printk_delay clean up.

Would you have time to prepare and send a patch anytime soon, please?

Or I wonder whether Andrew Murray might try to create a patch based on your "SYNC IDEA".

Quoted 14 lines · Petr Mladek

To summarize this discussion:

+ Benedikt would prefer to add the synchronous mode before moving the delay from the printk() caller to the console emit code path.

+ The delay in the printk() caller code path did not guarantee the output but it increased the chance to see it.

+ The synchronous mode will be even more reliable than the delay in printk() caller path.

Please, let me know if I did not get it right,

Quoted 5 lines

John, did you have any plan how to add the synchronous mode, please? Does it look complicated?

I guess that we would somehow need to "mis-use" the emergency priority and force it everywhere by some global system setting.

The synchronous mode would rely on the driver being nbcon. I envision something like this:

---- BEGIN SYNC IDEA ----

kernel/printk/printk.c +0 -0

index 2fe9a963c823a..beb5bb3c037b5 100644

kernel/printk/nbcon.c +12 -5

index 4b03b019cd5ee..8f8f29f757614 100644
@@ -1200,7 +1200,7 @@ static bool nbcon_kthread_should_wakeup(struct console *con, struct nbcon_contex
        cookie = console_srcu_read_lock();
 
        flags = console_srcu_read_flags(con);
-       if (console_is_usable(con, flags, false)) {
+       if (!(flags & CON_SYNC) &&  console_is_usable(con, flags, false)) {
                /* Bring the sequence in @ctxt up to date */
                ctxt->seq = nbcon_seq_read(con);
 

@@ -1654,7 +1654,7 @@ static void nbcon_atomic_flush_pending_con(struct console *con, u64 stop_seq)
  *                                     write_atomic() callback
  * @stop_seq:                  Flush up until this record
  */
-static void __nbcon_atomic_flush_pending(u64 stop_seq)
+static void __nbcon_atomic_flush_pending(u64 stop_seq, bool sync_only)
 {
        struct console *con;
        int cookie;

@@ -1666,6 +1666,9 @@ static void __nbcon_atomic_flush_pending(u64 stop_seq)
                if (!(flags & CON_NBCON))
                        continue;
 
+               if (sync_only && !(flags & CON_SYNC))
+                       continue;
+
                if (!console_is_usable(con, flags, true))
                        continue;
 

@@ -1688,7 +1691,12 @@ static void __nbcon_atomic_flush_pending(u64 stop_seq)
  */
 void nbcon_atomic_flush_pending(void)
 {
-       __nbcon_atomic_flush_pending(prb_next_reserve_seq(prb));
+       __nbcon_atomic_flush_pending(prb_next_reserve_seq(prb), false);
+}
+
+void nbcon_atomic_flush_sync_pending(void)
+{
+       __nbcon_atomic_flush_pending(prb_next_reserve_seq(prb), true);
 }
 
 /**

@@ -1701,7 +1709,7 @@ void nbcon_atomic_flush_pending(void)
 void nbcon_atomic_flush_unsafe(void)
 {
        panic_nbcon_allow_unsafe_takeover = true;
-       __nbcon_atomic_flush_pending(prb_next_reserve_seq(prb));
+       __nbcon_atomic_flush_pending(prb_next_reserve_seq(prb), false);
        panic_nbcon_allow_unsafe_takeover = false;
 }
 
---- END SYNC IDEA ----

BTW: The sync mode is the final piece so that PeterZ can start using mainline code for debugging by serial instead of his own workaround [0].

John

[0] https://git.kernel.org/pub/scm/linux/kernel/git/peterz/queue.git/log/?h=debug/experimental

Quoted 2 lines

The synchronous mode would rely on the driver being nbcon. I envision something like this:

Is it possible to apply synchronous mode for both nbcon and legacy consoles?

For the debugging case Benedikt suggested (is this the main use case for this feature?), it would be helpful if a developer could indicate a preference for synchronous mode without first determining the console type.

Quoted 12 lines

---- BEGIN SYNC IDEA ----

kernel/printk/printk.c +2 -0

index 2fe9a963c823a..beb5bb3c037b5 100644
@@ -2456,6 +2456,8 @@ asmlinkage int vprintk_emit(int facility, int level,
 
        if (ft.nbcon_atomic)
                nbcon_atomic_flush_pending();
+       else if (have_nbcon_console_sync)
+               nbcon_atomic_flush_sync_pending();
 

kernel/printk/printk.c asmlinkage int vprintk_emit(int facility, int level, · line 2463

Quoted 2 lines

kernel/printk/printk.c +0 -0

        if (ft.nbcon_offload)
                nbcon_kthreads_wake();

My interest in misusing (not proposing that as a solution) the emergency mode, is that the flush mode is nicely abstracted by printk_get_console_flush_type. Depending on how you trigger the sync mode, could printk_get_console_flush_type be expanded to look at a flag and return ft.legacy_direct, ft.legacy_offload or ft.nbcon_atomic_sync ?