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

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

[Paul E. McKenney]

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.

Thoughts?

							Thanx, Paul

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

[1]	The --kconfig argument is needed due to CONFIG_DEBUG_INFO Kconfig
	changes.  You can instead pull in -rcu commit f9993c8413d1
	("torture: Adjust to again produce debugging information"),
	which allows you to omit that --kconfig argument.

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

[Paul E. McKenney]

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;
 }

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

[John Ogness]

Hi Paul,

Thanks for looking into this! I am currently on vacation with family, so
my responses are limited. Some initial comments from me below...

On 2022-06-12, "Paul E. McKenney" <paulmck@kernel.org> wrote:
> 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.

For sure not this one.

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

Correct. It just triggers.

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

This is only useful if the context is guaranteed may_sleep().

What is _supposed_ to happen is that @system_state increases above
SYSTEM_RUNNING, which then causes direct printing to be used. So the
pr_emerg("Power down\n") in kernel_power_off() would directly flush all
remaining messages.

But if the threaded printers are already in the process of printing,
they block direct printing. That may be what we are seeing here.

What I find particularly interesting is that it is not the kthread-patch
that is causing the issue.

I will have some time tonight to take a closer look.

John Ogness

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

[Paul E. McKenney]

On Sun, Jun 12, 2022 at 06:09:10PM +0206, John Ogness wrote:
> Hi Paul,
> 
> Thanks for looking into this! I am currently on vacation with family, so
> my responses are limited. Some initial comments from me below...

First, this is not an emergency.  I have a good workaround that just got
done passing significant rcutorture testing.  This means that I can port
my RCU changes to v5.19-rc1/2 and get on with other testing.

So please ignore this for the rest of your time away, and have a great
time with your family!!!

> On 2022-06-12, "Paul E. McKenney" <paulmck@kernel.org> wrote:
> > 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.
> 
> For sure not this one.
> 
> > 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.
> 
> Correct. It just triggers.
> 
> > 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.
> 
> This is only useful if the context is guaranteed may_sleep().

Which is the case when called from torture_shutdown().

But it does seem to be common to invoke kernel_power_off() from things
like interrupt handlers.  Which means that putting the pr_flush() in
kernel_power_off() would be a bad idea given that we cannot detect
non-preemptible regions of code with CONFIG_PREEMPT_NONE=y kernels.
(That again!)

So any fix within kernel_power_off() would be a bit "interesting".

> What is _supposed_ to happen is that @system_state increases above
> SYSTEM_RUNNING, which then causes direct printing to be used. So the
> pr_emerg("Power down\n") in kernel_power_off() would directly flush all
> remaining messages.
> 
> But if the threaded printers are already in the process of printing,
> they block direct printing. That may be what we are seeing here.

Given that rcutorture can be a bit chatty at shutdown time, my guess
is that the threaded printers are already in the process of printing.

> What I find particularly interesting is that it is not the kthread-patch
> that is causing the issue.

I do know that feeling!

> I will have some time tonight to take a closer look.

Please wait until you are back from your vacation.  Given that I now
have a workaround, which might be as good a fix as there is, there is
no need to interrupt your vacation.

							Thanx, Paul

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

[John Ogness]

On 2022-06-10, "Paul E. McKenney" <paulmck@kernel.org> wrote:
> 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?

If you also compile with CONFIG_GDB_SCRIPTS=y then you can use the
defined "lx-dmesg" gdb command to see if the messages are in the
ringbuffer.

(You may need to add:

add-auto-load-safe-path /path/to/linux/scripts/gdb/vmlinux-gdb.py

to your $HOME/.gdbinit)

But since you are hitting the breakpoint, the messages will be there.

> 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 --kconfig "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

Thanks. Nice helper scripts. With this I could easily reproduce the
issue.

As I suspected, the final printk's cannot direct print because the
kthread was printing. Using the below patch did seem to address your
problem. But this is probably not the way forward.

What I have not figured out is why this problem does not exist when only
the kthread patch (but not the "extend console_lock" patch) is
applied. Somehow the console_lock is magically providing some sort of
synchronization in the end. Or maybe it is just the increased lock
contention that helps out.

It seems we need some sort of console_flush_on_panic() for non-panic
situations that is not as violent as console_flush_on_panic().

