Re: running out of tags in 9P (was Re: [git pull] vfs part 2)

[Al Viro]

On Fri, Jul 03, 2015 at 11:19:31AM +0300, Andrey Ryabinin wrote:
> On 07/02/2015 07:49 PM, Al Viro wrote:
> > On Thu, Jul 02, 2015 at 05:43:32PM +0100, Al Viro wrote:
> >>  	req->tc->tag = tag-1;
> >> +	if (req->status != REQ_STATUS_IDLE)
> >> +		pr_err("using tag %d with odd status (%d)", tag, req->status);
> > 
> > Should be tag - 1 here, actually.
> 
> So, with this change:
> 
> [   81.654695] 9pnet: late delivery, tag 2 already freed
> [   81.655186] 9pnet: mismatched reply [tag = 2]
> [   85.014795] 9pnet: late delivery, tag 4 already freed
> [   85.015753] 9pnet: late delivery, tag 4 already freed
> [   85.016473] 9pnet: late delivery, tag 4 already freed
> [   87.275842] 9pnet: mismatched reply [tag = 5]
> [   88.943223] 9pnet: late delivery, tag 4 already freed
> [   88.943790] 9pnet: late delivery, tag 4 already freed
> [   88.944320] 9pnet: late delivery, tag 4 already freed
> [   88.945050] 9pnet: mismatched reply [tag = 4]
> [  105.551220] 9pnet: late delivery, tag 3 already freed
> [  105.552065] 9pnet: late delivery, tag 3 already freed
> [  114.528467] 9pnet: late delivery, tag 4 already freed
> [  164.791295] 9pnet: late delivery, tag 2 already freed
> [  164.792156] 9pnet: using tag 2 with odd status (4)
> [  164.864398] 9pnet: mismatched reply [tag = 4]
> [  166.419993] 9pnet: mismatched reply [tag = 3]
> [  174.062625] 9pnet: late delivery, tag 3 already freed
> [  174.063121] 9pnet: late delivery, tag 3 already freed
> [  174.063637] 9pnet: late delivery, tag 3 already freed
> [  174.064018] 9pnet: late delivery, tag 3 already freed
> [  174.064547] 9pnet: mismatched reply [tag = 3]
> [  175.418729] 9pnet: late delivery, tag 3 already freed
> [  177.911727] 9pnet: mismatched reply [tag = 1]
> [  235.748520] 9pnet: late delivery, tag 1 already freed
> [  235.749595] 9pnet: using tag 1 with odd status (4)
> [  243.496782] 9pnet: late delivery, tag 6 already freed
> [  243.497697] 9pnet: late delivery, tag 6 already freed
> [  243.499079] 9pnet: mismatched reply [tag = 6]
> [  243.736388] 9pnet: late delivery, tag 1 already freed
> [  243.740019] 9pnet: late delivery, tag 1 already freed
> [  248.337712] 9pnet: late delivery, tag 2 already freed
> [  249.872950] 9pnet: mismatched reply [tag = 9]
> [  252.448858] 9pnet: mismatched reply [tag = 8]
> [  252.668878] 9pnet: mismatched reply [tag = 11]

FWIW, I'd reproduced it here as well.  With the addition of checking in
p9_client_cb() whether the tag is already freed in IDR, reporting ->status
when it's not "sent" and reporting Tflush, I've got this:

[ 2754.713015] 9pnet: flushing 1
[ 2755.516123] 9pnet: flush 1 [3]done
[ 2758.443265] 9pnet: flushing 16
[ 2768.655768] 9pnet: flush 16 [8]done
[ 2783.939538] 9pnet: flushing 30
[ 2786.067856] 9pnet: flush 30 [3]done
[ 2809.784119] 9pnet: [ffff880113213000] delivery in 0, tag 1
[ 2809.948681] 9pnet: [ffff880113213000] using tag 1 with odd status (4)

Here we have delivery when that sucker is into p9_free_req(), but hasn't
removed from IDR yet.

[ 2809.948681] 9pnet: [ffff880113213000] delivery in 0, tag 1
[ 2816.767861] 9pnet: [ffff880113213000] using tag 1 with odd status (4)

Ditto.

[ 2816.767861] 9pnet: flushing 4
[ 2816.769484] 9pnet: flush 4 [5]done
[ 2846.327753] 9pnet: flushing 3
[ 2854.876131] 9pnet: flush 3 [4]done
[ 2856.492801] 9pnet: flushing 6
[ 2857.675642] 9pnet: flush 6 [1]done
[ 2860.051701] 9pnet: [ffff880113213000] delivery in 0, tag 1
[ 2860.052941] 9pnet: [ffff880113213000] late delivery, tag 1 already freed in IDR
[ 2860.680181] 9pnet: [ffff880113213000] using tag 1 with odd status (4)

This has hit between p9_free_req() and reallocating that request.

[ 2909.911815] 9pnet: [ffff880113213000] delivery in 4, tag 1
[ 2909.913145] 9pnet: [ffff880113213000] late delivery, tag 1 already freed in IDR

... while _this_ one has raced with p9_free_req() in a different way.

[ 2910.852202] 9pnet: flushing 3
[ 2917.985941] 9pnet: flush 3 [4]done
[ 2937.600652] 9pnet: flushing 2
[ 2939.775354] 9pnet: flush 2 [4]done
[ 2961.521600] 9pnet: [ffff880113213000] delivery in 0, tag 1
[ 2962.320383] 9pnet: [ffff880113213000] using tag 1 with odd status (4)

Same at the very first one.

[ 2962.320383] 9pnet: [ffff880113213000] delivery in 4, tag 8
[ 3001.578372] 9pnet: [ffff880113213000] delivery in 4, tag 6

Those had hit before p9_free_req().

AFAICS, we get occasional stray responses from somewhere.  And no, it doesn't
seem to be related to flushes or to dropping chan->lock in req_done() (this
run had been with chan->lock taken on the outside of the loop).

What I really don't understand is WTF is it playing with p9_tag_lookup() -
it's stashing req->tc via virtqueue_add_sgs() opaque data argument, fetches
it back in req_done(), then picks ->tag from it and uses p9_tag_lookup() to
find req.  Why not simply pass req instead?  I had been wrong about that
p9_tag_lookup() being able to return NULL, but why bother with it at all?
--
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
the body of a message to majordomo@xxxxxxxxxxxxxxx
More majordomo info at  http://vger.kernel.org/majordomo-info.html
Please read the FAQ at  http://www.tux.org/lkml/