[RFC][PATCHv2 0/7] printk: use alt_printk to handle printk() recursive calls

[RFC][PATCHv2 0/7] printk: use alt_printk to handle printk() recursive calls

[Sergey Senozhatsky]

Hello,

        RFC

        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.

Deadlock scenarios that alt_printk 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);

[[against next-20160929]]

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 alt_print seq buffer
  printk: make alt_printk available when config printk set
  printk: use alternative printk buffers
  printk: report printk recursion from alt_printk flush
  printk: remove zap_locks() function

 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/{nmi.c => alt_printk.c} | 207 +++++++++++++++++++++++++---------
 kernel/printk/internal.h              |  44 ++++----
 kernel/printk/printk.c                |  92 +++------------
 lib/nmi_backtrace.c                   |   2 +-
 10 files changed, 220 insertions(+), 172 deletions(-)
 rename kernel/printk/{nmi.c => alt_printk.c} (58%)

-- 
2.10.0.372.g6fe1b14

[RFC][PATCHv2 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>
---
 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 8019cc0..c7ffbef 100644
--- a/kernel/printk/printk.c
+++ b/kernel/printk/printk.c
@@ -1922,7 +1922,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.0.372.g6fe1b14

[RFC][PATCHv2 2/7] printk: rename nmi.c and exported api

[Sergey Senozhatsky]

A preparation patch for alt_printk work. No functional change.
- rename nmi.c to alt_print.c
- rename exported functions to have alt_printk prefix.

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 => alt_printk.c} | 61 ++++++++++++++++++-----------------
 lib/nmi_backtrace.c                   |  2 +-
 8 files changed, 52 insertions(+), 49 deletions(-)
 rename kernel/printk/{nmi.c => alt_printk.c} (80%)

diff --git a/include/linux/printk.h b/include/linux/printk.h
index 696a56b..7510613 100644
--- a/include/linux/printk.h
+++ b/include/linux/printk.h
@@ -131,17 +131,17 @@ void early_printk(const char *s, ...) { }
 #endif
 
 #ifdef CONFIG_PRINTK_NMI
-extern void printk_nmi_init(void);
+extern void alt_printk_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 alt_printk_flush(void);
+extern void alt_printk_flush_on_panic(void);
 #else
-static inline void printk_nmi_init(void) { }
+static inline void alt_printk_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 alt_printk_flush(void) { }
+static inline void alt_printk_flush_on_panic(void) { }
 #endif /* PRINTK_NMI */
 
 #ifdef CONFIG_PRINTK
diff --git a/init/Kconfig b/init/Kconfig
index 34407f1..434807f 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 ALT_PRINTK_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 9af9274..3dab03c 100644
--- a/init/main.c
+++ b/init/main.c
@@ -577,7 +577,7 @@ asmlinkage __visible void __init start_kernel(void)
 	timekeeping_init();
 	time_init();
 	sched_clock_postinit();
-	printk_nmi_init();
+	alt_printk_init();
 	perf_event_init();
 	profile_init();
 	call_function_init();
diff --git a/kernel/kexec_core.c b/kernel/kexec_core.c
index a865969..a307fa3 100644
--- a/kernel/kexec_core.c
+++ b/kernel/kexec_core.c
@@ -909,7 +909,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();
+		alt_printk_flush_on_panic();
 		__crash_kexec(regs);
 
 		/*
diff --git a/kernel/panic.c b/kernel/panic.c
index e6480e2..28f97ce 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();
+		alt_printk_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();
+	alt_printk_flush_on_panic();
 	kmsg_dump(KMSG_DUMP_PANIC);
 
 	/*
diff --git a/kernel/printk/Makefile b/kernel/printk/Makefile
index abb0042..3fc5e4e 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)		+= alt_printk.o
 obj-$(CONFIG_A11Y_BRAILLE_CONSOLE)	+= braille.o
diff --git a/kernel/printk/nmi.c b/kernel/printk/alt_printk.c
similarity index 80%
rename from kernel/printk/nmi.c
rename to kernel/printk/alt_printk.c
index 16bab47..7178661 100644
--- a/kernel/printk/nmi.c
+++ b/kernel/printk/alt_printk.c
@@ -1,5 +1,5 @@
 /*
- * nmi.c - Safe printk in NMI context
+ * alt_printk.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 alt_printk_irq_ready;
 atomic_t nmi_message_lost;
 
-#define NMI_LOG_BUF_LEN ((1 << CONFIG_NMI_LOG_BUF_SHIFT) -		\
+#define ALT_LOG_BUF_LEN ((1 << CONFIG_ALT_PRINTK_LOG_BUF_SHIFT) -	\
 			 sizeof(atomic_t) - sizeof(struct irq_work))
 
-struct nmi_seq_buf {
+struct alt_printk_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[ALT_LOG_BUF_LEN];
 };
-static DEFINE_PER_CPU(struct nmi_seq_buf, nmi_print_seq);
+static DEFINE_PER_CPU(struct alt_printk_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 alt_printk_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 && alt_printk_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 alt_printk_flush_line(const char *text, int len)
 {
 	/*
 	 * The buffers are flushed in NMI only on panic.  The messages must
@@ -117,23 +117,24 @@ static void printk_nmi_flush_line(const char *text, int len)
  * printk one line from the temporary buffer from @start index until
  * and including the @end index.
  */
-static void printk_nmi_flush_seq_line(struct nmi_seq_buf *s,
+static void alt_printk_flush_seq_line(struct alt_printk_seq_buf *s,
 					int start, int end)
 {
 	const char *buf = s->buffer + start;
 
-	printk_nmi_flush_line(buf, (end - start) + 1);
+	alt_printk_flush_line(buf, (end - start) + 1);
 }
 
 /*
  * 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 __alt_printk_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 alt_printk_seq_buf *s = container_of(work,
+			struct alt_printk_seq_buf, work);
 	unsigned long flags;
 	size_t len, size;
 	int i, last_i;
@@ -157,9 +158,9 @@ static void __printk_nmi_flush(struct irq_work *work)
 	 * @len must only increase.
 	 */
 	if (i && i >= len) {
-		const char *msg = "printk_nmi_flush: internal error\n";
+		const char *msg = "alt_printk_flush: internal error\n";
 
-		printk_nmi_flush_line(msg, strlen(msg));
+		alt_printk_flush_line(msg, strlen(msg));
 	}
 
 	if (!len)
@@ -174,14 +175,14 @@ static void __printk_nmi_flush(struct irq_work *work)
 	/* Print line by line. */
 	for (; i < size; i++) {
 		if (s->buffer[i] == '\n') {
-			printk_nmi_flush_seq_line(s, last_i, i);
+			alt_printk_flush_seq_line(s, last_i, i);
 			last_i = i + 1;
 		}
 	}
 	/* Check if there was a partial line. */
 	if (last_i < size) {
-		printk_nmi_flush_seq_line(s, last_i, size - 1);
-		printk_nmi_flush_line("\n", strlen("\n"));
+		alt_printk_flush_seq_line(s, last_i, size - 1);
+		alt_printk_flush_line("\n", strlen("\n"));
 	}
 
 	/*
@@ -198,31 +199,31 @@ static void __printk_nmi_flush(struct irq_work *work)
 }
 
 /**
- * printk_nmi_flush - flush all per-cpu nmi buffers.
+ * alt_printk_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 alt_printk_flush(void)
 {
 	int cpu;
 
 	for_each_possible_cpu(cpu)
-		__printk_nmi_flush(&per_cpu(nmi_print_seq, cpu).work);
+		__alt_printk_flush(&per_cpu(nmi_print_seq, cpu).work);
 }
 
 /**
- * printk_nmi_flush_on_panic - flush all per-cpu nmi buffers when the system
+ * alt_printk_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 alt_printk_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 alt_printk_flush_on_panic(void)
 {
 	/*
 	 * Make sure that we could access the main ring buffer.
@@ -236,25 +237,25 @@ void printk_nmi_flush_on_panic(void)
 		raw_spin_lock_init(&logbuf_lock);
 	}
 
-	printk_nmi_flush();
+	alt_printk_flush();
 }
 
-void __init printk_nmi_init(void)
+void __init alt_printk_init(void)
 {
 	int cpu;
 
 	for_each_possible_cpu(cpu) {
-		struct nmi_seq_buf *s = &per_cpu(nmi_print_seq, cpu);
+		struct alt_printk_seq_buf *s = &per_cpu(nmi_print_seq, cpu);
 
-		init_irq_work(&s->work, __printk_nmi_flush);
+		init_irq_work(&s->work, __alt_printk_flush);
 	}
 
 	/* Make sure that IRQ works are initialized before enabling. */
 	smp_wmb();
-	printk_nmi_irq_ready = 1;
+	alt_printk_irq_ready = 1;
 
 	/* Flush pending messages that did not have scheduled IRQ works. */
-	printk_nmi_flush();
+	alt_printk_flush();
 }
 
 void printk_nmi_enter(void)
