[PATCH v3 0/4] printk: reduce deadlocks during panic

[PATCH v3 0/4] printk: reduce deadlocks during panic

[Stephen Brennan]

When a caller writes heavily to the kernel log (e.g. writing to
/dev/kmsg in a loop) while another panics, there's currently a high
likelihood of a deadlock (see patch 2 for the full description of this
deadlock).

The principle fix is to disable the optimistic spin once panic_cpu is
set, so the panic CPU doesn't spin waiting for a halted CPU to hand over
the console_sem.

However, this exposed us to a livelock situation, where the panic CPU
holds the console_sem, and another CPU could fill up the log buffer
faster than the consoles could drain it, preventing the panic from
progressing and halting the other CPUs. To avoid this, patch 3 adds a
mechanism to suppress printk (from non-panic-CPU) during panic, if we
reach a threshold of dropped messages.

A major goal with all of these patches is to try to decrease the
likelihood that another CPU is holding the console_sem when we halt it
in panic(). This reduces the odds of needing to break locks and
potentially encountering further deadlocks with the console drivers.

To test, I use the following script, kmsg_panic.sh:

    #!/bin/bash
    date
    # 991 chars (based on log buffer size):
    chars="$(printf 'a%.0s' {1..991})"
    while :; do
        echo $chars > /dev/kmsg
    done &
    echo c > /proc/sysrq-trigger &
    date
    exit

I defined a hang as any time the system did not reboot to a login prompt
on the serial console within 60 seconds. Here are the statistics on
hangs using this script, before and after the patch.

before:  776 hangs / 1484 trials - 52.3%
after :    0 hangs /  15k trials -  0.0%

v3:
    Some mild style changes, none of which affect testing (which has run
    continuously and is now over 15 thousand trials without a hang!)
v2:
    Each patch has minor updates from code reviews. I've re-done testing and
    updated the above statistics. Exact changes are in each patch.

Stephen Brennan (4):
  printk: Add panic_in_progress helper
  printk: disable optimistic spin during panic
  printk: Avoid livelock with heavy printk during panic
  printk: Drop console_sem during panic

 kernel/printk/printk.c | 55 +++++++++++++++++++++++++++++++++++++++++-
 1 file changed, 54 insertions(+), 1 deletion(-)

-- 
2.30.2

[PATCH v3 1/4] printk: Add panic_in_progress helper

[Stephen Brennan]

This will be used help avoid deadlocks during panics. Although it would
be better to include this in linux/panic.h, it would require that header
to include linux/atomic.h as well. On some architectures, this results
in a circular dependency. So instead add the helper directly to
printk.c.

Suggested-by: Petr Mladek <pmladek@suse.com>
Signed-off-by: Stephen Brennan <stephen.s.brennan@oracle.com>
Reviewed-by: Petr Mladek <pmladek@suse.com>
---

Notes:
    v3: Move the helper into printk.c due to circular include
    v2: Switch from macro to static inline function

 kernel/printk/printk.c | 5 +++++
 1 file changed, 5 insertions(+)

diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
index 57b132b658e1..b33c2861a8fc 100644
--- a/kernel/printk/printk.c
+++ b/kernel/printk/printk.c
@@ -1762,6 +1762,11 @@ static DEFINE_RAW_SPINLOCK(console_owner_lock);
 static struct task_struct *console_owner;
 static bool console_waiter;
 
