Re: Xen-unstable Linux 3.14-rc3 and 3.13 Network troubles "bisected"

[Sander Eikelenboom <linux@eikelenboom.it>]

Tuesday, March 18, 2014, 5:04:12 PM, you wrote:

> On Tue, Mar 18, 2014 at 04:21:27PM +0100, Sander Eikelenboom wrote:
> [...]
>> 
>> Added even more warns ...
>> 
>> [  297.885969] vif vif-7-0 vif7.0: ?!? xenvif_start_xmit stopping queue !  min_slots_needed:4 vif->rx.sring->req_prod:21764 vif->rx.req_cons:21762
>> [  298.760555] vif vif-7-0 vif7.0: ?!? xenvif_start_xmit stopping queue !  min_slots_needed:3 vif->rx.sring->req_prod:22488 vif->rx.req_cons:22486
>> 
>> [  306.376176] vif vif-7-0 vif7.0: ?!? get_next_rx_buffer before req npo->meta_prod:30 vif->rx.sring->req_prod:28313 vif->rx.req_cons:28313
>> [  306.376556] vif vif-7-0 vif7.0: ?!? xenvif_start_xmit stopping queue !  min_slots_needed:1 vif->rx.sring->req_prod:28313 vif->rx.req_cons:28313
>> [  306.391863] vif vif-7-0 vif7.0: ?!? get_next_rx_buffer after req npo->meta_prod:30 vif->rx.sring->req_prod:28313 vif->rx.req_cons:28314 req->gref:4325377 req->id:153
>> 
>> [  306.407599] vif vif-7-0 vif7.0: ?!? xenvif_gop_frag_copy Me here 2  npo->meta_prod:31 vif->rx.sring->req_prod:28313 vif->rx.req_cons:28314 npo->copy_gref:4325377  npo->copy_off:0  MAX_BUFFER_OFFSET:4096 bytes:640 size:640 i:4
>> [  306.423913] vif vif-7-0 vif7.0: ?!? xenvif_gop_frag_copy Me here end npo->meta_prod:31 vif->rx.sring->req_prod:28313 vif->rx.req_cons:28314 npo->copy_gref:4325377 npo->copy_off:640  MAX_BUFFER_OFFSET:4096 bytes:640 size:0 i:5
>> 
>> 
>> [  306.440941] vif vif-7-0 vif7.0: ?!? xenvif_gop_skb Me here 4 npo->meta_prod:31 old_meta_prod:25 vif->rx.sring->req_prod:28313 vif->rx.req_cons:28314 gso_type:1 gso_size:1448 nr_frags:1 req->gref:638 req->id:147
>> [  306.458334] vif vif-7-0 vif7.0: ?!? xenvif_gop_skb Me here 2 before req npo->meta_prod:31 vif->rx.sring->req_prod:28313 vif->rx.req_cons:28315 gso_type:0 gso_size:0 nr_frags:0
>> [  306.476097] vif vif-7-0 vif7.0: ?!? xenvif_gop_skb Me here 2 after req npo->meta_prod:31 vif->rx.sring->req_prod:28313 vif->rx.req_cons:28315 gso_type:0 gso_size:0 nr_frags:0 req->gref:4325377 req->id:154
>> [  306.494462] vif vif-7-0 vif7.0: ?!? xenvif_gop_skb Me here 3 before npo->meta_prod:32 old_meta_prod:31 vif->rx.sring->req_prod:28313 vif->rx.req_cons:28315 gso_type:0 gso_size:0 nr_frags:0 req->gref:4325377 req->id:154 j:0
>> [  306.513424] vif vif-7-0 vif7.0: ?!? xenvif_gop_frag_copy Me here start   npo->meta_prod:32 vif->rx.sring->req_prod:28313 vif->rx.req_cons:28315 npo->copy_gref:4325377 npo->copy_off:0  MAX_BUFFER_OFFSET:4096 bytes:0 size:66 i:0
>> [  311.390883] net_ratelimit: 317 callbacks suppressed
>> [  311.400901] vif vif-7-0 vif7.0: ?!? xenvif_start_xmit stopping queue !  min_slots_needed:3 vif->rx.sring->req_prod:32386 vif->rx.req_cons:32322
>> 
>> - So in this case we are in the 3rd iteration of the loop in xenvif_gop_frag_copy ...
>> - Xenvif_start_xmit stop the queue since it has detected it needs one more slot which is unavailable at that time.

> Yes.

>> - The current rx thread however doesn't know and doesn't check  (neither in the loop in xenvif_gop_frag_copy nor in get_next_rx_buffer that the ring if full) .. while prod == cons now .. consumes another one ..

> It does check -- but not in xenvif_gop_frag_copy -- see
> xenvif_rx_action, which calls xenvif_rx_ring_slots_available before
> queueing skb to break down. That is, when you call xenvif_gop_skb there
> should be enough room to accommodate that SKB.

>> - That ring request leads to the bad grant references reported by the hypervisor
>> 
>> (XEN) [2014-03-18 15:02:58.928] grant_table.c:1857:d0v2 Bad grant reference 4325377
>> 
>> So should there be a check added there ... or should the callers  "xenvif_gop_frag_copy" and the caller of that one "xenvif_gop_skb" already have anticipated that what the were about
>> to do wasn't going to fit anyway ?
>> 

