Re: [PATCH v2 3/4] printk: nbcon: move printk_delay to console emiting code

[Benedikt Spranger <b.spranger@linutronix.de>]

On Mon, 6 Jul 2026 18:05:06 +0100
Andrew Murray <amurray@thegoodpenguin.co.uk> wrote:

Hi Andrew,

> On Fri, 3 Jul 2026 at 15:56, Benedikt Spranger
> <b.spranger@linutronix.de> wrote:
> > On Tue, 30 Jun 2026 17:35:59 +0100
> > Andrew Murray <amurray@thegoodpenguin.co.uk> wrote:
> > > 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.
> >
> > > 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.
> 
> 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.

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

> Prior to the changes in this patchset, and assuming an nbcon console
iMX swtched over to nbcon, so your assumption is correct.

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

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

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

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

> > 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?
As said I did an ugly hack and forced printk() to be synchronous.

> Would that provide a more reliable way to guarantee output?
It does.

Regards
    Benedikt Spranger