Received: by 2002:a05:6902:102b:0:0:0:0 with SMTP id x11csp3251780ybt; Mon, 29 Jun 2020 20:29:48 -0700 (PDT) X-Google-Smtp-Source: ABdhPJwJrrXrfE6Au8L/ULxq1ksCQ2TFsDA6iGI17DOv4ycgyY1yUTos/MsoXkjxtha2SufHBt95 X-Received: by 2002:a50:ee07:: with SMTP id g7mr5182271eds.320.1593487788629; Mon, 29 Jun 2020 20:29:48 -0700 (PDT) ARC-Seal: i=1; a=rsa-sha256; t=1593487788; cv=none; d=google.com; s=arc-20160816; b=L5JspZi6CyZ/tFRjIAlEipwVmiiyMax/Iyf5aufkpGNJvUrx4ZHx6vrvXykN12xAzd Kq0EPdOlfix9FaliaR+cNRPGKCqQtxlwJNz50z9V2gvlg82m2JhaI5Nhy7e8eLj5DOLX p9fZE4sVBB6jkKTuYimOVb3/jD9vX5BTf1nwlhKc3hZz9Crw71cphl+yShw+TqAopk2R ux0wx4I6pDLEPVy6JXx2XXQ/4is5zckTQw+TdbgThUb/AAbiFT1YtaqCGevN1+So6dKs wy3xfb3jUD4CH4yr2tsRempaw2PvD7jd1WgoWVyulKJ8Nn+EeUteaizWTb4Iow6F/AwB KQyw== ARC-Message-Signature: i=1; a=rsa-sha256; c=relaxed/relaxed; d=google.com; s=arc-20160816; h=list-id:precedence:sender:mime-version:user-agent:references :in-reply-to:date:cc:to:from:subject:message-id; bh=uSCZ4HBwtWRSa91kC8zbew0JdBRvpb2sBhL1bxSvS9c=; b=snJhuMzDdtdfUWDsPfbCj1IA6vaS1FjIsojnqXx6Nnk8kQrk0dL+RNmpmUBWc6jg+b FBIuFS++ObOoWJzl5O8bj+E74hOsAyaaqgO3iAcny7XUfkrXfx77Z7qhCejfVZLul2wo X5O0LImtPE4Rd1EARAvKSZ8OiCUZ2NOKC0ySVPif7Pn0Z7sBNuL0ANM0AmNen9J1SHT/ wyJLK8vc62U0K/KZrpwgs3y3cdPe1Jz+ANj9S4U5S2gSi/EgA991BKuF8Z+Fi3kAgxjy bd/1BcL4yiaeDcsPWpqf3BvJIPAKH5y/DW4UyOVOuBN2oytsQsg551SqOTkj01rh4ubN HPtA== ARC-Authentication-Results: i=1; mx.google.com; spf=pass (google.com: domain of linux-kernel-owner@vger.kernel.org designates 23.128.96.18 as permitted sender) smtp.mailfrom=linux-kernel-owner@vger.kernel.org Return-Path: Received: from vger.kernel.org (vger.kernel.org. [23.128.96.18]) by mx.google.com with ESMTP id b8si1258557edz.89.2020.06.29.20.29.24; Mon, 29 Jun 2020 20:29:48 -0700 (PDT) Received-SPF: pass (google.com: domain of linux-kernel-owner@vger.kernel.org designates 23.128.96.18 as permitted sender) client-ip=23.128.96.18; Authentication-Results: mx.google.com; spf=pass (google.com: domain of linux-kernel-owner@vger.kernel.org designates 23.128.96.18 as permitted sender) smtp.mailfrom=linux-kernel-owner@vger.kernel.org Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand id S1729057AbgF3D3O (ORCPT + 99 others); Mon, 29 Jun 2020 23:29:14 -0400 Received: from shelob.surriel.com ([96.67.55.147]:56760 "EHLO shelob.surriel.com" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP id S1728147AbgF3D3O (ORCPT ); Mon, 29 Jun 2020 23:29:14 -0400 X-Greylist: delayed 447 seconds by postgrey-1.27 at vger.kernel.org; Mon, 29 Jun 2020 23:29:13 EDT Received: from imladris.surriel.com ([96.67.55.152]) by shelob.surriel.com with esmtpsa (TLS1.2) tls TLS_ECDHE_RSA_WITH_AES_256_GCM_SHA384 (Exim 4.94) (envelope-from ) id 1jq6q1-0006Nm-7o; Mon, 29 Jun 2020 23:21:37 -0400 Message-ID: Subject: Re: XHCI vs PCM2903B/PCM2904 part 2 From: Rik van Riel To: Mathias Nyman , Alan Stern Cc: linux-usb , alsa-devel@alsa-project.org, "linux-kernel@vger.kernel.org" , Mathias Nyman , Greg Kroah-Hartman , Jaroslav Kysela , Takashi Iwai Date: Mon, 29 Jun 2020 23:21:36 -0400 In-Reply-To: <059878e7-75b8-e033-ec9f-7e6b73df8f78@linux.intel.com> References: <273cc1c074cc4a4058f31afe487fb233f5cf0351.camel@surriel.com> <20200520163840.GA11084@rowland.harvard.edu> <667d8d156fa5d8420ef1c3b1d08b94a10d2398cc.camel@surriel.com> <20200520203417.GA23602@rowland.harvard.edu> <059878e7-75b8-e033-ec9f-7e6b73df8f78@linux.intel.com> Content-Type: multipart/signed; micalg="pgp-sha256"; protocol="application/pgp-signature"; boundary="=-7H8YpOtf/vhHCGpd5MEU" User-Agent: Evolution 3.34.4 (3.34.4-1.fc31) MIME-Version: 1.0 Sender: linux-kernel-owner@vger.kernel.org Precedence: bulk List-ID: X-Mailing-List: linux-kernel@vger.kernel.org --=-7H8YpOtf/vhHCGpd5MEU Content-Type: text/plain; charset="UTF-8" Content-Transfer-Encoding: quoted-printable [keeping old context since it's been a month...] On Mon, 2020-05-25 at 12:37 +0300, Mathias Nyman wrote: > On 21.5.2020 6.45, Rik van Riel wrote: > > On Wed, 2020-05-20 at 16:34 -0400, Alan Stern wrote: > > > On Wed, May 20, 2020 at 03:21:44PM -0400, Rik van Riel wrote: > > > > Interesting. That makes me really curious why things are > > > > getting stuck, now... > > >=20 > > > This could be a bug in xhci-hcd. Perhaps the controller's > > > endpoint=20 > > > state needs to be updated after one of these errors > > > occurs. Mathias=20 > > > will know all about that. > >=20 > > I am seeing something potentially interesting in the > > giant trace. First the final enqueue/dequeue before > > the babble error: > >=20 > > -0 [005] d.s. 776367.638233: xhci_inc_enq: ISOC > > 0000000033a6879e: enq 0x0000001014070420(0x0000001014070000) deq > > 0x0000001014070360(0x0000001014070000) segs 2 stream 0 free_trbs > > 497 > > bounce 196 cycle 1 > >=20 > > The next reference to 0x0000001014070360 is the babble error, > > and some info on the ISOC buffer itself: > >=20 > > -0 [005] d.h. 776367.639187: xhci_handle_event: > > EVENT: TRB 0000001014070360 status 'Babble Detected' len 196 slot > > 15 ep > > 9 type 'Transfer Event' flags e:C > > -0 [005] d.h. 776367.639195: > > xhci_handle_transfer: > > ISOC: Buffer 0000000e2676f400 length 196 TD size 0 intr 0 type > > 'Isoch' > > flags b:i:I:c:s:I:e:C > > n > > Immediately after the babble error, the next request is enqueued, > > and the doorbell is rung: > >=20 > > -0 [005] d.h. 776367.639196: xhci_inc_deq: ISOC > > 0000000033a6879e: enq 0x0000001014070420(0x0000001014070000) deq > > 0x0000001014070370(0x0000001014070000) segs 2 stream 0 free_trbs > > 498 bounce 196 cycle 1 > > -0 [005] d.h. 776367.639197: xhci_urb_giveback: > > ep4in-isoc: urb 0000000072126553 pipe 135040 slot 15 length 196/196 > > sgs 0/0 stream 0 flags 00000206 > > -0 [005] d.h. 776367.639197: xhci_inc_deq: > > EVENT 0000000097f84b16: enq 0x00000010170b5000(0x00000010170b5000) > > deq 0x00000010170b5670(0x00000010170b5000) segs 1 stream 0 > > free_trbs 254 bounce 0 cycle 1 > > -0 [005] ..s. 776367.639212: xhci_urb_enqueue: > > ep4in-isoc: urb 0000000072126553 pipe 135040 slot 15 length 0/196 > > sgs 0/0 stream 0 flags 00000206 > > -0 [005] d.s. 776367.639214: xhci_queue_trb: > > ISOC: Buffer 0000000e2676f400 length 196 TD size 0 intr 0 type > > 'Isoch' flags b:i:I:c:s:I:e:c > > -0 [005] d.s. 776367.639214: xhci_inc_enq: ISOC > > 0000000033a6879e: enq 0x0000001014070430(0x0000001014070000) deq > > 0x0000001014070370(0x0000001014070000) segs 2 stream 0 free_trbs > > 497 bounce 196 cycle 1 > > -0 [005] d.s. 776367.639215: > > xhci_ring_ep_doorbell: Ring doorbell for Slot 15 ep4in > >=20 > > However, after that point, no more xhci_handle_transfer: ISOC > > lines ar seen in the log. The doorbell line above is the last > > line in the log for ep4in. > >=20 > > Is this some area where USB3 and USB2 behave differently? >=20 > It acts as if the endpoint is no longer running. >=20 > If the endpoint would be halted then > xhci_requires_manual_halt_cleanup() should > reset the endpoints and it would show in the traces. >=20 > Could you add the code below and take new traces, it will show the > endpoint > state after the Babble error. Hi Mathias, I have finally rebooted into a kernel with your tracepoint. After a babble error, I get the following info in the trace. [ 556.716334] xhci_hcd 0000:00:14.0: Babble error for slot 13 ep 8 on endpoint 28672.016 :0/0 xhci-hcd:xhci_handle_tx_event(info: 196609, info2: 12845096, deq: 69501877488, tx_info: 12845252) 34816.037 :0/0 xhci-hcd:xhci_handle_tx_event(info: 196609, info2: 12845096, deq: 69501877856, tx_info: 12845252) 38912.043 :0/0 xhci-hcd:xhci_handle_tx_event(info: 196609, info2: 12845096, deq: 69501870176, tx_info: 12845252) I hope this is useful :) > diff --git a/drivers/usb/host/xhci-ring.c b/drivers/usb/host/xhci- > ring.c > index 0fda0c0f4d31..373d89ef7275 100644 > --- a/drivers/usb/host/xhci-ring.c > +++ b/drivers/usb/host/xhci-ring.c > @@ -2455,6 +2455,7 @@ static int handle_tx_event(struct xhci_hcd > *xhci, > case COMP_BABBLE_DETECTED_ERROR: > xhci_dbg(xhci, "Babble error for slot %u ep %u on > endpoint\n", > slot_id, ep_index); > + trace_xhci_handle_tx_event(ep_ctx); > status =3D -EOVERFLOW; > break; > /* Completion codes for endpoint error state */ > diff --git a/drivers/usb/host/xhci-trace.h b/drivers/usb/host/xhci- > trace.h > index b19582b2a72c..5081df079f4a 100644 > --- a/drivers/usb/host/xhci-trace.h > +++ b/drivers/usb/host/xhci-trace.h > @@ -360,6 +360,11 @@ DEFINE_EVENT(xhci_log_ep_ctx, xhci_add_endpoint, > TP_ARGS(ctx) > ); > =20 > +DEFINE_EVENT(xhci_log_ep_ctx, xhci_handle_tx_event, > + TP_PROTO(struct xhci_ep_ctx *ctx), > + TP_ARGS(ctx) > +); > + > DECLARE_EVENT_CLASS(xhci_log_slot_ctx, > TP_PROTO(struct xhci_slot_ctx *ctx), > TP_ARGS(ctx), >=20 >=20 >=20 --=20 All Rights Reversed. --=-7H8YpOtf/vhHCGpd5MEU Content-Type: application/pgp-signature; name="signature.asc" Content-Description: This is a digitally signed message part Content-Transfer-Encoding: 7bit -----BEGIN PGP SIGNATURE----- iQEzBAABCAAdFiEEKR73pCCtJ5Xj3yADznnekoTE3oMFAl76r8AACgkQznnekoTE 3oOnJAgAqIU1wK6FVNYgdtzF7fZpGRBrZ0LvLsVY2moqdjCcJ3htP4bdNKnAyLGK vEvkA4baneooSIgsRmZxzCVseQXkSDPDKN9Zw3nC4Ohig3wSmy8/w/sYIgMpsfwS vUUdjgrNe0ivvwL6MvVchsAfAugJ8Xs1rE9pCpdEXi5vdGEdOCA9UtSCRl2wk3oP YJWurHs68aU/Ge4S1oo8cnNp+IDYhRUxyAwBGKquigzYu+s3+dPig9EgxmJYilXM 9SEtxfeA8wcTqCoRXghDKW1zAxBGOE/5B449DoWLLrM2L/+W7obklS8EpQbxuF3p GQsehy0WurxKnM8sRMrVtE7m55z8CA== =ZBQZ -----END PGP SIGNATURE----- --=-7H8YpOtf/vhHCGpd5MEU--