[PATCHv7 0/8] printk: use printk_safe to handle printk() recursive calls

[PATCHv7 0/8] printk: use printk_safe to handle printk() recursive calls

[Sergey Senozhatsky]

Hello,

	This patch set extends a lock-less NMI per-cpu buffers idea to
handle recursive printk() calls. The basic mechanism is pretty much the
same -- at the beginning of a deadlock-prone section we switch to lock-less
printk callback, and return back to a default printk implementation at the
end; the messages are getting flushed to a logbuf buffer from a safer
context.

See patch 0006 for examples of possible deadlock scenarios that are
handled by printk-safe.


v7:
-- don't touch printk_nmi_enter/exit
-- new printk_safe macros naming: printk_safe_enter_irqsave/exit_irqrestore
-- added printk_safe_enter_irq/printk_safe_exit_irq
-- added patch that converts the rest of printk.c to printk-safe
-- fix build error on !NMI configs
-- improved lost_messages reporting

v6:
-- re-based
-- addressed Petr's review (added comments; moved lost accounting to seq buf)
...

[against next-20161224 + "printk: always report dropped messages" patch set]

Sergey Senozhatsky (8):
  printk: use vprintk_func in vprintk()
  printk: rename nmi.c and exported api
  printk: introduce per-cpu safe_print seq buffer
  printk: always use deferred printk when flush printk_safe lines
  printk: report lost messages in printk safe/nmi contexts
  printk: use printk_safe buffers in printk
  printk: remove zap_locks() function
  printk: convert the rest to printk-safe

 include/linux/printk.h                 |  21 ++-
 init/Kconfig                           |  16 ++-
 init/main.c                            |   2 +-
 kernel/kexec_core.c                    |   2 +-
 kernel/panic.c                         |   4 +-
 kernel/printk/Makefile                 |   2 +-
 kernel/printk/internal.h               |  79 ++++++-----
 kernel/printk/printk.c                 | 220 +++++++++++++------------------
 kernel/printk/{nmi.c => printk_safe.c} | 234 +++++++++++++++++++++++----------
 lib/nmi_backtrace.c                    |   2 +-
 10 files changed, 335 insertions(+), 247 deletions(-)
 rename kernel/printk/{nmi.c => printk_safe.c} (53%)

-- 
2.11.0

[PATCHv7 1/8] printk: use vprintk_func in vprintk()

[Sergey Senozhatsky]

vprintk(), just like printk(), better be using per-cpu printk_func
instead of direct vprintk_emit() call. Just in case if vprintk()
will ever be called from NMI, or from any other context that can
deadlock in printk().

Signed-off-by: Sergey Senozhatsky <sergey.senozhatsky@gmail.com>
Reviewed-by: Steven Rostedt <rostedt@goodmis.org>
Reviewed-by: Petr Mladek <pmladek@suse.com>
---
 kernel/printk/printk.c | 2 +-
 1 file changed, 1 insertion(+), 1 deletion(-)

diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
index 6a7ebcb0bb6e..005f435271ca 100644
--- a/kernel/printk/printk.c
+++ b/kernel/printk/printk.c
@@ -1802,7 +1802,7 @@ EXPORT_SYMBOL(vprintk_emit);
 
 asmlinkage int vprintk(const char *fmt, va_list args)
 {
-	return vprintk_emit(0, LOGLEVEL_DEFAULT, NULL, 0, fmt, args);
+	return vprintk_func(fmt, args);
 }
 EXPORT_SYMBOL(vprintk);
 
-- 
2.11.0

[PATCHv7 2/8] printk: rename nmi.c and exported api

[Sergey Senozhatsky]

A preparation patch for printk_safe work. No functional change.
- rename nmi.c to print_safe.c
- add `printk_safe' prefix to some (which used both by printk-safe
  and printk-nmi) of the exported functions.

Signed-off-by: Sergey Senozhatsky <sergey.senozhatsky@gmail.com>
---
 include/linux/printk.h                 | 12 +++----
 init/Kconfig                           | 16 +++++----
 init/main.c                            |  2 +-
 kernel/kexec_core.c                    |  2 +-
 kernel/panic.c                         |  4 +--
 kernel/printk/Makefile                 |  2 +-
 kernel/printk/{nmi.c => printk_safe.c} | 64 +++++++++++++++++-----------------
 lib/nmi_backtrace.c                    |  2 +-
 8 files changed, 53 insertions(+), 51 deletions(-)
 rename kernel/printk/{nmi.c => printk_safe.c} (79%)

diff --git a/include/linux/printk.h b/include/linux/printk.h
index 3472cc6b7a60..37e933eeffb2 100644
--- a/include/linux/printk.h
+++ b/include/linux/printk.h
@@ -147,17 +147,17 @@ void early_printk(const char *s, ...) { }
 #endif
 
 #ifdef CONFIG_PRINTK_NMI
-extern void printk_nmi_init(void);
+extern void printk_safe_init(void);
 extern void printk_nmi_enter(void);
 extern void printk_nmi_exit(void);
-extern void printk_nmi_flush(void);
-extern void printk_nmi_flush_on_panic(void);
+extern void printk_safe_flush(void);
+extern void printk_safe_flush_on_panic(void);
 #else
-static inline void printk_nmi_init(void) { }
+static inline void printk_safe_init(void) { }
 static inline void printk_nmi_enter(void) { }
 static inline void printk_nmi_exit(void) { }
-static inline void printk_nmi_flush(void) { }
-static inline void printk_nmi_flush_on_panic(void) { }
+static inline void printk_safe_flush(void) { }
+static inline void printk_safe_flush_on_panic(void) { }
 #endif /* PRINTK_NMI */
 
 #ifdef CONFIG_PRINTK
diff --git a/init/Kconfig b/init/Kconfig
index 223b734abccd..760b7d0bc9d7 100644
--- a/init/Kconfig
+++ b/init/Kconfig
@@ -875,17 +875,19 @@ config LOG_CPU_MAX_BUF_SHIFT
 		     13 =>   8 KB for each CPU
 		     12 =>   4 KB for each CPU
 
-config NMI_LOG_BUF_SHIFT
-	int "Temporary per-CPU NMI log buffer size (12 => 4KB, 13 => 8KB)"
+config PRINTK_SAFE_LOG_BUF_SHIFT
+	int "Temporary per-CPU printk log buffer size (12 => 4KB, 13 => 8KB)"
 	range 10 21
 	default 13
-	depends on PRINTK_NMI
+	depends on PRINTK
 	help
-	  Select the size of a per-CPU buffer where NMI messages are temporary
-	  stored. They are copied to the main log buffer in a safe context
-	  to avoid a deadlock. The value defines the size as a power of 2.
+	  Select the size of an alternate printk per-CPU buffer where messages
+	  printed from usafe contexts are temporary stored. One example would
+	  be NMI messages, another one - printk recursion. The messages are
+	  copied to the main log buffer in a safe context to avoid a deadlock.
+	  The value defines the size as a power of 2.
 
-	  NMI messages are rare and limited. The largest one is when
+	  Those messages are rare and limited. The largest one is when
 	  a backtrace is printed. It usually fits into 4KB. Select
 	  8KB if you want to be on the safe side.
 
diff --git a/init/main.c b/init/main.c
index b8f88013462d..b08305a7138c 100644
--- a/init/main.c
+++ b/init/main.c
@@ -579,7 +579,7 @@ asmlinkage __visible void __init start_kernel(void)
 	timekeeping_init();
 	time_init();
 	sched_clock_postinit();
-	printk_nmi_init();
+	printk_safe_init();
 	perf_event_init();
 	profile_init();
 	call_function_init();
diff --git a/kernel/kexec_core.c b/kernel/kexec_core.c
index 5617cc412444..14bb9eb76665 100644
--- a/kernel/kexec_core.c
+++ b/kernel/kexec_core.c
@@ -916,7 +916,7 @@ void crash_kexec(struct pt_regs *regs)
 	old_cpu = atomic_cmpxchg(&panic_cpu, PANIC_CPU_INVALID, this_cpu);
 	if (old_cpu == PANIC_CPU_INVALID) {
 		/* This is the 1st CPU which comes here, so go ahead. */
-		printk_nmi_flush_on_panic();
+		printk_safe_flush_on_panic();
 		__crash_kexec(regs);
 
 		/*
diff --git a/kernel/panic.c b/kernel/panic.c
index c51edaa04fce..8c8efcd310e7 100644
--- a/kernel/panic.c
+++ b/kernel/panic.c
@@ -188,7 +188,7 @@ void panic(const char *fmt, ...)
 	 * Bypass the panic_cpu check and call __crash_kexec directly.
 	 */
 	if (!_crash_kexec_post_notifiers) {
-		printk_nmi_flush_on_panic();
+		printk_safe_flush_on_panic();
 		__crash_kexec(NULL);
 
 		/*
@@ -213,7 +213,7 @@ void panic(const char *fmt, ...)
 	atomic_notifier_call_chain(&panic_notifier_list, 0, buf);
 
 	/* Call flush even twice. It tries harder with a single online CPU */
-	printk_nmi_flush_on_panic();
+	printk_safe_flush_on_panic();
 	kmsg_dump(KMSG_DUMP_PANIC);
 
 	/*
diff --git a/kernel/printk/Makefile b/kernel/printk/Makefile
index abb0042a427b..607928119f26 100644
--- a/kernel/printk/Makefile
+++ b/kernel/printk/Makefile
@@ -1,3 +1,3 @@
 obj-y	= printk.o
-obj-$(CONFIG_PRINTK_NMI)		+= nmi.o
+obj-$(CONFIG_PRINTK_NMI)		+= printk_safe.o
 obj-$(CONFIG_A11Y_BRAILLE_CONSOLE)	+= braille.o
diff --git a/kernel/printk/nmi.c b/kernel/printk/printk_safe.c
similarity index 79%
rename from kernel/printk/nmi.c
rename to kernel/printk/printk_safe.c
index f011aaef583c..fc80359dcd78 100644
--- a/kernel/printk/nmi.c
+++ b/kernel/printk/printk_safe.c
@@ -1,5 +1,5 @@
 /*
- * nmi.c - Safe printk in NMI context
+ * printk_safe.c - Safe printk in NMI context
  *
  * This program is free software; you can redistribute it and/or
  * modify it under the terms of the GNU General Public License
@@ -39,18 +39,18 @@
  * were handled or when IRQs are blocked.
  */
 DEFINE_PER_CPU(printk_func_t, printk_func) = vprintk_default;
-static int printk_nmi_irq_ready;
+static int printk_safe_irq_ready;
 atomic_t nmi_message_lost;
 
-#define NMI_LOG_BUF_LEN ((1 << CONFIG_NMI_LOG_BUF_SHIFT) -		\
+#define SAFE_LOG_BUF_LEN ((1 << CONFIG_PRINTK_SAFE_LOG_BUF_SHIFT) -	\
 			 sizeof(atomic_t) - sizeof(struct irq_work))
 
-struct nmi_seq_buf {
+struct printk_safe_seq_buf {
 	atomic_t		len;	/* length of written data */
 	struct irq_work		work;	/* IRQ work that flushes the buffer */
-	unsigned char		buffer[NMI_LOG_BUF_LEN];
+	unsigned char		buffer[SAFE_LOG_BUF_LEN];
 };
-static DEFINE_PER_CPU(struct nmi_seq_buf, nmi_print_seq);
+static DEFINE_PER_CPU(struct printk_safe_seq_buf, nmi_print_seq);
 
 /*
  * Safe printk() for NMI context. It uses a per-CPU buffer to
@@ -60,7 +60,7 @@ static DEFINE_PER_CPU(struct nmi_seq_buf, nmi_print_seq);
  */
 static int vprintk_nmi(const char *fmt, va_list args)
 {
-	struct nmi_seq_buf *s = this_cpu_ptr(&nmi_print_seq);
+	struct printk_safe_seq_buf *s = this_cpu_ptr(&nmi_print_seq);
 	int add = 0;
 	size_t len;
 
@@ -91,7 +91,7 @@ static int vprintk_nmi(const char *fmt, va_list args)
 		goto again;
 
 	/* Get flushed in a more safe context. */
-	if (add && printk_nmi_irq_ready) {
+	if (add && printk_safe_irq_ready) {
 		/* Make sure that IRQ work is really initialized. */
 		smp_rmb();
 		irq_work_queue(&s->work);
@@ -100,7 +100,7 @@ static int vprintk_nmi(const char *fmt, va_list args)
 	return add;
 }
 
-static void printk_nmi_flush_line(const char *text, int len)
+static void printk_safe_flush_line(const char *text, int len)
 {
 	/*
 	 * The buffers are flushed in NMI only on panic.  The messages must
@@ -111,11 +111,10 @@ static void printk_nmi_flush_line(const char *text, int len)
 		printk_deferred("%.*s", len, text);
 	else
 		printk("%.*s", len, text);
-
 }
 
 /* printk part of the temporary buffer line by line */
-static int printk_nmi_flush_buffer(const char *start, size_t len)
+static int printk_safe_flush_buffer(const char *start, size_t len)
 {
 	const char *c, *end;
 	bool header;
@@ -127,7 +126,7 @@ static int printk_nmi_flush_buffer(const char *start, size_t len)
 	/* Print line by line. */
 	while (c < end) {
 		if (*c == '\n') {
-			printk_nmi_flush_line(start, c - start + 1);
+			printk_safe_flush_line(start, c - start + 1);
 			start = ++c;
 			header = true;
 			continue;
@@ -140,7 +139,7 @@ static int printk_nmi_flush_buffer(const char *start, size_t len)
 				continue;
 			}
 
-			printk_nmi_flush_line(start, c - start);
+			printk_safe_flush_line(start, c - start);
 			start = c++;
 			header = true;
 			continue;
@@ -154,8 +153,8 @@ static int printk_nmi_flush_buffer(const char *start, size_t len)
 	if (start < end && !header) {
 		static const char newline[] = KERN_CONT "\n";
 
-		printk_nmi_flush_line(start, end - start);
-		printk_nmi_flush_line(newline, strlen(newline));
+		printk_safe_flush_line(start, end - start);
+		printk_safe_flush_line(newline, strlen(newline));
 	}
 
 	return len;
@@ -165,11 +164,12 @@ static int printk_nmi_flush_buffer(const char *start, size_t len)
  * Flush data from the associated per_CPU buffer. The function
  * can be called either via IRQ work or independently.
  */
-static void __printk_nmi_flush(struct irq_work *work)
+static void __printk_safe_flush(struct irq_work *work)
 {
 	static raw_spinlock_t read_lock =
 		__RAW_SPIN_LOCK_INITIALIZER(read_lock);
-	struct nmi_seq_buf *s = container_of(work, struct nmi_seq_buf, work);
+	struct printk_safe_seq_buf *s =
+		container_of(work, struct printk_safe_seq_buf, work);
 	unsigned long flags;
 	size_t len;
 	int i;
@@ -194,9 +194,9 @@ static void __printk_nmi_flush(struct irq_work *work)
 	 * buffer size.
 	 */
 	if ((i && i >= len) || len > sizeof(s->buffer)) {
-		const char *msg = "printk_nmi_flush: internal error\n";
+		const char *msg = "printk_safe_flush: internal error\n";
 
-		printk_nmi_flush_line(msg, strlen(msg));
+		printk_safe_flush_line(msg, strlen(msg));
 		len = 0;
 	}
 
@@ -205,7 +205,7 @@ static void __printk_nmi_flush(struct irq_work *work)
 
 	/* Make sure that data has been written up to the @len */
 	smp_rmb();
-	i += printk_nmi_flush_buffer(s->buffer + i, len - i);
+	i += printk_safe_flush_buffer(s->buffer + i, len - i);
 
 	/*
 	 * Check that nothing has got added in the meantime and truncate
@@ -221,31 +221,31 @@ static void __printk_nmi_flush(struct irq_work *work)
 }
 
 /**
- * printk_nmi_flush - flush all per-cpu nmi buffers.
+ * printk_safe_flush - flush all per-cpu nmi buffers.
  *
  * The buffers are flushed automatically via IRQ work. This function
  * is useful only when someone wants to be sure that all buffers have
  * been flushed at some point.
  */
-void printk_nmi_flush(void)
+void printk_safe_flush(void)
 {
 	int cpu;
 
 	for_each_possible_cpu(cpu)
-		__printk_nmi_flush(&per_cpu(nmi_print_seq, cpu).work);
+		__printk_safe_flush(&per_cpu(nmi_print_seq, cpu).work);
 }
 
 /**
- * printk_nmi_flush_on_panic - flush all per-cpu nmi buffers when the system
+ * printk_safe_flush_on_panic - flush all per-cpu nmi buffers when the system
  *	goes down.
  *
- * Similar to printk_nmi_flush() but it can be called even in NMI context when
+ * Similar to printk_safe_flush() but it can be called even in NMI context when
  * the system goes down. It does the best effort to get NMI messages into
  * the main ring buffer.
  *
  * Note that it could try harder when there is only one CPU online.
  */
-void printk_nmi_flush_on_panic(void)
+void printk_safe_flush_on_panic(void)
 {
 	/*
 	 * Make sure that we could access the main ring buffer.
@@ -259,25 +259,25 @@ void printk_nmi_flush_on_panic(void)
 		raw_spin_lock_init(&logbuf_lock);
 	}
 
-	printk_nmi_flush();
+	printk_safe_flush();
 }
 
-void __init printk_nmi_init(void)
+void __init printk_safe_init(void)
 {
 	int cpu;
 
 	for_each_possible_cpu(cpu) {
-		struct nmi_seq_buf *s = &per_cpu(nmi_print_seq, cpu);
+		struct printk_safe_seq_buf *s = &per_cpu(nmi_print_seq, cpu);
 
-		init_irq_work(&s->work, __printk_nmi_flush);
+		init_irq_work(&s->work, __printk_safe_flush);
 	}
 
 	/* Make sure that IRQ works are initialized before enabling. */
 	smp_wmb();
-	printk_nmi_irq_ready = 1;
+	printk_safe_irq_ready = 1;
 
 	/* Flush pending messages that did not have scheduled IRQ works. */
-	printk_nmi_flush();
+	printk_safe_flush();
 }
 
 void printk_nmi_enter(void)
diff --git a/lib/nmi_backtrace.c b/lib/nmi_backtrace.c
index 75554754eadf..5f7999eacad5 100644
--- a/lib/nmi_backtrace.c
+++ b/lib/nmi_backtrace.c
@@ -77,7 +77,7 @@ void nmi_trigger_cpumask_backtrace(const cpumask_t *mask,
 	 * Force flush any remote buffers that might be stuck in IRQ context
 	 * and therefore could not run their irq_work.
 	 */
-	printk_nmi_flush();
+	printk_safe_flush();
 
 	clear_bit_unlock(0, &backtrace_flag);
 	put_cpu();
-- 
2.11.0

Re: [PATCHv7 2/8] printk: rename nmi.c and exported api

[Petr Mladek]

On Tue 2016-12-27 23:16:05, Sergey Senozhatsky wrote:
> A preparation patch for printk_safe work. No functional change.
> - rename nmi.c to print_safe.c
> - add `printk_safe' prefix to some (which used both by printk-safe
>   and printk-nmi) of the exported functions.
> 
> Signed-off-by: Sergey Senozhatsky <sergey.senozhatsky@gmail.com>

Looks fine.

Reviewed-by: Petr Mladek <pmladek@suse.com>

Best Regards,
Petr

Re: [PATCHv7 2/8] printk: rename nmi.c and exported api

[Steven Rostedt]

On Tue, 27 Dec 2016 23:16:05 +0900
Sergey Senozhatsky <sergey.senozhatsky@gmail.com> wrote:

> A preparation patch for printk_safe work. No functional change.
> - rename nmi.c to print_safe.c
> - add `printk_safe' prefix to some (which used both by printk-safe
>   and printk-nmi) of the exported functions.
> 
> Signed-off-by: Sergey Senozhatsky <sergey.senozhatsky@gmail.com>

Looks good.

Reviewed-by: Steven Rostedt (VMware) <rostedt@goodmis.org>

-- Steve

Re: [PATCHv7 2/8] printk: rename nmi.c and exported api

[Steven Rostedt]

On Wed, 1 Feb 2017 10:48:05 -0500
Steven Rostedt <rostedt@goodmis.org> wrote:

> On Tue, 27 Dec 2016 23:16:05 +0900
> Sergey Senozhatsky <sergey.senozhatsky@gmail.com> wrote:
> 
> > A preparation patch for printk_safe work. No functional change.
> > - rename nmi.c to print_safe.c
> > - add `printk_safe' prefix to some (which used both by printk-safe
> >   and printk-nmi) of the exported functions.
> > 
> > Signed-off-by: Sergey Senozhatsky <sergey.senozhatsky@gmail.com>  
> 
> Looks good.
> 
> Reviewed-by: Steven Rostedt (VMware) <rostedt@goodmis.org>
> 

