Re: [BUG] 8e274732115f ("printk: extend console_lock for per-console locking")

["Paul E. McKenney" <paulmck@kernel.org>]

On Fri, Jun 10, 2022 at 01:50:38PM -0700, Paul E. McKenney wrote:
> Hello, John,
> 
> I have started getting rcutorture shutdown-time hangs when running
> against recent mainline, and bisected back to the 8e274732115f ("printk:
> extend console_lock for per-console locking") commit.  These hangs go
> away (or at least their probability drops dramatically) if I build with
> CONFIG_PREEMPTION=n -and- CONFIG_NO_HZ=y (not n!), at least assuming
> that I also boot with "nohz_full=0-N".
> 
> Attempts to debug using rcutorture's "--gdb" argument result in
> "[Inferior 1 (process 1) exited normally]", but with the same truncated
> console-log output as when running without "--gdb".  This suggests
> that the kernel really did run to completion and halt as expected,
> but that the shutdown-time printk() output was lost.  Furthermore, if I
> use the gdb "hbreak" command to set a breakpoint at kernel_power_off(),
> it really does hit that breakpoint.  This would not happen in the case
> of a kernel hang.
> 
> So, given that I can hit that breakpoint, what should I ask gdb to
> show me?
> 
> Alternatively, this reproduces on a variety of x86 platforms, so you
> should be able reproduce it as follows [1]:
> 
> 	git checkout v5.19-rc1
> 	tools/testing/selftests/rcutorture/bin/kvm.sh --allcpus --duration 2 --configs "TREE01" --gdb "CONFIG_DEBUG_INFO_NONE=n CONFIG_DEBUG_INFO_DWARF_TOOLCHAIN_DEFAULT=y" --trust-make
> 
> This builds a kernel, boots it, and then tells you how to launch gdb
> (presumably in some other window).  Once you give launch gdb and give
> it the suggested commands, the kernel runs for two minutes under qemu,
> then shuts down.  I used the following gdb commands to set the breakpoint
> and run the kernel:
> 
> 	target remote :1234  # suggested by the rcutorture script
> 	hbreak kernel_power_off  # added by me
> 	continue  # suggested by the rcutorture script
> 
> Or leave out the "gdb" if you prefer some other debugging approach.

And the patch below takes care of things in (admittedly quite light)
testing thus far.  What it does is add ten seconds of pure delay before
rcutorture shuts down the system.  Presumably, this delay gives printk()
the time that it needs to flush its buffers.  In the configurations
that I have tested thus far, anyway.

So what should I be doing instead?

o	console_flush_on_panic() seems like strong medicine, but might
	be the right thing to do.  The bit about proceeding even though
	it failed to acquire the lock doesn't look good for non-panic use.

o	printk_trigger_flush() has an attractive name, but it looks
	like it only just starts the flush rather than waiting for it
	to finish.

o	pr_flush(1000, true) looks quite interesting, and also seems to
	work in a few quick tests, so I will continue playing with that.

Right now, I am putting this immediately before the kernel/torture.c
call to kernel_power_off().  I could argue that kernel_power_off()
should flush the printk() buffers as part of a "clean system power_off",
to quote the kernel_power_off() header comment.  Or is there some reason
why kernel_power_off() should leave printk() buffers unflushed?

							Thanx, Paul

------------------------------------------------------------------------

diff --git a/kernel/torture.c b/kernel/torture.c
index 789aeb0e1159c..bbdec930ea21f 100644
--- a/kernel/torture.c
+++ b/kernel/torture.c
@@ -651,6 +651,7 @@ static int torture_shutdown(void *arg)
 		VERBOSE_TOROUT_STRING("No torture_shutdown_hook(), skipping.");
 	if (ftrace_dump_at_shutdown)
 		rcu_ftrace_dump(DUMP_ALL);
+	schedule_timeout_uninterruptible(HZ * 10);
 	kernel_power_off();	/* Shut down the system. */
 	return 0;
 }