[RFC][PATCHv5 0/7] printk: use printk_safe to handle printk() recursive calls

[RFC][PATCHv5 0/7] 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.


The question is how do we want to handle this? It might be too late
for the 4.10 merge window, so I'm OK with
	a) this patch set and deferred+async printk (which I can send out
	tomorrow) both will stay in mmotm/linux-next until 4.11 merge window,
	which should give us enough time for testing.

I'm perhaps a bit less OK with
	b) this will go into 4.11 and, thus, deferred+async printk will wait
	for 4.11 merge window.


Option "a)" looks quite good. What do you think? Andrew, can we do this?
(if so, then how can I help?)


Deadlock scenarios that printk_safe can handle:

a) printk recursion from logbuf_lock spin_lock section in printk()
  printk()
    raw_spin_lock(&logbuf_lock);
    WARN_ON(1);
    raw_spin_unlock(&logbuf_lock);

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

c) printk from logbuf_lock spin_lock section in console_unlock()
  printk()
    console_unlock()
      raw_spin_lock(&logbuf_lock);
      WARN_ON(1);
      raw_spin_unlock(&logbuf_lock);

d) printk from ->pi_lock from semaphore up
  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);

e) printk from console_cont_flush() /*and down the call chain */
  printk()
    console_unlock()
      call_console_drivers()
       ...
          WARN_ON(1);

v5:
-- some style clean-ups and renamings (Petr)
-- use deferred printk when flush nmi/safe messages (Petr)

v4:
-- addressed Steven's review points
-- use printk_safe in console_cont_flush()

v3: (review by Petr)
-- renamed to printk_safe
-- !NMI config build fix
-- report lost messages for both printk_sae and printk_nmi
-- dropped recursion reporting patch
-- etc.

v2:
-- fix build error on !NMI configs, reported by Fengguang
-- reworked the series based on Petr's feedback
-- added a new patch to drop zap_locks()

Sergey Senozhatsky (7):
  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

 arch/arm/kernel/smp.c                  |   4 +-
 include/linux/hardirq.h                |   4 +-
 include/linux/printk.h                 |  29 ++--
 init/Kconfig                           |  16 ++-
 init/main.c                            |   2 +-
 kernel/kexec_core.c                    |   2 +-
 kernel/panic.c                         |   4 +-
 kernel/printk/Makefile                 |   2 +-
 kernel/printk/internal.h               |  63 ++++-----
 kernel/printk/printk.c                 | 124 +++++------------
 kernel/printk/{nmi.c => printk_safe.c} | 242 ++++++++++++++++++++++++---------
 lib/nmi_backtrace.c                    |   2 +-
 12 files changed, 275 insertions(+), 219 deletions(-)
 rename kernel/printk/{nmi.c => printk_safe.c} (53%)

-- 
2.10.2

[RFC][PATCHv5 1/7] 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 a3ce35e..9f2f44a 100644
--- a/kernel/printk/printk.c
+++ b/kernel/printk/printk.c
@@ -1902,7 +1902,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.10.2