> No, see above.

>> And of course .. how made Paul's change trigger this ?
>> 

> Before Paul's change, we always reserve very large room for an incoming
> SKB. After Paul's change, we only reserve just enough room. Probably
> some extra room prevents this bug being triggered.

[  599.970745] vif vif-7-0 vif7.0: ?!? get_next_rx_buffer before req npo->meta_prod:37 vif->rx.sring->req_prod:506387 vif->rx.req_cons:506387 vif->rx.sring->req_event:504174
[  599.972487] vif vif-7-0 vif7.0: ?!? xenvif_start_xmit stopping queue !  min_slots_needed:1 vif->rx.sring->req_prod:506387 vif->rx.req_cons:506387 vif->rx.sring->req_event:506388
[  600.044322] vif vif-7-0 vif7.0: ?!? get_next_rx_buffer after req npo->meta_prod:37 vif->rx.sring->req_prod:506387 vif->rx.req_cons:506388 req->gref:165543936 req->id:19 vif->rx.sring->req_event:506388
[  600.081167] vif vif-7-0 vif7.0: ?!? xenvif_gop_frag_copy Me here 2  npo->meta_prod:38 vif->rx.sring->req_prod:506387 vif->rx.req_cons:506388 npo->copy_gref:165543936  npo->copy_off:0  MAX_BUFFER_OFFSET:4096 bytes:1168 size:1168 i:6 vif->rx.sring->req_event:506388 estimated_slots_needed:8
[  600.118268] vif vif-7-0 vif7.0: ?!? xenvif_gop_frag_copy Me here end npo->meta_prod:38 vif->rx.sring->req_prod:506387 vif->rx.req_cons:506388 npo->copy_gref:165543936 npo->copy_off:1168  MAX_BUFFER_OFFSET:4096 bytes:1168 size:0 i:7 vif->rx.sring->req_event:506388 estimated_slots_needed:8
[  600.155378] vif vif-7-0 vif7.0: ?!? xenvif_gop_skb Me here 4 npo->meta_prod:38 old_meta_prod:30 vif->rx.sring->req_prod:506387 vif->rx.req_cons:506388 gso_type:1 gso_size:1448 nr_frags:1 req->gref:570 req->id:11 estimated_slots_needed:8 i(frag): 0
[  600.192438] vif vif-7-0 vif7.0: ?!? xenvif_gop_skb Me here 5 npo->meta_prod:38 old_meta_prod:30 vif->rx.sring->req_prod:506387 vif->rx.req_cons:506388 gso_type:1 gso_size:1448 nr_frags:1 req->gref:570 req->id:11 estimated_slots_needed:8
[  600.229395] vif vif-7-0 vif7.0: ?!? xenvif_rx_action me here 2 ..  vif->rx.sring->req_prod:506387 vif->rx.req_cons:506388 sco->meta_slots_used:8 max_upped_gso:1 skb_is_gso(skb):1 max_slots_needed:8 j:3 is_gso:1 nr_frags:1 firstpart:1 secondpart:6 min_slots_needed:3
[  600.266518] vif vif-7-0 vif7.0: ?!? xenvif_rx_action me here 1 ..  vif->rx.sring->req_prod:506387 vif->rx.req_cons:506388                         max_upped_gso:1 skb_is_gso(skb):0 max_slots_needed:1 j:4 is_gso:0 nr_frags:0 firstpart:1 secondpart:0 min_slots_needed:1

It seems to estimate 8 slots and need 8 slots ... however .. shouldn't the queue have been stopped before getting here ..


> Wei.

>> 
>> >> The second time it does get to the code after the RING_GET_REQUEST in 'get_next_rx_buffer' and that leads to mayhem ...
>> >> 
>> >> So added a netdev_warn to xenvif_start_xmit for the "stop queue" case .. unfortunately it now triggers net_ratelimit at the end:
>> >> 
>> >> [  402.909693] vif vif-7-0 vif7.0: ?!? xenvif_start_xmit stopping queue !  min_slots_needed:7 vif->rx.sring->req_prod:189228 vif->rx.req_cons:189222
>> 
>> > I think xenvif_rx_ring_slots_available is doing its job. If req_prod -
>> > req_cons < needed, the queue is stopeed.

So it seems .. most of the time .. but if i look at the calculation of "min_slots_needed" in this function it seems completely different from the one in
xenvif_rx_action for max_slots_needed .. though both seem to be used for the same thing .. to calcultate how many slots the brokendown SKB would need to fit in ..
So i added the calculation method from xenvif_start_xmit to xenvif_rx_action .. in the error case you see min_slots_needed was 3 .. but max_slots_needed and max_slots_used both were 8.

The main difference between these calculation methods seems to be that min_slots_needed doesn't take the PAGE_SIZE into account to see how many slots are needed for the frags.

So Paul .. why was the "xenvif_count_skb_slots(vif, skb)" function dropped and replaced by two seperate and different calculations ?

--
Sander

>> 
>> > Wei.
>>