lists.openwall.net   lists  /  announce  owl-users  owl-dev  john-users  john-dev  passwdqc-users  yescrypt  popa3d-users  /  oss-security  kernel-hardening  musl  sabotage  tlsify  passwords  /  crypt-dev  xvendor  /  Bugtraq  Full-Disclosure  linux-kernel  linux-netdev  linux-ext4  linux-hardening  linux-cve-announce  PHC 
Open Source and information security mailing list archives
 
Hash Suite: Windows password security audit tool. GUI, reports in PDF.
[<prev] [next>] [<thread-prev] [thread-next>] [day] [month] [year] [list] 
Date:	Thu, 28 Jul 2011 17:17:59 -0700
From:	Fernando Lopez-Lezcano <nando@...ma.Stanford.EDU>
To:	Peter Zijlstra <peterz@...radead.org>
CC:	Fernando Lopez-Lezcano <nando@...ma.Stanford.EDU>,
	Thomas Gleixner <tglx@...utronix.de>,
	LKML <linux-kernel@...r.kernel.org>,
	linux-rt-users <linux-rt-users@...r.kernel.org>,
	"Paul E. McKenney" <paulmck@...ux.vnet.ibm.com>,
	Steven Rostedt <rostedt@...dmis.org>,
	Jason Wessel <jason.wessel@...driver.com>,
	Pekka Enberg <penberg@...nel.org>
Subject: Re: [ANNOUNCE] 3.0-rt4