[RFC][PATCHv5 2/7] 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
- rename exported functions to have a `printk_safe' prefix.

Signed-off-by: Sergey Senozhatsky <sergey.senozhatsky@gmail.com>
Acked-by: Steven Rostedt <rostedt@goodmis.org>
Reviewed-by: Petr Mladek <pmladek@suse.com>
---
 arch/arm/kernel/smp.c                  |  4 +-
 include/linux/hardirq.h                |  4 +-
 include/linux/printk.h                 | 20 +++++-----
 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} | 72 +++++++++++++++++-----------------
 lib/nmi_backtrace.c                    |  2 +-
 10 files changed, 65 insertions(+), 63 deletions(-)
 rename kernel/printk/{nmi.c => printk_safe.c} (77%)

diff --git a/arch/arm/kernel/smp.c b/arch/arm/kernel/smp.c
index 7dd14e8..8b056e1 100644
--- a/arch/arm/kernel/smp.c
+++ b/arch/arm/kernel/smp.c
@@ -644,11 +644,11 @@ void handle_IPI(int ipinr, struct pt_regs *regs)
 		break;
 
 	case IPI_CPU_BACKTRACE:
-		printk_nmi_enter();
+		printk_safe_nmi_enter();
 		irq_enter();
 		nmi_cpu_backtrace(regs);
 		irq_exit();
-		printk_nmi_exit();
+		printk_safe_nmi_exit();
 		break;
 
 	default:
diff --git a/include/linux/hardirq.h b/include/linux/hardirq.h
index c683996..14840aa 100644
--- a/include/linux/hardirq.h
+++ b/include/linux/hardirq.h
@@ -61,7 +61,7 @@ extern void irq_exit(void);
 
 #define nmi_enter()						\
 	do {							\
-		printk_nmi_enter();				\
+		printk_safe_nmi_enter();			\
 		lockdep_off();					\
 		ftrace_nmi_enter();				\
 		BUG_ON(in_nmi());				\
@@ -78,7 +78,7 @@ extern void irq_exit(void);
 		preempt_count_sub(NMI_OFFSET + HARDIRQ_OFFSET);	\
 		ftrace_nmi_exit();				\
 		lockdep_on();					\
-		printk_nmi_exit();				\
+		printk_safe_nmi_exit();				\
 	} while (0)
 
 #endif /* LINUX_HARDIRQ_H */
diff --git a/include/linux/printk.h b/include/linux/printk.h
index 3472cc6..67df41e 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_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_init(void);
+extern void printk_safe_nmi_enter(void);
+extern void printk_safe_nmi_exit(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_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_init(void) { }
+static inline void printk_safe_nmi_enter(void) { }
+static inline void printk_safe_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
diff --git a/init/Kconfig b/init/Kconfig
index 271692a..0662a43 100644
--- a/init/Kconfig
+++ b/init/Kconfig
@@ -862,17 +862,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 74cf81e..8e4e337 100644
--- a/init/main.c
+++ b/init/main.c
@@ -578,7 +578,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 8ad3a29e..344cd78 100644
--- a/kernel/kexec_core.c
+++ b/kernel/kexec_core.c
@@ -914,7 +914,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 c51edaa..8c8efcd 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 abb0042..6079281 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 77%
rename from kernel/printk/nmi.c
rename to kernel/printk/printk_safe.c
index 26cd42d..d5a4b6f 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
@@ -58,9 +58,9 @@ static DEFINE_PER_CPU(struct nmi_seq_buf, nmi_print_seq);
  * 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)
+static int vprintk_safe_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;
 
@@ -90,7 +90,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);
@@ -99,7 +99,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
@@ -110,11 +110,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;
@@ -126,7 +125,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;
@@ -139,7 +138,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;
@@ -153,8 +152,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;
@@ -164,11 +163,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;
@@ -193,9 +193,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;
 	}
 
@@ -204,7 +204,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
@@ -220,31 +220,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.
@@ -258,33 +258,33 @@ 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)
+void printk_safe_nmi_enter(void)
 {
-	this_cpu_write(printk_func, vprintk_nmi);
+	this_cpu_write(printk_func, vprintk_safe_nmi);
 }
 
-void printk_nmi_exit(void)
+void printk_safe_nmi_exit(void)
 {
 	this_cpu_write(printk_func, vprintk_default);
 }
diff --git a/lib/nmi_backtrace.c b/lib/nmi_backtrace.c
index 7555475..5f7999e 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.10.2

[RFC][PATCHv5 3/7] 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(flags)
  //
  //  any printk() call from here will endup in vprintk_safe(),
  //  that stores messages in a special per-CPU buffer.
  //
  printk_safe_exit(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    |  56 +++++++++++--------
 kernel/printk/printk.c      |   3 -
 kernel/printk/printk_safe.c | 133 ++++++++++++++++++++++++++++++++++----------
 5 files changed, 152 insertions(+), 63 deletions(-)

diff --git a/include/linux/printk.h b/include/linux/printk.h
index 67df41e..f7d291c 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_safe_nmi_enter(void);
 extern void printk_safe_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_safe_nmi_enter(void) { }
 static inline void printk_safe_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 6079281..4a2ffc3 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 7fd2838..97cee4f 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,42 @@ 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(flags)		\
+	do {					\
+		local_irq_save(flags);		\
+		__printk_safe_enter();		\
+	} while (0)
+
+#define printk_safe_exit(flags)		\
+	do {					\
+		__printk_safe_exit();		\
+		local_irq_restore(flags);	\
+	} while (0)
+
+#else
+
+__printf(1, 0) int vprintk_func(const char *fmt, va_list args) { return 0; }
+
+#define printk_safe_enter(f)	((void)(f))
+#define printk_safe_exit(f)	((void)(f))
+
+#endif /* CONFIG_PRINTK */
diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
index 9f2f44a..77446ba 100644
--- a/kernel/printk/printk.c
+++ b/kernel/printk/printk.c
@@ -2010,9 +2010,6 @@ static size_t msg_print_text(const struct printk_log *msg, enum log_flags prev,
 static size_t cont_print_text(char *text, 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 d5a4b6f..c22e286 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,15 +32,14 @@
  * 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;
 
 #define SAFE_LOG_BUF_LEN ((1 << CONFIG_PRINTK_SAFE_LOG_BUF_SHIFT) -	\
 			 sizeof(atomic_t) - sizeof(struct irq_work))
@@ -50,27 +49,26 @@ 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);
+atomic_t nmi_message_lost;
+#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.
- */
-static int vprintk_safe_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:
 	len = atomic_read(&s->len);
 
-	if (len >= sizeof(s->buffer)) {
-		atomic_inc(&nmi_message_lost);
-		return 0;
-	}
+	if (len >= sizeof(s->buffer))
+		return -ENOSPC;
 
 	/*
 	 * Make sure that all old data have been read before the buffer was
@@ -160,7 +158,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)
@@ -230,8 +228,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);
+	}
 }
 
 /**
@@ -261,14 +263,95 @@ 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_safe_nmi(const char *fmt, va_list args)
+{
+	struct printk_safe_seq_buf *s = this_cpu_ptr(&nmi_print_seq);
+	int add;
+
+	add = printk_safe_log_store(s, fmt, args);
+	if (add == -ENOSPC) {
+		atomic_inc(&nmi_message_lost);
+		add = 0;
+	}
+
+	return add;
+}
+
+void printk_safe_nmi_enter(void)
+{
+	this_cpu_or(printk_context, PRINTK_NMI_CONTEXT_MASK);
+}
+
+void printk_safe_nmi_exit(void)
+{
+	this_cpu_and(printk_context, ~PRINTK_NMI_CONTEXT_MASK);
+}
+
+#else
+
+static int vprintk_safe_nmi(const char *fmt, va_list args)
+{
+	return 0;
+}
+
+#endif /* CONFIG_PRINTK_NMI */
+
+/*
+ * Lockless 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_safe_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. */
@@ -278,13 +361,3 @@ void __init printk_safe_init(void)
 	/* Flush pending messages that did not have scheduled IRQ works. */
 	printk_safe_flush();
 }
-
-void printk_safe_nmi_enter(void)
-{
-	this_cpu_write(printk_func, vprintk_safe_nmi);
-}
-
-void printk_safe_nmi_exit(void)
-{
-	this_cpu_write(printk_func, vprintk_default);
-}
-- 
2.10.2

Re: [RFC][PATCHv5 3/7] printk: introduce per-cpu safe_print seq buffer

[Petr Mladek]

On Thu 2016-12-01 22:55:42, 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
> 
>  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(flags)
>   //
>   //  any printk() call from here will endup in vprintk_safe(),
>   //  that stores messages in a special per-CPU buffer.
>   //
>   printk_safe_exit(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.
> 
> diff --git a/kernel/printk/printk_safe.c b/kernel/printk/printk_safe.c
> index d5a4b6f..c22e286 100644
> --- a/kernel/printk/printk_safe.c
> +++ b/kernel/printk/printk_safe.c
> @@ -50,27 +49,26 @@ 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);
> +atomic_t nmi_message_lost;
> +#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.
> - */

We should keep/create a good description here because the function
has a non-trivial code. What about something like?

/*
 * Print a message into the given per-CPU buffer a safe way.
 * We need to be very careful here.
 *
 * First, the buffer might be flushed from another CPU at the same
 * time. This is solved by repeated write if the buffer length
 * is changed in the meantime.
 *
 * Second, the function might be called recursively if there
 * is an error message printed from this code. The recursion
 * will stop once the buffer is full. It is not ideal but it
 * should be enough to debug.
 */
> -static int vprintk_safe_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:
>  	len = atomic_read(&s->len);
>  
> -	if (len >= sizeof(s->buffer)) {
> -		atomic_inc(&nmi_message_lost);
> -		return 0;
> -	}
> +	if (len >= sizeof(s->buffer))
> +		return -ENOSPC;

I was curious if we would really leave the cycle if the buffer
is full. And the check has to be

	if (len >= sizeof(s->buffer) - 1)

but it is handled in separate patch that I have already sent.

>  	/*
>  	 * Make sure that all old data have been read before the buffer was
> @@ -261,14 +263,95 @@ 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.
> + */

Hmm, I wanted to describe why we need another per-CPU buffer in NMI
and I am not sure that we really need it.

vprintk_safe_nmi() and vprintk_safe() will never run in parallel.
vprintk_safe_nmi() might be nested into vprintk_safe() but
printk_safe_log_store() is able to handle the nesting.

It is Friday evening, so I am not 100% sure. But if this is true,
we might simplify everything even more. Single per-cpu buffer and
single per-CPU nesting counter might be enough. I have to think
about it.

Best Regards,
Petr

PS: Heh, I was sad that all my comments looked like nitpicking.
But I was not able to help myself. And it seems that a good function
description might actually help to get a better code ;-)

Re: [RFC][PATCHv5 3/7] printk: introduce per-cpu safe_print seq buffer

[Sergey Senozhatsky]

On (12/09/16 17:46), Petr Mladek wrote:
> > -/*
> > - * 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.
> > - */
> 
> We should keep/create a good description here because the function
> has a non-trivial code. What about something like?
> 

which is really not related to this patch set.


> >  	 * Make sure that all old data have been read before the buffer was
> > @@ -261,14 +263,95 @@ 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.
> > + */
> 
> Hmm, I wanted to describe why we need another per-CPU buffer in NMI
> and I am not sure that we really need it.

NMI-printk can interrupt safe-printk's vsnprintf() in the middle of
the "while (*fmt)" loop: safe-priNMI-PRINTK


	-ss

Re: [RFC][PATCHv5 3/7] printk: introduce per-cpu safe_print seq buffer

[Petr Mladek]

On Sat 2016-12-10 12:10:22, Sergey Senozhatsky wrote:
> On (12/09/16 17:46), Petr Mladek wrote:
> > > -/*
> > > - * 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.
> > > - */
> > 
> > We should keep/create a good description here because the function
> > has a non-trivial code. What about something like?
> > 
> 
> which is really not related to this patch set.

I am sorry but I do not understand. This patch removes description
that explained constrains of a rather complex code. In fact, the
constrains has changed because we started using the function also
in other context. When will be the right time/patchset to explain
it?

> 
> > >  	 * Make sure that all old data have been read before the buffer was
> > > @@ -261,14 +263,95 @@ 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.
> > > + */
> > 
> > Hmm, I wanted to describe why we need another per-CPU buffer in NMI
> > and I am not sure that we really need it.
> 
> NMI-printk can interrupt safe-printk's vsnprintf() in the middle of
> the "while (*fmt)" loop: safe-priNMI-PRINTK

But this already happens when any of the WARNs is triggered
inside vsnprintf(). Either this is safe or we are in
trouble.

Well, there is a difference. NMI can come at anytime and vsnprintf()
continues printing the original string once we are back from NMI.
But if we hit WARN() inside vsnprintf(), it usually means an error,
vsnprintf() stops printing into the given buffer and returns. It
means that it does not overwrite the message printed by the nested
printks.

The only exceptions are WARN_ONCE() calls in set_field_width()
and set_precision(). They are self-repairing, vsnprintf()
continues printing and will overwrite the nested warnings.
Well, I am not sure if we should bother.

By other words, we really need separate per-CPU buffer for NMI
and the generic printk_safe. I am sorry for the noise.

Well, is it that bad to ask for better comments? You see that
I ended in quite some doubts, even found problems, when I tried
to review the code carefully. Or am I dumb and it was all obvious?

Best Regards,
Petr

PS: I know that I am sometimes in too nitpicking mode and it
might be annoying and discouraging. I have to find the right
boundaries.

Re: [RFC][PATCHv5 3/7] printk: introduce per-cpu safe_print seq buffer

[Sergey Senozhatsky]

On (12/12/16 14:54), Petr Mladek wrote:
> On Sat 2016-12-10 12:10:22, Sergey Senozhatsky wrote:
> > On (12/09/16 17:46), Petr Mladek wrote:
> > > > -/*
> > > > - * 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.
> > > > - */
> > > 
> > > We should keep/create a good description here because the function
> > > has a non-trivial code. What about something like?
> > > 
> > 
> > which is really not related to this patch set.
> 
> I am sorry but I do not understand. This patch removes description
> that explained constrains of a rather complex code. In fact, the
> constrains has changed because we started using the function also
> in other context. When will be the right time/patchset to explain
> it?

but I didn't remove it.

$ grep -A3 -B3 'But the buffer might get flushed from another' kernel/printk/printk_safe.c

/*
 * 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_safe_nmi(const char *fmt, va_list args)


> > > > +#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.
> > > > + */
> > > 
> > > Hmm, I wanted to describe why we need another per-CPU buffer in NMI
> > > and I am not sure that we really need it.
> > 
> > NMI-printk can interrupt safe-printk's vsnprintf() in the middle of
> > the "while (*fmt)" loop: safe-priNMI-PRINTK
> 
> But this already happens when any of the WARNs is triggered
> inside vsnprintf(). Either this is safe or we are in
> trouble.

the point was that when printk-safe resumes after being interrupted
by NMI-printk it continues printing from the offset at which it has
been interrupted, writing over the lines that were sprintf-d by NMI
printk; because NMI-printk used the same buffer offset `s->len'. so
at least part of NMI-printk message will be lost.

	-ss

