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

Groups > linux.kernel > #1491941 > unrolled thread

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

Back to article view | Back to linux.kernel

Contents

  [RFC][PATCH 0/7] printk: use alt_printk to handle printk() recursive calls Sergey Senozhatsky <sergey.senozhatsky@gmail.com> - 2016-09-27 16:30 +0200
    [RFC][PATCH 5/7] printk: drop vprintk_func function Sergey Senozhatsky <sergey.senozhatsky@gmail.com> - 2016-09-27 16:30 +0200
    [RFC][PATCH 3/7] printk: introduce per-cpu alt_print seq buffer Sergey Senozhatsky <sergey.senozhatsky@gmail.com> - 2016-09-27 16:30 +0200
      Re: [RFC][PATCH 3/7] printk: introduce per-cpu alt_print seq buffer Petr Mladek <pmladek@suse.com> - 2016-09-29 14:30 +0200
        Re: [RFC][PATCH 3/7] printk: introduce per-cpu alt_print seq buffer Sergey Senozhatsky <sergey.senozhatsky.work@gmail.com> - 2016-09-30 03:10 +0200
          Re: [RFC][PATCH 3/7] printk: introduce per-cpu alt_print seq buffer Petr Mladek <pmladek@suse.com> - 2016-09-30 13:40 +0200
    [RFC][PATCH 1/7] printk: use vprintk_func in vprintk() Sergey Senozhatsky <sergey.senozhatsky@gmail.com> - 2016-09-27 16:30 +0200
    [RFC][PATCH 2/7] printk: rename nmi.c and exported api Sergey Senozhatsky <sergey.senozhatsky@gmail.com> - 2016-09-27 16:30 +0200
    [RFC][PATCH 6/7] printk: use alternative printk buffers Sergey Senozhatsky <sergey.senozhatsky@gmail.com> - 2016-09-27 16:30 +0200
      Re: [RFC][PATCH 6/7] printk: use alternative printk buffers Petr Mladek <pmladek@suse.com> - 2016-09-29 15:10 +0200
        Re: [RFC][PATCH 6/7] printk: use alternative printk buffers Sergey Senozhatsky <sergey.senozhatsky.work@gmail.com> - 2016-09-30 03:20 +0200
          Re: [RFC][PATCH 6/7] printk: use alternative printk buffers Petr Mladek <pmladek@suse.com> - 2016-09-30 13:20 +0200
            Re: [RFC][PATCH 6/7] printk: use alternative printk buffers Sergey Senozhatsky <sergey.senozhatsky.work@gmail.com> - 2016-10-01 04:50 +0200
              Re: [RFC][PATCH 6/7] printk: use alternative printk buffers Petr Mladek <pmladek@suse.com> - 2016-10-04 14:30 +0200
                Re: [RFC][PATCH 6/7] printk: use alternative printk buffers Sergey Senozhatsky <sergey.senozhatsky.work@gmail.com> - 2016-10-05 03:40 +0200
                  Re: [RFC][PATCH 6/7] printk: use alternative printk buffers Petr Mladek <pmladek@suse.com> - 2016-10-05 12:20 +0200
            Re: [RFC][PATCH 6/7] printk: use alternative printk buffers Sergey Senozhatsky <sergey.senozhatsky@gmail.com> - 2016-10-03 10:00 +0200
            Re: [RFC][PATCH 6/7] printk: use alternative printk buffers Petr Mladek <pmladek@suse.com> - 2016-10-04 17:00 +0200
              Re: [RFC][PATCH 6/7] printk: use alternative printk buffers Sergey Senozhatsky <sergey.senozhatsky.work@gmail.com> - 2016-10-05 03:30 +0200
                Re: [RFC][PATCH 6/7] printk: use alternative printk buffers Petr Mladek <pmladek@suse.com> - 2016-10-05 12:00 +0200
                  Re: [RFC][PATCH 6/7] printk: use alternative printk buffers Sergey Senozhatsky <sergey.senozhatsky.work@gmail.com> - 2016-10-06 06:30 +0200
                    Re: [RFC][PATCH 6/7] printk: use alternative printk buffers Petr Mladek <pmladek@suse.com> - 2016-10-06 13:40 +0200
                      Re: [RFC][PATCH 6/7] printk: use alternative printk buffers Sergey Senozhatsky <sergey.senozhatsky.work@gmail.com> - 2016-10-10 06:20 +0200
                        Re: [RFC][PATCH 6/7] printk: use alternative printk buffers Petr Mladek <pmladek@suse.com> - 2016-10-10 13:20 +0200
                          Re: [RFC][PATCH 6/7] printk: use alternative printk buffers Sergey Senozhatsky <sergey.senozhatsky.work@gmail.com> - 2016-10-11 09:40 +0200
                            Re: [RFC][PATCH 6/7] printk: use alternative printk buffers Petr Mladek <pmladek@suse.com> - 2016-10-11 11:40 +0200
    [RFC][PATCH 4/7] printk: make alt_printk available when config printk set Sergey Senozhatsky <sergey.senozhatsky@gmail.com> - 2016-09-27 16:30 +0200
    [RFC][PATCH 7/7] printk: new printk() recursion detection Sergey Senozhatsky <sergey.senozhatsky@gmail.com> - 2016-09-27 16:30 +0200
      Re: [RFC][PATCH 7/7] printk: new printk() recursion detection Petr Mladek <pmladek@suse.com> - 2016-09-29 15:30 +0200
        Re: [RFC][PATCH 7/7] printk: new printk() recursion detection Sergey Senozhatsky <sergey.senozhatsky.work@gmail.com> - 2016-09-30 04:10 +0200
    Re: [RFC][PATCH 0/7] printk: use alt_printk to handle printk()  recursive calls Petr Mladek <pmladek@suse.com> - 2016-09-29 15:30 +0200
      Re: [RFC][PATCH 0/7] printk: use alt_printk to handle printk()  recursive calls Sergey Senozhatsky <sergey.senozhatsky.work@gmail.com> - 2016-09-30 04:50 +0200
        Re: [RFC][PATCH 0/7] printk: use alt_printk to handle printk()  recursive calls Petr Mladek <pmladek@suse.com> - 2016-09-30 13:30 +0200
          Re: [RFC][PATCH 0/7] printk: use alt_printk to handle printk()  recursive calls Sergey Senozhatsky <sergey.senozhatsky.work@gmail.com> - 2016-10-01 05:10 +0200
            Re: [RFC][PATCH 0/7] printk: use alt_printk to handle printk()  recursive calls Petr Mladek <pmladek@suse.com> - 2016-10-04 13:40 +0200

Page 1 of 2  [1] 2  Next page →

#1491941 — [RFC][PATCH 0/7] printk: use alt_printk to handle printk() recursive calls

	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.

Deadlocks 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);

and some other.

[[against next-20160927]]


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: drop vprintk_func function
  printk: use alternative printk buffers
  printk: new printk() recursion detection

 include/linux/printk.h     |  14 +-
 init/Kconfig               |  16 +-
 init/main.c                |   2 +-
 kernel/kexec_core.c        |   2 +-
 kernel/panic.c             |   4 +-
 kernel/printk/Makefile     |   2 +-
 kernel/printk/alt_printk.c | 432 +++++++++++++++++++++++++++++++++++++++++++++
 kernel/printk/internal.h   |  26 ++-
 kernel/printk/nmi.c        | 268 ----------------------------
 kernel/printk/printk.c     |  67 +++----
 lib/nmi_backtrace.c        |   2 +-
 11 files changed, 495 insertions(+), 340 deletions(-)
 create mode 100644 kernel/printk/alt_printk.c
 delete mode 100644 kernel/printk/nmi.c