I take that back. This isn't the patch I reviewed :-p (I'm not sure I
totally agree with the entire change, but I'm not going to argue it
either).

I was reviewing patch 3, but needed to apply this patch to look at all
the changes of patch 3, but I did the reply here, where it was meant
for patch 3.

-- Steve

Re: [PATCHv7 2/8] printk: rename nmi.c and exported api

[Geert Uytterhoeven]

Hi Sergey,

On Tue, Dec 27, 2016 at 3:16 PM, Sergey Senozhatsky
<sergey.senozhatsky@gmail.com> wrote:
> A preparation patch for printk_safe work. No functional change.
> - rename nmi.c to print_safe.c
> - add `printk_safe' prefix to some (which used both by printk-safe
>   and printk-nmi) of the exported functions.
>
> Signed-off-by: Sergey Senozhatsky <sergey.senozhatsky@gmail.com>

> --- a/init/Kconfig
> +++ b/init/Kconfig
> @@ -875,17 +875,19 @@ config LOG_CPU_MAX_BUF_SHIFT
>                      13 =>   8 KB for each CPU
>                      12 =>   4 KB for each CPU
>
> -config NMI_LOG_BUF_SHIFT
> -       int "Temporary per-CPU NMI log buffer size (12 => 4KB, 13 => 8KB)"
> +config PRINTK_SAFE_LOG_BUF_SHIFT
> +       int "Temporary per-CPU printk log buffer size (12 => 4KB, 13 => 8KB)"
>         range 10 21
>         default 13
> -       depends on PRINTK_NMI
> +       depends on PRINTK

Was this dependency change intentional?
My platform doesn't have PRINTK_NMI.

Gr{oetje,eeting}s,

                        Geert

--
Geert Uytterhoeven -- There's lots of Linux beyond ia32 -- geert@linux-m68k.org

In personal conversations with technical people, I call myself a hacker. But
when I'm talking to journalists I just say "programmer" or something like that.
                                -- Linus Torvalds

Re: [PATCHv7 2/8] printk: rename nmi.c and exported api

[Sergey Senozhatsky]

Hello Geert,

On (02/23/17 08:50), Geert Uytterhoeven wrote:
> Hi Sergey,
[..]
> > -config NMI_LOG_BUF_SHIFT
> > -       int "Temporary per-CPU NMI log buffer size (12 => 4KB, 13 => 8KB)"
> > +config PRINTK_SAFE_LOG_BUF_SHIFT
> > +       int "Temporary per-CPU printk log buffer size (12 => 4KB, 13 => 8KB)"
> >         range 10 21
> >         default 13
> > -       depends on PRINTK_NMI
> > +       depends on PRINTK
> 
> Was this dependency change intentional?
> My platform doesn't have PRINTK_NMI.

yes. printk-safe uses the same mechanism as printk-nmi (per-CPU buffers, etc.)
and does not depend on HAVE_NMI/PRINTK_NMI, but depends on PRINTK.

NMI related part of printk-safe (printk-nmi per-CPU buffers, etc.) is not
compiled for !HAVE_NMI systems (since PRINTK_NMI is unset there).

	-ss

Re: [PATCHv7 2/8] printk: rename nmi.c and exported api

[Geert Uytterhoeven]

Hi Sergey,

On Thu, Feb 23, 2017 at 9:02 AM, Sergey Senozhatsky
<sergey.senozhatsky.work@gmail.com> wrote:
> On (02/23/17 08:50), Geert Uytterhoeven wrote:
>> > -config NMI_LOG_BUF_SHIFT
>> > -       int "Temporary per-CPU NMI log buffer size (12 => 4KB, 13 => 8KB)"
>> > +config PRINTK_SAFE_LOG_BUF_SHIFT
>> > +       int "Temporary per-CPU printk log buffer size (12 => 4KB, 13 => 8KB)"
>> >         range 10 21
>> >         default 13
>> > -       depends on PRINTK_NMI
>> > +       depends on PRINTK
>>
>> Was this dependency change intentional?
>> My platform doesn't have PRINTK_NMI.
>
> yes. printk-safe uses the same mechanism as printk-nmi (per-CPU buffers, etc.)
> and does not depend on HAVE_NMI/PRINTK_NMI, but depends on PRINTK.
>
> NMI related part of printk-safe (printk-nmi per-CPU buffers, etc.) is not
> compiled for !HAVE_NMI systems (since PRINTK_NMI is unset there).

OK, thanks for the clarification!

Gr{oetje,eeting}s,

                        Geert

--
Geert Uytterhoeven -- There's lots of Linux beyond ia32 -- geert@linux-m68k.org

In personal conversations with technical people, I call myself a hacker. But
when I'm talking to journalists I just say "programmer" or something like that.
                                -- Linus Torvalds

[PATCHv7 3/8] printk: introduce per-cpu safe_print seq buffer

[Sergey Senozhatsky]

This patch extends the idea of NMI per-cpu buffers to regions
that may cause recursive printk() calls and possible deadlocks.
Namely, printk() can't handle printk calls from schedule code
or printk() calls from lock debugging code (spin_dump() for instance);
because those may be called with `sem->lock' already taken or any
other `critical' locks (p->pi_lock, etc.). An example of deadlock
can be

 vprintk_emit()
  console_unlock()
   up()                        << raw_spin_lock_irqsave(&sem->lock, flags);
    wake_up_process()
     try_to_wake_up()
      ttwu_queue()
       ttwu_activate()
        activate_task()
         enqueue_task()
          enqueue_task_fair()
           cfs_rq_of()
            task_of()
             WARN_ON_ONCE(!entity_is_task(se))
              vprintk_emit()
               console_trylock()
                down_trylock()
                 raw_spin_lock_irqsave(&sem->lock, flags)
                 ^^^^ deadlock

and some other cases.

Just like in NMI implementation, the solution uses a per-cpu
`printk_func' pointer to 'redirect' printk() calls to a 'safe'
callback, that store messages in a per-cpu buffer and flushes
them back to logbuf buffer later.

Usage example:

 printk()
  printk_safe_enter_irqsave(flags)
  //
  //  any printk() call from here will endup in vprintk_safe(),
  //  that stores messages in a special per-CPU buffer.
  //
  printk_safe_exit_irqrestore(flags)

The 'redirection' mechanism, though, has been reworked, as suggested
by Petr Mladek. Instead of using a per-cpu @print_func callback we now
keep a per-cpu printk-context variable and call either default or nmi
vprintk function depending on its value. printk_nmi_entrer/exit and
printk_safe_enter/exit, thus, just set/celar corresponding bits in
printk-context functions.

The patch only adds printk_safe support, we don't use it yet.

Signed-off-by: Sergey Senozhatsky <sergey.senozhatsky@gmail.com>
---
 include/linux/printk.h      |  21 +++++---
 kernel/printk/Makefile      |   2 +-
 kernel/printk/internal.h    |  76 ++++++++++++++++++--------
 kernel/printk/printk.c      |   3 --
 kernel/printk/printk_safe.c | 128 +++++++++++++++++++++++++++++++++++---------
 5 files changed, 172 insertions(+), 58 deletions(-)

diff --git a/include/linux/printk.h b/include/linux/printk.h
index 37e933eeffb2..571257e0f53d 100644
--- a/include/linux/printk.h
+++ b/include/linux/printk.h
@@ -147,17 +147,11 @@ void early_printk(const char *s, ...) { }
 #endif
 
 #ifdef CONFIG_PRINTK_NMI
-extern void printk_safe_init(void);
 extern void printk_nmi_enter(void);
 extern void printk_nmi_exit(void);
-extern void printk_safe_flush(void);
-extern void printk_safe_flush_on_panic(void);
 #else
-static inline void printk_safe_init(void) { }
 static inline void printk_nmi_enter(void) { }
 static inline void printk_nmi_exit(void) { }
-static inline void printk_safe_flush(void) { }
-static inline void printk_safe_flush_on_panic(void) { }
 #endif /* PRINTK_NMI */
 
 #ifdef CONFIG_PRINTK
@@ -209,6 +203,9 @@ void __init setup_log_buf(int early);
 __printf(1, 2) void dump_stack_set_arch_desc(const char *fmt, ...);
 void dump_stack_print_info(const char *log_lvl);
 void show_regs_print_info(const char *log_lvl);
+extern void printk_safe_init(void);
+extern void printk_safe_flush(void);
+extern void printk_safe_flush_on_panic(void);
 #else
 static inline __printf(1, 0)
 int vprintk(const char *s, va_list args)
@@ -268,6 +265,18 @@ static inline void dump_stack_print_info(const char *log_lvl)
 static inline void show_regs_print_info(const char *log_lvl)
 {
 }
+
+static inline void printk_safe_init(void)
+{
+}
+
+static inline void printk_safe_flush(void)
+{
+}
+
+static inline void printk_safe_flush_on_panic(void)
+{
+}
 #endif
 
 extern asmlinkage void dump_stack(void) __cold;
diff --git a/kernel/printk/Makefile b/kernel/printk/Makefile
index 607928119f26..4a2ffc39eb95 100644
--- a/kernel/printk/Makefile
+++ b/kernel/printk/Makefile
@@ -1,3 +1,3 @@
 obj-y	= printk.o
-obj-$(CONFIG_PRINTK_NMI)		+= printk_safe.o
+obj-$(CONFIG_PRINTK)	+= printk_safe.o
 obj-$(CONFIG_A11Y_BRAILLE_CONSOLE)	+= braille.o
diff --git a/kernel/printk/internal.h b/kernel/printk/internal.h
index 7fd2838fa417..c65e36509f3b 100644
--- a/kernel/printk/internal.h
+++ b/kernel/printk/internal.h
@@ -16,26 +16,8 @@
  */
 #include <linux/percpu.h>
 
-typedef __printf(1, 0) int (*printk_func_t)(const char *fmt, va_list args);
-
-int __printf(1, 0) vprintk_default(const char *fmt, va_list args);
-
 #ifdef CONFIG_PRINTK_NMI
 
-extern raw_spinlock_t logbuf_lock;
-
-/*
- * printk() could not take logbuf_lock in NMI context. Instead,
- * it temporary stores the strings into a per-CPU buffer.
- * The alternative implementation is chosen transparently
- * via per-CPU variable.
- */
-DECLARE_PER_CPU(printk_func_t, printk_func);
-static inline __printf(1, 0) int vprintk_func(const char *fmt, va_list args)
-{
-	return this_cpu_read(printk_func)(fmt, args);
-}
-
 extern atomic_t nmi_message_lost;
 static inline int get_nmi_message_lost(void)
 {
@@ -44,14 +26,62 @@ static inline int get_nmi_message_lost(void)
 
 #else /* CONFIG_PRINTK_NMI */
 
-static inline __printf(1, 0) int vprintk_func(const char *fmt, va_list args)
-{
-	return vprintk_default(fmt, args);
-}
-
 static inline int get_nmi_message_lost(void)
 {
 	return 0;
 }
 
 #endif /* CONFIG_PRINTK_NMI */
+
+#ifdef CONFIG_PRINTK
+
+#define PRINTK_SAFE_CONTEXT_MASK	0x7fffffff
+#define PRINTK_NMI_CONTEXT_MASK	0x80000000
+
+extern raw_spinlock_t logbuf_lock;
+
+__printf(1, 0) int vprintk_default(const char *fmt, va_list args);
+__printf(1, 0) int vprintk_func(const char *fmt, va_list args);
+void __printk_safe_enter(void);
+void __printk_safe_exit(void);
+
+#define printk_safe_enter_irqsave(flags)	\
+	do {					\
+		local_irq_save(flags);		\
+		__printk_safe_enter();		\
+	} while (0)
+
+#define printk_safe_exit_irqrestore(flags)	\
+	do {					\
+		__printk_safe_exit();		\
+		local_irq_restore(flags);	\
+	} while (0)
+
+#define printk_safe_enter_irq()		\
+	do {					\
+		local_irq_disable();		\
+		__printk_safe_enter();		\
+	} while (0)
+
+#define printk_safe_exit_irq()			\
+	do {					\
+		__printk_safe_exit();		\
+		local_irq_enable();		\
+	} while (0)
+
+#else
+
+__printf(1, 0) int vprintk_func(const char *fmt, va_list args) { return 0; }
+
+/*
+ * In !PRINTK builds we still export logbuf_lock spin_lock, console_sem
+ * semaphore and some of console functions (console_unlock()/etc.), so
+ * printk-safe must preserve the existing local IRQ guarantees.
+ */
+#define printk_safe_enter_irqsave(flags) local_irq_save(flags)
+#define printk_safe_exit_irqrestore(flags) local_irq_restore(flags)
+
+#define printk_safe_enter_irq() local_irq_disable()
+#define printk_safe_exit_irq() local_irq_enable()
+
+#endif /* CONFIG_PRINTK */
diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
index 005f435271ca..9cc9a97c2cc8 100644
--- a/kernel/printk/printk.c
+++ b/kernel/printk/printk.c
@@ -1900,9 +1900,6 @@ static size_t msg_print_text(const struct printk_log *msg,
 			     bool syslog, char *buf, size_t size) { return 0; }
 static bool suppress_message_printing(int level) { return false; }
 
-/* Still needs to be defined for users */
-DEFINE_PER_CPU(printk_func_t, printk_func);
-
 #endif /* CONFIG_PRINTK */
 
 #ifdef CONFIG_EARLY_PRINTK
diff --git a/kernel/printk/printk_safe.c b/kernel/printk/printk_safe.c
index fc80359dcd78..efc89a4e9df5 100644
--- a/kernel/printk/printk_safe.c
+++ b/kernel/printk/printk_safe.c
@@ -1,5 +1,5 @@
 /*
- * printk_safe.c - Safe printk in NMI context
+ * printk_safe.c - Safe printk for printk-deadlock-prone contexts
  *
  * This program is free software; you can redistribute it and/or
  * modify it under the terms of the GNU General Public License
@@ -32,13 +32,13 @@
  * is later flushed into the main ring buffer via IRQ work.
  *
  * The alternative implementation is chosen transparently
- * via @printk_func per-CPU variable.
+ * by examinig current printk() context mask stored in @printk_context
+ * per-CPU variable.
  *
  * The implementation allows to flush the strings also from another CPU.
  * There are situations when we want to make sure that all buffers
  * were handled or when IRQs are blocked.
  */
-DEFINE_PER_CPU(printk_func_t, printk_func) = vprintk_default;
 static int printk_safe_irq_ready;
 atomic_t nmi_message_lost;
 
@@ -50,18 +50,28 @@ struct printk_safe_seq_buf {
 	struct irq_work		work;	/* IRQ work that flushes the buffer */
 	unsigned char		buffer[SAFE_LOG_BUF_LEN];
 };
+
+static DEFINE_PER_CPU(struct printk_safe_seq_buf, safe_print_seq);
+static DEFINE_PER_CPU(int, printk_context);
+
+#ifdef CONFIG_PRINTK_NMI
 static DEFINE_PER_CPU(struct printk_safe_seq_buf, nmi_print_seq);
+#endif
 
 /*
- * Safe printk() for NMI context. It uses a per-CPU buffer to
- * store the message. NMIs are not nested, so there is always only
- * one writer running. But the buffer might get flushed from another
- * CPU, so we need to be careful.
+ * Add a message to per-CPU context-dependent buffer. NMI and printk-safe
+ * have dedicated buffers, because otherwise printk-safe preempted by
+ * NMI-printk would have overwritten the NMI messages.
+ *
+ * The messages are fushed from irq work (or from panic()), possibly,
+ * from other CPU, concurrently with printk_safe_log_store(). Should this
+ * happen, printk_safe_log_store() will notice the buffer->len mismatch
+ * and repeat the write.
  */
-static int vprintk_nmi(const char *fmt, va_list args)
+static int printk_safe_log_store(struct printk_safe_seq_buf *s,
+				 const char *fmt, va_list args)
 {
-	struct printk_safe_seq_buf *s = this_cpu_ptr(&nmi_print_seq);
-	int add = 0;
+	int add;
 	size_t len;
 
 again:
@@ -74,8 +84,8 @@ static int vprintk_nmi(const char *fmt, va_list args)
 	}
 
 	/*
-	 * Make sure that all old data have been read before the buffer was
-	 * reseted. This is not needed when we just append data.
+	 * Make sure that all old data have been read before the buffer
+	 * was reset. This is not needed when we just append data.
 	 */
 	if (!len)
 		smp_rmb();
@@ -161,7 +171,7 @@ static int printk_safe_flush_buffer(const char *start, size_t len)
 }
 
 /*
- * Flush data from the associated per_CPU buffer. The function
+ * Flush data from the associated per-CPU buffer. The function
  * can be called either via IRQ work or independently.
  */
 static void __printk_safe_flush(struct irq_work *work)
@@ -231,8 +241,12 @@ void printk_safe_flush(void)
 {
 	int cpu;
 
-	for_each_possible_cpu(cpu)
+	for_each_possible_cpu(cpu) {
+#ifdef CONFIG_PRINTK_NMI
 		__printk_safe_flush(&per_cpu(nmi_print_seq, cpu).work);
+#endif
+		__printk_safe_flush(&per_cpu(safe_print_seq, cpu).work);
+	}
 }
 
 /**
@@ -262,14 +276,88 @@ void printk_safe_flush_on_panic(void)
 	printk_safe_flush();
 }
 
+#ifdef CONFIG_PRINTK_NMI
+/*
+ * Safe printk() for NMI context. It uses a per-CPU buffer to
+ * store the message. NMIs are not nested, so there is always only
+ * one writer running. But the buffer might get flushed from another
+ * CPU, so we need to be careful.
+ */
+static int vprintk_nmi(const char *fmt, va_list args)
+{
+	struct printk_safe_seq_buf *s = this_cpu_ptr(&nmi_print_seq);
+
+	return printk_safe_log_store(s, fmt, args);
+}
+
+void printk_nmi_enter(void)
+{
+	this_cpu_or(printk_context, PRINTK_NMI_CONTEXT_MASK);
+}
+
+void printk_nmi_exit(void)
+{
+	this_cpu_and(printk_context, ~PRINTK_NMI_CONTEXT_MASK);
+}
+
+#else
+
+static int vprintk_nmi(const char *fmt, va_list args)
+{
+	return 0;
+}
+
+#endif /* CONFIG_PRINTK_NMI */
+
+/*
+ * Lock-less printk(), to avoid deadlocks should the printk() recurse
+ * into itself. It uses a per-CPU buffer to store the message, just like
+ * NMI.
+ */
+static int vprintk_safe(const char *fmt, va_list args)
+{
+	struct printk_safe_seq_buf *s = this_cpu_ptr(&safe_print_seq);
+
+	return printk_safe_log_store(s, fmt, args);
+}
+
+/* Can be preempted by NMI. */
+void __printk_safe_enter(void)
+{
+	this_cpu_inc(printk_context);
+}
+
+/* Can be preempted by NMI. */
+void __printk_safe_exit(void)
+{
+	this_cpu_dec(printk_context);
+}
+
+__printf(1, 0) int vprintk_func(const char *fmt, va_list args)
+{
+	if (this_cpu_read(printk_context) & PRINTK_NMI_CONTEXT_MASK)
+		return vprintk_nmi(fmt, args);
+
+	if (this_cpu_read(printk_context) & PRINTK_SAFE_CONTEXT_MASK)
+		return vprintk_safe(fmt, args);
+
+	return vprintk_default(fmt, args);
+}
+
 void __init printk_safe_init(void)
 {
 	int cpu;
 
 	for_each_possible_cpu(cpu) {
-		struct printk_safe_seq_buf *s = &per_cpu(nmi_print_seq, cpu);
+		struct printk_safe_seq_buf *s;
+
+		s = &per_cpu(safe_print_seq, cpu);
+		init_irq_work(&s->work, __printk_safe_flush);
 
+#ifdef CONFIG_PRINTK_NMI
+		s = &per_cpu(nmi_print_seq, cpu);
 		init_irq_work(&s->work, __printk_safe_flush);
+#endif
 	}
 
 	/* Make sure that IRQ works are initialized before enabling. */
@@ -279,13 +367,3 @@ void __init printk_safe_init(void)
 	/* Flush pending messages that did not have scheduled IRQ works. */
 	printk_safe_flush();
 }
-
-void printk_nmi_enter(void)
-{
-	this_cpu_write(printk_func, vprintk_nmi);
-}
-
-void printk_nmi_exit(void)
-{
-	this_cpu_write(printk_func, vprintk_default);
-}
-- 
2.11.0

