[Date Prev][Date Next][Thread Prev][Thread Next][Date Index][Thread Index]

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



Ping ?


Saturday, March 22, 2014, 7:28:34 PM, you wrote:


> Friday, March 21, 2014, 6:27:27 PM, you wrote:


>> Friday, March 21, 2014, 5:49:58 PM, you wrote:

>>> [...]
>>>> > Those are different estimations. max_slots_needed estimates the worst
>>>> > case while min_slots_needed estimates the best case. When
>>>> > min_slots_needed is met, netback puts the SKB into its internal queue.
>>>> > xenvif_rx_action then will dequeue that packet, check max_slots_needed,
>>>> > if met, break SKB down.
>>>> 
>>>> I realised that, though if you don't count the cost of calculation .. the 
>>>> best would be
>>>> to have min_slots and max_slots the same .. and being correct. But cost of 
>>>> the calculation count ..
>>>> on the other hand min_slots seems to be far too low in this case. Is the 
>>>> nr_frags the best thing to check for ?
>>>> Wouldn't something like skbsize / PAGE_SIZE be a better estimate ?
>>>> 

>>> It doesn't matter. It won't cause breakage at that point.

>> That was more from a performance point of view ... if the estimate can be 
>> that much off
>> it would do the more costly check .. and still bail out. So the better the 
>> first estimation
>> (at about the same cost of course) the better.


>>>> 
>>>> > What I would expect is, even if they yield different values, checking
>>>> > the ring availability is enough before breaking SKB down.
>>>> 
>>>> > In your above case, max_slots_needed was met and SKB broken down. And as
>>>> > you said in your empirical test, bumping max_slots_needed by 1 prevented
>>>> > issues, then we might have problem calculating max_slots_needed. If you
>>>> > can work out what went wrong that can be very useful.
>>>> 
>>>> OK ran the whole night with "max_slots_needed+1" and i saw no triggering 
>>>> of both:
>>>>     - the non-fatal oddity (only a temporary cons > prod ..)
>>>>     - the fatal case (leading to the grantref error)
>>>> 
>>>> So it seems we are off by one .. somewhere
>>>> 
>>>> 
>>>> At first the non-fatal oddity .. this one i really can't grasp:
>>>> 
>>>> [  567.880282] vif vif-7-0 vif7.0: ?!? xenvif_start_xmit stopping queue !  
>>>> min_slots_needed:4 vif->rx.sring->req_prod:562972 vif->rx.req_cons:562969 
>>>> vif->rx.sring->req_event:562973
>>>> [  569.893801] vif vif-7-0 vif7.0: ?!? xenvif_start_xmit stopping queue !  
>>>> min_slots_needed:4 vif->rx.sring->req_prod:571188 vif->rx.req_cons:571187 
>>>> vif->rx.sring->req_event:571189
>>>> [  571.892419] vif vif-7-0 vif7.0: ?!? xenvif_start_xmit stopping queue !  
>>>> min_slots_needed:4 vif->rx.sring->req_prod:577141 vif->rx.req_cons:577138 
>>>> vif->rx.sring->req_event:577142
>>>> [  575.451383] vif vif-7-0 vif7.0: ?!? get_next_rx_buffer before req 
>>>> npo->meta_prod:6 vif->rx.sring->req_prod:590603 vif->rx.req_cons:590603 
>>>> vif->rx.sring->req_event:589615, reserved_slots_left:0
>>>> [  575.487721] vif vif-7-0 vif7.0: ?!? get_next_rx_buffer after req 
>>>> npo->meta_prod:6 vif->rx.sring->req_prod:590660 vif->rx.req_cons:590604 
>>>> req->gref:569 req->id:11 vif->rx.sring->req_event:589615 
>>>> reserved_slots_left:-1
>>>> [  575.524427] vif vif-7-0 vif7.0: ?!? xenvif_start_xmit stopping queue !  
>>>> min_slots_needed:4 vif->rx.sring->req_prod:590660 vif->rx.req_cons:590660 
>>>> vif->rx.sring->req_event:590661
>>>> [  576.508063] vif vif-7-0 vif7.0: ?!? get_next_rx_buffer before req 
>>>> npo->meta_prod:16 vif->rx.sring->req_prod:594343 vif->rx.req_cons:594343 
>>>> vif->rx.sring->req_event:591619, reserved_slots_left:0
>>>> [  576.544708] vif vif-7-0 vif7.0: ?!? get_next_rx_buffer after req 
>>>> npo->meta_prod:16 vif->rx.sring->req_prod:594389 vif->rx.req_cons:594344 
>>>> req->gref:668 req->id:167 vif->rx.sring->req_event:591619 
>>>> reserved_slots_left:-1
>>>> [  576.581595] vif vif-7-0 vif7.0: ?!? xenvif_start_xmit stopping queue !  
>>>> min_slots_needed:4 vif->rx.sring->req_prod:594389 vif->rx.req_cons:594389 
>>>> vif->rx.sring->req_event:594390
>>>> [  577.325826] vif vif-7-0 vif7.0: ?!? xenvif_start_xmit stopping queue !  
>>>> min_slots_needed:2 vif->rx.sring->req_prod:597248 vif->rx.req_cons:597247 
>>>> vif->rx.sring->req_event:597249
>>>> [  577.576973] vif vif-7-0 vif7.0: ?!? xenvif_start_xmit stopping queue !  
>>>> min_slots_needed:4 vif->rx.sring->req_prod:598146 vif->rx.req_cons:598143 
>>>> vif->rx.sring->req_event:598147
>>>> 
>>>> What i don't get is:
>>>> - i do warn just before the RING_GET_REQUEST on 
>>>> vif->rx.sring->req_prod:590603 vif->rx.req_cons:590603 .. so cons == prod
>>>> - i warn because  req = RING_GET_REQUEST(&vif->rx, vif->rx.req_cons++); is 
>>>> going to add one to cons .. leading to a situation that should not exist ..
>>>> - however in the warn just after this RING_GET_REQUEST .. prod is somehow 
>>>> increased a lot .. probably the "next_rx_buffer" aspect of things .. so 
>>>> cons is much smaller than prod again ..