+static bool panic_in_progress(void)
+{
+	return unlikely(atomic_read(&panic_cpu) != PANIC_CPU_INVALID);
+}
+
 /**
  * console_lock_spinning_enable - mark beginning of code where another
  *	thread might safely busy wait
-- 
2.30.2

[PATCH v3 2/4] printk: disable optimistic spin during panic

[Stephen Brennan]

A CPU executing with console lock spinning enabled might be halted
during a panic. Before the panicking CPU calls console_flush_on_panic(),
it may call console_trylock(), which attempts to optimistically spin,
deadlocking the panic CPU:

CPU 0 (panic CPU)             CPU 1
-----------------             ------
                              printk() {
                                vprintk_func() {
                                  vprintk_default() {
                                    vprintk_emit() {
                                      console_unlock() {
                                        console_lock_spinning_enable();
                                        ... printing to console ...
panic() {
  crash_smp_send_stop() {
    NMI  -------------------> HALT
  }
  atomic_notifier_call_chain() {
    printk() {
      ...
      console_trylock_spinnning() {
        // optimistic spin infinitely

This hang during panic can be induced when a kdump kernel is loaded, and
crash_kexec_post_notifiers=1 is present on the kernel command line. The
following script which concurrently writes to /dev/kmsg, and triggers a
panic, can result in this hang:

    #!/bin/bash
    date
    # 991 chars (based on log buffer size):
    chars="$(printf 'a%.0s' {1..991})"
    while :; do
        echo $chars > /dev/kmsg
    done &
    echo c > /proc/sysrq-trigger &
    date
    exit

To avoid this deadlock, ensure that console_trylock_spinning() does not
allow spinning once a panic has begun.

Fixes: dbdda842fe96 ("printk: Add console owner and waiter logic to load balance console writes")

Suggested-by: Petr Mladek <pmladek@suse.com>
Signed-off-by: Stephen Brennan <stephen.s.brennan@oracle.com>
Reviewed-by: Petr Mladek <pmladek@suse.com>
---
 kernel/printk/printk.c | 10 ++++++++++
 1 file changed, 10 insertions(+)

diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
index b33c2861a8fc..1b96166eea35 100644
--- a/kernel/printk/printk.c
+++ b/kernel/printk/printk.c
@@ -1848,6 +1848,16 @@ static int console_trylock_spinning(void)
 	if (console_trylock())
 		return 1;
 
+	/*
+	 * It's unsafe to spin once a panic has begun. If we are the
+	 * panic CPU, we may have already halted the owner of the
+	 * console_sem. If we are not the panic CPU, then we should
+	 * avoid taking console_sem, so the panic CPU has a better
+	 * chance of cleanly acquiring it later.
+	 */
+	if (panic_in_progress())
+		return 0;
+
 	printk_safe_enter_irqsave(flags);
 
 	raw_spin_lock(&console_owner_lock);
-- 
2.30.2

[PATCH v3 3/4] printk: Avoid livelock with heavy printk during panic

[Stephen Brennan]

During panic(), if another CPU is writing heavily the kernel log (e.g.
via /dev/kmsg), then the panic CPU may livelock writing out its messages
to the console. Note when too many messages are dropped during panic and
suppress further printk, except from the panic CPU. This could result in
some important messages being dropped. However, messages are already
being dropped, so this approach at least prevents a livelock.

Reviewed-by: Petr Mladek <pmladek@suse.com>
Signed-off-by: Stephen Brennan <stephen.s.brennan@oracle.com>
---

Notes:
    v3: Use pr_warn_once, and don't break the message line
    v2: Add pr_warn when we suppress printk on non-panic CPU

 kernel/printk/printk.c | 15 +++++++++++++++
 1 file changed, 15 insertions(+)

diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
index 1b96166eea35..cc7bb86f7bfe 100644
--- a/kernel/printk/printk.c
+++ b/kernel/printk/printk.c
@@ -93,6 +93,12 @@ EXPORT_SYMBOL_GPL(console_drivers);
  */
 int __read_mostly suppress_printk;
 