Re: [PATCHv7 3/8] printk: introduce per-cpu safe_print seq buffer

[Petr Mladek]

On Tue 2016-12-27 23:16:06, Sergey Senozhatsky wrote:
> This patch extends the idea of NMI per-cpu buffers to regions
> that may cause recursive printk() calls and possible deadlocks.
> Namely, printk() can't handle printk calls from schedule code
> or printk() calls from lock debugging code (spin_dump() for instance);
> because those may be called with `sem->lock' already taken or any
> other `critical' locks (p->pi_lock, etc.). An example of deadlock
> can be
> 
> Usage example:
> 
>  printk()
>   printk_safe_enter_irqsave(flags)
>   //
>   //  any printk() call from here will endup in vprintk_safe(),
>   //  that stores messages in a special per-CPU buffer.
>   //
>   printk_safe_exit_irqrestore(flags)
> 
> Signed-off-by: Sergey Senozhatsky <sergey.senozhatsky@gmail.com>

I really like the new variants for printk_safe_enter/exit and
different IRQ context.

Reviewed-by: Petr Mladek <pmladek@suse.com>

Best Regards,
Petr

Re: [PATCHv7 3/8] printk: introduce per-cpu safe_print seq buffer

[Sergey Senozhatsky]

On (01/04/17 14:31), Petr Mladek wrote:
> On Tue 2016-12-27 23:16:06, Sergey Senozhatsky wrote:
> > This patch extends the idea of NMI per-cpu buffers to regions
> > that may cause recursive printk() calls and possible deadlocks.
> > Namely, printk() can't handle printk calls from schedule code
> > or printk() calls from lock debugging code (spin_dump() for instance);
> > because those may be called with `sem->lock' already taken or any
> > other `critical' locks (p->pi_lock, etc.). An example of deadlock
> > can be
> > 
> > Usage example:
> > 
> >  printk()
> >   printk_safe_enter_irqsave(flags)
> >   //
> >   //  any printk() call from here will endup in vprintk_safe(),
> >   //  that stores messages in a special per-CPU buffer.
> >   //
> >   printk_safe_exit_irqrestore(flags)
> > 
> > Signed-off-by: Sergey Senozhatsky <sergey.senozhatsky@gmail.com>
> 
> I really like the new variants for printk_safe_enter/exit and
> different IRQ context.
> 
> Reviewed-by: Petr Mladek <pmladek@suse.com>

thanks.

	-ss

Re: [PATCHv7 3/8] printk: introduce per-cpu safe_print seq buffer

[Steven Rostedt]

On Tue, 27 Dec 2016 23:16:06 +0900
Sergey Senozhatsky <sergey.senozhatsky@gmail.com> wrote:

> This patch extends the idea of NMI per-cpu buffers to regions
> that may cause recursive printk() calls and possible deadlocks.
> Namely, printk() can't handle printk calls from schedule code
> or printk() calls from lock debugging code (spin_dump() for instance);
> because those may be called with `sem->lock' already taken or any
> other `critical' locks (p->pi_lock, etc.). An example of deadlock
> can be
> 
>  vprintk_emit()
>   console_unlock()
>    up()                        << raw_spin_lock_irqsave(&sem->lock, flags);
>     wake_up_process()
>      try_to_wake_up()
>       ttwu_queue()
>        ttwu_activate()
>         activate_task()
>          enqueue_task()
>           enqueue_task_fair()
>            cfs_rq_of()
>             task_of()
>              WARN_ON_ONCE(!entity_is_task(se))
>               vprintk_emit()
>                console_trylock()
>                 down_trylock()
>                  raw_spin_lock_irqsave(&sem->lock, flags)
>                  ^^^^ deadlock
> 
> and some other cases.
> 
> Just like in NMI implementation, the solution uses a per-cpu
> `printk_func' pointer to 'redirect' printk() calls to a 'safe'
> callback, that store messages in a per-cpu buffer and flushes
> them back to logbuf buffer later.
> 
> Usage example:
> 
>  printk()
>   printk_safe_enter_irqsave(flags)
>   //
>   //  any printk() call from here will endup in vprintk_safe(),
>   //  that stores messages in a special per-CPU buffer.
>   //
>   printk_safe_exit_irqrestore(flags)
> 
> The 'redirection' mechanism, though, has been reworked, as suggested
> by Petr Mladek. Instead of using a per-cpu @print_func callback we now
> keep a per-cpu printk-context variable and call either default or nmi
> vprintk function depending on its value. printk_nmi_entrer/exit and
> printk_safe_enter/exit, thus, just set/celar corresponding bits in
> printk-context functions.
> 
> The patch only adds printk_safe support, we don't use it yet.
> 
> Signed-off-by: Sergey Senozhatsky <sergey.senozhatsky@gmail.com>


/me does the actual reviewed-by now :-p

Yes, I like this approach. I probably would have done it pretty much
the same way.

Reviewed-by: Steven Rostedt (VMware) <rostedt@goodmis.org>

-- Steve

[PATCHv7 4/8] printk: always use deferred printk when flush printk_safe lines

[Sergey Senozhatsky]

Always use printk_deferred() in printk_safe_flush_line().
Flushing can be done from NMI or printk_safe contexts (when
we are in panic), so we can't call console drivers, yet still
want to store the messages in the logbuf buffer. Therefore we
use a deferred printk version.

Signed-off-by: Sergey Senozhatsky <sergey.senozhatsky@gmail.com>
Suggested-by: Petr Mladek <pmladek@suse.com>
Reviewed-by: Petr Mladek <pmladek@suse.com>
---
 kernel/printk/printk_safe.c | 12 +++++-------
 1 file changed, 5 insertions(+), 7 deletions(-)

diff --git a/kernel/printk/printk_safe.c b/kernel/printk/printk_safe.c
index efc89a4e9df5..054c9128ade0 100644
--- a/kernel/printk/printk_safe.c
+++ b/kernel/printk/printk_safe.c
@@ -113,14 +113,12 @@ static int printk_safe_log_store(struct printk_safe_seq_buf *s,
 static void printk_safe_flush_line(const char *text, int len)
 {
 	/*
-	 * The buffers are flushed in NMI only on panic.  The messages must
-	 * go only into the ring buffer at this stage.  Consoles will get
-	 * explicitly called later when a crashdump is not generated.
+	 * Avoid any console drivers calls from here, because we may be
+	 * in NMI or printk_safe context (when in panic). The messages
+	 * must go only into the ring buffer at this stage.  Consoles will
+	 * get explicitly called later when a crashdump is not generated.
 	 */
-	if (in_nmi())
-		printk_deferred("%.*s", len, text);
-	else
-		printk("%.*s", len, text);
+	printk_deferred("%.*s", len, text);
 }
 
 /* printk part of the temporary buffer line by line */
-- 
2.11.0

Re: [PATCHv7 4/8] printk: always use deferred printk when flush printk_safe lines

[Steven Rostedt]

On Tue, 27 Dec 2016 23:16:07 +0900
Sergey Senozhatsky <sergey.senozhatsky@gmail.com> wrote:

> Always use printk_deferred() in printk_safe_flush_line().
> Flushing can be done from NMI or printk_safe contexts (when
> we are in panic), so we can't call console drivers, yet still
> want to store the messages in the logbuf buffer. Therefore we
> use a deferred printk version.
> 
> Signed-off-by: Sergey Senozhatsky <sergey.senozhatsky@gmail.com>
> Suggested-by: Petr Mladek <pmladek@suse.com>
> Reviewed-by: Petr Mladek <pmladek@suse.com>
> ---
>  kernel/printk/printk_safe.c | 12 +++++-------
>  1 file changed, 5 insertions(+), 7 deletions(-)
> 
> diff --git a/kernel/printk/printk_safe.c b/kernel/printk/printk_safe.c
> index efc89a4e9df5..054c9128ade0 100644
> --- a/kernel/printk/printk_safe.c
> +++ b/kernel/printk/printk_safe.c
> @@ -113,14 +113,12 @@ static int printk_safe_log_store(struct printk_safe_seq_buf *s,
>  static void printk_safe_flush_line(const char *text, int len)
>  {
>  	/*
> -	 * The buffers are flushed in NMI only on panic.  The messages must
> -	 * go only into the ring buffer at this stage.  Consoles will get
> -	 * explicitly called later when a crashdump is not generated.
> +	 * Avoid any console drivers calls from here, because we may be
> +	 * in NMI or printk_safe context (when in panic). The messages
> +	 * must go only into the ring buffer at this stage.  Consoles will
> +	 * get explicitly called later when a crashdump is not generated.
>  	 */
> -	if (in_nmi())
> -		printk_deferred("%.*s", len, text);
> -	else
> -		printk("%.*s", len, text);
> +	printk_deferred("%.*s", len, text);
>  }

The helper function was there because of the if statement. Just nuke
this function and call printk_deferred() directly. You can move the
comment to the caller.

-- Steve

>  
>  /* printk part of the temporary buffer line by line */

Re: [PATCHv7 4/8] printk: always use deferred printk when flush printk_safe lines

[Sergey Senozhatsky]

On (02/01/17 11:06), Steven Rostedt wrote:
[..]
> >  static void printk_safe_flush_line(const char *text, int len)
> >  {
> >  	/*
> > -	 * The buffers are flushed in NMI only on panic.  The messages must
> > -	 * go only into the ring buffer at this stage.  Consoles will get
> > -	 * explicitly called later when a crashdump is not generated.
> > +	 * Avoid any console drivers calls from here, because we may be
> > +	 * in NMI or printk_safe context (when in panic). The messages
> > +	 * must go only into the ring buffer at this stage.  Consoles will
> > +	 * get explicitly called later when a crashdump is not generated.
> >  	 */
> > -	if (in_nmi())
> > -		printk_deferred("%.*s", len, text);
> > -	else
> > -		printk("%.*s", len, text);
> > +	printk_deferred("%.*s", len, text);
> >  }
> 
> The helper function was there because of the if statement. Just nuke
> this function and call printk_deferred() directly. You can move the
> comment to the caller.

indeed. thanks.

Petr, how would you prefer to handle this?

	-ss

Re: [PATCHv7 4/8] printk: always use deferred printk when flush printk_safe lines

[Petr Mladek]

On Thu 2017-02-02 15:05:38, Sergey Senozhatsky wrote:
> On (02/01/17 11:06), Steven Rostedt wrote:
> [..]
> > >  static void printk_safe_flush_line(const char *text, int len)
> > >  {
> > >  	/*
> > > -	 * The buffers are flushed in NMI only on panic.  The messages must
> > > -	 * go only into the ring buffer at this stage.  Consoles will get
> > > -	 * explicitly called later when a crashdump is not generated.
> > > +	 * Avoid any console drivers calls from here, because we may be
> > > +	 * in NMI or printk_safe context (when in panic). The messages
> > > +	 * must go only into the ring buffer at this stage.  Consoles will
> > > +	 * get explicitly called later when a crashdump is not generated.
> > >  	 */
> > > -	if (in_nmi())
> > > -		printk_deferred("%.*s", len, text);
> > > -	else
> > > -		printk("%.*s", len, text);
> > > +	printk_deferred("%.*s", len, text);
> > >  }
> > 
> > The helper function was there because of the if statement. Just nuke
> > this function and call printk_deferred() directly. You can move the
> > comment to the caller.
> 
> indeed. thanks.
> 
> Petr, how would you prefer to handle this?

I am still learning how to manage the patches in the printk.git tree.

I would like to add Steven's Reviewed-by tags, links to the mails,
and list of CC-ed people. IMHO, the only way is to rebase the for-4.11
and for-next branches. Then I could do the above suggested change during
the rebase.

Any other solutions are welcome. I will wait with the rebase at least
until Monday. We are discussing the lockdep in the 6th patch anyway.

Best Regards,
Petr

Re: [PATCHv7 4/8] printk: always use deferred printk when flush printk_safe lines

[Petr Mladek]

On Thu 2017-02-02 16:37:53, Petr Mladek wrote:
> On Thu 2017-02-02 15:05:38, Sergey Senozhatsky wrote:
> > On (02/01/17 11:06), Steven Rostedt wrote:
> > [..]
> > > >  static void printk_safe_flush_line(const char *text, int len)
> > > >  {
> > > >  	/*
> > > > -	 * The buffers are flushed in NMI only on panic.  The messages must
> > > > -	 * go only into the ring buffer at this stage.  Consoles will get
> > > > -	 * explicitly called later when a crashdump is not generated.
> > > > +	 * Avoid any console drivers calls from here, because we may be
> > > > +	 * in NMI or printk_safe context (when in panic). The messages
> > > > +	 * must go only into the ring buffer at this stage.  Consoles will
> > > > +	 * get explicitly called later when a crashdump is not generated.
> > > >  	 */
> > > > -	if (in_nmi())
> > > > -		printk_deferred("%.*s", len, text);
> > > > -	else
> > > > -		printk("%.*s", len, text);
> > > > +	printk_deferred("%.*s", len, text);
> > > >  }
> > > 
> > > The helper function was there because of the if statement. Just nuke
> > > this function and call printk_deferred() directly. You can move the
> > > comment to the caller.
> > 
> > indeed. thanks.
> > 
> > Petr, how would you prefer to handle this?
> 
> I am still learning how to manage the patches in the printk.git tree.
> 
> I would like to add Steven's Reviewed-by tags, links to the mails,
> and list of CC-ed people. IMHO, the only way is to rebase the for-4.11
> and for-next branches. Then I could do the above suggested change during
> the rebase.

Alternatively you could send this other solution as a replay to this
thread. Then we could comment, add reviewed tags. And I could use
the new approved variant during the rebase.

This is probably better approach for non-oneliner changes.

> Any other solutions are welcome. I will wait with the rebase at least
> until Monday. We are discussing the lockdep in the 6th patch anyway.

Best Regards,
Petr

Re: [PATCHv7 4/8] printk: always use deferred printk when flush printk_safe lines

[Sergey Senozhatsky]

On (02/02/17 16:52), Petr Mladek wrote:
[..]
> > I am still learning how to manage the patches in the printk.git tree.
> > 
> > I would like to add Steven's Reviewed-by tags, links to the mails,
> > and list of CC-ed people. IMHO, the only way is to rebase the for-4.11
> > and for-next branches. Then I could do the above suggested change during
> > the rebase.
> 
> Alternatively you could send this other solution as a replay to this
> thread. Then we could comment, add reviewed tags. And I could use
> the new approved variant during the rebase.
> 
> This is probably better approach for non-oneliner changes.

by "the new approved variant" do you mean resend of the entire
patch set (v8) or just 0004 patch?

	-ss

Re: [PATCHv7 4/8] printk: always use deferred printk when flush printk_safe lines

[Petr Mladek]

On Fri 2017-02-03 11:04:18, Sergey Senozhatsky wrote:
> On (02/02/17 16:52), Petr Mladek wrote:
> [..]
> > > I am still learning how to manage the patches in the printk.git tree.
> > > 
> > > I would like to add Steven's Reviewed-by tags, links to the mails,
> > > and list of CC-ed people. IMHO, the only way is to rebase the for-4.11
> > > and for-next branches. Then I could do the above suggested change during
> > > the rebase.
> > 
> > Alternatively you could send this other solution as a replay to this
> > thread. Then we could comment, add reviewed tags. And I could use
> > the new approved variant during the rebase.
> > 
> > This is probably better approach for non-oneliner changes.
> 
> by "the new approved variant" do you mean resend of the entire
> patch set (v8) or just 0004 patch?

I depends on how many and how complicated are possible conflicts
with the followup patches.

It is perfectly fine to send just 0004 if there are no conflicts
or if they are trivial to resolve.

Best Regards,
Petr

Re: [PATCHv7 4/8] printk: always use deferred printk when flush printk_safe lines

[Sergey Senozhatsky]

On (02/03/17 12:18), Petr Mladek wrote:
[..]
> > by "the new approved variant" do you mean resend of the entire
> > patch set (v8) or just 0004 patch?
> 
> I depends on how many and how complicated are possible conflicts
> with the followup patches.
> 
> It is perfectly fine to send just 0004 if there are no conflicts
> or if they are trivial to resolve.

so there are no conflicts at all. 0004 can be replaced with the patch below.
but the thing is - I want to keep printk_safe_flush_line() around.

we call

static void printk_safe_flush_line(const char *text, int len)
{
	/*
	 * Avoid any console drivers calls from here, because we may be
	 * in NMI or printk_safe context (when in panic). The messages
	 * must go only into the ring buffer at this stage.  Consoles will
	 * get explicitly called later when a crashdump is not generated.
	 */
	printk_deferred("%.*s", len, text);
}

from many places:

  4x   printk_safe_flush_buffer()
  1x   __printk_safe_flush()


replacing printk_safe_flush_line() with printk_deferred() produces things
like these

               printk_deferred("%.*s", end - start, start);
               printk_deferred("%.*s", strlen(newline), newline);

which, I think, makes the code worse. any objections?

just in case, the patch (which I prefer to be ignored)

===8<======8<===

>From daa9bd8c2659a91036c00e22bb218be6871a371d Mon Sep 17 00:00:00 2001
From: Sergey Senozhatsky <sergey.senozhatsky@gmail.com>
Date: Tue, 27 Dec 2016 23:16:07 +0900
Subject: [PATCH] printk: always use deferred printk when flush printk_safe
 lines

Always use printk_deferred() in printk_safe_flush_line().
Flushing can be done from NMI or printk_safe contexts (when
we are in panic), so we can't call console drivers, yet still
want to store the messages in the logbuf buffer. Therefore we
use a deferred printk version.

Signed-off-by: Sergey Senozhatsky <sergey.senozhatsky@gmail.com>
Suggested-by: Petr Mladek <pmladek@suse.com>
---
 kernel/printk/printk_safe.c | 30 ++++++++++++------------------
 1 file changed, 12 insertions(+), 18 deletions(-)

diff --git a/kernel/printk/printk_safe.c b/kernel/printk/printk_safe.c
index efc89a4e9df5..801f0f1c7547 100644
--- a/kernel/printk/printk_safe.c
+++ b/kernel/printk/printk_safe.c
@@ -110,19 +110,6 @@ static int printk_safe_log_store(struct printk_safe_seq_buf *s,
 	return add;
 }
 
-static void printk_safe_flush_line(const char *text, int len)
-{
-	/*
-	 * The buffers are flushed in NMI only on panic.  The messages must
-	 * go only into the ring buffer at this stage.  Consoles will get
-	 * explicitly called later when a crashdump is not generated.
-	 */
-	if (in_nmi())
-		printk_deferred("%.*s", len, text);
-	else
-		printk("%.*s", len, text);
-}
-
 /* printk part of the temporary buffer line by line */
 static int printk_safe_flush_buffer(const char *start, size_t len)
 {
@@ -136,7 +123,14 @@ static int printk_safe_flush_buffer(const char *start, size_t len)
 	/* Print line by line. */
 	while (c < end) {
 		if (*c == '\n') {
-			printk_safe_flush_line(start, c - start + 1);
+			/*
+			 * Avoid any console drivers calls from here, because
+			 * we may be in NMI or printk_safe context (when in
+			 * panic). The messages must go only into the ring
+			 * buffer at this stage.  Consoles will get explicitly
+			 * called later when a crashdump is not generated.
+			 */
+			printk_deferred("%.*s", c - start + 1, start);
 			start = ++c;
 			header = true;
 			continue;
@@ -149,7 +143,7 @@ static int printk_safe_flush_buffer(const char *start, size_t len)
 				continue;
 			}
 
-			printk_safe_flush_line(start, c - start);
+			printk_deferred("%.*s", c - start, start);
 			start = c++;
 			header = true;
 			continue;
@@ -163,8 +157,8 @@ static int printk_safe_flush_buffer(const char *start, size_t len)
 	if (start < end && !header) {
 		static const char newline[] = KERN_CONT "\n";
 
-		printk_safe_flush_line(start, end - start);
-		printk_safe_flush_line(newline, strlen(newline));
+		printk_deferred("%.*s", end - start, start);
+		printk_deferred("%.*s", strlen(newline), newline);
 	}
 
 	return len;
@@ -206,7 +200,7 @@ static void __printk_safe_flush(struct irq_work *work)
 	if ((i && i >= len) || len > sizeof(s->buffer)) {
 		const char *msg = "printk_safe_flush: internal error\n";
 
-		printk_safe_flush_line(msg, strlen(msg));
+		printk_deferred("%.*s", strlen(msg), msg);
 		len = 0;
 	}
 
-- 
2.11.1

Re: [PATCHv7 4/8] printk: always use deferred printk when flush printk_safe lines

[Sergey Senozhatsky]

On (02/06/17 10:48), Sergey Senozhatsky wrote:
[..]
> from many places:
> 
>   4x   printk_safe_flush_buffer()
>   1x   __printk_safe_flush()
> 
> 
> replacing printk_safe_flush_line() with printk_deferred() produces things
> like these
> 
>                printk_deferred("%.*s", end - start, start);
>                printk_deferred("%.*s", strlen(newline), newline);

ah... besides we need to cast length argument to "int".


> just in case, the patch (which I prefer to be ignored)

let's keep printk_safe_flush_line().

	-ss

Re: [PATCHv7 4/8] printk: always use deferred printk when flush printk_safe lines

[Petr Mladek]

On Mon 2017-02-06 11:08:20, Sergey Senozhatsky wrote:
> On (02/06/17 10:48), Sergey Senozhatsky wrote:
> [..]
> > from many places:
> > 
> >   4x   printk_safe_flush_buffer()
> >   1x   __printk_safe_flush()
> > 
> > 
> > replacing printk_safe_flush_line() with printk_deferred() produces things
> > like these
> > 
> >                printk_deferred("%.*s", end - start, start);
> >                printk_deferred("%.*s", strlen(newline), newline);
> 
> ah... besides we need to cast length argument to "int".

Good point.


> > just in case, the patch (which I prefer to be ignored)
> 
> let's keep printk_safe_flush_line().

I do not have strong opinion but I would slightly prefer
to keep the helper function. The use of printk_deferred()
is a bit tricky and it is better to have only one copy.

Steven, could you live with the original patch, please?

Best Regards,
Petr

Re: [PATCHv7 4/8] printk: always use deferred printk when flush printk_safe lines

[Steven Rostedt]

On Mon, 6 Feb 2017 13:16:52 +0100
Petr Mladek <pmladek@suse.com> wrote:

 
> > > just in case, the patch (which I prefer to be ignored)  
> > 
> > let's keep printk_safe_flush_line().  
> 
> I do not have strong opinion but I would slightly prefer
> to keep the helper function. The use of printk_deferred()
> is a bit tricky and it is better to have only one copy.
> 
> Steven, could you live with the original patch, please?

Sure, but make it into a static inline.

-- Steve

Re: [PATCHv7 4/8] printk: always use deferred printk when flush printk_safe lines

[Sergey Senozhatsky]

On (02/06/17 08:27), Steven Rostedt wrote:
[..]
> > > > just in case, the patch (which I prefer to be ignored)  
> > > 
> > > let's keep printk_safe_flush_line().  
> > 
> > I do not have strong opinion but I would slightly prefer
> > to keep the helper function. The use of printk_deferred()
> > is a bit tricky and it is better to have only one copy.
> > 
> > Steven, could you live with the original patch, please?
> 
> Sure, but make it into a static inline.

well, I'll be surprised if gcc doesn't inline that simple one-liner.

attached. no conflicts, the patch can replace 0004.

===8<===8<===

>From 69bbb0f436a2a89ec41a5831c03490e0a78ce12e Mon Sep 17 00:00:00 2001
From: Sergey Senozhatsky <sergey.senozhatsky@gmail.com>
Date: Tue, 27 Dec 2016 23:16:07 +0900
Subject: [PATCH] printk: always use deferred printk when flush printk_safe
 lines

Always use printk_deferred() in printk_safe_flush_line().
Flushing can be done from NMI or printk_safe contexts (when
we are in panic), so we can't call console drivers, yet still
want to store the messages in the logbuf buffer. Therefore we
use a deferred printk version.

Signed-off-by: Sergey Senozhatsky <sergey.senozhatsky@gmail.com>
Suggested-by: Petr Mladek <pmladek@suse.com>
Signed-off-by: Petr Mladek <pmladek@suse.com>
---
 kernel/printk/printk_safe.c | 14 ++++++--------
 1 file changed, 6 insertions(+), 8 deletions(-)

diff --git a/kernel/printk/printk_safe.c b/kernel/printk/printk_safe.c
index efc89a4e9df5..5214d326d3ba 100644
--- a/kernel/printk/printk_safe.c
+++ b/kernel/printk/printk_safe.c
@@ -110,17 +110,15 @@ static int printk_safe_log_store(struct printk_safe_seq_buf *s,
 	return add;
 }
 
-static void printk_safe_flush_line(const char *text, int len)
+static inline void printk_safe_flush_line(const char *text, int len)
 {
 	/*
-	 * The buffers are flushed in NMI only on panic.  The messages must
-	 * go only into the ring buffer at this stage.  Consoles will get
-	 * explicitly called later when a crashdump is not generated.
+	 * Avoid any console drivers calls from here, because we may be
+	 * in NMI or printk_safe context (when in panic). The messages
+	 * must go only into the ring buffer at this stage.  Consoles will
+	 * get explicitly called later when a crashdump is not generated.
 	 */
-	if (in_nmi())
-		printk_deferred("%.*s", len, text);
-	else
-		printk("%.*s", len, text);
+	printk_deferred("%.*s", len, text);
 }
 
 /* printk part of the temporary buffer line by line */
-- 
2.11.0

Re: [PATCHv7 4/8] printk: always use deferred printk when flush printk_safe lines

[Steven Rostedt]

On Tue, 7 Feb 2017 01:42:53 +0900
Sergey Senozhatsky <sergey.senozhatsky@gmail.com> wrote:

> On (02/06/17 08:27), Steven Rostedt wrote:
> [..]
> > > > > just in case, the patch (which I prefer to be ignored)    
> > > > 
> > > > let's keep printk_safe_flush_line().    
> > > 
> > > I do not have strong opinion but I would slightly prefer
> > > to keep the helper function. The use of printk_deferred()
> > > is a bit tricky and it is better to have only one copy.
> > > 
> > > Steven, could you live with the original patch, please?  
> > 
> > Sure, but make it into a static inline.  
> 
> well, I'll be surprised if gcc doesn't inline that simple one-liner.

I never trust gcc ;-)  It's been known to uninline simple one liners
before that have been marked as "inline" :-p

> 
> attached. no conflicts, the patch can replace 0004.
> 
> ===8<===8<===
> 
> >From 69bbb0f436a2a89ec41a5831c03490e0a78ce12e Mon Sep 17 00:00:00 2001  
> From: Sergey Senozhatsky <sergey.senozhatsky@gmail.com>
> Date: Tue, 27 Dec 2016 23:16:07 +0900
> Subject: [PATCH] printk: always use deferred printk when flush printk_safe
>  lines
> 
> Always use printk_deferred() in printk_safe_flush_line().
> Flushing can be done from NMI or printk_safe contexts (when
> we are in panic), so we can't call console drivers, yet still
> want to store the messages in the logbuf buffer. Therefore we
> use a deferred printk version.
> 
> Signed-off-by: Sergey Senozhatsky <sergey.senozhatsky@gmail.com>
> Suggested-by: Petr Mladek <pmladek@suse.com>
> Signed-off-by: Petr Mladek <pmladek@suse.com>

Reviewed-by: Steven Rostedt (VMware) <rostedt@goodmis.org>

-- Steve

> ---
>  kernel/printk/printk_safe.c | 14 ++++++--------
>  1 file changed, 6 insertions(+), 8 deletions(-)
> 
> diff --git a/kernel/printk/printk_safe.c b/kernel/printk/printk_safe.c
> index efc89a4e9df5..5214d326d3ba 100644
> --- a/kernel/printk/printk_safe.c
> +++ b/kernel/printk/printk_safe.c
> @@ -110,17 +110,15 @@ static int printk_safe_log_store(struct printk_safe_seq_buf *s,
>  	return add;
>  }
>  
> -static void printk_safe_flush_line(const char *text, int len)
> +static inline void printk_safe_flush_line(const char *text, int len)
>  {
>  	/*
> -	 * The buffers are flushed in NMI only on panic.  The messages must
> -	 * go only into the ring buffer at this stage.  Consoles will get
> -	 * explicitly called later when a crashdump is not generated.
> +	 * Avoid any console drivers calls from here, because we may be
> +	 * in NMI or printk_safe context (when in panic). The messages
> +	 * must go only into the ring buffer at this stage.  Consoles will
> +	 * get explicitly called later when a crashdump is not generated.
>  	 */
> -	if (in_nmi())
> -		printk_deferred("%.*s", len, text);
> -	else
> -		printk("%.*s", len, text);
> +	printk_deferred("%.*s", len, text);
>  }
>  
>  /* printk part of the temporary buffer line by line */

[PATCHv7 5/8] printk: report lost messages in printk safe/nmi contexts

[Sergey Senozhatsky]

Account lost messages in pritk-safe and printk-safe-nmi
contexts and report those numbers during printk_safe_flush().

The patch also moves lost message counter to struct
`printk_safe_seq_buf' instead of having dedicated static
counters - this simplifies the code.

