lockdep warning after recent cleanup in console code

lockdep warning after recent cleanup in console code

[Shevchenko, Andriy]

[-- Warning: decoded text below may be mangled, UTF-8 assumed --]
[-- Attachment #1: Type: text/plain; charset="utf-8", Size: 4547 bytes --]

Hei!

During weekend the linux-next was being broken by introducing a lockdep
warning in the console code

[    0.000000] BIOS-e820: [mem 0x00000000e0000000-0x00000000ffffffff]
reserved
[    0.000000]
[    0.000000] =============================================
[    0.000000] [ INFO: possible recursive locking detected ]
[    0.000000] 3.15.0-rc2-next-20140428-00030-gd3550d8 #38 Not tainted
[    0.000000] ---------------------------------------------
[    0.000000] swapper/0 is trying to acquire lock:
[    0.000000]  (console_lock){......}, at: [<c10728cc>]
register_console+0x15e/0x295
[    0.000000]
[    0.000000] but task is already holding lock:
[    0.000000]  (console_lock){......}, at: [<c1071e7a>] vprintk_emit
+0x381/0x3ea
[    0.000000]
[    0.000000] other info that might help us debug this:
[    0.000000]  Possible unsafe locking scenario:
[    0.000000]
[    0.000000]        CPU0
[    0.000000]        ----
[    0.000000]   lock(console_lock);
[    0.000000]   lock(console_lock);
[    0.000000]
[    0.000000]  *** DEADLOCK ***
[    0.000000]
[    0.000000]  May be due to missing lock nesting notation
[    0.000000]
[    0.000000] 3 locks held by swapper/0:
[    0.000000]  #0:  (console_lock){......}, at: [<c1071e7a>]
vprintk_emit+0x381/0x3ea
[    0.000000]  #1:  (console_lock){......}, at: [<c1071e7a>]
vprintk_emit+0x381/0x3ea
[    0.000000]  #2:  (console_lock){......}, at: [<c1071e7a>]
vprintk_emit+0x381/0x3ea
[    0.000000]
[    0.000000] stack backtrace:
[    0.000000] CPU: 0 PID: 0 Comm: swapper Not tainted
3.15.0-rc2-next-20140428-00030-gd3550d8 #38
[    0.000000]  00000000 00000000 c186de1c c15878ae c1daf840 c186de88
c106c154 c1794d9d
[    0.000000]  c17958f7 c1794c9c 0000002a 00000000 00000000 c1daf840
c1983700 00000080
[    0.000000]  04002001 c187a0b0 00000000 c1879ba0 c1879b40 c1879b40
00200046 00000000
[    0.000000] Call Trace:
[    0.000000]  [<c15878ae>] dump_stack+0x49/0x73
[    0.000000]  [<c106c154>] __lock_acquire+0xb31/0xc7c
[    0.000000]  [<c106c33b>] lock_acquire+0x9c/0x111
[    0.000000]  [<c10728cc>] ? register_console+0x15e/0x295
[    0.000000]  [<c10707dd>] console_lock+0x41/0x46
[    0.000000]  [<c10728cc>] ? register_console+0x15e/0x295
[    0.000000]  [<c10728cc>] register_console+0x15e/0x295
[    0.000000]  [<c1582f80>] early_console_register+0x33/0x35
[    0.000000]  [<c1910411>] setup_early_printk+0x144/0x151
[    0.000000]  [<c19013f6>] do_early_param+0x41/0x73
[    0.000000]  [<c19013b5>] ? loglevel+0x2c/0x2c
[    0.000000]  [<c104c766>] parse_args+0x24f/0x307
[    0.000000]  [<c19013b5>] ? loglevel+0x2c/0x2c
[    0.000000]  [<c190169d>] parse_early_options+0x1c/0x21
[    0.000000]  [<c190169d>] ? parse_early_options+0x1c/0x21
[    0.000000]  [<c19013b5>] ? loglevel+0x2c/0x2c
[    0.000000]  [<c19016cc>] parse_early_param+0x2a/0x36
[    0.000000]  [<c19042c0>] setup_arch+0x3c9/0xc55
[    0.000000]  [<c1071ebe>] ? vprintk_emit+0x3c5/0x3ea
[    0.000000]  [<c1584869>] ? printk+0x28/0x2d
[    0.000000]  [<c1901754>] start_kernel+0x72/0x305
[    0.000000]  [<c19012b4>] i386_start_kernel+0x82/0x86
[    0.000000] bootconsole [earlyhsu0] enabled

Bisecting shows the culprit (which I guessed before), namely commit
5dc90cb49691755faaad2a395d297d0162075eca ("printk: enable interrupts 
before calling console_trylock_for_printk()").

Following patch helps me, but I'm not familiar with console locking
scheme, I believe there is a better solution.

--- a/kernel/printk/printk.c
+++ b/kernel/printk/printk.c
@@ -1700,8 +1700,10 @@ asmlinkage int vprintk_emit(int facility, int
level,
         * The release will print out buffers and wake up /dev/kmsg and
syslog()
         * users.
         */
+       lockdep_off();
        if (console_trylock_for_printk())
                console_unlock();
+       lockdep_on();
        preempt_enable();
 
        return printed_len;


-- 
Andy Shevchenko <andriy.shevchenko@intel.com>
Intel Finland Oy
---------------------------------------------------------------------
Intel Finland Oy
Registered Address: PL 281, 00181 Helsinki 
Business Identity Code: 0357606 - 4 
Domiciled in Helsinki 

This e-mail and any attachments may contain confidential material for
the sole use of the intended recipient(s). Any review or distribution
by others is strictly prohibited. If you are not the intended
recipient, please contact the sender and delete all copies.
ÿôèº{.nÇ+‰·Ÿ®‰­†+%ŠËÿ±éݶ\x17¥Šwÿº{.nÇ+‰·¥Š{±þG«éÿŠ{ayº\x1dʇڙë,j\a­¢f£¢·hšïêÿ‘êçz_è®\x03(­éšŽŠÝ¢j"ú\x1a¶^[m§ÿÿ¾\a«þG«éÿ¢¸?™¨è­Ú&£ø§~á¶iO•æ¬z·švØ^\x14\x04\x1a¶^[m§ÿÿÃ\fÿ¶ìÿ¢¸?–I¥

Re: lockdep warning after recent cleanup in console code

[Steven Rostedt]

Peter,

Things have changed with regard to printk() in linux-next. Now it
appears that lockdep is going haywire over it. I don't understand the
exact reason for the lockdep_off() and lockdep_on() logic that is in
printk(), but it obviously seems to be causing issues with the new
changes.

Care to take a look?

-- Steve


On Mon, 28 Apr 2014 16:35:26 +0000
"Shevchenko, Andriy" <andriy.shevchenko@intel.com> wrote:

> Hei!
> 
> During weekend the linux-next was being broken by introducing a lockdep
> warning in the console code
> 
> [    0.000000] BIOS-e820: [mem 0x00000000e0000000-0x00000000ffffffff]
> reserved
> [    0.000000]
> [    0.000000] =============================================
> [    0.000000] [ INFO: possible recursive locking detected ]
> [    0.000000] 3.15.0-rc2-next-20140428-00030-gd3550d8 #38 Not tainted
> [    0.000000] ---------------------------------------------
> [    0.000000] swapper/0 is trying to acquire lock:
> [    0.000000]  (console_lock){......}, at: [<c10728cc>]
> register_console+0x15e/0x295
> [    0.000000]
> [    0.000000] but task is already holding lock:
> [    0.000000]  (console_lock){......}, at: [<c1071e7a>] vprintk_emit
> +0x381/0x3ea
> [    0.000000]
> [    0.000000] other info that might help us debug this:
> [    0.000000]  Possible unsafe locking scenario:
> [    0.000000]
> [    0.000000]        CPU0
> [    0.000000]        ----
> [    0.000000]   lock(console_lock);
> [    0.000000]   lock(console_lock);
> [    0.000000]
> [    0.000000]  *** DEADLOCK ***
> [    0.000000]
> [    0.000000]  May be due to missing lock nesting notation
> [    0.000000]
> [    0.000000] 3 locks held by swapper/0:
> [    0.000000]  #0:  (console_lock){......}, at: [<c1071e7a>]
> vprintk_emit+0x381/0x3ea
> [    0.000000]  #1:  (console_lock){......}, at: [<c1071e7a>]
> vprintk_emit+0x381/0x3ea
> [    0.000000]  #2:  (console_lock){......}, at: [<c1071e7a>]
> vprintk_emit+0x381/0x3ea
> [    0.000000]
> [    0.000000] stack backtrace:
> [    0.000000] CPU: 0 PID: 0 Comm: swapper Not tainted
> 3.15.0-rc2-next-20140428-00030-gd3550d8 #38
> [    0.000000]  00000000 00000000 c186de1c c15878ae c1daf840 c186de88
> c106c154 c1794d9d
> [    0.000000]  c17958f7 c1794c9c 0000002a 00000000 00000000 c1daf840
> c1983700 00000080
> [    0.000000]  04002001 c187a0b0 00000000 c1879ba0 c1879b40 c1879b40
> 00200046 00000000
> [    0.000000] Call Trace:
> [    0.000000]  [<c15878ae>] dump_stack+0x49/0x73
> [    0.000000]  [<c106c154>] __lock_acquire+0xb31/0xc7c
> [    0.000000]  [<c106c33b>] lock_acquire+0x9c/0x111
> [    0.000000]  [<c10728cc>] ? register_console+0x15e/0x295
> [    0.000000]  [<c10707dd>] console_lock+0x41/0x46
> [    0.000000]  [<c10728cc>] ? register_console+0x15e/0x295
> [    0.000000]  [<c10728cc>] register_console+0x15e/0x295
> [    0.000000]  [<c1582f80>] early_console_register+0x33/0x35
> [    0.000000]  [<c1910411>] setup_early_printk+0x144/0x151
> [    0.000000]  [<c19013f6>] do_early_param+0x41/0x73
> [    0.000000]  [<c19013b5>] ? loglevel+0x2c/0x2c
> [    0.000000]  [<c104c766>] parse_args+0x24f/0x307
> [    0.000000]  [<c19013b5>] ? loglevel+0x2c/0x2c
> [    0.000000]  [<c190169d>] parse_early_options+0x1c/0x21
> [    0.000000]  [<c190169d>] ? parse_early_options+0x1c/0x21
> [    0.000000]  [<c19013b5>] ? loglevel+0x2c/0x2c
> [    0.000000]  [<c19016cc>] parse_early_param+0x2a/0x36
> [    0.000000]  [<c19042c0>] setup_arch+0x3c9/0xc55
> [    0.000000]  [<c1071ebe>] ? vprintk_emit+0x3c5/0x3ea
> [    0.000000]  [<c1584869>] ? printk+0x28/0x2d
> [    0.000000]  [<c1901754>] start_kernel+0x72/0x305
> [    0.000000]  [<c19012b4>] i386_start_kernel+0x82/0x86
> [    0.000000] bootconsole [earlyhsu0] enabled
> 
> Bisecting shows the culprit (which I guessed before), namely commit
> 5dc90cb49691755faaad2a395d297d0162075eca ("printk: enable interrupts 
> before calling console_trylock_for_printk()").
> 
> Following patch helps me, but I'm not familiar with console locking
> scheme, I believe there is a better solution.
> 
> --- a/kernel/printk/printk.c
> +++ b/kernel/printk/printk.c
> @@ -1700,8 +1700,10 @@ asmlinkage int vprintk_emit(int facility, int
> level,
>          * The release will print out buffers and wake up /dev/kmsg and
> syslog()
>          * users.
>          */
> +       lockdep_off();
>         if (console_trylock_for_printk())
>                 console_unlock();
> +       lockdep_on();
>         preempt_enable();
>  
>         return printed_len;
> 
> 

Re: lockdep warning after recent cleanup in console code

[Jan Kara]

On Mon 28-04-14 13:43:31, Steven Rostedt wrote:
> Things have changed with regard to printk() in linux-next. Now it
> appears that lockdep is going haywire over it. I don't understand the
> exact reason for the lockdep_off() and lockdep_on() logic that is in
> printk(), but it obviously seems to be causing issues with the new
> changes.
> 
> Care to take a look?
  The obvious cause is that I moved lockdep_on() somewhat earlier in
vprintk_emit() so lockdep now covers more of printk code. And apparently
something is wrong there...

								Honza
> 
> -- Steve
> 
> 
> On Mon, 28 Apr 2014 16:35:26 +0000
> "Shevchenko, Andriy" <andriy.shevchenko@intel.com> wrote:
> 
> > Hei!
> > 
> > During weekend the linux-next was being broken by introducing a lockdep
> > warning in the console code
> > 
> > [    0.000000] BIOS-e820: [mem 0x00000000e0000000-0x00000000ffffffff]
> > reserved
> > [    0.000000]
> > [    0.000000] =============================================
> > [    0.000000] [ INFO: possible recursive locking detected ]
> > [    0.000000] 3.15.0-rc2-next-20140428-00030-gd3550d8 #38 Not tainted
> > [    0.000000] ---------------------------------------------
> > [    0.000000] swapper/0 is trying to acquire lock:
> > [    0.000000]  (console_lock){......}, at: [<c10728cc>]
> > register_console+0x15e/0x295
> > [    0.000000]
> > [    0.000000] but task is already holding lock:
> > [    0.000000]  (console_lock){......}, at: [<c1071e7a>] vprintk_emit
> > +0x381/0x3ea
> > [    0.000000]
> > [    0.000000] other info that might help us debug this:
> > [    0.000000]  Possible unsafe locking scenario:
> > [    0.000000]
> > [    0.000000]        CPU0
> > [    0.000000]        ----
> > [    0.000000]   lock(console_lock);
> > [    0.000000]   lock(console_lock);
> > [    0.000000]
> > [    0.000000]  *** DEADLOCK ***
> > [    0.000000]
> > [    0.000000]  May be due to missing lock nesting notation
> > [    0.000000]
> > [    0.000000] 3 locks held by swapper/0:
> > [    0.000000]  #0:  (console_lock){......}, at: [<c1071e7a>]
> > vprintk_emit+0x381/0x3ea
> > [    0.000000]  #1:  (console_lock){......}, at: [<c1071e7a>]
> > vprintk_emit+0x381/0x3ea
> > [    0.000000]  #2:  (console_lock){......}, at: [<c1071e7a>]
> > vprintk_emit+0x381/0x3ea
> > [    0.000000]
> > [    0.000000] stack backtrace:
> > [    0.000000] CPU: 0 PID: 0 Comm: swapper Not tainted
> > 3.15.0-rc2-next-20140428-00030-gd3550d8 #38
> > [    0.000000]  00000000 00000000 c186de1c c15878ae c1daf840 c186de88
> > c106c154 c1794d9d
> > [    0.000000]  c17958f7 c1794c9c 0000002a 00000000 00000000 c1daf840
> > c1983700 00000080
> > [    0.000000]  04002001 c187a0b0 00000000 c1879ba0 c1879b40 c1879b40
> > 00200046 00000000
> > [    0.000000] Call Trace:
> > [    0.000000]  [<c15878ae>] dump_stack+0x49/0x73
> > [    0.000000]  [<c106c154>] __lock_acquire+0xb31/0xc7c
> > [    0.000000]  [<c106c33b>] lock_acquire+0x9c/0x111
> > [    0.000000]  [<c10728cc>] ? register_console+0x15e/0x295
> > [    0.000000]  [<c10707dd>] console_lock+0x41/0x46
> > [    0.000000]  [<c10728cc>] ? register_console+0x15e/0x295
> > [    0.000000]  [<c10728cc>] register_console+0x15e/0x295
> > [    0.000000]  [<c1582f80>] early_console_register+0x33/0x35
> > [    0.000000]  [<c1910411>] setup_early_printk+0x144/0x151
> > [    0.000000]  [<c19013f6>] do_early_param+0x41/0x73
> > [    0.000000]  [<c19013b5>] ? loglevel+0x2c/0x2c
> > [    0.000000]  [<c104c766>] parse_args+0x24f/0x307
> > [    0.000000]  [<c19013b5>] ? loglevel+0x2c/0x2c
> > [    0.000000]  [<c190169d>] parse_early_options+0x1c/0x21
> > [    0.000000]  [<c190169d>] ? parse_early_options+0x1c/0x21
> > [    0.000000]  [<c19013b5>] ? loglevel+0x2c/0x2c
> > [    0.000000]  [<c19016cc>] parse_early_param+0x2a/0x36
> > [    0.000000]  [<c19042c0>] setup_arch+0x3c9/0xc55
> > [    0.000000]  [<c1071ebe>] ? vprintk_emit+0x3c5/0x3ea
> > [    0.000000]  [<c1584869>] ? printk+0x28/0x2d
> > [    0.000000]  [<c1901754>] start_kernel+0x72/0x305
> > [    0.000000]  [<c19012b4>] i386_start_kernel+0x82/0x86
> > [    0.000000] bootconsole [earlyhsu0] enabled
> > 
> > Bisecting shows the culprit (which I guessed before), namely commit
> > 5dc90cb49691755faaad2a395d297d0162075eca ("printk: enable interrupts 
> > before calling console_trylock_for_printk()").
> > 
> > Following patch helps me, but I'm not familiar with console locking
> > scheme, I believe there is a better solution.
> > 
> > --- a/kernel/printk/printk.c
> > +++ b/kernel/printk/printk.c
> > @@ -1700,8 +1700,10 @@ asmlinkage int vprintk_emit(int facility, int
> > level,
> >          * The release will print out buffers and wake up /dev/kmsg and
> > syslog()
> >          * users.
> >          */
> > +       lockdep_off();
> >         if (console_trylock_for_printk())
> >                 console_unlock();
> > +       lockdep_on();
> >         preempt_enable();
> >  
> >         return printed_len;
> > 
> > 
> 
-- 
Jan Kara <jack@suse.cz>
SUSE Labs, CR

Re: lockdep warning after recent cleanup in console code

[Steven Rostedt]

On Mon, 28 Apr 2014 19:51:39 +0200
Jan Kara <jack@suse.cz> wrote:

> On Mon 28-04-14 13:43:31, Steven Rostedt wrote:
> > Things have changed with regard to printk() in linux-next. Now it
> > appears that lockdep is going haywire over it. I don't understand the
> > exact reason for the lockdep_off() and lockdep_on() logic that is in
> > printk(), but it obviously seems to be causing issues with the new
> > changes.
> > 
> > Care to take a look?
>   The obvious cause is that I moved lockdep_on() somewhat earlier in
> vprintk_emit() so lockdep now covers more of printk code. And apparently
> something is wrong there...
> 

Exactly, and I rather know *exactly* what is wrong before we just start
throwing patches at the problem and hope it goes away. That's not how
to solve a software bug.

-- Steve

Re: lockdep warning after recent cleanup in console code

[Peter Zijlstra]

On Mon, Apr 28, 2014 at 01:43:31PM -0400, Steven Rostedt wrote:
> 
> Peter,
> 
> Things have changed with regard to printk() in linux-next. Now it
> appears that lockdep is going haywire over it. I don't understand the
> exact reason for the lockdep_off() and lockdep_on() logic that is in
> printk(), but it obviously seems to be causing issues with the new
> changes.
> 
> Care to take a look?

https://lkml.org/lkml/2011/6/21/247

Re: lockdep warning after recent cleanup in console code

[Jan Kara]

[-- Attachment #1: Type: text/plain, Size: 1102 bytes --]

On Mon 28-04-14 14:14:39, Steven Rostedt wrote:
> On Mon, 28 Apr 2014 19:51:39 +0200
> Jan Kara <jack@suse.cz> wrote:
> 
> > On Mon 28-04-14 13:43:31, Steven Rostedt wrote:
> > > Things have changed with regard to printk() in linux-next. Now it
> > > appears that lockdep is going haywire over it. I don't understand the
> > > exact reason for the lockdep_off() and lockdep_on() logic that is in
> > > printk(), but it obviously seems to be causing issues with the new
> > > changes.
> > > 
> > > Care to take a look?
> >   The obvious cause is that I moved lockdep_on() somewhat earlier in
> > vprintk_emit() so lockdep now covers more of printk code. And apparently
> > something is wrong there...
> > 
> 
> Exactly, and I rather know *exactly* what is wrong before we just start
> throwing patches at the problem and hope it goes away. That's not how
> to solve a software bug.
  So I had a look and we are missing mutex_release() in
console_trylock_for_printk() if we don't have a console to print to.
Attached patch should fix the problem.

								Honza
-- 
Jan Kara <jack@suse.cz>
SUSE Labs, CR

[-- Attachment #2: 0001-printk-Fix-lockdep-instrumentation-of-console_sem.patch --]
[-- Type: text/x-patch, Size: 3383 bytes --]

>From e8cfbd7ec0f9a820ab38c3ce236940167fa82193 Mon Sep 17 00:00:00 2001
From: Jan Kara <jack@suse.cz>
Date: Mon, 28 Apr 2014 21:09:26 +0200
Subject: [PATCH] printk: Fix lockdep instrumentation of console_sem

Printk calls mutex_acquire() / mutex_release() by hand to instrument
lockdep about console_sem. However in some corner cases the
instrumentation is missing. Fix the problem by creating helper functions
for locking / unlocking console_sem which take care of lockdep
instrumentation as well.

Signed-off-by: Jan Kara <jack@suse.cz>
---
 kernel/printk/printk.c | 39 ++++++++++++++++++++++++++++-----------
 1 file changed, 28 insertions(+), 11 deletions(-)

diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
index 91c554e027c5..bcaab92fe7c0 100644
--- a/kernel/printk/printk.c
+++ b/kernel/printk/printk.c
@@ -1877,6 +1877,26 @@ module_param_named(console_suspend, console_suspend_enabled,
 MODULE_PARM_DESC(console_suspend, "suspend console during suspend"
 	" and hibernate operations");
 
+static inline void down_console_sem(void)
+{
+	down(&console_sem);
+	mutex_acquire(&console_lock_dep_map, 0, 0, _RET_IP_);
+}
+
+static inline int down_trylock_console_sem(void)
+{
+	if (down_trylock(&console_sem))
+		return 1;
+	mutex_acquire(&console_lock_dep_map, 0, 1, _RET_IP_);
+	return 0;
+}
+
+static inline void up_console_sem(void)
+{
+	mutex_release(&console_lock_dep_map, 1, _RET_IP_);
+	up(&console_sem);
+}
+
 /**
  * suspend_console - suspend the console subsystem
  *
@@ -1889,14 +1909,14 @@ void suspend_console(void)
 	printk("Suspending console(s) (use no_console_suspend to debug)\n");
 	console_lock();
 	console_suspended = 1;
-	up(&console_sem);
+	up_console_sem();
 }
 
 void resume_console(void)
 {
 	if (!console_suspend_enabled)
 		return;
-	down(&console_sem);
+	down_console_sem();
 	console_suspended = 0;
 	console_unlock();
 }
@@ -1938,12 +1958,11 @@ void console_lock(void)
 {
 	might_sleep();
 
-	down(&console_sem);
+	down_console_sem();
 	if (console_suspended)
 		return;
 	console_locked = 1;
 	console_may_schedule = 1;
-	mutex_acquire(&console_lock_dep_map, 0, 0, _RET_IP_);
 }
 EXPORT_SYMBOL(console_lock);
 
@@ -1957,15 +1976,14 @@ EXPORT_SYMBOL(console_lock);
  */
 int console_trylock(void)
 {
-	if (down_trylock(&console_sem))
+	if (down_trylock_console_sem())
 		return 0;
 	if (console_suspended) {
-		up(&console_sem);
+		up_console_sem();
 		return 0;
 	}
 	console_locked = 1;
 	console_may_schedule = 0;
-	mutex_acquire(&console_lock_dep_map, 0, 1, _RET_IP_);
 	return 1;
 }
 EXPORT_SYMBOL(console_trylock);
@@ -2027,7 +2045,7 @@ void console_unlock(void)
 	bool retry;
 
 	if (console_suspended) {
-		up(&console_sem);
+		up_console_sem();
 		return;
 	}
 
@@ -2089,7 +2107,6 @@ skip:
 		local_irq_restore(flags);
 	}
 	console_locked = 0;
-	mutex_release(&console_lock_dep_map, 1, _RET_IP_);
 
 	/* Release the exclusive_console once it is used */
 	if (unlikely(exclusive_console))
@@ -2097,7 +2114,7 @@ skip:
 
 	raw_spin_unlock(&logbuf_lock);
 
-	up(&console_sem);
+	up_console_sem();
 
 	/*
 	 * Someone could have filled up the buffer again, so re-check if there's
@@ -2142,7 +2159,7 @@ void console_unblank(void)
 	 * oops_in_progress is set to 1..
 	 */
 	if (oops_in_progress) {
-		if (down_trylock(&console_sem) != 0)
+		if (down_trylock_console_sem() != 0)
 			return;
 	} else
 		console_lock();
-- 
1.8.1.4

Re: lockdep warning after recent cleanup in console code

[Steven Rostedt]

On Mon, 28 Apr 2014 21:24:16 +0200
Jan Kara <jack@suse.cz> wrote:


>   So I had a look and we are missing mutex_release() in
> console_trylock_for_printk() if we don't have a console to print to.
> Attached patch should fix the problem.
> 

Note, your patch changes the logic a bit. It causes the
mutex_acquire(&console_lock_dep_map) to happen on console_suspend,
which the original code never did.

-- Steve

Re: lockdep warning after recent cleanup in console code

[Jan Kara]

On Mon 28-04-14 15:36:42, Steven Rostedt wrote:
> On Mon, 28 Apr 2014 21:24:16 +0200
> Jan Kara <jack@suse.cz> wrote:
> 
> 
> >   So I had a look and we are missing mutex_release() in
> > console_trylock_for_printk() if we don't have a console to print to.
> > Attached patch should fix the problem.
> > 
> 
> Note, your patch changes the logic a bit. It causes the
> mutex_acquire(&console_lock_dep_map) to happen on console_suspend,
> which the original code never did.
  Yes, I know. That's actually intentional and also fixes a lockdep warning
- there was a separate patch doing exactly that flying around because
otherwise when you suspend-resume & CPU hotplug, lockdep complains because
of some cpu hotplug locks. Maybe I should note that in a changelog.

								Honza
-- 
Jan Kara <jack@suse.cz>
SUSE Labs, CR

Re: lockdep warning after recent cleanup in console code

[Andy Shevchenko]

On Mon, 2014-04-28 at 21:24 +0200, Jan Kara wrote:
> On Mon 28-04-14 14:14:39, Steven Rostedt wrote:
> > On Mon, 28 Apr 2014 19:51:39 +0200
> > Jan Kara <jack@suse.cz> wrote:
> > 
> > > On Mon 28-04-14 13:43:31, Steven Rostedt wrote:
> > > > Things have changed with regard to printk() in linux-next. Now it
> > > > appears that lockdep is going haywire over it. I don't understand the
> > > > exact reason for the lockdep_off() and lockdep_on() logic that is in
> > > > printk(), but it obviously seems to be causing issues with the new
> > > > changes.
> > > > 
> > > > Care to take a look?
> > >   The obvious cause is that I moved lockdep_on() somewhat earlier in
> > > vprintk_emit() so lockdep now covers more of printk code. And apparently
> > > something is wrong there...
> > > 
> > 
> > Exactly, and I rather know *exactly* what is wrong before we just start
> > throwing patches at the problem and hope it goes away. That's not how
> > to solve a software bug.
>   So I had a look and we are missing mutex_release() in
> console_trylock_for_printk() if we don't have a console to print to.
> Attached patch should fix the problem.

Besides it doesn't apply clearly on top of today's linux-next, it
doesn't fix the issue, but modifies it a bit.


[    0.000000] =============================================
[    0.000000] [ INFO: possible recursive locking detected ]
[    0.000000] 3.15.0-rc3-next-20140429-00031-gb91b421 #54 Not tainted
[    0.000000] ---------------------------------------------
[    0.000000] swapper/0 is trying to acquire lock:
[    0.000000]  (console_lock){......}, at: [<c107078b>] console_lock
+0x8/0x27
[    0.000000] 
[    0.000000] but task is already holding lock:
[    0.000000]  (console_lock){......}, at: [<c1070be5>] console_trylock
+0x1b/0x50
[    0.000000] 
[    0.000000] other info that might help us debug this:
[    0.000000]  Possible unsafe locking scenario:
[    0.000000] 
[    0.000000]        CPU0
[    0.000000]        ----
[    0.000000]   lock(console_lock);
[    0.000000]   lock(console_lock);
[    0.000000] 
[    0.000000]  *** DEADLOCK ***
[    0.000000] 
[    0.000000]  May be due to missing lock nesting notation
[    0.000000] 
[    0.000000] 3 locks held by swapper/0:
[    0.000000]  #0:  (console_lock){......}, at: [<c1070be5>]
console_trylock+0x1b/0x50
[    0.000000]  #1:  (console_lock){......}, at: [<c1070be5>]
console_trylock+0x1b/0x50
[    0.000000]  #2:  (console_lock){......}, at: [<c1070be5>]
console_trylock+0x1b/0x50
[    0.000000] 
[    0.000000] stack backtrace:
[    0.000000] CPU: 0 PID: 0 Comm: swapper Not tainted
3.15.0-rc3-next-20140429-00031-gb91b421 #54
[    0.000000]  00000000 00000000 c186de14 c15879ea c1daf840 c186de80
c106c188 c1794dff
[    0.000000]  c1795959 c1794cfe 0000002a 00000000 00000000 c1daf840
c1983700 00000080
[    0.000000]  04002001 c187a0b0 00000000 00000000 c1879b40 c1879b40
00200046 00000000
[    0.000000] Call Trace:
[    0.000000]  [<c15879ea>] dump_stack+0x49/0x73
[    0.000000]  [<c106c188>] __lock_acquire+0xb31/0xc7c
[    0.000000]  [<c106c36f>] lock_acquire+0x9c/0x111
[    0.000000]  [<c107078b>] ? console_lock+0x8/0x27
[    0.000000]  [<c107077e>] down_console_sem+0x24/0x29
[    0.000000]  [<c107078b>] ? console_lock+0x8/0x27
[    0.000000]  [<c107078b>] console_lock+0x8/0x27
[    0.000000]  [<c10728e9>] register_console+0x15e/0x295
[    0.000000]  [<c15830bc>] early_console_register+0x33/0x35
[    0.000000]  [<c191047a>] setup_early_printk+0x144/0x151
[    0.000000]  [<c19013f6>] do_early_param+0x41/0x73
[    0.000000]  [<c19013b5>] ? loglevel+0x2c/0x2c
[    0.000000]  [<c104c788>] parse_args+0x271/0x33b
[    0.000000]  [<c19013b5>] ? loglevel+0x2c/0x2c
[    0.000000]  [<c19016e6>] parse_early_options+0x1c/0x21
[    0.000000]  [<c19016e6>] ? parse_early_options+0x1c/0x21
[    0.000000]  [<c19013b5>] ? loglevel+0x2c/0x2c
[    0.000000]  [<c1901715>] parse_early_param+0x2a/0x36
[    0.000000]  [<c1904329>] setup_arch+0x3c9/0xc55
[    0.000000]  [<c1071f08>] ? vprintk_emit+0x3c5/0x3ea
[    0.000000]  [<c15849a5>] ? printk+0x28/0x2d
[    0.000000]  [<c190179d>] start_kernel+0x72/0x325
[    0.000000]  [<c19012b4>] i386_start_kernel+0x82/0x86
[    0.000000] bootconsole [earlyhsu0] enabled




-- 
Andy Shevchenko <andriy.shevchenko@linux.intel.com>
Intel Finland Oy

Re: lockdep warning after recent cleanup in console code

[Jan Kara]

[-- Attachment #1: Type: text/plain, Size: 1562 bytes --]

On Tue 29-04-14 11:38:04, Andy Shevchenko wrote:
> On Mon, 2014-04-28 at 21:24 +0200, Jan Kara wrote:
> > On Mon 28-04-14 14:14:39, Steven Rostedt wrote:
> > > On Mon, 28 Apr 2014 19:51:39 +0200
> > > Jan Kara <jack@suse.cz> wrote:
> > > 
> > > > On Mon 28-04-14 13:43:31, Steven Rostedt wrote:
> > > > > Things have changed with regard to printk() in linux-next. Now it
> > > > > appears that lockdep is going haywire over it. I don't understand the
> > > > > exact reason for the lockdep_off() and lockdep_on() logic that is in
> > > > > printk(), but it obviously seems to be causing issues with the new
> > > > > changes.
> > > > > 
> > > > > Care to take a look?
> > > >   The obvious cause is that I moved lockdep_on() somewhat earlier in
> > > > vprintk_emit() so lockdep now covers more of printk code. And apparently
> > > > something is wrong there...
> > > > 
> > > 
> > > Exactly, and I rather know *exactly* what is wrong before we just start
> > > throwing patches at the problem and hope it goes away. That's not how
> > > to solve a software bug.
> >   So I had a look and we are missing mutex_release() in
> > console_trylock_for_printk() if we don't have a console to print to.
> > Attached patch should fix the problem.
> 
> Besides it doesn't apply clearly on top of today's linux-next, it
> doesn't fix the issue, but modifies it a bit.
  Sorry, I was too tired and missed conversion of one place. Attached is a
new version of the patch which also applies cleanly against linux-next.

								Honza
-- 
Jan Kara <jack@suse.cz>
SUSE Labs, CR

[-- Attachment #2: 0001-printk-Fix-lockdep-instrumentation-of-console_sem.patch --]
[-- Type: text/x-patch, Size: 3958 bytes --]

>From 02e7e0901329f6b9ac3392be41a72b3cee4ac995 Mon Sep 17 00:00:00 2001
From: Jan Kara <jack@suse.cz>
Date: Mon, 28 Apr 2014 21:09:26 +0200
Subject: [PATCH] printk: Fix lockdep instrumentation of console_sem

Printk calls mutex_acquire() / mutex_release() by hand to instrument
lockdep about console_sem. However in some corner cases the
instrumentation is missing. Fix the problem by creating helper functions
for locking / unlocking console_sem which take care of lockdep
instrumentation as well.

Signed-off-by: Jan Kara <jack@suse.cz>
---
 kernel/printk/printk.c |   46 ++++++++++++++++++++++++++++++++--------------
 1 files changed, 32 insertions(+), 14 deletions(-)

diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
index 48a038b..82d19e6 100644
--- a/kernel/printk/printk.c
+++ b/kernel/printk/printk.c
@@ -94,6 +94,29 @@ static struct lockdep_map console_lock_dep_map = {
 #endif
 
 /*
+ * Helper macros to handle lockdep when locking/unlocking console_sem. We use
+ * macros instead of functions so that _RET_IP_ contains useful information.
+ */
+#define down_console_sem() do { \
+	down(&console_sem);\
+	mutex_acquire(&console_lock_dep_map, 0, 0, _RET_IP_);\
+} while (0)
+
+static int __down_trylock_console_sem(unsigned long ip)
+{
+	if (down_trylock(&console_sem))
+		return 1;
+	mutex_acquire(&console_lock_dep_map, 0, 1, ip);
+	return 0;
+}
+#define down_trylock_console_sem() __down_trylock_console_sem(_RET_IP_)
+
+#define up_console_sem() do { \
+	mutex_release(&console_lock_dep_map, 1, _RET_IP_);\
+	up(&console_sem);\
+} while (0)
+
+/*
  * This is used for debugging the mess that is the VT code by
  * keeping track if we have the console semaphore held. It's
  * definitely not the perfect debug tool (we don't know if _WE_
@@ -1428,7 +1451,7 @@ static int console_trylock_for_printk(void)
 	 */
 	if (!can_use_console(cpu)) {
 		console_locked = 0;
-		up(&console_sem);
+		up_console_sem();
 		return 0;
 	}
 	return 1;
@@ -1977,16 +2000,14 @@ void suspend_console(void)
 	printk("Suspending console(s) (use no_console_suspend to debug)\n");
 	console_lock();
 	console_suspended = 1;
-	up(&console_sem);
-	mutex_release(&console_lock_dep_map, 1, _RET_IP_);
+	up_console_sem();
 }
 
 void resume_console(void)
 {
 	if (!console_suspend_enabled)
 		return;
-	down(&console_sem);
-	mutex_acquire(&console_lock_dep_map, 0, 0, _RET_IP_);
+	down_console_sem();
 	console_suspended = 0;
 	console_unlock();
 }
@@ -2028,12 +2049,11 @@ void console_lock(void)
 {
 	might_sleep();
 
-	down(&console_sem);
+	down_console_sem();
 	if (console_suspended)
 		return;
 	console_locked = 1;
 	console_may_schedule = 1;
-	mutex_acquire(&console_lock_dep_map, 0, 0, _RET_IP_);
 }
 EXPORT_SYMBOL(console_lock);
 
@@ -2047,15 +2067,14 @@ EXPORT_SYMBOL(console_lock);
  */
 int console_trylock(void)
 {
-	if (down_trylock(&console_sem))
+	if (down_trylock_console_sem())
 		return 0;
 	if (console_suspended) {
-		up(&console_sem);
+		up_console_sem();
 		return 0;
 	}
 	console_locked = 1;
 	console_may_schedule = 0;
-	mutex_acquire(&console_lock_dep_map, 0, 1, _RET_IP_);
 	return 1;
 }
 EXPORT_SYMBOL(console_trylock);
@@ -2117,7 +2136,7 @@ void console_unlock(void)
 	bool retry;
 
 	if (console_suspended) {
-		up(&console_sem);
+		up_console_sem();
 		return;
 	}
 
@@ -2179,7 +2198,6 @@ skip:
 		local_irq_restore(flags);
 	}
 	console_locked = 0;
-	mutex_release(&console_lock_dep_map, 1, _RET_IP_);
 
 	/* Release the exclusive_console once it is used */
 	if (unlikely(exclusive_console))
@@ -2187,7 +2205,7 @@ skip:
 
 	raw_spin_unlock(&logbuf_lock);
 
-	up(&console_sem);
+	up_console_sem();
 
 	/*
 	 * Someone could have filled up the buffer again, so re-check if there's
@@ -2232,7 +2250,7 @@ void console_unblank(void)
 	 * oops_in_progress is set to 1..
 	 */
 	if (oops_in_progress) {
-		if (down_trylock(&console_sem) != 0)
+		if (down_trylock_console_sem() != 0)
 			return;
 	} else
 		console_lock();
-- 
1.6.0.2

Re: lockdep warning after recent cleanup in console code

[Andy Shevchenko]

On Tue, 2014-04-29 at 23:07 +0200, Jan Kara wrote:
> On Tue 29-04-14 11:38:04, Andy Shevchenko wrote:
> > On Mon, 2014-04-28 at 21:24 +0200, Jan Kara wrote:
> > > On Mon 28-04-14 14:14:39, Steven Rostedt wrote:
> > > > On Mon, 28 Apr 2014 19:51:39 +0200
> > > > Jan Kara <jack@suse.cz> wrote:
> > > > 
> > > > > On Mon 28-04-14 13:43:31, Steven Rostedt wrote:
> > > > > > Things have changed with regard to printk() in linux-next. Now it
> > > > > > appears that lockdep is going haywire over it. I don't understand the
> > > > > > exact reason for the lockdep_off() and lockdep_on() logic that is in
> > > > > > printk(), but it obviously seems to be causing issues with the new
> > > > > > changes.
> > > > > > 
> > > > > > Care to take a look?
> > > > >   The obvious cause is that I moved lockdep_on() somewhat earlier in
> > > > > vprintk_emit() so lockdep now covers more of printk code. And apparently
> > > > > something is wrong there...
> > > > > 
> > > > 
> > > > Exactly, and I rather know *exactly* what is wrong before we just start
> > > > throwing patches at the problem and hope it goes away. That's not how
> > > > to solve a software bug.
> > >   So I had a look and we are missing mutex_release() in
> > > console_trylock_for_printk() if we don't have a console to print to.
> > > Attached patch should fix the problem.
> > 
> > Besides it doesn't apply clearly on top of today's linux-next, it
> > doesn't fix the issue, but modifies it a bit.
>   Sorry, I was too tired and missed conversion of one place. Attached is a
> new version of the patch which also applies cleanly against linux-next.

Either you decide to revert, not apply or leave as is that patch that
prevents to apply clearly, this one seems good.

Tested-by: Andy Shevchenko <andriy.shevchenko@linux.intel.com>


-- 
Andy Shevchenko <andriy.shevchenko@linux.intel.com>
Intel Finland Oy