+/*
+ * During panic, heavy printk by other CPUs can delay the
+ * panic and risk deadlock on console resources.
+ */
+int __read_mostly suppress_panic_printk;
+
 #ifdef CONFIG_LOCKDEP
 static struct lockdep_map console_lock_dep_map = {
 	.name = "console_lock"
@@ -2233,6 +2239,10 @@ asmlinkage int vprintk_emit(int facility, int level,
 	if (unlikely(suppress_printk))
 		return 0;
 
+	if (unlikely(suppress_panic_printk) &&
+	    atomic_read(&panic_cpu) != raw_smp_processor_id())
+		return 0;
+
 	if (level == LOGLEVEL_SCHED) {
 		level = LOGLEVEL_DEFAULT;
 		in_sched = true;
@@ -2618,6 +2628,7 @@ void console_unlock(void)
 {
 	static char ext_text[CONSOLE_EXT_LOG_MAX];
 	static char text[CONSOLE_LOG_MAX];
+	static int panic_console_dropped;
 	unsigned long flags;
 	bool do_cond_resched, retry;
 	struct printk_info info;
@@ -2672,6 +2683,10 @@ void console_unlock(void)
 		if (console_seq != r.info->seq) {
 			console_dropped += r.info->seq - console_seq;
 			console_seq = r.info->seq;
+			if (panic_in_progress() && panic_console_dropped++ > 10) {
+				suppress_panic_printk = 1;
+				pr_warn_once("Too many dropped messages. Supress messages on non-panic CPUs to prevent livelock.\n");
+			}
 		}
 
 		if (suppress_message_printing(r.info->level)) {
-- 
2.30.2

[PATCH v3 4/4] printk: Drop console_sem during panic

[Stephen Brennan]

If another CPU is in panic, we are about to be halted. Try to gracefully
abandon the console_sem, leaving it free for the panic CPU to grab.

Suggested-by: Petr Mladek <pmladek@suse.com>
Signed-off-by: Stephen Brennan <stephen.s.brennan@oracle.com>
---

Notes:
    v2: Factor check out to a helper, and check at the end of
    console_unlock() to prevent retry as well.

 kernel/printk/printk.c | 25 ++++++++++++++++++++++++-
 1 file changed, 24 insertions(+), 1 deletion(-)

diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
index cc7bb86f7bfe..35676e76482e 100644
--- a/kernel/printk/printk.c
+++ b/kernel/printk/printk.c
@@ -2598,6 +2598,25 @@ static int have_callable_console(void)
 	return 0;
 }
 
+/*
+ * Return true when this CPU should unlock console_sem without pushing all
+ * messages to the console. This reduces the chance that the console is
+ * locked when the panic CPU tries to use it.
+ */
+static bool abandon_console_lock_in_panic(void)
+{
+	if (!panic_in_progress())
+		return false;
+
+	/*
+	 * We can use raw_smp_processor_id() here because it is impossible for
+	 * the task to be migrated to the panic_cpu, or away from it. If
+	 * panic_cpu has already been set, and we're not currently executing on
+	 * that CPU, then we never will be.
+	 */
+	return atomic_read(&panic_cpu) != raw_smp_processor_id();
+}
+
 /*
  * Can we actually use the console at this time on this cpu?
  *
@@ -2746,6 +2765,10 @@ void console_unlock(void)
 		if (handover)
 			return;
 
+		/* Allow panic_cpu to take over the consoles safely */
+		if (abandon_console_lock_in_panic())
+			break;
+
 		if (do_cond_resched)
 			cond_resched();
 	}
@@ -2763,7 +2786,7 @@ void console_unlock(void)
 	 * flush, no worries.
 	 */
 	retry = prb_read_valid(prb, next_seq, NULL);
-	if (retry && console_trylock())
+	if (retry && !abandon_console_lock_in_panic() && console_trylock())
 		goto again;
 }
 EXPORT_SYMBOL(console_unlock);
-- 
2.30.2

Re: [PATCH v3 1/4] printk: Add panic_in_progress helper

[Stephen Brennan]

Stephen Brennan <stephen.s.brennan@oracle.com> writes:
> This will be used help avoid deadlocks during panics. Although it would
> be better to include this in linux/panic.h, it would require that header
> to include linux/atomic.h as well. On some architectures, this results
> in a circular dependency. So instead add the helper directly to
> printk.c.
>
> Suggested-by: Petr Mladek <pmladek@suse.com>
> Signed-off-by: Stephen Brennan <stephen.s.brennan@oracle.com>
> Reviewed-by: Petr Mladek <pmladek@suse.com>
> ---
>
> Notes:
>     v3: Move the helper into printk.c due to circular include
>     v2: Switch from macro to static inline function
>
>  kernel/printk/printk.c | 5 +++++
>  1 file changed, 5 insertions(+)
>
> diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
> index 57b132b658e1..b33c2861a8fc 100644
> --- a/kernel/printk/printk.c
> +++ b/kernel/printk/printk.c
> @@ -1762,6 +1762,11 @@ static DEFINE_RAW_SPINLOCK(console_owner_lock);
>  static struct task_struct *console_owner;
>  static bool console_waiter;
>  
> +static bool panic_in_progress(void)
> +{
> +	return unlikely(atomic_read(&panic_cpu) != PANIC_CPU_INVALID);
> +}
> +

Unfortunately this is defined within a (very large)
#ifdef CONFIG_PRINTK section. Thanks to the kbuild bot which will have
earned the reported-by tag on this patch :D

v4 will be tomorrow. Sorry for the noise everyone!

>  /**
>   * console_lock_spinning_enable - mark beginning of code where another
>   *	thread might safely busy wait
> -- 
> 2.30.2

Re: [PATCH v3 4/4] printk: Drop console_sem during panic

[Sergey Senozhatsky]

On (22/02/01 10:58), Stephen Brennan wrote:
> +/*
> + * Return true when this CPU should unlock console_sem without pushing all
> + * messages to the console. This reduces the chance that the console is
> + * locked when the panic CPU tries to use it.
> + */
> +static bool abandon_console_lock_in_panic(void)
> +{
> +	if (!panic_in_progress())
> +		return false;
> +
> +	/*
> +	 * We can use raw_smp_processor_id() here because it is impossible for
> +	 * the task to be migrated to the panic_cpu, or away from it. If
> +	 * panic_cpu has already been set, and we're not currently executing on
> +	 * that CPU, then we never will be.
> +	 */
> +	return atomic_read(&panic_cpu) != raw_smp_processor_id();
> +}
> +
>  /*
>   * Can we actually use the console at this time on this cpu?
>   *
> @@ -2746,6 +2765,10 @@ void console_unlock(void)
>  		if (handover)
>  			return;
>  
> +		/* Allow panic_cpu to take over the consoles safely */
> +		if (abandon_console_lock_in_panic())
> +			break;

Sorry, why not just `return` like in handover case?

> +
>  		if (do_cond_resched)
>  			cond_resched();
>  	}
> @@ -2763,7 +2786,7 @@ void console_unlock(void)
>  	 * flush, no worries.
>  	 */
>  	retry = prb_read_valid(prb, next_seq, NULL);
> -	if (retry && console_trylock())
> +	if (retry && !abandon_console_lock_in_panic() && console_trylock())
>  		goto again;
>  }
>  EXPORT_SYMBOL(console_unlock);