@Petr, does it make sense to add the below patch to mainline? It is only
marginally helpful because it performs the direct printing in the wrong
context. Really we need that final pr_emerg("Power down\n") to be a
successful direct print so that the buffer is fully flushed before
hitting machine_power_off(). In fact, the below patch could make things
worse because the printing kthread could take over printing from that
final pr_emerg().

John Ogness

diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
index ea3dd55709e7..5950586008fa 100644
--- a/kernel/printk/printk.c
+++ b/kernel/printk/printk.c
@@ -3841,6 +3841,18 @@ static int printk_kthread_func(void *data)
 		console_kthread_printing_exit();
 
 		mutex_unlock(&con->lock);
+
+		/*
+		 * The kernel may have transitioned to a direct printing
+		 * state, but any printk calls may not have direct printed
+		 * because this thread was printing its message. Grab and
+		 * release the console lock to flush out any pending
+		 * messages on all consoles.
+		 */
+		if (allow_direct_printing()) {
+			console_lock();
+			console_unlock();
+		}
 	}
 
 	con_printk(KERN_INFO, con, "printing thread stopped\n");

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

[Paul E. McKenney]

On Mon, Jun 13, 2022 at 04:18:56AM +0206, John Ogness wrote:
> On 2022-06-10, "Paul E. McKenney" <paulmck@kernel.org> wrote:
> > 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?
> 
> If you also compile with CONFIG_GDB_SCRIPTS=y then you can use the
> defined "lx-dmesg" gdb command to see if the messages are in the
> ringbuffer.
> 
> (You may need to add:
> 
> add-auto-load-safe-path /path/to/linux/scripts/gdb/vmlinux-gdb.py
> 
> to your $HOME/.gdbinit)
> 
> But since you are hitting the breakpoint, the messages will be there.
> 
> > 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 --kconfig "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
> 
> Thanks. Nice helper scripts. With this I could easily reproduce the
> issue.

Glad that they worked nicely for you!

> As I suspected, the final printk's cannot direct print because the
> kthread was printing. Using the below patch did seem to address your
> problem. But this is probably not the way forward.

When I apply it, I still lose output, perhaps due to different timing?
Doing the pr_flush(1000, true) just before the call to kernel_power_off()
has been working quite well thus far, though.

							Thanx, Paul

> What I have not figured out is why this problem does not exist when only
> the kthread patch (but not the "extend console_lock" patch) is
> applied. Somehow the console_lock is magically providing some sort of
> synchronization in the end. Or maybe it is just the increased lock
> contention that helps out.
> 
> It seems we need some sort of console_flush_on_panic() for non-panic
> situations that is not as violent as console_flush_on_panic().
> 
> @Petr, does it make sense to add the below patch to mainline? It is only
> marginally helpful because it performs the direct printing in the wrong
> context. Really we need that final pr_emerg("Power down\n") to be a
> successful direct print so that the buffer is fully flushed before
> hitting machine_power_off(). In fact, the below patch could make things
> worse because the printing kthread could take over printing from that
> final pr_emerg().
> 
> John Ogness
> 
> diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
> index ea3dd55709e7..5950586008fa 100644
> --- a/kernel/printk/printk.c
> +++ b/kernel/printk/printk.c
> @@ -3841,6 +3841,18 @@ static int printk_kthread_func(void *data)
>  		console_kthread_printing_exit();
>  
>  		mutex_unlock(&con->lock);
> +
> +		/*
> +		 * The kernel may have transitioned to a direct printing
> +		 * state, but any printk calls may not have direct printed
> +		 * because this thread was printing its message. Grab and
> +		 * release the console lock to flush out any pending
> +		 * messages on all consoles.
> +		 */
> +		if (allow_direct_printing()) {
> +			console_lock();
> +			console_unlock();
> +		}
>  	}
>  
>  	con_printk(KERN_INFO, con, "printing thread stopped\n");

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

[John Ogness]

On 2022-06-12, "Paul E. McKenney" <paulmck@kernel.org> wrote:
>> As I suspected, the final printk's cannot direct print because the
>> kthread was printing. Using the below patch did seem to address your
>> problem. But this is probably not the way forward.
>
> When I apply it, I still lose output, perhaps due to different timing?
> Doing the pr_flush(1000, true) just before the call to kernel_power_off()
> has been working quite well thus far, though.