Signed-off-by: Sergey Senozhatsky <sergey.senozhatsky@gmail.com>
---
 kernel/printk/internal.h    | 17 -----------------
 kernel/printk/printk.c      | 10 ----------
 kernel/printk/printk_safe.c | 38 ++++++++++++++++++++++++++++----------
 3 files changed, 28 insertions(+), 37 deletions(-)

diff --git a/kernel/printk/internal.h b/kernel/printk/internal.h
index c65e36509f3b..1db044f808b7 100644
--- a/kernel/printk/internal.h
+++ b/kernel/printk/internal.h
@@ -16,23 +16,6 @@
  */
 #include <linux/percpu.h>
 
-#ifdef CONFIG_PRINTK_NMI
-
-extern atomic_t nmi_message_lost;
-static inline int get_nmi_message_lost(void)
-{
-	return atomic_xchg(&nmi_message_lost, 0);
-}
-
-#else /* CONFIG_PRINTK_NMI */
-
-static inline int get_nmi_message_lost(void)
-{
-	return 0;
-}
-
-#endif /* CONFIG_PRINTK_NMI */
-
 #ifdef CONFIG_PRINTK
 
 #define PRINTK_SAFE_CONTEXT_MASK	0x7fffffff
diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
index 9cc9a97c2cc8..86f3f03faf6f 100644
--- a/kernel/printk/printk.c
+++ b/kernel/printk/printk.c
@@ -1676,7 +1676,6 @@ asmlinkage int vprintk_emit(int facility, int level,
 	unsigned long flags;
 	int this_cpu;
 	int printed_len = 0;
-	int nmi_message_lost;
 	bool in_sched = false;
 	/* cpu currently holding logbuf_lock in this function */
 	static unsigned int logbuf_cpu = UINT_MAX;
@@ -1727,15 +1726,6 @@ asmlinkage int vprintk_emit(int facility, int level,
 					 strlen(recursion_msg));
 	}
 
-	nmi_message_lost = get_nmi_message_lost();
-	if (unlikely(nmi_message_lost)) {
-		text_len = scnprintf(textbuf, sizeof(textbuf),
-				     "BAD LUCK: lost %d message(s) from NMI context!",
-				     nmi_message_lost);
-		printed_len += log_store(0, 2, LOG_PREFIX|LOG_NEWLINE, 0,
-					 NULL, 0, textbuf, text_len);
-	}
-
 	/*
 	 * The printf needs to come first; we need the syslog
 	 * prefix which might be passed-in as a parameter.
diff --git a/kernel/printk/printk_safe.c b/kernel/printk/printk_safe.c
index 054c9128ade0..04fff7074cce 100644
--- a/kernel/printk/printk_safe.c
+++ b/kernel/printk/printk_safe.c
@@ -40,13 +40,15 @@
  * were handled or when IRQs are blocked.
  */
 static int printk_safe_irq_ready;
-atomic_t nmi_message_lost;
 
 #define SAFE_LOG_BUF_LEN ((1 << CONFIG_PRINTK_SAFE_LOG_BUF_SHIFT) -	\
-			 sizeof(atomic_t) - sizeof(struct irq_work))
+				sizeof(atomic_t) -			\
+				sizeof(atomic_t) -			\
+				sizeof(struct irq_work))
 
 struct printk_safe_seq_buf {
 	atomic_t		len;	/* length of written data */
+	atomic_t		message_lost;
 	struct irq_work		work;	/* IRQ work that flushes the buffer */
 	unsigned char		buffer[SAFE_LOG_BUF_LEN];
 };
@@ -58,6 +60,16 @@ static DEFINE_PER_CPU(int, printk_context);
 static DEFINE_PER_CPU(struct printk_safe_seq_buf, nmi_print_seq);
 #endif
 
+/* Get flushed in a more safe context. */
+static void queue_flush_work(struct printk_safe_seq_buf *s)
+{
+	if (printk_safe_irq_ready) {
+		/* Make sure that IRQ work is really initialized. */
+		smp_rmb();
+		irq_work_queue(&s->work);
+	}
+}
+
 /*
  * Add a message to per-CPU context-dependent buffer. NMI and printk-safe
  * have dedicated buffers, because otherwise printk-safe preempted by
@@ -79,7 +91,8 @@ static int printk_safe_log_store(struct printk_safe_seq_buf *s,
 
 	/* The trailing '\0' is not counted into len. */
 	if (len >= sizeof(s->buffer) - 1) {
-		atomic_inc(&nmi_message_lost);
+		atomic_inc(&s->message_lost);
+		queue_flush_work(s);
 		return 0;
 	}
 
@@ -91,6 +104,8 @@ static int printk_safe_log_store(struct printk_safe_seq_buf *s,
 		smp_rmb();
 
 	add = vscnprintf(s->buffer + len, sizeof(s->buffer) - len, fmt, args);
+	if (!add)
+		return 0;
 
 	/*
 	 * Do it once again if the buffer has been flushed in the meantime.
@@ -100,13 +115,7 @@ static int printk_safe_log_store(struct printk_safe_seq_buf *s,
 	if (atomic_cmpxchg(&s->len, len, len + add) != len)
 		goto again;
 
-	/* Get flushed in a more safe context. */
-	if (add && printk_safe_irq_ready) {
-		/* Make sure that IRQ work is really initialized. */
-		smp_rmb();
-		irq_work_queue(&s->work);
-	}
-
+	queue_flush_work(s);
 	return add;
 }
 
@@ -168,6 +177,14 @@ static int printk_safe_flush_buffer(const char *start, size_t len)
 	return len;
 }
 
