Re: [PATCH] Revert "usb: dwc3: gadget: use allocated/queued reqs for LST bit"

["Ville Syrjälä" <ville.syrjala@linux.intel.com>]

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

On Tue, Oct 04, 2016 at 03:23:12PM +0300, Felipe Balbi wrote:
> 
> Hi,
> 
> Ville Syrj�l� <ville.syrjala@linux.intel.com> writes:
> > On Mon, Oct 03, 2016 at 07:08:43PM +0300, Felipe Balbi wrote:
> >> 
> >> Hi,
> >> 
> >> ville.syrjala@linux.intel.com writes:
> >> > From: Ville Syrj�l� <ville.syrjala@linux.intel.com>
> >> >
> >> > This reverts commit 55a0237f8f47957163125e20ee9260538c5c341c.
> >> >
> >> > commit  55a0237f8f47 ("usb: dwc3: gadget: use allocated/queued reqs for
> >> > LST bit") causes my BYT FFRD8 with g_ether to behave poorly. ssh/scp
> >> > is very sluggish and can even stall entirely. Revert cures it.
> >> >
> >> > Cc: Felipe Balbi <felipe.balbi@linux.intel.com>
> >> > Cc: stable@vger.kernel.org
> >> > Signed-off-by: Ville Syrj�l� <ville.syrjala@linux.intel.com>
> >> 
> >> Reverting that commit is not the best idea. Let's start with the usual:
> >> 
> >> - Kernel version
> >> - dmesg on both sides (host and device)
> >> - dwc3 tracepoints:
> >> 
> >> # mkdir -p /t
> >> # mount -t tracefs none /t
> >> # echo 8192 > /t/buffer_size_kb
> >> # echo 1 > /t/events/dwc3/enable
> >> # echo 0 > /t/events/dwc3/dwc3_readl/enable
> >> # echo 0 > /t/events/dwc3/dwc3_writel/enable
> >> 
> >> This should be enough to tell me what's really going on.
> >
> > I've attached the (compressed due to size) dmesgs/traces from the device.
> > For my test I just did 'for i in `seq 1 5` ; dmesg ; done' in an ssh
> > session, and I did get the lag in the bad run, so presumably the trace
> > should have caught it. Both were on 4.8 (+ the revert for the good run).
> >
> > Host side dmesg just showes me:
> >  usb 3-3.4: new high-speed USB device number 25 using xhci_hcd
> >  cdc_ether 3-3.4:1.0 usb0: register 'cdc_ether' at usb-0000:00:14.0-3.4, CDC Ethernet Device, ...
> > when I boot the device. Nothing extra appears when things lag around.
> > I'm running 4.5.something on the host.
> 
> Looking at your logs what I can see is that "revert.trace" doesn't
> respect gadget driver's IRQ throttling, which means you get an interrupt
> for each and every request, while "bad.trace" shows dwc3 respecting
> "no_interrupt" flag passed in by g_ether.
> 
> The only explanation I have for this behavior when we start respecting
> gadget driver's flags, is that there's a possible race in u_ether.c
> where it can go for a long time without an interrupt due to that
> throttling.
> 
> This only happens with IN endpoints (the ones which are throttled) and
> the behavior can be seen in log snippet below:
> 
>   27782:     irq/17-dwc3-2524  [000] d...   666.891969: tx_complete: req ffff88016da1a6c0 length 1514/1514 flags ZsI tx_qlen 4 qmult 5
>   27802:     ksoftirqd/0-3     [000] .Ns1   666.892047: eth_start_xmit: req ffff88016da1a6c0 length 0/1514 flags Zsi tx_qlen 5 qmult 5
>   27808:     ksoftirqd/0-3     [000] .Ns2   666.892062: eth_start_xmit: req ffff88016da1a300 length 0/1514 flags ZsI tx_qlen 6 qmult 5
>   27814:     ksoftirqd/0-3     [000] .Ns2   666.892069: eth_start_xmit: req ffff88016da1ab40 length 0/1514 flags Zsi tx_qlen 7 qmult 5
>   27820:     ksoftirqd/0-3     [000] .Ns2   666.892075: eth_start_xmit: req ffff88016da1acc0 length 0/1514 flags Zsi tx_qlen 8 qmult 5
>   27826:     ksoftirqd/0-3     [000] .Ns2   666.892082: eth_start_xmit: req ffff88016da1ae40 length 0/1514 flags Zsi tx_qlen 9 qmult 5
>   27832:     ksoftirqd/0-3     [000] .Ns2   666.892088: eth_start_xmit: req ffff88016da1a780 length 0/1514 flags Zsi tx_qlen 10 qmult 5
>   27884:     irq/17-dwc3-2524  [000] d...   666.892213: tx_complete: req ffff88016da1a840 length 1514/1514 flags Zsi tx_qlen 9 qmult 5
>   27889:     irq/17-dwc3-2524  [000] d...   666.892215: tx_complete: req ffff88016da1a600 length 1514/1514 flags Zsi tx_qlen 8 qmult 5
>   27897:            sshd-2684  [002] ..s1   666.892223: eth_start_xmit: req ffff88016da1a840 length 0/1514 flags Zsi tx_qlen 9 qmult 5
>   27898:     irq/17-dwc3-2524  [000] d...   666.892223: tx_complete: req ffff88016da1a180 length 1514/1514 flags Zsi tx_qlen 8 qmult 5
>   27903:     irq/17-dwc3-2524  [000] d...   666.892225: tx_complete: req ffff88016da1a240 length 1514/1514 flags Zsi tx_qlen 7 qmult 5
>   27910:            sshd-2684  [002] ..s1   666.892230: eth_start_xmit: req ffff88016da1a180 length 0/1514 flags Zsi tx_qlen 8 qmult 5
>   27913:     irq/17-dwc3-2524  [000] d...   666.892231: tx_complete: req ffff88016da1a6c0 length 1514/1514 flags Zsi tx_qlen 7 qmult 5
>   27920:            sshd-2684  [002] ..s1   666.892236: eth_start_xmit: req ffff88016da1a6c0 length 0/1514 flags Zsi tx_qlen 8 qmult 5
>   27923:     irq/17-dwc3-2524  [000] d...   666.892238: tx_complete: req ffff88016da1a300 length 1514/1514 flags ZsI tx_qlen 7 qmult 5
>   27928:            sshd-2684  [002] ..s1   666.892242: eth_start_xmit: req ffff88016da1a240 length 0/1514 flags Zsi tx_qlen 8 qmult 5
>   27944:            sshd-2684  [002] ..s1   666.892253: eth_start_xmit: req ffff88016da1a300 length 0/1514 flags Zsi tx_qlen 9 qmult 5
>   27953:            sshd-2684  [002] ..s1   666.892262: eth_start_xmit: req ffff88016da1a600 length 0/1514 flags Zsi tx_qlen 10 qmult 5
> 
> Note here that we reached tx_qlen = 10 without any interrupts being requested.
> 
> I patched u_ether with below to capture log above:
> 
> diff --git a/drivers/usb/gadget/function/u_ether.c b/drivers/usb/gadget/function/u_ether.c
> index 5f562c1ec795..e34c26ffcdf4 100644
> --- a/drivers/usb/gadget/function/u_ether.c
> +++ b/drivers/usb/gadget/function/u_ether.c
> @@ -465,6 +465,15 @@ static void tx_complete(struct usb_ep *ep, struct usb_request *req)
>         dev_kfree_skb_any(skb);
>  
>         atomic_dec(&dev->tx_qlen);
> +
> +       trace_printk("req %p length %d/%d flags %c%c%c tx_qlen %d qmult %d\n",
> +                       req, req->actual, req->length,
> +                       req->zero ? 'Z' : 'z',
> +                       req->short_not_ok ? 'S' : 's',
> +                       req->no_interrupt ? 'i' : 'I',
> +                       atomic_read(&dev->tx_qlen),
> +                       dev->qmult);
> +
>         if (netif_carrier_ok(dev->net))
>                 netif_wake_queue(dev->net);
>  }
> @@ -600,6 +609,12 @@ static netdev_tx_t eth_start_xmit(struct sk_buff *skb,
>         case 0:
>                 netif_trans_update(net);
>                 atomic_inc(&dev->tx_qlen);
> +               trace_printk("req %p length %d/%d flags %c%c%c tx_qlen %d qmult %d\n",
> +                               req, req->actual, req->length, req->zero ? 'Z' : 'z',
> +                               req->short_not_ok ? 'S' : 's',
> +                               req->no_interrupt ? 'i' : 'I',
> +                               atomic_read(&dev->tx_qlen),
> +                               dev->qmult);
>         }
>  
>         if (retval) {
> 
> The only way I can think of to avoid this problem is to make sure we
> don't starve our request queue with something like:
> 
> diff --git a/drivers/usb/gadget/function/u_ether.c b/drivers/usb/gadget/function/u_ether.c
> index 5f562c1ec795..ddfa866c2cba 100644
> --- a/drivers/usb/gadget/function/u_ether.c
> +++ b/drivers/usb/gadget/function/u_ether.c
> @@ -587,8 +596,9 @@ static netdev_tx_t eth_start_xmit(struct sk_buff *skb,
>  
>         /* throttle high/super speed IRQ rate back slightly */
>         if (gadget_is_dualspeed(dev->gadget))
> -               req->no_interrupt = (dev->gadget->speed == USB_SPEED_HIGH ||
> -                                    dev->gadget->speed == USB_SPEED_SUPER)
> +               req->no_interrupt = (((dev->gadget->speed == USB_SPEED_HIGH ||
> +                                      dev->gadget->speed == USB_SPEED_SUPER)) &&
> +                                       !list_empty(&dev->tx_reqs))
>                         ? ((atomic_read(&dev->tx_qlen) % dev->qmult) != 0)
>                         : 0;
>  
> I have been testing this for about half an hour and I can't see delays
> or link getting stuck. Care to test ? If it works for your setup, I'll
> send this with Cc: stable and your Reported-by and Tested-by tags.

That doesn't appear to cure the problem unfortunately. I've attached another
trace, with your u_ether trace_printks included.

-- 
Ville Syrj�l�
Intel OTC

[-- Attachment #2: u_ether.trace.gz --]
[-- Type: application/octet-stream, Size: 58771 bytes --]