Your pr_flush() is appropriate for your RCU tests, but this is a problem
in general that needs to be addressed. I suppose we should start a new
thread for that. ;-)

During development we experimented with the idea of kthreads pausing
themselves whenever direct printing is activated. It was racey because
there are situations when direct printing is only temporarily active and
it was hard to coordinate who prints when direct printing becomes
inactive again. So we dropped that idea. However, in this situation the
system will not be disabling direct printing.

@Paul, can you try the below change instead? Until this has been
officially solved, you probably want to keep your pr_flush()
solution. (After all, that is exactly what pr_flush() is for.) But it
would be helpful if you could run this last test for us.

@Petr, I like the idea of the kthreads getting out of the way rather
than trying to direct print themselves (for this situation). It still
isn't optimal because that final pr_emerg("Power down\n") might come
before the kthread has finished its current line. But in that case the
kthread may not have much a chance to finish the printing anyway.

John Ogness

diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
index ea3dd55709e7..45c6c2b0b104 100644
--- a/kernel/printk/printk.c
+++ b/kernel/printk/printk.c
@@ -3729,7 +3729,9 @@ static bool printer_should_wake(struct console *con, u64 seq)
 		return true;
 
 	if (con->blocked ||
-	    console_kthreads_atomically_blocked()) {
+	    console_kthreads_atomically_blocked() ||
+	    system_state > SYSTEM_RUNNING ||
+	    oops_in_progress) {
 		return false;
 	}
 

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

[Petr Mladek]

On Mon 2022-06-13 11:10:19, John Ogness wrote:
> On 2022-06-12, "Paul E. McKenney" <paulmck@kernel.org> wrote:
> >> As I suspected, the final printk's cannot direct print because the
> >> kthread was printing. Using the below patch did seem to address your
> >> problem. But this is probably not the way forward.
> >
> > When I apply it, I still lose output, perhaps due to different timing?
> > Doing the pr_flush(1000, true) just before the call to kernel_power_off()
> > has been working quite well thus far, though.
> 
> Your pr_flush() is appropriate for your RCU tests, but this is a problem
> in general that needs to be addressed. I suppose we should start a new
> thread for that. ;-)
> 
> During development we experimented with the idea of kthreads pausing
> themselves whenever direct printing is activated. It was racey because
> there are situations when direct printing is only temporarily active and
> it was hard to coordinate who prints when direct printing becomes
> inactive again. So we dropped that idea. However, in this situation the
> system will not be disabling direct printing.
> 
> @Paul, can you try the below change instead? Until this has been
> officially solved, you probably want to keep your pr_flush()
> solution. (After all, that is exactly what pr_flush() is for.) But it
> would be helpful if you could run this last test for us.
> 
> @Petr, I like the idea of the kthreads getting out of the way rather
> than trying to direct print themselves (for this situation). It still
> isn't optimal because that final pr_emerg("Power down\n") might come
> before the kthread has finished its current line. But in that case the
> kthread may not have much a chance to finish the printing anyway.

I wonder if we could somehow combine it with pr_flush(timeout).

The kthread might bail-out when pr_flush() is running. It will
know that someone would continue printing. The timeout might
help to avoid a deadlock. We could somehow reuse
console_trylock_spinning() code here.


> John Ogness
> 
> diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
> index ea3dd55709e7..45c6c2b0b104 100644
> --- a/kernel/printk/printk.c
> +++ b/kernel/printk/printk.c
> @@ -3729,7 +3729,9 @@ static bool printer_should_wake(struct console *con, u64 seq)
>  		return true;
>  
>  	if (con->blocked ||
> -	    console_kthreads_atomically_blocked()) {
> +	    console_kthreads_atomically_blocked() ||
> +	    system_state > SYSTEM_RUNNING ||
> +	    oops_in_progress) {
>  		return false;
>  	}

Also this is an interesting idea. We know that panic() will try
to flush the messages. Well, panic() is not always called
after Oops.

Best Regards,
Petr

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

[Petr Mladek]

On Fri 2022-06-10 13:50:38, 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".

This means that the kthreads are probably more often sleeping with
con->lock when the pre-emtion is done by regular ticks.

We might want to wake them if we could call pr_flush().
But we could not do this in the generic panic() path.
It might cause deadlock when panic() is called from
scheduler code.

Pest Regards,
Petr

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

