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

[Petr Mladek <pmladek@suse.com>]

On Sun 2026-06-14 13:55:31, Andrew Murray wrote:
> On Mon, 8 Jun 2026 at 16:25, Petr Mladek <pmladek@suse.com> wrote:
> >
> > On Mon 2026-06-01 00:17:39, Andrew Murray 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.
> > >
> > > 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.
> > >
> > > Let's address this by moving the printk delay from the calling code
> > > to the console emiting code instead. Whilst this ensures that delays
> > > are still observed (especially for slower consoles), it doesn't improve
> > > the use-case of using boot_delay/printk_delay to correlate timings
> > > between physical events and console output.
> > >
> > > diff --git a/kernel/printk/nbcon.c b/kernel/printk/nbcon.c
> > > index d7044a7a214bdd4537a5e20d876d99bc3ffe8b3a..a507a2fed5bf4366e24330f763b842a698ecf6f7 100644
> > > --- a/kernel/printk/nbcon.c
> > > +++ b/kernel/printk/nbcon.c
> > > @@ -1267,11 +1267,16 @@ static int nbcon_kthread_func(void *__console)
> > >
> > >               con_flags = console_srcu_read_flags(con);
> > >
> > > +             wctxt.len = 0;
> > > +
> > >               if (console_is_usable(con, con_flags, false))
> > >                       backlog = nbcon_emit_one(&wctxt, false);
> > >
> > >               console_srcu_read_unlock(cookie);
> > >
> > > +             if (backlog && wctxt.len > 0)
> >
> > Heh, this is tricky. It might probably work but it is not guarantted
> > by design.
> >
> > The "backlog" name is a bit misleading. The value is basically
> > wctxt.ctxt.backlog. The real meaning is that printk_get_next_message()
> > was able to read a message. It means that there _was_ a backlog.
> > But it is not clear whether there are still pending messages or not.
> 
> Yes I found that to be the case (see my notes in the cover letter) -
> backlog is only true if a record was successfully retrieved, though
> that record may be one that is suppressed.
> 
> 
> >
> > Also it is not clear that whether the message was pushed to the
> > console or not. It might have been supressed in which case
> > (wctxt.len == 0). But it might also be emitted only partially
> > when a higher priority context took over the console context
> > ownership.
> 
> You say it might probably work but isn't guaranteed by design, I'm
> struggling to see what I've missed...

Ah, I am sorry I was not clear enough, see below.

> As far as I could tell, nbcon_emit_next_record only returns true when
> a record has been printed and it still has context. The only exception
> to that is where pmsg.outbuf_len is zero (suppressed), in which case
> it may return true. Thus if (nbcon_emit_next_record() &&
> !pmsg.outbuf_len) then we can be sure a record was printed. In order
> to apply this test from the various callers...
> 
> for nbcon_emit_one - this returns ctxt->backlog if
> nbcon_emit_next_record returned true. But backlog is *always* true
> when nbcon_emit_next_record returns true. Thus the test of (backlog &&
> wctxt.len) is equivelant to (nbcon_emit_next_record() &&
> !pmsg.outbuf_len).
> 
> So I still think this implementation is valid.

You are right. Your change would work with the current code.

When I talked about the design I meant that we "did not expect"
that anyone would need to check whether nbcon_emit_next_record()
really emitted something.

Or better to say, the design has always been complicated.
And we had to review it when the callers needed anything.
For example, see see the commit ba00f7c4d0051e351e
("printk: console_flush_one_record() code cleanup").
We did it before commit 1bc9a28f076fa68736 ("printk:
Use console_flush_one_record for legacy printer kthread").

And the check if (backlog && wctxt.len > 0) is not a good design.
I would say that it depends on internal implementation details
which might change in the future. Also the variable name "backlog"
does not well describe the real behavior.

This is why I suggested to add the @emitted field into
struct nbcon_context instead. It might look like it adds some
complexity. But the semantic of this field will be clear and
simple. So, it should make the life easier in the long term.

> > I would prefer to explicitely set some flag when
> > nbcon_emit_next_record() really called con->write*().
> > See below.
> >
> > > +                     printk_delay(false);
> > > +
> > >               cond_resched();
> > >
> > >       } while (backlog);
> > > @@ -1595,7 +1604,9 @@ static int __nbcon_atomic_flush_pending_con(struct console *con, u64 stop_seq)
> > >                       nbcon_context_release(ctxt);
> > >               }
> > >
> > > -             if (!ctxt->backlog) {
> > > +             if (ctxt->backlog && wctxt.len > 0) {
> > > +                     printk_delay(true);
> > > +             } else {
> >
> > This changes the semantic. The original code call this when
> > no message was read. The new code would call this path also
> > when the output was suppressed. It would probably work.
> > But still.
> 
> Ah, good spot! I missed that.
> 
> 
> >
> > >                       /* Are there reserved but not yet finalized records? */
> > >                       if (nbcon_seq_read(con) < stop_seq)
> > >                               err = -ENOENT;
> >
> >
> > As mentioned above, I would add a flag which would be set when
> > con->write*() was called.
> 
> I'm not sure why I tried to avoid adding members to nbcon_context, but
> I prefer your solution, it isn't so fragile, and makes it easier to
> understand. I'll update for my next revision.

Uff :-)

> >
> > It modifies the type of unsafe_takeover in struct nbcon_write_context.
> > But it actually makes it more compatible with struct nbcon_state.
> 
> What is the intent of this change (bool to unsigned char)?

I meant that my proposed change switched it from bool to 1 bit.
But I see that it will not be fully compatible anyway because it is

   unsigned int unsafe_takeover	: 1 in struct nbcon_state

vs
   unsigned char unsafe_takeover : 1 in struct struct nbcon_write_context.

Honestly, I am not sure what C standard says about bool vs. bit
and bit vs. bit operations. But I believe that compilers would
do the right thing in both cases. Anyway, bit vs. bit sounds cleaner.


> > My proposal (on top of this patch):
> >
> > diff --git a/include/linux/console.h b/include/linux/console.h
> > index 5520e4477ad7..5a86942e55ef 100644
> > --- a/include/linux/console.h
> > +++ b/include/linux/console.h
> > @@ -290,6 +290,7 @@ 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 tried 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 +299,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
> >  #ifdef CONFIG_PRINTK_EXECUTION_CTX
> >         int                     cpu;
> >         pid_t                   pid;

Best Regards,
Petr