On Wed, Feb 05, 2025 at 10:28:06PM +0106, John Ogness wrote:
> On 2025-02-05, "Paul E. McKenney" <paulmck@xxxxxxxxxx> wrote:
> >> Would it make sense to put a call to pr_flush() at the beginning of the
> >> kernel_power_off() function? I suspect that would take care of much
> >> more than just rcutorture.
> >>
> >> Or maybe after the pr_emerg("Power down\n"), since that is normally
> >> the last thing that shows up on rcutorture's console logs.
>
> Yes, after the pr_emerg("Power down\n"), as in your patch below.
>
> > And that does the trick! I specified 500ms, but maybe -1 would be
> > better? You tell me! ;-)
>
> I probably would have chosen 1000ms, but if the kthread has made no
> forward progress after a few max timeslices, it probably is dead or will
> not be scheduled anyway.
I picked 500ms randomly, so I am happy to make it be 1000ms.
> If there is no backlog, pr_flush() returns immediately.
OK, so I don't need to add "if (IS_ENABLED(CONFIG_PREEMPT_RT))" to guard
it, then?
> I recommend _not_ using timeout_ms=-1 here, in case the kthread cannot
> be scheduled (for whatever reason).
Sounds eminently reasonable to me!
> > ------------------------------------------------------------------------
> >
> > commit 172b692a79ec5801eab57cb55d2f9c398f244c62
> > Author: Paul E. McKenney <paulmck@xxxxxxxxxx>
> > Date: Wed Feb 5 12:27:23 2025 -0800
> >
> > printk: Flush console log from kernel_power_off()
> >
> > Kernels built with CONFIG_PREEMPT_RT=y can lose significant console output
> > and shutdown time, which hides shutdown-time RCU issues from rcutorture.
> > Therefore, make pr_flush() public and invoke it after then last print
> > in kernel_power_off().
> >
> > Signed-off-by: Paul E. McKenney <paulmck@xxxxxxxxxx>
> > Cc: Petr Mladek <pmladek@xxxxxxxx>
> > Cc: Steven Rostedt <rostedt@xxxxxxxxxxx>
> > Cc: John Ogness <john.ogness@xxxxxxxxxxxxx>
> > Cc: Sergey Senozhatsky <senozhatsky@xxxxxxxxxxxx>
> >
> > diff --git a/include/linux/printk.h b/include/linux/printk.h
> > index 4217a9f412b2..b3e88ff1ecc3 100644
> > --- a/include/linux/printk.h
> > +++ b/include/linux/printk.h
> > @@ -806,4 +806,6 @@ static inline void print_hex_dump_debug(const char *prefix_str, int prefix_type,
> > #define print_hex_dump_bytes(prefix_str, prefix_type, buf, len) \
> > print_hex_dump_debug(prefix_str, prefix_type, 16, 1, buf, len, true)
> >
> > +
> > +bool pr_flush(int timeout_ms, bool reset_on_progress);
>
> This will fail to link for !CONFIG_PRINTK.
>
> In kernel/printk/printk.c currently there is:
>
> #ifdef CONFIG_PRINTK
> static bool pr_flush(int timeout_ms, bool reset_on_progress);
> #else
> static bool pr_flush(int timeout_ms, bool reset_on_progress) { return true; }
> #endif
>
> This would need to move to include/linux/printk.h
>
> There you will find an existing CONFIG_PRINTK if/else block to move
> those to.
Thank you, will do!
> > #endif
> > diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
> > index 80910bc3470c..e0c6e5a99897 100644
> > --- a/kernel/printk/printk.c
> > +++ b/kernel/printk/printk.c
> > @@ -2461,7 +2461,7 @@ asmlinkage __visible int _printk(const char *fmt, ...)
> > }
> > EXPORT_SYMBOL(_printk);
> >
> > -static bool pr_flush(int timeout_ms, bool reset_on_progress);
> > +bool pr_flush(int timeout_ms, bool reset_on_progress);
> > static bool __pr_flush(struct console *con, int timeout_ms, bool reset_on_progress);
> >
> > #else /* CONFIG_PRINTK */
> > @@ -4466,7 +4466,7 @@ static bool __pr_flush(struct console *con, int timeout_ms, bool reset_on_progre
> > * Context: Process context. May sleep while acquiring console lock.
> > * Return: true if all usable printers are caught up.
> > */
> > -static bool pr_flush(int timeout_ms, bool reset_on_progress)
> > +bool pr_flush(int timeout_ms, bool reset_on_progress)
> > {
> > return __pr_flush(NULL, timeout_ms, reset_on_progress);
> > }
> > diff --git a/kernel/reboot.c b/kernel/reboot.c
> > index a701000bab34..3448e6ae3556 100644
> > --- a/kernel/reboot.c
> > +++ b/kernel/reboot.c
> > @@ -704,6 +704,7 @@ void kernel_power_off(void)
> > migrate_to_reboot_cpu();
> > syscore_shutdown();
> > pr_emerg("Power down\n");
> > + pr_flush(500, 1);
>
> I would have chosen:
>
> pr_flush(1000, true);
>
> but I really don't have an argument either way.
Hey, of the two of us, you are the printk() expert, so I will make it
be 1000. ;-)
Thanx, Paul
> > kmsg_dump(KMSG_DUMP_SHUTDOWN);
> > machine_power_off();
> > }
>
> John Ogness