[Petr Mladek]

On Sun 2022-06-12 18:09:10, John Ogness wrote:
> Hi Paul,
> 
> Thanks for looking into this! I am currently on vacation with family, so
> my responses are limited. Some initial comments from me below...
> 
> On 2022-06-12, "Paul E. McKenney" <paulmck@kernel.org> wrote:
> > 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.
> 
> For sure not this one.
> 
> > 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.
> 
> Correct. It just triggers.
> 
> > 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.
> 
> This is only useful if the context is guaranteed may_sleep().
> 
> What is _supposed_ to happen is that @system_state increases above
> SYSTEM_RUNNING, which then causes direct printing to be used. So the
> pr_emerg("Power down\n") in kernel_power_off() would directly flush all
> remaining messages.
> 
> But if the threaded printers are already in the process of printing,
> they block direct printing. That may be what we are seeing here.
> 
> What I find particularly interesting is that it is not the kthread-patch
> that is causing the issue.

Yes, it is interesting :-)

I think that it is because the initial kthreads allowed to handover
console_lock() to another caller. It was removed when kthreads
started using the new con->lock mutex.

This might also be the reason why the extra
console_lock()/console_unlock() helped.

Best Regards,
Petr

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

[Petr Mladek]

On Mon 2022-06-13 12:32:08, Petr Mladek wrote:
> On Mon 2022-06-13 11:10:19, John Ogness wrote:
> > On 2022-06-12, "Paul E. McKenney" <paulmck@kernel.org> wrote:
> > >> As I suspected, the final printk's cannot direct print because the
> > >> kthread was printing. Using the below patch did seem to address your
> > >> problem. But this is probably not the way forward.
> > >
> > > When I apply it, I still lose output, perhaps due to different timing?
> > > Doing the pr_flush(1000, true) just before the call to kernel_power_off()
> > > has been working quite well thus far, though.
> > 
> > @Petr, I like the idea of the kthreads getting out of the way rather
> > than trying to direct print themselves (for this situation). It still
> > isn't optimal because that final pr_emerg("Power down\n") might come
> > before the kthread has finished its current line. But in that case the
> > kthread may not have much a chance to finish the printing anyway.
> 
> I wonder if we could somehow combine it with pr_flush(timeout).
> 
> The kthread might bail-out when pr_flush() is running. It will
> know that someone would continue printing. The timeout might
> help to avoid a deadlock. We could somehow reuse
> console_trylock_spinning() code here.
> > 
> > diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
> > index ea3dd55709e7..45c6c2b0b104 100644
> > --- a/kernel/printk/printk.c
> > +++ b/kernel/printk/printk.c
> > @@ -3729,7 +3729,9 @@ static bool printer_should_wake(struct console *con, u64 seq)
> >  		return true;
> >  
> >  	if (con->blocked ||
> > -	    console_kthreads_atomically_blocked()) {
> > +	    console_kthreads_atomically_blocked() ||
> > +	    system_state > SYSTEM_RUNNING ||
> > +	    oops_in_progress) {
> >  		return false;
> >  	}
> 
> Also this is an interesting idea. We know that panic() will try
> to flush the messages. Well, panic() is not always called
> after Oops.

I tried to combine the various approaches and findings into
the following patch.

It introduces try_block_console_kthread() function. It tries
to summon console_lock() so that it is later available for
printk().

The function causes that console kthreads will not longer
handle the messages. Also it waits until all kthreads leave
the critical section and allow to take the global console lock.

It can be safely called in atomic context because it uses
busy wait by udelay(). Infinite waiting is prevented by
timeout currectly hardcoded to 10s.

The function is used in panic() and kernel_shutdown_prepare()
when we know that the system is going down and kthreads will
not be usable any longer.


Problems:

  + Just the best effort.
  + Does not help on single CPU system.


Testing:

I tried Paul's RCU torture test few times. It always failed without
this patch and always succeded with this patch. If I got the resutls
corretly.


Possible improvements and alternative approaches:

   + Prevent console kthreads from sleeping in critical
     section. Replace mutex with a spinlock?

   + Allow to steal con->lock similar way like the global
     console_sem.

   + Modify console kthreads process priority to make them
     scheduled immediately on another CPU.


What do you think, please?