+static void report_message_lost(struct printk_safe_seq_buf *s)
+{
+	int lost = atomic_xchg(&s->message_lost, 0);
+
+	if (lost)
+		printk_deferred("Lost %d message(s)!\n", lost);
+}
+
 /*
  * Flush data from the associated per-CPU buffer. The function
  * can be called either via IRQ work or independently.
@@ -225,6 +242,7 @@ static void __printk_safe_flush(struct irq_work *work)
 		goto more;
 
 out:
+	report_message_lost(s);
 	raw_spin_unlock_irqrestore(&read_lock, flags);
 }
 
-- 
2.11.0

Re: [PATCHv7 5/8] printk: report lost messages in printk safe/nmi contexts

[Petr Mladek]

On Tue 2016-12-27 23:16:08, Sergey Senozhatsky wrote:
> Account lost messages in pritk-safe and printk-safe-nmi
> contexts and report those numbers during printk_safe_flush().
> 
> The patch also moves lost message counter to struct
> `printk_safe_seq_buf' instead of having dedicated static
> counters - this simplifies the code.
> 
> Signed-off-by: Sergey Senozhatsky <sergey.senozhatsky@gmail.com>

I like that the handling is localized in printk_safe.c and that
the warning is printed right after the messages that fit the buffer.

Reviewed-by: Petr Mladek <pmladek@suse.com>

Best Regards,
Petr

Re: [PATCHv7 5/8] printk: report lost messages in printk safe/nmi contexts

[Sergey Senozhatsky]

On (01/04/17 15:46), Petr Mladek wrote:
> On Tue 2016-12-27 23:16:08, Sergey Senozhatsky wrote:
> > Account lost messages in pritk-safe and printk-safe-nmi
> > contexts and report those numbers during printk_safe_flush().
> > 
> > The patch also moves lost message counter to struct
> > `printk_safe_seq_buf' instead of having dedicated static
> > counters - this simplifies the code.
> > 
> > Signed-off-by: Sergey Senozhatsky <sergey.senozhatsky@gmail.com>
> 
> I like that the handling is localized in printk_safe.c and that
> the warning is printed right after the messages that fit the buffer.
> 
> Reviewed-by: Petr Mladek <pmladek@suse.com>

thanks.

	-ss

Re: [PATCHv7 5/8] printk: report lost messages in printk safe/nmi contexts

[Steven Rostedt]

On Tue, 27 Dec 2016 23:16:08 +0900
Sergey Senozhatsky <sergey.senozhatsky@gmail.com> wrote:

> Account lost messages in pritk-safe and printk-safe-nmi
> contexts and report those numbers during printk_safe_flush().
> 
> The patch also moves lost message counter to struct
> `printk_safe_seq_buf' instead of having dedicated static
> counters - this simplifies the code.
> 
> Signed-off-by: Sergey Senozhatsky <sergey.senozhatsky@gmail.com>
> ---

This looks fine, but I'm curious if you tested it. That is, added a
bunch of printks to overflow the buffer. IIRC, I did it to the original
nmi code. If you haven't you may want to just to make sure it works. I
can also test it too if I get some time.

-- Steve

Re: [PATCHv7 5/8] printk: report lost messages in printk safe/nmi contexts

[Sergey Senozhatsky]

On (02/01/17 11:37), Steven Rostedt wrote:
> This looks fine, but I'm curious if you tested it. That is, added a
> bunch of printks to overflow the buffer. IIRC, I did it to the original
> nmi code. If you haven't you may want to just to make sure it works. I
> can also test it too if I get some time.

Hello Steven,

yes, I have tested it on my x86 box.

	-ss

Re: [PATCHv7 5/8] printk: report lost messages in printk safe/nmi contexts

[Steven Rostedt]

On Thu, 2 Feb 2017 11:02:57 +0900
Sergey Senozhatsky <sergey.senozhatsky.work@gmail.com> wrote:

> On (02/01/17 11:37), Steven Rostedt wrote:
> > This looks fine, but I'm curious if you tested it. That is, added a
> > bunch of printks to overflow the buffer. IIRC, I did it to the original
> > nmi code. If you haven't you may want to just to make sure it works. I
> > can also test it too if I get some time.  
> 
> Hello Steven,
> 
> yes, I have tested it on my x86 box.
> 

Please note how you tested it in your change log. It's not really a
requirement, and you don't really have to do it. But it helps people
have warm fuzzies about the code. I'm trying to do this in the future
in my own work too.

-- Steve

Re: [PATCHv7 5/8] printk: report lost messages in printk safe/nmi contexts

[Petr Mladek]

On Thu 2017-02-02 09:34:09, Steven Rostedt wrote:
> On Thu, 2 Feb 2017 11:02:57 +0900
> Sergey Senozhatsky <sergey.senozhatsky.work@gmail.com> wrote:
> 
> > On (02/01/17 11:37), Steven Rostedt wrote:
> > > This looks fine, but I'm curious if you tested it. That is, added a
> > > bunch of printks to overflow the buffer. IIRC, I did it to the original
> > > nmi code. If you haven't you may want to just to make sure it works. I
> > > can also test it too if I get some time.  

I have tested it and actually found a bug. I was lucky because it was
a cornercase. It is already fixed upstream by the commit
4a998e322abc935e ("printk/NMI: fix up handling of the full nmi
log buffer").

> Please note how you tested it in your change log. It's not really a
> requirement, and you don't really have to do it. But it helps people
> have warm fuzzies about the code. I'm trying to do this in the future
> in my own work too.

Goot to know.

Best Regards,
Petr

Re: [PATCHv7 5/8] printk: report lost messages in printk safe/nmi contexts

[Sergey Senozhatsky]

On (02/02/17 09:34), Steven Rostedt wrote:
> On Thu, 2 Feb 2017 11:02:57 +0900
> Sergey Senozhatsky <sergey.senozhatsky.work@gmail.com> wrote:
> 
> > On (02/01/17 11:37), Steven Rostedt wrote:
> > > This looks fine, but I'm curious if you tested it. That is, added a
> > > bunch of printks to overflow the buffer. IIRC, I did it to the original
> > > nmi code. If you haven't you may want to just to make sure it works. I
> > > can also test it too if I get some time.
> > 
> > Hello Steven,
> > 
> > yes, I have tested it on my x86 box.
> > 
> 
> Please note how you tested it in your change log. It's not really a
> requirement, and you don't really have to do it. But it helps people
> have warm fuzzies about the code. I'm trying to do this in the future
> in my own work too.

well. sure, no objections, but in this particular case it's hardly possible
to hit all of those problems within a reasonable time. so what I did was just
a bunch of dirty hacks to provoke the problems. something like this

	extern int XXX;

	vprintk_emit()
	{
		spin_lock(&logbuf_lock);

			//
			// in various places
			//
			if (XXX == 1) {
				WARN_ON(1);
			}

		spin_unlock(&logbuf_lock);
	}

and I set/clear that XXX from one of sysfs attrs... yeah, I know...
but it does what I want. so I'm not really sure I want to note this
in the change log. am I wrong?

	-ss

Re: [PATCHv7 5/8] printk: report lost messages in printk safe/nmi contexts

[Steven Rostedt]

On Fri, 3 Feb 2017 10:57:57 +0900
Sergey Senozhatsky <sergey.senozhatsky.work@gmail.com> wrote:
ell. sure, no objections, but in this particular case it's hardly
possible
> to hit all of those problems within a reasonable time. so what I did was just
> a bunch of dirty hacks to provoke the problems. something like this
> 
> 	extern int XXX;
> 
> 	vprintk_emit()
> 	{
> 		spin_lock(&logbuf_lock);
> 
> 			//
> 			// in various places
> 			//
> 			if (XXX == 1) {
> 				WARN_ON(1);
> 			}
> 
> 		spin_unlock(&logbuf_lock);
> 	}
> 
> and I set/clear that XXX from one of sysfs attrs... yeah, I know...
> but it does what I want. so I'm not really sure I want to note this
> in the change log. am I wrong?

No you are not. But just seeing this in email does help. And yeah, this
is the type of testing that I do as well on things like this. No need
to put it in the change log.

-- Steve

[PATCHv7 6/8] printk: use printk_safe buffers in printk

[Sergey Senozhatsky]

Use printk_safe per-CPU buffers in printk recursion-prone blocks:
-- around logbuf_lock protected sections in vprintk_emit() and
   console_unlock()
-- around down_trylock_console_sem() and up_console_sem()

Note that this solution addresses deadlocks caused by printk()
recursive calls only. That is vprintk_emit() and console_unlock().
The rest will be converted in a followup patch.

Another thing to note is that we now keep lockdep enabled in printk,
because we are protected against the printk recursion caused by
lockdep in vprintk_emit() by the printk-safe mechanism - we first
switch to per-CPU buffers and only then access the deadlock-prone
locks.

Examples:

1) printk() from logbuf_lock spin_lock section

Assume the following code:
  printk()
    raw_spin_lock(&logbuf_lock);
    WARN_ON(1);
    raw_spin_unlock(&logbuf_lock);

which now produces:

 ------------[ cut here ]------------
 WARNING: CPU: 0 PID: 366 at kernel/printk/printk.c:1811 vprintk_emit
 CPU: 0 PID: 366 Comm: bash
 Call Trace:
   warn_slowpath_null+0x1d/0x1f
   vprintk_emit+0x1cd/0x438
   vprintk_default+0x1d/0x1f
   printk+0x48/0x50
  [..]

2) printk() from semaphore sem->lock spin_lock section

Assume the following code

  printk()
    console_trylock()
      down_trylock()
        raw_spin_lock_irqsave(&sem->lock, flags);
        WARN_ON(1);
        raw_spin_unlock_irqrestore(&sem->lock, flags);

which now produces:

 ------------[ cut here ]------------
 WARNING: CPU: 1 PID: 363 at kernel/locking/semaphore.c:141 down_trylock
 CPU: 1 PID: 363 Comm: bash
 Call Trace:
   warn_slowpath_null+0x1d/0x1f
   down_trylock+0x3d/0x62
   ? vprintk_emit+0x3f9/0x414
   console_trylock+0x31/0xeb
   vprintk_emit+0x3f9/0x414
   vprintk_default+0x1d/0x1f
   printk+0x48/0x50
  [..]

3) printk() from console_unlock()

Assume the following code:

  printk()
    console_unlock()
      raw_spin_lock(&logbuf_lock);
      WARN_ON(1);
      raw_spin_unlock(&logbuf_lock);

which now produces:

 ------------[ cut here ]------------
 WARNING: CPU: 1 PID: 329 at kernel/printk/printk.c:2384 console_unlock
 CPU: 1 PID: 329 Comm: bash
 Call Trace:
   warn_slowpath_null+0x18/0x1a
   console_unlock+0x12d/0x559
   ? trace_hardirqs_on_caller+0x16d/0x189
   ? trace_hardirqs_on+0xd/0xf
   vprintk_emit+0x363/0x374
   vprintk_default+0x18/0x1a
   printk+0x43/0x4b
  [..]

4) printk() from try_to_wake_up()

Assume the following code:

  printk()
    console_unlock()
      up()
        try_to_wake_up()
          raw_spin_lock_irqsave(&p->pi_lock, flags);
          WARN_ON(1);
          raw_spin_unlock_irqrestore(&p->pi_lock, flags);

which now produces:

 ------------[ cut here ]------------
 WARNING: CPU: 3 PID: 363 at kernel/sched/core.c:2028 try_to_wake_up
 CPU: 3 PID: 363 Comm: bash
 Call Trace:
   warn_slowpath_null+0x1d/0x1f
   try_to_wake_up+0x7f/0x4f7
   wake_up_process+0x15/0x17
   __up.isra.0+0x56/0x63
   up+0x32/0x42
   __up_console_sem+0x37/0x55
   console_unlock+0x21e/0x4c2
   vprintk_emit+0x41c/0x462
   vprintk_default+0x1d/0x1f
   printk+0x48/0x50
  [..]

5) printk() from call_console_drivers()

Assume the following code:
  printk()
    console_unlock()
      call_console_drivers()
      ...
          WARN_ON(1);

which now produces:

 ------------[ cut here ]------------
 WARNING: CPU: 2 PID: 305 at kernel/printk/printk.c:1604 call_console_drivers
 CPU: 2 PID: 305 Comm: bash
 Call Trace:
   warn_slowpath_null+0x18/0x1a
   call_console_drivers.isra.6.constprop.16+0x3a/0xb0
   console_unlock+0x471/0x48e
   vprintk_emit+0x1f4/0x206
   vprintk_default+0x18/0x1a
   vprintk_func+0x6e/0x70
   printk+0x3e/0x46
  [..]

6) unsupported placeholder in printk() format now prints an actual
   warning from vscnprintf(), instead of
   	'BUG: recent printk recursion!'.

 ------------[ cut here ]------------
 WARNING: CPU: 5 PID: 337 at lib/vsprintf.c:1900 format_decode
 Please remove unsupported %
  in format string
 CPU: 5 PID: 337 Comm: bash
 Call Trace:
   dump_stack+0x4f/0x65
   __warn+0xc2/0xdd
   warn_slowpath_fmt+0x4b/0x53
   format_decode+0x22c/0x308
   vsnprintf+0x89/0x3b7
   vscnprintf+0xd/0x26
   vprintk_emit+0xb4/0x238
   vprintk_default+0x1d/0x1f
   vprintk_func+0x6c/0x73
   printk+0x43/0x4b
  [..]

Signed-off-by: Sergey Senozhatsky <sergey.senozhatsky@gmail.com>
Reviewed-by: Petr Mladek <pmladek@suse.com>
---
 kernel/printk/printk.c | 47 ++++++++++++++++++++++++++++++++---------------
 1 file changed, 32 insertions(+), 15 deletions(-)

diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
index 86f3f03faf6f..2dd43ae94c64 100644
--- a/kernel/printk/printk.c
+++ b/kernel/printk/printk.c
@@ -213,17 +213,36 @@ static int nr_ext_console_drivers;
 
 static int __down_trylock_console_sem(unsigned long ip)
 {
-	if (down_trylock(&console_sem))
+	int lock_failed;
+	unsigned long flags;
+
+	/*
+	 * Here and in __up_console_sem() we need to be in safe mode,
+	 * because spindump/WARN/etc from under console ->lock will
+	 * deadlock in printk()->down_trylock_console_sem() otherwise.
+	 */
+	printk_safe_enter_irqsave(flags);
+	lock_failed = down_trylock(&console_sem);
+	printk_safe_exit_irqrestore(flags);
+
+	if (lock_failed)
 		return 1;
 	mutex_acquire(&console_lock_dep_map, 0, 1, ip);
 	return 0;
 }
 #define down_trylock_console_sem() __down_trylock_console_sem(_RET_IP_)
 
-#define up_console_sem() do { \
-	mutex_release(&console_lock_dep_map, 1, _RET_IP_);\
-	up(&console_sem);\
-} while (0)
+static void __up_console_sem(unsigned long ip)
+{
+	unsigned long flags;
+
+	mutex_release(&console_lock_dep_map, 1, ip);
+
+	printk_safe_enter_irqsave(flags);
+	up(&console_sem);
+	printk_safe_exit_irqrestore(flags);
+}
+#define up_console_sem() __up_console_sem(_RET_IP_)
 
 /*
  * This is used for debugging the mess that is the VT code by
@@ -1688,7 +1707,7 @@ asmlinkage int vprintk_emit(int facility, int level,
 	boot_delay_msec(level);
 	printk_delay();
 
-	local_irq_save(flags);
+	printk_safe_enter_irqsave(flags);
 	this_cpu = smp_processor_id();
 
 	/*
@@ -1704,13 +1723,12 @@ asmlinkage int vprintk_emit(int facility, int level,
 		 */
 		if (!oops_in_progress && !lockdep_recursing(current)) {
 			recursion_bug = true;
-			local_irq_restore(flags);
+			printk_safe_exit_irqrestore(flags);
 			return 0;
 		}
 		zap_locks();
 	}
 
-	lockdep_off();
 	/* This stops the holder of console_sem just where we want him */
 	raw_spin_lock(&logbuf_lock);
 	logbuf_cpu = this_cpu;