-- 
2.10.0.372.g6fe1b14

[toc] | [next] | [standalone]

#1491943 — [RFC][PATCH 5/7] printk: drop vprintk_func function

Drop vprintk_func() function and use this_cpu_read(printk_func),
since now we always have alt_printk enabled.

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

diff --git a/kernel/printk/internal.h b/kernel/printk/internal.h
index 3eebf6d..b030ca0 100644
--- a/kernel/printk/internal.h
+++ b/kernel/printk/internal.h
@@ -31,10 +31,6 @@ extern raw_spinlock_t logbuf_lock;
  * 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);
-}
 
 void alt_printk_enter(void);
 void alt_printk_exit(void);
diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
index c7ffbef..2afa16b 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_func(fmt, args);
+	return this_cpu_read(printk_func)(fmt, args);
 }
 EXPORT_SYMBOL(vprintk);
 
@@ -1984,7 +1984,7 @@ asmlinkage __visible int printk(const char *fmt, ...)
 	int r;
 
 	va_start(args, fmt);
-	r = vprintk_func(fmt, args);
+	r = this_cpu_read(printk_func)(fmt, args);
 	va_end(args);
 
 	return r;
-- 
2.10.0.372.g6fe1b14

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

#1491944 — [RFC][PATCH 3/7] printk: introduce per-cpu alt_print seq buffer

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
of critical scheduler locks (p->pi_lock, etc.). An example of
a 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_do_activate()
        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 patch only adds a alt_printk support, we don't use it yet.

Signed-off-by: Sergey Senozhatsky <sergey.senozhatsky@gmail.com>
---
 kernel/printk/alt_printk.c | 160 +++++++++++++++++++++++++++++++++++++++++----
 kernel/printk/internal.h   |  12 ++++
 2 files changed, 158 insertions(+), 14 deletions(-)

