[PATCH v2 0/3] printk: Deadlock in NMI regression

[PATCH v2 0/3] printk: Deadlock in NMI regression

[Petr Mladek]

The commit 719f6a7040f1bdaf96 ("printk: Use the main logbuf in NMI
when logbuf_lock is available") brought back the possible deadlocks
in printk() and NMI.

This is rework of the proposed fix, see
https://lkml.kernel.org/r/20180606111557.xzs6l3lkvg7lq3ts@pathway.suse.cz

I realized that we could rather easily move the check to vprintk_func()
and still avoid any race. I believe that this is a win-win solution.


Changes against v1:

  + Move the check from vprintk_emit() to vprintk_func()
  + More straightforward commit message
  + Fix build with CONFIG_PRINTK_NMI disabled


Petr Mladek (3):
  printk: Split the code for storing a message into the log buffer
  printk: Create helper function to queue deferred console handling
  printk/nmi: Prevent deadlock when accessing the main log buffer in NMI

 include/linux/printk.h      |  4 ++++
 kernel/printk/internal.h    |  9 ++++++-
 kernel/printk/printk.c      | 57 +++++++++++++++++++++++++++-----------------
 kernel/printk/printk_safe.c | 58 +++++++++++++++++++++++++++++----------------
 kernel/trace/trace.c        |  4 +++-
 lib/nmi_backtrace.c         |  3 ---
 6 files changed, 87 insertions(+), 48 deletions(-)

-- 
2.13.7

[PATCH v2 1/3] printk: Split the code for storing a message into the log buffer

[Petr Mladek]

It is just a preparation step. The patch does not change
the existing behavior.

Signed-off-by: Petr Mladek <pmladek@suse.com>
---
 kernel/printk/printk.c | 43 ++++++++++++++++++++++++++-----------------
 1 file changed, 26 insertions(+), 17 deletions(-)

diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
index 247808333ba4..a844c611b17c 100644
--- a/kernel/printk/printk.c
+++ b/kernel/printk/printk.c
@@ -1824,28 +1824,16 @@ static size_t log_output(int facility, int level, enum log_flags lflags, const c
 	return log_store(facility, level, lflags, 0, dict, dictlen, text, text_len);
 }
 
-asmlinkage int vprintk_emit(int facility, int level,
-			    const char *dict, size_t dictlen,
-			    const char *fmt, va_list args)
+/* Must be called under logbuf_lock. */
+int vprintk_store(int facility, int level,
+		  const char *dict, size_t dictlen,
+		  const char *fmt, va_list args)
 {
 	static char textbuf[LOG_LINE_MAX];
 	char *text = textbuf;
 	size_t text_len;
 	enum log_flags lflags = 0;
-	unsigned long flags;
-	int printed_len;
-	bool in_sched = false;
-
-	if (level == LOGLEVEL_SCHED) {
-		level = LOGLEVEL_DEFAULT;
-		in_sched = true;
-	}
-
-	boot_delay_msec(level);
-	printk_delay();
 
-	/* This stops the holder of console_sem just where we want him */
-	logbuf_lock_irqsave(flags);
 	/*
 	 * The printf needs to come first; we need the syslog
 	 * prefix which might be passed-in as a parameter.
@@ -1886,8 +1874,29 @@ asmlinkage int vprintk_emit(int facility, int level,
 	if (dict)
 		lflags |= LOG_PREFIX|LOG_NEWLINE;
 
-	printed_len = log_output(facility, level, lflags, dict, dictlen, text, text_len);
+	return log_output(facility, level, lflags,
+			  dict, dictlen, text, text_len);
+}
 
+asmlinkage int vprintk_emit(int facility, int level,
+			    const char *dict, size_t dictlen,
+			    const char *fmt, va_list args)
+{
+	int printed_len;
+	bool in_sched = false;
+	unsigned long flags;
+
+	if (level == LOGLEVEL_SCHED) {
+		level = LOGLEVEL_DEFAULT;
+		in_sched = true;
+	}
+
+	boot_delay_msec(level);
+	printk_delay();
+
+	/* This stops the holder of console_sem just where we want him */
+	logbuf_lock_irqsave(flags);
+	printed_len = vprintk_store(facility, level, dict, dictlen, fmt, args);
 	logbuf_unlock_irqrestore(flags);
 
 	/* If called from the scheduler, we can not call up(). */
-- 
2.13.7

[PATCH v2 2/3] printk: Create helper function to queue deferred console handling

[Petr Mladek]

It is just a preparation step. The patch does not change
the existing behavior.

Signed-off-by: Petr Mladek <pmladek@suse.com>
---
 kernel/printk/printk.c | 14 +++++++++-----
 1 file changed, 9 insertions(+), 5 deletions(-)

diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
index a844c611b17c..5105ad9c5eb8 100644
--- a/kernel/printk/printk.c
+++ b/kernel/printk/printk.c
@@ -2887,16 +2887,20 @@ void wake_up_klogd(void)
 	preempt_enable();
 }
 
-int vprintk_deferred(const char *fmt, va_list args)
+void defer_console(void)
 {
-	int r;
-
-	r = vprintk_emit(0, LOGLEVEL_SCHED, NULL, 0, fmt, args);
-
 	preempt_disable();
 	__this_cpu_or(printk_pending, PRINTK_PENDING_OUTPUT);
 	irq_work_queue(this_cpu_ptr(&wake_up_klogd_work));
 	preempt_enable();
+}
+
+int vprintk_deferred(const char *fmt, va_list args)
+{
+	int r;
+
+	r = vprintk_emit(0, LOGLEVEL_SCHED, NULL, 0, fmt, args);
+	defer_console();
 
 	return r;
 }
-- 
2.13.7

Re: [PATCH v2 0/3] printk: Deadlock in NMI regression

[Sergey Senozhatsky]

On (06/27/18 16:08), Petr Mladek wrote:
> The commit 719f6a7040f1bdaf96 ("printk: Use the main logbuf in NMI
> when logbuf_lock is available") brought back the possible deadlocks
> in printk() and NMI.
> 
> This is rework of the proposed fix, see
> https://lkml.kernel.org/r/20180606111557.xzs6l3lkvg7lq3ts@pathway.suse.cz
> 
> I realized that we could rather easily move the check to vprintk_func()
> and still avoid any race. I believe that this is a win-win solution.
> 
> 
> Changes against v1:
> 
>   + Move the check from vprintk_emit() to vprintk_func()
>   + More straightforward commit message
>   + Fix build with CONFIG_PRINTK_NMI disabled

Did I miss out V1?

> Petr Mladek (3):
>   printk: Split the code for storing a message into the log buffer
>   printk: Create helper function to queue deferred console handling
>   printk/nmi: Prevent deadlock when accessing the main log buffer in NMI

Patch 3/3 is not in my mailbox, somehow [I checked the spam folder].
I'm not Cc-ed or the message got lost somewhere before it reached my
gmail?

	-ss

[PATCH v2 3/3] printk/nmi: Prevent deadlock when accessing the main log buffer in NMI

[Petr Mladek]

The commit 719f6a7040f1bdaf96 ("printk: Use the main logbuf in NMI
when logbuf_lock is available") brought back the possible deadlocks
in printk() and NMI.

The check of logbuf_lock is done only in printk_nmi_enter() to prevent
mixed output. But another CPU might take the lock later, enter NMI, and:

      + Both NMIs might be serialized by yet another lock, for example,
	the one in nmi_cpu_backtrace().

      + The other CPU might get stopped in NMI, see smp_send_stop()
	in panic().

The only safe solution is to use trylock when storing the message
into the main log-buffer. It might cause reordering when some lines
go to the main lock buffer directly and others are delayed via
the per-CPU buffer. It means that it is not useful in general.

This patch replaces the problematic NMI deferred context with NMI
direct context. It can be used to mark a code that might produce
many messages in NMI and the risk of losing them is more critical
than problems with eventual reordering.

The context is then used when dumping trace buffers on oops. It was
the primary motivation for the original fix. Also the reordering is
even smaller issue there because some traces have their own time stamps.

Finally, nmi_cpu_backtrace() need not longer be serialized because
it will always us the per-CPU buffers again.

Fixes: 719f6a7040f1bdaf96 ("printk: Use the main logbuf in NMI when logbuf_lock is available")
Cc: stable@vger.kernel.org
Signed-off-by: Petr Mladek <pmladek@suse.com>
---
 include/linux/printk.h      |  4 ++++
 kernel/printk/internal.h    |  9 ++++++-
 kernel/printk/printk_safe.c | 58 +++++++++++++++++++++++++++++----------------
 kernel/trace/trace.c        |  4 +++-
 lib/nmi_backtrace.c         |  3 ---
 5 files changed, 52 insertions(+), 26 deletions(-)

diff --git a/include/linux/printk.h b/include/linux/printk.h
index 6d7e800affd8..3ede9f46a494 100644
--- a/include/linux/printk.h
+++ b/include/linux/printk.h
@@ -148,9 +148,13 @@ void early_printk(const char *s, ...) { }
 #ifdef CONFIG_PRINTK_NMI
 extern void printk_nmi_enter(void);
 extern void printk_nmi_exit(void);
+extern void printk_nmi_direct_enter(void);
+extern void printk_nmi_direct_exit(void);
 #else
 static inline void printk_nmi_enter(void) { }
 static inline void printk_nmi_exit(void) { }
+static inline void printk_nmi_direct_enter(void) { }
+static inline void printk_nmi_direct_exit(void) { }
 #endif /* PRINTK_NMI */
 
 #ifdef CONFIG_PRINTK
diff --git a/kernel/printk/internal.h b/kernel/printk/internal.h
index 2a7d04049af4..02410304c683 100644
--- a/kernel/printk/internal.h
+++ b/kernel/printk/internal.h
@@ -19,11 +19,16 @@
 #ifdef CONFIG_PRINTK
 
 #define PRINTK_SAFE_CONTEXT_MASK	 0x3fffffff
-#define PRINTK_NMI_DEFERRED_CONTEXT_MASK 0x40000000
+#define PRINTK_NMI_DIRECT_CONTEXT_MASK	 0x40000000
 #define PRINTK_NMI_CONTEXT_MASK		 0x80000000
 
 extern raw_spinlock_t logbuf_lock;
 
+__printf(5, 0)
+int vprintk_store(int facility, int level,
+		  const char *dict, size_t dictlen,
+		  const char *fmt, va_list args);
+
 __printf(1, 0) int vprintk_default(const char *fmt, va_list args);
 __printf(1, 0) int vprintk_deferred(const char *fmt, va_list args);
 __printf(1, 0) int vprintk_func(const char *fmt, va_list args);
@@ -54,6 +59,8 @@ void __printk_safe_exit(void);
 		local_irq_enable();		\
 	} while (0)
 
+void defer_console(void);
+
 #else
 
 __printf(1, 0) int vprintk_func(const char *fmt, va_list args) { return 0; }
diff --git a/kernel/printk/printk_safe.c b/kernel/printk/printk_safe.c
index d7d091309054..6bd7b467121d 100644
--- a/kernel/printk/printk_safe.c
+++ b/kernel/printk/printk_safe.c
@@ -308,24 +308,33 @@ static __printf(1, 0) int vprintk_nmi(const char *fmt, va_list args)
 
 void printk_nmi_enter(void)
 {
-	/*
-	 * The size of the extra per-CPU buffer is limited. Use it only when
-	 * the main one is locked. If this CPU is not in the safe context,
-	 * the lock must be taken on another CPU and we could wait for it.
-	 */
-	if ((this_cpu_read(printk_context) & PRINTK_SAFE_CONTEXT_MASK) &&
-	    raw_spin_is_locked(&logbuf_lock)) {
-		this_cpu_or(printk_context, PRINTK_NMI_CONTEXT_MASK);
-	} else {
-		this_cpu_or(printk_context, PRINTK_NMI_DEFERRED_CONTEXT_MASK);
-	}
+	this_cpu_or(printk_context, PRINTK_NMI_CONTEXT_MASK);
 }
 
 void printk_nmi_exit(void)
 {
-	this_cpu_and(printk_context,
-		     ~(PRINTK_NMI_CONTEXT_MASK |
-		       PRINTK_NMI_DEFERRED_CONTEXT_MASK));
+	this_cpu_and(printk_context, ~PRINTK_NMI_CONTEXT_MASK);
+}
+
+/*
+ * Marks a code that might produce many messages in NMI context
+ * and the risk of losing them is more critical than eventual
+ * reordering.
+ *
+ * It has effect only when called in NMI context. Then printk()
+ * will try to store the messages into the main logbuf directly
+ * and use the per-CPU buffers only as a fallback when the lock
+ * is not available.
+ */
+void printk_nmi_direct_enter(void)
+{
+	if (this_cpu_read(printk_context) & PRINTK_NMI_CONTEXT_MASK)
+		this_cpu_or(printk_context, PRINTK_NMI_DIRECT_CONTEXT_MASK);
+}
+
+void printk_nmi_direct_exit(void)
+{
+	this_cpu_and(printk_context, ~PRINTK_NMI_DIRECT_CONTEXT_MASK);
 }
 
 #else
@@ -363,6 +372,20 @@ void __printk_safe_exit(void)
 
 __printf(1, 0) int vprintk_func(const char *fmt, va_list args)
 {
+	/*
+	 * Try to use the main logbuf even in NMI. But avoid calling console
+	 * drivers that might have their own locks.
+	 */
+	if ((this_cpu_read(printk_context) & PRINTK_NMI_DIRECT_CONTEXT_MASK) &&
+	    raw_spin_trylock(&logbuf_lock)) {
+		int len;
+
+		len = vprintk_store(0, LOGLEVEL_DEFAULT, NULL, 0, fmt, args);
+		raw_spin_unlock(&logbuf_lock);
+		defer_console();
+		return len;
+	}
+
 	/* Use extra buffer in NMI when logbuf_lock is taken or in safe mode. */
 	if (this_cpu_read(printk_context) & PRINTK_NMI_CONTEXT_MASK)
 		return vprintk_nmi(fmt, args);
@@ -371,13 +394,6 @@ __printf(1, 0) int vprintk_func(const char *fmt, va_list args)
 	if (this_cpu_read(printk_context) & PRINTK_SAFE_CONTEXT_MASK)
 		return vprintk_safe(fmt, args);
 
-	/*
-	 * Use the main logbuf when logbuf_lock is available in NMI.
-	 * But avoid calling console drivers that might have their own locks.
-	 */
-	if (this_cpu_read(printk_context) & PRINTK_NMI_DEFERRED_CONTEXT_MASK)
-		return vprintk_deferred(fmt, args);
-
 	/* No obstacles. */
 	return vprintk_default(fmt, args);
 }
diff --git a/kernel/trace/trace.c b/kernel/trace/trace.c
index 108ce3e1dc13..38b6dbe1709b 100644
--- a/kernel/trace/trace.c
+++ b/kernel/trace/trace.c
@@ -8279,6 +8279,7 @@ void ftrace_dump(enum ftrace_dump_mode oops_dump_mode)
 	tracing_off();
 
 	local_irq_save(flags);
+	printk_nmi_direct_enter();
 
 	/* Simulate the iterator */
 	trace_init_global_iter(&iter);
@@ -8358,7 +8359,8 @@ void ftrace_dump(enum ftrace_dump_mode oops_dump_mode)
 	for_each_tracing_cpu(cpu) {
 		atomic_dec(&per_cpu_ptr(iter.trace_buffer->data, cpu)->disabled);
 	}
- 	atomic_dec(&dump_running);
+	atomic_dec(&dump_running);
+	printk_nmi_direct_exit();
 	local_irq_restore(flags);
 }
 EXPORT_SYMBOL_GPL(ftrace_dump);
diff --git a/lib/nmi_backtrace.c b/lib/nmi_backtrace.c
index 61a6b5aab07e..15ca78e1c7d4 100644
--- a/lib/nmi_backtrace.c
+++ b/lib/nmi_backtrace.c
@@ -87,11 +87,9 @@ void nmi_trigger_cpumask_backtrace(const cpumask_t *mask,
 
 bool nmi_cpu_backtrace(struct pt_regs *regs)
 {
-	static arch_spinlock_t lock = __ARCH_SPIN_LOCK_UNLOCKED;
 	int cpu = smp_processor_id();
 
 	if (cpumask_test_cpu(cpu, to_cpumask(backtrace_mask))) {
-		arch_spin_lock(&lock);
 		if (regs && cpu_in_idle(instruction_pointer(regs))) {
 			pr_warn("NMI backtrace for cpu %d skipped: idling at %pS\n",
 				cpu, (void *)instruction_pointer(regs));
@@ -102,7 +100,6 @@ bool nmi_cpu_backtrace(struct pt_regs *regs)
 			else
 				dump_stack();
 		}
-		arch_spin_unlock(&lock);
 		cpumask_clear_cpu(cpu, to_cpumask(backtrace_mask));
 		return true;
 	}
-- 
2.13.7

Re: [PATCH v2 0/3] printk: Deadlock in NMI regression

[Sergey Senozhatsky]

On (06/27/18 23:16), Sergey Senozhatsky wrote:
> > Petr Mladek (3):
> >   printk: Split the code for storing a message into the log buffer
> >   printk: Create helper function to queue deferred console handling
> >   printk/nmi: Prevent deadlock when accessing the main log buffer in NMI
> 
> Patch 3/3 is not in my mailbox, somehow [I checked the spam folder].
> I'm not Cc-ed or the message got lost somewhere before it reached my
> gmail?

UPD: 3/3 just arrived, with a 12 minutes delay.

	-ss

Re: [PATCH v2 0/3] printk: Deadlock in NMI regression

[Petr Mladek]

On Wed 2018-06-27 23:16:12, Sergey Senozhatsky wrote:
> On (06/27/18 16:08), Petr Mladek wrote:
> > The commit 719f6a7040f1bdaf96 ("printk: Use the main logbuf in NMI
> > when logbuf_lock is available") brought back the possible deadlocks
> > in printk() and NMI.
> > 
> > This is rework of the proposed fix, see
> > https://lkml.kernel.org/r/20180606111557.xzs6l3lkvg7lq3ts@pathway.suse.cz

Grr, the right link is
https://lkml.kernel.org/r/20180608104825.e7xoxteelaxnwx66@pathway.suse.cz


> > I realized that we could rather easily move the check to vprintk_func()
> > and still avoid any race. I believe that this is a win-win solution.
> > 
> > 
> > Changes against v1:
> > 
> >   + Move the check from vprintk_emit() to vprintk_func()
> >   + More straightforward commit message
> >   + Fix build with CONFIG_PRINTK_NMI disabled
> 
> Did I miss out V1?

It is the above fixed link. I am sorry for the confusion.


> > Petr Mladek (3):
> >   printk: Split the code for storing a message into the log buffer
> >   printk: Create helper function to queue deferred console handling
> >   printk/nmi: Prevent deadlock when accessing the main log buffer in NMI
> 
> Patch 3/3 is not in my mailbox, somehow [I checked the spam folder].
> I'm not Cc-ed or the message got lost somewhere before it reached my
> gmail?

Ah, the following line somehow confused git send-mail and the message
had broken list of recipients:

Cc: stable@vger.kernel.org # 4.13+

I have sent it once again as you have already noticed.

Best Regards,
Petr

Re: [PATCH v2 1/3] printk: Split the code for storing a message into the log buffer

[Sergey Senozhatsky]

On (06/27/18 16:08), Petr Mladek wrote:
[..]
>  	if (dict)
>  		lflags |= LOG_PREFIX|LOG_NEWLINE;
>  
> -	printed_len = log_output(facility, level, lflags, dict, dictlen, text, text_len);
> +	return log_output(facility, level, lflags,
> +			  dict, dictlen, text, text_len);
> +}
			  YAYY!


Acked-by: Sergey Senozhatsky <sergey.senozhatsky@gmail.com>

	-ss

Re: [PATCH v2 2/3] printk: Create helper function to queue deferred console handling

[Sergey Senozhatsky]

On (06/27/18 16:08), Petr Mladek wrote:
> -int vprintk_deferred(const char *fmt, va_list args)
> +void defer_console(void)
>  {
> -	int r;
> -
> -	r = vprintk_emit(0, LOGLEVEL_SCHED, NULL, 0, fmt, args);
> -
>  	preempt_disable();
>  	__this_cpu_or(printk_pending, PRINTK_PENDING_OUTPUT);
>  	irq_work_queue(this_cpu_ptr(&wake_up_klogd_work));
>  	preempt_enable();
> +}
> +
> +int vprintk_deferred(const char *fmt, va_list args)
> +{
> +	int r;
> +
> +	r = vprintk_emit(0, LOGLEVEL_SCHED, NULL, 0, fmt, args);
> +	defer_console();
>  
>  	return r;


You can just call vprintk_emit(LOGLEVEL_SCHED) from vprintk_func(),
then you don't need to factor out vprintk_deferred() and vprintk_emit().
Any reason for that split?

I'd also may be prefer to have a bit different name. I'm talking
about defer_console().

Other than that

Acked-by: Sergey Senozhatsky <sergey.senozhatsky@gmail.com>

	-ss

Re: [PATCH v2 2/3] printk: Create helper function to queue deferred console handling

[Sergey Senozhatsky]

On (06/28/18 11:16), Sergey Senozhatsky wrote:
> 
> You can just call vprintk_emit(LOGLEVEL_SCHED) from vprintk_func(),
> then you don't need to factor out vprintk_deferred() and vprintk_emit().
> Any reason for that split?

My bad, no you can't. I forgot that for direct_nmi vprintk_func()
logbuf_lock is locked at the upper level - vprintk_func().

	-ss

Re: [PATCH v2 3/3] printk/nmi: Prevent deadlock when accessing the main log buffer in NMI

[Sergey Senozhatsky]

On (06/27/18 16:20), Petr Mladek wrote:
> +/*
> + * Marks a code that might produce many messages in NMI context
> + * and the risk of losing them is more critical than eventual
> + * reordering.
> + *
> + * It has effect only when called in NMI context. Then printk()
> + * will try to store the messages into the main logbuf directly
> + * and use the per-CPU buffers only as a fallback when the lock
> + * is not available.
> + */
> +void printk_nmi_direct_enter(void)
> +{
> +	if (this_cpu_read(printk_context) & PRINTK_NMI_CONTEXT_MASK)
> +		this_cpu_or(printk_context, PRINTK_NMI_DIRECT_CONTEXT_MASK);
> +}

A side note: This nesting also handles recursive printk-s for us.

NMI:
	printk_nmi_enter
	ftrace_dump
	 printk_nmi_direct_enter
	  vprintk_func
	   spin_lock(logbuf_lock)
	    vprintk_store
	     vsprintf
	      WARN_ON
	       vprintk_func
	        vprintk_nmi

>  __printf(1, 0) int vprintk_func(const char *fmt, va_list args)
>  {
> +	/*
> +	 * Try to use the main logbuf even in NMI. But avoid calling console
> +	 * drivers that might have their own locks.
> +	 */
> +	if ((this_cpu_read(printk_context) & PRINTK_NMI_DIRECT_CONTEXT_MASK) &&
> +	    raw_spin_trylock(&logbuf_lock)) {
> +		int len;
> +
> +		len = vprintk_store(0, LOGLEVEL_DEFAULT, NULL, 0, fmt, args);
> +		raw_spin_unlock(&logbuf_lock);
> +		defer_console();
> +		return len;
> +	}

So, maybe, something a bit better than defer_console().

Otherwise,
Acked-by: Sergey Senozhatsky <sergey.senozhatsky@gmail.com>

	-ss

Re: [PATCH v2 0/3] printk: Deadlock in NMI regression

[Sergey Senozhatsky]

On (06/27/18 16:08), Petr Mladek wrote:
> 
>  kernel/printk/printk.c      | 57 +++++++++++++++++++++++++++-----------------
>  kernel/printk/printk_safe.c | 58 +++++++++++++++++++++++++++++----------------

Shall we just merge these two?

	-ss

Re: [PATCH v2 0/3] printk: Deadlock in NMI regression

[Sergey Senozhatsky]

On (06/27/18 16:34), Petr Mladek wrote:
[..]
> > > Changes against v1:
> > > 
> > >   + Move the check from vprintk_emit() to vprintk_func()
> > >   + More straightforward commit message
> > >   + Fix build with CONFIG_PRINTK_NMI disabled
> > 
> > Did I miss out V1?
> 
> It is the above fixed link. I am sorry for the confusion.

Ah, yep.

[..]
> Ah, the following line somehow confused git send-mail and the message
> had broken list of recipients:
> 
> Cc: stable@vger.kernel.org # 4.13+
> 
> I have sent it once again as you have already noticed.

Got it. Happened to me before as well. I asked because I sort of have
some suspicion that lkml email deliver has not been completely reliable
lately.

	-ss

Re: [PATCH v2 3/3] printk/nmi: Prevent deadlock when accessing the main log buffer in NMI

[Petr Mladek]

On Thu 2018-06-28 11:25:07, Sergey Senozhatsky wrote:
> On (06/27/18 16:20), Petr Mladek wrote:
> > +/*
> > + * Marks a code that might produce many messages in NMI context
> > + * and the risk of losing them is more critical than eventual
> > + * reordering.
> > + *
> > + * It has effect only when called in NMI context. Then printk()
> > + * will try to store the messages into the main logbuf directly
> > + * and use the per-CPU buffers only as a fallback when the lock
> > + * is not available.
> > + */
> > +void printk_nmi_direct_enter(void)
> > +{
> > +	if (this_cpu_read(printk_context) & PRINTK_NMI_CONTEXT_MASK)
> > +		this_cpu_or(printk_context, PRINTK_NMI_DIRECT_CONTEXT_MASK);
> > +}
> 
> A side note: This nesting also handles recursive printk-s for us.
> 
> NMI:
> 	printk_nmi_enter
> 	ftrace_dump
> 	 printk_nmi_direct_enter
> 	  vprintk_func
> 	   spin_lock(logbuf_lock)
> 	    vprintk_store
> 	     vsprintf
> 	      WARN_ON
> 	       vprintk_func
> 	        vprintk_nmi

Uff, it seems that the current design is "good" at lest from some
points of view.

> >  __printf(1, 0) int vprintk_func(const char *fmt, va_list args)
> >  {
> > +	/*
> > +	 * Try to use the main logbuf even in NMI. But avoid calling console
> > +	 * drivers that might have their own locks.
> > +	 */
> > +	if ((this_cpu_read(printk_context) & PRINTK_NMI_DIRECT_CONTEXT_MASK) &&
> > +	    raw_spin_trylock(&logbuf_lock)) {
> > +		int len;
> > +
> > +		len = vprintk_store(0, LOGLEVEL_DEFAULT, NULL, 0, fmt, args);
> > +		raw_spin_unlock(&logbuf_lock);
> > +		defer_console();
> > +		return len;
> > +	}
> 
> So, maybe, something a bit better than defer_console().

I am not super happy with the name either. But wakeup_console(),
schedule_console(), or queue_console() looked confusing.

Also I thought about poke_console() but I guess that I already suggested
this name in the past and people did not like it.

Feel free to suggest anything.


> Otherwise,
> Acked-by: Sergey Senozhatsky <sergey.senozhatsky@gmail.com>

Anyway, thanks a lot for review.

Best Regards,
Petr

Re: [PATCH v2 0/3] printk: Deadlock in NMI regression

[Petr Mladek]

On Thu 2018-06-28 11:39:02, Sergey Senozhatsky wrote:
> On (06/27/18 16:08), Petr Mladek wrote:
> > 
> >  kernel/printk/printk.c      | 57 +++++++++++++++++++++++++++-----------------
> >  kernel/printk/printk_safe.c | 58 +++++++++++++++++++++++++++++----------------
> 
> Shall we just merge these two?

Do you mean to merge files or the patches, please?

I would prefer to keep it as is in both cases.

The printk code could deserve a clean up but I would rather
split it into more files than the opposite.

Best Regards,
Petr

Re: [PATCH v2 3/3] printk/nmi: Prevent deadlock when accessing the main log buffer in NMI

[Sergey Senozhatsky]

On (06/28/18 11:41), Petr Mladek wrote:
> > 
> > A side note: This nesting also handles recursive printk-s for us.
> > 
> > NMI:
> > 	printk_nmi_enter
> > 	ftrace_dump
> > 	 printk_nmi_direct_enter
> > 	  vprintk_func
> > 	   spin_lock(logbuf_lock)
> > 	    vprintk_store
> > 	     vsprintf
> > 	      WARN_ON
> > 	       vprintk_func
> > 	        vprintk_nmi
> 
> Uff, it seems that the current design is "good" at lest from some
> points of view.

yep yep

> > > +		len = vprintk_store(0, LOGLEVEL_DEFAULT, NULL, 0, fmt, args);
> > > +		raw_spin_unlock(&logbuf_lock);
> > > +		defer_console();
> > > +		return len;
> > > +	}
> > 
> > So, maybe, something a bit better than defer_console().
> 
> I am not super happy with the name either. But wakeup_console(),
> schedule_console(), or queue_console() looked confusing.

Hmm. defer_console() makes me think that we are dealing with that
fbcon=nodefer and deferred console takeover thing here.


So I summon Mr. Rostedt!

Does schedule_console_output() look bad?
What about defer_console_output()?
Any other ideas?

	-ss

Re: [PATCH v2 0/3] printk: Deadlock in NMI regression

[Sergey Senozhatsky]

On (06/28/18 12:54), Petr Mladek wrote:
> 
> On Thu 2018-06-28 11:39:02, Sergey Senozhatsky wrote:
> > On (06/27/18 16:08), Petr Mladek wrote:
> > >
> > >  kernel/printk/printk.c      | 57 +++++++++++++++++++++++++++-----------------
> > >  kernel/printk/printk_safe.c | 58 +++++++++++++++++++++++++++++----------------
> >
> > Shall we just merge these two?
>
> Do you mean to merge files or the patches, please?

Yeah... dunno. We now lock logbuf spinlock outside of printk.c, and
we now have printk.c functions that have that "printk guts, must be
called under logbuf lock" requirement and so on. I like when static
things are static :)

	-ss

Re: [PATCH v2 3/3] printk/nmi: Prevent deadlock when accessing the main log buffer in NMI

[Petr Mladek]

On Fri 2018-06-29 10:47:03, Sergey Senozhatsky wrote:
> On (06/28/18 11:41), Petr Mladek wrote:
> > > 
> > > A side note: This nesting also handles recursive printk-s for us.
> > > 
> > > NMI:
> > > 	printk_nmi_enter
> > > 	ftrace_dump
> > > 	 printk_nmi_direct_enter
> > > 	  vprintk_func
> > > 	   spin_lock(logbuf_lock)
> > > 	    vprintk_store
> > > 	     vsprintf
> > > 	      WARN_ON
> > > 	       vprintk_func
> > > 	        vprintk_nmi
> > 
> > Uff, it seems that the current design is "good" at lest from some
> > points of view.
> 
> yep yep
> 
> > > > +		len = vprintk_store(0, LOGLEVEL_DEFAULT, NULL, 0, fmt, args);
> > > > +		raw_spin_unlock(&logbuf_lock);
> > > > +		defer_console();
> > > > +		return len;
> > > > +	}
> > > 
> > > So, maybe, something a bit better than defer_console().
> > 
> > I am not super happy with the name either. But wakeup_console(),
> > schedule_console(), or queue_console() looked confusing.
> 
> Hmm. defer_console() makes me think that we are dealing with that
> fbcon=nodefer and deferred console takeover thing here.
> 
> 
> So I summon Mr. Rostedt!
> 
> Does schedule_console_output() look bad?
> What about defer_console_output()?

I am fine with both. I slightly prefer defer_console_output()
because I have "schedule" associated with deadlocks in this
code path (context) ;-)

Best Regards,
Petr

Re: [PATCH v2 3/3] printk/nmi: Prevent deadlock when accessing the main log buffer in NMI

[Sergey Senozhatsky]

On (06/29/18 09:25), Petr Mladek wrote:
> > So I summon Mr. Rostedt!
> > 
> > Does schedule_console_output() look bad?
> > What about defer_console_output()?
> 
> I am fine with both. I slightly prefer defer_console_output()

I am fine with defer_console_output().

	-ss

Re: [PATCH v2 0/3] printk: Deadlock in NMI regression

[Petr Mladek]

On Wed 2018-06-27 16:08:14, Petr Mladek wrote:
> The commit 719f6a7040f1bdaf96 ("printk: Use the main logbuf in NMI
> when logbuf_lock is available") brought back the possible deadlocks
> in printk() and NMI.
> 
> This is rework of the proposed fix, see
> https://lkml.kernel.org/r/20180606111557.xzs6l3lkvg7lq3ts@pathway.suse.cz
> 
> I realized that we could rather easily move the check to vprintk_func()
> and still avoid any race. I believe that this is a win-win solution.
> 
> 
> Changes against v1:
> 
>   + Move the check from vprintk_emit() to vprintk_func()
>   + More straightforward commit message
>   + Fix build with CONFIG_PRINTK_NMI disabled
> 
> 
> Petr Mladek (3):
>   printk: Split the code for storing a message into the log buffer
>   printk: Create helper function to queue deferred console handling
>   printk/nmi: Prevent deadlock when accessing the main log buffer in NMI
> 
>  include/linux/printk.h      |  4 ++++
>  kernel/printk/internal.h    |  9 ++++++-
>  kernel/printk/printk.c      | 57 +++++++++++++++++++++++++++-----------------
>  kernel/printk/printk_safe.c | 58 +++++++++++++++++++++++++++++----------------
>  kernel/trace/trace.c        |  4 +++-
>  lib/nmi_backtrace.c         |  3 ---
>  6 files changed, 87 insertions(+), 48 deletions(-)

JFYI, I have renamed the new function defer_console() to
defer_console_output() and pushed everything to printk.git,
branch for-4.19-nmi.

Best Regards,
Petr