Groups | Search | Server Info | Keyboard shortcuts | Login | Register [http] [https] [nntp] [nntps]

Groups > linux.kernel > #1384116 > unrolled thread

[PATCH v5 4/4] printk/nmi: flush NMI messages on the system panic

Back to article view | Back to linux.kernel

This discussion starts older than the indexed window; earlier articles aren't shown. The article labeled Started by below is the oldest one visible, not the original post.

Contents

  [PATCH v5 4/4] printk/nmi: flush NMI messages on the system panic Petr Mladek <pmladek@suse.com> - 2016-04-21 13:50 +0200
    Re: [PATCH v5 4/4] printk/nmi: flush NMI messages on the system panic Sergey Senozhatsky <sergey.senozhatsky.work@gmail.com> - 2016-04-23 05:50 +0200
      Re: [PATCH v5 4/4] printk/nmi: flush NMI messages on the system panic Petr Mladek <pmladek@suse.com> - 2016-04-26 16:30 +0200
        Re: [PATCH v5 4/4] printk/nmi: flush NMI messages on the system panic Sergey Senozhatsky <sergey.senozhatsky.work@gmail.com> - 2016-04-27 02:40 +0200

#1384116 — [PATCH v5 4/4] printk/nmi: flush NMI messages on the system panic

In NMI context, printk() messages are stored into per-CPU buffers to avoid
a possible deadlock.  They are normally flushed to the main ring buffer via
an IRQ work.  But the work is never called when the system calls panic() in
the very same NMI handler.

This patch tries to flush NMI buffers before the crash dump is generated.
In this case it does not risk a double release and bails out when the
logbuf_lock is already taken.  The aim is to get the messages into the main
ring buffer when possible.  It makes them better accessible in the vmcore.

Then the patch tries to flush the buffers second time when other CPUs are
down.  It might be more aggressive and reset logbuf_lock. The aim is to
get the messages available for the consequent kmsg_dump() and
console_flush_on_panic() calls.

The patch causes vprintk_emit() to be called even in NMI context again. But
it is done via printk_deferred() so that the console handling is skipped.
Consoles use internal locks and we could not prevent a deadlock easily.
They are explicitly called later when the crash dump is not generated, see
console_flush_on_panic().

Signed-off-by: Petr Mladek <pmladek@suse.com>
---
 include/linux/printk.h   |  2 ++
 kernel/kexec_core.c      |  1 +
 kernel/panic.c           |  6 +++++-
 kernel/printk/internal.h |  2 ++
 kernel/printk/nmi.c      | 39 ++++++++++++++++++++++++++++++++++++++-
 kernel/printk/printk.c   |  2 +-
 6 files changed, 49 insertions(+), 3 deletions(-)

diff --git a/include/linux/printk.h b/include/linux/printk.h
index 51dd6b824fe2..f4da695fd615 100644
--- a/include/linux/printk.h
+++ b/include/linux/printk.h
@@ -127,11 +127,13 @@ 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);
 #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) { }
 #endif /* PRINTK_NMI */
 
 #ifdef CONFIG_PRINTK
diff --git a/kernel/kexec_core.c b/kernel/kexec_core.c
index 8d34308ea449..1dc3fe8495e0 100644
--- a/kernel/kexec_core.c
+++ b/kernel/kexec_core.c
@@ -893,6 +893,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();
 		__crash_kexec(regs);
 
 		/*
diff --git a/kernel/panic.c b/kernel/panic.c
index 535c96510a44..8aa74497cc5a 100644
--- a/kernel/panic.c
+++ b/kernel/panic.c
@@ -160,8 +160,10 @@ void panic(const char *fmt, ...)
 	 *
 	 * Bypass the panic_cpu check and call __crash_kexec directly.
 	 */
