Re: workqueue, pci: INFO: possible recursive locking detected

[Lai Jiangshan <laijs@cn.fujitsu.com>]

On 07/19/2013 04:23 AM, Srivatsa S. Bhat wrote:
> 
> On 07/17/2013 03:37 PM, Lai Jiangshan wrote:
>> On 07/16/2013 10:41 PM, Srivatsa S. Bhat wrote:
>>> Hi,
>>>
>>> I have been seeing this warning every time during boot. I haven't
>>> spent time digging through it though... Please let me know if
>>> any machine-specific info is needed.
>>>
>>> Regards,
>>> Srivatsa S. Bhat
>>>
>>>
>>> ----------------------------------------------------
>>>
>>> =============================================
>>> [ INFO: possible recursive locking detected ]
>>> 3.11.0-rc1-lockdep-fix-a #6 Not tainted
>>> ---------------------------------------------
>>> kworker/0:1/142 is trying to acquire lock:
>>>  ((&wfc.work)){+.+.+.}, at: [<ffffffff81077100>] flush_work+0x0/0xb0
>>>
>>> but task is already holding lock:
>>>  ((&wfc.work)){+.+.+.}, at: [<ffffffff81075dd9>] process_one_work+0x169/0x610
>>>
>>> other info that might help us debug this:
>>>  Possible unsafe locking scenario:
>>>
>>>        CPU0
>>>        ----
>>>   lock((&wfc.work));
>>>   lock((&wfc.work));
>>
>>
> 
> 
> Hi Lai,
> 
> Thanks for taking a look into this!
> 
>>
>> This is false negative,
> 
> I believe you meant false-positive...
> 
>> the two "wfc"s are different, they are
>> both on stack. flush_work() can't be deadlock in such case:
>>
>> void foo(void *)
>> {
>> 	...
>> 	if (xxx)
>> 		work_on_cpu(..., foo, ...);
>> 	...
>> }
>>
>> bar()
>> {
>> 	work_on_cpu(..., foo, ...);
>> }
>>
>> The complaint is caused by "work_on_cpu() uses a static lock_class_key".
>> we should fix work_on_cpu().
>> (but the caller should also be careful, the foo()/local_pci_probe() is re-entering)
>>
>> But I can't find an elegant fix.
>>
>> long work_on_cpu(int cpu, long (*fn)(void *), void *arg)
>> {
>> 	struct work_for_cpu wfc = { .fn = fn, .arg = arg };
>>
>> +#ifdef CONFIG_LOCKDEP
>> +	static struct lock_class_key __key;
>> +	INIT_WORK_ONSTACK(&wfc.work, work_for_cpu_fn);
>> +	lockdep_init_map(&wfc.work.lockdep_map, &wfc.work, &__key, 0);
>> +#else
>> 	INIT_WORK_ONSTACK(&wfc.work, work_for_cpu_fn);
>> +#endif
>> 	schedule_work_on(cpu, &wfc.work);
>> 	flush_work(&wfc.work);
>> 	return wfc.ret;
>> }
>>
> 
> Unfortunately that didn't seem to fix it.. I applied the patch
> shown below, and I got the same old warning.
> 
> ---
> 
>  kernel/workqueue.c |    6 ++++++
>  1 file changed, 6 insertions(+)
> 
> 
> diff --git a/kernel/workqueue.c b/kernel/workqueue.c
> index f02c4a4..07d9a67 100644
> --- a/kernel/workqueue.c
> +++ b/kernel/workqueue.c
> @@ -4754,7 +4754,13 @@ long work_on_cpu(int cpu, long (*fn)(void *), void *arg)
>  {
>  	struct work_for_cpu wfc = { .fn = fn, .arg = arg };
>  
> +#ifdef CONFIG_LOCKDEP
> +	static struct lock_class_key __key;

Sorry, this "static" should be removed.

Thanks,
Lai


> +	INIT_WORK_ONSTACK(&wfc.work, work_for_cpu_fn);
> +	lockdep_init_map(&wfc.work.lockdep_map, "&wfc.work", &__key, 0);
> +#else
>  	INIT_WORK_ONSTACK(&wfc.work, work_for_cpu_fn);
> +#endif
>  	schedule_work_on(cpu, &wfc.work);
>  	flush_work(&wfc.work);
>  	return wfc.ret;
> 
> 
> 
> Warning:
> --------
> 
> wmi: Mapper loaded
> be2net 0000:11:00.0: irq 102 for MSI/MSI-X
> be2net 0000:11:00.0: enabled 1 MSI-x vector(s)
> be2net 0000:11:00.0: created 0 RSS queue(s) and 1 default RX queue
> be2net 0000:11:00.0: created 1 TX queue(s)
> pci 0000:11:04.0: [19a2:0710] type 00 class 0x020000
> 
> =============================================
> [ INFO: possible recursive locking detected ]
> 3.11.0-rc1-wq-fix #10 Not tainted
> ---------------------------------------------
> kworker/0:1/126 is trying to acquire lock:
>  (&wfc.work){+.+.+.}, at: [<ffffffff810770f0>] flush_work+0x0/0xb0
> 
> but task is already holding lock:
>  (&wfc.work){+.+.+.}, at: [<ffffffff81075dc9>] process_one_work+0x169/0x610
> 
> other info that might help us debug this:
>  Possible unsafe locking scenario:
> 
>        CPU0
>        ----
>   lock(&wfc.work);
>   lock(&wfc.work);
> 
>  *** DEADLOCK ***
> 
>  May be due to missing lock nesting notation
> 
> 3 locks held by kworker/0:1/126:
>  #0:  (events){.+.+.+}, at: [<ffffffff81075dc9>] process_one_work+0x169/0x610
>  #1:  (&wfc.work){+.+.+.}, at: [<ffffffff81075dc9>] process_one_work+0x169/0x610
>  #2:  (&__lockdep_no_validate__){......}, at: [<ffffffff81398ada>] device_attach+0x2a/0xc0
> 
> stack backtrace:
> CPU: 0 PID: 126 Comm: kworker/0:1 Not tainted 3.11.0-rc1-wq-fix #10
> Hardware name: IBM  -[8737R2A]-/00Y2738, BIOS -[B2E120RUS-1.20]- 11/30/2012
> Workqueue: events work_for_cpu_fn
>  ffff881036887408 ffff881036889668 ffffffff81619059 0000000000000003
>  ffff881036886a80 ffff881036889698 ffffffff810c1624 ffff881036886a80
>  ffff881036887408 ffff881036886a80 0000000000000000 ffff8810368896f8
> Call Trace:
>  [<ffffffff81619059>] dump_stack+0x59/0x80
>  [<ffffffff810c1624>] print_deadlock_bug+0xf4/0x100
>  [<ffffffff810c3104>] validate_chain+0x504/0x750
>  [<ffffffff810c365d>] __lock_acquire+0x30d/0x580
>  [<ffffffff810c3967>] lock_acquire+0x97/0x170
>  [<ffffffff810770f0>] ? start_flush_work+0x220/0x220
>  [<ffffffff81077138>] flush_work+0x48/0xb0
>  [<ffffffff810770f0>] ? start_flush_work+0x220/0x220
>  [<ffffffff810c2000>] ? mark_held_locks+0x80/0x130
>  [<ffffffff81074ceb>] ? queue_work_on+0x4b/0xa0
>  [<ffffffff810c2375>] ? trace_hardirqs_on_caller+0x105/0x1d0
>  [<ffffffff810c244d>] ? trace_hardirqs_on+0xd/0x10
>  [<ffffffff81077334>] work_on_cpu+0xa4/0xc0
>  [<ffffffff8106f940>] ? wqattrs_hash+0x190/0x190
>  [<ffffffff812d1ed0>] ? pci_pm_prepare+0x60/0x60
>  [<ffffffff812d1ffa>] __pci_device_probe+0x9a/0xe0
>  [<ffffffff8161ef90>] ? _raw_spin_unlock_irq+0x30/0x50
>  [<ffffffff812d3302>] ? pci_dev_get+0x22/0x30
>  [<ffffffff812d334a>] pci_device_probe+0x3a/0x60
>  [<ffffffff8161ef90>] ? _raw_spin_unlock_irq+0x30/0x50
>  [<ffffffff81398bdc>] really_probe+0x6c/0x320
>  [<ffffffff81398ed7>] driver_probe_device+0x47/0xa0
>  [<ffffffff81398fe0>] ? __driver_attach+0xb0/0xb0
>  [<ffffffff81399033>] __device_attach+0x53/0x60
>  [<ffffffff81396b24>] bus_for_each_drv+0x74/0xa0
>  [<ffffffff81398b50>] device_attach+0xa0/0xc0
>  [<ffffffff812c99f9>] pci_bus_add_device+0x39/0x60
>  [<ffffffff812ed341>] virtfn_add+0x251/0x3e0
>  [<ffffffff810c244d>] ? trace_hardirqs_on+0xd/0x10
>  [<ffffffff812ed9bf>] sriov_enable+0x22f/0x3d0
>  [<ffffffff812edbad>] pci_enable_sriov+0x4d/0x60
>  [<ffffffffa0127045>] be_vf_setup+0x175/0x410 [be2net]
>  [<ffffffffa012d3ca>] be_setup+0x37a/0x4b0 [be2net]
>  [<ffffffffa012dac0>] be_probe+0x5c0/0x820 [be2net]
>  [<ffffffff812d1f1e>] local_pci_probe+0x4e/0x90
>  [<ffffffff8106f958>] work_for_cpu_fn+0x18/0x30
>  [<ffffffff81075e3a>] process_one_work+0x1da/0x610
>  [<ffffffff81075dc9>] ? process_one_work+0x169/0x610
>  [<ffffffff810764fc>] worker_thread+0x28c/0x3a0
>  [<ffffffff81076270>] ? process_one_work+0x610/0x610
>  [<ffffffff8107da5e>] kthread+0xee/0x100
>  [<ffffffff8107d970>] ? __init_kthread_worker+0x70/0x70
>  [<ffffffff81628e5c>] ret_from_fork+0x7c/0xb0
>  [<ffffffff8107d970>] ? __init_kthread_worker+0x70/0x70
> be2net 0000:11:04.0: enabling device (0040 -> 0042)
> be2net 0000:11:04.0: Could not use PCIe error reporting
> be2net 0000:11:04.0: VF is not privileged to issue opcode 89-1
> be2net 0000:11:04.0: VF is not privileged to issue opcode 125-1
> 
> 
> Regards,
> Srivatsa S. Bhat
> 
>