Re: [RFC][PATCHv5 3/7] printk: introduce per-cpu safe_print seq buffer

[Petr Mladek]

On Mon 2016-12-12 23:12:30, Sergey Senozhatsky wrote:
> On (12/12/16 14:54), Petr Mladek wrote:
> > On Sat 2016-12-10 12:10:22, Sergey Senozhatsky wrote:
> > > On (12/09/16 17:46), Petr Mladek wrote:
> > > > > -/*
> > > > > - * 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.
> > > > > - */
> > > > 
> > > > We should keep/create a good description here because the function
> > > > has a non-trivial code. What about something like?
> > > > 
> > > 
> > > which is really not related to this patch set.
> > 
> > I am sorry but I do not understand. This patch removes description
> > that explained constrains of a rather complex code. In fact, the
> > constrains has changed because we started using the function also
> > in other context. When will be the right time/patchset to explain
> > it?
> 
> but I didn't remove it.
> 
> $ grep -A3 -B3 'But the buffer might get flushed from another' kernel/printk/printk_safe.c
> 
> /*
>  * 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_safe_nmi(const char *fmt, va_list args)

I know, it is moved to the caller of the complex function.
And the description of the other new caller explicitly talks
about printk() recursion (nesting). It opens question if
it is still safe and there is no single note about it.
Also there is no explanation why we need the other buffer
at all.


> > > > > +#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.
> > > > > + */
> > > > 
> > > > Hmm, I wanted to describe why we need another per-CPU buffer in NMI
> > > > and I am not sure that we really need it.
> > > 
> > > NMI-printk can interrupt safe-printk's vsnprintf() in the middle of
> > > the "while (*fmt)" loop: safe-priNMI-PRINTK
> > 
> > But this already happens when any of the WARNs is triggered
> > inside vsnprintf(). Either this is safe or we are in
> > trouble.
> 
> the point was that when printk-safe resumes after being interrupted
> by NMI-printk it continues printing from the offset at which it has
> been interrupted, writing over the lines that were sprintf-d by NMI
> printk; because NMI-printk used the same buffer offset `s->len'. so
> at least part of NMI-printk message will be lost.

Yes, I wrote this in the previous mail as well. I remember that
I already thought about this problem when working on the original
NMI implementation and I forgot it. This is what comments are for.
Even authors forget details and they do not want to get into
the same cycles again and again.

I understand that you are tired with respining the patchset.
But hey, updating comments is easy. And if people only ask
to add some comments, it means that it is most likely
the last round and all is almost done.

I do not know. Maybe you take my comments as criticism.
But it is not meant like this. I only want to safe some
work me and other people in the future.

Best Regards,
Petr

Re: [RFC][PATCHv5 3/7] printk: introduce per-cpu safe_print seq buffer

[Sergey Senozhatsky]

On (12/12/16 14:54), Petr Mladek wrote:
[..]
> > > Hmm, I wanted to describe why we need another per-CPU buffer in NMI
> > > and I am not sure that we really need it.
> > 
> > NMI-printk can interrupt safe-printk's vsnprintf() in the middle of
> > the "while (*fmt)" loop: safe-priNMI-PRINTK
> 
> But this already happens when any of the WARNs is triggered
> inside vsnprintf(). Either this is safe or we are in
> trouble.
[..]
> Well, I am not sure if we should bother.

well, I'd probably agree that we shouldn't care. I'd may be even
say that nested warnings from vsnprintf() are not so important to
over-complicated everything (comparing to lost NMI-printk messages,
which are really important).


> Well, is it that bad to ask for better comments?

ok, I'll take a look. gotta re-base the series once again anyway.

> Or am I dumb and it was all obvious?

of course no! I never said that. never! :)
my apologies.

	-ss

[RFC][PATCHv5 4/7] 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>
---
 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 c22e286..3ded9e1 100644
--- a/kernel/printk/printk_safe.c
+++ b/kernel/printk/printk_safe.c
@@ -100,14 +100,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.10.2

Re: [RFC][PATCHv5 4/7] printk: always use deferred printk when flush printk_safe lines

[Petr Mladek]

On Thu 2016-12-01 22:55:43, Sergey Senozhatsky 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.

Also this makes it clear that we are storing the messages into
the main logbuffer here. Note that printk() might get redirected
to the per-CPU buffer when this is triggered in panic.

> Signed-off-by: Sergey Senozhatsky <sergey.senozhatsky@gmail.com>
> Suggested-by: Petr Mladek <pmladek@suse.com>

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

Best Regards,
Petr

[RFC][PATCHv5 5/7] 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().

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

diff --git a/kernel/printk/internal.h b/kernel/printk/internal.h
index 97cee4f..d245602 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 77446ba..6f7b217 100644
--- a/kernel/printk/printk.c
+++ b/kernel/printk/printk.c
@@ -1776,7 +1776,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;
@@ -1827,15 +1826,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 3ded9e1..0689b94 100644
--- a/kernel/printk/printk_safe.c
+++ b/kernel/printk/printk_safe.c
@@ -52,10 +52,11 @@ struct printk_safe_seq_buf {
 
 static DEFINE_PER_CPU(struct printk_safe_seq_buf, safe_print_seq);
 static DEFINE_PER_CPU(int, printk_context);
+static atomic_t safe_message_lost;
 
 #ifdef CONFIG_PRINTK_NMI
 static DEFINE_PER_CPU(struct printk_safe_seq_buf, nmi_print_seq);
-atomic_t nmi_message_lost;
+static atomic_t nmi_message_lost;
 #endif
 
 static int printk_safe_log_store(struct printk_safe_seq_buf *s,
@@ -155,6 +156,36 @@ static int printk_safe_flush_buffer(const char *start, size_t len)
 	return len;
 }
 
+static void report_message_lost(atomic_t *num_lost, const char *context)
+{
+	int lost = atomic_xchg(num_lost, 0);
+
+	if (lost)
+		printk_deferred("Lost %d message(s) from %s context!\n",
+				lost,
+				context);
+}
+
+#ifdef CONFIG_PRINTK_NMI
+
+static void report_nmi_message_lost(void)
+{
+	report_message_lost(&nmi_message_lost, "NMI");
+}
+
+#else
+
+static void report_nmi_message_lost(void)
+{
+}
+
+#endif /* CONFIG_PRINTK_NMI */
+
+static void report_safe_message_lost(void)
+{
+	report_message_lost(&safe_message_lost, "printk-safe");
+}
+
 /*
  * Flush data from the associated per-CPU buffer. The function
  * can be called either via IRQ work or independently.
@@ -211,6 +242,9 @@ static void __printk_safe_flush(struct irq_work *work)
 	if (atomic_cmpxchg(&s->len, len, 0) != len)
 		goto more;
 
+	report_nmi_message_lost();
+	report_safe_message_lost();
+
 out:
 	raw_spin_unlock_irqrestore(&read_lock, flags);
 }
@@ -309,8 +343,15 @@ static int vprintk_safe_nmi(const char *fmt, va_list args)
 static int vprintk_safe(const char *fmt, va_list args)
 {
 	struct printk_safe_seq_buf *s = this_cpu_ptr(&safe_print_seq);
+	int add;
 
-	return printk_safe_log_store(s, fmt, args);
+	add = printk_safe_log_store(s, fmt, args);
+	if (add == -ENOSPC) {
+		atomic_inc(&safe_message_lost);
+		add = 0;
+	}
+
+	return add;
 }
 
 /* Can be preempted by NMI. */
-- 
2.10.2

Re: [RFC][PATCHv5 5/7] printk: report lost messages in printk safe/nmi contexts

[Petr Mladek]

On Thu 2016-12-01 22:55:44, Sergey Senozhatsky wrote:
> Account lost messages in pritk-safe and printk-safe-nmi
> contexts and report those numbers during printk_safe_flush().
> 
> Signed-off-by: Sergey Senozhatsky <sergey.senozhatsky@gmail.com>
> ---
> --- a/kernel/printk/printk_safe.c
> +++ b/kernel/printk/printk_safe.c
> @@ -211,6 +242,9 @@ static void __printk_safe_flush(struct irq_work *work)
>  	if (atomic_cmpxchg(&s->len, len, 0) != len)
>  		goto more;
>  
> +	report_nmi_message_lost();
> +	report_safe_message_lost();

The great thing about this solution is that we print this message
in the right order (after the messages that fit into the buffer).

But not really because we report lost messages from both buffers
and from all CPUs here.

The perfect solution would be to remember the number of lost messages
in struct printk_safe_seq_buf. Then we might bump the value directly
in printk_safe_log_store() instead of returning the ugly -ENOSPC.
Also we could use an universal message (no "NMI" or "printk-safe")
because it could be printed right after flushing the messages
that fit the buffer.

This solution is good enough and still better than the previous one, so

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


But if you would want to change it to the "perfect" one, it would be
appreciated ;-) It will be even more straightforward and less code.
In this, case I would do the change in an earlier patch to make
it more straightforward. But we could also do this later
(in another patchset).

Best Regards,
Petr

Re: [RFC][PATCHv5 5/7] printk: report lost messages in printk safe/nmi contexts

[Sergey Senozhatsky]

On (12/12/16 16:58), Petr Mladek wrote:
> On Thu 2016-12-01 22:55:44, Sergey Senozhatsky wrote:
[..]
> But not really because we report lost messages from both buffers
> and from all CPUs here.
[..]
> The perfect solution would be to remember the number of lost messages
> in struct printk_safe_seq_buf. Then we might bump the value directly
> in printk_safe_log_store() instead of returning the ugly -ENOSPC.

ok, I can take a look. this won't grow the per-CPU buffers bigger,
but will shrink the actual message buffer size by sizeof(atomic),
not that dramatic.

* unrelated, can be done later (if ever) *

speaking of tha actual message buffer size, we, may be, can move
`struct irq_work' out of printk_safe_seq_buf. there is already
a printk-related per-CPU irq_work in place - wake_up_klogd_work.
so we may be can use it, instead of defining a bunch of new irq_works.
this will increase the printk-safe/nmi per-CPU message buffer size
by sizeof(irq_work).