diff --git a/lib/nmi_backtrace.c b/lib/nmi_backtrace.c
index 7555475..257ab1e 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();
+	alt_printk_flush();
 
 	clear_bit_unlock(0, &backtrace_flag);
 	put_cpu();
-- 
2.10.0.372.g6fe1b14

[RFC][PATCHv2 3/7] printk: introduce per-cpu alt_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()
  local_irq_save()
  alt_printk_enter()
  //
  //  any printk() call from here will endup in vprintk_alt(),
  //  that stores messages in a special per-CPU buffer.
  //
  alt_printk_exit()
  local_irq_restore()

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
alt_printk_enter/exit, thus, just set/celar corresponding bits in
printk-context functions.

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

Signed-off-by: Sergey Senozhatsky <sergey.senozhatsky@gmail.com>
---
 kernel/printk/alt_printk.c | 117 +++++++++++++++++++++++++++++++++++----------
 kernel/printk/internal.h   |  43 ++++++++---------
 kernel/printk/printk.c     |   3 --
 3 files changed, 111 insertions(+), 52 deletions(-)

diff --git a/kernel/printk/alt_printk.c b/kernel/printk/alt_printk.c
index 7178661..4bc1e7d 100644
--- a/kernel/printk/alt_printk.c
+++ b/kernel/printk/alt_printk.c
@@ -1,5 +1,5 @@
 /*
- * alt_printk.c - Safe printk in NMI context
+ * alt_printk.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 @alt_printk_ctx
+ * 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 alt_printk_irq_ready;
 atomic_t nmi_message_lost;
 
@@ -52,25 +52,21 @@ struct alt_printk_seq_buf {
 };
 static DEFINE_PER_CPU(struct alt_printk_seq_buf, nmi_print_seq);
 
-/*
- * 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)
+static DEFINE_PER_CPU(struct alt_printk_seq_buf, alt_print_seq);
+static DEFINE_PER_CPU(int, alt_printk_ctx);
+static DEFINE_PER_CPU(unsigned long, alt_printk_irq_flags);
+
+static int alt_printk_log_store(struct alt_printk_seq_buf *s,
+		const char *fmt, va_list args)
 {
-	struct alt_printk_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);
+	if (len >= sizeof(s->buffer))
 		return 0;
-	}
 
 	/*
 	 * Make sure that all old data have been read before the buffer was
@@ -110,7 +106,6 @@ static void alt_printk_flush_line(const char *text, int len)
 		printk_deferred("%.*s", len, text);
 	else
 		printk("%.*s", len, text);
-
 }
 
 /*
@@ -240,6 +235,83 @@ void alt_printk_flush_on_panic(void)
 	alt_printk_flush();
 }
 
+/*
+ * 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 alt_printk_seq_buf *s = this_cpu_ptr(&nmi_print_seq);
+	int add;
+
+	add = alt_printk_log_store(s, fmt, args);
+	if (!add)
+		atomic_inc(&nmi_message_lost);
+
+	return add;
+}
+
+void printk_nmi_enter(void)
+{
+	this_cpu_or(alt_printk_ctx, ALT_PRINTK_NMI_CONTEXT_MASK);
+}
+
+void printk_nmi_exit(void)
+{
+	this_cpu_and(alt_printk_ctx, ~ALT_PRINTK_NMI_CONTEXT_MASK);
+}
+
+/*
+ * 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_alt(const char *fmt, va_list args)
+{
+	struct alt_printk_seq_buf *s = this_cpu_ptr(&alt_print_seq);
+
+	return alt_printk_log_store(s, fmt, args);
+}
+
+/*
+ * Returns with local IRQs disabled.
+ * Can be preempted by NMI.
+ */
+void alt_printk_enter(void)
+{
+	unsigned long flags;
+	int entry_count;
+
+	local_irq_save(flags);
+	if (!(this_cpu_read(alt_printk_ctx) & ALT_PRINTK_CONTEXT_MASK))
+		this_cpu_write(alt_printk_irq_flags, flags);
+	this_cpu_inc(alt_printk_ctx);
+}
+
+/*
+ * Restores local IRQs state saved in alt_printk_enter().
+ * Can be preempted by NMI.
+ */
+void alt_printk_exit(void)
+{
+	this_cpu_dec(alt_printk_ctx);
+	if (!(this_cpu_read(alt_printk_ctx) & ALT_PRINTK_CONTEXT_MASK))
+		local_irq_restore(this_cpu_read(alt_printk_irq_flags));
+}
+
+__printf(1, 0) int vprintk_func(const char *fmt, va_list args)
+{
+	if (this_cpu_read(alt_printk_ctx) & ALT_PRINTK_NMI_CONTEXT_MASK)
+		return vprintk_nmi(fmt, args);
+
+	if (this_cpu_read(alt_printk_ctx) & ALT_PRINTK_CONTEXT_MASK)
+		return vprintk_alt(fmt, args);
+
+	return vprintk_default(fmt, args);
+}
+
 void __init alt_printk_init(void)
 {
 	int cpu;
@@ -248,6 +320,9 @@ void __init alt_printk_init(void)
 		struct alt_printk_seq_buf *s = &per_cpu(nmi_print_seq, cpu);
 
 		init_irq_work(&s->work, __alt_printk_flush);
+
+		s = &per_cpu(alt_print_seq, cpu);
+		init_irq_work(&s->work, __alt_printk_flush);
 	}
 
 	/* Make sure that IRQ works are initialized before enabling. */
@@ -257,13 +332,3 @@ void __init alt_printk_init(void)
 	/* Flush pending messages that did not have scheduled IRQ works. */
 	alt_printk_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);
-}
diff --git a/kernel/printk/internal.h b/kernel/printk/internal.h
index 7fd2838..6338f5b 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,29 @@ 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 ALT_PRINTK_CONTEXT_MASK		0x07ffffff
+#define ALT_PRINTK_NMI_CONTEXT_MASK	0x08000000
+
+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 alt_printk_enter(void);
+void alt_printk_exit(void);
+
+#else
+
+__printf(1, 0) int vprintk_func(const char *fmt, va_list args) { return 0; }
+void alt_printk_enter(void) { }
+void alt_printk_exit(void) { }
+
+#endif /* CONFIG_PRINTK */
diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
index c7ffbef..ac3d10e 100644
--- a/kernel/printk/printk.c
+++ b/kernel/printk/printk.c
@@ -2029,9 +2029,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
-- 
2.10.0.372.g6fe1b14

Re: [RFC][PATCHv2 3/7] printk: introduce per-cpu alt_print seq buffer

[Sergey Senozhatsky]

On (10/01/16 00:17), Sergey Senozhatsky wrote:
[..]
> +void alt_printk_enter(void)
> +{
> +	unsigned long flags;
-
> +	local_irq_save(flags);
> +	if (!(this_cpu_read(alt_printk_ctx) & ALT_PRINTK_CONTEXT_MASK))
> +		this_cpu_write(alt_printk_irq_flags, flags);
> +	this_cpu_inc(alt_printk_ctx);
> +}
[..]
> +void alt_printk_exit(void)
> +{
> +	this_cpu_dec(alt_printk_ctx);
> +	if (!(this_cpu_read(alt_printk_ctx) & ALT_PRINTK_CONTEXT_MASK))
> +		local_irq_restore(this_cpu_read(alt_printk_irq_flags));
> +}

