All of lore.kernel.org
 help / color / mirror / Atom feed
From: Sergey Senozhatsky <sergey.senozhatsky@gmail.com>
To: Petr Mladek <pmladek@suse.com>, Jan Kara <jack@suse.cz>
Cc: Andrew Morton <akpm@linux-foundation.org>,
	Tejun Heo <tj@kernel.org>, Calvin Owens <calvinowens@fb.com>,
	linux-kernel@vger.kernel.org,
	Sergey Senozhatsky <sergey.senozhatsky@gmail.com>,
	Sergey Senozhatsky <sergey.senozhatsky.work@gmail.com>
Subject: [RFC][PATCH 6/7] printk: use alternative printk buffers
Date: Tue, 27 Sep 2016 23:22:36 +0900	[thread overview]
Message-ID: <20160927142237.5539-7-sergey.senozhatsky@gmail.com> (raw)
In-Reply-To: <20160927142237.5539-1-sergey.senozhatsky@gmail.com>

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

  parent reply	other threads:[~2016-09-27 14:24 UTC|newest]

Thread overview: 35+ messages / expand[flat|nested]  mbox.gz  Atom feed  top
2016-09-27 14:22 [RFC][PATCH 0/7] printk: use alt_printk to handle printk() recursive calls Sergey Senozhatsky
2016-09-27 14:22 ` [RFC][PATCH 1/7] printk: use vprintk_func in vprintk() Sergey Senozhatsky
2016-09-27 14:22 ` [RFC][PATCH 2/7] printk: rename nmi.c and exported api Sergey Senozhatsky
2016-09-27 14:22 ` [RFC][PATCH 3/7] printk: introduce per-cpu alt_print seq buffer Sergey Senozhatsky
2016-09-29 12:26   ` Petr Mladek
2016-09-30  1:05     ` Sergey Senozhatsky
2016-09-30 11:35       ` Petr Mladek
2016-09-27 14:22 ` [RFC][PATCH 4/7] printk: make alt_printk available when config printk set Sergey Senozhatsky
2016-09-27 14:22 ` [RFC][PATCH 5/7] printk: drop vprintk_func function Sergey Senozhatsky
2016-09-27 14:22 ` Sergey Senozhatsky [this message]
2016-09-29 13:00   ` [RFC][PATCH 6/7] printk: use alternative printk buffers Petr Mladek
2016-09-30  1:15     ` Sergey Senozhatsky
2016-09-30 11:15       ` Petr Mladek
2016-10-01  2:48         ` Sergey Senozhatsky
2016-10-04 12:22           ` Petr Mladek
2016-10-05  1:36             ` Sergey Senozhatsky
2016-10-05 10:18               ` Petr Mladek
2016-10-03  7:53         ` Sergey Senozhatsky
2016-10-04 14:52         ` Petr Mladek
2016-10-05  1:27           ` Sergey Senozhatsky
2016-10-05  9:50             ` Petr Mladek
2016-10-06  4:22               ` Sergey Senozhatsky
2016-10-06 11:32                 ` Petr Mladek
2016-10-10  4:09                   ` Sergey Senozhatsky
2016-10-10 11:17                     ` Petr Mladek
2016-10-11  7:35                       ` Sergey Senozhatsky
2016-10-11  9:30                         ` Petr Mladek
2016-09-27 14:22 ` [RFC][PATCH 7/7] printk: new printk() recursion detection Sergey Senozhatsky
2016-09-29 13:19   ` Petr Mladek
2016-09-30  2:00     ` Sergey Senozhatsky
2016-09-29 13:25 ` [RFC][PATCH 0/7] printk: use alt_printk to handle printk() recursive calls Petr Mladek
2016-09-30  2:43   ` Sergey Senozhatsky
2016-09-30 11:27     ` Petr Mladek
2016-10-01  3:02       ` Sergey Senozhatsky
2016-10-04 11:35         ` Petr Mladek

Reply instructions:

You may reply publicly to this message via plain-text email
using any one of the following methods:

* Save the following mbox file, import it into your mail client,
  and reply-to-all from there: mbox

  Avoid top-posting and favor interleaved quoting:
  https://en.wikipedia.org/wiki/Posting_style#Interleaved_style

* Reply using the --to, --cc, and --in-reply-to
  switches of git-send-email(1):

  git send-email \
    --in-reply-to=20160927142237.5539-7-sergey.senozhatsky@gmail.com \
    --to=sergey.senozhatsky@gmail.com \
    --cc=akpm@linux-foundation.org \
    --cc=calvinowens@fb.com \
    --cc=jack@suse.cz \
    --cc=linux-kernel@vger.kernel.org \
    --cc=pmladek@suse.com \
    --cc=sergey.senozhatsky.work@gmail.com \
    --cc=tj@kernel.org \
    /path/to/YOUR_REPLY

  https://kernel.org/pub/software/scm/git/docs/git-send-email.html

* If your mail client supports setting the In-Reply-To header
  via mailto: links, try the mailto: link
Be sure your reply has a Subject: header at the top and a blank line before the message body. 
This is an external index of several public inboxes,
see mirroring instructions on how to clone and mirror
all data and code used by this external index.