> Also we could use an universal message (no "NMI" or "printk-safe")
> because it could be printed right after flushing the messages
> that fit the buffer.

this "context" part probably can be dropped. both printk-safe and
printk-nmi per-CPU buffer sizes are controlled by a single .config
option anyway; user can't increase the printk-safe buffer size
without increasing the printk-nmi buffer size (in case if printk-safe
buffer is too small).

> This solution is good enough and still better than the previous one, so
> 
> Reviewed-by: Petr Mladek <pmladek@suse.com>

thanks.

	-ss

Re: [RFC][PATCHv5 5/7] printk: report lost messages in printk safe/nmi contexts

[Petr Mladek]

On Tue 2016-12-13 10:52:37, Sergey Senozhatsky wrote:
> On (12/12/16 16:58), Petr Mladek wrote:
> > On Thu 2016-12-01 22:55:44, Sergey Senozhatsky wrote:
> [..]
> > But not really because we report lost messages from both buffers
> > and from all CPUs here.
> [..]
> > The perfect solution would be to remember the number of lost messages
> > in struct printk_safe_seq_buf. Then we might bump the value directly
> > in printk_safe_log_store() instead of returning the ugly -ENOSPC.
> 
> ok, I can take a look. this won't grow the per-CPU buffers bigger,
> but will shrink the actual message buffer size by sizeof(atomic),
> not that dramatic.