@@ -1770,12 +1788,10 @@ asmlinkage int vprintk_emit(int facility, int level,
 
 	logbuf_cpu = UINT_MAX;
 	raw_spin_unlock(&logbuf_lock);
-	lockdep_on();
-	local_irq_restore(flags);
+	printk_safe_exit_irqrestore(flags);
 
 	/* If called from the scheduler, we can not call up(). */
 	if (!in_sched) {
-		lockdep_off();
 		/*
 		 * Try to acquire and then immediately release the console
 		 * semaphore.  The release will print out buffers and wake up
@@ -1783,7 +1799,6 @@ asmlinkage int vprintk_emit(int facility, int level,
 		 */
 		if (console_trylock())
 			console_unlock();
-		lockdep_on();
 	}
 
 	return printed_len;
@@ -2207,7 +2222,8 @@ void console_unlock(void)
 		size_t len;
 		bool report_dropped_msg = false;
 
-		raw_spin_lock_irqsave(&logbuf_lock, flags);
+		printk_safe_enter_irqsave(flags);
+		raw_spin_lock(&logbuf_lock);
 		if (seen_seq != log_next_seq) {
 			wake_klogd = true;
 			seen_seq = log_next_seq;
@@ -2258,7 +2274,7 @@ void console_unlock(void)
 		stop_critical_timings();	/* don't trace print latency */
 		call_console_drivers(ext_text, ext_len, text, len);
 		start_critical_timings();
-		local_irq_restore(flags);
+		printk_safe_exit_irqrestore(flags);
 
 		if (do_cond_resched)
 			cond_resched();
@@ -2281,7 +2297,8 @@ void console_unlock(void)
 	 */
 	raw_spin_lock(&logbuf_lock);
 	retry = console_seq != log_next_seq;
-	raw_spin_unlock_irqrestore(&logbuf_lock, flags);
+	raw_spin_unlock(&logbuf_lock);
+	printk_safe_exit_irqrestore(flags);
 
 	if (retry && console_trylock())
 		goto again;
-- 
2.11.0

Re: [PATCHv7 6/8] printk: use printk_safe buffers in printk

[Ross Zwisler]

On Tue, Dec 27, 2016 at 7:16 AM, Sergey Senozhatsky
<sergey.senozhatsky@gmail.com> wrote:
> Use printk_safe per-CPU buffers in printk recursion-prone blocks:
> -- around logbuf_lock protected sections in vprintk_emit() and
>    console_unlock()
> -- around down_trylock_console_sem() and up_console_sem()
>
> Note that this solution addresses deadlocks caused by printk()
> recursive calls only. That is vprintk_emit() and console_unlock().
> The rest will be converted in a followup patch.
>
> Another thing to note is that we now keep lockdep enabled in printk,
> because we are protected against the printk recursion caused by
> lockdep in vprintk_emit() by the printk-safe mechanism - we first
> switch to per-CPU buffers and only then access the deadlock-prone
> locks.

When booting v4.10-rc5-mmots-2017-01-26-15-49 from the mmots tree, I
sometimes see the following lockdep splat which I think may be related
to this commit?

[   13.090634] ======================================================
[   13.090634] [ INFO: possible circular locking dependency detected ]
[   13.090635] 4.10.0-rc5-mm1-00313-g5c0c3d7-dirty #10 Not tainted
[   13.090635] -------------------------------------------------------
[   13.090635] systemd/1 is trying to acquire lock:
[   13.090636]  ((console_sem).lock){-.....}, at: [<ffffffff81110194>]
down_trylock+0x14/0x40
[   13.090637]
[   13.090637] but task is already holding lock:
[   13.090637]  (&rq->lock){-.-.-.}, at: [<ffffffff810e6116>]
task_rq_lock+0x56/0xd0
[   13.090638]
[   13.090639] which lock already depends on the new lock.
[   13.090639]
[   13.090639]
[   13.090640] the existing dependency chain (in reverse order) is:
[   13.090640] c
[   13.090640] -> #2 (&rq->lock){-.-.-.}:
[   13.090641]        [<ffffffff8111727d>] lock_acquire+0xfd/0x200
[   13.090642]        [<ffffffff81ca3171>] _raw_spin_lock+0x41/0x80
[   13.090642]        [<ffffffff810fa38a>] task_fork_fair+0x3a/0x100
[   13.090642]        [<ffffffff810ea80d>] sched_fork+0x10d/0x2c0
[   13.090643]        [<ffffffff810b05df>] copy_process.part.30+0x69f/0x2190
[   13.090643]        [<ffffffff810b22c6>] _do_fork+0xf6/0x700
[   13.090643]        [<ffffffff810b28f9>] kernel_thread+0x29/0x30
[   13.090644]        [<ffffffff81c91572>] rest_init+0x22/0x140
[   13.090644]        [<ffffffff8280b051>] start_kernel+0x461/0x482
[   13.090644]        [<ffffffff8280a2d6>] x86_64_start_reservations+0x2a/0x2c
[   13.090645]        [<ffffffff8280a424>] x86_64_start_kernel+0x14c/0x16f
[   13.090645]        [<ffffffff810001c4>] verify_cpu+0x0/0xfc
[   13.090645]
[   13.090645] -> #1 (&p->pi_lock){-.-.-.}:
[   13.090647]        [<ffffffff8111727d>] lock_acquire+0xfd/0x200
[   13.090647]        [<ffffffff81ca3f79>] _raw_spin_lock_irqsave+0x59/0x93
[   13.090647]        [<ffffffff810e943f>] try_to_wake_up+0x3f/0x530
[   13.090648]        [<ffffffff810e9945>] wake_up_process+0x15/0x20
[   13.090648]        [<ffffffff81c9fc4c>] __up.isra.0+0x4c/0x50
[   13.090648]        [<ffffffff81110256>] up+0x46/0x50
[   13.090649]        [<ffffffff81128a55>] __up_console_sem+0x45/0x80
[   13.090649]        [<ffffffff81129baf>] console_unlock+0x29f/0x5e0
[   13.090649]        [<ffffffff8112a1c0>] vprintk_emit+0x2d0/0x3a0
[   13.090650]        [<ffffffff8112a429>] vprintk_default+0x29/0x50
[   13.090650]        [<ffffffff8112b445>] vprintk_func+0x25/0x80
[   13.090650]        [<ffffffff81205c6d>] printk+0x52/0x6e
[   13.090651]        [<ffffffff81185bdc>] kauditd_hold_skb+0x9c/0xa0
[   13.090651]        [<ffffffff8118601b>] kauditd_thread+0x23b/0x520
[   13.090651]        [<ffffffff810dbb6f>] kthread+0x10f/0x150
[   13.090652]        [<ffffffff81ca42c1>] ret_from_fork+0x31/0x40
[   13.090652]
[   13.090652] -> #0 ((console_sem).lock){-.....}:
[   13.090653]        [<ffffffff81116c85>] __lock_acquire+0x10e5/0x1270
[   13.090653]        [<ffffffff8111727d>] lock_acquire+0xfd/0x200
[   13.090654]        [<ffffffff81ca3f79>] _raw_spin_lock_irqsave+0x59/0x93
[   13.090654]        [<ffffffff81110194>] down_trylock+0x14/0x40
[   13.090654]        [<ffffffff81128b7c>] __down_trylock_console_sem+0x3c/0xc0
[   13.090655]        [<ffffffff81128c16>] console_trylock+0x16/0x90
[   13.090655]        [<ffffffff8112a1b7>] vprintk_emit+0x2c7/0x3a0
[   13.090655]        [<ffffffff8112a429>] vprintk_default+0x29/0x50
[   13.090656]        [<ffffffff8112b445>] vprintk_func+0x25/0x80
[   13.090656]        [<ffffffff81205c6d>] printk+0x52/0x6e
[   13.090656]        [<ffffffff810b3329>] __warn+0x39/0xf0
[   13.090657]        [<ffffffff810b343f>] warn_slowpath_fmt+0x5f/0x80
[   13.090657]        [<ffffffff810f550b>] update_load_avg+0x85b/0xb80
[   13.090657]        [<ffffffff810f58bf>] detach_task_cfs_rq+0x3f/0x210
[   13.090658]        [<ffffffff810f8e34>] task_change_group_fair+0x24/0x100
[   13.090658]        [<ffffffff810e46ef>] sched_change_group+0x5f/0x110
[   13.090658]        [<ffffffff810efd03>] sched_move_task+0x53/0x160
[   13.090659]        [<ffffffff810efe46>] cpu_cgroup_attach+0x36/0x70
[   13.090659]        [<ffffffff81172aa0>] cgroup_migrate_execute+0x230/0x3f0
[   13.090659]        [<ffffffff81172d2e>] cgroup_migrate+0xce/0x140
[   13.090660]        [<ffffffff8117301f>] cgroup_attach_task+0x27f/0x3e0
[   13.090660]        [<ffffffff81175b7e>] __cgroup_procs_write+0x30e/0x510
[   13.090661]        [<ffffffff81175d94>] cgroup_procs_write+0x14/0x20
[   13.090661]        [<ffffffff811700e4>] cgroup_file_write+0x44/0x1e0
[   13.090661]        [<ffffffff8135a92c>] kernfs_fop_write+0x13c/0x1c0
[   13.090662]        [<ffffffff812b8e07>] __vfs_write+0x37/0x160
[   13.090662]        [<ffffffff812ba8ab>] vfs_write+0xcb/0x1f0
[   13.090662]        [<ffffffff812bbe38>] SyS_write+0x58/0xc0
[   13.090663]        [<ffffffff81ca4041>] entry_SYSCALL_64_fastpath+0x1f/0xc2
[   13.090663]
[   13.090663] other info that might help us debug this:
[   13.090663]
[   13.090664] Chain exists of:
[   13.090664]   (console_sem).lock --> &p->pi_lock --> &rq->lock
[   13.090665]
[   13.090666]  Possible unsafe locking scenario:
[   13.090666]
[   13.090666]        CPU0                    CPU1
[   13.090667]        ----                    ----
[   13.090667]   lock(&rq->lock);
[   13.090668]                                lock(&p->pi_lock);
[   13.090668]                                lock(&rq->lock);
[   13.090669]   lock((console_sem).lock);
[   13.090670]
[   13.090670]  * DEADLOCK *
[   13.090670]
[   13.090671] 6 locks held by systemd/1:
[   13.090671]  #0:  (sb_writers#6){.+.+.+}, at: [<ffffffff812ba97b>]
vfs_write+0x19b/0x1f0
[   13.090672]  #1:  (&of->mutex){+.+.+.}, at: [<ffffffff8135a8f6>]
kernfs_fop_write+0x106/0x1c0
[   13.090673]  #2:  (cgroup_mutex){+.+.+.}, at: [<ffffffff811751aa>]
cgroup_kn_lock_live+0x5a/0x220
[   13.090674]  #3:  (&cgroup_threadgroup_rwsem){+++++.}, at:
[<ffffffff811109cb>] percpu_down_write+0x2b/0x130
[   13.090676]  #4:  (&p->pi_lock){-.-.-.}, at: [<ffffffff810e6101>]
task_rq_lock+0x41/0xd0
[   13.090677]  #5:  (&rq->lock){-.-.-.}, at: [<ffffffff810e6116>]
task_rq_lock+0x56/0xd0
[   13.090678]
[   13.090678] stack backtrace:
[   13.090679] CPU: 8 PID: 1 Comm: systemd Not tainted
4.10.0-rc5-mm1-00313-g5c0c3d7-dirty #10
[   13.090679] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996),
BIOS rel-1.9.1-0-gb3ef39f-prebuilt.qemu-project.org 04/01/2014
[   13.090679] Call Trace:
[   13.090680]  dump_stack+0x86/0xc3
[   13.090680]  print_circular_bug+0x1be/0x210
[   13.090680]  __lock_acquire+0x10e5/0x1270
[   13.090681]  lock_acquire+0xfd/0x200
[   13.090681]  ? down_trylock+0x14/0x40
[   13.090681]  _raw_spin_lock_irqsave+0x59/0x93
[   13.090681]  ? down_trylock+0x14/0x40
[   13.090682]  ? vprintk_emit+0x2c7/0x3a0
[   13.090682]  down_trylock+0x14/0x40
[   13.090682]  __down_trylock_console_sem+0x3c/0xc0
[   13.090683]  console_trylock+0x16/0x90
[   13.090683]  ? trace_hardirqs_off+0xd/0x10
[   13.090683]  vprintk_emit+0x2c7/0x3a0
[   13.090684]  ? update_load_avg+0x85b/0xb80
[   13.090684]  vprintk_default+0x29/0x50
[   13.090684]  vprintk_func+0x25/0x80
[   13.090684]  printk+0x52/0x6e
[   13.090685]  ? update_load_avg+0x85b/0xb80
[   13.090685]  __warn+0x39/0xf0
[   13.090685]  warn_slowpath_fmt+0x5f/0x80
[   13.090686]  update_load_avg+0x85b/0xb80
[   13.090686]  ? debug_smp_processor_id+0x17/0x20
[   13.090686]  detach_task_cfs_rq+0x3f/0x210
[   13.090687]  task_change_group_fair+0x24/0x100
[   13.090687]  sched_change_group+0x5f/0x110
[   13.090687]  sched_move_task+0x53/0x160
[   13.090687]  cpu_cgroup_attach+0x36/0x70
[   13.090688]  cgroup_migrate_execute+0x230/0x3f0
[   13.090688]  cgroup_migrate+0xce/0x140
[   13.090688]  ? cgroup_migrate+0x5/0x140
[   13.090689]  cgroup_attach_task+0x27f/0x3e0
[   13.090689]  ? cgroup_attach_task+0x9b/0x3e0
[   13.090689]  __cgroup_procs_write+0x30e/0x510
[   13.090690]  ? __cgroup_procs_write+0x70/0x510
[   13.090690]  cgroup_procs_write+0x14/0x20
[   13.090690]  cgroup_file_write+0x44/0x1e0
[   13.090690]  kernfs_fop_write+0x13c/0x1c0
[   13.090691]  __vfs_write+0x37/0x160
[   13.090691]  ? rcu_read_lock_sched_held+0x4a/0x80
[   13.090691]  ? rcu_sync_lockdep_assert+0x2f/0x60
[   13.090692]  ? __sb_start_write+0x10d/0x220
[   13.090692]  ? vfs_write+0x19b/0x1f0
[   13.090692]  ? security_file_permission+0x3b/0xc0
[   13.090693]  vfs_write+0xcb/0x1f0
[   13.090693]  SyS_write+0x58/0xc0
[   13.090693]  entry_SYSCALL_64_fastpath+0x1f/0xc2
[   13.090693] RIP: 0033:0x7f8b7c1be210
[   13.090694] RSP: 002b:00007ffe73febfd8 EFLAGS: 00000246 ORIG_RAX:
0000000000000001
[   13.090694] RAX: ffffffffffffffda RBX: 000055a84870a7e0 RCX: 00007f8b7c1be210
[   13.090695] RDX: 0000000000000004 RSI: 000055a84870aa10 RDI: 0000000000000033
[   13.090695] RBP: 0000000000000000 R08: 000055a84870a8c0 R09: 00007f8b7dbda900
[   13.090695] R10: 000055a84870aa10 R11: 0000000000000246 R12: 0000000000000000
[   13.090696] R13: 000055a848775360 R14: 000055a84870a7e0 R15: 0000000000000033

Re: [PATCHv7 6/8] printk: use printk_safe buffers in printk

[Jan Kara]

On Tue 31-01-17 10:27:53, Ross Zwisler wrote:
> On Tue, Dec 27, 2016 at 7:16 AM, Sergey Senozhatsky
> <sergey.senozhatsky@gmail.com> wrote:
> > Use printk_safe per-CPU buffers in printk recursion-prone blocks:
> > -- around logbuf_lock protected sections in vprintk_emit() and
> >    console_unlock()
> > -- around down_trylock_console_sem() and up_console_sem()
> >
> > Note that this solution addresses deadlocks caused by printk()
> > recursive calls only. That is vprintk_emit() and console_unlock().
> > The rest will be converted in a followup patch.
> >
> > Another thing to note is that we now keep lockdep enabled in printk,
> > because we are protected against the printk recursion caused by
> > lockdep in vprintk_emit() by the printk-safe mechanism - we first
> > switch to per-CPU buffers and only then access the deadlock-prone
> > locks.
> 
> When booting v4.10-rc5-mmots-2017-01-26-15-49 from the mmots tree, I
> sometimes see the following lockdep splat which I think may be related
> to this commit?

I don't think it is really related. Look at the backtrace:

> [   13.090684]  printk+0x52/0x6e
> [   13.090685]  ? update_load_avg+0x85b/0xb80
> [   13.090685]  __warn+0x39/0xf0
> [   13.090685]  warn_slowpath_fmt+0x5f/0x80
> [   13.090686]  update_load_avg+0x85b/0xb80
> [   13.090686]  ? debug_smp_processor_id+0x17/0x20
> [   13.090686]  detach_task_cfs_rq+0x3f/0x210
> [   13.090687]  task_change_group_fair+0x24/0x100
> [   13.090687]  sched_change_group+0x5f/0x110
> [   13.090687]  sched_move_task+0x53/0x160
> [   13.090687]  cpu_cgroup_attach+0x36/0x70
> [   13.090688]  cgroup_migrate_execute+0x230/0x3f0
> [   13.090688]  cgroup_migrate+0xce/0x140
> [   13.090688]  ? cgroup_migrate+0x5/0x140
> [   13.090689]  cgroup_attach_task+0x27f/0x3e0
> [   13.090689]  ? cgroup_attach_task+0x9b/0x3e0
> [   13.090689]  __cgroup_procs_write+0x30e/0x510
> [   13.090690]  ? __cgroup_procs_write+0x70/0x510
> [   13.090690]  cgroup_procs_write+0x14/0x20
> [   13.090690]  cgroup_file_write+0x44/0x1e0
> [   13.090690]  kernfs_fop_write+0x13c/0x1c0
> [   13.090691]  __vfs_write+0x37/0x160
> [   13.090691]  ? rcu_read_lock_sched_held+0x4a/0x80
> [   13.090691]  ? rcu_sync_lockdep_assert+0x2f/0x60
> [   13.090692]  ? __sb_start_write+0x10d/0x220
> [   13.090692]  ? vfs_write+0x19b/0x1f0
> [   13.090692]  ? security_file_permission+0x3b/0xc0
> [   13.090693]  vfs_write+0xcb/0x1f0
> [   13.090693]  SyS_write+0x58/0xc0

Clearly scheduler code (update_load_avg) calls WARN_ON from scheduler while
holding rq_lock which has been always forbidden. Sergey and Petr were doing
some work to prevent similar deadlocks but I'm not sure how far they
went...

								Honza
-- 
Jan Kara <jack@suse.com>
SUSE Labs, CR

Re: [PATCHv7 6/8] printk: use printk_safe buffers in printk

[Peter Zijlstra]

On Wed, Feb 01, 2017 at 10:06:25AM +0100, Jan Kara wrote:
> Clearly scheduler code (update_load_avg) calls WARN_ON from scheduler while
> holding rq_lock which has been always forbidden. Sergey and Petr were doing
> some work to prevent similar deadlocks but I'm not sure how far they
> went...

Its not forbidden, just can result in the occasional deadlock, meh.


In any case, there's a patch in tip fixing that warn trigger.

Re: [PATCHv7 6/8] printk: use printk_safe buffers in printk

[Petr Mladek]

On Wed 2017-02-01 10:37:39, Peter Zijlstra wrote:
> On Wed, Feb 01, 2017 at 10:06:25AM +0100, Jan Kara wrote:
> > Clearly scheduler code (update_load_avg) calls WARN_ON from scheduler while
> > holding rq_lock which has been always forbidden. Sergey and Petr were doing
> > some work to prevent similar deadlocks but I'm not sure how far they
> > went...
> 
> Its not forbidden, just can result in the occasional deadlock, meh.
> 
> 
> In any case, there's a patch in tip fixing that warn trigger.

I guess that you are talking about the introduction of
#define SCHED_WARN_ON(x)	WARN_ONCE(x, #x)

It reduces the risk of the deadlock but some risk is still there.
IMHO, it does not avoid the lockdep warning.

One solution would be to hide the occasional deadlock and disable
lockdep in SCHED_WARN_ON():

#define SCHED_WARN_ON(x)				\
({							\
	int __ret_sched_warn_on;			\
	lockdep_off();					\
	__ret_sched_warn_on = WARN_ONCE(x, #x);		\
	lockdep_on();					\
	unlikely(__ret_sched_warn_on);			\
})


Another solution would be to redirect it into the
alternative buffer and let it printed later:

#define SCHED_WARN_ON(x)	WARN_ONCE(x, #x)		\
({								\
	unsigned long __sched_warn_on_flags;			\
	printk_safe_enter_irqsave(__sched_warn_on_flags);	\
	__ret_sched_warn_on = WARN_ONCE(x, #x);			\
	printk_safe_exit_irqrestore(__sched_warn_on_flags);	\
	unlikely(__ret_sched_warn_on);				\
})

Best Regards,
Petr

Re: [PATCHv7 6/8] printk: use printk_safe buffers in printk

[Peter Zijlstra]

On Wed, Feb 01, 2017 at 04:39:10PM +0100, Petr Mladek wrote:
> I guess that you are talking about the introduction of
> #define SCHED_WARN_ON(x)	WARN_ONCE(x, #x)

No, there's a lot of regular WARN/WARN_ON/etc.. usage in the scheduler.
That thing was just a convenience wapper to print the condition that
warned.

> It reduces the risk of the deadlock but some risk is still there.
> IMHO, it does not avoid the lockdep warning.

It doesn't reduce anything, nor did it ever try. I really don't care if
it occasionally deadlocks, as long as it mostly gets out.

> One solution would be to hide the occasional deadlock and disable
> lockdep in SCHED_WARN_ON():
> 
> #define SCHED_WARN_ON(x)				\
> ({							\
> 	int __ret_sched_warn_on;			\
> 	lockdep_off();					\
> 	__ret_sched_warn_on = WARN_ONCE(x, #x);		\
> 	lockdep_on();					\
> 	unlikely(__ret_sched_warn_on);			\
> })

Like said, there's plenty of regular WARN/WARN_ON usage, so this will
not help much.

> Another solution would be to redirect it into the
> alternative buffer and let it printed later:
> 
> #define SCHED_WARN_ON(x)	WARN_ONCE(x, #x)		\
> ({								\
> 	unsigned long __sched_warn_on_flags;			\
> 	printk_safe_enter_irqsave(__sched_warn_on_flags);	\
> 	__ret_sched_warn_on = WARN_ONCE(x, #x);			\
> 	printk_safe_exit_irqrestore(__sched_warn_on_flags);	\
> 	unlikely(__ret_sched_warn_on);				\
> })

So my kernel doesn't yet have that abomination; that redirects it to a
buffer for later printing right? I hope that buffer is big enough to
hold a full WARN splat and the machine lives long enough to make it to
printing that crap.

Re: [PATCHv7 6/8] printk: use printk_safe buffers in printk

[Steven Rostedt]

On Wed, 1 Feb 2017 17:15:41 +0100
Peter Zijlstra <peterz@infradead.org> wrote:
 
> So my kernel doesn't yet have that abomination; that redirects it to a
> buffer for later printing right? I hope that buffer is big enough to
> hold a full WARN splat and the machine lives long enough to make it to
> printing that crap.


By default the buffer is 8K (minus 3 * sizeof(long)). But there's a
config option to grow it up to 128K if you like.

-- Steve

Re: [PATCHv7 6/8] printk: use printk_safe buffers in printk

[Sergey Senozhatsky]

On (02/01/17 16:39), Petr Mladek wrote:
[..]
> I guess that you are talking about the introduction of
> #define SCHED_WARN_ON(x)	WARN_ONCE(x, #x)

my guess would be that Jan was talking about printk_deferred() patch.
it's on my TODO list.

I want to entirely remove console_sem and scheduler out of printk() path.
that's the only way to make printk() deadlock safe.

	-ss

Re: [PATCHv7 6/8] printk: use printk_safe buffers in printk

[Peter Zijlstra]

On Thu, Feb 02, 2017 at 11:11:34AM +0900, Sergey Senozhatsky wrote:
> On (02/01/17 16:39), Petr Mladek wrote:
> [..]
> > I guess that you are talking about the introduction of
> > #define SCHED_WARN_ON(x)	WARN_ONCE(x, #x)
> 
> my guess would be that Jan was talking about printk_deferred() patch.
> it's on my TODO list.
> 
> I want to entirely remove console_sem and scheduler out of printk() path.
> that's the only way to make printk() deadlock safe.

And useless.. if you never get around to the 'later' part where you
print the content. This way you still mostly get the output.

And no, its not the only way, see my printk->early_printk patches. early
serial console only does a loop over outb, impossible to mess that up.

Re: [PATCHv7 6/8] printk: use printk_safe buffers in printk

[Sergey Senozhatsky]

On (02/02/17 10:07), Peter Zijlstra wrote:
> On Thu, Feb 02, 2017 at 11:11:34AM +0900, Sergey Senozhatsky wrote:
> > On (02/01/17 16:39), Petr Mladek wrote:
> > [..]
> > > I guess that you are talking about the introduction of
> > > #define SCHED_WARN_ON(x)	WARN_ONCE(x, #x)
> > 
> > my guess would be that Jan was talking about printk_deferred() patch.
> > it's on my TODO list.
> > 
> > I want to entirely remove console_sem and scheduler out of printk() path.
> > that's the only way to make printk() deadlock safe.
> 
> And useless.. if you never get around to the 'later' part where you
> print the content. This way you still mostly get the output.

well, I wouldn't say that printk_deferred() has less chances. I see your
point, of course. but with printk_deferred() we, at least, will have messages
in logbuf (or printk_safe buffers), so they can appear in crash dump, for
instance. that "later" part can be sysrq, for example, or panic->flush_on_panic(),
etc. if "normal" printk->queue irq_work doesn't work.

needless to say, that in this particular case (WARN from sched), if the
first printk() out of N printk()-s, which sched core calls to dump_stack(),
deadlocks, then we got nothing to print/dump.

> And no, its not the only way, see my printk->early_printk patches. early
> serial console only does a loop over outb, impossible to mess that up.

certainly :)

	-ss

Re: [PATCHv7 6/8] printk: use printk_safe buffers in printk

[Petr Mladek]

On Thu 2017-02-02 19:03:48, Sergey Senozhatsky wrote:
> On (02/02/17 10:07), Peter Zijlstra wrote:
> > On Thu, Feb 02, 2017 at 11:11:34AM +0900, Sergey Senozhatsky wrote:
> > > On (02/01/17 16:39), Petr Mladek wrote:
> > > [..]
> > > > I guess that you are talking about the introduction of
> > > > #define SCHED_WARN_ON(x)	WARN_ONCE(x, #x)
> > > 
> > > my guess would be that Jan was talking about printk_deferred() patch.
> > > it's on my TODO list.
> > > 
> > > I want to entirely remove console_sem and scheduler out of printk() path.
> > > that's the only way to make printk() deadlock safe.
> > 
> > And useless.. if you never get around to the 'later' part where you
> > print the content. This way you still mostly get the output.
> 
> well, I wouldn't say that printk_deferred() has less chances. I see your
> point, of course. but with printk_deferred() we, at least, will have messages
> in logbuf (or printk_safe buffers), so they can appear in crash dump, for
> instance. that "later" part can be sysrq, for example, or panic->flush_on_panic(),
> etc. if "normal" printk->queue irq_work doesn't work.
> 
> needless to say, that in this particular case (WARN from sched), if the
> first printk() out of N printk()-s, which sched core calls to dump_stack(),
> deadlocks, then we got nothing to print/dump.

An always deferred printk() or another deferred ways are future work.
We should try to find a good solution, definitely.

The question is what to do with this patch. We need to change things
step by step. The printk_safe patchset is one of them and looks
almost ready.

The lockdep warnings are correct and help to find locations where
scheduler warnings might cause a deadlock.

One solution would be to keep lockdep as is in this patch. It means
to hide existing risk until we have some reasonable printk_deferred()
solution.

Another solution would to keep this patch as is and implement
WARN*_DEFERRED() variants that would either use
printk_safe_enter()/exit() as the currently usable deferred and
lockless solution. Or they could just disable lockdep and hide
the report for now. These deferred variants should be
used on all locations reported by lockdep where we want to accept the
risk. We will at least know where the potential risk is and could find
a proper solution later.

Note that I do not like hiding problems but they were hidden before this
patchset as well. I am just looking for the best way forward.


> > And no, its not the only way, see my printk->early_printk patches. early
> > serial console only does a loop over outb, impossible to mess that up.
> 
> certainly :)

Yup. I still would like to get Peter's patches in. They are in the
queue.

Best Regards,
Petr

Re: [PATCHv7 6/8] printk: use printk_safe buffers in printk

[Sergey Senozhatsky]

On (02/02/17 16:20), Petr Mladek wrote:
> > well, I wouldn't say that printk_deferred() has less chances. I see your
> > point, of course. but with printk_deferred() we, at least, will have messages
> > in logbuf (or printk_safe buffers), so they can appear in crash dump, for
> > instance. that "later" part can be sysrq, for example, or panic->flush_on_panic(),
> > etc. if "normal" printk->queue irq_work doesn't work.
> > 
> > needless to say, that in this particular case (WARN from sched), if the
> > first printk() out of N printk()-s, which sched core calls to dump_stack(),
> > deadlocks, then we got nothing to print/dump.
> 
> An always deferred printk() or another deferred ways are future work.
> We should try to find a good solution, definitely.
> 
> The question is what to do with this patch. We need to change things
> step by step. The printk_safe patchset is one of them and looks
> almost ready.
> 
> The lockdep warnings are correct and help to find locations where
> scheduler warnings might cause a deadlock.

I like that lockdep warning. and looking at it... I think lockdep does
not add any additional risks.

we are in deadlock risky sched->printk condition due to WARN from
sched, not lockdep. the lockdep warning that we see happens after
we switch to printk_safe mode.


please see console_trylock()->__down_trylock_console_sem()


static int __down_trylock_console_sem(unsigned long ip)
{
...
 224        printk_safe_enter_irqsave(flags);
 225        lock_failed = down_trylock(&console_sem);   << print_circular_bug() comes from here
 226        printk_safe_exit_irqrestore(flags);
...
}

so the unsafe/safe printk 'map' should be as follows

[   13.090679] Call Trace:
[   13.090680]  dump_stack+0x86/0xc3
[   13.090680]  print_circular_bug+0x1be/0x210          << still in printk_safe
[   13.090680]  __lock_acquire+0x10e5/0x1270
[   13.090681]  lock_acquire+0xfd/0x200
[   13.090681]  ? down_trylock+0x14/0x40
[   13.090681]  _raw_spin_lock_irqsave+0x59/0x93
[   13.090681]  ? down_trylock+0x14/0x40
[   13.090682]  ? vprintk_emit+0x2c7/0x3a0
[   13.090682]  down_trylock+0x14/0x40
[   13.090682]  __down_trylock_console_sem+0x3c/0xc0    << we are in printk_safe now (!)
[   13.090683]  console_trylock+0x16/0x90
[   13.090683]  ? trace_hardirqs_off+0xd/0x10
[   13.090683]  vprintk_emit+0x2c7/0x3a0
[   13.090684]  ? update_load_avg+0x85b/0xb80
[   13.090684]  vprintk_default+0x29/0x50
[   13.090684]  vprintk_func+0x25/0x80                  << we are in unsafe printk here (!)
[   13.090684]  printk+0x52/0x6e
[   13.090685]  ? update_load_avg+0x85b/0xb80
[   13.090685]  __warn+0x39/0xf0
[   13.090685]  warn_slowpath_fmt+0x5f/0x80
[   13.090686]  update_load_avg+0x85b/0xb80
[   13.090686]  ? debug_smp_processor_id+0x17/0x20
[   13.090686]  detach_task_cfs_rq+0x3f/0x210
[   13.090687]  task_change_group_fair+0x24/0x100
[   13.090687]  sched_change_group+0x5f/0x110
[   13.090687]  sched_move_task+0x53/0x160
[   13.090687]  cpu_cgroup_attach+0x36/0x70
[   13.090688]  cgroup_migrate_execute+0x230/0x3f0
[   13.090688]  cgroup_migrate+0xce/0x140
[   13.090688]  ? cgroup_migrate+0x5/0x140
[   13.090689]  cgroup_attach_task+0x27f/0x3e0
[   13.090689]  ? cgroup_attach_task+0x9b/0x3e0
[   13.090689]  __cgroup_procs_write+0x30e/0x510
[   13.090690]  ? __cgroup_procs_write+0x70/0x510
[   13.090690]  cgroup_procs_write+0x14/0x20
[   13.090690]  cgroup_file_write+0x44/0x1e0
[   13.090690]  kernfs_fop_write+0x13c/0x1c0
[   13.090691]  __vfs_write+0x37/0x160
[   13.090691]  ? rcu_read_lock_sched_held+0x4a/0x80
[   13.090691]  ? rcu_sync_lockdep_assert+0x2f/0x60
[   13.090692]  ? __sb_start_write+0x10d/0x220
[   13.090692]  ? vfs_write+0x19b/0x1f0
[   13.090692]  ? security_file_permission+0x3b/0xc0
[   13.090693]  vfs_write+0xcb/0x1f0
[   13.090693]  SyS_write+0x58/0xc0
[   13.090693]  entry_SYSCALL_64_fastpath+0x1f/0xc2


that unsafe console_trylock() is not caused by lockdep. yes, we can
deadlock in down_trylock(), but lockdep is not the root cause. and
if we will disable lockdep, sched->printk->console_trylock() still
will have pretty much same chances to deadlock.

let me know if I'm missing something.


> One solution would be to keep lockdep as is in this patch. It means
> to hide existing risk until we have some reasonable printk_deferred()
> solution.

well, yes. this is still a possible way to go (until the deferred printk()).


> Another solution would to keep this patch as is and implement
> WARN*_DEFERRED() variants that would either use
> printk_safe_enter()/exit() as the currently usable deferred and
> lockless solution. Or they could just disable lockdep and hide
> the report for now. These deferred variants should be
> used on all locations reported by lockdep where we want to accept the
> risk. We will at least know where the potential risk is and could find
> a proper solution later.

WARN*_DEFERRED() looks to me like almost unmaintainable thing.
too much work; a never ending work.


> Note that I do not like hiding problems but they were hidden before this
> patchset as well. I am just looking for the best way forward.

sure.

	-ss

Re: [PATCHv7 6/8] printk: use printk_safe buffers in printk

[Sergey Senozhatsky]

Hello Ross,

I was offline for a week for personal reasons.

On (01/31/17 10:27), Ross Zwisler wrote:
[..]
> [   13.090634] ======================================================
> [   13.090634] [ INFO: possible circular locking dependency detected ]
> [   13.090635] 4.10.0-rc5-mm1-00313-g5c0c3d7-dirty #10 Not tainted
> [   13.090635] -------------------------------------------------------
> [   13.090635] systemd/1 is trying to acquire lock:
> [   13.090636]  ((console_sem).lock){-.....}, at: [<ffffffff81110194>]
> down_trylock+0x14/0x40
> [   13.090637]
> [   13.090637] but task is already holding lock:
> [   13.090637]  (&rq->lock){-.-.-.}, at: [<ffffffff810e6116>]
> task_rq_lock+0x56/0xd0
> [   13.090638]
> [   13.090639] which lock already depends on the new lock.
> [   13.090639]
> [   13.090639]
> [   13.090640] the existing dependency chain (in reverse order) is:
> [   13.090640] c
> [   13.090640] -> #2 (&rq->lock){-.-.-.}:
> [   13.090641]        [<ffffffff8111727d>] lock_acquire+0xfd/0x200
> [   13.090642]        [<ffffffff81ca3171>] _raw_spin_lock+0x41/0x80
> [   13.090642]        [<ffffffff810fa38a>] task_fork_fair+0x3a/0x100
> [   13.090642]        [<ffffffff810ea80d>] sched_fork+0x10d/0x2c0
> [   13.090643]        [<ffffffff810b05df>] copy_process.part.30+0x69f/0x2190
> [   13.090643]        [<ffffffff810b22c6>] _do_fork+0xf6/0x700
> [   13.090643]        [<ffffffff810b28f9>] kernel_thread+0x29/0x30
> [   13.090644]        [<ffffffff81c91572>] rest_init+0x22/0x140
> [   13.090644]        [<ffffffff8280b051>] start_kernel+0x461/0x482
> [   13.090644]        [<ffffffff8280a2d6>] x86_64_start_reservations+0x2a/0x2c
> [   13.090645]        [<ffffffff8280a424>] x86_64_start_kernel+0x14c/0x16f
> [   13.090645]        [<ffffffff810001c4>] verify_cpu+0x0/0xfc
> [   13.090645]
> [   13.090645] -> #1 (&p->pi_lock){-.-.-.}:
> [   13.090647]        [<ffffffff8111727d>] lock_acquire+0xfd/0x200
> [   13.090647]        [<ffffffff81ca3f79>] _raw_spin_lock_irqsave+0x59/0x93
> [   13.090647]        [<ffffffff810e943f>] try_to_wake_up+0x3f/0x530
> [   13.090648]        [<ffffffff810e9945>] wake_up_process+0x15/0x20
> [   13.090648]        [<ffffffff81c9fc4c>] __up.isra.0+0x4c/0x50
> [   13.090648]        [<ffffffff81110256>] up+0x46/0x50
> [   13.090649]        [<ffffffff81128a55>] __up_console_sem+0x45/0x80
> [   13.090649]        [<ffffffff81129baf>] console_unlock+0x29f/0x5e0
> [   13.090649]        [<ffffffff8112a1c0>] vprintk_emit+0x2d0/0x3a0
> [   13.090650]        [<ffffffff8112a429>] vprintk_default+0x29/0x50
> [   13.090650]        [<ffffffff8112b445>] vprintk_func+0x25/0x80
> [   13.090650]        [<ffffffff81205c6d>] printk+0x52/0x6e
> [   13.090651]        [<ffffffff81185bdc>] kauditd_hold_skb+0x9c/0xa0
> [   13.090651]        [<ffffffff8118601b>] kauditd_thread+0x23b/0x520
> [   13.090651]        [<ffffffff810dbb6f>] kthread+0x10f/0x150
> [   13.090652]        [<ffffffff81ca42c1>] ret_from_fork+0x31/0x40
> [   13.090652]
> [   13.090652] -> #0 ((console_sem).lock){-.....}:
> [   13.090653]        [<ffffffff81116c85>] __lock_acquire+0x10e5/0x1270
> [   13.090653]        [<ffffffff8111727d>] lock_acquire+0xfd/0x200
> [   13.090654]        [<ffffffff81ca3f79>] _raw_spin_lock_irqsave+0x59/0x93
> [   13.090654]        [<ffffffff81110194>] down_trylock+0x14/0x40
> [   13.090654]        [<ffffffff81128b7c>] __down_trylock_console_sem+0x3c/0xc0
> [   13.090655]        [<ffffffff81128c16>] console_trylock+0x16/0x90
> [   13.090655]        [<ffffffff8112a1b7>] vprintk_emit+0x2c7/0x3a0
> [   13.090655]        [<ffffffff8112a429>] vprintk_default+0x29/0x50
> [   13.090656]        [<ffffffff8112b445>] vprintk_func+0x25/0x80
> [   13.090656]        [<ffffffff81205c6d>] printk+0x52/0x6e
> [   13.090656]        [<ffffffff810b3329>] __warn+0x39/0xf0
> [   13.090657]        [<ffffffff810b343f>] warn_slowpath_fmt+0x5f/0x80
> [   13.090657]        [<ffffffff810f550b>] update_load_avg+0x85b/0xb80
> [   13.090657]        [<ffffffff810f58bf>] detach_task_cfs_rq+0x3f/0x210
> [   13.090658]        [<ffffffff810f8e34>] task_change_group_fair+0x24/0x100
> [   13.090658]        [<ffffffff810e46ef>] sched_change_group+0x5f/0x110
> [   13.090658]        [<ffffffff810efd03>] sched_move_task+0x53/0x160
> [   13.090659]        [<ffffffff810efe46>] cpu_cgroup_attach+0x36/0x70
> [   13.090659]        [<ffffffff81172aa0>] cgroup_migrate_execute+0x230/0x3f0
> [   13.090659]        [<ffffffff81172d2e>] cgroup_migrate+0xce/0x140
> [   13.090660]        [<ffffffff8117301f>] cgroup_attach_task+0x27f/0x3e0
> [   13.090660]        [<ffffffff81175b7e>] __cgroup_procs_write+0x30e/0x510
> [   13.090661]        [<ffffffff81175d94>] cgroup_procs_write+0x14/0x20
> [   13.090661]        [<ffffffff811700e4>] cgroup_file_write+0x44/0x1e0
> [   13.090661]        [<ffffffff8135a92c>] kernfs_fop_write+0x13c/0x1c0
> [   13.090662]        [<ffffffff812b8e07>] __vfs_write+0x37/0x160
> [   13.090662]        [<ffffffff812ba8ab>] vfs_write+0xcb/0x1f0
> [   13.090662]        [<ffffffff812bbe38>] SyS_write+0x58/0xc0
> [   13.090663]        [<ffffffff81ca4041>] entry_SYSCALL_64_fastpath+0x1f/0xc2


... so it looks like a printk() from the scheduler; I don't think it's
related to printk_safe(). and to make it worse, printk is not in safe mode
when sched_move_task()->update_load_avg() calls it... so the system is
free to deadlock. we need printk_deferred() patch here.

I may be wrong, I just saw the message -- so this is a rather quick reply.


does the patch below fix the problem for you?
https://git.kernel.org/cgit/linux/kernel/git/tip/tip.git/commit/?h=sched/core&id=1b1d62254df0fe42a711eb71948f915918987790


	-ss

Re: [PATCHv7 6/8] printk: use printk_safe buffers in printk

[Steven Rostedt]

On Tue, 27 Dec 2016 23:16:09 +0900
Sergey Senozhatsky <sergey.senozhatsky@gmail.com> wrote:

> Use printk_safe per-CPU buffers in printk recursion-prone blocks:
> -- around logbuf_lock protected sections in vprintk_emit() and
>    console_unlock()
> -- around down_trylock_console_sem() and up_console_sem()
> 
> Note that this solution addresses deadlocks caused by printk()
> recursive calls only. That is vprintk_emit() and console_unlock().
> The rest will be converted in a followup patch.
> 
> Another thing to note is that we now keep lockdep enabled in printk,
> because we are protected against the printk recursion caused by
> lockdep in vprintk_emit() by the printk-safe mechanism - we first
> switch to per-CPU buffers and only then access the deadlock-prone
> locks.
> 
> Examples:
> 
> 1) printk() from logbuf_lock spin_lock section
> 
> Assume the following code:
>   printk()
>     raw_spin_lock(&logbuf_lock);
>     WARN_ON(1);
>     raw_spin_unlock(&logbuf_lock);
> 
> which now produces:
> 
>  ------------[ cut here ]------------
>  WARNING: CPU: 0 PID: 366 at kernel/printk/printk.c:1811 vprintk_emit
>  CPU: 0 PID: 366 Comm: bash
>  Call Trace:
>    warn_slowpath_null+0x1d/0x1f
>    vprintk_emit+0x1cd/0x438
>    vprintk_default+0x1d/0x1f
>    printk+0x48/0x50
>   [..]
> 
> 2) printk() from semaphore sem->lock spin_lock section
> 
> Assume the following code
> 
>   printk()
>     console_trylock()
>       down_trylock()
>         raw_spin_lock_irqsave(&sem->lock, flags);
>         WARN_ON(1);
>         raw_spin_unlock_irqrestore(&sem->lock, flags);
> 
> which now produces:
> 
>  ------------[ cut here ]------------
>  WARNING: CPU: 1 PID: 363 at kernel/locking/semaphore.c:141 down_trylock
>  CPU: 1 PID: 363 Comm: bash
>  Call Trace:
>    warn_slowpath_null+0x1d/0x1f
>    down_trylock+0x3d/0x62
>    ? vprintk_emit+0x3f9/0x414
>    console_trylock+0x31/0xeb
>    vprintk_emit+0x3f9/0x414
>    vprintk_default+0x1d/0x1f
>    printk+0x48/0x50
>   [..]
> 
> 3) printk() from console_unlock()
> 
> Assume the following code:
> 
>   printk()
>     console_unlock()
>       raw_spin_lock(&logbuf_lock);
>       WARN_ON(1);
>       raw_spin_unlock(&logbuf_lock);
> 
> which now produces:
> 
>  ------------[ cut here ]------------
>  WARNING: CPU: 1 PID: 329 at kernel/printk/printk.c:2384 console_unlock
>  CPU: 1 PID: 329 Comm: bash
>  Call Trace:
>    warn_slowpath_null+0x18/0x1a
>    console_unlock+0x12d/0x559
>    ? trace_hardirqs_on_caller+0x16d/0x189
>    ? trace_hardirqs_on+0xd/0xf
>    vprintk_emit+0x363/0x374
>    vprintk_default+0x18/0x1a
>    printk+0x43/0x4b
>   [..]
> 
> 4) printk() from try_to_wake_up()
> 
> Assume the following code:
> 
>   printk()
>     console_unlock()
>       up()
>         try_to_wake_up()
>           raw_spin_lock_irqsave(&p->pi_lock, flags);
>           WARN_ON(1);
>           raw_spin_unlock_irqrestore(&p->pi_lock, flags);
> 
> which now produces:
> 
>  ------------[ cut here ]------------
>  WARNING: CPU: 3 PID: 363 at kernel/sched/core.c:2028 try_to_wake_up
>  CPU: 3 PID: 363 Comm: bash
>  Call Trace:
>    warn_slowpath_null+0x1d/0x1f
>    try_to_wake_up+0x7f/0x4f7
>    wake_up_process+0x15/0x17
>    __up.isra.0+0x56/0x63
>    up+0x32/0x42
>    __up_console_sem+0x37/0x55
>    console_unlock+0x21e/0x4c2
>    vprintk_emit+0x41c/0x462
>    vprintk_default+0x1d/0x1f
>    printk+0x48/0x50
>   [..]
> 
> 5) printk() from call_console_drivers()
> 
> Assume the following code:
>   printk()
>     console_unlock()
>       call_console_drivers()
>       ...
>           WARN_ON(1);
> 
> which now produces:
> 
>  ------------[ cut here ]------------
>  WARNING: CPU: 2 PID: 305 at kernel/printk/printk.c:1604 call_console_drivers
>  CPU: 2 PID: 305 Comm: bash
>  Call Trace:
>    warn_slowpath_null+0x18/0x1a
>    call_console_drivers.isra.6.constprop.16+0x3a/0xb0
>    console_unlock+0x471/0x48e
>    vprintk_emit+0x1f4/0x206
>    vprintk_default+0x18/0x1a
>    vprintk_func+0x6e/0x70
>    printk+0x3e/0x46
>   [..]
> 
> 6) unsupported placeholder in printk() format now prints an actual
>    warning from vscnprintf(), instead of
>    	'BUG: recent printk recursion!'.
> 
>  ------------[ cut here ]------------
>  WARNING: CPU: 5 PID: 337 at lib/vsprintf.c:1900 format_decode
>  Please remove unsupported %
>   in format string
>  CPU: 5 PID: 337 Comm: bash
>  Call Trace:
>    dump_stack+0x4f/0x65
>    __warn+0xc2/0xdd
>    warn_slowpath_fmt+0x4b/0x53
>    format_decode+0x22c/0x308
>    vsnprintf+0x89/0x3b7
>    vscnprintf+0xd/0x26
>    vprintk_emit+0xb4/0x238
>    vprintk_default+0x1d/0x1f
>    vprintk_func+0x6c/0x73
>    printk+0x43/0x4b
>   [..]
> 
> Signed-off-by: Sergey Senozhatsky <sergey.senozhatsky@gmail.com>
> Reviewed-by: Petr Mladek <pmladek@suse.com>
> ---