diff --git a/kernel/printk/alt_printk.c b/kernel/printk/alt_printk.c
index 7178661..8978390 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
@@ -53,24 +53,39 @@ 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.
+ * There can be two alt_printk contexts at most - a `normal' alt_printk
+ * and NMI alt_printk context. Normal alt_printk context is the one that
+ * direct caller of printk() setups (either a process or IRQ) and it can
+ * be preempted only by NMI (if the platform supports NMI). NMI context
+ * can preempt normal alt_printk context, but cannot be preempted on its
+ * own.
  */
-static int vprintk_nmi(const char *fmt, va_list args)
+#ifdef CONFIG_PRINTK_NMI
+#define MAX_ALT_PRINTK_CTX	2
+#else
+#define MAX_ALT_PRINTK_CTX	1
+#endif
+
+struct alt_printk_ctx {
+	atomic_t	idx;
+	unsigned int	entry_count;
+	printk_func_t	saved_printk_func[MAX_ALT_PRINTK_CTX];
+};
+
+static DEFINE_PER_CPU(struct alt_printk_seq_buf, alt_print_seq);
+static DEFINE_PER_CPU(struct alt_printk_ctx, alt_printk_ctx);
+
+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
@@ -99,6 +114,96 @@ static int vprintk_nmi(const char *fmt, va_list args)
 	return add;
 }
 
+/*
+ * 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 must keep the track of `printk_func' because alt_printk
+ * context can be preempted by NMI alt_printk context.
+ *
+ * Consider the following example:
+ *
+ * vprintk_emit()
+ * 	alt_printk_enter()
+ * 		printk_func = vprintk_alt;
+ *
+ * -> NMI
+ *  	printk_nmi_enter()
+ *		printk_func = vprintk_nmi;
+ *	printk_nmi_exit()
+ *		printk_func = vprintk_default;
+ *		^^^^^^^^^^^
+ * <- NMI
+ *
+ * 	printk("foo") -> vprintk_default();
+ *
+ * Thus we must restore the orignal `printk_func' value, the one
+ * NMI saw at printk_nmi_enter() time.
+ */
+static void __lockless_printk_enter(printk_func_t new_func)
+{
+	struct alt_printk_ctx *ctx = this_cpu_ptr(&alt_printk_ctx);
+	int idx = atomic_inc_return(&ctx->idx) - 1;
+
+	ctx->saved_printk_func[idx] = this_cpu_read(printk_func);
+	this_cpu_write(printk_func, new_func);
+}
+
+static void __lockless_printk_exit(void)
+{
+	struct alt_printk_ctx *ctx = this_cpu_ptr(&alt_printk_ctx);
+	int idx = atomic_read(&ctx->idx) - 1;
+
+	this_cpu_write(printk_func, ctx->saved_printk_func[idx]);
+	atomic_dec(&ctx->idx);
+}
+
+/* Local IRQs must be disabled; can be preempted by NMI. */
+void alt_printk_enter(void)
+{
+	struct alt_printk_ctx *ctx = this_cpu_ptr(&alt_printk_ctx);
+
+	/*
+	 * We can't switch `printk_func' while the CPU is flushing its
+	 * alternative buffers. At the same time, we leave flushing
+	 * `unprotected', because we always use vprintk_default() there.
+	 *
+	 * ->entry_count can detect printk() recursion from flushing context:
+	 *  -- alt_printk_flush() sets ->entry_count to 1
+	 *  -- every vprintk_default() call from alt_printk_flush() increments
+	 *     ->entry_count to 2 when it enters the recursion un-safe region
+	 *     and decrements it back to 1 when it leaves that region
+	 *  -- thus, if printk() will recurs from recursion un-safe region, we
+	 *     will see ->entry_count > 2.
+	 */
+	ctx->entry_count++;
+	if (ctx->entry_count > 1)
+		return;
+
+	/* @TODO: do something sensible in case of printk() recursion */
+
+	__lockless_printk_enter(vprintk_alt);
+}
+
+/* Local IRQs must be disabled; can be preempted by NMI. */
+void alt_printk_exit(void)
+{
+	struct alt_printk_ctx *ctx = this_cpu_ptr(&alt_printk_ctx);
+
+	if (ctx->entry_count == 1)
+		__lockless_printk_exit();
+	ctx->entry_count--;
+}
+
 static void alt_printk_flush_line(const char *text, int len)
 {
 	/*
@@ -110,7 +215,6 @@ static void alt_printk_flush_line(const char *text, int len)
 		printk_deferred("%.*s", len, text);
 	else
 		printk("%.*s", len, text);
-
 }
 
 /*
@@ -135,6 +239,7 @@ static void __alt_printk_flush(struct irq_work *work)
 		__RAW_SPIN_LOCK_INITIALIZER(read_lock);
 	struct alt_printk_seq_buf *s = container_of(work,
 			struct alt_printk_seq_buf, work);
+	struct alt_printk_ctx *ctx = this_cpu_ptr(&alt_printk_ctx);
 	unsigned long flags;
 	size_t len, size;
 	int i, last_i;
@@ -147,6 +252,11 @@ static void __alt_printk_flush(struct irq_work *work)
 	 * a backtrace.
 	 */
 	raw_spin_lock_irqsave(&read_lock, flags);
+	/*
+	 * Forbid the alt_printk on this CPU, we want to flush messages to
+	 * logbuf, not to alt_printk buffer again.
+	 */
+	ctx->entry_count++;
 
 	i = 0;
 more:
@@ -195,6 +305,7 @@ static void __alt_printk_flush(struct irq_work *work)
 		goto more;
 
 out:
+	ctx->entry_count--;
 	raw_spin_unlock_irqrestore(&read_lock, flags);
 }
 
@@ -248,6 +359,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. */
@@ -258,12 +372,30 @@ void __init alt_printk_init(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_write(printk_func, vprintk_nmi);
+	__lockless_printk_enter(vprintk_nmi);
 }
 
 void printk_nmi_exit(void)
 {
-	this_cpu_write(printk_func, vprintk_default);
+	__lockless_printk_exit();
 }
diff --git a/kernel/printk/internal.h b/kernel/printk/internal.h
index 7fd2838..c5f970e 100644
--- a/kernel/printk/internal.h
+++ b/kernel/printk/internal.h
@@ -20,6 +20,18 @@ 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
+
+void alt_printk_enter(void);
+void alt_printk_exit(void);
+
+#else
+
+void alt_printk_enter(void) { }
+void alt_printk_exit(void) { }
+
+#endif /* CONFIG_PRINTK */
+
 #ifdef CONFIG_PRINTK_NMI
 
 extern raw_spinlock_t logbuf_lock;
-- 
2.10.0.372.g6fe1b14

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

#1493440 — Re: [RFC][PATCH 3/7] printk: introduce per-cpu alt_print seq buffer

On Tue 2016-09-27 23:22:33, 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
> of critical scheduler locks (p->pi_lock, etc.). An example of
> a 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_do_activate()
>         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()

We need to make sure that exit() is called on the same CPU.
Therefore we need to disable preemption as well.

>   //
>   //  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 patch only adds a alt_printk support, we don't use it yet.
> 
> Signed-off-by: Sergey Senozhatsky <sergey.senozhatsky@gmail.com>
> ---
>  kernel/printk/alt_printk.c | 160 +++++++++++++++++++++++++++++++++++++++++----
>  kernel/printk/internal.h   |  12 ++++
>  2 files changed, 158 insertions(+), 14 deletions(-)
> 
> diff --git a/kernel/printk/alt_printk.c b/kernel/printk/alt_printk.c
> index 7178661..8978390 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
> @@ -53,24 +53,39 @@ 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.
> + * There can be two alt_printk contexts at most - a `normal' alt_printk
> + * and NMI alt_printk context. Normal alt_printk context is the one that
> + * direct caller of printk() setups (either a process or IRQ) and it can
> + * be preempted only by NMI (if the platform supports NMI). NMI context
> + * can preempt normal alt_printk context, but cannot be preempted on its
> + * own.
>   */
> -static int vprintk_nmi(const char *fmt, va_list args)
> +#ifdef CONFIG_PRINTK_NMI
> +#define MAX_ALT_PRINTK_CTX	2
> +#else
> +#define MAX_ALT_PRINTK_CTX	1
> +#endif
> +
> +struct alt_printk_ctx {
> +	atomic_t	idx;
> +	unsigned int	entry_count;
> +	printk_func_t	saved_printk_func[MAX_ALT_PRINTK_CTX];
> +};
> +
> +static DEFINE_PER_CPU(struct alt_printk_seq_buf, alt_print_seq);
> +static DEFINE_PER_CPU(struct alt_printk_ctx, alt_printk_ctx);
> +
> +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
> @@ -99,6 +114,96 @@ static int vprintk_nmi(const char *fmt, va_list args)
>  	return add;
>  }
>  
> +/*
> + * 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 must keep the track of `printk_func' because alt_printk
> + * context can be preempted by NMI alt_printk context.
> + *
> + * Consider the following example:
> + *
> + * vprintk_emit()
> + * 	alt_printk_enter()
> + * 		printk_func = vprintk_alt;
> + *
> + * -> NMI
> + *  	printk_nmi_enter()
> + *		printk_func = vprintk_nmi;
> + *	printk_nmi_exit()
> + *		printk_func = vprintk_default;
> + *		^^^^^^^^^^^
> + * <- NMI
> + *
> + * 	printk("foo") -> vprintk_default();
> + *
> + * Thus we must restore the orignal `printk_func' value, the one
> + * NMI saw at printk_nmi_enter() time.
> + */
> +static void __lockless_printk_enter(printk_func_t new_func)
> +{
> +	struct alt_printk_ctx *ctx = this_cpu_ptr(&alt_printk_ctx);
> +	int idx = atomic_inc_return(&ctx->idx) - 1;
> +
> +	ctx->saved_printk_func[idx] = this_cpu_read(printk_func);
> +	this_cpu_write(printk_func, new_func);
> +}
> +
> +static void __lockless_printk_exit(void)
> +{
> +	struct alt_printk_ctx *ctx = this_cpu_ptr(&alt_printk_ctx);
> +	int idx = atomic_read(&ctx->idx) - 1;
> +
> +	this_cpu_write(printk_func, ctx->saved_printk_func[idx]);
> +	atomic_dec(&ctx->idx);
> +}
> +
> +/* Local IRQs must be disabled; can be preempted by NMI. */
> +void alt_printk_enter(void)
> +{
> +	struct alt_printk_ctx *ctx = this_cpu_ptr(&alt_printk_ctx);
> +
> +	/*
> +	 * We can't switch `printk_func' while the CPU is flushing its
> +	 * alternative buffers. At the same time, we leave flushing
> +	 * `unprotected', because we always use vprintk_default() there.
> +	 *
> +	 * ->entry_count can detect printk() recursion from flushing context:
> +	 *  -- alt_printk_flush() sets ->entry_count to 1
> +	 *  -- every vprintk_default() call from alt_printk_flush() increments
> +	 *     ->entry_count to 2 when it enters the recursion un-safe region
> +	 *     and decrements it back to 1 when it leaves that region
> +	 *  -- thus, if printk() will recurs from recursion un-safe region, we
> +	 *     will see ->entry_count > 2.
> +	 */
> +	ctx->entry_count++;
> +	if (ctx->entry_count > 1)
> +		return;
> +
> +	/* @TODO: do something sensible in case of printk() recursion */
> +
> +	__lockless_printk_enter(vprintk_alt);
> +}
> +
> +/* Local IRQs must be disabled; can be preempted by NMI. */
> +void alt_printk_exit(void)
> +{
> +	struct alt_printk_ctx *ctx = this_cpu_ptr(&alt_printk_ctx);
> +
> +	if (ctx->entry_count == 1)
> +		__lockless_printk_exit();
> +	ctx->entry_count--;
> +}

Huh, this is complicated like hell. I think that it is like this
because of two reasons. First, it tries to change more values a
lockless way. Second, it tries to be kind of generic.

Note that it is not much generic. idx is increased or decreased only
when entry_count == 1 or when called from nmi_enter()/exit().
Therefore it could not be easily extended to yet another alt buffer.
Also it relies on the fact the nmi_enter()/exit() calls are not
nested.

What do you think about my approach with the printk_context per-CPU
value from the WARN_DEFERRED() patchset? The main idea is that
the entry()/exit() functions manipulate preempt_count-like per-CPU
variable. The printk() function selects the safe implementation
according to the current state.