IMHO, the size is a negligible difference. If we are often getting
on the edge of the buffers, we have problems anyway.


> * unrelated, can be done later (if ever) *
> 
> speaking of tha actual message buffer size, we, may be, can move
> `struct irq_work' out of printk_safe_seq_buf. there is already
> a printk-related per-CPU irq_work in place - wake_up_klogd_work.
> so we may be can use it, instead of defining a bunch of new irq_works.
> this will increase the printk-safe/nmi per-CPU message buffer size
> by sizeof(irq_work).

Interesting idea! I think that there is a space for more optimization.
For example, we will not need to schedule the irq work if we are
flushing  the per-CPU buffers from irq work and we know that
we will flush consoles or wake up the kthread right after that.
Also I though about using a global "printk_pending" variable
and queue the irqwork only when the given event was not already set.

I would leave all this optimization for a later patchset.


> > Also we could use an universal message (no "NMI" or "printk-safe")
> > because it could be printed right after flushing the messages
> > that fit the buffer.
> 
> this "context" part probably can be dropped. both printk-safe and
> printk-nmi per-CPU buffer sizes are controlled by a single .config
> option anyway; user can't increase the printk-safe buffer size
> without increasing the printk-nmi buffer size (in case if printk-safe
> buffer is too small).

I agree.

Best Regards,
Petr

[RFC][PATCHv5 6/7] 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().

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+0x1cd/0x438
 CPU: 0 PID: 366 Comm: bash
 Call Trace:
  [<ffffffff81045658>] warn_slowpath_null+0x1d/0x1f
  [<ffffffff81091527>] vprintk_emit+0x1cd/0x438
  [<ffffffff810918fe>] vprintk_default+0x1d/0x1f
  [<ffffffff810fdf6a>] printk+0x48/0x50
  [..]
  [<ffffffff813caaaa>] entry_SYSCALL_64_fastpath+0x18/0xad
 ---[ end trace ]---

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+0x3d/0x62
 CPU: 1 PID: 363 Comm: bash
 Call Trace:
  [<ffffffff81045658>] warn_slowpath_null+0x1d/0x1f
  [<ffffffff810838df>] down_trylock+0x3d/0x62
  [<ffffffff8109177e>] ? vprintk_emit+0x3f9/0x414
  [<ffffffff810905cb>] console_trylock+0x31/0xeb
  [<ffffffff8109177e>] vprintk_emit+0x3f9/0x414
  [<ffffffff81091905>] vprintk_default+0x1d/0x1f
  [<ffffffff810fdf71>] printk+0x48/0x50
  [..]
  [<ffffffff813caaaa>] entry_SYSCALL_64_fastpath+0x18/0xad
 ---[ end trace ]---

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+0x12d/0x559
 CPU: 1 PID: 329 Comm: bash
 Call Trace:
  [<ffffffff8103d6ca>] warn_slowpath_null+0x18/0x1a
  [<ffffffff8107f917>] console_unlock+0x12d/0x559
  [<ffffffff810772c4>] ? trace_hardirqs_on_caller+0x16d/0x189
  [<ffffffff810772ed>] ? trace_hardirqs_on+0xd/0xf
  [<ffffffff810800a6>] vprintk_emit+0x363/0x374
  [<ffffffff81080219>] vprintk_default+0x18/0x1a
  [<ffffffff810c7f77>] printk+0x43/0x4b
  [..]
  [<ffffffff814c2d6a>] entry_SYSCALL_64_fastpath+0x18/0xad
 ---[ end trace ]---

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+0x7f/0x4f7
 CPU: 3 PID: 363 Comm: bash
 Call Trace:
  [<ffffffff81045658>] warn_slowpath_null+0x1d/0x1f
  [<ffffffff8106c8d0>] try_to_wake_up+0x7f/0x4f7
  [<ffffffff8106cd5d>] wake_up_process+0x15/0x17
  [<ffffffff813c82c6>] __up.isra.0+0x56/0x63
  [<ffffffff810839a3>] up+0x32/0x42
  [<ffffffff8108f624>] __up_console_sem+0x37/0x55
  [<ffffffff810910ff>] console_unlock+0x21e/0x4c2
  [<ffffffff810917bf>] vprintk_emit+0x41c/0x462
  [<ffffffff81091971>] vprintk_default+0x1d/0x1f
  [<ffffffff810fdfdd>] printk+0x48/0x50
  [..]
  [<ffffffff813cab2a>] entry_SYSCALL_64_fastpath+0x18/0xad
 ---[ end trace ]---

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+0x3a/0xb0
 CPU: 2 PID: 305 Comm: bash
 Call Trace:
  [<ffffffff810399c0>] warn_slowpath_null+0x18/0x1a
  [<ffffffff8106b218>] call_console_drivers.isra.6.constprop.16+0x3a/0xb0
  [<ffffffff8106cc46>] console_unlock+0x471/0x48e
  [<ffffffff8106ce57>] vprintk_emit+0x1f4/0x206
  [<ffffffff8106cfcb>] vprintk_default+0x18/0x1a
  [<ffffffff8106af66>] vprintk_func+0x6e/0x70
  [<ffffffff810abbe3>] printk+0x3e/0x46
[..]
  [<ffffffff8145a860>] entry_SYSCALL_64_fastpath+0x13/0x94
 ---[ end trace ]---

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

diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
index 6f7b217..80f0177 100644
--- a/kernel/printk/printk.c
+++ b/kernel/printk/printk.c
@@ -213,17 +213,31 @@ 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;
+
+	printk_safe_enter(flags);
+	lock_failed = down_trylock(&console_sem);
+	printk_safe_exit(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(flags);
+	up(&console_sem);
+	printk_safe_exit(flags);
+}
+#define up_console_sem() __up_console_sem(_RET_IP_)
 
 /*
  * This is used for debugging the mess that is the VT code by
@@ -1788,7 +1802,7 @@ asmlinkage int vprintk_emit(int facility, int level,
 	boot_delay_msec(level);
 	printk_delay();
 
-	local_irq_save(flags);
+	printk_safe_enter(flags);
 	this_cpu = smp_processor_id();
 
 	/*
@@ -1804,13 +1818,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(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;
@@ -1870,12 +1883,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(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
@@ -1883,7 +1894,6 @@ asmlinkage int vprintk_emit(int facility, int level,
 		 */
 		if (console_trylock())
 			console_unlock();
-		lockdep_on();
 	}
 
 	return printed_len;
@@ -2263,7 +2273,8 @@ static void console_cont_flush(char *text, size_t size)
 	unsigned long flags;
 	size_t len;
 
-	raw_spin_lock_irqsave(&logbuf_lock, flags);
+	printk_safe_enter(flags);
+	raw_spin_lock(&logbuf_lock);
 
 	if (!cont.len)
 		goto out;
@@ -2288,10 +2299,11 @@ static void console_cont_flush(char *text, size_t size)
 	stop_critical_timings();
 	call_console_drivers(cont.level, NULL, 0, text, len);
 	start_critical_timings();
-	local_irq_restore(flags);
+	printk_safe_exit(flags);
 	return;
 out:
-	raw_spin_unlock_irqrestore(&logbuf_lock, flags);
+	raw_spin_unlock(&logbuf_lock);
+	printk_safe_exit(flags);
 }
 
 /**
@@ -2356,7 +2368,8 @@ void console_unlock(void)
 		size_t len;
 		int level;
 
-		raw_spin_lock_irqsave(&logbuf_lock, flags);
+		printk_safe_enter(flags);
+		raw_spin_lock(&logbuf_lock);
 		if (seen_seq != log_next_seq) {
 			wake_klogd = true;
 			seen_seq = log_next_seq;
@@ -2417,7 +2430,7 @@ void console_unlock(void)
 		stop_critical_timings();	/* don't trace print latency */
 		call_console_drivers(level, ext_text, ext_len, text, len);
 		start_critical_timings();
-		local_irq_restore(flags);
+		printk_safe_exit(flags);
 
 		if (do_cond_resched)
 			cond_resched();
@@ -2440,7 +2453,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(flags);
 
 	if (retry && console_trylock())
 		goto again;
-- 
2.10.2

Re: [RFC][PATCHv5 6/7] printk: use printk_safe buffers in printk

[Petr Mladek]

On Thu 2016-12-01 22:55:45, Sergey Senozhatsky 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().
> 
> 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.
> 
> Signed-off-by: Sergey Senozhatsky <sergey.senozhatsky@gmail.com>

Looks fine and safe to me.

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

Best Regards,
Petr

Re: [RFC][PATCHv5 6/7] printk: use printk_safe buffers in printk

[Sergey Senozhatsky]

On (12/12/16 17:30), Petr Mladek wrote:
> On Thu 2016-12-01 22:55:45, Sergey Senozhatsky 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().
> > 
> > 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.
> > 
> > Signed-off-by: Sergey Senozhatsky <sergey.senozhatsky@gmail.com>
> 
> Looks fine and safe to me.
> 
> Reviewed-by: Petr Mladek <pmladek@suse.com>

thanks.

	-ss

[RFC][PATCHv5 7/7] 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>
---
 kernel/printk/printk.c | 61 --------------------------------------------------
 1 file changed, 61 deletions(-)

diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
index 80f0177..729dd71 100644
--- a/kernel/printk/printk.c
+++ b/kernel/printk/printk.c
@@ -1600,28 +1600,6 @@ static void call_console_drivers(int level,
 	}
 }
 
-/*
- * 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)
@@ -1782,17 +1760,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;
@@ -1803,42 +1777,8 @@ asmlinkage int vprintk_emit(int facility, int level,
 	printk_delay();
 
 	printk_safe_enter(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(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.
@@ -1881,7 +1821,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(flags);
 
-- 
2.10.2

Re: [RFC][PATCHv5 7/7] printk: remove zap_locks() function

[Petr Mladek]

On Thu 2016-12-01 22:55:46, Sergey Senozhatsky wrote:
> 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>

I like this patch. The code is unused after protecting the section
by printk_safe_enter()/exit(). And also the panic mode is handled
by the commits mentioned above.

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

Best Regards,
Petr

Re: [RFC][PATCHv5 7/7] printk: remove zap_locks() function

[Sergey Senozhatsky]

On (12/12/16 17:37), Petr Mladek wrote:
> On Thu 2016-12-01 22:55:46, Sergey Senozhatsky wrote:
> > 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>
> 
> I like this patch. The code is unused after protecting the section
> by printk_safe_enter()/exit(). And also the panic mode is handled
> by the commits mentioned above.

and the scenario that code tried to address was super-tiny.
basically, a recursion from vscnprintf()/log_output() every 30
seconds (zap_locks() timeout):

	if (unlikely(logbuf_cpu == this_cpu)) {
		zap_locks();
	}

	raw_spin_lock(&logbuf_lock);
	logbuf_cpu = this_cpu;

	text_len = vscnprintf(text, sizeof(textbuf), fmt, args);
	kern_level = printk_get_level(text));
	log_output(facility, level, lflags, dict, dictlen, text, text_len);

	logbuf_cpu = UINT_MAX;
	raw_spin_unlock(&logbuf_lock);

now we cover a much bigger scope.


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

thanks.

	-ss