>>> Frontend is also accessing the ring. So it's normal that some index
>>> changed.

>> Ah ok .. so here the frontend is "saving us" by putting more stuff on the 
>> ring so we don't run dry ..

>>>> - How everi don't see anything in the RING_GET_REQUEST macro fiddling with 
>>>> vif->rx.sring->req_prod ..
>>>> - so who has been fiddling with vif->rx.sring->req_prod in the mean time 
>>>> .. my very limited c skills fail to see how this works :-)
>>>> 
>>>> 
>>>> Then the fatal case ...
>>>> 
>>>> [ 1108.566486] vif vif-7-0 vif7.0: ?!? xenvif_start_xmit stopping queue !  
>>>> min_slots_needed:1 vif->rx.sring->req_prod:1843278 
>>>> vif->rx.req_cons:1843278 vif->rx.sring->req_event:1843279
>>>> [ 1109.775757] vif vif-7-0 vif7.0: ?!? xenvif_start_xmit stopping queue !  
>>>> min_slots_needed:4 vif->rx.sring->req_prod:1847779 
>>>> vif->rx.req_cons:1847776 vif->rx.sring->req_event:1847780
>>>> [ 1110.041661] vif vif-7-0 vif7.0: ?!? xenvif_start_xmit stopping queue !  
>>>> min_slots_needed:4 vif->rx.sring->req_prod:1848795 
>>>> vif->rx.req_cons:1848794 vif->rx.sring->req_event:1848796
>>>> [ 1110.301778] vif vif-7-0 vif7.0: ?!? xenvif_start_xmit stopping queue !  
>>>> min_slots_needed:4 vif->rx.sring->req_prod:1849755 
>>>> vif->rx.req_cons:1849754 vif->rx.sring->req_event:1849756
>>>> [ 1111.565412] vif vif-7-0 vif7.0: ?!? get_next_rx_buffer before req 
>>>> npo->meta_prod:35 vif->rx.sring->req_prod:1854291 vif->rx.req_cons:1854291 
>>>> vif->rx.sring->req_event:1853482, reserved_slots_left:0
>>>> [ 1111.565973] vif vif-7-0 vif7.0: ?!? xenvif_start_xmit stopping queue !  
>>>> min_slots_needed:1 vif->rx.sring->req_prod:1854291 
>>>> vif->rx.req_cons:1854291 vif->rx.sring->req_event:1854292
>>>> [ 1111.638425] vif vif-7-0 vif7.0: ?!? get_next_rx_buffer after req 
>>>> npo->meta_prod:35 vif->rx.sring->req_prod:1854291 vif->rx.req_cons:1854292 
>>>> req->gref:4325377 req->id:83 vif->rx.sring->req_event:1854292 
>>>> reserved_slots_left:-1
>>>> [ 1111.675042] vif vif-7-0 vif7.0: ?!? xenvif_gop_frag_copy Me here 2  
>>>> npo->meta_prod:36 vif->rx.sring->req_prod:1854291 vif->rx.req_cons:1854292 
>>>> npo->copy_gref:4325377  npo->copy_off:0  MAX_BUFFER_OFFSET:4096 bytes:1168 
>>>> size:1168 i:5 vif->rx.sring->req_event:1854292 estimated_slots_needed:7 
>>>> reserved_slots_left:-1
>>>> [ 1111.711833] vif vif-7-0 vif7.0: ?!? xenvif_gop_frag_copy Me here end 
>>>> npo->meta_prod:36 vif->rx.sring->req_prod:1854291 vif->rx.req_cons:1854292 
>>>> npo->copy_gref:4325377 npo->copy_off:1168  MAX_BUFFER_OFFSET:4096 
>>>> bytes:1168 size:0 i:6 vif->rx.sring->req_event:1854292 gso_gaps:0 
>>>> estimated_slots_needed:7 reserved_slots_left:-1
>>>> [ 1111.766836] vif vif-7-0 vif7.0: ?!? xenvif_gop_skb Me here 4 after 
>>>> npo->meta_prod:36 old_meta_prod:29 vif->rx.sring->req_prod:1854291 
>>>> vif->rx.req_cons:1854292 meta->gso_type:1 meta->gso_size:1448 nr_frags:1 
>>>> req->gref:674 req->id:76 estimated_slots_needed:7 i(frag):0 j(data):1 
>>>> reserved_slots_left:-1
>>>> [ 1111.803702] vif vif-7-0 vif7.0: ?!? xenvif_gop_skb Me here 5 
>>>> npo->meta_prod:36 old_meta_prod:29 vif->rx.sring->req_prod:1854291 
>>>> vif->rx.req_cons:1854292 meta->gso_type:1 meta->gso_size:1448 nr_frags:1 
>>>> req->gref:674 req->id:76 estimated_slots_needed:7 j(data):1 
>>>> reserved_slots_left:-1    used in funcstart: 0 + 1 .. used_dataloop:1 .. 
>>>> used_fragloop:6
>>>> [ 1111.858602] vif vif-7-0 vif7.0: ?!? xenvif_rx_action me here 2 ..  
>>>> vif->rx.sring->req_prod:1854291 vif->rx.req_cons:1854292 
>>>> sco->meta_slots_used:7 max_upped_gso:1 skb_is_gso(skb):1 
>>>> max_slots_needed:7 j:3 is_gso:1 nr_frags:1 firstpart:1 secondpart:5 
>>>> reserved_slots_left:-1
>>>> 
>>>> Ok so if i try to pull this apart (from bottom to top):
>>>> 
>>>> - it starts out with "xenvif_rx_action" and calculated we would need:
>>>>       1 slot for the  DIV_ROUND_UP(offset_in_page(skb->data) + 
>>>> skb_headlen(skb), PAGE_SIZE);
>>>>       5 slots for 1 frag
>>>>       1 slot for GSO
>>>>       So 7 slots in total .. 
>>>> 
>>>> - it checks  if there are enough slots available if 
>>>> (!xenvif_rx_ring_slots_available(vif, max_slots_needed)) and aparently 
>>>> there are .. so it continues
>>>> 
>>>> - We end up in "xenvif_gop_skb" processing .. and everything seems to go 
>>>> well ..
>>>>       - In the start of this function we do one unconditional 
>>>> RING_GET_REQUEST .. and potentially one conditional (if gso)
>>>>           - Question: in "xenvif_rx_action" we only reserved ONE slot for 
>>>> GSO stuff .. so this could cost TWO slots .. is that right ?