>  static void alt_printk_flush_line(const char *text, int len)
>  {
>  	/*
> @@ -110,7 +215,6 @@ static void alt_printk_flush_line(const char *text, int len)
>  		printk_deferred("%.*s", len, text);
>  	else
>  		printk("%.*s", len, text);
> -
>  }
>  
>  /*
> @@ -135,6 +239,7 @@ static void __alt_printk_flush(struct irq_work *work)
>  		__RAW_SPIN_LOCK_INITIALIZER(read_lock);
>  	struct alt_printk_seq_buf *s = container_of(work,
>  			struct alt_printk_seq_buf, work);
> +	struct alt_printk_ctx *ctx = this_cpu_ptr(&alt_printk_ctx);
>  	unsigned long flags;
>  	size_t len, size;
>  	int i, last_i;
> @@ -147,6 +252,11 @@ static void __alt_printk_flush(struct irq_work *work)
>  	 * a backtrace.
>  	 */
>  	raw_spin_lock_irqsave(&read_lock, flags);
> +	/*
> +	 * Forbid the alt_printk on this CPU, we want to flush messages to
> +	 * logbuf, not to alt_printk buffer again.
> +	 */
> +	ctx->entry_count++;

This looks very strange. If entry_count is not zero, it means that we
are not in a safe context to flush the alternative buffer. Or do
I miss something, please?
 

My other concern about this approach was that it would spread printk()
messages to even more buffers. But I am not scared anymore. The
new buffer will be used only for printk-internal errors that would
normally cause a deadlock. The important thing is that we are able
to share the implementation handling the extra buffer.

So, I think that this approach have a chance if we clean it a bit.

Best Regards,
Petr

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

#1493815 — Re: [RFC][PATCH 3/7] printk: introduce per-cpu alt_print seq buffer

On (09/29/16 14:26), Petr Mladek wrote:
[..]
> >  printk()
> >   local_irq_save()
> >   alt_printk_enter()
> 
> We need to make sure that exit() is called on the same CPU.
> Therefore we need to disable preemption as well.

local_irq_save() does this for us, we can't get sched tick or
re-sched IPI, and even more - we eliminate race conditions on
this CPU. only one path can touch alt_printk related stuff,
NMI works with its own buffer.

[..]
> What do you think about my approach with the printk_context per-CPU
> value from the WARN_DEFERRED() patchset? The main idea is that
> the entry()/exit() functions manipulate preempt_count-like per-CPU
> variable. The printk() function selects the safe implementation
> according to the current state.

I'll take a look.

hm, what I was thinking of... you are right, this all smells a bit
bad. I'll revisit it.

thanks!

	-ss

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

#1494033 — Re: [RFC][PATCH 3/7] printk: introduce per-cpu alt_print seq buffer

On Fri 2016-09-30 10:05:28, Sergey Senozhatsky wrote:
> On (09/29/16 14:26), Petr Mladek wrote:
> [..]
> > >  printk()
> > >   local_irq_save()
> > >   alt_printk_enter()
> > 
> > We need to make sure that exit() is called on the same CPU.
> > Therefore we need to disable preemption as well.
> 
> local_irq_save() does this for us, we can't get sched tick or
> re-sched IPI, and even more - we eliminate race conditions on
> this CPU. only one path can touch alt_printk related stuff,
> NMI works with its own buffer.
> 
> [..]
> > What do you think about my approach with the printk_context per-CPU
> > value from the WARN_DEFERRED() patchset? The main idea is that
> > the entry()/exit() functions manipulate preempt_count-like per-CPU
> > variable. The printk() function selects the safe implementation
> > according to the current state.
> 
> I'll take a look.
> 
> I'll revisit it.

Just a side note. If you make it less generic then please use some more
meaning-full name for the alternative printk stuff. The following
comes to my mind:

	     printk_safe_enter();
	     printk_safe_exit();
	     vprintk_safe();

IMHO, the "_safe" suffix often means a variant that prevents a
possible deadlock.

I wonder where this patches would end but it looks promising.

Best Regards,
Petr

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

#1491945 — [RFC][PATCH 1/7] printk: use vprintk_func in vprintk()

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

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

#1491946 — [RFC][PATCH 2/7] printk: rename nmi.c and exported api

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

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

#1491948 — [RFC][PATCH 6/7] printk: use alternative printk buffers

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 it addresses deadlocks caused by recursiove printk()
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 ]---

another example of WARN_ON() from scheduler code:

 ------------[ cut here ]------------
 WARNING: CPU: 1 PID: 361 at kernel/sched/core.c:2026 try_to_wake_up+0x6c/0x4e4
 CPU: 1 PID: 361 Comm: bash
 Call Trace:
  <IRQ>  [<ffffffff811e2544>] dump_stack+0x68/0x92
  [<ffffffff810455cd>] __warn+0xc2/0xdd
  [<ffffffff81045658>] warn_slowpath_null+0x1d/0x1f
  [<ffffffff8106c8bd>] try_to_wake_up+0x6c/0x4e4
  [<ffffffff81089760>] ? lock_acquire+0x130/0x1c4
  [<ffffffff8106cd4a>] wake_up_process+0x15/0x17
  [<ffffffff8105a696>] wake_up_worker+0x28/0x2a
  [<ffffffff8105a869>] insert_work+0xa5/0xb1
  [<ffffffff8105bb99>] __queue_work+0x374/0x509
  [<ffffffff8105bd68>] queue_work_on+0x3a/0x64
  [<ffffffff812d7fd1>] dbs_irq_work+0x24/0x27
  [<ffffffff810ebbe7>] irq_work_run_list+0x43/0x67
  [<ffffffff810ebe26>] irq_work_run+0x2a/0x44
  [<ffffffff81019196>] smp_irq_work_interrupt+0x2e/0x35
  [<ffffffff813cccf9>] irq_work_interrupt+0x89/0x90
  [<ffffffff813cd1fe>] ? __do_softirq+0x96/0x434
  [<ffffffff813cd207>] ? __do_softirq+0x9f/0x434
  [<ffffffff8104b6e4>] irq_exit+0x40/0x90
  [<ffffffff813ccee9>] smp_apic_timer_interrupt+0x42/0x4d
  [<ffffffff813cc2d9>] apic_timer_interrupt+0x89/0x90
  <EOI>  [<ffffffff8101c578>] ? native_sched_clock+0x7/0xbc
  [<ffffffff81072db7>] ? sched_clock_cpu+0x17/0xc6
  [<ffffffff81072fef>] running_clock+0x10/0x12
  [<ffffffff810917d8>] vprintk_emit+0x448/0x462
  [<ffffffff8109195e>] vprintk_default+0x1d/0x1f
  [<ffffffff810fdfca>] 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 | 27 ++++++++++++++++++++-------
 1 file changed, 20 insertions(+), 7 deletions(-)

diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
index 2afa16b..e5dacfb 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;
@@ -2239,8 +2237,18 @@ EXPORT_SYMBOL(console_lock);
  */
 int console_trylock(void)
 {
-	if (down_trylock_console_sem())
+	unsigned long flags;
+	int lock_failed;
+
+	local_irq_save(flags);
+	alt_printk_enter();
+	lock_failed = down_trylock_console_sem();
+	alt_printk_exit();
+	local_irq_restore(flags);
+
+	if (lock_failed)
 		return 0;
+
 	if (console_suspended) {
 		up_console_sem();
 		return 0;
@@ -2395,7 +2403,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;
@@ -2456,6 +2466,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)
@@ -2479,7 +2490,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

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

#1493448 — Re: [RFC][PATCH 6/7] printk: use alternative printk buffers

On Tue 2016-09-27 23:22:36, Sergey Senozhatsky wrote:
> 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 it addresses deadlocks caused by recursiove printk()
> 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 ]---
> 
> another example of WARN_ON() from scheduler code:
> 
>  ------------[ cut here ]------------
>  WARNING: CPU: 1 PID: 361 at kernel/sched/core.c:2026 try_to_wake_up+0x6c/0x4e4
>  CPU: 1 PID: 361 Comm: bash
>  Call Trace:
>   <IRQ>  [<ffffffff811e2544>] dump_stack+0x68/0x92
>   [<ffffffff810455cd>] __warn+0xc2/0xdd
>   [<ffffffff81045658>] warn_slowpath_null+0x1d/0x1f
>   [<ffffffff8106c8bd>] try_to_wake_up+0x6c/0x4e4
>   [<ffffffff81089760>] ? lock_acquire+0x130/0x1c4
>   [<ffffffff8106cd4a>] wake_up_process+0x15/0x17
>   [<ffffffff8105a696>] wake_up_worker+0x28/0x2a
>   [<ffffffff8105a869>] insert_work+0xa5/0xb1
>   [<ffffffff8105bb99>] __queue_work+0x374/0x509
>   [<ffffffff8105bd68>] queue_work_on+0x3a/0x64
>   [<ffffffff812d7fd1>] dbs_irq_work+0x24/0x27
>   [<ffffffff810ebbe7>] irq_work_run_list+0x43/0x67
>   [<ffffffff810ebe26>] irq_work_run+0x2a/0x44
>   [<ffffffff81019196>] smp_irq_work_interrupt+0x2e/0x35
>   [<ffffffff813cccf9>] irq_work_interrupt+0x89/0x90
>   [<ffffffff813cd1fe>] ? __do_softirq+0x96/0x434
>   [<ffffffff813cd207>] ? __do_softirq+0x9f/0x434
>   [<ffffffff8104b6e4>] irq_exit+0x40/0x90
>   [<ffffffff813ccee9>] smp_apic_timer_interrupt+0x42/0x4d
>   [<ffffffff813cc2d9>] apic_timer_interrupt+0x89/0x90
>   <EOI>  [<ffffffff8101c578>] ? native_sched_clock+0x7/0xbc
>   [<ffffffff81072db7>] ? sched_clock_cpu+0x17/0xc6
>   [<ffffffff81072fef>] running_clock+0x10/0x12
>   [<ffffffff810917d8>] vprintk_emit+0x448/0x462
>   [<ffffffff8109195e>] vprintk_default+0x1d/0x1f
>   [<ffffffff810fdfca>] 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 | 27 ++++++++++++++++++++-------
>  1 file changed, 20 insertions(+), 7 deletions(-)
> 
> diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
> index 2afa16b..e5dacfb 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();

IMHO, we could not longer enter vprintk_emit() recursively. The same
section that was guarded by logbuf_cpu is guarded by
alt_printk_enter()/exit() now.

IMHO, we could remove all the logic around the recursion. Then we
could even disable/enable irqs inside alt_printk_enter()/exit().

And to correct myself from the previous mail. It is enough to disable
IRQs. It is enough to make sure that we will not preempt and will
stay on the same CPU.

>  	/* 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;
> @@ -2239,8 +2237,18 @@ EXPORT_SYMBOL(console_lock);
>   */
>  int console_trylock(void)
>  {
> -	if (down_trylock_console_sem())
> +	unsigned long flags;
> +	int lock_failed;
> +
> +	local_irq_save(flags);
> +	alt_printk_enter();
> +	lock_failed = down_trylock_console_sem();
> +	alt_printk_exit();
> +	local_irq_restore(flags);
> +
> +	if (lock_failed)
>  		return 0;
> +
>  	if (console_suspended) {
>  		up_console_sem();
>  		return 0;
> @@ -2395,7 +2403,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;
> @@ -2456,6 +2466,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)
> @@ -2479,7 +2490,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);

We should mention that this patch makes an obsolete artefact from
printk_deferred(). It opens the door for another big cleanup and
relief.

Best Regards,
Petr

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

#1493819 — Re: [RFC][PATCH 6/7] printk: use alternative printk buffers

On (09/29/16 15:00), Petr Mladek wrote:
[..]
> > @@ -1791,7 +1791,7 @@ asmlinkage int vprintk_emit(int facility, int level,
> >  		zap_locks();
> >  	}
> >  
> > -	lockdep_off();
> > +	alt_printk_enter();
> 
> IMHO, we could not longer enter vprintk_emit() recursively. The same
> section that was guarded by logbuf_cpu is guarded by
> alt_printk_enter()/exit() now.

you might be very right here. I'll take a look.

> IMHO, we could remove all the logic around the recursion. Then we
> could even disable/enable irqs inside alt_printk_enter()/exit().

I was thinking of doing something like this; but that would require
storing 'unsigned long' flags in per-cpu data

	alt_enter()
	{
		unsinged long flags;

		local_irq_save(flags);
		ctx = this_cpu_ptr();
		ctx->flags = flags;
		...
	}

	alt_exit()
	{
		ctx = this_cpu_ptr();
		...
		local_irq_restore(ctx->flags);
	}


and the decision was to keep `unsigned long flags' on stack in the
alt_enter/exit caller. besides in most of the cases we already have
it (in vprintk_emit() and console_unlock()).

but I can certainly hide these details in alt_enter/exit.


> And to correct myself from the previous mail. It is enough to disable
> IRQs. It is enough to make sure that we will not preempt and will
> stay on the same CPU.

ah, no prob.

> > @@ -2479,7 +2490,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);
> 
> We should mention that this patch makes an obsolete artefact from
> printk_deferred(). It opens the door for another big cleanup and
> relief.

do you mean that, once alt_printk is done properly, we can drop
printk_deferred()? I was thinking of it, but decided not to
mention/touch it in this patch set.

	-ss

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

#1494030 — Re: [RFC][PATCH 6/7] printk: use alternative printk buffers

On Fri 2016-09-30 10:15:44, Sergey Senozhatsky wrote:
> On (09/29/16 15:00), Petr Mladek wrote:
> [..]
> > > @@ -1791,7 +1791,7 @@ asmlinkage int vprintk_emit(int facility, int level,
> > >  		zap_locks();
> > >  	}
> > >  
> > > -	lockdep_off();
> > > +	alt_printk_enter();
> > 
> > IMHO, we could not longer enter vprintk_emit() recursively. The same
> > section that was guarded by logbuf_cpu is guarded by
> > alt_printk_enter()/exit() now.
> 
> you might be very right here. I'll take a look.
> 
> > IMHO, we could remove all the logic around the recursion. Then we
> > could even disable/enable irqs inside alt_printk_enter()/exit().
> 
> I was thinking of doing something like this; but that would require
> storing 'unsigned long' flags in per-cpu data
> 
> 	alt_enter()
> 	{
> 		unsinged long flags;
> 
> 		local_irq_save(flags);
> 		ctx = this_cpu_ptr();
> 		ctx->flags = flags;
> 		...
> 	}
> 
> 	alt_exit()
> 	{
> 		ctx = this_cpu_ptr();
> 		...
> 		local_irq_restore(ctx->flags);
> 	}
>
> and the decision was to keep `unsigned long flags' on stack in the
> alt_enter/exit caller. besides in most of the cases we already have
> it (in vprintk_emit() and console_unlock()).