diff --git a/include/linux/printk.h b/include/linux/printk.h
index 10ec29bc0135..78f27ca15922 100644
--- a/include/linux/printk.h
+++ b/include/linux/printk.h
@@ -173,6 +173,7 @@ extern void printk_prefer_direct_enter(void);
 extern void printk_prefer_direct_exit(void);
 
 extern bool pr_flush(int timeout_ms, bool reset_on_progress);
+extern void try_block_console_kthreads(int timeout_ms);
 
 /*
  * Please don't use printk_ratelimit(), because it shares ratelimiting state
diff --git a/kernel/panic.c b/kernel/panic.c
index a3c758dba15a..4cf13c37bd08 100644
--- a/kernel/panic.c
+++ b/kernel/panic.c
@@ -297,6 +297,7 @@ void panic(const char *fmt, ...)
 		 * unfortunately means it may not be hardened to work in a
 		 * panic situation.
 		 */
+		try_block_console_kthreads(10000);
 		smp_send_stop();
 	} else {
 		/*
@@ -304,6 +305,7 @@ void panic(const char *fmt, ...)
 		 * kmsg_dump, we will need architecture dependent extra
 		 * works in addition to stopping other CPUs.
 		 */
+		try_block_console_kthreads(10000);
 		crash_smp_send_stop();
 	}
 
diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
index ea3dd55709e7..0bcd4f5cf2fc 100644
--- a/kernel/printk/printk.c
+++ b/kernel/printk/printk.c
@@ -250,6 +250,8 @@ static atomic_t console_kthreads_active = ATOMIC_INIT(0);
 #define console_kthread_printing_exit() \
 	atomic_dec(&console_kthreads_active)
 
+static bool block_console_kthreads;
+
 /*
  * Helper macros to handle lockdep when locking/unlocking console_sem. We use
  * macros instead of functions so that _RET_IP_ contains useful information.
@@ -3686,6 +3688,24 @@ bool pr_flush(int timeout_ms, bool reset_on_progress)
 }
 EXPORT_SYMBOL(pr_flush);
 
+void try_block_console_kthreads(int timeout_ms)
+{
+	block_console_kthreads = true;
+
+	while (timeout_ms > 0) {
+		if (console_trylock()) {
+			console_unlock();
+			return;
+		}
+
+		udelay(1000);
+		timeout_ms -= 1;
+	}
+
+	/* Failed to block console kthreads. Let them do the job. */
+	block_console_kthreads = false;
+}
+
 static void __printk_fallback_preferred_direct(void)
 {
 	printk_prefer_direct_enter();
@@ -3729,7 +3749,8 @@ static bool printer_should_wake(struct console *con, u64 seq)
 		return true;
 
 	if (con->blocked ||
-	    console_kthreads_atomically_blocked()) {
+	    console_kthreads_atomically_blocked() ||
+	    block_console_kthreads) {
 		return false;
 	}
 
diff --git a/kernel/reboot.c b/kernel/reboot.c
index a091145ee710..222bdd076cd0 100644
--- a/kernel/reboot.c
+++ b/kernel/reboot.c
@@ -270,6 +270,7 @@ static void kernel_shutdown_prepare(enum system_states state)
 	blocking_notifier_call_chain(&reboot_notifier_list,
 		(state == SYSTEM_HALT) ? SYS_HALT : SYS_POWER_OFF, NULL);
 	system_state = state;
+	try_block_console_kthreads(10000);
 	usermodehelper_disable();
 	device_shutdown();
 }

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

[Paul E. McKenney]

