2.6.34-rc1: rcu lockdep bug?

2.6.34-rc1: rcu lockdep bug?

[Américo Wang]

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

Hello, Paul and Peter,

Attached is the lockdep warning that I triggered today.

I am not sure if this is a bug of rcu lockdep, because I am
testing my patch when this occurred. However, in the backtrace,
there is none of the functions that I touched, weird.

So, please help to check if this is a bug of rcu lockdep.

Please Cc netdev when necessary.

Thanks much!

[-- Attachment #2: rcu-lockdep-bug.txt --]
[-- Type: text/plain, Size: 5816 bytes --]

Mar 11 17:11:22 dhcp-66-70-5 kernel: =================================
Mar 11 17:11:22 dhcp-66-70-5 kernel: [ INFO: inconsistent lock state ]
Mar 11 17:11:22 dhcp-66-70-5 kernel: 2.6.34-rc1 #58
Mar 11 17:11:22 dhcp-66-70-5 kernel: ---------------------------------
Mar 11 17:11:22 dhcp-66-70-5 kernel: inconsistent {SOFTIRQ-ON-W} -> {IN-SOFTIRQ-W} usage.
Mar 11 17:11:22 dhcp-66-70-5 kernel: swapper/0 [HC0[0]:SC1[1]:HE0:SE0] takes:
Mar 11 17:11:22 dhcp-66-70-5 kernel:  (usbfs_mutex){+.?...}, at: [<ffffffff8146419f>] netif_receive_skb+0xe7/0x819
Mar 11 17:11:22 dhcp-66-70-5 kernel: {SOFTIRQ-ON-W} state was registered at:
Mar 11 17:11:22 dhcp-66-70-5 kernel:   [<ffffffff810a6dc2>] __lock_acquire+0xaec/0xe55
Mar 11 17:11:22 dhcp-66-70-5 kernel:   [<ffffffff810a9585>] lock_acquire+0x163/0x1aa
Mar 11 17:11:22 dhcp-66-70-5 kernel:   [<ffffffff8154f5f9>] mutex_lock_nested+0x64/0x4e9
Mar 11 17:11:22 dhcp-66-70-5 kernel:   [<ffffffff813e5ec5>] usbdev_open+0x115/0x4e9
Mar 11 17:11:22 dhcp-66-70-5 kernel:   [<ffffffff8117af83>] chrdev_open+0x27a/0x2fe
Mar 11 17:11:22 dhcp-66-70-5 kernel:   [<ffffffff81172f98>] __dentry_open+0x2d4/0x4d2
Mar 11 17:11:22 dhcp-66-70-5 kernel:   [<ffffffff81174560>] nameidata_to_filp+0x58/0x7e
Mar 11 17:11:22 dhcp-66-70-5 kernel:   [<ffffffff811858e9>] do_last+0x81b/0xa3d
Mar 11 17:11:22 dhcp-66-70-5 kernel:   [<ffffffff81187220>] do_filp_open+0x2ff/0x869
Mar 11 17:11:22 dhcp-66-70-5 kernel:   [<ffffffff81172b53>] do_sys_open+0x8c/0x187
Mar 11 17:11:22 dhcp-66-70-5 kernel:   [<ffffffff81172c96>] sys_open+0x27/0x30
Mar 11 17:11:22 dhcp-66-70-5 kernel:   [<ffffffff81003a5b>] system_call_fastpath+0x16/0x1b
Mar 11 17:11:22 dhcp-66-70-5 kernel: irq event stamp: 7135619
Mar 11 17:11:22 dhcp-66-70-5 kernel: hardirqs last  enabled at (7135618): [<ffffffff8116c69f>] __kmalloc_node_track_caller+0x18d/0x256
Mar 11 17:11:22 dhcp-66-70-5 kernel: hardirqs last disabled at (7135619): [<ffffffff8155220a>] _raw_spin_lock_irqsave+0x3f/0xe2
Mar 11 17:11:22 dhcp-66-70-5 kernel: softirqs last  enabled at (7135604): [<ffffffff8106a9a8>] __do_softirq+0x334/0x35f
Mar 11 17:11:22 dhcp-66-70-5 kernel: softirqs last disabled at (7135611): [<ffffffff8100498c>] call_softirq+0x1c/0x4c
Mar 11 17:11:22 dhcp-66-70-5 kernel: 
Mar 11 17:11:22 dhcp-66-70-5 kernel: other info that might help us debug this:
Mar 11 17:11:22 dhcp-66-70-5 kernel: 2 locks held by swapper/0:
Mar 11 17:11:22 dhcp-66-70-5 kernel:  #0:  (rcu_read_lock){.+.+..}, at: [<ffffffff81468baa>] net_rx_action+0xc9/0x40f
Mar 11 17:11:22 dhcp-66-70-5 kernel:  #1:  (&(&napi->poll_lock)->rlock){+.-...}, at: [<ffffffff81468c39>] net_rx_action+0x158/0x40f
Mar 11 17:11:22 dhcp-66-70-5 kernel: 
Mar 11 17:11:22 dhcp-66-70-5 kernel: stack backtrace:
Mar 11 17:11:22 dhcp-66-70-5 kernel: Pid: 0, comm: swapper Not tainted 2.6.34-rc1 #58
Mar 11 17:11:22 dhcp-66-70-5 kernel: Call Trace:
Mar 11 17:11:22 dhcp-66-70-5 kernel:  <IRQ>  [<ffffffff810a1985>] print_usage_bug+0x26b/0x283
Mar 11 17:11:22 dhcp-66-70-5 kernel:  [<ffffffff810a4486>] ? check_usage_forwards+0x0/0x141
Mar 11 17:11:22 dhcp-66-70-5 kernel:  [<ffffffff810a1e7d>] mark_lock+0x4e0/0x8ff
Mar 11 17:11:22 dhcp-66-70-5 kernel:  [<ffffffff810a6ce3>] __lock_acquire+0xa0d/0xe55
Mar 11 17:11:22 dhcp-66-70-5 kernel:  [<ffffffff810a9585>] lock_acquire+0x163/0x1aa
Mar 11 17:11:22 dhcp-66-70-5 kernel:  [<ffffffff8146419f>] ? netif_receive_skb+0xe7/0x819
Mar 11 17:11:22 dhcp-66-70-5 kernel:  [<ffffffff81552237>] _raw_spin_lock_irqsave+0x6c/0xe2
Mar 11 17:11:22 dhcp-66-70-5 kernel:  [<ffffffff8146419f>] ? netif_receive_skb+0xe7/0x819
Mar 11 17:11:22 dhcp-66-70-5 kernel:  [<ffffffff8146419f>] netif_receive_skb+0xe7/0x819
Mar 11 17:11:22 dhcp-66-70-5 kernel:  [<ffffffff814649a8>] napi_skb_finish+0x37/0x6a
Mar 11 17:11:22 dhcp-66-70-5 kernel:  [<ffffffff81465118>] napi_gro_receive+0x44/0x50
Mar 11 17:11:22 dhcp-66-70-5 kernel:  [<ffffffffa01d8bdc>] tg3_poll_work+0x9c6/0xfab [tg3]
Mar 11 17:11:22 dhcp-66-70-5 kernel:  [<ffffffff810a7063>] ? __lock_acquire+0xd8d/0xe55
Mar 11 17:11:22 dhcp-66-70-5 kernel:  [<ffffffffa01d92bc>] tg3_poll+0xfb/0x322 [tg3]
Mar 11 17:11:22 dhcp-66-70-5 kernel:  [<ffffffff81468c95>] net_rx_action+0x1b4/0x40f
Mar 11 17:11:22 dhcp-66-70-5 kernel:  [<ffffffff81468baa>] ? net_rx_action+0xc9/0x40f
Mar 11 17:11:22 dhcp-66-70-5 kernel:  [<ffffffff8106a808>] __do_softirq+0x194/0x35f
Mar 11 17:11:22 dhcp-66-70-5 kernel:  [<ffffffff8100498c>] call_softirq+0x1c/0x4c
Mar 11 17:11:22 dhcp-66-70-5 kernel:  [<ffffffff81006d10>] do_softirq+0x8c/0x181
Mar 11 17:11:22 dhcp-66-70-5 kernel:  [<ffffffff8106a66b>] irq_exit+0xa5/0xae
Mar 11 17:11:22 dhcp-66-70-5 kernel:  [<ffffffff8155c2aa>] do_IRQ+0x10a/0x136
Mar 11 17:11:22 dhcp-66-70-5 kernel:  [<ffffffff81553453>] ret_from_intr+0x0/0xf
Mar 11 17:11:22 dhcp-66-70-5 kernel:  <EOI>  [<ffffffff81332544>] ? acpi_safe_halt+0x61/0x84
Mar 11 17:11:22 dhcp-66-70-5 kernel:  [<ffffffff8133253b>] ? acpi_safe_halt+0x58/0x84
Mar 11 17:11:22 dhcp-66-70-5 kernel:  [<ffffffff8133270e>] acpi_idle_enter_c1+0xd7/0x17b
Mar 11 17:11:22 dhcp-66-70-5 kernel:  [<ffffffff815581b4>] ? __atomic_notifier_call_chain+0x92/0xa7
Mar 11 17:11:22 dhcp-66-70-5 kernel:  [<ffffffff8142960f>] ? ladder_select_state+0x42/0x23d
Mar 11 17:11:22 dhcp-66-70-5 kernel:  [<ffffffff81428439>] cpuidle_idle_call+0x104/0x1b4
Mar 11 17:11:22 dhcp-66-70-5 kernel:  [<ffffffff810020df>] cpu_idle+0xfd/0x163
Mar 11 17:11:22 dhcp-66-70-5 kernel:  [<ffffffff8152cb36>] rest_init+0x13a/0x145
Mar 11 17:11:22 dhcp-66-70-5 kernel:  [<ffffffff8152c9fc>] ? rest_init+0x0/0x145
Mar 11 17:11:22 dhcp-66-70-5 kernel:  [<ffffffff81c92702>] start_kernel+0x789/0x79d
Mar 11 17:11:22 dhcp-66-70-5 kernel:  [<ffffffff81c912f4>] x86_64_start_reservations+0x104/0x10f
Mar 11 17:11:22 dhcp-66-70-5 kernel:  [<ffffffff81c914df>] x86_64_start_kernel+0x1e0/0x1ee

Re: 2.6.34-rc1: rcu lockdep bug?

[Paul E. McKenney]

On Thu, Mar 11, 2010 at 06:05:38PM +0800, Américo Wang wrote:
> Hello, Paul and Peter,
> 
> Attached is the lockdep warning that I triggered today.
> 
> I am not sure if this is a bug of rcu lockdep, because I am
> testing my patch when this occurred. However, in the backtrace,
> there is none of the functions that I touched, weird.
> 
> So, please help to check if this is a bug of rcu lockdep.

This sort of thing is caused by acquiring the same lock with softirq
(AKA BH) blocked and not, which can result in self-deadlock.

There was such a bug in the RCU lockdep stuff in -tip, but it has long
since been fixed.  If you were seeing that bug, rcu_do_batch() would
be on the stack, which it does not appear to be.

So does your patch involve the usbfs_mutex?  Or attempt to manipulate
vfs/fs state from withing networking softirq/BH context?

							Thanx, Paul

> Please Cc netdev when necessary.
> 
> Thanks much!

> Mar 11 17:11:22 dhcp-66-70-5 kernel: =================================
> Mar 11 17:11:22 dhcp-66-70-5 kernel: [ INFO: inconsistent lock state ]
> Mar 11 17:11:22 dhcp-66-70-5 kernel: 2.6.34-rc1 #58
> Mar 11 17:11:22 dhcp-66-70-5 kernel: ---------------------------------
> Mar 11 17:11:22 dhcp-66-70-5 kernel: inconsistent {SOFTIRQ-ON-W} -> {IN-SOFTIRQ-W} usage.
> Mar 11 17:11:22 dhcp-66-70-5 kernel: swapper/0 [HC0[0]:SC1[1]:HE0:SE0] takes:
> Mar 11 17:11:22 dhcp-66-70-5 kernel:  (usbfs_mutex){+.?...}, at: [<ffffffff8146419f>] netif_receive_skb+0xe7/0x819
> Mar 11 17:11:22 dhcp-66-70-5 kernel: {SOFTIRQ-ON-W} state was registered at:
> Mar 11 17:11:22 dhcp-66-70-5 kernel:   [<ffffffff810a6dc2>] __lock_acquire+0xaec/0xe55
> Mar 11 17:11:22 dhcp-66-70-5 kernel:   [<ffffffff810a9585>] lock_acquire+0x163/0x1aa
> Mar 11 17:11:22 dhcp-66-70-5 kernel:   [<ffffffff8154f5f9>] mutex_lock_nested+0x64/0x4e9
> Mar 11 17:11:22 dhcp-66-70-5 kernel:   [<ffffffff813e5ec5>] usbdev_open+0x115/0x4e9
> Mar 11 17:11:22 dhcp-66-70-5 kernel:   [<ffffffff8117af83>] chrdev_open+0x27a/0x2fe
> Mar 11 17:11:22 dhcp-66-70-5 kernel:   [<ffffffff81172f98>] __dentry_open+0x2d4/0x4d2
> Mar 11 17:11:22 dhcp-66-70-5 kernel:   [<ffffffff81174560>] nameidata_to_filp+0x58/0x7e
> Mar 11 17:11:22 dhcp-66-70-5 kernel:   [<ffffffff811858e9>] do_last+0x81b/0xa3d
> Mar 11 17:11:22 dhcp-66-70-5 kernel:   [<ffffffff81187220>] do_filp_open+0x2ff/0x869
> Mar 11 17:11:22 dhcp-66-70-5 kernel:   [<ffffffff81172b53>] do_sys_open+0x8c/0x187
> Mar 11 17:11:22 dhcp-66-70-5 kernel:   [<ffffffff81172c96>] sys_open+0x27/0x30
> Mar 11 17:11:22 dhcp-66-70-5 kernel:   [<ffffffff81003a5b>] system_call_fastpath+0x16/0x1b
> Mar 11 17:11:22 dhcp-66-70-5 kernel: irq event stamp: 7135619
> Mar 11 17:11:22 dhcp-66-70-5 kernel: hardirqs last  enabled at (7135618): [<ffffffff8116c69f>] __kmalloc_node_track_caller+0x18d/0x256
> Mar 11 17:11:22 dhcp-66-70-5 kernel: hardirqs last disabled at (7135619): [<ffffffff8155220a>] _raw_spin_lock_irqsave+0x3f/0xe2
> Mar 11 17:11:22 dhcp-66-70-5 kernel: softirqs last  enabled at (7135604): [<ffffffff8106a9a8>] __do_softirq+0x334/0x35f
> Mar 11 17:11:22 dhcp-66-70-5 kernel: softirqs last disabled at (7135611): [<ffffffff8100498c>] call_softirq+0x1c/0x4c
> Mar 11 17:11:22 dhcp-66-70-5 kernel: 
> Mar 11 17:11:22 dhcp-66-70-5 kernel: other info that might help us debug this:
> Mar 11 17:11:22 dhcp-66-70-5 kernel: 2 locks held by swapper/0:
> Mar 11 17:11:22 dhcp-66-70-5 kernel:  #0:  (rcu_read_lock){.+.+..}, at: [<ffffffff81468baa>] net_rx_action+0xc9/0x40f
> Mar 11 17:11:22 dhcp-66-70-5 kernel:  #1:  (&(&napi->poll_lock)->rlock){+.-...}, at: [<ffffffff81468c39>] net_rx_action+0x158/0x40f
> Mar 11 17:11:22 dhcp-66-70-5 kernel: 
> Mar 11 17:11:22 dhcp-66-70-5 kernel: stack backtrace:
> Mar 11 17:11:22 dhcp-66-70-5 kernel: Pid: 0, comm: swapper Not tainted 2.6.34-rc1 #58
> Mar 11 17:11:22 dhcp-66-70-5 kernel: Call Trace:
> Mar 11 17:11:22 dhcp-66-70-5 kernel:  <IRQ>  [<ffffffff810a1985>] print_usage_bug+0x26b/0x283
> Mar 11 17:11:22 dhcp-66-70-5 kernel:  [<ffffffff810a4486>] ? check_usage_forwards+0x0/0x141
> Mar 11 17:11:22 dhcp-66-70-5 kernel:  [<ffffffff810a1e7d>] mark_lock+0x4e0/0x8ff
> Mar 11 17:11:22 dhcp-66-70-5 kernel:  [<ffffffff810a6ce3>] __lock_acquire+0xa0d/0xe55
> Mar 11 17:11:22 dhcp-66-70-5 kernel:  [<ffffffff810a9585>] lock_acquire+0x163/0x1aa
> Mar 11 17:11:22 dhcp-66-70-5 kernel:  [<ffffffff8146419f>] ? netif_receive_skb+0xe7/0x819
> Mar 11 17:11:22 dhcp-66-70-5 kernel:  [<ffffffff81552237>] _raw_spin_lock_irqsave+0x6c/0xe2
> Mar 11 17:11:22 dhcp-66-70-5 kernel:  [<ffffffff8146419f>] ? netif_receive_skb+0xe7/0x819
> Mar 11 17:11:22 dhcp-66-70-5 kernel:  [<ffffffff8146419f>] netif_receive_skb+0xe7/0x819
> Mar 11 17:11:22 dhcp-66-70-5 kernel:  [<ffffffff814649a8>] napi_skb_finish+0x37/0x6a
> Mar 11 17:11:22 dhcp-66-70-5 kernel:  [<ffffffff81465118>] napi_gro_receive+0x44/0x50
> Mar 11 17:11:22 dhcp-66-70-5 kernel:  [<ffffffffa01d8bdc>] tg3_poll_work+0x9c6/0xfab [tg3]
> Mar 11 17:11:22 dhcp-66-70-5 kernel:  [<ffffffff810a7063>] ? __lock_acquire+0xd8d/0xe55
> Mar 11 17:11:22 dhcp-66-70-5 kernel:  [<ffffffffa01d92bc>] tg3_poll+0xfb/0x322 [tg3]
> Mar 11 17:11:22 dhcp-66-70-5 kernel:  [<ffffffff81468c95>] net_rx_action+0x1b4/0x40f
> Mar 11 17:11:22 dhcp-66-70-5 kernel:  [<ffffffff81468baa>] ? net_rx_action+0xc9/0x40f
> Mar 11 17:11:22 dhcp-66-70-5 kernel:  [<ffffffff8106a808>] __do_softirq+0x194/0x35f
> Mar 11 17:11:22 dhcp-66-70-5 kernel:  [<ffffffff8100498c>] call_softirq+0x1c/0x4c
> Mar 11 17:11:22 dhcp-66-70-5 kernel:  [<ffffffff81006d10>] do_softirq+0x8c/0x181
> Mar 11 17:11:22 dhcp-66-70-5 kernel:  [<ffffffff8106a66b>] irq_exit+0xa5/0xae
> Mar 11 17:11:22 dhcp-66-70-5 kernel:  [<ffffffff8155c2aa>] do_IRQ+0x10a/0x136
> Mar 11 17:11:22 dhcp-66-70-5 kernel:  [<ffffffff81553453>] ret_from_intr+0x0/0xf
> Mar 11 17:11:22 dhcp-66-70-5 kernel:  <EOI>  [<ffffffff81332544>] ? acpi_safe_halt+0x61/0x84
> Mar 11 17:11:22 dhcp-66-70-5 kernel:  [<ffffffff8133253b>] ? acpi_safe_halt+0x58/0x84
> Mar 11 17:11:22 dhcp-66-70-5 kernel:  [<ffffffff8133270e>] acpi_idle_enter_c1+0xd7/0x17b
> Mar 11 17:11:22 dhcp-66-70-5 kernel:  [<ffffffff815581b4>] ? __atomic_notifier_call_chain+0x92/0xa7
> Mar 11 17:11:22 dhcp-66-70-5 kernel:  [<ffffffff8142960f>] ? ladder_select_state+0x42/0x23d
> Mar 11 17:11:22 dhcp-66-70-5 kernel:  [<ffffffff81428439>] cpuidle_idle_call+0x104/0x1b4
> Mar 11 17:11:22 dhcp-66-70-5 kernel:  [<ffffffff810020df>] cpu_idle+0xfd/0x163
> Mar 11 17:11:22 dhcp-66-70-5 kernel:  [<ffffffff8152cb36>] rest_init+0x13a/0x145
> Mar 11 17:11:22 dhcp-66-70-5 kernel:  [<ffffffff8152c9fc>] ? rest_init+0x0/0x145
> Mar 11 17:11:22 dhcp-66-70-5 kernel:  [<ffffffff81c92702>] start_kernel+0x789/0x79d
> Mar 11 17:11:22 dhcp-66-70-5 kernel:  [<ffffffff81c912f4>] x86_64_start_reservations+0x104/0x10f
> Mar 11 17:11:22 dhcp-66-70-5 kernel:  [<ffffffff81c914df>] x86_64_start_kernel+0x1e0/0x1ee

Re: 2.6.34-rc1: rcu lockdep bug?

[Américo Wang]

On Thu, Mar 11, 2010 at 05:45:56AM -0800, Paul E. McKenney wrote:
>On Thu, Mar 11, 2010 at 06:05:38PM +0800, Américo Wang wrote:
>> Hello, Paul and Peter,
>> 
>> Attached is the lockdep warning that I triggered today.
>> 
>> I am not sure if this is a bug of rcu lockdep, because I am
>> testing my patch when this occurred. However, in the backtrace,
>> there is none of the functions that I touched, weird.
>> 
>> So, please help to check if this is a bug of rcu lockdep.
>
>This sort of thing is caused by acquiring the same lock with softirq
>(AKA BH) blocked and not, which can result in self-deadlock.
>
>There was such a bug in the RCU lockdep stuff in -tip, but it has long
>since been fixed.  If you were seeing that bug, rcu_do_batch() would
>be on the stack, which it does not appear to be.
>
>So does your patch involve the usbfs_mutex?  Or attempt to manipulate
>vfs/fs state from withing networking softirq/BH context?
>

Nope, it is a patch for netpoll, nothing related with usb, nor vfs.

Thanks much!

Re: 2.6.34-rc1: rcu lockdep bug?

[Américo Wang]

(Cc'ing netdev)

On Fri, Mar 12, 2010 at 12:17 AM, Américo Wang <xiyou.wangcong@gmail.com> wrote:
> On Thu, Mar 11, 2010 at 05:45:56AM -0800, Paul E. McKenney wrote:
>>On Thu, Mar 11, 2010 at 06:05:38PM +0800, Américo Wang wrote:
>>> Hello, Paul and Peter,
>>>
>>> Attached is the lockdep warning that I triggered today.
>>>
>>> I am not sure if this is a bug of rcu lockdep, because I am
>>> testing my patch when this occurred. However, in the backtrace,
>>> there is none of the functions that I touched, weird.
>>>
>>> So, please help to check if this is a bug of rcu lockdep.
>>
>>This sort of thing is caused by acquiring the same lock with softirq
>>(AKA BH) blocked and not, which can result in self-deadlock.
>>
>>There was such a bug in the RCU lockdep stuff in -tip, but it has long
>>since been fixed.  If you were seeing that bug, rcu_do_batch() would
>>be on the stack, which it does not appear to be.
>>
>>So does your patch involve the usbfs_mutex?  Or attempt to manipulate
>>vfs/fs state from withing networking softirq/BH context?
>>
>
> Nope, it is a patch for netpoll, nothing related with usb, nor vfs.
>

Ok, after decoding the lockdep output, it looks like that
netif_receive_skb() should call rcu_read_lock_bh() instead of rcu_read_lock()?
But I don't know if all callers of netif_receive_skb() are in softirq context.

Paul, what do you think?

Thank you.

Re: 2.6.34-rc1: rcu lockdep bug?

[David Miller]

From: Américo Wang <xiyou.wangcong@gmail.com>
Date: Fri, 12 Mar 2010 15:56:03 +0800

> Ok, after decoding the lockdep output, it looks like that
> netif_receive_skb() should call rcu_read_lock_bh() instead of rcu_read_lock()?
> But I don't know if all callers of netif_receive_skb() are in softirq context.

Normally, netif_receive_skb() is invoked from softirq context.

However, via netpoll it can be invoked essentially from any context.

But, when this happens, the networking receive path makes amends such
that this works fine.  That's what the netpoll_receive_skb() check in
netif_receive_skb() is for.  That check makes it bail out early if the
call to netif_receive_skb() is via a netpoll invocation.

Re: 2.6.34-rc1: rcu lockdep bug?

[Américo Wang]

On Fri, Mar 12, 2010 at 4:07 PM, David Miller <davem@davemloft.net> wrote:
> From: Américo Wang <xiyou.wangcong@gmail.com>
> Date: Fri, 12 Mar 2010 15:56:03 +0800
>
>> Ok, after decoding the lockdep output, it looks like that
>> netif_receive_skb() should call rcu_read_lock_bh() instead of rcu_read_lock()?
>> But I don't know if all callers of netif_receive_skb() are in softirq context.
>
> Normally, netif_receive_skb() is invoked from softirq context.
>
> However, via netpoll it can be invoked essentially from any context.
>
> But, when this happens, the networking receive path makes amends such
> that this works fine.  That's what the netpoll_receive_skb() check in
> netif_receive_skb() is for.  That check makes it bail out early if the
> call to netif_receive_skb() is via a netpoll invocation.
>

Oh, I see. This means we should call rcu_read_lock_bh() instead.
If Paul has no objections, I will send a patch for this.

Thanks much, David!

Re: 2.6.34-rc1: rcu lockdep bug?

[Eric Dumazet]

Le vendredi 12 mars 2010 à 16:59 +0800, Américo Wang a écrit :
> On Fri, Mar 12, 2010 at 4:07 PM, David Miller <davem@davemloft.net> wrote:
> > From: Américo Wang <xiyou.wangcong@gmail.com>
> > Date: Fri, 12 Mar 2010 15:56:03 +0800
> >
> >> Ok, after decoding the lockdep output, it looks like that
> >> netif_receive_skb() should call rcu_read_lock_bh() instead of rcu_read_lock()?
> >> But I don't know if all callers of netif_receive_skb() are in softirq context.
> >
> > Normally, netif_receive_skb() is invoked from softirq context.
> >
> > However, via netpoll it can be invoked essentially from any context.
> >
> > But, when this happens, the networking receive path makes amends such
> > that this works fine.  That's what the netpoll_receive_skb() check in
> > netif_receive_skb() is for.  That check makes it bail out early if the
> > call to netif_receive_skb() is via a netpoll invocation.
> >
> 
> Oh, I see. This means we should call rcu_read_lock_bh() instead.
> If Paul has no objections, I will send a patch for this.
> 

Nope, its calling rcu_read_lock() from interrupt context and it should
stay as is (we dont need to disable bh, this has a cpu cost)

Re: 2.6.34-rc1: rcu lockdep bug?

[Américo Wang]

On Fri, Mar 12, 2010 at 7:11 PM, Eric Dumazet <eric.dumazet@gmail.com> wrote:
> Le vendredi 12 mars 2010 à 16:59 +0800, Américo Wang a écrit :
>> On Fri, Mar 12, 2010 at 4:07 PM, David Miller <davem@davemloft.net> wrote:
>> > From: Américo Wang <xiyou.wangcong@gmail.com>
>> > Date: Fri, 12 Mar 2010 15:56:03 +0800
>> >
>> >> Ok, after decoding the lockdep output, it looks like that
>> >> netif_receive_skb() should call rcu_read_lock_bh() instead of rcu_read_lock()?
>> >> But I don't know if all callers of netif_receive_skb() are in softirq context.
>> >
>> > Normally, netif_receive_skb() is invoked from softirq context.
>> >
>> > However, via netpoll it can be invoked essentially from any context.
>> >
>> > But, when this happens, the networking receive path makes amends such
>> > that this works fine.  That's what the netpoll_receive_skb() check in
>> > netif_receive_skb() is for.  That check makes it bail out early if the
>> > call to netif_receive_skb() is via a netpoll invocation.
>> >
>>
>> Oh, I see. This means we should call rcu_read_lock_bh() instead.
>> If Paul has no objections, I will send a patch for this.
>>
>
> Nope, its calling rcu_read_lock() from interrupt context and it should
> stay as is (we dont need to disable bh, this has a cpu cost)
>

Oh, but lockdep complains about rcu_read_lock(), it said
rcu_read_lock() can't be used in softirq context.

Am I missing something?

Re: 2.6.34-rc1: rcu lockdep bug?

[Eric Dumazet]

Le vendredi 12 mars 2010 à 21:11 +0800, Américo Wang a écrit :

> Oh, but lockdep complains about rcu_read_lock(), it said
> rcu_read_lock() can't be used in softirq context.
> 
> Am I missing something?

Well, lockdep might be dumb, I dont know...

I suggest you read rcu_read_lock_bh kernel doc :

/**
 * rcu_read_lock_bh - mark the beginning of a softirq-only RCU critical
section
 *
 * This is equivalent of rcu_read_lock(), but to be used when updates
 * are being done using call_rcu_bh(). Since call_rcu_bh() callbacks
 * consider completion of a softirq handler to be a quiescent state,
 * a process in RCU read-side critical section must be protected by
 * disabling softirqs. Read-side critical sections in interrupt context
 * can use just rcu_read_lock().
 *
 */


Last sentence being perfect :

Read-side critical sections in interrupt context
can use just rcu_read_lock().

Re: 2.6.34-rc1: rcu lockdep bug?

[Américo Wang]

On Fri, Mar 12, 2010 at 02:37:38PM +0100, Eric Dumazet wrote:
>Le vendredi 12 mars 2010 à 21:11 +0800, Américo Wang a écrit :
>
>> Oh, but lockdep complains about rcu_read_lock(), it said
>> rcu_read_lock() can't be used in softirq context.
>> 
>> Am I missing something?
>
>Well, lockdep might be dumb, I dont know...
>
>I suggest you read rcu_read_lock_bh kernel doc :
>
>/**
> * rcu_read_lock_bh - mark the beginning of a softirq-only RCU critical
>section
> *
> * This is equivalent of rcu_read_lock(), but to be used when updates
> * are being done using call_rcu_bh(). Since call_rcu_bh() callbacks
> * consider completion of a softirq handler to be a quiescent state,
> * a process in RCU read-side critical section must be protected by
> * disabling softirqs. Read-side critical sections in interrupt context
> * can use just rcu_read_lock().
> *
> */
>
>
>Last sentence being perfect :
>
>Read-side critical sections in interrupt context
>can use just rcu_read_lock().
>

Yeah, right, then it is more likely to be a bug of rcu lockdep.
Paul is looking at it.

Thanks!

Re: 2.6.34-rc1: rcu lockdep bug?

[Paul E. McKenney]

On Sat, Mar 13, 2010 at 01:33:56PM +0800, Américo Wang wrote:
> On Fri, Mar 12, 2010 at 02:37:38PM +0100, Eric Dumazet wrote:
> >Le vendredi 12 mars 2010 à 21:11 +0800, Américo Wang a écrit :
> >
> >> Oh, but lockdep complains about rcu_read_lock(), it said
> >> rcu_read_lock() can't be used in softirq context.
> >> 
> >> Am I missing something?
> >
> >Well, lockdep might be dumb, I dont know...
> >
> >I suggest you read rcu_read_lock_bh kernel doc :
> >
> >/**
> > * rcu_read_lock_bh - mark the beginning of a softirq-only RCU critical
> >section
> > *
> > * This is equivalent of rcu_read_lock(), but to be used when updates
> > * are being done using call_rcu_bh(). Since call_rcu_bh() callbacks
> > * consider completion of a softirq handler to be a quiescent state,
> > * a process in RCU read-side critical section must be protected by
> > * disabling softirqs. Read-side critical sections in interrupt context
> > * can use just rcu_read_lock().
> > *
> > */
> >
> >
> >Last sentence being perfect :
> >
> >Read-side critical sections in interrupt context
> >can use just rcu_read_lock().
> >
> 
> Yeah, right, then it is more likely to be a bug of rcu lockdep.
> Paul is looking at it.

Except that it seems to be working correctly for me...

							Thanx, Paul

Re: 2.6.34-rc1: rcu lockdep bug?

[Américo Wang]

On Sat, Mar 13, 2010 at 01:58:38PM -0800, Paul E. McKenney wrote:
>On Sat, Mar 13, 2010 at 01:33:56PM +0800, Américo Wang wrote:
>> On Fri, Mar 12, 2010 at 02:37:38PM +0100, Eric Dumazet wrote:
>> >Le vendredi 12 mars 2010 à 21:11 +0800, Américo Wang a écrit :
>> >
>> >> Oh, but lockdep complains about rcu_read_lock(), it said
>> >> rcu_read_lock() can't be used in softirq context.
>> >> 
>> >> Am I missing something?
>> >
>> >Well, lockdep might be dumb, I dont know...
>> >
>> >I suggest you read rcu_read_lock_bh kernel doc :
>> >
>> >/**
>> > * rcu_read_lock_bh - mark the beginning of a softirq-only RCU critical
>> >section
>> > *
>> > * This is equivalent of rcu_read_lock(), but to be used when updates
>> > * are being done using call_rcu_bh(). Since call_rcu_bh() callbacks
>> > * consider completion of a softirq handler to be a quiescent state,
>> > * a process in RCU read-side critical section must be protected by
>> > * disabling softirqs. Read-side critical sections in interrupt context
>> > * can use just rcu_read_lock().
>> > *
>> > */
>> >
>> >
>> >Last sentence being perfect :
>> >
>> >Read-side critical sections in interrupt context
>> >can use just rcu_read_lock().
>> >
>> 
>> Yeah, right, then it is more likely to be a bug of rcu lockdep.
>> Paul is looking at it.
>
>Except that it seems to be working correctly for me...
>

Hmm, then I am confused. The only possibility here is that this is
a lockdep bug...

Thanks for your help!

Re: 2.6.34-rc1: rcu lockdep bug?

[Américo Wang]

2010/3/15 Américo Wang <xiyou.wangcong@gmail.com>:
> On Sat, Mar 13, 2010 at 01:58:38PM -0800, Paul E. McKenney wrote:
>>On Sat, Mar 13, 2010 at 01:33:56PM +0800, Américo Wang wrote:
>>> On Fri, Mar 12, 2010 at 02:37:38PM +0100, Eric Dumazet wrote:
>>> >Le vendredi 12 mars 2010 à 21:11 +0800, Américo Wang a écrit :
>>> >
>>> >> Oh, but lockdep complains about rcu_read_lock(), it said
>>> >> rcu_read_lock() can't be used in softirq context.
>>> >>
>>> >> Am I missing something?
>>> >
>>> >Well, lockdep might be dumb, I dont know...
>>> >
>>> >I suggest you read rcu_read_lock_bh kernel doc :
>>> >
>>> >/**
>>> > * rcu_read_lock_bh - mark the beginning of a softirq-only RCU critical
>>> >section
>>> > *
>>> > * This is equivalent of rcu_read_lock(), but to be used when updates
>>> > * are being done using call_rcu_bh(). Since call_rcu_bh() callbacks
>>> > * consider completion of a softirq handler to be a quiescent state,
>>> > * a process in RCU read-side critical section must be protected by
>>> > * disabling softirqs. Read-side critical sections in interrupt context
>>> > * can use just rcu_read_lock().
>>> > *
>>> > */
>>> >
>>> >
>>> >Last sentence being perfect :
>>> >
>>> >Read-side critical sections in interrupt context
>>> >can use just rcu_read_lock().
>>> >
>>>
>>> Yeah, right, then it is more likely to be a bug of rcu lockdep.
>>> Paul is looking at it.
>>
>>Except that it seems to be working correctly for me...
>>
>
> Hmm, then I am confused. The only possibility here is that this is
> a lockdep bug...
>

I believe so...

Peter, this looks odd:

 kernel:  (usbfs_mutex){+.?...}, at: [<ffffffff8146419f>]
netif_receive_skb+0xe7/0x819

netif_receive_skb() never has a chance to take usbfs_mutex. How can this
comes out?

Re: 2.6.34-rc1: rcu lockdep bug?

[Américo Wang]

2010/3/15 Américo Wang <xiyou.wangcong@gmail.com>:
> 2010/3/15 Américo Wang <xiyou.wangcong@gmail.com>:
>> On Sat, Mar 13, 2010 at 01:58:38PM -0800, Paul E. McKenney wrote:
>>>On Sat, Mar 13, 2010 at 01:33:56PM +0800, Américo Wang wrote:
>>>> On Fri, Mar 12, 2010 at 02:37:38PM +0100, Eric Dumazet wrote:
>>>> >Le vendredi 12 mars 2010 à 21:11 +0800, Américo Wang a écrit :
>>>> >
>>>> >> Oh, but lockdep complains about rcu_read_lock(), it said
>>>> >> rcu_read_lock() can't be used in softirq context.
>>>> >>
>>>> >> Am I missing something?
>>>> >
>>>> >Well, lockdep might be dumb, I dont know...
>>>> >
>>>> >I suggest you read rcu_read_lock_bh kernel doc :
>>>> >
>>>> >/**
>>>> > * rcu_read_lock_bh - mark the beginning of a softirq-only RCU critical
>>>> >section
>>>> > *
>>>> > * This is equivalent of rcu_read_lock(), but to be used when updates
>>>> > * are being done using call_rcu_bh(). Since call_rcu_bh() callbacks
>>>> > * consider completion of a softirq handler to be a quiescent state,
>>>> > * a process in RCU read-side critical section must be protected by
>>>> > * disabling softirqs. Read-side critical sections in interrupt context
>>>> > * can use just rcu_read_lock().
>>>> > *
>>>> > */
>>>> >
>>>> >
>>>> >Last sentence being perfect :
>>>> >
>>>> >Read-side critical sections in interrupt context
>>>> >can use just rcu_read_lock().
>>>> >
>>>>
>>>> Yeah, right, then it is more likely to be a bug of rcu lockdep.
>>>> Paul is looking at it.
>>>
>>>Except that it seems to be working correctly for me...
>>>
>>
>> Hmm, then I am confused. The only possibility here is that this is
>> a lockdep bug...
>>
>
> I believe so...
>
> Peter, this looks odd:
>
>  kernel:  (usbfs_mutex){+.?...}, at: [<ffffffff8146419f>]
> netif_receive_skb+0xe7/0x819
>
> netif_receive_skb() never has a chance to take usbfs_mutex. How can this
> comes out?
>

Ok, I think I found what lockdep really complains about, it is that we took
spin_lock in netpoll_poll_lock() which is in hardirq-enabled environment,
later, we took another spin_lock with spin_lock_irqsave() in netpoll_rx(),
so lockdep thought we broke the locking rule.

I don't know why netpoll_rx() needs irq disabled, it looks like that no one
takes rx_lock in hardirq context. So can we use spin_lock(&rx_lock)
instead? Or am I missing something here? Eric? David?

Thanks!

Re: 2.6.34-rc1: rcu lockdep bug?

[Eric Dumazet]

Le lundi 15 mars 2010 à 17:39 +0800, Américo Wang a écrit :

> 
> Ok, I think I found what lockdep really complains about, it is that we took
> spin_lock in netpoll_poll_lock() which is in hardirq-enabled environment,
> later, we took another spin_lock with spin_lock_irqsave() in netpoll_rx(),
> so lockdep thought we broke the locking rule.
> 
> I don't know why netpoll_rx() needs irq disabled, it looks like that no one
> takes rx_lock in hardirq context. So can we use spin_lock(&rx_lock)
> instead? Or am I missing something here? Eric? David?

I am a bit lost.

Could you give the complete picture, because I cannot find it in my
netdev archives.

Re: 2.6.34-rc1: rcu lockdep bug?

[Américo Wang]

On Mon, Mar 15, 2010 at 6:04 PM, Eric Dumazet <eric.dumazet@gmail.com> wrote:
> Le lundi 15 mars 2010 à 17:39 +0800, Américo Wang a écrit :
>
>>
>> Ok, I think I found what lockdep really complains about, it is that we took
>> spin_lock in netpoll_poll_lock() which is in hardirq-enabled environment,
>> later, we took another spin_lock with spin_lock_irqsave() in netpoll_rx(),
>> so lockdep thought we broke the locking rule.
>>
>> I don't know why netpoll_rx() needs irq disabled, it looks like that no one
>> takes rx_lock in hardirq context. So can we use spin_lock(&rx_lock)
>> instead? Or am I missing something here? Eric? David?
>
> I am a bit lost.
>
> Could you give the complete picture, because I cannot find it in my
> netdev archives.
>

Sure, sorry for this.

Here is the whole thread:

http://lkml.org/lkml/2010/3/11/100

Re: 2.6.34-rc1: rcu lockdep bug?

[Eric Dumazet]

Le lundi 15 mars 2010 à 18:12 +0800, Américo Wang a écrit :
> On Mon, Mar 15, 2010 at 6:04 PM, Eric Dumazet <eric.dumazet@gmail.com> wrote:
> > Le lundi 15 mars 2010 à 17:39 +0800, Américo Wang a écrit :
> >
> >>
> >> Ok, I think I found what lockdep really complains about, it is that we took
> >> spin_lock in netpoll_poll_lock() which is in hardirq-enabled environment,
> >> later, we took another spin_lock with spin_lock_irqsave() in netpoll_rx(),
> >> so lockdep thought we broke the locking rule.
> >>
> >> I don't know why netpoll_rx() needs irq disabled, it looks like that no one
> >> takes rx_lock in hardirq context. So can we use spin_lock(&rx_lock)
> >> instead? Or am I missing something here? Eric? David?
> >
> > I am a bit lost.
> >
> > Could you give the complete picture, because I cannot find it in my
> > netdev archives.
> >
> 
> Sure, sorry for this.
> 
> Here is the whole thread:
> 
> http://lkml.org/lkml/2010/3/11/100

OK thanks

netpoll_rx() can be called from hard irqs (netif_rx()), so rx_lock
definitly needs irq care.

netpoll_poll_lock() does take a spinlock with irq enabled, but its not
rx_lock, its napi->poll_lock.

I dont see what could be the problem, is it reproductible with vanilla
kernel ?

Re: 2.6.34-rc1: rcu lockdep bug?

[Américo Wang]

On Mon, Mar 15, 2010 at 6:41 PM, Eric Dumazet <eric.dumazet@gmail.com> wrote:
> Le lundi 15 mars 2010 à 18:12 +0800, Américo Wang a écrit :
>> On Mon, Mar 15, 2010 at 6:04 PM, Eric Dumazet <eric.dumazet@gmail.com> wrote:
>> > Le lundi 15 mars 2010 à 17:39 +0800, Américo Wang a écrit :
>> >
>> >>
>> >> Ok, I think I found what lockdep really complains about, it is that we took
>> >> spin_lock in netpoll_poll_lock() which is in hardirq-enabled environment,
>> >> later, we took another spin_lock with spin_lock_irqsave() in netpoll_rx(),
>> >> so lockdep thought we broke the locking rule.
>> >>
>> >> I don't know why netpoll_rx() needs irq disabled, it looks like that no one
>> >> takes rx_lock in hardirq context. So can we use spin_lock(&rx_lock)
>> >> instead? Or am I missing something here? Eric? David?
>> >
>> > I am a bit lost.
>> >
>> > Could you give the complete picture, because I cannot find it in my
>> > netdev archives.
>> >
>>
>> Sure, sorry for this.
>>
>> Here is the whole thread:
>>
>> http://lkml.org/lkml/2010/3/11/100
>
> OK thanks
>
> netpoll_rx() can be called from hard irqs (netif_rx()), so rx_lock
> definitly needs irq care.
>
> netpoll_poll_lock() does take a spinlock with irq enabled, but its not
> rx_lock, its napi->poll_lock.

Yeah, I knew, but besides rcu locks, these two locks are the only
locks that can be taken in the call chain. I suspect lockdep got
something wrong.

>
> I dont see what could be the problem, is it reproductible with vanilla
> kernel ?
>

No. I don't know why, my patch doesn't touch any function in the
call chain.

I already "fix" this in another way, so no need to worry this any more.

Thanks for your help!

Re: 2.6.34-rc1: rcu lockdep bug?

[Paul E. McKenney]

On Fri, Mar 12, 2010 at 09:11:02PM +0800, Américo Wang wrote:
> On Fri, Mar 12, 2010 at 7:11 PM, Eric Dumazet <eric.dumazet@gmail.com> wrote:
> > Le vendredi 12 mars 2010 à 16:59 +0800, Américo Wang a écrit :
> >> On Fri, Mar 12, 2010 at 4:07 PM, David Miller <davem@davemloft.net> wrote:
> >> > From: Américo Wang <xiyou.wangcong@gmail.com>
> >> > Date: Fri, 12 Mar 2010 15:56:03 +0800
> >> >
> >> >> Ok, after decoding the lockdep output, it looks like that
> >> >> netif_receive_skb() should call rcu_read_lock_bh() instead of rcu_read_lock()?
> >> >> But I don't know if all callers of netif_receive_skb() are in softirq context.
> >> >
> >> > Normally, netif_receive_skb() is invoked from softirq context.
> >> >
> >> > However, via netpoll it can be invoked essentially from any context.
> >> >
> >> > But, when this happens, the networking receive path makes amends such
> >> > that this works fine.  That's what the netpoll_receive_skb() check in
> >> > netif_receive_skb() is for.  That check makes it bail out early if the
> >> > call to netif_receive_skb() is via a netpoll invocation.
> >> >
> >>
> >> Oh, I see. This means we should call rcu_read_lock_bh() instead.
> >> If Paul has no objections, I will send a patch for this.
> >>
> >
> > Nope, its calling rcu_read_lock() from interrupt context and it should
> > stay as is (we dont need to disable bh, this has a cpu cost)
> >
> 
> Oh, but lockdep complains about rcu_read_lock(), it said
> rcu_read_lock() can't be used in softirq context.
> 
> Am I missing something?

Hmmm...  It is supposed to be OK to use rcu_read_lock() in pretty much
any context, even NMI.  I will take a look.

							Thanx, Paul

Re: 2.6.34-rc1: rcu lockdep bug?

[Américo Wang]

On Fri, Mar 12, 2010 at 02:03:19PM -0800, Paul E. McKenney wrote:
>On Fri, Mar 12, 2010 at 09:11:02PM +0800, Américo Wang wrote:
>> On Fri, Mar 12, 2010 at 7:11 PM, Eric Dumazet <eric.dumazet@gmail.com> wrote:
>> > Le vendredi 12 mars 2010 à 16:59 +0800, Américo Wang a écrit :
>> >> On Fri, Mar 12, 2010 at 4:07 PM, David Miller <davem@davemloft.net> wrote:
>> >> > From: Américo Wang <xiyou.wangcong@gmail.com>
>> >> > Date: Fri, 12 Mar 2010 15:56:03 +0800
>> >> >
>> >> >> Ok, after decoding the lockdep output, it looks like that
>> >> >> netif_receive_skb() should call rcu_read_lock_bh() instead of rcu_read_lock()?
>> >> >> But I don't know if all callers of netif_receive_skb() are in softirq context.
>> >> >
>> >> > Normally, netif_receive_skb() is invoked from softirq context.
>> >> >
>> >> > However, via netpoll it can be invoked essentially from any context.
>> >> >
>> >> > But, when this happens, the networking receive path makes amends such
>> >> > that this works fine.  That's what the netpoll_receive_skb() check in
>> >> > netif_receive_skb() is for.  That check makes it bail out early if the
>> >> > call to netif_receive_skb() is via a netpoll invocation.
>> >> >
>> >>
>> >> Oh, I see. This means we should call rcu_read_lock_bh() instead.
>> >> If Paul has no objections, I will send a patch for this.
>> >>
>> >
>> > Nope, its calling rcu_read_lock() from interrupt context and it should
>> > stay as is (we dont need to disable bh, this has a cpu cost)
>> >
>> 
>> Oh, but lockdep complains about rcu_read_lock(), it said
>> rcu_read_lock() can't be used in softirq context.
>> 
>> Am I missing something?
>
>Hmmm...  It is supposed to be OK to use rcu_read_lock() in pretty much
>any context, even NMI.  I will take a look.
>

Thanks! Please let me know if you have new progress.