Re: [PATCH v3 4/4] printk: Drop console_sem during panic

[Stephen Brennan]

Sergey Senozhatsky <senozhatsky@chromium.org> writes:
> On (22/02/01 10:58), Stephen Brennan wrote:
>> +/*
>> + * Return true when this CPU should unlock console_sem without pushing all
>> + * messages to the console. This reduces the chance that the console is
>> + * locked when the panic CPU tries to use it.
>> + */
>> +static bool abandon_console_lock_in_panic(void)
>> +{
>> +	if (!panic_in_progress())
>> +		return false;
>> +
>> +	/*
>> +	 * We can use raw_smp_processor_id() here because it is impossible for
>> +	 * the task to be migrated to the panic_cpu, or away from it. If
>> +	 * panic_cpu has already been set, and we're not currently executing on
>> +	 * that CPU, then we never will be.
>> +	 */
>> +	return atomic_read(&panic_cpu) != raw_smp_processor_id();
>> +}
>> +
>>  /*
>>   * Can we actually use the console at this time on this cpu?
>>   *
>> @@ -2746,6 +2765,10 @@ void console_unlock(void)
>>  		if (handover)
>>  			return;
>>  
>> +		/* Allow panic_cpu to take over the consoles safely */
>> +		if (abandon_console_lock_in_panic())
>> +			break;
>
> Sorry, why not just `return` like in handover case?