On Mon, Jun 13, 2022 at 11:10:19AM +0206, John Ogness wrote:
> On 2022-06-12, "Paul E. McKenney" <paulmck@kernel.org> wrote:
> >> As I suspected, the final printk's cannot direct print because the
> >> kthread was printing. Using the below patch did seem to address your
> >> problem. But this is probably not the way forward.
> >
> > When I apply it, I still lose output, perhaps due to different timing?
> > Doing the pr_flush(1000, true) just before the call to kernel_power_off()
> > has been working quite well thus far, though.
> 
> Your pr_flush() is appropriate for your RCU tests, but this is a problem
> in general that needs to be addressed. I suppose we should start a new
> thread for that. ;-)
> 
> During development we experimented with the idea of kthreads pausing
> themselves whenever direct printing is activated. It was racey because
> there are situations when direct printing is only temporarily active and
> it was hard to coordinate who prints when direct printing becomes
> inactive again. So we dropped that idea. However, in this situation the
> system will not be disabling direct printing.
> 
> @Paul, can you try the below change instead? Until this has been
> officially solved, you probably want to keep your pr_flush()
> solution. (After all, that is exactly what pr_flush() is for.) But it
> would be helpful if you could run this last test for us.
> 
> @Petr, I like the idea of the kthreads getting out of the way rather
> than trying to direct print themselves (for this situation). It still
> isn't optimal because that final pr_emerg("Power down\n") might come
> before the kthread has finished its current line. But in that case the
> kthread may not have much a chance to finish the printing anyway.
> 
> John Ogness
> 
> diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
> index ea3dd55709e7..45c6c2b0b104 100644
> --- a/kernel/printk/printk.c
> +++ b/kernel/printk/printk.c
> @@ -3729,7 +3729,9 @@ static bool printer_should_wake(struct console *con, u64 seq)
>  		return true;
>  
>  	if (con->blocked ||
> -	    console_kthreads_atomically_blocked()) {
> +	    console_kthreads_atomically_blocked() ||
> +	    system_state > SYSTEM_RUNNING ||
> +	    oops_in_progress) {
>  		return false;
>  	}

And this one works for me, thank you!!!

On to Petr's patch...

							Thanx, Paul

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

[Paul E. McKenney]

On Mon, Jun 13, 2022 at 05:07:47PM +0200, Petr Mladek wrote:
> On Mon 2022-06-13 12:32:08, Petr Mladek wrote:
> > On Mon 2022-06-13 11:10:19, John Ogness wrote:
> > > On 2022-06-12, "Paul E. McKenney" <paulmck@kernel.org> wrote:
> > > >> As I suspected, the final printk's cannot direct print because the
> > > >> kthread was printing. Using the below patch did seem to address your
> > > >> problem. But this is probably not the way forward.
> > > >
> > > > When I apply it, I still lose output, perhaps due to different timing?
> > > > Doing the pr_flush(1000, true) just before the call to kernel_power_off()
> > > > has been working quite well thus far, though.
> > > 
> > > @Petr, I like the idea of the kthreads getting out of the way rather
> > > than trying to direct print themselves (for this situation). It still
> > > isn't optimal because that final pr_emerg("Power down\n") might come
> > > before the kthread has finished its current line. But in that case the
> > > kthread may not have much a chance to finish the printing anyway.
> > 
> > I wonder if we could somehow combine it with pr_flush(timeout).
> > 
> > The kthread might bail-out when pr_flush() is running. It will
> > know that someone would continue printing. The timeout might
> > help to avoid a deadlock. We could somehow reuse
> > console_trylock_spinning() code here.
> > > 
> > > diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
> > > index ea3dd55709e7..45c6c2b0b104 100644
> > > --- a/kernel/printk/printk.c
> > > +++ b/kernel/printk/printk.c
> > > @@ -3729,7 +3729,9 @@ static bool printer_should_wake(struct console *con, u64 seq)
> > >  		return true;
> > >  
> > >  	if (con->blocked ||
> > > -	    console_kthreads_atomically_blocked()) {
> > > +	    console_kthreads_atomically_blocked() ||
> > > +	    system_state > SYSTEM_RUNNING ||
> > > +	    oops_in_progress) {
> > >  		return false;
> > >  	}
> > 
> > Also this is an interesting idea. We know that panic() will try
> > to flush the messages. Well, panic() is not always called
> > after Oops.
> 
> I tried to combine the various approaches and findings into
> the following patch.
> 
> It introduces try_block_console_kthread() function. It tries
> to summon console_lock() so that it is later available for
> printk().
> 
> The function causes that console kthreads will not longer
> handle the messages. Also it waits until all kthreads leave
> the critical section and allow to take the global console lock.
> 
> It can be safely called in atomic context because it uses
> busy wait by udelay(). Infinite waiting is prevented by
> timeout currectly hardcoded to 10s.
> 
> The function is used in panic() and kernel_shutdown_prepare()
> when we know that the system is going down and kthreads will
> not be usable any longer.
> 
> 
> Problems:
> 
>   + Just the best effort.
>   + Does not help on single CPU system.
> 
> 
> Testing:
> 
> I tried Paul's RCU torture test few times. It always failed without
> this patch and always succeded with this patch. If I got the resutls
> corretly.
> 
> 
> Possible improvements and alternative approaches:
> 
>    + Prevent console kthreads from sleeping in critical
>      section. Replace mutex with a spinlock?
> 
>    + Allow to steal con->lock similar way like the global
>      console_sem.
> 
>    + Modify console kthreads process priority to make them
>      scheduled immediately on another CPU.
> 
> 
> What do you think, please?