I would pass the pointer to flags as alt_enter() parameter.
> 
> but I can certainly hide these details in alt_enter/exit.
>
> > > @@ -2479,7 +2490,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);
> > 
> > We should mention that this patch makes an obsolete artefact from
> > printk_deferred(). It opens the door for another big cleanup and
> > relief.
> 
> do you mean that, once alt_printk is done properly, we can drop
> printk_deferred()? I was thinking of it, but decided not to
> mention/touch it in this patch set.

My understanding is the following:

The difference between normal printk() and printk_deferred() is
that the other does not call console_trylock()/console_unlock().
It means that printk_deferred() can avoid recursion only from these
two calls.

printk_deferred() is used only in scheduler and timekeeping code.
Therefore it prevents only limited number of possible recursions
and deadlocks at the moment.

This patch guards most of the two calls a more generic way.
The redirected parts prevent recursion not only to into the
code guarded by console_sem but also into parts guarded
by lockbuf_lock.

By other words, this patch is supposed to handle a superset
of the deadlocks that are currently prevented by printk_deferred().
If this is true, we do not longer need printk_deferred().

The only question is if this patch guards enough parts of
console_try_lock()/console_unlock() to handle the superset
of the possible deadlocks.

I see that it does not guard two up_console_sem() calls
from console_unlock(). But this can be fixed in the next
version.

Or is there any other catch that I do not see at the moment?

In each case, getting rid of printk_deferred() could be
a fantastic selling point for this patchset.

Best Regards,
Petr

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

#1494340 — Re: [RFC][PATCH 6/7] printk: use alternative printk buffers

On (09/30/16 13:15), Petr Mladek wrote:
[..]
> > and the decision was to keep `unsigned long flags' on stack in the
> > alt_enter/exit caller. besides in most of the cases we already have
> > it (in vprintk_emit() and console_unlock()).
> 
> I would pass the pointer to flags as alt_enter() parameter.

can do. or _may be_ leave the IRQ manipulation as it is. because there
are different tricks. take a look at console_ulock() and so on.

> > do you mean that, once alt_printk is done properly, we can drop
> > printk_deferred()? I was thinking of it, but decided not to
> > mention/touch it in this patch set.
> 
> My understanding is the following:
> 
> The difference between normal printk() and printk_deferred() is
> that the other does not call console_trylock()/console_unlock().
> It means that printk_deferred() can avoid recursion only from these
> two calls.

yes.

> printk_deferred() is used only in scheduler and timekeeping code.
> Therefore it prevents only limited number of possible recursions
> and deadlocks at the moment.
> 
> This patch guards most of the two calls a more generic way.
> The redirected parts prevent recursion not only to into the
> code guarded by console_sem but also into parts guarded
> by lockbuf_lock.

yes. I'm considering to extend it to "non-recursive printk" cases
sometime in the future. it's easy to protect lockbuf_lock, but not
so easy to protect sleeping console_lock().

the cases I'm talking of are (for instance):

  devkmsg_open()
   raw_spin_lock_irq(&logbuf_lock)
    spin_dump()
     printk()
      raw_spin_lock_irq(&logbuf_lock)  << deadlock

entering to alt_printk mode each time we take the `logbuf_lock' sort
of makes sense. can be done later, don't want to overload this patch set.

addressing sleeping console_sem function is not super hard in general.
we just would have to put alt_printk_enter/exit into scheduler code, or
at least into semaphore code. which can be hard to sell. there are
gazillions of semaphores and we need to protect only one of them, but
have to do alt_printk_enter/exit for every.

> By other words, this patch is supposed to handle a superset
> of the deadlocks that are currently prevented by printk_deferred().
> If this is true, we do not longer need printk_deferred().