-	if (!crash_kexec_post_notifiers)
+	if (!crash_kexec_post_notifiers) {
+		printk_nmi_flush_on_panic();
 		__crash_kexec(NULL);
+	}
 
 	/*
 	 * Note smp_send_stop is the usual smp shutdown function, which
@@ -176,6 +178,8 @@ 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();
 	kmsg_dump(KMSG_DUMP_PANIC);
 
 	/*
diff --git a/kernel/printk/internal.h b/kernel/printk/internal.h
index 341bedccc065..7fd2838fa417 100644
--- a/kernel/printk/internal.h
+++ b/kernel/printk/internal.h
@@ -22,6 +22,8 @@ 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.
diff --git a/kernel/printk/nmi.c b/kernel/printk/nmi.c
index bf08557d7e3d..b69eb8a2876f 100644
--- a/kernel/printk/nmi.c
+++ b/kernel/printk/nmi.c
@@ -17,6 +17,7 @@
 
 #include <linux/preempt.h>
 #include <linux/spinlock.h>
+#include <linux/debug_locks.h>
 #include <linux/smp.h>
 #include <linux/cpumask.h>
 #include <linux/irq_work.h>
@@ -106,7 +107,16 @@ static void print_nmi_seq_line(struct nmi_seq_buf *s, int start, int end)
 {
 	const char *buf = s->buffer + start;
 
-	printk("%.*s", (end - start) + 1, buf);
+	/*
+	 * The buffers are flushed in NMI only on panic.  The messages must
+	 * go only into the ring buffer at this stage.  Consoles will get
+	 * explicitly called later when a crashdump is not generated.
+	 */
+	if (in_nmi())
+		printk_deferred("%.*s", (end - start) + 1, buf);
+	else
+		printk("%.*s", (end - start) + 1, buf);
+
 }
 
 /*
@@ -194,6 +204,33 @@ void printk_nmi_flush(void)
 		__printk_nmi_flush(&per_cpu(nmi_print_seq, cpu).work);
 }
 
+/**
+ * printk_nmi_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
+ * 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)
+{
+	/*
+	 * Make sure that we could access the main ring buffer.
+	 * Do not risk a double release when more CPUs are up.
+	 */
+	if (in_nmi() && raw_spin_is_locked(&logbuf_lock)) {
+		if (num_online_cpus() > 1)
+			return;
+
+		debug_locks_off();
+		raw_spin_lock_init(&logbuf_lock);
+	}
+
+	printk_nmi_flush();
+}
+
 void __init printk_nmi_init(void)
 {
 	int cpu;
diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
index e38579d730f4..60cdf6386763 100644
--- a/kernel/printk/printk.c
+++ b/kernel/printk/printk.c
@@ -245,7 +245,7 @@ __packed __aligned(4)
  * within the scheduler's rq lock. It must be released before calling
  * console_unlock() or anything else that might wake up a process.
  */
-static DEFINE_RAW_SPINLOCK(logbuf_lock);
+DEFINE_RAW_SPINLOCK(logbuf_lock);
 
 #ifdef CONFIG_PRINTK
 DECLARE_WAIT_QUEUE_HEAD(log_wait);
-- 
1.8.5.6

[toc] | [next] | [standalone]

#1385568

Hello Petr,

On (04/21/16 13:48), Petr Mladek wrote:
>  extern void printk_nmi_flush(void);
> +extern void printk_nmi_flush_on_panic(void);
>  #else
>  static inline void printk_nmi_flush(void) { }
> +static inline void printk_nmi_flush_on_panic(void) { }
[..]
> +void printk_nmi_flush_on_panic(void)
> +{
> +	/*
> +	 * Make sure that we could access the main ring buffer.
> +	 * Do not risk a double release when more CPUs are up.
> +	 */
> +	if (in_nmi() && raw_spin_is_locked(&logbuf_lock)) {
> +		if (num_online_cpus() > 1)
> +			return;
> +
> +		debug_locks_off();
> +		raw_spin_lock_init(&logbuf_lock);
> +	}
> +
> +	printk_nmi_flush();
> +}
[..]
> -static DEFINE_RAW_SPINLOCK(logbuf_lock);
> +DEFINE_RAW_SPINLOCK(logbuf_lock);

just an idea,

how about doing it a bit differently?


move printk_nmi_flush_on_panic() to printk.c, and place it next to
printk_flush_on_panic() (so we will have two printk "flush-on-panic"
functions sitting together). /* printk_nmi_flush() is in printk.h,
so it's visible to printk anyway */

it also will let us keep logbuf_lock static, it's a bit too internal
to printk to expose it, I think.


IOW, something like this?

---

 kernel/printk/internal.h |  2 --
 kernel/printk/nmi.c      | 27 ---------------------------
 kernel/printk/printk.c   | 29 ++++++++++++++++++++++++++++-
 3 files changed, 28 insertions(+), 30 deletions(-)

diff --git a/kernel/printk/internal.h b/kernel/printk/internal.h
index 7fd2838..341bedc 100644
--- a/kernel/printk/internal.h
+++ b/kernel/printk/internal.h
@@ -22,8 +22,6 @@ 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.
diff --git a/kernel/printk/nmi.c b/kernel/printk/nmi.c
index b69eb8a..b68a9864 100644
--- a/kernel/printk/nmi.c
+++ b/kernel/printk/nmi.c
@@ -204,33 +204,6 @@ void printk_nmi_flush(void)
 		__printk_nmi_flush(&per_cpu(nmi_print_seq, cpu).work);
 }
 