On 07/28/2011 02:22 PM, Peter Zijlstra wrote:
> On Thu, 2011-07-28 at 12:16 -0700, Fernando Lopez-Lezcano wrote:
>> [    0.000000] =============================================
>> [    0.000000] [ INFO: possible recursive locking detected ]
>> [    0.000000] 3.0.0-1.rt5.1.fc15.ccrma.i686.rtPAE #1
>> [    0.000000] ---------------------------------------------
>> [    0.000000] swapper/0 is trying to acquire lock:
>> [    0.000000]  (&parent->list_lock){+.+...}, at: [<c04fb406>] __cache_free+0x43/0xc3
>> [    0.000000]
>> [    0.000000] but task is already holding lock:
>> [    0.000000]  (&parent->list_lock){+.+...}, at: [<c04fc538>] do_tune_cpucache+0xf2/0x2bb
>> [    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(&parent->list_lock);
>> [    0.000000]   lock(&parent->list_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:  (cache_chain_mutex){+.+...}, at: [<c0bd9d2b>] kmem_cache_init_late+0xe/0x61
>> [    0.000000]  #1:  (&per_cpu(slab_lock, __cpu).lock){+.+...}, at: [<c04faa65>] __local_lock_irq+0x1e/0x5b
>> [    0.000000]  #2:  (&parent->list_lock){+.+...}, at: [<c04fc538>] do_tune_cpucache+0xf2/0x2bb
>> [    0.000000]
>> [    0.000000] stack backtrace:
>> [    0.000000] Pid: 0, comm: swapper Not tainted 3.0.0-1.rt5.1.fc15.ccrma.i686.rtPAE #1
>> [    0.000000] Call Trace:
>> [    0.000000]  [<c0856355>] ? printk+0x2d/0x2f
>> [    0.000000]  [<c0474a4b>] __lock_acquire+0x805/0xb57
>> [    0.000000]  [<c0472604>] ? lock_release_holdtime.part.10+0x4b/0x51
>> [    0.000000]  [<c085ecb4>] ? _raw_spin_unlock+0x31/0x3d
>> [    0.000000]  [<c085dbc5>] ? rt_spin_lock_slowlock+0x75/0x190
>> [    0.000000]  [<c04720c3>] ? trace_hardirqs_off+0xb/0xd
>> [    0.000000]  [<c04fb406>] ? __cache_free+0x43/0xc3
>> [    0.000000]  [<c0475215>] lock_acquire+0xde/0x11d
>> [    0.000000]  [<c04fb406>] ? __cache_free+0x43/0xc3
>> [    0.000000]  [<c085e24f>] rt_spin_lock+0x50/0x56
>> [    0.000000]  [<c04fb406>] ? __cache_free+0x43/0xc3
>> [    0.000000]  [<c04fb406>] __cache_free+0x43/0xc3
>> [    0.000000]  [<c043646d>] ? test_ti_thread_flag+0x8/0x10
>> [    0.000000]  [<c04fb23f>] kmem_cache_free+0x6c/0xdc
>> [    0.000000]  [<c04fb2fe>] slab_destroy+0x4f/0x53
>> [    0.000000]  [<c04fb396>] free_block+0x94/0xc1
>> [    0.000000]  [<c04fc551>] do_tune_cpucache+0x10b/0x2bb
>> [    0.000000]  [<c04fc8dc>] enable_cpucache+0x7b/0xa7
>> [    0.000000]  [<c0bd9d3c>] kmem_cache_init_late+0x1f/0x61
>> [    0.000000]  [<c0bba687>] start_kernel+0x24c/0x363
>> [    0.000000]  [<c0bba1c4>] ? loglevel+0x18/0x18
>> [    0.000000]  [<c0bba0ba>] i386_start_kernel+0xa9/0xaf
>
> Ooh, fun.. one does wonder why mainline doesn't show this..
>
> This is the normal OFF_SLAB recursion, and the reason this shows up is
> because this is ran before we do the lockdep fixup.
>
> Fernando, does something like the below (not actually against -rt, but
> it shouldn't matter much) fix things?

Strange. Looks like it only happens on a cold start (I would have to 
test more to be sure), so far two warm starts and it is not there, one 
cold start and it is there - sorry, I have run out of time now for more 
tests... (I checked my build logs and the patch applied cleanly, no 
complains there). Come to think of it I think this was not always 
happening before the patch (ie: not getting the error on all boots).

-- Fernando


[    0.000000] =============================================
[    0.000000] [ INFO: possible recursive locking detected ]
[    0.000000] 3.0.0-1.rt6.1.fc15.ccrma.i686.rtPAE #1
[    0.000000] ---------------------------------------------
[    0.000000] swapper/0 is trying to acquire lock:
[    0.000000]  (&parent->list_lock){+.+...}, at: [<c04fb406>] 
__cache_free+0x43/0xc3
[    0.000000]
[    0.000000] but task is already holding lock:
[    0.000000]  (&parent->list_lock){+.+...}, at: [<c04fc538>] 
do_tune_cpucache+0xf2/0x2bb
[    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(&parent->list_lock);
[    0.000000]   lock(&parent->list_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:  (cache_chain_mutex){+.+...}, at: [<c0bd9d3b>] 
kmem_cache_init_late+0x1e/0x6a
[    0.000000]  #1:  (&per_cpu(slab_lock, __cpu).lock){+.+...}, at: 
[<c04faa65>] __local_lock_irq+0x1e/0x5b
[    0.000000]  #2:  (&parent->list_lock){+.+...}, at: [<c04fc538>] 
do_tune_cpucache+0xf2/0x2bb
[    0.000000]
[    0.000000] stack backtrace:
[    0.000000] Pid: 0, comm: swapper Not tainted 
3.0.0-1.rt6.1.fc15.ccrma.i686.rtPAE #1
[    0.000000] Call Trace:
[    0.000000]  [<c0856355>] ? printk+0x2d/0x2f
[    0.000000]  [<c0474a5b>] __lock_acquire+0x805/0xb57
[    0.000000]  [<c0472614>] ? lock_release_holdtime.part.10+0x4b/0x51
[    0.000000]  [<c085ecb4>] ? _raw_spin_unlock+0x31/0x3d
[    0.000000]  [<c085dbc5>] ? rt_spin_lock_slowlock+0x75/0x190
[    0.000000]  [<c04720d3>] ? trace_hardirqs_off+0xb/0xd
[    0.000000]  [<c04fb406>] ? __cache_free+0x43/0xc3
[    0.000000]  [<c0475225>] lock_acquire+0xde/0x11d
[    0.000000]  [<c04fb406>] ? __cache_free+0x43/0xc3
[    0.000000]  [<c085e24f>] rt_spin_lock+0x50/0x56
[    0.000000]  [<c04fb406>] ? __cache_free+0x43/0xc3
[    0.000000]  [<c04fb406>] __cache_free+0x43/0xc3
[    0.000000]  [<c043646d>] ? test_ti_thread_flag+0x8/0x10
[    0.000000]  [<c04fb23f>] kmem_cache_free+0x6c/0xdc
[    0.000000]  [<c04fb2fe>] slab_destroy+0x4f/0x53
[    0.000000]  [<c04fb396>] free_block+0x94/0xc1
[    0.000000]  [<c04fc551>] do_tune_cpucache+0x10b/0x2bb
[    0.000000]  [<c04fc8dc>] enable_cpucache+0x7b/0xa7
[    0.000000]  [<c0bd9d4c>] kmem_cache_init_late+0x2f/0x6a
[    0.000000]  [<c0bba687>] start_kernel+0x24c/0x363
[    0.000000]  [<c0bba1c4>] ? loglevel+0x18/0x18
[    0.000000]  [<c0bba0ba>] i386_start_kernel+0xa9/0xaf
[    0.000000] Console: colour VGA+ 80x25



--
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
the body of a message to majordomo@...r.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html
Please read the FAQ at  http://www.tux.org/lkml/

Powered by blists - more mailing lists

Powered by Openwall GNU/*/Linux Powered by OpenVZ