From mboxrd@z Thu Jan 1 00:00:00 1970 Return-Path: Received: from mga03.intel.com ([134.134.136.65]:58656 "EHLO mga03.intel.com" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP id S1750888AbcJFHgx (ORCPT ); Thu, 6 Oct 2016 03:36:53 -0400 From: Felipe Balbi To: Ville =?utf-8?B?U3lyasOkbMOk?= Cc: linux-usb@vger.kernel.org, stable@vger.kernel.org Subject: Re: [PATCH] Revert "usb: dwc3: gadget: use allocated/queued reqs for LST bit" In-Reply-To: <87mvikp5wx.fsf@linux.intel.com> References: <1475504282-13268-1-git-send-email-ville.syrjala@linux.intel.com> <87lgy5za7o.fsf@linux.intel.com> <20161004083855.GW4329@intel.com> <8760p8qp5b.fsf@linux.intel.com> <20161004132059.GX4329@intel.com> <87mvikp5wx.fsf@linux.intel.com> Date: Thu, 06 Oct 2016 10:36:09 +0300 Message-ID: <87shsand3q.fsf@linux.intel.com> MIME-Version: 1.0 Content-Type: multipart/signed; boundary="=-=-="; micalg=pgp-sha256; protocol="application/pgp-signature" Sender: stable-owner@vger.kernel.org List-ID: --=-=-= Content-Type: text/plain Content-Transfer-Encoding: quoted-printable Hi, Felipe Balbi writes: >>> >> Reverting that commit is not the best idea. Let's start with the usu= al: >>> >>=20 >>> >> - Kernel version >>> >> - dmesg on both sides (host and device) >>> >> - dwc3 tracepoints: >>> >>=20 >>> >> # 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 >>> >>=20 >>> >> This should be enough to tell me what's really going on. >>> > >>> > I've attached the (compressed due to size) dmesgs/traces from the dev= ice. >>> > 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 ru= n). >>> > >>> > 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. >>>=20 >>> 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. >>>=20 >>> 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. >>>=20 >>> This only happens with IN endpoints (the ones which are throttled) and >>> the behavior can be seen in log snippet below: >>>=20 >>> 27782: irq/17-dwc3-2524 [000] d... 666.891969: tx_complete: re= q 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: re= q ffff88016da1a840 length 1514/1514 flags Zsi tx_qlen 9 qmult 5 >>> 27889: irq/17-dwc3-2524 [000] d... 666.892215: tx_complete: re= q 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: re= q ffff88016da1a180 length 1514/1514 flags Zsi tx_qlen 8 qmult 5 >>> 27903: irq/17-dwc3-2524 [000] d... 666.892225: tx_complete: re= q 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: re= q 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: re= q 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 >>>=20 >>> Note here that we reached tx_qlen =3D 10 without any interrupts being r= equested. >>>=20 >>> I patched u_ether with below to capture log above: >>>=20 >>> 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); >>>=20=20 >>> 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->zer= o ? 'Z' : 'z', >>> + req->short_not_ok ? 'S' : 's', >>> + req->no_interrupt ? 'i' : 'I', >>> + atomic_read(&dev->tx_qlen), >>> + dev->qmult); >>> } >>>=20=20 >>> if (retval) { >>>=20 >>> 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: >>>=20 >>> 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 *s= kb, >>>=20=20 >>> /* throttle high/super speed IRQ rate back slightly */ >>> if (gadget_is_dualspeed(dev->gadget)) >>> - req->no_interrupt =3D (dev->gadget->speed =3D=3D USB_SP= EED_HIGH || >>> - dev->gadget->speed =3D=3D USB_SPEE= D_SUPER) >>> + req->no_interrupt =3D (((dev->gadget->speed =3D=3D USB_= SPEED_HIGH || >>> + dev->gadget->speed =3D=3D USB_SP= EED_SUPER)) && >>> + !list_empty(&dev->tx_reqs)) >>> ? ((atomic_read(&dev->tx_qlen) % dev->qmult) != =3D 0) >>> : 0; >>>=20=20 >>> 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 ano= ther >> trace, with your u_ether trace_printks included. > > Now I only seem to find delays on ep1out. Here are a few instances: > > irq/22-dwc3-803 [001] d..1 19.446979: dwc3_gadget_ep_cmd: ep1ou= t: cmd 'Update Transfer' [131079] params 00000000 00000000 00000000 --> sta= tus: Successful > irq/22-dwc3-803 [001] d..1 20.452232: dwc3_event: event (000060= 84): ep1out: Transfer In-Progress > > irq/22-dwc3-803 [001] d..1 20.761702: dwc3_gadget_ep_cmd: ep1ou= t: cmd 'Update Transfer' [131079] params 00000000 00000000 00000000 --> sta= tus: Successful > irq/22-dwc3-803 [001] d..1 21.044345: dwc3_event: event (000060= 84): ep1out: Transfer In-Progress > > irq/22-dwc3-803 [001] d..1 21.999383: dwc3_gadget_ep_cmd: ep1ou= t: cmd 'Update Transfer' [131079] params 00000000 00000000 00000000 --> sta= tus: Successful > [...] > irq/22-dwc3-803 [001] d..1 22.239576: dwc3_event: event (000060= 84): ep1out: Transfer In-Progress > > irq/22-dwc3-803 [001] d..1 22.979703: dwc3_gadget_ep_cmd: ep1ou= t: cmd 'Update Transfer' [131079] params 00000000 00000000 00000000 --> sta= tus: Successful > [...] > irq/22-dwc3-803 [001] d..1 23.125096: dwc3_event: event (000060= 84): ep1out: Transfer In-Progress > > irq/22-dwc3-803 [001] d..1 23.820697: dwc3_gadget_ep_cmd: ep1ou= t: cmd 'Update Transfer' [131079] params 00000000 00000000 00000000 --> sta= tus: Successful > irq/22-dwc3-803 [001] d..1 24.461117: dwc3_event: event (000060= 84): ep1out: Transfer In-Progress > > irq/22-dwc3-803 [001] d..1 24.882567: dwc3_gadget_ep_cmd: ep1ou= t: cmd 'Update Transfer' [131079] params 00000000 00000000 00000000 --> sta= tus: Successful > irq/22-dwc3-803 [001] d..1 25.693330: dwc3_event: event (000060= 84): ep1out: Transfer In-Progress > > irq/22-dwc3-803 [001] d..1 25.702107: dwc3_gadget_ep_cmd: ep1ou= t: cmd 'Update Transfer' [131079] params 00000000 00000000 00000000 --> sta= tus: Successful > irq/22-dwc3-803 [001] d..1 26.045495: dwc3_event: event (000060= 84): ep1out: Transfer In-Progress > > Based on this, it would seem that host side isn't sending the data; but > that's quite odd. Let's put a sniffer here tomorrow and look at this > more carefully, I couldn't reproduce this with SKL as I was testing this > today. Okay, I have found a regression on dwc3 and another patch follows: commit 5e1a2af3e46248c55098cdae643c4141851b703e Author: Felipe Balbi Date: Wed Oct 5 14:24:37 2016 +0300 usb: dwc3: gadget: properly account queued requests =20=20=20=20 Some requests could be accounted for multiple times. Let's fix that so each and every requests is accounted for only once. =20=20=20=20 Cc: # v4.8 Fixes: 55a0237f8f47 ("usb: dwc3: gadget: use allocated/queued reqs for = LST bit") Signed-off-by: Felipe Balbi diff --git a/drivers/usb/dwc3/gadget.c b/drivers/usb/dwc3/gadget.c index 07cc8929f271..3c3ced128c77 100644 =2D-- a/drivers/usb/dwc3/gadget.c +++ b/drivers/usb/dwc3/gadget.c @@ -783,6 +783,7 @@ static void dwc3_prepare_one_trb(struct dwc3_ep *dep, req->trb =3D trb; req->trb_dma =3D dwc3_trb_dma_offset(dep, trb); req->first_trb_index =3D dep->trb_enqueue; + dep->queued_requests++; } =20 dwc3_ep_inc_enq(dep); @@ -833,8 +834,6 @@ static void dwc3_prepare_one_trb(struct dwc3_ep *dep, =20 trb->ctrl |=3D DWC3_TRB_CTRL_HWO; =20 =2D dep->queued_requests++; =2D trace_dwc3_prepare_trb(dep, trb); } =20 @@ -1861,8 +1860,11 @@ static int __dwc3_cleanup_done_trbs(struct dwc3 *dwc= , struct dwc3_ep *dep, unsigned int s_pkt =3D 0; unsigned int trb_status; =20 =2D dep->queued_requests--; dwc3_ep_inc_deq(dep); + + if (req->trb =3D=3D trb) + dep->queued_requests--; + trace_dwc3_complete_trb(dep, trb); =20 /* I have also built a branch which you can use for testing. Here's a pull request, once you tell me it works for you, then I can send proper patches out: The following changes since commit c8d2bc9bc39ebea8437fd974fdbc21847bb897a3: Linux 4.8 (2016-10-02 16:24:33 -0700) are available in the git repository at: git://git.kernel.org/pub/scm/linux/kernel/git/balbi/usb.git tmp-test-v4.8 for you to fetch changes up to c968b8d1effe64a7980802d1eef29f4e1922faca: usb: dwc3: gadget: properly account queued requests (2016-10-06 10:16:37 = +0300) =2D--------------------------------------------------------------- Felipe Balbi (2): usb: gadget: function: u_ether: don't starve tx request queue usb: dwc3: gadget: properly account queued requests drivers/usb/dwc3/gadget.c | 7 ++++--- drivers/usb/gadget/function/u_ether.c | 5 +++-- 2 files changed, 7 insertions(+), 5 deletions(-) =2D-=20 balbi --=-=-= Content-Type: application/pgp-signature; name="signature.asc" -----BEGIN PGP SIGNATURE----- iQIcBAEBCAAGBQJX9f7pAAoJEMy+uJnhGpkGf2QQAJgeR+dccstZDBLYiHJfxWMk jb9xfCEu1RTpqr6Xcls07h1ek4aS3zNdzFqgB8OIj0/7rA9kKzrsXwIs68pUrrjq vw7heXh3yJVDMx/lEcCOSt6yjbjZBNMMLfq53jPRuX2OcCbGGTDigFWsJNb4rokI hFXQ0MT/ROa9Uz9GlqHGcCI6sTmRrmWFZH6IdxKDE2c/vwROme6gWzgkKm8WAP2O ARnJh85HNtkAxrh3Da/IxgqCrLhnCHFTs/AMEByqc57+FZ3Vos5UQ7kPOCQQ+UF8 H18GjR3OYeqWblXG1lFBE7ofdKKoyRub1KH48EBVA++cuzh/r7sFZWcsH8B6gOC0 O6aTxorjSHAMyS6QlYxsAJWucdMbWUq8LggpKptulqKYjqK5liBbwgnUmirpNLuJ bOz2OeokM0vAHcABzMY22mdZLBHNFBBBM7niNZRmJ104XaZt6P0UEO+o15qXIqjo SE/0bZTZZ/WoCsogh1iuQJ/HsQxA5jJYIBOKiwVFr09ZesumlB7s74KF8rhdA/QA AVW7HVkuP+P0VsTvRPmNGz4X7aYx0Oi14z7GWImUPwYCHtRbD/g5XVw/PfKS1k+d 80F0/H9u2cb6JjmrpyIl81eOL5Xl9+G5Rt73/If6nKpk/E74W4TG82cF83U5Z4bI FnCGhBAHZ4zWhQDt1z93 =SwUk -----END PGP SIGNATURE----- --=-=-=--