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.
If there is no backlog, pr_flush() returns immediately.
I recommend _not_ using timeout_ms=-1 here, in case the kthread cannot
be scheduled (for whatever reason).
> ------------------------------------------------------------------------
>
> 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.
> #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.
> kmsg_dump(KMSG_DUMP_SHUTDOWN);
> machine_power_off();
> }
John Ogness