a few words why did I make it so complex here. it may look that nested
alt_printk_enter()-s are not really possible; but it's not exactly the
case. and the reasons being is that printk exports too many symbols.
basically, the only 'safe' printk variant at the moment is

	printk()
		vprintk_func()

because it 'respects' current printk context... and that's it.
the reset of them will call vprintk_emit() regardless the context.
this patch set fixes (in 0001) vprintk()

	vprintk()
		vprintk_func()

but we still have

EXPORT_SYMBOL(vprintk_emit)
EXPORT_SYMBOL(printk_emit)
EXPORT_SYMBOL_GPL(vprintk_default)

any of those called from alt_printk_log_store() will deadlock us.

 printk()
  vprintk_emit()
   alt_printk_enter()
   raw_spin_lock(&logbuf_lock)
   ...
        printk() 				<< first recursion
         vprintk_alt()
          alt_printk_log_store()
           vprintk_default()
           ---> vprintk_emit()			<< second recursion
                 raw_spin_lock(&logbuf_lock)	<< deadlock
   ...
   alt_printk_exit()



our vprintk_alt()->alt_printk_log_store() seems to be *more or less*
safe, for the time being. there are many WARN_ON_* on
vprintk_alt()->alt_printk_log_store()->vsnprintf() path but they all
seem to be calling printk():

- WARN_ON_ONCE() from vsnprintf()
- WARN_ONCE() from vsnprintf()->format_decode()
- WARN_ON vsnprintf()->set_field_width()
- WARN_ON from vsnprintf()->set_precision()
- WARN_ON from vsnprintf()->pointer()->flags_string()

a side note, some of these WARNs are... 'funny'. e.g., to deadlock a
system it's enough to just pass an unsupported flag in format string.
vsnprintf() will
    WARN_ONCE(1, "Please remove unsupported %%%c in format string\n", *fmt)