We need to drop console_sem before returning, since the whole benefit
here is to increase the chance that console_sem is unlocked when the
panic_cpu halts this CPU.

in the handover case, there's another cpu waiting, and we're essentially
transferring the console_sem ownership to that cpu, so we explicitly
return and skip the unlocking portion.

Does this need some comments to clarify it?

Admittedly if I had a few more lines of context in the diff, you would
see the console unlock directly after the loop; it's a bit clearer when
you're looking at the function as whole:

2768 		/* Allow panic_cpu to take over the consoles safely */
2769 		if (abandon_console_lock_in_panic())
2770 			break;
2771 
2772 		if (do_cond_resched)
2773 			cond_resched();
2774 	}
2775 
2776 	/* Get consistent value of the next-to-be-used sequence number. */
2777 	next_seq = console_seq;
2778 
2779 	console_locked = 0;
2780 	up_console_sem();

Stephen

>
>> +
>>  		if (do_cond_resched)
>>  			cond_resched();
>>  	}
>> @@ -2763,7 +2786,7 @@ void console_unlock(void)
>>  	 * flush, no worries.
>>  	 */
>>  	retry = prb_read_valid(prb, next_seq, NULL);
>> -	if (retry && console_trylock())
>> +	if (retry && !abandon_console_lock_in_panic() && console_trylock())
>>  		goto again;
>>  }
>>  EXPORT_SYMBOL(console_unlock);

Re: [PATCH v3 4/4] printk: Drop console_sem during panic

[Sergey Senozhatsky]

On (22/02/04 10:53), Stephen Brennan wrote:
> Sergey Senozhatsky <senozhatsky@chromium.org> writes:
> > On (22/02/01 10:58), Stephen Brennan wrote:
> >> +/*
> >> + * Return true when this CPU should unlock console_sem without pushing all
> >> + * messages to the console. This reduces the chance that the console is
> >> + * locked when the panic CPU tries to use it.
> >> + */
> >> +static bool abandon_console_lock_in_panic(void)
> >> +{
> >> +	if (!panic_in_progress())
> >> +		return false;
> >> +
> >> +	/*
> >> +	 * We can use raw_smp_processor_id() here because it is impossible for
> >> +	 * the task to be migrated to the panic_cpu, or away from it. If
> >> +	 * panic_cpu has already been set, and we're not currently executing on
> >> +	 * that CPU, then we never will be.
> >> +	 */
> >> +	return atomic_read(&panic_cpu) != raw_smp_processor_id();
> >> +}
> >> +
> >>  /*
> >>   * Can we actually use the console at this time on this cpu?
> >>   *
> >> @@ -2746,6 +2765,10 @@ void console_unlock(void)
> >>  		if (handover)
> >>  			return;
> >>  
> >> +		/* Allow panic_cpu to take over the consoles safely */
> >> +		if (abandon_console_lock_in_panic())
> >> +			break;
> >
> > Sorry, why not just `return` like in handover case?
> 
> We need to drop console_sem before returning, since the whole benefit
> here is to increase the chance that console_sem is unlocked when the
> panic_cpu halts this CPU.

Yes, that makes sense.

> in the handover case, there's another cpu waiting, and we're essentially
> transferring the console_sem ownership to that cpu, so we explicitly
> return and skip the unlocking portion.
> 
> Does this need some comments to clarify it?

No. Everything looks good. Thanks.