-/**
- * printk_nmi_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
- * 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)
-{
-	/*
-	 * Make sure that we could access the main ring buffer.
-	 * Do not risk a double release when more CPUs are up.
-	 */
-	if (in_nmi() && raw_spin_is_locked(&logbuf_lock)) {
-		if (num_online_cpus() > 1)
-			return;
-
-		debug_locks_off();
-		raw_spin_lock_init(&logbuf_lock);
-	}
-
-	printk_nmi_flush();
-}
-
 void __init printk_nmi_init(void)
 {
 	int cpu;
diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
index 0a0e789..1509baa 100644
--- a/kernel/printk/printk.c
+++ b/kernel/printk/printk.c
@@ -245,7 +245,7 @@ __packed __aligned(4)
  * within the scheduler's rq lock. It must be released before calling
  * console_unlock() or anything else that might wake up a process.
  */
-DEFINE_RAW_SPINLOCK(logbuf_lock);
+static DEFINE_RAW_SPINLOCK(logbuf_lock);
 
 #ifdef CONFIG_PRINTK
 DECLARE_WAIT_QUEUE_HEAD(log_wait);
@@ -2447,6 +2447,33 @@ void console_unblank(void)
 }
 
 /**
+ * printk_nmi_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
+ * 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)
+{
+	/*
+	 * Make sure that we could access the main ring buffer.
+	 * Do not risk a double release when more CPUs are up.
+	 */
+	if (in_nmi() && raw_spin_is_locked(&logbuf_lock)) {
+		if (num_online_cpus() > 1)
+			return;
+
+		debug_locks_off();
+		raw_spin_lock_init(&logbuf_lock);
+	}
+
+	printk_nmi_flush();
+}
+
+/**
  * console_flush_on_panic - flush console content on panic
  *
  * Immediately output all pending messages no matter what.

[toc] | [prev] | [next] | [standalone]

#1387537

On Sat 2016-04-23 12:49:24, Sergey Senozhatsky wrote:
> Hello Petr,
> 
> On (04/21/16 13:48), Petr Mladek wrote:
> >  extern void printk_nmi_flush(void);
> > +extern void printk_nmi_flush_on_panic(void);
> >  #else
> >  static inline void printk_nmi_flush(void) { }
> > +static inline void printk_nmi_flush_on_panic(void) { }
> [..]
> > +void printk_nmi_flush_on_panic(void)
> > +{
> > +	/*
> > +	 * Make sure that we could access the main ring buffer.
> > +	 * Do not risk a double release when more CPUs are up.
> > +	 */
> > +	if (in_nmi() && raw_spin_is_locked(&logbuf_lock)) {
> > +		if (num_online_cpus() > 1)
> > +			return;
> > +
> > +		debug_locks_off();
> > +		raw_spin_lock_init(&logbuf_lock);
> > +	}
> > +
> > +	printk_nmi_flush();
> > +}
> [..]
> > -static DEFINE_RAW_SPINLOCK(logbuf_lock);
> > +DEFINE_RAW_SPINLOCK(logbuf_lock);
> 
> just an idea,
> 
> how about doing it a bit differently?
> 
> 
> move printk_nmi_flush_on_panic() to printk.c, and place it next to
> printk_flush_on_panic() (so we will have two printk "flush-on-panic"
> functions sitting together). /* printk_nmi_flush() is in printk.h,
> so it's visible to printk anyway */
> 
> it also will let us keep logbuf_lock static, it's a bit too internal
> to printk to expose it, I think.
> 
> IOW, something like this?

It is rather cosmetic change. I 

> ---
> 
>  kernel/printk/internal.h |  2 --
>  kernel/printk/nmi.c      | 27 ---------------------------
>  kernel/printk/printk.c   | 29 ++++++++++++++++++++++++++++-
>  3 files changed, 28 insertions(+), 30 deletions(-)
> 
> diff --git a/kernel/printk/internal.h b/kernel/printk/internal.h
> index 7fd2838..341bedc 100644
> --- a/kernel/printk/internal.h
> +++ b/kernel/printk/internal.h
> @@ -22,8 +22,6 @@ int __printf(1, 0) vprintk_default(const char *fmt, va_list args);
>  
>  #ifdef CONFIG_PRINTK_NMI
>  
> -extern raw_spinlock_t logbuf_lock;

Well, it was exposed only in the internal.h header file. I consider
this rather a cosmetic change and do not have strong opinion about it. :-)

Anyway, thanks a lot for review.

Best Regards,
Petr

[toc] | [prev] | [next] | [standalone]

#1388528

On (04/26/16 16:21), Petr Mladek wrote:
[..]
> > move printk_nmi_flush_on_panic() to printk.c, and place it next to
> > printk_flush_on_panic() (so we will have two printk "flush-on-panic"
> > functions sitting together). /* printk_nmi_flush() is in printk.h,
> > so it's visible to printk anyway */
> > 
> > it also will let us keep logbuf_lock static, it's a bit too internal
> > to printk to expose it, I think.
> > 
> > IOW, something like this?
> 
> It is rather cosmetic change. I 

oh yes, it is. just to keep similar functionality (flush, zap locks)
in one place (printk).

	-ss

[toc] | [prev] | [standalone]

Back to top | Article view | linux.kernel

csiph-web