but the problem is that we are already in printk():

   printk()
    raw_spin_lock(&logbuf_lock)
    text_len = vscnprintf(text, sizeof(textbuf), fmt, args)
                WARN_ONCE(1, "Please remove unsupported ...)
                 printk()
                  raw_spin_lock(&logbuf_lock)			<< deadlock



with alt_printk enabled we are cool now.

[  175.226161] BUG: recent printk recursion!
[  175.226170] ------------[ cut here ]------------
[  175.226173] WARNING: CPU: 3 PID: 361 at lib/vsprintf.c:1900 format_decode+0x22c/0x308
[  175.226175] Please remove unsupported %{ in format string
[  175.226182] CPU: 3 PID: 361 Comm: bash
[  175.226194] Call Trace:
[  175.226197]  [<ffffffff811efbaf>] dump_stack+0x68/0x92
[  175.226199]  [<ffffffff8103d5e7>] __warn+0xb8/0xd3
[  175.226202]  [<ffffffff8103d648>] warn_slowpath_fmt+0x46/0x4e
[  175.226204]  [<ffffffff811f648d>] format_decode+0x22c/0x308
[  175.226207]  [<ffffffff811f7715>] vsnprintf+0x89/0x481
[  175.226209]  [<ffffffff811f7e92>] vscnprintf+0xd/0x26
[  175.226212]  [<ffffffff81080701>] vprintk_emit+0xcc/0x271
[  175.226214]  [<ffffffff81080a08>] vprintk_default+0x18/0x1a
[  175.226217]  [<ffffffff810819b1>] vprintk_func+0x82/0x89
[  175.226219]  [<ffffffff810c82d0>] printk+0x3e/0x46
[..]
[  175.226244]  [<ffffffff814c1d6a>] entry_SYSCALL_64_fastpath+0x18/0xad
[  175.226249] ---[ end trace ]---



speaking of %p. FORMAT_TYPE_PTR is big and sometimes seem to be platform
dependent. there are tons of things that can go wrong there. for instance:

- vsnprintf()
    pointer()
     symbol_string()
      sprint_backtrace()
       __sprint_symbol()
        kallsyms_lookup()
         get_symbol_pos()
          BUG_ON

- vsnprintf()
   pointer()
    symbol_string()
     sprint_backtrace()
      __sprint_symbol()
       kallsyms_lookup()
        module_address_lookup()
         __module_address()
          BUG_ON

- vsnprintf()
   pointer()
    symbol_string()
     sprint_backtrace()
      __sprint_symbol()
       kallsyms_lookup()
        module_address_lookup()
         module_assert_mutex_or_preempt()
          WARN_ON_ONCE()


and probably even more.

for example, drivers/base/core.c has its own printk() implementation
and calls vprintk_emit() directly
	 return vprintk_emit(0, level, hdrlen ? hdr : NULL, hdrlen, fmt, args)


so as a precautions measure I've decided to enable alt_printk_enter()
nesting. but can drop it.

	-ss

Re: [RFC][PATCHv2 3/7] printk: introduce per-cpu alt_print seq buffer

[Petr Mladek]

On Sat 2016-10-01 11:24:15, Sergey Senozhatsky wrote:
> On (10/01/16 00:17), Sergey Senozhatsky wrote:
> [..]
> > +void alt_printk_enter(void)
> > +{
> > +	unsigned long flags;
> -
> > +	local_irq_save(flags);
> > +	if (!(this_cpu_read(alt_printk_ctx) & ALT_PRINTK_CONTEXT_MASK))
> > +		this_cpu_write(alt_printk_irq_flags, flags);
> > +	this_cpu_inc(alt_printk_ctx);
> > +}
> [..]
> > +void alt_printk_exit(void)
> > +{
> > +	this_cpu_dec(alt_printk_ctx);
> > +	if (!(this_cpu_read(alt_printk_ctx) & ALT_PRINTK_CONTEXT_MASK))
> > +		local_irq_restore(this_cpu_read(alt_printk_irq_flags));
> > +}
> 
> a few words why did I make it so complex here. it may look that nested
> alt_printk_enter()-s are not really possible; but it's not exactly the
> case. and the reasons being is that printk exports too many symbols.
> basically, the only 'safe' printk variant at the moment is
> 
> 	printk()
> 		vprintk_func()
> 
> because it 'respects' current printk context... and that's it.
> the reset of them will call vprintk_emit() regardless the context.
> this patch set fixes (in 0001) vprintk()
> 
> 	vprintk()
> 		vprintk_func()

This is fixed by the 1st patch in this patchset.

> but we still have
> 
> EXPORT_SYMBOL(vprintk_emit)
> EXPORT_SYMBOL(printk_emit)
> EXPORT_SYMBOL_GPL(vprintk_default)

It is a pity. Anyway, there should either be a big fat warning
in a comment about these functions. Or we should check/count
misuses and print a warning later, like we do with lost NMI messages.

Of course, we should revisit the exported status of these functions
and if they might get redirected to a save implementation. But
if anyone wants to shoot herself into her foot, we might hardly
prevent it.


> any of those called from alt_printk_log_store() will deadlock us.
> 
>  printk()
>   vprintk_emit()
>    alt_printk_enter()
>    raw_spin_lock(&logbuf_lock)
>    ...
>         printk() 				<< first recursion
>          vprintk_alt()
>           alt_printk_log_store()
>            vprintk_default()
>            ---> vprintk_emit()			<< second recursion
>                  raw_spin_lock(&logbuf_lock)	<< deadlock
>    ...
>    alt_printk_exit()
>
>
> our vprintk_alt()->alt_printk_log_store() seems to be *more or less*
> safe, for the time being.

I would solve this by a check and warning. People, should know
what they do when using vprintk_default()/emit() directly. If they
use it a wrong way, it is a bug that should get fixed.

As you suggest, alt_printk_log_store() is rather simple functions.
There is not much space for such an adventurous code.


> there are many WARN_ON_* on
> vprintk_alt()->alt_printk_log_store()->vsnprintf() path but they all
> seem to be calling printk():
> 
> - WARN_ON_ONCE() from vsnprintf()
> - WARN_ONCE() from vsnprintf()->format_decode()
> - WARN_ON vsnprintf()->set_field_width()
> - WARN_ON from vsnprintf()->set_precision()
> - WARN_ON from vsnprintf()->pointer()->flags_string()
> 
> a side note, some of these WARNs are... 'funny'. e.g., to deadlock a
> system it's enough to just pass an unsupported flag in format string.
> vsnprintf() will
>     WARN_ONCE(1, "Please remove unsupported %%%c in format string\n", *fmt)
> 
> but the problem is that we are already in printk():
> 
>    printk()
>     raw_spin_lock(&logbuf_lock)
>     text_len = vscnprintf(text, sizeof(textbuf), fmt, args)
>                 WARN_ONCE(1, "Please remove unsupported ...)
>                  printk()
>                   raw_spin_lock(&logbuf_lock)			<< deadlock

Just for record. This vscnprintf() is called when logbuf_cpu is set.
Therefore this particular recursion is not possible at the moment.

Anyway, I agree that alt_printk_enter() calls might get nested.
The direct vprintk_emit() calls are one reason. I guess that
we will need to use the same counter/enter functions also
for WARN_*DEFERRED(). And it would cause nesting as well.

Therefore we need to be careful about loosing the original
value of irq flags.

The question is whether we need to store the flags in
a per-CPU variable. We might also store it on the stack
of the enter()/exit() function caller. I mean something like


void alt_printk_enter(unsigned long *flags)
{
	preempt_disable();
	if (!this_cpu_read(alt_printk_ctx) & ALT_PRINTK_CONTEXT_MASK)
		local_irq_save(*flags);
	preempt_enable();

	this_cpu_inc(alt_printk_ctx);	
}

void alt_printk_exit(unsigned long *flags)
{
	this_cpu_dec(alt_printk_ctx);

	if (!(this_cpu_read(alt_printk_ctx) & ALT_PRINTK_CONTEXT_MASK))
		local_irq_restore(*flags);
}

I am not sure if it is less hairy. But it has some "advantages":

  + saves a per-CPU variable
  + symmetric number of irq_save()/restore() calls
  + the side effect with the irq disabling is more evident

Well, your variant might be less error prone.

Best Regards,
Petr


PS: I am sorry for writing so long answer. It took me some
time to understand why the code should be like this. The
answers helped me to get the picture. I hope that they are
somehow useful for others as well.

Re: [RFC][PATCHv2 3/7] printk: introduce per-cpu alt_print seq buffer

[Sergey Senozhatsky]

On (10/06/16 16:56), Petr Mladek wrote:
[..]
> > there are many WARN_ON_* on
> > vprintk_alt()->alt_printk_log_store()->vsnprintf() path but they all
> > seem to be calling printk():
> > 
> > - WARN_ON_ONCE() from vsnprintf()
> > - WARN_ONCE() from vsnprintf()->format_decode()
> > - WARN_ON vsnprintf()->set_field_width()
> > - WARN_ON from vsnprintf()->set_precision()
> > - WARN_ON from vsnprintf()->pointer()->flags_string()
> > 
> > a side note, some of these WARNs are... 'funny'. e.g., to deadlock a
> > system it's enough to just pass an unsupported flag in format string.
> > vsnprintf() will
> >     WARN_ONCE(1, "Please remove unsupported %%%c in format string\n", *fmt)
> > 
> > but the problem is that we are already in printk():
> > 
> >    printk()
> >     raw_spin_lock(&logbuf_lock)
> >     text_len = vscnprintf(text, sizeof(textbuf), fmt, args)
> >                 WARN_ONCE(1, "Please remove unsupported ...)
> >                  printk()
> >                   raw_spin_lock(&logbuf_lock)			<< deadlock
> 
> Just for record. This vscnprintf() is called when logbuf_cpu is set.
> Therefore this particular recursion is not possible at the moment.

ah, indeed. thanks.

> Anyway, I agree that alt_printk_enter() calls might get nested.
> The direct vprintk_emit() calls are one reason. I guess that
> we will need to use the same counter/enter functions also
> for WARN_*DEFERRED(). And it would cause nesting as well.
> 
> Therefore we need to be careful about loosing the original
> value of irq flags.
> 
> The question is whether we need to store the flags in
> a per-CPU variable. We might also store it on the stack
> of the enter()/exit() function caller. I mean something like

yes, let's keep it on the stack. this particular implementation
was just an experiment, and I hate it. what I currently have in
my tree:

#define alt_printk_enter(flags)                 \
        do {                                    \
                local_irq_save(flags);          \
                __alt_printk_enter();           \
        } while (0)

#define alt_printk_exit(flags)                  \
        do {                                    \
                __alt_printk_exit();            \
                local_irq_restore(flags);       \
        } while (0)

	-ss

Re: [RFC][PATCHv2 3/7] printk: introduce per-cpu alt_print seq buffer

[Petr Mladek]

On Sat 2016-10-08 04:40:15, Sergey Senozhatsky wrote:
> On (10/06/16 16:56), Petr Mladek wrote:
> > The question is whether we need to store the flags in
> > a per-CPU variable. We might also store it on the stack
> > of the enter()/exit() function caller. I mean something like
> 
> yes, let's keep it on the stack. this particular implementation
> was just an experiment, and I hate it. what I currently have in
> my tree:
> 
> #define alt_printk_enter(flags)                 \
>         do {                                    \
>                 local_irq_save(flags);          \
>                 __alt_printk_enter();           \
>         } while (0)
> 
> #define alt_printk_exit(flags)                  \
>         do {                                    \
>                 __alt_printk_exit();            \
>                 local_irq_restore(flags);       \
>         } while (0)

Looks fine to me.

Best Regards,
Petr

Re: [RFC][PATCHv2 3/7] printk: introduce per-cpu alt_print seq buffer

[Petr Mladek]

On Sat 2016-10-01 00:17:54, Sergey Senozhatsky wrote:
> This patch extends the idea of NMI per-cpu buffers to regions
> that may cause recursive printk() calls and possible deadlocks.

> diff --git a/kernel/printk/alt_printk.c b/kernel/printk/alt_printk.c
> index 7178661..4bc1e7d 100644
> --- a/kernel/printk/alt_printk.c
> +++ b/kernel/printk/alt_printk.c
>  	len = atomic_read(&s->len);
>  
> -	if (len >= sizeof(s->buffer)) {
> -		atomic_inc(&nmi_message_lost);
> +	if (len >= sizeof(s->buffer))
>  		return 0;
> -	}
>  
>  	/*
>  	 * Make sure that all old data have been read before the buffer was
> @@ -240,6 +235,83 @@ void alt_printk_flush_on_panic(void)
>  	alt_printk_flush();
>  }
>  
> +/*
> + * 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 alt_printk_seq_buf *s = this_cpu_ptr(&nmi_print_seq);
> +	int add;
> +
> +	add = alt_printk_log_store(s, fmt, args);
> +	if (!add)
> +		atomic_inc(&nmi_message_lost);

This would could also empty string as an error. A solution might be
update alt_printk_log_store() to return -1 in case of lost log.
Note that vprintk_nmi() still needs to return 0 in this case to
stay compatible with printk().

> +
> +	return add;
> +}
> +
> +void printk_nmi_enter(void)
> +{
> +	this_cpu_or(alt_printk_ctx, ALT_PRINTK_NMI_CONTEXT_MASK);
> +}
> +
> +void printk_nmi_exit(void)
> +{
> +	this_cpu_and(alt_printk_ctx, ~ALT_PRINTK_NMI_CONTEXT_MASK);
> +}
> +
> +/*
> + * 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_alt(const char *fmt, va_list args)
> +{
> +	struct alt_printk_seq_buf *s = this_cpu_ptr(&alt_print_seq);
> +
> +	return alt_printk_log_store(s, fmt, args);

We should handle lost strings here as well. But it can be
done in a followup patch.

> +}
> +
> +/*
> + * Returns with local IRQs disabled.
> + * Can be preempted by NMI.
> + */
> +void alt_printk_enter(void)
> +{
> +	unsigned long flags;
> +	int entry_count;
> +
> +	local_irq_save(flags);
> +	if (!(this_cpu_read(alt_printk_ctx) & ALT_PRINTK_CONTEXT_MASK))
> +		this_cpu_write(alt_printk_irq_flags, flags);
> +	this_cpu_inc(alt_printk_ctx);
> +}
> +
> +/*
> + * Restores local IRQs state saved in alt_printk_enter().
> + * Can be preempted by NMI.
> + */
> +void alt_printk_exit(void)
> +{
> +	this_cpu_dec(alt_printk_ctx);
> +	if (!(this_cpu_read(alt_printk_ctx) & ALT_PRINTK_CONTEXT_MASK))
> +		local_irq_restore(this_cpu_read(alt_printk_irq_flags));
> +}

I will discuss this in your replay that explains the details.

Anyway, it looks much easier now.

Best Regards,
Petr

Re: [RFC][PATCHv2 3/7] printk: introduce per-cpu alt_print seq buffer

[Sergey Senozhatsky]

On (10/06/16 15:08), Petr Mladek wrote:
[..]
> > +static int vprintk_nmi(const char *fmt, va_list args)
> > +{
> > +	struct alt_printk_seq_buf *s = this_cpu_ptr(&nmi_print_seq);
> > +	int add;
> > +
> > +	add = alt_printk_log_store(s, fmt, args);
> > +	if (!add)
> > +		atomic_inc(&nmi_message_lost);
> 
> This would could also empty string as an error. A solution might be
> update alt_printk_log_store() to return -1 in case of lost log.
> Note that vprintk_nmi() still needs to return 0 in this case to
> stay compatible with printk().

will do.

> > +static int vprintk_alt(const char *fmt, va_list args)
> > +{
> > +	struct alt_printk_seq_buf *s = this_cpu_ptr(&alt_print_seq);
> > +
> > +	return alt_printk_log_store(s, fmt, args);
> 
> We should handle lost strings here as well. But it can be
> done in a followup patch.

ok, will do.

	-ss

[RFC][PATCHv2 4/7] printk: make alt_printk available when config printk set

[Sergey Senozhatsky]

alt_printk must be enabled on systems that have CONFIG_PRINTK set,
while NMI related functions must depend on CONFIG_PRINTK_NMI.

Signed-off-by: Sergey Senozhatsky <sergey.senozhatsky@gmail.com>
---
 include/linux/printk.h     | 21 +++++++++++++++------
 kernel/printk/Makefile     |  2 +-
 kernel/printk/alt_printk.c | 30 +++++++++++++++++++++++++-----
 3 files changed, 41 insertions(+), 12 deletions(-)

diff --git a/include/linux/printk.h b/include/linux/printk.h
index 7510613..068a124 100644
--- a/include/linux/printk.h
+++ b/include/linux/printk.h
@@ -131,17 +131,11 @@ void early_printk(const char *s, ...) { }
 #endif
 
 #ifdef CONFIG_PRINTK_NMI
-extern void alt_printk_init(void);
 extern void printk_nmi_enter(void);
 extern void printk_nmi_exit(void);
-extern void alt_printk_flush(void);
-extern void alt_printk_flush_on_panic(void);
 #else
-static inline void alt_printk_init(void) { }
 static inline void printk_nmi_enter(void) { }
 static inline void printk_nmi_exit(void) { }
-static inline void alt_printk_flush(void) { }
-static inline void alt_printk_flush_on_panic(void) { }
 #endif /* PRINTK_NMI */
 
 #ifdef CONFIG_PRINTK
@@ -193,6 +187,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 alt_printk_init(void);
+extern void alt_printk_flush(void);
+extern void alt_printk_flush_on_panic(void);
 #else
 static inline __printf(1, 0)
 int vprintk(const char *s, va_list args)
@@ -252,6 +249,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 alt_printk_init(void)
+{
+}
+
+static inline void alt_printk_flush(void)
+{
+}
+
+static inline void alt_printk_flush_on_panic(void)
+{
+}
 #endif
 
 extern asmlinkage void dump_stack(void) __cold;
diff --git a/kernel/printk/Makefile b/kernel/printk/Makefile
index 3fc5e4e..d11838c 100644
--- a/kernel/printk/Makefile
+++ b/kernel/printk/Makefile
@@ -1,3 +1,3 @@
 obj-y	= printk.o
-obj-$(CONFIG_PRINTK_NMI)		+= alt_printk.o
+obj-$(CONFIG_PRINTK)		+= alt_printk.o
 obj-$(CONFIG_A11Y_BRAILLE_CONSOLE)	+= braille.o
diff --git a/kernel/printk/alt_printk.c b/kernel/printk/alt_printk.c
index 4bc1e7d..db0bfc8 100644
--- a/kernel/printk/alt_printk.c
+++ b/kernel/printk/alt_printk.c
@@ -40,7 +40,6 @@
  * were handled or when IRQs are blocked.
  */
 static int alt_printk_irq_ready;
-atomic_t nmi_message_lost;
 
 #define ALT_LOG_BUF_LEN ((1 << CONFIG_ALT_PRINTK_LOG_BUF_SHIFT) -	\
 			 sizeof(atomic_t) - sizeof(struct irq_work))
@@ -50,12 +49,16 @@ struct alt_printk_seq_buf {
 	struct irq_work		work;	/* IRQ work that flushes the buffer */
 	unsigned char		buffer[ALT_LOG_BUF_LEN];
 };
-static DEFINE_PER_CPU(struct alt_printk_seq_buf, nmi_print_seq);
 
 static DEFINE_PER_CPU(struct alt_printk_seq_buf, alt_print_seq);
 static DEFINE_PER_CPU(int, alt_printk_ctx);
 static DEFINE_PER_CPU(unsigned long, alt_printk_irq_flags);
 
+#ifdef CONFIG_PRINTK_NMI
+static DEFINE_PER_CPU(struct alt_printk_seq_buf, nmi_print_seq);
+atomic_t nmi_message_lost;
+#endif
+
 static int alt_printk_log_store(struct alt_printk_seq_buf *s,
 		const char *fmt, va_list args)
 {
@@ -204,8 +207,12 @@ void alt_printk_flush(void)
 {
 	int cpu;
 
-	for_each_possible_cpu(cpu)
+	for_each_possible_cpu(cpu) {
+#ifdef CONFIG_PRINTK_NMI
 		__alt_printk_flush(&per_cpu(nmi_print_seq, cpu).work);
+#endif
+		__alt_printk_flush(&per_cpu(alt_print_seq, cpu).work);
+	}
 }
 
 /**
@@ -235,6 +242,8 @@ void alt_printk_flush_on_panic(void)
 	alt_printk_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
@@ -263,6 +272,15 @@ void printk_nmi_exit(void)
 	this_cpu_and(alt_printk_ctx, ~ALT_PRINTK_NMI_CONTEXT_MASK);
 }
 
+#else
+
+static int vprintk_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
@@ -317,12 +335,14 @@ void __init alt_printk_init(void)
 	int cpu;
 
 	for_each_possible_cpu(cpu) {
-		struct alt_printk_seq_buf *s = &per_cpu(nmi_print_seq, cpu);
+		struct alt_printk_seq_buf *s = &per_cpu(alt_print_seq, cpu);
 
 		init_irq_work(&s->work, __alt_printk_flush);
 
-		s = &per_cpu(alt_print_seq, cpu);
+#ifdef CONFIG_PRINTK_NMI
+		s = &per_cpu(nmi_print_seq, cpu);
 		init_irq_work(&s->work, __alt_printk_flush);
+#endif
 	}
 
 	/* Make sure that IRQ works are initialized before enabling. */
-- 
2.10.0.372.g6fe1b14

Re: [RFC][PATCHv2 4/7] printk: make alt_printk available when config printk set

[Petr Mladek]

On Sat 2016-10-01 00:17:55, Sergey Senozhatsky wrote:
> alt_printk must be enabled on systems that have CONFIG_PRINTK set,
> while NMI related functions must depend on CONFIG_PRINTK_NMI.
>
> Signed-off-by: Sergey Senozhatsky <sergey.senozhatsky@gmail.com>
> ---
>  include/linux/printk.h     | 21 +++++++++++++++------
>  kernel/printk/Makefile     |  2 +-
>  kernel/printk/alt_printk.c | 30 +++++++++++++++++++++++++-----
>  3 files changed, 41 insertions(+), 12 deletions(-)
> 
> diff --git a/include/linux/printk.h b/include/linux/printk.h
> index 7510613..068a124 100644
> --- a/include/linux/printk.h
> +++ b/include/linux/printk.h
> @@ -131,17 +131,11 @@ void early_printk(const char *s, ...) { }
>  #endif
>  
>  #ifdef CONFIG_PRINTK_NMI
> -extern void alt_printk_init(void);
>  extern void printk_nmi_enter(void);
>  extern void printk_nmi_exit(void);
> -extern void alt_printk_flush(void);
> -extern void alt_printk_flush_on_panic(void);
>  #else
> -static inline void alt_printk_init(void) { }
>  static inline void printk_nmi_enter(void) { }
>  static inline void printk_nmi_exit(void) { }
> -static inline void alt_printk_flush(void) { }
> -static inline void alt_printk_flush_on_panic(void) { }
>  #endif /* PRINTK_NMI */
>  
>  #ifdef CONFIG_PRINTK
> @@ -193,6 +187,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 alt_printk_init(void);
> +extern void alt_printk_flush(void);
> +extern void alt_printk_flush_on_panic(void);
>  #else
>  static inline __printf(1, 0)
>  int vprintk(const char *s, va_list args)
> @@ -252,6 +249,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 alt_printk_init(void)
> +{
> +}
> +
> +static inline void alt_printk_flush(void)
> +{
> +}
> +
> +static inline void alt_printk_flush_on_panic(void)
> +{
> +}
>  #endif
>  
>  extern asmlinkage void dump_stack(void) __cold;
> diff --git a/kernel/printk/Makefile b/kernel/printk/Makefile
> index 3fc5e4e..d11838c 100644
> --- a/kernel/printk/Makefile
> +++ b/kernel/printk/Makefile
> @@ -1,3 +1,3 @@
>  obj-y	= printk.o
> -obj-$(CONFIG_PRINTK_NMI)		+= alt_printk.o
> +obj-$(CONFIG_PRINTK)		+= alt_printk.o
>  obj-$(CONFIG_A11Y_BRAILLE_CONSOLE)	+= braille.o
> diff --git a/kernel/printk/alt_printk.c b/kernel/printk/alt_printk.c
> index 4bc1e7d..db0bfc8 100644
> --- a/kernel/printk/alt_printk.c
> +++ b/kernel/printk/alt_printk.c
> @@ -40,7 +40,6 @@
>   * were handled or when IRQs are blocked.
>   */
>  static int alt_printk_irq_ready;
> -atomic_t nmi_message_lost;
>  
>  #define ALT_LOG_BUF_LEN ((1 << CONFIG_ALT_PRINTK_LOG_BUF_SHIFT) -	\
>  			 sizeof(atomic_t) - sizeof(struct irq_work))
> @@ -50,12 +49,16 @@ struct alt_printk_seq_buf {
>  	struct irq_work		work;	/* IRQ work that flushes the buffer */
>  	unsigned char		buffer[ALT_LOG_BUF_LEN];
>  };
> -static DEFINE_PER_CPU(struct alt_printk_seq_buf, nmi_print_seq);
>  
>  static DEFINE_PER_CPU(struct alt_printk_seq_buf, alt_print_seq);
>  static DEFINE_PER_CPU(int, alt_printk_ctx);
>  static DEFINE_PER_CPU(unsigned long, alt_printk_irq_flags);
>  
> +#ifdef CONFIG_PRINTK_NMI
> +static DEFINE_PER_CPU(struct alt_printk_seq_buf, nmi_print_seq);
> +atomic_t nmi_message_lost;
> +#endif
> +
>  static int alt_printk_log_store(struct alt_printk_seq_buf *s,
>  		const char *fmt, va_list args)
>  {
> @@ -204,8 +207,12 @@ void alt_printk_flush(void)
>  {
>  	int cpu;
>  
> -	for_each_possible_cpu(cpu)
> +	for_each_possible_cpu(cpu) {
> +#ifdef CONFIG_PRINTK_NMI
>  		__alt_printk_flush(&per_cpu(nmi_print_seq, cpu).work);
> +#endif
> +		__alt_printk_flush(&per_cpu(alt_print_seq, cpu).work);

This line should be added already in the 3rd patch.

> +	}
>  }
>  
>  /**
> @@ -235,6 +242,8 @@ void alt_printk_flush_on_panic(void)
>  	alt_printk_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
> @@ -263,6 +272,15 @@ void printk_nmi_exit(void)
>  	this_cpu_and(alt_printk_ctx, ~ALT_PRINTK_NMI_CONTEXT_MASK);
>  }
>  
> +#else
> +
> +static int vprintk_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
> @@ -317,12 +335,14 @@ void __init alt_printk_init(void)
>  	int cpu;
>  
>  	for_each_possible_cpu(cpu) {
> -		struct alt_printk_seq_buf *s = &per_cpu(nmi_print_seq, cpu);
> +		struct alt_printk_seq_buf *s = &per_cpu(alt_print_seq, cpu);
>  
>  		init_irq_work(&s->work, __alt_printk_flush);
>  
> -		s = &per_cpu(alt_print_seq, cpu);
> +#ifdef CONFIG_PRINTK_NMI
> +		s = &per_cpu(nmi_print_seq, cpu);
>  		init_irq_work(&s->work, __alt_printk_flush);
> +#endif

Also the initialization of both irq works should be done already
in the 3rd patch.


BTW: I have tried to simulate the compilation on an architecture
without NMI (commented out HAVE_NMI in arch/x86/Kconfig
and I have got the following build error with the first three
patches only:

  LD      init/built-in.o
kernel/built-in.o: In function `vprintk':
/prace/kernel/linux/kernel/printk/printk.c:1914: undefined reference to `vprintk_func'
kernel/built-in.o: In function `printk':
/prace/kernel/linux/kernel/printk/printk.c:1976: undefined reference to `vprintk_func'
Makefile:949: recipe for target 'vmlinux' failed


Where the two lines are in:

asmlinkage int vprintk(const char *fmt, va_list args)
{
	return vprintk_func(fmt, args);
}

and

asmlinkage __visible int printk(const char *fmt, ...)
{
	va_list args;
	int r;

	va_start(args, fmt);
	r = vprintk_func(fmt, args);
	va_end(args);

	return r;
}


I know that it is a pain to make it all correctly. I suffered from headaches
when preparing the WARN_*DEFERRED() patchset :-)


Best Regards,
Petr

Re: [RFC][PATCHv2 4/7] printk: make alt_printk available when config printk set

[Sergey Senozhatsky]

On (10/06/16 17:23), Petr Mladek wrote:
> This line should be added already in the 3rd patch.
[..]
> Also the initialization of both irq works should be done already
> in the 3rd patch.

indeed. my bad. thanks.

> BTW: I have tried to simulate the compilation on an architecture
> without NMI (commented out HAVE_NMI in arch/x86/Kconfig
> and I have got the following build error with the first three
> patches only:
> 
>   LD      init/built-in.o
> kernel/built-in.o: In function `vprintk':
> /prace/kernel/linux/kernel/printk/printk.c:1914: undefined reference to `vprintk_func'
> kernel/built-in.o: In function `printk':
> /prace/kernel/linux/kernel/printk/printk.c:1976: undefined reference to `vprintk_func'
> Makefile:949: recipe for target 'vmlinux' failed

Fengguang Wu reported a build error for V1 on some .configs, I thought it
was fixed in V2.

thanks a lot!

	-ss

> Where the two lines are in:
> 
> asmlinkage int vprintk(const char *fmt, va_list args)
> {
> 	return vprintk_func(fmt, args);
> }
> 
> and
> 
> asmlinkage __visible int printk(const char *fmt, ...)
> {
> 	va_list args;
> 	int r;
> 
> 	va_start(args, fmt);
> 	r = vprintk_func(fmt, args);
> 	va_end(args);
> 
> 	return r;
> }
> 
> 
> I know that it is a pain to make it all correctly. I suffered from headaches
> when preparing the WARN_*DEFERRED() patchset :-)

[RFC][PATCHv2 5/7] printk: use alternative printk buffers

[Sergey Senozhatsky]

Use alt_printk buffer in 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.

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:
  [<ffffffff811e24d9>] dump_stack+0x68/0x92
  [<ffffffff810455cd>] __warn+0xc2/0xdd
  [<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:
  [<ffffffff811e24e0>] dump_stack+0x68/0x92
  [<ffffffff810455cd>] __warn+0xc2/0xdd
  [<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:
  [<ffffffff811f2380>] dump_stack+0x68/0x92
  [<ffffffff8103d649>] __warn+0xb8/0xd3
  [<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:
  [<ffffffff811e2557>] dump_stack+0x68/0x92
  [<ffffffff810455cd>] __warn+0xc2/0xdd
  [<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 ]---

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

diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
index ac3d10e..b99d6b3 100644
--- a/kernel/printk/printk.c
+++ b/kernel/printk/printk.c
@@ -1791,7 +1791,7 @@ asmlinkage int vprintk_emit(int facility, int level,
 		zap_locks();
 	}
 
-	lockdep_off();
+	alt_printk_enter();
 	/* This stops the holder of console_sem just where we want him */
 	raw_spin_lock(&logbuf_lock);
 	logbuf_cpu = this_cpu;
@@ -1900,12 +1900,11 @@ asmlinkage int vprintk_emit(int facility, int level,
 
 	logbuf_cpu = UINT_MAX;
 	raw_spin_unlock(&logbuf_lock);
-	lockdep_on();
+	alt_printk_exit();
 	local_irq_restore(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
@@ -1913,7 +1912,6 @@ asmlinkage int vprintk_emit(int facility, int level,
 		 */
 		if (console_trylock())
 			console_unlock();
-		lockdep_on();
 	}
 
 	return printed_len;
@@ -2236,8 +2234,15 @@ EXPORT_SYMBOL(console_lock);
  */
 int console_trylock(void)
 {
-	if (down_trylock_console_sem())
+	int lock_failed;
+
+	alt_printk_enter();
+	lock_failed = down_trylock_console_sem();
+	alt_printk_exit();
+
+	if (lock_failed)
 		return 0;
+
 	if (console_suspended) {
 		up_console_sem();
 		return 0;
@@ -2392,7 +2397,9 @@ void console_unlock(void)
 		size_t len;
 		int level;
 
-		raw_spin_lock_irqsave(&logbuf_lock, flags);
+		local_irq_save(flags);
+		alt_printk_enter();
+		raw_spin_lock(&logbuf_lock);
 		if (seen_seq != log_next_seq) {
 			wake_klogd = true;
 			seen_seq = log_next_seq;
@@ -2453,6 +2460,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();
+		alt_printk_exit();
 		local_irq_restore(flags);
 
 		if (do_cond_resched)
@@ -2476,7 +2484,9 @@ 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);
+	alt_printk_exit();
+	local_irq_restore(flags);
 
 	if (retry && console_trylock())
 		goto again;
-- 
2.10.0.372.g6fe1b14

[RFC][PATCHv2 6/7] printk: report printk recursion from alt_printk flush

[Sergey Senozhatsky]

If we end up executing vprintk_alt() then we have a printk
recursion. Set alt_printk_ctx `ALT_PRINTK_RECURSION_MASK' bit
in vprintk_alt() to indicate that recutsion and report the
"BUG: recent printk recursion!" problem later from
__alt_printk_flush().

Example:

 BUG: recent printk recursion!
 ------------[ cut here ]------------
 WARNING: CPU: 3 PID: 366 at kernel/printk/printk.c:1803 vprintk_emit+0x139/0x38c
 CPU: 3 PID: 366 Comm: bash
 Call Trace:
  [<ffffffff811be508>] dump_stack+0x4d/0x63
  [<ffffffff81039932>] __warn+0xb8/0xd3
  [<ffffffff810399b3>] warn_slowpath_null+0x18/0x1a
  [<ffffffff8106bfdb>] vprintk_emit+0x139/0x38c
  [<ffffffff8106c390>] vprintk_default+0x18/0x1a
  [<ffffffff8106d1e6>] vprintk_func+0x65/0x67
  [<ffffffff810ab27f>] printk+0x3e/0x46
[..]
  [<ffffffff8145fb60>] entry_SYSCALL_64_fastpath+0x13/0x94
  ---[ end trace ]---

Signed-off-by: Sergey Senozhatsky <sergey.senozhatsky@gmail.com>
---
 kernel/printk/alt_printk.c | 9 +++++++++
 kernel/printk/internal.h   | 1 +
 2 files changed, 10 insertions(+)

diff --git a/kernel/printk/alt_printk.c b/kernel/printk/alt_printk.c
index db0bfc8..0010089 100644
--- a/kernel/printk/alt_printk.c
+++ b/kernel/printk/alt_printk.c
@@ -150,6 +150,13 @@ static void __alt_printk_flush(struct irq_work *work)
 more:
 	len = atomic_read(&s->len);
 
+	if (this_cpu_read(alt_printk_ctx) & ALT_PRINTK_RECURSION_MASK) {
+		const char *msg = "BUG: recent printk recursion!\n";
+
+		this_cpu_and(alt_printk_ctx, ~ALT_PRINTK_RECURSION_MASK);
+		alt_printk_flush_line(msg, strlen(msg));
+	}
+
 	/*
 	 * This is just a paranoid check that nobody has manipulated
 	 * the buffer an unexpected way. If we printed something then
@@ -290,6 +297,8 @@ static int vprintk_alt(const char *fmt, va_list args)
 {
 	struct alt_printk_seq_buf *s = this_cpu_ptr(&alt_print_seq);
 
+	/* There is only one way to get here -- a printk recursion. */
+	this_cpu_or(alt_printk_ctx, ALT_PRINTK_RECURSION_MASK);
 	return alt_printk_log_store(s, fmt, args);
 }
 
diff --git a/kernel/printk/internal.h b/kernel/printk/internal.h
index 6338f5b..403b6ed 100644
--- a/kernel/printk/internal.h
+++ b/kernel/printk/internal.h
@@ -37,6 +37,7 @@ static inline int get_nmi_message_lost(void)
 
 #define ALT_PRINTK_CONTEXT_MASK		0x07ffffff
 #define ALT_PRINTK_NMI_CONTEXT_MASK	0x08000000
+#define ALT_PRINTK_RECURSION_MASK	0x10000000
 
 extern raw_spinlock_t logbuf_lock;
 
-- 
2.10.0.372.g6fe1b14

Re: [RFC][PATCHv2 6/7] printk: report printk recursion from alt_printk flush

[Petr Mladek]

On Sat 2016-10-01 00:17:57, Sergey Senozhatsky wrote:
> If we end up executing vprintk_alt() then we have a printk
> recursion. Set alt_printk_ctx `ALT_PRINTK_RECURSION_MASK' bit
> in vprintk_alt() to indicate that recutsion and report the
> "BUG: recent printk recursion!" problem later from
> __alt_printk_flush().
> 
> Example:
> 
>  BUG: recent printk recursion!
>  ------------[ cut here ]------------
>  WARNING: CPU: 3 PID: 366 at kernel/printk/printk.c:1803 vprintk_emit+0x139/0x38c
>  CPU: 3 PID: 366 Comm: bash
>  Call Trace:
>   [<ffffffff811be508>] dump_stack+0x4d/0x63
>   [<ffffffff81039932>] __warn+0xb8/0xd3
>   [<ffffffff810399b3>] warn_slowpath_null+0x18/0x1a
>   [<ffffffff8106bfdb>] vprintk_emit+0x139/0x38c
>   [<ffffffff8106c390>] vprintk_default+0x18/0x1a
>   [<ffffffff8106d1e6>] vprintk_func+0x65/0x67
>   [<ffffffff810ab27f>] printk+0x3e/0x46
> [..]
>   [<ffffffff8145fb60>] entry_SYSCALL_64_fastpath+0x13/0x94
>   ---[ end trace ]---
> 
> Signed-off-by: Sergey Senozhatsky <sergey.senozhatsky@gmail.com>
> ---
>  kernel/printk/alt_printk.c | 9 +++++++++
>  kernel/printk/internal.h   | 1 +
>  2 files changed, 10 insertions(+)
> 
> diff --git a/kernel/printk/alt_printk.c b/kernel/printk/alt_printk.c
> index db0bfc8..0010089 100644
> --- a/kernel/printk/alt_printk.c
> +++ b/kernel/printk/alt_printk.c
> @@ -150,6 +150,13 @@ static void __alt_printk_flush(struct irq_work *work)
>  more:
>  	len = atomic_read(&s->len);
>  
> +	if (this_cpu_read(alt_printk_ctx) & ALT_PRINTK_RECURSION_MASK) {
> +		const char *msg = "BUG: recent printk recursion!\n";
> +
> +		this_cpu_and(alt_printk_ctx, ~ALT_PRINTK_RECURSION_MASK);
> +		alt_printk_flush_line(msg, strlen(msg));
> +	}
> +
>  	/*
>  	 * This is just a paranoid check that nobody has manipulated
>  	 * the buffer an unexpected way. If we printed something then
> @@ -290,6 +297,8 @@ static int vprintk_alt(const char *fmt, va_list args)
>  {
>  	struct alt_printk_seq_buf *s = this_cpu_ptr(&alt_print_seq);
>  
> +	/* There is only one way to get here -- a printk recursion. */
> +	this_cpu_or(alt_printk_ctx, ALT_PRINTK_RECURSION_MASK);

Is it really a bug? In most cases, the message that is being printed
describes a bug. We just allow to print it this alternative way to
avoid a possible deadlock. IMHO, this might cause a confusion.

Instead I would print an error when we missed some messages
because the alternative buffer was not big enough.

Best Regards,
Petr

Re: [RFC][PATCHv2 6/7] printk: report printk recursion from alt_printk flush

[Sergey Senozhatsky]

On (10/06/16 17:41), Petr Mladek wrote:
[..]
> > +	if (this_cpu_read(alt_printk_ctx) & ALT_PRINTK_RECURSION_MASK) {
> > +		const char *msg = "BUG: recent printk recursion!\n";
> > +
> > +		this_cpu_and(alt_printk_ctx, ~ALT_PRINTK_RECURSION_MASK);
> > +		alt_printk_flush_line(msg, strlen(msg));
> > +	}
> > +
> >  	/*
> >  	 * This is just a paranoid check that nobody has manipulated
> >  	 * the buffer an unexpected way. If we printed something then
> > @@ -290,6 +297,8 @@ static int vprintk_alt(const char *fmt, va_list args)
> >  {
> >  	struct alt_printk_seq_buf *s = this_cpu_ptr(&alt_print_seq);
> >  
> > +	/* There is only one way to get here -- a printk recursion. */
> > +	this_cpu_or(alt_printk_ctx, ALT_PRINTK_RECURSION_MASK);
> 
> Is it really a bug? In most cases, the message that is being printed
> describes a bug. We just allow to print it this alternative way to
> avoid a possible deadlock. IMHO, this might cause a confusion.

just wanted to preserve the existing behavior, but can drop it.

> Instead I would print an error when we missed some messages
> because the alternative buffer was not big enough.

ok, will do.

	-ss

Re: [RFC][PATCHv2 6/7] printk: report printk recursion from alt_printk flush

[Petr Mladek]

On Sat 2016-10-08 03:59:20, Sergey Senozhatsky wrote:
> On (10/06/16 17:41), Petr Mladek wrote:
> [..]
> > > +	if (this_cpu_read(alt_printk_ctx) & ALT_PRINTK_RECURSION_MASK) {
> > > +		const char *msg = "BUG: recent printk recursion!\n";
> > > +
> > > +		this_cpu_and(alt_printk_ctx, ~ALT_PRINTK_RECURSION_MASK);
> > > +		alt_printk_flush_line(msg, strlen(msg));
> > > +	}
> > > +
> > >  	/*
> > >  	 * This is just a paranoid check that nobody has manipulated
> > >  	 * the buffer an unexpected way. If we printed something then
> > > @@ -290,6 +297,8 @@ static int vprintk_alt(const char *fmt, va_list args)
> > >  {
> > >  	struct alt_printk_seq_buf *s = this_cpu_ptr(&alt_print_seq);
> > >  
> > > +	/* There is only one way to get here -- a printk recursion. */
> > > +	this_cpu_or(alt_printk_ctx, ALT_PRINTK_RECURSION_MASK);
> > 
> > Is it really a bug? In most cases, the message that is being printed
> > describes a bug. We just allow to print it this alternative way to
> > avoid a possible deadlock. IMHO, this might cause a confusion.
> 
> just wanted to preserve the existing behavior, but can drop it.

I see. Well, the current code drops the original message if there is a
recursion and there is no oops_in_progress. Therefore the warning
is the only way to know that a message was lost. But we store
the original message in the alternative buffer now. Therefore
it is not longer lost.

Best Regards,
Petr

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

[Sergey Senozhatsky]

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

1) Since 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 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. May be we
still would want to do sema_init() in alt_printk_flush_on_panic(), just
in case.

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

diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
index b99d6b3..fb2d26b 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)
@@ -1748,18 +1726,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;
 	int nmi_message_lost;
 	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;
@@ -1769,43 +1742,9 @@ asmlinkage int vprintk_emit(int facility, int level,
 	boot_delay_msec(level);
 	printk_delay();
 
-	local_irq_save(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;
-			local_irq_restore(flags);
-			return 0;
-		}
-		zap_locks();
-	}
-
 	alt_printk_enter();
 	/* 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));
-	}
 
 	nmi_message_lost = get_nmi_message_lost();
 	if (unlikely(nmi_message_lost)) {
@@ -1898,10 +1837,8 @@ asmlinkage int vprintk_emit(int facility, int level,
 						 dict, dictlen, text, text_len);
 	}
 
-	logbuf_cpu = UINT_MAX;
 	raw_spin_unlock(&logbuf_lock);
 	alt_printk_exit();
-	local_irq_restore(flags);
 
 	/* If called from the scheduler, we can not call up(). */
 	if (!in_sched) {
-- 
2.10.0.372.g6fe1b14

Re: [RFC][PATCHv2 0/7] printk: use alt_printk to handle printk() recursive calls

[Petr Mladek]

On Sat 2016-10-01 00:17:51, Sergey Senozhatsky wrote:
> Hello,
> 
>         RFC
> 
>         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.

OK, I think again that this patch set makes sense. It looks good after
all my doubts ;-)

Just I would like you to consider using some more meaningful name
instead of the "alt" prefix. I wonder how the following prefix
would look like:

	printk_safe*
	printk_safe_nmi*

I am not sure. It is possible that I am also confused that
you used prefix rather than a suffix. I was actually forced
to rename many new functions in the kthread worker API (my other
pet project) to start with the name of the subsystem (kthread
in this case).

Also "alt_printk_ctx" per-CPU variable describes a global
printk state. I think that the alt_ prefix is not needed
and "printk_context" would be better readable.

Thanks for patience with me.

Best Regards,
Petr

Re: [RFC][PATCHv2 0/7] printk: use alt_printk to handle printk() recursive calls

[Sergey Senozhatsky]

On (10/06/16 17:55), Petr Mladek wrote:
> On Sat 2016-10-01 00:17:51, Sergey Senozhatsky wrote:
> > Hello,
> > 
> >         RFC
> > 
> >         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.
> 
> OK, I think again that this patch set makes sense. It looks good after
> all my doubts ;-)
> 
> Just I would like you to consider using some more meaningful name
> instead of the "alt" prefix. I wonder how the following prefix
> would look like:
> 
> 	printk_safe*
> 	printk_safe_nmi*

sure. I want to rename it. not entirely sure that printk_safe_enter()
is the best option here, but I can't think of anything better.

> prefix rather than a suffix.

good point. will change to 'suffix'.

> Also "alt_printk_ctx" per-CPU variable describes a global
> printk state. I think that the alt_ prefix is not needed
> and "printk_context" would be better readable.

yep, will do. thanks.

	-ss