Reviewed-by: Steven Rostedt (VMware) <rostedt@goodmis.org>

-- Steve

Re: [PATCHv7 6/8] printk: use printk_safe buffers in printk

[Sergey Senozhatsky]

On (02/01/17 12:04), Steven Rostedt wrote:
> >   [..]
> > 
> > Signed-off-by: Sergey Senozhatsky <sergey.senozhatsky@gmail.com>
> > Reviewed-by: Petr Mladek <pmladek@suse.com>
> > ---
> 
> Reviewed-by: Steven Rostedt (VMware) <rostedt@goodmis.org>

here and in other patches: thanks for taking a look, Steven.

	-ss

[PATCHv7 7/8] printk: remove zap_locks() function

[Sergey Senozhatsky]

We use printk-safe now which makes printk-recursion detection code
in vprintk_emit() unreachable. The tricky thing here is that, apart
from detecting and reporting printk recursions, that code also used
to zap_locks() in case of panic() from the same CPU. However,
zap_locks() does not look to be needed anymore:

1) Since commit 08d78658f393 ("panic: release stale console lock to
   always get the logbuf printed out") panic flushing of `logbuf' to
   console ignores the state of `console_sem' by doing
   	panic()
		console_trylock();
		console_unlock();

2) Since commit cf9b1106c81c ("printk/nmi: flush NMI messages on the
   system panic") panic attempts to zap the `logbuf_lock' spin_lock to
   successfully flush nmi messages to `logbuf'.

Basically, it seems that we either already do what zap_locks() used to
do but in other places or we ignore the state of the lock. The only
reaming difference is that we don't re-init the console semaphore in
printk_safe_flush_on_panic(), but this is not necessary because we
don't call console drivers from printk_safe_flush_on_panic() due to
the fact that we are using a deferred printk() version (as was
suggested by Petr Mladek).

Signed-off-by: Sergey Senozhatsky <sergey.senozhatsky@gmail.com>
Reviewed-by: Petr Mladek <pmladek@suse.com>
---
 kernel/printk/printk.c | 61 --------------------------------------------------
 1 file changed, 61 deletions(-)

diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
index 2dd43ae94c64..1002dfd4ee96 100644
--- a/kernel/printk/printk.c
+++ b/kernel/printk/printk.c
@@ -1556,28 +1556,6 @@ static void call_console_drivers(const char *ext_text, size_t ext_len,
 	}
 }
 
-/*
- * Zap console related locks when oopsing.
- * To leave time for slow consoles to print a full oops,
- * only zap at most once every 30 seconds.
- */
-static void zap_locks(void)
-{
-	static unsigned long oops_timestamp;
-
-	if (time_after_eq(jiffies, oops_timestamp) &&
-	    !time_after(jiffies, oops_timestamp + 30 * HZ))
-		return;
-
-	oops_timestamp = jiffies;
-
-	debug_locks_off();
-	/* If a crash is occurring, make sure we can't deadlock */
-	raw_spin_lock_init(&logbuf_lock);
-	/* And make sure that we print immediately */
-	sema_init(&console_sem, 1);
-}
-
 int printk_delay_msec __read_mostly;
 
 static inline void printk_delay(void)
@@ -1687,17 +1665,13 @@ asmlinkage int vprintk_emit(int facility, int level,
 			    const char *dict, size_t dictlen,
 			    const char *fmt, va_list args)
 {
-	static bool recursion_bug;
 	static char textbuf[LOG_LINE_MAX];
 	char *text = textbuf;
 	size_t text_len = 0;
 	enum log_flags lflags = 0;
 	unsigned long flags;
-	int this_cpu;
 	int printed_len = 0;
 	bool in_sched = false;
-	/* cpu currently holding logbuf_lock in this function */
-	static unsigned int logbuf_cpu = UINT_MAX;
 
 	if (level == LOGLEVEL_SCHED) {
 		level = LOGLEVEL_DEFAULT;
@@ -1708,42 +1682,8 @@ asmlinkage int vprintk_emit(int facility, int level,
 	printk_delay();
 
 	printk_safe_enter_irqsave(flags);
-	this_cpu = smp_processor_id();
-
-	/*
-	 * Ouch, printk recursed into itself!
-	 */
-	if (unlikely(logbuf_cpu == this_cpu)) {
-		/*
-		 * If a crash is occurring during printk() on this CPU,
-		 * then try to get the crash message out but make sure
-		 * we can't deadlock. Otherwise just return to avoid the
-		 * recursion and return - but flag the recursion so that
-		 * it can be printed at the next appropriate moment:
-		 */
-		if (!oops_in_progress && !lockdep_recursing(current)) {
-			recursion_bug = true;
-			printk_safe_exit_irqrestore(flags);
-			return 0;
-		}
-		zap_locks();
-	}
-
 	/* This stops the holder of console_sem just where we want him */
 	raw_spin_lock(&logbuf_lock);
-	logbuf_cpu = this_cpu;
-
-	if (unlikely(recursion_bug)) {
-		static const char recursion_msg[] =
-			"BUG: recent printk recursion!";
-
-		recursion_bug = false;
-		/* emit KERN_CRIT message */
-		printed_len += log_store(0, 2, LOG_PREFIX|LOG_NEWLINE, 0,
-					 NULL, 0, recursion_msg,
-					 strlen(recursion_msg));
-	}
-
 	/*
 	 * The printf needs to come first; we need the syslog
 	 * prefix which might be passed-in as a parameter.
@@ -1786,7 +1726,6 @@ asmlinkage int vprintk_emit(int facility, int level,
 
 	printed_len += log_output(facility, level, lflags, dict, dictlen, text, text_len);
 
-	logbuf_cpu = UINT_MAX;
 	raw_spin_unlock(&logbuf_lock);
 	printk_safe_exit_irqrestore(flags);
 
-- 
2.11.0

[PATCHv7 8/8] printk: convert the rest to printk-safe

[Sergey Senozhatsky]

This patch converts the rest of logbuf users (which are
out of printk recursion case, but can deadlock in printk).
To make printk-safe usage easier the patch introduces 4
helper macros:
- logbuf_lock_irq()/logbuf_unlock_irq()
  lock/unlock the logbuf lock and disable/enable local IRQ

- logbuf_lock_irqsave(flags)/logbuf_unlock_irqrestore(flags)
  lock/unlock the logbuf lock and saves/restores local IRQ state

Signed-off-by: Sergey Senozhatsky <sergey.senozhatsky@gmail.com>
---
 kernel/printk/printk.c | 103 +++++++++++++++++++++++++++++++------------------
 1 file changed, 65 insertions(+), 38 deletions(-)

diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
index 1002dfd4ee96..75a944b3429f 100644
--- a/kernel/printk/printk.c
+++ b/kernel/printk/printk.c
@@ -370,6 +370,34 @@ __packed __aligned(4)
  */
 DEFINE_RAW_SPINLOCK(logbuf_lock);
 
+/*
+ * Helper macros to lock/unlock logbuf_lock and switch between
+ * printk-safe/unsafe modes.
+ */
+#define logbuf_lock_irq()				\
+	do {						\
+		printk_safe_enter_irq();		\
+		raw_spin_lock(&logbuf_lock);		\
+	} while (0)
+
+#define logbuf_unlock_irq()				\
+	do {						\
+		raw_spin_unlock(&logbuf_lock);		\
+		printk_safe_exit_irq();			\
+	} while (0)
+
+#define logbuf_lock_irqsave(flags)			\
+	do {						\
+		printk_safe_enter_irqsave(flags);	\
+		raw_spin_lock(&logbuf_lock);		\
+	} while (0)
+
+#define logbuf_unlock_irqrestore(flags)		\
+	do {						\
+		raw_spin_unlock(&logbuf_lock);		\
+		printk_safe_exit_irqrestore(flags);	\
+	} while (0)
+
 #ifdef CONFIG_PRINTK
 DECLARE_WAIT_QUEUE_HEAD(log_wait);
 /* the next printk record to read by syslog(READ) or /proc/kmsg */
@@ -801,20 +829,21 @@ static ssize_t devkmsg_read(struct file *file, char __user *buf,
 	ret = mutex_lock_interruptible(&user->lock);
 	if (ret)
 		return ret;
-	raw_spin_lock_irq(&logbuf_lock);
+
+	logbuf_lock_irq();
 	while (user->seq == log_next_seq) {
 		if (file->f_flags & O_NONBLOCK) {
 			ret = -EAGAIN;
-			raw_spin_unlock_irq(&logbuf_lock);
+			logbuf_unlock_irq();
 			goto out;
 		}
 
-		raw_spin_unlock_irq(&logbuf_lock);
+		logbuf_unlock_irq();
 		ret = wait_event_interruptible(log_wait,
 					       user->seq != log_next_seq);
 		if (ret)
 			goto out;
-		raw_spin_lock_irq(&logbuf_lock);
+		logbuf_lock_irq();
 	}
 
 	if (user->seq < log_first_seq) {
@@ -822,7 +851,7 @@ static ssize_t devkmsg_read(struct file *file, char __user *buf,
 		user->idx = log_first_idx;
 		user->seq = log_first_seq;
 		ret = -EPIPE;
-		raw_spin_unlock_irq(&logbuf_lock);
+		logbuf_unlock_irq();
 		goto out;
 	}
 
@@ -835,7 +864,7 @@ static ssize_t devkmsg_read(struct file *file, char __user *buf,
 
 	user->idx = log_next(user->idx);
 	user->seq++;
-	raw_spin_unlock_irq(&logbuf_lock);
+	logbuf_unlock_irq();
 
 	if (len > count) {
 		ret = -EINVAL;
@@ -862,7 +891,7 @@ static loff_t devkmsg_llseek(struct file *file, loff_t offset, int whence)
 	if (offset)
 		return -ESPIPE;
 
-	raw_spin_lock_irq(&logbuf_lock);
+	logbuf_lock_irq();
 	switch (whence) {
 	case SEEK_SET:
 		/* the first record */
@@ -886,7 +915,7 @@ static loff_t devkmsg_llseek(struct file *file, loff_t offset, int whence)
 	default:
 		ret = -EINVAL;
 	}
-	raw_spin_unlock_irq(&logbuf_lock);
+	logbuf_unlock_irq();
 	return ret;
 }
 
@@ -900,7 +929,7 @@ static unsigned int devkmsg_poll(struct file *file, poll_table *wait)
 
 	poll_wait(file, &log_wait, wait);
 
-	raw_spin_lock_irq(&logbuf_lock);
+	logbuf_lock_irq();
 	if (user->seq < log_next_seq) {
 		/* return error when data has vanished underneath us */
 		if (user->seq < log_first_seq)
@@ -908,7 +937,7 @@ static unsigned int devkmsg_poll(struct file *file, poll_table *wait)
 		else
 			ret = POLLIN|POLLRDNORM;
 	}
-	raw_spin_unlock_irq(&logbuf_lock);
+	logbuf_unlock_irq();
 
 	return ret;
 }
@@ -938,10 +967,10 @@ static int devkmsg_open(struct inode *inode, struct file *file)
 
 	mutex_init(&user->lock);
 
-	raw_spin_lock_irq(&logbuf_lock);
+	logbuf_lock_irq();
 	user->idx = log_first_idx;
 	user->seq = log_first_seq;
-	raw_spin_unlock_irq(&logbuf_lock);
+	logbuf_unlock_irq();
 
 	file->private_data = user;
 	return 0;
@@ -1083,13 +1112,13 @@ void __init setup_log_buf(int early)
 		return;
 	}
 
-	raw_spin_lock_irqsave(&logbuf_lock, flags);
+	logbuf_lock_irqsave(flags);
 	log_buf_len = new_log_buf_len;
 	log_buf = new_log_buf;
 	new_log_buf_len = 0;
 	free = __LOG_BUF_LEN - log_next_idx;
 	memcpy(log_buf, __log_buf, __LOG_BUF_LEN);
-	raw_spin_unlock_irqrestore(&logbuf_lock, flags);
+	logbuf_unlock_irqrestore(flags);
 
 	pr_info("log_buf_len: %d bytes\n", log_buf_len);
 	pr_info("early log buf free: %d(%d%%)\n",
@@ -1267,7 +1296,7 @@ static int syslog_print(char __user *buf, int size)
 		size_t n;
 		size_t skip;
 
-		raw_spin_lock_irq(&logbuf_lock);
+		logbuf_lock_irq();
 		if (syslog_seq < log_first_seq) {
 			/* messages are gone, move to first one */
 			syslog_seq = log_first_seq;
@@ -1275,7 +1304,7 @@ static int syslog_print(char __user *buf, int size)
 			syslog_partial = 0;
 		}
 		if (syslog_seq == log_next_seq) {
-			raw_spin_unlock_irq(&logbuf_lock);
+			logbuf_unlock_irq();
 			break;
 		}
 
@@ -1294,7 +1323,7 @@ static int syslog_print(char __user *buf, int size)
 			syslog_partial += n;
 		} else
 			n = 0;
-		raw_spin_unlock_irq(&logbuf_lock);
+		logbuf_unlock_irq();
 
 		if (!n)
 			break;
@@ -1323,7 +1352,7 @@ static int syslog_print_all(char __user *buf, int size, bool clear)
 	if (!text)
 		return -ENOMEM;
 
-	raw_spin_lock_irq(&logbuf_lock);
+	logbuf_lock_irq();
 	if (buf) {
 		u64 next_seq;
 		u64 seq;
@@ -1371,12 +1400,12 @@ static int syslog_print_all(char __user *buf, int size, bool clear)
 			idx = log_next(idx);
 			seq++;
 
-			raw_spin_unlock_irq(&logbuf_lock);
+			logbuf_unlock_irq();
 			if (copy_to_user(buf + len, text, textlen))
 				len = -EFAULT;
 			else
 				len += textlen;
-			raw_spin_lock_irq(&logbuf_lock);
+			logbuf_lock_irq();
 
 			if (seq < log_first_seq) {
 				/* messages are gone, move to next one */
@@ -1390,7 +1419,7 @@ static int syslog_print_all(char __user *buf, int size, bool clear)
 		clear_seq = log_next_seq;
 		clear_idx = log_next_idx;
 	}
-	raw_spin_unlock_irq(&logbuf_lock);
+	logbuf_unlock_irq();
 
 	kfree(text);
 	return len;
@@ -1477,7 +1506,7 @@ int do_syslog(int type, char __user *buf, int len, int source)
 		break;
 	/* Number of chars in the log buffer */
 	case SYSLOG_ACTION_SIZE_UNREAD:
-		raw_spin_lock_irq(&logbuf_lock);
+		logbuf_lock_irq();
 		if (syslog_seq < log_first_seq) {
 			/* messages are gone, move to first one */
 			syslog_seq = log_first_seq;
@@ -1505,7 +1534,7 @@ int do_syslog(int type, char __user *buf, int len, int source)
 			}
 			error -= syslog_partial;
 		}
-		raw_spin_unlock_irq(&logbuf_lock);
+		logbuf_unlock_irq();
 		break;
 	/* Size of the log buffer */
 	case SYSLOG_ACTION_SIZE_BUFFER:
@@ -1681,9 +1710,8 @@ asmlinkage int vprintk_emit(int facility, int level,
 	boot_delay_msec(level);
 	printk_delay();
 
-	printk_safe_enter_irqsave(flags);
 	/* This stops the holder of console_sem just where we want him */
-	raw_spin_lock(&logbuf_lock);
+	logbuf_lock_irqsave(flags);
 	/*
 	 * The printf needs to come first; we need the syslog
 	 * prefix which might be passed-in as a parameter.
@@ -1726,8 +1754,7 @@ asmlinkage int vprintk_emit(int facility, int level,
 
 	printed_len += log_output(facility, level, lflags, dict, dictlen, text, text_len);
 
-	raw_spin_unlock(&logbuf_lock);
-	printk_safe_exit_irqrestore(flags);
+	logbuf_unlock_irqrestore(flags);
 
 	/* If called from the scheduler, we can not call up(). */
 	if (!in_sched) {
@@ -2500,10 +2527,10 @@ void register_console(struct console *newcon)
 		 * console_unlock(); will print out the buffered messages
 		 * for us.
 		 */
-		raw_spin_lock_irqsave(&logbuf_lock, flags);
+		logbuf_lock_irqsave(flags);
 		console_seq = syslog_seq;
 		console_idx = syslog_idx;
-		raw_spin_unlock_irqrestore(&logbuf_lock, flags);
+		logbuf_unlock_irqrestore(flags);
 		/*
 		 * We're about to replay the log buffer.  Only do this to the
 		 * just-registered console to avoid excessive message spam to
@@ -2802,12 +2829,12 @@ void kmsg_dump(enum kmsg_dump_reason reason)
 		/* initialize iterator with data about the stored records */
 		dumper->active = true;
 
-		raw_spin_lock_irqsave(&logbuf_lock, flags);
+		logbuf_lock_irqsave(flags);
 		dumper->cur_seq = clear_seq;
 		dumper->cur_idx = clear_idx;
 		dumper->next_seq = log_next_seq;
 		dumper->next_idx = log_next_idx;
-		raw_spin_unlock_irqrestore(&logbuf_lock, flags);
+		logbuf_unlock_irqrestore(flags);
 
 		/* invoke dumper which will iterate over records */
 		dumper->dump(dumper, reason);
@@ -2892,9 +2919,9 @@ bool kmsg_dump_get_line(struct kmsg_dumper *dumper, bool syslog,
 	unsigned long flags;
 	bool ret;
 
-	raw_spin_lock_irqsave(&logbuf_lock, flags);
+	logbuf_lock_irqsave(flags);
 	ret = kmsg_dump_get_line_nolock(dumper, syslog, line, size, len);
-	raw_spin_unlock_irqrestore(&logbuf_lock, flags);
+	logbuf_unlock_irqrestore(flags);
 
 	return ret;
 }
@@ -2933,7 +2960,7 @@ bool kmsg_dump_get_buffer(struct kmsg_dumper *dumper, bool syslog,
 	if (!dumper->active)
 		goto out;
 
-	raw_spin_lock_irqsave(&logbuf_lock, flags);
+	logbuf_lock_irqsave(flags);
 	if (dumper->cur_seq < log_first_seq) {
 		/* messages are gone, move to first available one */
 		dumper->cur_seq = log_first_seq;
@@ -2942,7 +2969,7 @@ bool kmsg_dump_get_buffer(struct kmsg_dumper *dumper, bool syslog,
 
 	/* last entry */
 	if (dumper->cur_seq >= dumper->next_seq) {
-		raw_spin_unlock_irqrestore(&logbuf_lock, flags);
+		logbuf_unlock_irqrestore(flags);
 		goto out;
 	}
 
@@ -2984,7 +3011,7 @@ bool kmsg_dump_get_buffer(struct kmsg_dumper *dumper, bool syslog,
 	dumper->next_seq = next_seq;
 	dumper->next_idx = next_idx;
 	ret = true;
-	raw_spin_unlock_irqrestore(&logbuf_lock, flags);
+	logbuf_unlock_irqrestore(flags);
 out:
 	if (len)
 		*len = l;
@@ -3022,9 +3049,9 @@ void kmsg_dump_rewind(struct kmsg_dumper *dumper)
 {
 	unsigned long flags;
 
-	raw_spin_lock_irqsave(&logbuf_lock, flags);
+	logbuf_lock_irqsave(flags);
 	kmsg_dump_rewind_nolock(dumper);
-	raw_spin_unlock_irqrestore(&logbuf_lock, flags);
+	logbuf_unlock_irqrestore(flags);
 }
 EXPORT_SYMBOL_GPL(kmsg_dump_rewind);
 
-- 
2.11.0

Re: [PATCHv7 8/8] printk: convert the rest to printk-safe

[Petr Mladek]

On Tue 2016-12-27 23:16:11, Sergey Senozhatsky wrote:
> This patch converts the rest of logbuf users (which are
> out of printk recursion case, but can deadlock in printk).
> To make printk-safe usage easier the patch introduces 4
> helper macros:
> - logbuf_lock_irq()/logbuf_unlock_irq()
>   lock/unlock the logbuf lock and disable/enable local IRQ
> 
> - logbuf_lock_irqsave(flags)/logbuf_unlock_irqrestore(flags)
>   lock/unlock the logbuf lock and saves/restores local IRQ state
> 
> Signed-off-by: Sergey Senozhatsky <sergey.senozhatsky@gmail.com>

I like that it is so straigforward using the new macros. It is great
that you discovered this before we finished the patchset.

Reviewed-by: Petr Mladek <pmladek@suse.com>

Best Regards,
Petr

PS: All patches look fine to me. I am going to do some tests before
I could say a final word. I guess that it will be fine and we will
be able to push it to linux-next.

Re: [PATCHv7 8/8] printk: convert the rest to printk-safe

[Sergey Senozhatsky]

On (01/04/17 17:28), Petr Mladek wrote:
> On Tue 2016-12-27 23:16:11, Sergey Senozhatsky wrote:
> > This patch converts the rest of logbuf users (which are
> > out of printk recursion case, but can deadlock in printk).
> > To make printk-safe usage easier the patch introduces 4
> > helper macros:
> > - logbuf_lock_irq()/logbuf_unlock_irq()
> >   lock/unlock the logbuf lock and disable/enable local IRQ
> > 
> > - logbuf_lock_irqsave(flags)/logbuf_unlock_irqrestore(flags)
> >   lock/unlock the logbuf lock and saves/restores local IRQ state
> > 
> > Signed-off-by: Sergey Senozhatsky <sergey.senozhatsky@gmail.com>
> 
> I like that it is so straigforward using the new macros. It is great
> that you discovered this before we finished the patchset.
> 
> Reviewed-by: Petr Mladek <pmladek@suse.com>

thanks.

	-ss

Re: [PATCHv7 0/8] printk: use printk_safe to handle printk() recursive calls

[Petr Mladek]

On Tue 2016-12-27 23:16:03, Sergey Senozhatsky wrote:
> Hello,
> 
> 	This patch set extends a lock-less NMI per-cpu buffers idea to
> handle recursive printk() calls. The basic mechanism is pretty much the
> same -- at the beginning of a deadlock-prone section we switch to lock-less
> printk callback, and return back to a default printk implementation at the
> end; the messages are getting flushed to a logbuf buffer from a safer
> context.
> 
> See patch 0006 for examples of possible deadlock scenarios that are
> handled by printk-safe.
> 
> 
> v7:
> -- don't touch printk_nmi_enter/exit
> -- new printk_safe macros naming: printk_safe_enter_irqsave/exit_irqrestore
> -- added printk_safe_enter_irq/printk_safe_exit_irq
> -- added patch that converts the rest of printk.c to printk-safe
> -- fix build error on !NMI configs
> -- improved lost_messages reporting
> 
> v6:
> -- re-based
> -- addressed Petr's review (added comments; moved lost accounting to seq buf)
> ...
> 
> [against next-20161224 + "printk: always report dropped messages" patch set]
> 
> Sergey Senozhatsky (8):
>   printk: use vprintk_func in vprintk()
>   printk: rename nmi.c and exported api
>   printk: introduce per-cpu safe_print seq buffer
>   printk: always use deferred printk when flush printk_safe lines
>   printk: report lost messages in printk safe/nmi contexts
>   printk: use printk_safe buffers in printk
>   printk: remove zap_locks() function
>   printk: convert the rest to printk-safe
> 
>  include/linux/printk.h                 |  21 ++-
>  init/Kconfig                           |  16 ++-
>  init/main.c                            |   2 +-
>  kernel/kexec_core.c                    |   2 +-
>  kernel/panic.c                         |   4 +-
>  kernel/printk/Makefile                 |   2 +-
>  kernel/printk/internal.h               |  79 ++++++-----
>  kernel/printk/printk.c                 | 220 +++++++++++++------------------
>  kernel/printk/{nmi.c => printk_safe.c} | 234 +++++++++++++++++++++++----------
>  lib/nmi_backtrace.c                    |   2 +-
>  10 files changed, 335 insertions(+), 247 deletions(-)
>  rename kernel/printk/{nmi.c => printk_safe.c} (53%)

The entire patchset looks fine from my point of view.

Andrew, if you do not mind, I am going to make it tested in linux-next
via mine new git tree, see
https://git.kernel.org/cgit/linux/kernel/git/pmladek/printk.git/

I will push there also the patch that modifies MAINTAINERS file.
Then I will try to get all these changes upstream in the next merge
window.

It will be great if you still could keep an eye over the printk
patches and stop us when we do something bad.

Best Regards,
Petr