[BUG] Inconsistent lock state in virtnet poll

[BUG] Inconsistent lock state in virtnet poll

[Thomas Gleixner]

The following lockdep splat happens reproducibly on 5.7-rc4

Thanks,

        tglx

================================
WARNING: inconsistent lock state
5.7.0-rc4+ #79 Not tainted
--------------------------------
inconsistent {SOFTIRQ-ON-W} -> {IN-SOFTIRQ-W} usage.
ip/356 [HC0[0]:SC1[1]:HE1:SE0] takes:
f3ee4cd8 (&syncp->seq#2){+.?.}-{0:0}, at: net_rx_action+0xfb/0x390
{SOFTIRQ-ON-W} state was registered at:
  lock_acquire+0x82/0x300
  try_fill_recv+0x39f/0x590
  virtnet_open+0xe0/0x180
  __dev_open+0xbe/0x160
  __dev_change_flags+0x152/0x1b0
  dev_change_flags+0x23/0x60
  do_setlink+0x814/0xa30
  __rtnl_newlink+0x583/0x8e0
  rtnl_newlink+0x36/0x60
  rtnetlink_rcv_msg+0x139/0x470
  netlink_rcv_skb+0x6a/0xe0
  rtnetlink_rcv+0xd/0x10
  netlink_unicast+0x175/0x250
  netlink_sendmsg+0x263/0x440
  sock_sendmsg+0x5c/0x60
  ____sys_sendmsg+0x182/0x1d0
  ___sys_sendmsg+0x59/0x90
  __sys_sendmsg+0x39/0x80
  __ia32_sys_socketcall+0x2d2/0x330
  do_fast_syscall_32+0x82/0x340
  entry_SYSENTER_32+0xaa/0x102
irq event stamp: 2276
hardirqs last  enabled at (2276): [<c18e419e>] net_rx_action+0x7e/0x390
hardirqs last disabled at (2275): [<c18e4178>] net_rx_action+0x58/0x390
softirqs last  enabled at (2272): [<c16f87ee>] virtnet_napi_enable+0xe/0x50
softirqs last disabled at (2273): [<c101fb10>] call_on_stack+0x40/0x50

other info that might help us debug this:
 Possible unsafe locking scenario:

       CPU0
       ----
  lock(&syncp->seq#2);
  <Interrupt>
    lock(&syncp->seq#2);

 *** DEADLOCK ***

1 lock held by ip/356:
 #0: c20a4a38 (rtnl_mutex){+.+.}-{3:3}, at: rtnetlink_rcv_msg+0x118/0x470

stack backtrace:
CPU: 2 PID: 356 Comm: ip Not tainted 5.7.0-rc4+ #79
Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.12.0-1 04/01/2014
Call Trace:
 <SOFTIRQ>
 dump_stack+0x6e/0x9e
 print_usage_bug.cold+0x15a/0x162
 mark_lock+0x58d/0x6e0
 ? check_usage_backwards+0x180/0x180
 __lock_acquire+0xdd7/0x24f0
 ? select_task_rq_fair+0xbb/0xfe0
 ? __lock_acquire+0x35f/0x24f0
 ? __lock_acquire+0x35f/0x24f0
 ? __lock_acquire+0x35f/0x24f0
 lock_acquire+0x82/0x300
 ? net_rx_action+0xfb/0x390
 ? find_held_lock+0x24/0x80
 ? lock_release+0x8a/0x260
 ? virtnet_poll+0xd0/0x3d9
 virtnet_poll+0x1d3/0x3d9
 ? net_rx_action+0xfb/0x390
 ? trace_hardirqs_on+0x4a/0xf0
 net_rx_action+0xfb/0x390
 ? __do_softirq+0x84/0x3ca
 ? virtnet_napi_enable+0xe/0x50
 __do_softirq+0xb1/0x3ca
 ? virtnet_napi_enable+0xe/0x50
 ? __irqentry_text_end+0x8/0x8
 call_on_stack+0x40/0x50
 </SOFTIRQ>
 ? do_softirq.part.0+0x4e/0x50
 ? __local_bh_enable_ip+0xd1/0xe0
 ? virtnet_napi_enable+0x41/0x50
 ? virtnet_open+0x7f/0x180
 ? __dev_open+0xbe/0x160
 ? __dev_change_flags+0x152/0x1b0
 ? dev_change_flags+0x23/0x60
 ? do_setlink+0x814/0xa30
 ? __lock_acquire+0x35f/0x24f0
 ? __nla_parse+0x1c/0x30
 ? __rtnl_newlink+0x583/0x8e0
 ? lock_acquire+0x82/0x300
 ? handle_mm_fault+0x6e6/0xa10
 ? find_held_lock+0x24/0x80
 ? __lock_acquire+0x35f/0x24f0
 ? lock_acquire+0x82/0x300
 ? __lock_acquire+0x35f/0x24f0
 ? rtnl_newlink+0x23/0x60
 ? rcu_read_lock_sched_held+0x3f/0x70
 ? kmem_cache_alloc_trace+0x235/0x260
 ? rtnl_newlink+0x36/0x60
 ? __rtnl_newlink+0x8e0/0x8e0
 ? rtnetlink_rcv_msg+0x139/0x470
 ? netlink_deliver_tap+0x81/0x3a0
 ? find_held_lock+0x24/0x80
 ? rtnl_bridge_getlink+0x240/0x240
 ? netlink_rcv_skb+0x6a/0xe0
 ? rtnl_bridge_getlink+0x240/0x240
 ? rtnetlink_rcv+0xd/0x10
 ? netlink_unicast+0x175/0x250
 ? netlink_sendmsg+0x263/0x440
 ? netlink_unicast+0x250/0x250
 ? sock_sendmsg+0x5c/0x60
 ? ____sys_sendmsg+0x182/0x1d0
 ? ___sys_sendmsg+0x59/0x90
 ? lock_acquire+0x82/0x300
 ? __might_fault+0x39/0x80
 ? __sys_sendmsg+0x39/0x80
 ? __ia32_sys_socketcall+0x2d2/0x330
 ? do_fast_syscall_32+0x82/0x340
 ? entry_SYSENTER_32+0xaa/0x102

Re: [BUG] Inconsistent lock state in virtnet poll

[Michael S. Tsirkin]

On Tue, May 05, 2020 at 02:08:56PM +0200, Thomas Gleixner wrote:
> 
> The following lockdep splat happens reproducibly on 5.7-rc4
> 
> Thanks,
> 
>         tglx
> 
> ================================
> WARNING: inconsistent lock state
> 5.7.0-rc4+ #79 Not tainted
> --------------------------------
> inconsistent {SOFTIRQ-ON-W} -> {IN-SOFTIRQ-W} usage.
> ip/356 [HC0[0]:SC1[1]:HE1:SE0] takes:
> f3ee4cd8 (&syncp->seq#2){+.?.}-{0:0}, at: net_rx_action+0xfb/0x390
> {SOFTIRQ-ON-W} state was registered at:
>   lock_acquire+0x82/0x300
>   try_fill_recv+0x39f/0x590

Weird. Where does try_fill_recv acquire any locks?


>   virtnet_open+0xe0/0x180
>   __dev_open+0xbe/0x160
>   __dev_change_flags+0x152/0x1b0
>   dev_change_flags+0x23/0x60
>   do_setlink+0x814/0xa30
>   __rtnl_newlink+0x583/0x8e0
>   rtnl_newlink+0x36/0x60
>   rtnetlink_rcv_msg+0x139/0x470
>   netlink_rcv_skb+0x6a/0xe0
>   rtnetlink_rcv+0xd/0x10
>   netlink_unicast+0x175/0x250
>   netlink_sendmsg+0x263/0x440
>   sock_sendmsg+0x5c/0x60
>   ____sys_sendmsg+0x182/0x1d0
>   ___sys_sendmsg+0x59/0x90
>   __sys_sendmsg+0x39/0x80
>   __ia32_sys_socketcall+0x2d2/0x330
>   do_fast_syscall_32+0x82/0x340
>   entry_SYSENTER_32+0xaa/0x102
> irq event stamp: 2276
> hardirqs last  enabled at (2276): [<c18e419e>] net_rx_action+0x7e/0x390
> hardirqs last disabled at (2275): [<c18e4178>] net_rx_action+0x58/0x390
> softirqs last  enabled at (2272): [<c16f87ee>] virtnet_napi_enable+0xe/0x50
> softirqs last disabled at (2273): [<c101fb10>] call_on_stack+0x40/0x50
> 
> other info that might help us debug this:
>  Possible unsafe locking scenario:
> 
>        CPU0
>        ----
>   lock(&syncp->seq#2);
>   <Interrupt>
>     lock(&syncp->seq#2);
> 
>  *** DEADLOCK ***
> 
> 1 lock held by ip/356:
>  #0: c20a4a38 (rtnl_mutex){+.+.}-{3:3}, at: rtnetlink_rcv_msg+0x118/0x470
> 
> stack backtrace:
> CPU: 2 PID: 356 Comm: ip Not tainted 5.7.0-rc4+ #79
> Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.12.0-1 04/01/2014
> Call Trace:
>  <SOFTIRQ>
>  dump_stack+0x6e/0x9e
>  print_usage_bug.cold+0x15a/0x162
>  mark_lock+0x58d/0x6e0
>  ? check_usage_backwards+0x180/0x180
>  __lock_acquire+0xdd7/0x24f0
>  ? select_task_rq_fair+0xbb/0xfe0
>  ? __lock_acquire+0x35f/0x24f0
>  ? __lock_acquire+0x35f/0x24f0
>  ? __lock_acquire+0x35f/0x24f0
>  lock_acquire+0x82/0x300
>  ? net_rx_action+0xfb/0x390
>  ? find_held_lock+0x24/0x80
>  ? lock_release+0x8a/0x260
>  ? virtnet_poll+0xd0/0x3d9
>  virtnet_poll+0x1d3/0x3d9
>  ? net_rx_action+0xfb/0x390
>  ? trace_hardirqs_on+0x4a/0xf0
>  net_rx_action+0xfb/0x390
>  ? __do_softirq+0x84/0x3ca
>  ? virtnet_napi_enable+0xe/0x50
>  __do_softirq+0xb1/0x3ca
>  ? virtnet_napi_enable+0xe/0x50
>  ? __irqentry_text_end+0x8/0x8
>  call_on_stack+0x40/0x50
>  </SOFTIRQ>
>  ? do_softirq.part.0+0x4e/0x50
>  ? __local_bh_enable_ip+0xd1/0xe0
>  ? virtnet_napi_enable+0x41/0x50
>  ? virtnet_open+0x7f/0x180
>  ? __dev_open+0xbe/0x160
>  ? __dev_change_flags+0x152/0x1b0
>  ? dev_change_flags+0x23/0x60
>  ? do_setlink+0x814/0xa30
>  ? __lock_acquire+0x35f/0x24f0
>  ? __nla_parse+0x1c/0x30
>  ? __rtnl_newlink+0x583/0x8e0
>  ? lock_acquire+0x82/0x300
>  ? handle_mm_fault+0x6e6/0xa10
>  ? find_held_lock+0x24/0x80
>  ? __lock_acquire+0x35f/0x24f0
>  ? lock_acquire+0x82/0x300
>  ? __lock_acquire+0x35f/0x24f0
>  ? rtnl_newlink+0x23/0x60
>  ? rcu_read_lock_sched_held+0x3f/0x70
>  ? kmem_cache_alloc_trace+0x235/0x260
>  ? rtnl_newlink+0x36/0x60
>  ? __rtnl_newlink+0x8e0/0x8e0
>  ? rtnetlink_rcv_msg+0x139/0x470
>  ? netlink_deliver_tap+0x81/0x3a0
>  ? find_held_lock+0x24/0x80
>  ? rtnl_bridge_getlink+0x240/0x240
>  ? netlink_rcv_skb+0x6a/0xe0
>  ? rtnl_bridge_getlink+0x240/0x240
>  ? rtnetlink_rcv+0xd/0x10
>  ? netlink_unicast+0x175/0x250
>  ? netlink_sendmsg+0x263/0x440
>  ? netlink_unicast+0x250/0x250
>  ? sock_sendmsg+0x5c/0x60
>  ? ____sys_sendmsg+0x182/0x1d0
>  ? ___sys_sendmsg+0x59/0x90
>  ? lock_acquire+0x82/0x300
>  ? __might_fault+0x39/0x80
>  ? __sys_sendmsg+0x39/0x80
>  ? __ia32_sys_socketcall+0x2d2/0x330
>  ? do_fast_syscall_32+0x82/0x340
>  ? entry_SYSENTER_32+0xaa/0x102

Re: [BUG] Inconsistent lock state in virtnet poll

[Thomas Gleixner]

"Michael S. Tsirkin" <mst@redhat.com> writes:
> On Tue, May 05, 2020 at 02:08:56PM +0200, Thomas Gleixner wrote:
>> 
>> The following lockdep splat happens reproducibly on 5.7-rc4
>
>> ================================
>> WARNING: inconsistent lock state
>> 5.7.0-rc4+ #79 Not tainted
>> --------------------------------
>> inconsistent {SOFTIRQ-ON-W} -> {IN-SOFTIRQ-W} usage.
>> ip/356 [HC0[0]:SC1[1]:HE1:SE0] takes:
>> f3ee4cd8 (&syncp->seq#2){+.?.}-{0:0}, at: net_rx_action+0xfb/0x390
>> {SOFTIRQ-ON-W} state was registered at:
>>   lock_acquire+0x82/0x300
>>   try_fill_recv+0x39f/0x590
>
> Weird. Where does try_fill_recv acquire any locks?

  u64_stats_update_begin(&rq->stats.syncp);

That's a 32bit kernel which uses a seqcount for this. sequence counts
are "lock" constructs where you need to make sure that writers are
serialized.

Actually the problem at hand is that try_fill_recv() is called from
fully preemptible context initialy and then from softirq context.

Obviously that's for the open() path a non issue, but lockdep does not
know about that. OTOH, there is other code which calls that from
non-softirq context.

The hack below made it shut up. It's obvioulsy not ideal, but at least
it let me look at the actual problem I was chasing down :)

Thanks,

        tglx

8<-----------
--- a/drivers/net/virtio_net.c
+++ b/drivers/net/virtio_net.c
@@ -1243,9 +1243,11 @@ static bool try_fill_recv(struct virtnet
 			break;
 	} while (rq->vq->num_free);
 	if (virtqueue_kick_prepare(rq->vq) && virtqueue_notify(rq->vq)) {
+		local_bh_disable();
 		u64_stats_update_begin(&rq->stats.syncp);
 		rq->stats.kicks++;
 		u64_stats_update_end(&rq->stats.syncp);
+		local_bh_enable();
 	}
 
 	return !oom;

Re: [BUG] Inconsistent lock state in virtnet poll

[Eric Dumazet]

On 5/5/20 3:30 PM, Thomas Gleixner wrote:
> "Michael S. Tsirkin" <mst@redhat.com> writes:
>> On Tue, May 05, 2020 at 02:08:56PM +0200, Thomas Gleixner wrote:
>>>
>>> The following lockdep splat happens reproducibly on 5.7-rc4
>>
>>> ================================
>>> WARNING: inconsistent lock state
>>> 5.7.0-rc4+ #79 Not tainted
>>> --------------------------------
>>> inconsistent {SOFTIRQ-ON-W} -> {IN-SOFTIRQ-W} usage.
>>> ip/356 [HC0[0]:SC1[1]:HE1:SE0] takes:
>>> f3ee4cd8 (&syncp->seq#2){+.?.}-{0:0}, at: net_rx_action+0xfb/0x390
>>> {SOFTIRQ-ON-W} state was registered at:
>>>   lock_acquire+0x82/0x300
>>>   try_fill_recv+0x39f/0x590
>>
>> Weird. Where does try_fill_recv acquire any locks?
> 
>   u64_stats_update_begin(&rq->stats.syncp);
> 
> That's a 32bit kernel which uses a seqcount for this. sequence counts
> are "lock" constructs where you need to make sure that writers are
> serialized.
> 
> Actually the problem at hand is that try_fill_recv() is called from
> fully preemptible context initialy and then from softirq context.
> 
> Obviously that's for the open() path a non issue, but lockdep does not
> know about that. OTOH, there is other code which calls that from
> non-softirq context.
> 
> The hack below made it shut up. It's obvioulsy not ideal, but at least
> it let me look at the actual problem I was chasing down :)
> 
> Thanks,
> 
>         tglx
> 
> 8<-----------
> --- a/drivers/net/virtio_net.c
> +++ b/drivers/net/virtio_net.c
> @@ -1243,9 +1243,11 @@ static bool try_fill_recv(struct virtnet
>  			break;
>  	} while (rq->vq->num_free);
>  	if (virtqueue_kick_prepare(rq->vq) && virtqueue_notify(rq->vq)) {
> +		local_bh_disable();

Or use u64_stats_update_begin_irqsave() whic is a NOP on 64bit kernels

>  		u64_stats_update_begin(&rq->stats.syncp);
>  		rq->stats.kicks++;
>  		u64_stats_update_end(&rq->stats.syncp);
> +		local_bh_enable();
>  	}
>  
>  	return !oom;
> 

Re: [BUG] Inconsistent lock state in virtnet poll

[Michael S. Tsirkin]

On Tue, May 05, 2020 at 03:40:09PM -0700, Eric Dumazet wrote:
> 
> 
> On 5/5/20 3:30 PM, Thomas Gleixner wrote:
> > "Michael S. Tsirkin" <mst@redhat.com> writes:
> >> On Tue, May 05, 2020 at 02:08:56PM +0200, Thomas Gleixner wrote:
> >>>
> >>> The following lockdep splat happens reproducibly on 5.7-rc4
> >>
> >>> ================================
> >>> WARNING: inconsistent lock state
> >>> 5.7.0-rc4+ #79 Not tainted
> >>> --------------------------------
> >>> inconsistent {SOFTIRQ-ON-W} -> {IN-SOFTIRQ-W} usage.
> >>> ip/356 [HC0[0]:SC1[1]:HE1:SE0] takes:
> >>> f3ee4cd8 (&syncp->seq#2){+.?.}-{0:0}, at: net_rx_action+0xfb/0x390
> >>> {SOFTIRQ-ON-W} state was registered at:
> >>>   lock_acquire+0x82/0x300
> >>>   try_fill_recv+0x39f/0x590
> >>
> >> Weird. Where does try_fill_recv acquire any locks?
> > 
> >   u64_stats_update_begin(&rq->stats.syncp);
> > 
> > That's a 32bit kernel which uses a seqcount for this. sequence counts
> > are "lock" constructs where you need to make sure that writers are
> > serialized.
> > 
> > Actually the problem at hand is that try_fill_recv() is called from
> > fully preemptible context initialy and then from softirq context.
> > 
> > Obviously that's for the open() path a non issue, but lockdep does not
> > know about that. OTOH, there is other code which calls that from
> > non-softirq context.
> > 
> > The hack below made it shut up. It's obvioulsy not ideal, but at least
> > it let me look at the actual problem I was chasing down :)
> > 
> > Thanks,
> > 
> >         tglx
> > 
> > 8<-----------
> > --- a/drivers/net/virtio_net.c
> > +++ b/drivers/net/virtio_net.c
> > @@ -1243,9 +1243,11 @@ static bool try_fill_recv(struct virtnet
> >  			break;
> >  	} while (rq->vq->num_free);
> >  	if (virtqueue_kick_prepare(rq->vq) && virtqueue_notify(rq->vq)) {
> > +		local_bh_disable();
> 
> Or use u64_stats_update_begin_irqsave() whic is a NOP on 64bit kernels

I like this better I think.

Will send a patch now.

-- 
MST

Re: [BUG] Inconsistent lock state in virtnet poll

[Michael S. Tsirkin]

On Wed, May 06, 2020 at 12:30:52AM +0200, Thomas Gleixner wrote:
> "Michael S. Tsirkin" <mst@redhat.com> writes:
> > On Tue, May 05, 2020 at 02:08:56PM +0200, Thomas Gleixner wrote:
> >> 
> >> The following lockdep splat happens reproducibly on 5.7-rc4
> >
> >> ================================
> >> WARNING: inconsistent lock state
> >> 5.7.0-rc4+ #79 Not tainted
> >> --------------------------------
> >> inconsistent {SOFTIRQ-ON-W} -> {IN-SOFTIRQ-W} usage.
> >> ip/356 [HC0[0]:SC1[1]:HE1:SE0] takes:
> >> f3ee4cd8 (&syncp->seq#2){+.?.}-{0:0}, at: net_rx_action+0xfb/0x390
> >> {SOFTIRQ-ON-W} state was registered at:
> >>   lock_acquire+0x82/0x300
> >>   try_fill_recv+0x39f/0x590
> >
> > Weird. Where does try_fill_recv acquire any locks?
> 
>   u64_stats_update_begin(&rq->stats.syncp);
> 
> That's a 32bit kernel which uses a seqcount for this. sequence counts
> are "lock" constructs where you need to make sure that writers are
> serialized.
> 
> Actually the problem at hand is that try_fill_recv() is called from
> fully preemptible context initialy and then from softirq context.
> 
> Obviously that's for the open() path a non issue, but lockdep does not
> know about that. OTOH, there is other code which calls that from
> non-softirq context.

Well to be more specific, try_fill_recv is either called from napi,
or from preemptible contexts with napi disabled and rtnl lock taken.

Two try_fill_recv calls in parallel would cause ring corruption
and no end of mischief, we certainly don't want that even on 64 bit
kernels.


> The hack below made it shut up. It's obvioulsy not ideal, but at least
> it let me look at the actual problem I was chasing down :)
> 
> Thanks,
> 
>         tglx

I'll post a hack based on Eric's suggestion since that is at least
0-overhead on 64 bit. It would be nice if we could teach
lockdep that it's about napi...


> 8<-----------
> --- a/drivers/net/virtio_net.c
> +++ b/drivers/net/virtio_net.c
> @@ -1243,9 +1243,11 @@ static bool try_fill_recv(struct virtnet
>  			break;
>  	} while (rq->vq->num_free);
>  	if (virtqueue_kick_prepare(rq->vq) && virtqueue_notify(rq->vq)) {
> +		local_bh_disable();
>  		u64_stats_update_begin(&rq->stats.syncp);
>  		rq->stats.kicks++;
>  		u64_stats_update_end(&rq->stats.syncp);
> +		local_bh_enable();
>  	}
>  
>  	return !oom;

Re: [BUG] Inconsistent lock state in virtnet poll

[Michael S. Tsirkin]

On Tue, May 05, 2020 at 03:40:09PM -0700, Eric Dumazet wrote:
> 
> 
> On 5/5/20 3:30 PM, Thomas Gleixner wrote:
> > "Michael S. Tsirkin" <mst@redhat.com> writes:
> >> On Tue, May 05, 2020 at 02:08:56PM +0200, Thomas Gleixner wrote:
> >>>
> >>> The following lockdep splat happens reproducibly on 5.7-rc4
> >>
> >>> ================================
> >>> WARNING: inconsistent lock state
> >>> 5.7.0-rc4+ #79 Not tainted
> >>> --------------------------------
> >>> inconsistent {SOFTIRQ-ON-W} -> {IN-SOFTIRQ-W} usage.
> >>> ip/356 [HC0[0]:SC1[1]:HE1:SE0] takes:
> >>> f3ee4cd8 (&syncp->seq#2){+.?.}-{0:0}, at: net_rx_action+0xfb/0x390
> >>> {SOFTIRQ-ON-W} state was registered at:
> >>>   lock_acquire+0x82/0x300
> >>>   try_fill_recv+0x39f/0x590
> >>
> >> Weird. Where does try_fill_recv acquire any locks?
> > 
> >   u64_stats_update_begin(&rq->stats.syncp);
> > 
> > That's a 32bit kernel which uses a seqcount for this. sequence counts
> > are "lock" constructs where you need to make sure that writers are
> > serialized.
> > 
> > Actually the problem at hand is that try_fill_recv() is called from
> > fully preemptible context initialy and then from softirq context.
> > 
> > Obviously that's for the open() path a non issue, but lockdep does not
> > know about that. OTOH, there is other code which calls that from
> > non-softirq context.
> > 
> > The hack below made it shut up. It's obvioulsy not ideal, but at least
> > it let me look at the actual problem I was chasing down :)
> > 
> > Thanks,
> > 
> >         tglx
> > 
> > 8<-----------
> > --- a/drivers/net/virtio_net.c
> > +++ b/drivers/net/virtio_net.c
> > @@ -1243,9 +1243,11 @@ static bool try_fill_recv(struct virtnet
> >  			break;
> >  	} while (rq->vq->num_free);
> >  	if (virtqueue_kick_prepare(rq->vq) && virtqueue_notify(rq->vq)) {
> > +		local_bh_disable();
> 
> Or use u64_stats_update_begin_irqsave() whic is a NOP on 64bit kernels

I applied this, but am still trying to think of something that
is 0 overhead for all configs.
Maybe we can select a lockdep class depending on whether napi
is enabled?


> >  		u64_stats_update_begin(&rq->stats.syncp);
> >  		rq->stats.kicks++;
> >  		u64_stats_update_end(&rq->stats.syncp);
> > +		local_bh_enable();
> >  	}
> >  
> >  	return !oom;
> > 

Re: [BUG] Inconsistent lock state in virtnet poll

[Eric Dumazet]

On 5/5/20 5:43 PM, Michael S. Tsirkin wrote:
> On Tue, May 05, 2020 at 03:40:09PM -0700, Eric Dumazet wrote:
>>
>>
>> On 5/5/20 3:30 PM, Thomas Gleixner wrote:
>>> "Michael S. Tsirkin" <mst@redhat.com> writes:
>>>> On Tue, May 05, 2020 at 02:08:56PM +0200, Thomas Gleixner wrote:
>>>>>
>>>>> The following lockdep splat happens reproducibly on 5.7-rc4
>>>>
>>>>> ================================
>>>>> WARNING: inconsistent lock state
>>>>> 5.7.0-rc4+ #79 Not tainted
>>>>> --------------------------------
>>>>> inconsistent {SOFTIRQ-ON-W} -> {IN-SOFTIRQ-W} usage.
>>>>> ip/356 [HC0[0]:SC1[1]:HE1:SE0] takes:
>>>>> f3ee4cd8 (&syncp->seq#2){+.?.}-{0:0}, at: net_rx_action+0xfb/0x390
>>>>> {SOFTIRQ-ON-W} state was registered at:
>>>>>   lock_acquire+0x82/0x300
>>>>>   try_fill_recv+0x39f/0x590
>>>>
>>>> Weird. Where does try_fill_recv acquire any locks?
>>>
>>>   u64_stats_update_begin(&rq->stats.syncp);
>>>
>>> That's a 32bit kernel which uses a seqcount for this. sequence counts
>>> are "lock" constructs where you need to make sure that writers are
>>> serialized.
>>>
>>> Actually the problem at hand is that try_fill_recv() is called from
>>> fully preemptible context initialy and then from softirq context.
>>>
>>> Obviously that's for the open() path a non issue, but lockdep does not
>>> know about that. OTOH, there is other code which calls that from
>>> non-softirq context.
>>>
>>> The hack below made it shut up. It's obvioulsy not ideal, but at least
>>> it let me look at the actual problem I was chasing down :)
>>>
>>> Thanks,
>>>
>>>         tglx
>>>
>>> 8<-----------
>>> --- a/drivers/net/virtio_net.c
>>> +++ b/drivers/net/virtio_net.c
>>> @@ -1243,9 +1243,11 @@ static bool try_fill_recv(struct virtnet
>>>  			break;
>>>  	} while (rq->vq->num_free);
>>>  	if (virtqueue_kick_prepare(rq->vq) && virtqueue_notify(rq->vq)) {
>>> +		local_bh_disable();
>>
>> Or use u64_stats_update_begin_irqsave() whic is a NOP on 64bit kernels
> 
> I applied this, but am still trying to think of something that
> is 0 overhead for all configs.
> Maybe we can select a lockdep class depending on whether napi
> is enabled?


Do you _really_ need 64bit counter for stats.kicks on 32bit kernels ?

Adding 64bit counters just because we can might be overhead anyway.

> 
> 
>>>  		u64_stats_update_begin(&rq->stats.syncp);
>>>  		rq->stats.kicks++;
>>>  		u64_stats_update_end(&rq->stats.syncp);
>>> +		local_bh_enable();
>>>  	}
>>>  
>>>  	return !oom;
>>>
> 

Re: [BUG] Inconsistent lock state in virtnet poll

[Michael S. Tsirkin]

On Tue, May 05, 2020 at 06:19:09PM -0700, Eric Dumazet wrote:
> 
> 
> On 5/5/20 5:43 PM, Michael S. Tsirkin wrote:
> > On Tue, May 05, 2020 at 03:40:09PM -0700, Eric Dumazet wrote:
> >>
> >>
> >> On 5/5/20 3:30 PM, Thomas Gleixner wrote:
> >>> "Michael S. Tsirkin" <mst@redhat.com> writes:
> >>>> On Tue, May 05, 2020 at 02:08:56PM +0200, Thomas Gleixner wrote:
> >>>>>
> >>>>> The following lockdep splat happens reproducibly on 5.7-rc4
> >>>>
> >>>>> ================================
> >>>>> WARNING: inconsistent lock state
> >>>>> 5.7.0-rc4+ #79 Not tainted
> >>>>> --------------------------------
> >>>>> inconsistent {SOFTIRQ-ON-W} -> {IN-SOFTIRQ-W} usage.
> >>>>> ip/356 [HC0[0]:SC1[1]:HE1:SE0] takes:
> >>>>> f3ee4cd8 (&syncp->seq#2){+.?.}-{0:0}, at: net_rx_action+0xfb/0x390
> >>>>> {SOFTIRQ-ON-W} state was registered at:
> >>>>>   lock_acquire+0x82/0x300
> >>>>>   try_fill_recv+0x39f/0x590
> >>>>
> >>>> Weird. Where does try_fill_recv acquire any locks?
> >>>
> >>>   u64_stats_update_begin(&rq->stats.syncp);
> >>>
> >>> That's a 32bit kernel which uses a seqcount for this. sequence counts
> >>> are "lock" constructs where you need to make sure that writers are
> >>> serialized.
> >>>
> >>> Actually the problem at hand is that try_fill_recv() is called from
> >>> fully preemptible context initialy and then from softirq context.
> >>>
> >>> Obviously that's for the open() path a non issue, but lockdep does not
> >>> know about that. OTOH, there is other code which calls that from
> >>> non-softirq context.
> >>>
> >>> The hack below made it shut up. It's obvioulsy not ideal, but at least
> >>> it let me look at the actual problem I was chasing down :)
> >>>
> >>> Thanks,
> >>>
> >>>         tglx
> >>>
> >>> 8<-----------
> >>> --- a/drivers/net/virtio_net.c
> >>> +++ b/drivers/net/virtio_net.c
> >>> @@ -1243,9 +1243,11 @@ static bool try_fill_recv(struct virtnet
> >>>  			break;
> >>>  	} while (rq->vq->num_free);
> >>>  	if (virtqueue_kick_prepare(rq->vq) && virtqueue_notify(rq->vq)) {
> >>> +		local_bh_disable();
> >>
> >> Or use u64_stats_update_begin_irqsave() whic is a NOP on 64bit kernels
> > 
> > I applied this, but am still trying to think of something that
> > is 0 overhead for all configs.
> > Maybe we can select a lockdep class depending on whether napi
> > is enabled?
> 
> 
> Do you _really_ need 64bit counter for stats.kicks on 32bit kernels ?
> 
> Adding 64bit counters just because we can might be overhead anyway.

Well 32 bit kernels don't fundamentally kick less than 64 bit ones,
and we kick more or less per packet, sometimes per batch,
people expect these to be in sync ..

> > 
> > 
> >>>  		u64_stats_update_begin(&rq->stats.syncp);
> >>>  		rq->stats.kicks++;
> >>>  		u64_stats_update_end(&rq->stats.syncp);
> >>> +		local_bh_enable();
> >>>  	}
> >>>  
> >>>  	return !oom;
> >>>
> > 

Re: [BUG] Inconsistent lock state in virtnet poll

[Eric Dumazet]

On 5/5/20 6:25 PM, Michael S. Tsirkin wrote:
> On Tue, May 05, 2020 at 06:19:09PM -0700, Eric Dumazet wrote:
>>
>>
>> On 5/5/20 5:43 PM, Michael S. Tsirkin wrote:
>>> On Tue, May 05, 2020 at 03:40:09PM -0700, Eric Dumazet wrote:
>>>>
>>>>
>>>> On 5/5/20 3:30 PM, Thomas Gleixner wrote:
>>>>> "Michael S. Tsirkin" <mst@redhat.com> writes:
>>>>>> On Tue, May 05, 2020 at 02:08:56PM +0200, Thomas Gleixner wrote:
>>>>>>>
>>>>>>> The following lockdep splat happens reproducibly on 5.7-rc4
>>>>>>
>>>>>>> ================================
>>>>>>> WARNING: inconsistent lock state
>>>>>>> 5.7.0-rc4+ #79 Not tainted
>>>>>>> --------------------------------
>>>>>>> inconsistent {SOFTIRQ-ON-W} -> {IN-SOFTIRQ-W} usage.
>>>>>>> ip/356 [HC0[0]:SC1[1]:HE1:SE0] takes:
>>>>>>> f3ee4cd8 (&syncp->seq#2){+.?.}-{0:0}, at: net_rx_action+0xfb/0x390
>>>>>>> {SOFTIRQ-ON-W} state was registered at:
>>>>>>>   lock_acquire+0x82/0x300
>>>>>>>   try_fill_recv+0x39f/0x590
>>>>>>
>>>>>> Weird. Where does try_fill_recv acquire any locks?
>>>>>
>>>>>   u64_stats_update_begin(&rq->stats.syncp);
>>>>>
>>>>> That's a 32bit kernel which uses a seqcount for this. sequence counts
>>>>> are "lock" constructs where you need to make sure that writers are
>>>>> serialized.
>>>>>
>>>>> Actually the problem at hand is that try_fill_recv() is called from
>>>>> fully preemptible context initialy and then from softirq context.
>>>>>
>>>>> Obviously that's for the open() path a non issue, but lockdep does not
>>>>> know about that. OTOH, there is other code which calls that from
>>>>> non-softirq context.
>>>>>
>>>>> The hack below made it shut up. It's obvioulsy not ideal, but at least
>>>>> it let me look at the actual problem I was chasing down :)
>>>>>
>>>>> Thanks,
>>>>>
>>>>>         tglx
>>>>>
>>>>> 8<-----------
>>>>> --- a/drivers/net/virtio_net.c
>>>>> +++ b/drivers/net/virtio_net.c
>>>>> @@ -1243,9 +1243,11 @@ static bool try_fill_recv(struct virtnet
>>>>>  			break;
>>>>>  	} while (rq->vq->num_free);
>>>>>  	if (virtqueue_kick_prepare(rq->vq) && virtqueue_notify(rq->vq)) {
>>>>> +		local_bh_disable();
>>>>
>>>> Or use u64_stats_update_begin_irqsave() whic is a NOP on 64bit kernels
>>>
>>> I applied this, but am still trying to think of something that
>>> is 0 overhead for all configs.
>>> Maybe we can select a lockdep class depending on whether napi
>>> is enabled?
>>
>>
>> Do you _really_ need 64bit counter for stats.kicks on 32bit kernels ?
>>
>> Adding 64bit counters just because we can might be overhead anyway.
> 
> Well 32 bit kernels don't fundamentally kick less than 64 bit ones,
> and we kick more or less per packet, sometimes per batch,
> people expect these to be in sync ..

Well, we left many counters in networking stack as 'unsigned long'
and nobody complained yet of overflows on 32bit kernels.

SNMP agents are used to the fact that counters do overflow.

Problems might happen if the overflows happen too fast, say every 10 seconds,
but other than that, forcing 64bit counters for something which is not
_required_ for the data path is adding pain.

I am mentioning this, because trying to add lockdep stuff and associated
maintenance cost for 32bit kernels in 2020 makes little sense to me,
considering I added include/linux/u64_stats_sync.h 10 years ago.

Re: [BUG] Inconsistent lock state in virtnet poll

[Michael S. Tsirkin]

On Tue, May 05, 2020 at 07:24:18PM -0700, Eric Dumazet wrote:
> 
> 
> On 5/5/20 6:25 PM, Michael S. Tsirkin wrote:
> > On Tue, May 05, 2020 at 06:19:09PM -0700, Eric Dumazet wrote:
> >>
> >>
> >> On 5/5/20 5:43 PM, Michael S. Tsirkin wrote:
> >>> On Tue, May 05, 2020 at 03:40:09PM -0700, Eric Dumazet wrote:
> >>>>
> >>>>
> >>>> On 5/5/20 3:30 PM, Thomas Gleixner wrote:
> >>>>> "Michael S. Tsirkin" <mst@redhat.com> writes:
> >>>>>> On Tue, May 05, 2020 at 02:08:56PM +0200, Thomas Gleixner wrote:
> >>>>>>>
> >>>>>>> The following lockdep splat happens reproducibly on 5.7-rc4
> >>>>>>
> >>>>>>> ================================
> >>>>>>> WARNING: inconsistent lock state
> >>>>>>> 5.7.0-rc4+ #79 Not tainted
> >>>>>>> --------------------------------
> >>>>>>> inconsistent {SOFTIRQ-ON-W} -> {IN-SOFTIRQ-W} usage.
> >>>>>>> ip/356 [HC0[0]:SC1[1]:HE1:SE0] takes:
> >>>>>>> f3ee4cd8 (&syncp->seq#2){+.?.}-{0:0}, at: net_rx_action+0xfb/0x390
> >>>>>>> {SOFTIRQ-ON-W} state was registered at:
> >>>>>>>   lock_acquire+0x82/0x300
> >>>>>>>   try_fill_recv+0x39f/0x590
> >>>>>>
> >>>>>> Weird. Where does try_fill_recv acquire any locks?
> >>>>>
> >>>>>   u64_stats_update_begin(&rq->stats.syncp);
> >>>>>
> >>>>> That's a 32bit kernel which uses a seqcount for this. sequence counts
> >>>>> are "lock" constructs where you need to make sure that writers are
> >>>>> serialized.
> >>>>>
> >>>>> Actually the problem at hand is that try_fill_recv() is called from
> >>>>> fully preemptible context initialy and then from softirq context.
> >>>>>
> >>>>> Obviously that's for the open() path a non issue, but lockdep does not
> >>>>> know about that. OTOH, there is other code which calls that from
> >>>>> non-softirq context.
> >>>>>
> >>>>> The hack below made it shut up. It's obvioulsy not ideal, but at least
> >>>>> it let me look at the actual problem I was chasing down :)
> >>>>>
> >>>>> Thanks,
> >>>>>
> >>>>>         tglx
> >>>>>
> >>>>> 8<-----------
> >>>>> --- a/drivers/net/virtio_net.c
> >>>>> +++ b/drivers/net/virtio_net.c
> >>>>> @@ -1243,9 +1243,11 @@ static bool try_fill_recv(struct virtnet
> >>>>>  			break;
> >>>>>  	} while (rq->vq->num_free);
> >>>>>  	if (virtqueue_kick_prepare(rq->vq) && virtqueue_notify(rq->vq)) {
> >>>>> +		local_bh_disable();
> >>>>
> >>>> Or use u64_stats_update_begin_irqsave() whic is a NOP on 64bit kernels
> >>>
> >>> I applied this, but am still trying to think of something that
> >>> is 0 overhead for all configs.
> >>> Maybe we can select a lockdep class depending on whether napi
> >>> is enabled?
> >>
> >>
> >> Do you _really_ need 64bit counter for stats.kicks on 32bit kernels ?
> >>
> >> Adding 64bit counters just because we can might be overhead anyway.
> > 
> > Well 32 bit kernels don't fundamentally kick less than 64 bit ones,
> > and we kick more or less per packet, sometimes per batch,
> > people expect these to be in sync ..
> 
> Well, we left many counters in networking stack as 'unsigned long'
> and nobody complained yet of overflows on 32bit kernels.

Right.  For TX it is helpful that everything is maintained
atomically so we do need the seqlock machinery anyway:

        u64_stats_update_begin(&sq->stats.syncp);
        sq->stats.bytes += bytes;
        sq->stats.packets += packets;
        sq->stats.xdp_tx += n;
        sq->stats.xdp_tx_drops += drops;
        sq->stats.kicks += kicks;
        u64_stats_update_end(&sq->stats.syncp);

for RX kicks are currently updated separately.  Which I guess is more or
less a minor bug.

        if (rq->vq->num_free > min((unsigned int)budget, virtqueue_get_vring_size(rq->vq)) / 2) {
                if (!try_fill_recv(vi, rq, GFP_ATOMIC))
                        schedule_delayed_work(&vi->refill, 0);
        }

        u64_stats_update_begin(&rq->stats.syncp);
        for (i = 0; i < VIRTNET_RQ_STATS_LEN; i++) {
                size_t offset = virtnet_rq_stats_desc[i].offset;
                u64 *item;

                item = (u64 *)((u8 *)&rq->stats + offset);
                *item += *(u64 *)((u8 *)&stats + offset);
        }
        u64_stats_update_end(&rq->stats.syncp);

we should update kicks in virtnet_receive.

And as long as we do that there's no cost to 64 bit counters ...


> SNMP agents are used to the fact that counters do overflow.
> 
> Problems might happen if the overflows happen too fast, say every 10 seconds,
> but other than that, forcing 64bit counters for something which is not
> _required_ for the data path is adding pain.
> 
> I am mentioning this, because trying to add lockdep stuff and associated
> maintenance cost for 32bit kernels in 2020 makes little sense to me,
> considering I added include/linux/u64_stats_sync.h 10 years ago.
> 

Not sure what do you suggest here...


> 
> 
> 

Re: [BUG] Inconsistent lock state in virtnet poll

[Jason Wang]

On 2020/5/6 下午3:31, Michael S. Tsirkin wrote:
> On Tue, May 05, 2020 at 07:24:18PM -0700, Eric Dumazet wrote:
>> On 5/5/20 6:25 PM, Michael S. Tsirkin wrote:
>>> On Tue, May 05, 2020 at 06:19:09PM -0700, Eric Dumazet wrote:
>>>> On 5/5/20 5:43 PM, Michael S. Tsirkin wrote:
>>>>> On Tue, May 05, 2020 at 03:40:09PM -0700, Eric Dumazet wrote:
>>>>>> On 5/5/20 3:30 PM, Thomas Gleixner wrote:
>>>>>>> "Michael S. Tsirkin"<mst@redhat.com>  writes:
>>>>>>>> On Tue, May 05, 2020 at 02:08:56PM +0200, Thomas Gleixner wrote:
>>>>>>>>> The following lockdep splat happens reproducibly on 5.7-rc4
>>>>>>>>> ================================
>>>>>>>>> WARNING: inconsistent lock state
>>>>>>>>> 5.7.0-rc4+ #79 Not tainted
>>>>>>>>> --------------------------------
>>>>>>>>> inconsistent {SOFTIRQ-ON-W} -> {IN-SOFTIRQ-W} usage.
>>>>>>>>> ip/356 [HC0[0]:SC1[1]:HE1:SE0] takes:
>>>>>>>>> f3ee4cd8 (&syncp->seq#2){+.?.}-{0:0}, at: net_rx_action+0xfb/0x390
>>>>>>>>> {SOFTIRQ-ON-W} state was registered at:
>>>>>>>>>    lock_acquire+0x82/0x300
>>>>>>>>>    try_fill_recv+0x39f/0x590
>>>>>>>> Weird. Where does try_fill_recv acquire any locks?
>>>>>>>    u64_stats_update_begin(&rq->stats.syncp);
>>>>>>>
>>>>>>> That's a 32bit kernel which uses a seqcount for this. sequence counts
>>>>>>> are "lock" constructs where you need to make sure that writers are
>>>>>>> serialized.
>>>>>>>
>>>>>>> Actually the problem at hand is that try_fill_recv() is called from
>>>>>>> fully preemptible context initialy and then from softirq context.
>>>>>>>
>>>>>>> Obviously that's for the open() path a non issue, but lockdep does not
>>>>>>> know about that. OTOH, there is other code which calls that from
>>>>>>> non-softirq context.
>>>>>>>
>>>>>>> The hack below made it shut up. It's obvioulsy not ideal, but at least
>>>>>>> it let me look at the actual problem I was chasing down:)
>>>>>>>
>>>>>>> Thanks,
>>>>>>>
>>>>>>>          tglx
>>>>>>>
>>>>>>> 8<-----------
>>>>>>> --- a/drivers/net/virtio_net.c
>>>>>>> +++ b/drivers/net/virtio_net.c
>>>>>>> @@ -1243,9 +1243,11 @@ static bool try_fill_recv(struct virtnet
>>>>>>>   			break;
>>>>>>>   	} while (rq->vq->num_free);
>>>>>>>   	if (virtqueue_kick_prepare(rq->vq) && virtqueue_notify(rq->vq)) {
>>>>>>> +		local_bh_disable();
>>>>>> Or use u64_stats_update_begin_irqsave() whic is a NOP on 64bit kernels
>>>>> I applied this, but am still trying to think of something that
>>>>> is 0 overhead for all configs.
>>>>> Maybe we can select a lockdep class depending on whether napi
>>>>> is enabled?
>>>> Do you_really_  need 64bit counter for stats.kicks on 32bit kernels ?
>>>>
>>>> Adding 64bit counters just because we can might be overhead anyway.
>>> Well 32 bit kernels don't fundamentally kick less than 64 bit ones,
>>> and we kick more or less per packet, sometimes per batch,
>>> people expect these to be in sync ..
>> Well, we left many counters in networking stack as 'unsigned long'
>> and nobody complained yet of overflows on 32bit kernels.
> Right.  For TX it is helpful that everything is maintained
> atomically so we do need the seqlock machinery anyway:
>
>          u64_stats_update_begin(&sq->stats.syncp);
>          sq->stats.bytes += bytes;
>          sq->stats.packets += packets;
>          sq->stats.xdp_tx += n;
>          sq->stats.xdp_tx_drops += drops;
>          sq->stats.kicks += kicks;
>          u64_stats_update_end(&sq->stats.syncp);
>
> for RX kicks are currently updated separately.  Which I guess is more or
> less a minor bug.
>
>          if (rq->vq->num_free > min((unsigned int)budget, virtqueue_get_vring_size(rq->vq)) / 2) {
>                  if (!try_fill_recv(vi, rq, GFP_ATOMIC))
>                          schedule_delayed_work(&vi->refill, 0);
>          }
>
>          u64_stats_update_begin(&rq->stats.syncp);
>          for (i = 0; i < VIRTNET_RQ_STATS_LEN; i++) {
>                  size_t offset = virtnet_rq_stats_desc[i].offset;
>                  u64 *item;
>
>                  item = (u64 *)((u8 *)&rq->stats + offset);
>                  *item += *(u64 *)((u8 *)&stats + offset);
>          }
>          u64_stats_update_end(&rq->stats.syncp);
>
> we should update kicks in virtnet_receive.
>
> And as long as we do that there's no cost to 64 bit counters ...
>
>

Or find way to use u32 to count kick in workqueue (which should be rare) 
separately.

Thanks