yes, I suppose so.
the only difference here is that printk_deferred() immediately puts the
message into logbuf (well, *if* it can lock the `logbuf_lock'), while
vprintk_alt() puts it into per-cpu buffer first and needs an irq work in
that CPU to flush it to logbuf. OTOH, vprintk_alt() does not depend on
`logbuf_lock'.

> The only question is if this patch guards enough parts of
> console_try_lock()/console_unlock() to handle the superset
> of the possible deadlocks.
> 
> I see that it does not guard two up_console_sem() calls
> from console_unlock(). But this can be fixed in the next
> version.
>
> Or is there any other catch that I do not see at the moment?

it's a bit tricky. we break from printing loop only with logbuf_lock
spin_lock locked, irqs disabled and in alt_printk mode. so everything
after the printing loop is still protected, up until

	raw_spin_lock(&logbuf_lock);
	retry = console_seq != log_next_seq;
	raw_spin_unlock(&logbuf_lock);
	alt_printk_exit();
	local_irq_restore(flags);

> In each case, getting rid of printk_deferred() could be
> a fantastic selling point for this patchset.

agree.

I also suspect that we can eliminate the recursion detection logic
in vprintk_emit().

	-ss

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

#1495401 — Re: [RFC][PATCH 6/7] printk: use alternative printk buffers

On Sat 2016-10-01 11:48:29, Sergey Senozhatsky wrote:
> On (09/30/16 13:15), Petr Mladek wrote:
> > > do you mean that, once alt_printk is done properly, we can drop
> > > printk_deferred()? I was thinking of it, but decided not to
> > > mention/touch it in this patch set.
> > 
> > My understanding is the following:
> > 
> > The difference between normal printk() and printk_deferred() is
> > that the other does not call console_trylock()/console_unlock().
> > It means that printk_deferred() can avoid recursion only from these
> > two calls.
> 
> yes.
> 
> > printk_deferred() is used only in scheduler and timekeeping code.
> > Therefore it prevents only limited number of possible recursions
> > and deadlocks at the moment.
> > 
> > This patch guards most of the two calls a more generic way.
> > The redirected parts prevent recursion not only to into the
> > code guarded by console_sem but also into parts guarded
> > by lockbuf_lock.
> 
> yes. I'm considering to extend it to "non-recursive printk" cases
> sometime in the future. it's easy to protect lockbuf_lock, but not
> so easy to protect sleeping console_lock().
> 
> the cases I'm talking of are (for instance):
> 
>   devkmsg_open()
>    raw_spin_lock_irq(&logbuf_lock)
>     spin_dump()
>      printk()
>       raw_spin_lock_irq(&logbuf_lock)  << deadlock

I have finally got it. You are right, there are still some other
possible deadlocks.

But these are not protected at the moment. Neither printk_deferred()
not logbuf_cpu prevent this. Therefore this is not a reason to keep
either printk_deferred() or logbuf_cpu.


> entering to alt_printk mode each time we take the `logbuf_lock' sort
> of makes sense. can be done later, don't want to overload this patch set.

I agree that it does not make sense to solve these other problems in
this patchset.


> addressing sleeping console_sem function is not super hard in general.
> we just would have to put alt_printk_enter/exit into scheduler code, or
> at least into semaphore code. which can be hard to sell. there are
> gazillions of semaphores and we need to protect only one of them, but
> have to do alt_printk_enter/exit for every.

Yeah, so a generic solution for console_sem might be rather hard.
I would not complicate this patchset with it.


> > By other words, this patch is supposed to handle a superset
> > of the deadlocks that are currently prevented by printk_deferred().
> > If this is true, we do not longer need printk_deferred().
> 
> yes, I suppose so.
> the only difference here is that printk_deferred() immediately puts the
> message into logbuf (well, *if* it can lock the `logbuf_lock'), while
> vprintk_alt() puts it into per-cpu buffer first and needs an irq work in
> that CPU to flush it to logbuf. OTOH, vprintk_alt() does not depend on
> `logbuf_lock'.

On the other hand, the per-CPU buffer will include only error
messages from the printk() code. This is why I am fine with
the extra buffer. The only way is to use printk_deferred()
these days. And as you said, this was error prone and hard
to maintain.


> > The only question is if this patch guards enough parts of
> > console_try_lock()/console_unlock() to handle the superset
> > of the possible deadlocks.
> > 
> > I see that it does not guard two up_console_sem() calls
> > from console_unlock(). But this can be fixed in the next
> > version.
> >
> > Or is there any other catch that I do not see at the moment?
> 
> it's a bit tricky. we break from printing loop only with logbuf_lock
> spin_lock locked, irqs disabled and in alt_printk mode. so everything
> after the printing loop is still protected, up until
> 
> 	raw_spin_lock(&logbuf_lock);
> 	retry = console_seq != log_next_seq;
> 	raw_spin_unlock(&logbuf_lock);
> 	alt_printk_exit();
> 	local_irq_restore(flags);

Yes, but we are safe to call normal printk() at this point.
lockbuf_lock is released => no danger of a deadlock.
console_sem is taken but this is not a problem. printk()
will do console_trylock() protected by the alt_printk_enter()/exit().
Therefore the trylock will fail but it could not cause a deadlock.

We just need to replace

	if (retry && console_trylock())
		goto again;

with a safe variant, something like

	if (retry) {
		local_irq_save(flags);
		alt_printk_enter();
		lock_failed = console_trylock();
		alt_printk_exit();
		local_irq_restore(flags);

		if (!lock_failed)
			goto again;
	}

Or do I miss anything?

> > In each case, getting rid of printk_deferred() could be
> > a fantastic selling point for this patchset.
> 
> agree.

I believe that it is doable and worth try.

I am going to look at the second version of the patchset.

Best Regards,
Petr

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

#1495662 — Re: [RFC][PATCH 6/7] printk: use alternative printk buffers

On (10/04/16 14:22), Petr Mladek wrote:
[..]
> 	if (retry && console_trylock())
> 		goto again;
> 
> with a safe variant, something like
> 
> 	if (retry) {
> 		local_irq_save(flags);
> 		alt_printk_enter();
> 		lock_failed = console_trylock();
> 		alt_printk_exit();
> 		local_irq_restore(flags);
> 
> 		if (!lock_failed)
> 			goto again;
> 	}
> 
> Or do I miss anything?

nope, you don't. that's close to what I do in v3.

> I am going to look at the second version of the patchset.

thanks a lot for your review!

I'll refresh the patch set a bit later this week. I think it's more
or less in shape now.... well, still under the old name: alt_printk.

	-ss

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

#1495797 — Re: [RFC][PATCH 6/7] printk: use alternative printk buffers

On Wed 2016-10-05 10:36:57, Sergey Senozhatsky wrote:
> On (10/04/16 14:22), Petr Mladek wrote:
> [..]
> > 	if (retry && console_trylock())
> > 		goto again;
> > 
> > with a safe variant, something like
> > 
> > 	if (retry) {
> > 		local_irq_save(flags);
> > 		alt_printk_enter();
> > 		lock_failed = console_trylock();
> > 		alt_printk_exit();
> > 		local_irq_restore(flags);
> > 
> > 		if (!lock_failed)
> > 			goto again;
> > 	}
> > 
> > Or do I miss anything?
> 
> nope, you don't. that's close to what I do in v3.
> 
> > I am going to look at the second version of the patchset.
> 
> thanks a lot for your review!
> 
> I'll refresh the patch set a bit later this week. I think it's more
> or less in shape now.... well, still under the old name: alt_printk.

Note that I have stopped reviewing v2 after realizing that it
did not help to get rid of printk_deferred().

I would like to revisit the usefulness of this approach first.
The motivation at
https://lkml.kernel.org/r/20160928011845.GA753@swordfish
does not longer fly. We will still need to maintain all
the printk_deferred()/WARN_*DEFERRED calls.

Also let me to reply to the mail
https://lkml.kernel.org/r/20160930004832.GA547@swordfish
The examples do not look real to me.

I am not sure what is the real group of fixed problems
at the moment.

I am sad when writing this. I was really optimistic
about this patchset.

Best Regards,
Petr

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

#1494727 — Re: [RFC][PATCH 6/7] printk: use alternative printk buffers

On (09/30/16 13:15), Petr Mladek wrote:
[..]
> > and the decision was to keep `unsigned long flags' on stack in the
> > alt_enter/exit caller. besides in most of the cases we already have
> > it (in vprintk_emit() and console_unlock()).
> 
> I would pass the pointer to flags as alt_enter() parameter.

I think I'll do something like this

--

void __alt_printk_enter(void);
void __alt_printk_exit(void);

#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)

--

seems that this mostly will fit our needs in printk().
for anything that does not fit -- we have __alt_printk_enter()/exit().


and I'll also extend alt_printk more, some additional paths.

I'm also thinking about your rename proposal, but didn't find
a perfect name yet.

	-ss

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

#1495467 — Re: [RFC][PATCH 6/7] printk: use alternative printk buffers

On Fri 2016-09-30 13:15:46, Petr Mladek wrote:
> On Fri 2016-09-30 10:15:44, Sergey Senozhatsky wrote:
> > On (09/29/16 15:00), Petr Mladek wrote:
> > [..]
> > > > @@ -1791,7 +1791,7 @@ asmlinkage int vprintk_emit(int facility, int level,
> > > >  		zap_locks();
> > > >  	}
> > > >  
> > > > -	lockdep_off();
> > > > +	alt_printk_enter();
> > > 
> > > IMHO, we could not longer enter vprintk_emit() recursively. The same
> > > section that was guarded by logbuf_cpu is guarded by
> > > alt_printk_enter()/exit() now.
> > 
> > you might be very right here. I'll take a look.
> > 
> > > IMHO, we could remove all the logic around the recursion. Then we
> > > could even disable/enable irqs inside alt_printk_enter()/exit().
> > 
> > I was thinking of doing something like this; but that would require
> > storing 'unsigned long' flags in per-cpu data
> > 
> > 	alt_enter()
> > 	{
> > 		unsinged long flags;
> > 
> > 		local_irq_save(flags);
> > 		ctx = this_cpu_ptr();
> > 		ctx->flags = flags;
> > 		...
> > 	}
> > 
> > 	alt_exit()
> > 	{
> > 		ctx = this_cpu_ptr();
> > 		...
> > 		local_irq_restore(ctx->flags);
> > 	}
> >
> > and the decision was to keep `unsigned long flags' on stack in the
> > alt_enter/exit caller. besides in most of the cases we already have
> > it (in vprintk_emit() and console_unlock()).
> 
> I would pass the pointer to flags as alt_enter() parameter.
> > 
> > but I can certainly hide these details in alt_enter/exit.
> >
> > > > @@ -2479,7 +2490,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);
> > > 
> > > We should mention that this patch makes an obsolete artefact from
> > > printk_deferred(). It opens the door for another big cleanup and
> > > relief.
> > 
> > do you mean that, once alt_printk is done properly, we can drop
> > printk_deferred()? I was thinking of it, but decided not to
> > mention/touch it in this patch set.
> 
> My understanding is the following:
> 
> The difference between normal printk() and printk_deferred() is
> that the other does not call console_trylock()/console_unlock().
> It means that printk_deferred() can avoid recursion only from these
> two calls.
> 
> printk_deferred() is used only in scheduler and timekeeping code.
> Therefore it prevents only limited number of possible recursions
> and deadlocks at the moment.
> 
> This patch guards most of the two calls a more generic way.
> The redirected parts prevent recursion not only to into the
> code guarded by console_sem but also into parts guarded
> by lockbuf_lock.
> 
> By other words, this patch is supposed to handle a superset
> of the deadlocks that are currently prevented by printk_deferred().
> If this is true, we do not longer need printk_deferred().
> 
> The only question is if this patch guards enough parts of
> console_try_lock()/console_unlock() to handle the superset
> of the possible deadlocks.
> 
> I see that it does not guard two up_console_sem() calls
> from console_unlock(). But this can be fixed in the next
> version.
> 
> Or is there any other catch that I do not see at the moment?

And there is :-( The above logic looked at the problem only from
one side. It was about errors starting from the printk()
code itself, for example:

 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


But it does no solve errors starting in the scheduler or
timekeeping code. I mean:

   any_function_waking_process()
    wake_up_process()
     try_to_wake_up()  // takes &p->pi_lock
      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()   // success
	       console_unlock()
	         up_console_sem()
		  up()
		    __up()
		     wake_up_process()
		      try_to_wake_up()
		       raw_spin_lock_irqsave(&p->pi_lock, flags);
		       ^^^^ deadlock

The only thing that might help here is to call
alt_printk_enter()/exit() in wake_up_process() itself. Otherwise,
we still would need to keep the printk_deferred() stuff.

By other words, we might need to put alt_printk_enter()/exit()
into the scheduler and timekeeping code. In theory it might
be easier to maintain than the separated printk_deferred() calls.
But there might be some catches because we need to disable
the interrupts, ...

Sigh, this 2nd scenario is much more likely than the 1st one.
I guess that warnings in the scheduler/timekeeping code
will be triggered outside printk() most of the time.

It means that this approach might be much harder to sell
after all :-(

Best Regards,
Petr

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

#1495660 — Re: [RFC][PATCH 6/7] printk: use alternative printk buffers

On (10/04/16 16:52), Petr Mladek wrote:
> > 
> > Or is there any other catch that I do not see at the moment?
> 
> And there is :-( The above logic looked at the problem only from
> one side. It was about errors starting from the printk()
> code itself, for example:

yes, like I said - printk recursion and printk deadlock are different
things. and recursion cases are a subset of deadlock cases.

> The only thing that might help here is to call
> alt_printk_enter()/exit() in wake_up_process() itself. Otherwise,
> we still would need to keep the printk_deferred() stuff.

yes.
or
- combine alt_printk and DEFERRED_WARN/etc.
or
- rewrite printk() to be lock-less by default (for all invocations).

> By other words, we might need to put alt_printk_enter()/exit()
> into the scheduler and timekeeping code. In theory it might
> be easier to maintain than the separated printk_deferred() calls.
> But there might be some catches because we need to disable
> the interrupts, ...

right. and I have some doubts that people will be willing to put
alt_printk_enter/exit into those hot paths.


> Sigh, this 2nd scenario is much more likely than the 1st one.
> I guess that warnings in the scheduler/timekeeping code
> will be triggered outside printk() most of the time.

hm. may be. but the reports we received so far starts from printk()
and end up in printk() - IOW, recursion.

> It means that this approach might be much harder to sell
> after all :-(

well, it solves a number of problems that the existing implementation
cannot handle.

would have been nice to cover all of the cases, but that's a bit hard.

	-ss

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

#1495787 — Re: [RFC][PATCH 6/7] printk: use alternative printk buffers

On Wed 2016-10-05 10:27:14, Sergey Senozhatsky wrote:
> On (10/04/16 16:52), Petr Mladek wrote:
> > > 
> > > Or is there any other catch that I do not see at the moment?
> > 
> > And there is :-( The above logic looked at the problem only from
> > one side. It was about errors starting from the printk()
> > code itself, for example:
> 
> yes, like I said - printk recursion and printk deadlock are different
> things. and recursion cases are a subset of deadlock cases.

I see.

> > The only thing that might help here is to call
> > alt_printk_enter()/exit() in wake_up_process() itself. Otherwise,
> > we still would need to keep the printk_deferred() stuff.
> 
> yes.
> or
> - combine alt_printk and DEFERRED_WARN/etc.

The question is if alt_printk brings any win after all, see below.


> or
> - rewrite printk() to be lock-less by default (for all invocations).

We already have it and it is called trace_printk(). But it is very
tricky and have some limitations. For example, it does not support
random parallel readers. Also printing the trace log is noticeably
slow.


> > By other words, we might need to put alt_printk_enter()/exit()
> > into the scheduler and timekeeping code. In theory it might
> > be easier to maintain than the separated printk_deferred() calls.
> > But there might be some catches because we need to disable
> > the interrupts, ...
> 
> right. and I have some doubts that people will be willing to put
> alt_printk_enter/exit into those hot paths.

I have the same doubts.


> > Sigh, this 2nd scenario is much more likely than the 1st one.
> > I guess that warnings in the scheduler/timekeeping code
> > will be triggered outside printk() most of the time.
> 
> hm. may be. but the reports we received so far starts from printk()
> and end up in printk() - IOW, recursion.

My statement might have been too strong. Well, my thinking was
the following:

I am not aware of any real life bug reports caused by recursion
inside locbuf_lock garded section. I guess that it is because
the most sensitive one is guarded by that logbuf_cpu check.

I am not aware of any generic recursions inside the console code.
In fact, it is not easily possible because we console_trylock().
It means that we do not call console if it is already being handled.

We are basically down to the recursion/deadlock caused by the
wake_up_process() call. And there are much more such calls outside
printk().

In fact, I am aware only about one report. It was related to the
async printk patchset, the added wake_up_process(), and used
RT scheduler. This one started from printk() almost by definition.


> > It means that this approach might be much harder to sell
> > after all :-(
> 
> well, it solves a number of problems that the existing implementation
> cannot handle.

Please, provide a summary. I wonder if these are real life problems.

Note that we need to put aside all problems that are solvable
with printk_deferred(). It seems that printk_deferred() will
need to stay because it avoids the deadlock caused by
scheduler/timekeeping code locks. By other words, if there
is a missing printk_deferred() we need to put it there
anyway because the same code might get first called
outside printk().

Or do I miss something?

Best Regards,
Petr

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

Page 1 of 2  [1] 2  Next page →

Back to top | Article view | linux.kernel

csiph-web