>>> The slot reserved for GSO is for meta data, so 1 is enough.

>>>>           - But in this case we only use one ... see "used in funcstart: 0 
>>>> + 1"
>>>> 
>>>>       - Now we loop 1 time through the  "while (data < 
>>>> skb_tail_pointer(skb))" loop ... since j(data)=1
>>>>           - and call "xenvif_gop_frag_copy" from inside this loop here .. 
>>>> which potentially calls .. get_next_rx_buffer
>>>>           - If i understand it correctly the number of slots this loop 
>>>> should take at a maximum should be what we calculated before with the
>>>>             DIV_ROUND_UP(offset_in_page(skb->data) + skb_headlen(skb), 
>>>> PAGE_SIZE) ? (1 slot in this case)
>>>>           - Nothing is logged yet because cons is still smaller than prod 
>>>> at this time, but from the aftermath we see this was "used_dataloop:1"
>>>>           - So that seems correct .. 
>>>> 
>>>>       - Now we are at the loop through "nr_frags"  and loop the 1 frag we 
>>>> have .. 
>>>>                   - This all goes well until the sixth iteration (i from 
>>>> 0..5) .. and call "xenvif_gop_frag_copy" from inside this loop ...

>>> Isn't there only one frag?

>> Yes there is only one frag .. but it seems to be much larger than PAGE_SIZE 
>> .. and xenvif_gop_frag_copy brakes that frag down into smaller bits .. hence 
>> the calculation in xenvif_rx_action determining the slots needed by doing:

>>                 for (i = 0; i < nr_frags; i++) {
>>                         unsigned int size;
>>                         size = skb_frag_size(&skb_shinfo(skb)->frags[i]);
>>                         max_slots_needed += DIV_ROUND_UP(size, PAGE_SIZE);
>>                 }

>> But the code in xenvif_gop_frag_copy .. seems to be needing one more slot 
>> (from the emperical test) .. and calling "get_next_rx_buffer" seems involved 
>> in that ..

> Hmm looked again .. and it seems this is it .. when your frags are large 
> enough you have the chance of running into this.

> Problem is .. i don't see an easy fix, the "one more slot" of the empirical 
> test doesn't seem to be the worst case either (i think):

> - In my case the packets that hit this only have 1 frag, but i could have had 
> more frags.
>   I also think you can't rule out the possibility of doing the 
> "get_next_rx_buffer" for multiple subsequent frags from one packet,
>   so in the worst (and perhaps even from a single frag since it's looped over 
> a split of it in what seems PAGE_SIZE pieces.)
>   - So an exact calculation of how much slots we are going to need for 
> hitting this "get_next_rx_buffer"  upfront in "xenvif_rx_action" seems 
> unfeasible.
>   - A worst case gamble seems impossible either .. if you take multiple frags 
> * multiple times the "get_next_rx_buffer" ... you would probably be back at 
> just
>     setting the needed_slots to MAX_SKB_FRAGS.

> - Other thing would be checking for the available slots before doing the  
> "get_next_rx_buffer" .. how ever .. we don't account for how many slots we 
> still need to
>   just process the remaining frags.

> - Just remove the whole "get_next_rx_buffer".. just tested it but it seems 
> the "get_next_rx_buffer" is necessary ..  when i make start_new_rx_buffer 
> always return false
>   i hit the bug below :S

> So the questions are ... is the "get_next_rx_buffer" part really necessary ?
>    - if not, what is the benefit of the "get_next_rx_buffer" and does that 
> outweigh the additional cost of accounting
>      of needed_slots for the frags that have yet to be processed ?
>    - if yes, erhmmm what would be the best acceptable solution .. returning 
> to using MAX_SKB_FRAGS ?

> --
> Sander