And rcutorture thinks well of this one, also.  ;-)

Thank you both!!!

							Thanx, Paul

> diff --git a/include/linux/printk.h b/include/linux/printk.h
> index 10ec29bc0135..78f27ca15922 100644
> --- a/include/linux/printk.h
> +++ b/include/linux/printk.h
> @@ -173,6 +173,7 @@ extern void printk_prefer_direct_enter(void);
>  extern void printk_prefer_direct_exit(void);
>  
>  extern bool pr_flush(int timeout_ms, bool reset_on_progress);
> +extern void try_block_console_kthreads(int timeout_ms);
>  
>  /*
>   * Please don't use printk_ratelimit(), because it shares ratelimiting state
> diff --git a/kernel/panic.c b/kernel/panic.c
> index a3c758dba15a..4cf13c37bd08 100644
> --- a/kernel/panic.c
> +++ b/kernel/panic.c
> @@ -297,6 +297,7 @@ void panic(const char *fmt, ...)
>  		 * unfortunately means it may not be hardened to work in a
>  		 * panic situation.
>  		 */
> +		try_block_console_kthreads(10000);
>  		smp_send_stop();
>  	} else {
>  		/*
> @@ -304,6 +305,7 @@ void panic(const char *fmt, ...)
>  		 * kmsg_dump, we will need architecture dependent extra
>  		 * works in addition to stopping other CPUs.
>  		 */
> +		try_block_console_kthreads(10000);
>  		crash_smp_send_stop();
>  	}
>  
> diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
> index ea3dd55709e7..0bcd4f5cf2fc 100644
> --- a/kernel/printk/printk.c
> +++ b/kernel/printk/printk.c
> @@ -250,6 +250,8 @@ static atomic_t console_kthreads_active = ATOMIC_INIT(0);
>  #define console_kthread_printing_exit() \
>  	atomic_dec(&console_kthreads_active)
>  
> +static bool block_console_kthreads;
> +
>  /*
>   * Helper macros to handle lockdep when locking/unlocking console_sem. We use
>   * macros instead of functions so that _RET_IP_ contains useful information.
> @@ -3686,6 +3688,24 @@ bool pr_flush(int timeout_ms, bool reset_on_progress)
>  }
>  EXPORT_SYMBOL(pr_flush);
>  
> +void try_block_console_kthreads(int timeout_ms)
> +{
> +	block_console_kthreads = true;
> +
> +	while (timeout_ms > 0) {
> +		if (console_trylock()) {
> +			console_unlock();
> +			return;
> +		}
> +
> +		udelay(1000);
> +		timeout_ms -= 1;
> +	}
> +
> +	/* Failed to block console kthreads. Let them do the job. */
> +	block_console_kthreads = false;
> +}
> +
>  static void __printk_fallback_preferred_direct(void)
>  {
>  	printk_prefer_direct_enter();
> @@ -3729,7 +3749,8 @@ static bool printer_should_wake(struct console *con, u64 seq)
>  		return true;
>  
>  	if (con->blocked ||
> -	    console_kthreads_atomically_blocked()) {
> +	    console_kthreads_atomically_blocked() ||
> +	    block_console_kthreads) {
>  		return false;
>  	}
>  
> diff --git a/kernel/reboot.c b/kernel/reboot.c
> index a091145ee710..222bdd076cd0 100644
> --- a/kernel/reboot.c
> +++ b/kernel/reboot.c
> @@ -270,6 +270,7 @@ static void kernel_shutdown_prepare(enum system_states state)
>  	blocking_notifier_call_chain(&reboot_notifier_list,
>  		(state == SYSTEM_HALT) ? SYS_HALT : SYS_POWER_OFF, NULL);
>  	system_state = state;
> +	try_block_console_kthreads(10000);
>  	usermodehelper_disable();
>  	device_shutdown();
>  }