From mboxrd@z Thu Jan 1 00:00:00 1970 Return-Path: Received: from mga11.intel.com ([192.55.52.93]:20139 "EHLO mga11.intel.com" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP id S1752544AbcJDMXo (ORCPT ); Tue, 4 Oct 2016 08:23:44 -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: <20161004083855.GW4329@intel.com> References: <1475504282-13268-1-git-send-email-ville.syrjala@linux.intel.com> <87lgy5za7o.fsf@linux.intel.com> <20161004083855.GW4329@intel.com> Date: Tue, 04 Oct 2016 15:23:12 +0300 Message-ID: <8760p8qp5b.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; charset=utf-8 Content-Transfer-Encoding: quoted-printable Hi, Ville Syrj=C3=A4l=C3=A4 writes: > On Mon, Oct 03, 2016 at 07:08:43PM +0300, Felipe Balbi wrote: >>=20 >> Hi, >>=20 >> ville.syrjala@linux.intel.com writes: >> > From: Ville Syrj=C3=A4l=C3=A4 >> > >> > 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 >> > Cc: stable@vger.kernel.org >> > Signed-off-by: Ville Syrj=C3=A4l=C3=A4 >>=20 >> Reverting that commit is not the best idea. Let's start with the usual: >>=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 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 ff= ff88016da1a6c0 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 ff= ff88016da1a840 length 1514/1514 flags Zsi tx_qlen 9 qmult 5 27889: irq/17-dwc3-2524 [000] d... 666.892215: tx_complete: req ff= ff88016da1a600 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 ff= ff88016da1a180 length 1514/1514 flags Zsi tx_qlen 8 qmult 5 27903: irq/17-dwc3-2524 [000] d... 666.892225: tx_complete: req ff= ff88016da1a240 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 ff= ff88016da1a6c0 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 ff= ff88016da1a300 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 =3D 10 without any interrupts being reque= sted. I patched u_ether with below to capture log above: diff --git a/drivers/usb/gadget/function/u_ether.c b/drivers/usb/gadget/fun= ction/u_ether.c index 5f562c1ec795..e34c26ffcdf4 100644 =2D-- 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 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 q= mult %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); } =20 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/fun= ction/u_ether.c index 5f562c1ec795..ddfa866c2cba 100644 =2D-- 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, =20 /* throttle high/super speed IRQ rate back slightly */ if (gadget_is_dualspeed(dev->gadget)) =2D req->no_interrupt =3D (dev->gadget->speed =3D=3D USB_SPEE= D_HIGH || =2D dev->gadget->speed =3D=3D USB_SPEED_= SUPER) + req->no_interrupt =3D (((dev->gadget->speed =3D=3D USB_SPEE= D_HIGH || + dev->gadget->speed =3D=3D USB_SPEED_= SUPER)) && + !list_empty(&dev->tx_reqs)) ? ((atomic_read(&dev->tx_qlen) % dev->qmult) !=3D 0) : 0; =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. cheers =2D-=20 balbi --=-=-= Content-Type: application/pgp-signature; name="signature.asc" -----BEGIN PGP SIGNATURE----- iQIcBAEBCAAGBQJX858wAAoJEMy+uJnhGpkG8O4P/05RwoERFo1eCjK+/Khk9zMP 5Yd+Fi87cHZd9HFZJEXh2EhXDJ7OkUAkkVL5NTFOAszX+QX7gL8gebugzKm8skVR idP6mvy5cpi0QA+q9mp46bcCnFr7tAnZTwkInRYSI3mdasD1qZxLvPPmyW6cajod r/eyCKv3WqMR+QdtuB5EhRSPaaGuhXuHKvqjyAXltzl6XjnPcWKo1jEreQEqdM/U AXlprrbHBHPPUgmZRuSn3R7SguX9WY1x6K5aOH5yifCwqYdO6xtMuDNIVDH1TpPf Ni/j1O+k80gXwF/7E2Rt4GpnrkA6XVN3azqyA8T+c6syyzwMWiXdNHrZJfHcAlhw l9g1a17EqDw3VwPHIkGQy6uWlBYzazhGkz50N0WYReJiGvDRGXfBaE23AKzs5Iq4 TIYIHjq4fOCoBMNj2YAhmda4glare44Y2z1TNQ6JWAEsVdTuREQPWBeFs6JyNIVW TgWhcXKZJOoqOMMj9H8opZ5RSYF6tgPMJaBV5GAr4t1OsorRYO/8FgriKkP40yHO ubgx4Tubcwq9rC5EKwfph7HfmEbxad1edp35edQ5w66A2bEmt5yhnf+qP1HrxaUf 2l/o1g14omGtqy3XAKs/tfdfrqwuw0vcbfeULVp9MRjrwT8Eq1zyi8mqzX+CSZRz oJryWw3otImq/96adLqW =IA6n -----END PGP SIGNATURE----- --=-=-=--