> [  235.655964] BUG: unable to handle kernel paging request at ffffc9001223b018
> [  235.660380] IP: [<ffffffff8177d30e>] xenvif_gop_frag_copy+0x13e/0x580
> [  235.664887] PGD 59a2a067 PUD 59a2b067 PMD 55c38067 PTE 0
> [  235.669236] Oops: 0002 [#1] SMP
> [  235.673611] Modules linked in:
> [  235.677936] CPU: 0 PID: 10518 Comm: vif9.0 Not tainted 
> 3.13.6-20140322-nbdebug30+ #1
> [  235.682377] Hardware name: MSI MS-7640/890FXA-GD70 (MS-7640)  , BIOS 
> V1.8B1 09/13/2010
> [  235.686711] task: ffff88004dc40000 ti: ffff88004b74a000 task.ti: 
> ffff88004b74a000
> [  235.691185] RIP: e030:[<ffffffff8177d30e>]  [<ffffffff8177d30e>] 
> xenvif_gop_frag_copy+0x13e/0x580
> [  235.695869] RSP: e02b:ffff88004b74bb28  EFLAGS: 00010203
> [  235.700613] RAX: ffff880080000000 RBX: ffff88004b74bd40 RCX: 
> 000000000126d940
> [  235.705522] RDX: ffffc9001223aff8 RSI: ffff880000000000 RDI: 
> 0000000000049b65
> [  235.710488] RBP: ffff88004b74bc08 R08: 000000000000012c R09: 
> 00000000000000ae
> [  235.715515] R10: ffff88004b74bd2c R11: 0000000000000001 R12: 
> 0000000000000000
> [  235.720570] R13: 000000000000099e R14: 0000000000000662 R15: 
> ffff88004a6d0940
> [  235.725688] FS:  00007f4cbed78700(0000) GS:ffff88005f600000(0000) 
> knlGS:0000000000000000
> [  235.730961] CS:  e033 DS: 0000 ES: 0000 CR0: 000000008005003b
> [  235.736061] CR2: ffffc9001223b018 CR3: 00000000572b1000 CR4: 
> 0000000000000660
> [  235.741247] Stack:
> [  235.746320]  ffff880000000000 ffffffff810fa475 ffff88004dc40000 
> ffff88004dc40000
> [  235.751848]  ffffffff81b4ca4d 00000000000002dc 0000000000000000 
> ffff88004b74be18
> [  235.757195]  ffff88004b74bb88 ffffffff810f6251 ffffffff822ee9a0 
> 00000000000002dc
> [  235.762802] Call Trace:
> [  235.768086]  [<ffffffff810fa475>] ? lock_acquire+0xe5/0x150
> [  235.773386]  [<ffffffff81b4ca4d>] ? _raw_spin_unlock_irqrestore+0x6d/0x90
> [  235.778783]  [<ffffffff810f6251>] ? trace_hardirqs_on_caller+0x101/0x240
> [  235.784252]  [<ffffffff810f639d>] ? trace_hardirqs_on+0xd/0x10
> [  235.789726]  [<ffffffff8177f32e>] xenvif_rx_action+0x86e/0x1670
> [  235.795167]  [<ffffffff810f7fc8>] ? __lock_acquire+0x418/0x2220
> [  235.800560]  [<ffffffff810df5f6>] ? finish_task_switch+0x46/0xf0
> [  235.805782]  [<ffffffff817810e0>] xenvif_kthread+0x40/0x190
> [  235.811064]  [<ffffffff810f05e0>] ? __init_waitqueue_head+0x60/0x60
> [  235.816442]  [<ffffffff817810a0>] ? xenvif_stop_queue+0x60/0x60
> [  235.821888]  [<ffffffff810d4f24>] kthread+0xe4/0x100
> [  235.827688]  [<ffffffff81b4cc10>] ? _raw_spin_unlock_irq+0x30/0x50
> [  235.833925]  [<ffffffff810d4e40>] ? __init_kthread_worker+0x70/0x70
> [  235.839890]  [<ffffffff81b4de3c>] ret_from_fork+0x7c/0xb0
> [  235.845920]  [<ffffffff810d4e40>] ? __init_kthread_worker+0x70/0x70
> [  235.852174] Code: 89 c2 83 c0 01 48 8d 0c 92 48 8b 53 10 89 03 48 b8 00 00 
> 00 80 00 88 ff ff 48 8d 14 ca 48 b9 00 00 00 00 00 16 00 00 48 03 4d c0 <66> 
> 44 89 62 20 66 c7 42 08 f0 7f 66 c7 42 22 02 00 48 c1 f9 06
> [  235.865664] RIP  [<ffffffff8177d30e>] xenvif_gop_frag_copy+0x13e/0x580
> [  235.872106]  RSP <ffff88004b74bb28>
> [  235.878358] CR2: ffffc9001223b018
> [  235.885099] ---[ end trace 5971b65cc816997b ]---




>>>>                   - "xenvif_gop_frag_copy" calls "get_next_rx_buffer" .. 
>>>> cons becomes larger than prod ..and the "miracle" from the non-fatal case 
>>>> of prod suddenly becoming larger does not happen
>>>> 
>>>>       - So the calculation of how many slots are required for the frags in 
>>>> "xenvif_rx_action" does not match wath the code in "xenvif_gop_frag_copy" 
>>>> seems to need,
>>>>         I don't see why .. it's rounding up .. should behave correct if 
>>>> the left over happens to be 0 size ..
>>>> 
>>>> 
>>>> 
>>>> > Wei.
>>>> 






_______________________________________________
Xen-devel mailing list
Xen-devel@xxxxxxxxxxxxx
http://lists.xen.org/xen-devel


 


Rackspace

Lists.xenproject.org is hosted with RackSpace, monitoring our
servers 24x7x365 and backed by RackSpace's Fanatical Support®.