From patchwork Fri Sep 18 11:13:44 2020 Content-Type: text/plain; charset="utf-8" MIME-Version: 1.0 Content-Transfer-Encoding: 7bit X-Patchwork-Submitter: Ran Wang X-Patchwork-Id: 1366820 X-Patchwork-Delegate: marek.vasut@gmail.com Return-Path: X-Original-To: incoming@patchwork.ozlabs.org Delivered-To: patchwork-incoming@bilbo.ozlabs.org Authentication-Results: ozlabs.org; spf=pass (sender SPF authorized) smtp.mailfrom=lists.denx.de (client-ip=2a01:238:438b:c500:173d:9f52:ddab:ee01; helo=phobos.denx.de; envelope-from=u-boot-bounces@lists.denx.de; receiver=) Authentication-Results: ozlabs.org; dmarc=pass (p=none dis=none) header.from=nxp.com Authentication-Results: ozlabs.org; dkim=pass (1024-bit key; unprotected) header.d=nxp.com header.i=@nxp.com header.a=rsa-sha256 header.s=selector2 header.b=aYQiDzbM; dkim-atps=neutral Received: from phobos.denx.de (phobos.denx.de [IPv6:2a01:238:438b:c500:173d:9f52:ddab:ee01]) (using TLSv1.3 with cipher TLS_AES_256_GCM_SHA384 (256/256 bits) key-exchange X25519 server-signature RSA-PSS (4096 bits)) (No client certificate requested) by ozlabs.org (Postfix) with ESMTPS id 4BtB6W6Pcqz9sSt for ; Fri, 18 Sep 2020 21:13:53 +1000 (AEST) Received: from h2850616.stratoserver.net (localhost [IPv6:::1]) by phobos.denx.de (Postfix) with ESMTP id 0F4B282442; Fri, 18 Sep 2020 13:13:50 +0200 (CEST) Authentication-Results: phobos.denx.de; dmarc=pass (p=none dis=none) header.from=nxp.com Authentication-Results: phobos.denx.de; spf=pass smtp.mailfrom=u-boot-bounces@lists.denx.de Authentication-Results: phobos.denx.de; dkim=pass (1024-bit key; unprotected) header.d=nxp.com header.i=@nxp.com header.b="aYQiDzbM"; dkim-atps=neutral Received: by phobos.denx.de (Postfix, from userid 109) id 8DCD88244B; Fri, 18 Sep 2020 13:13:48 +0200 (CEST) X-Spam-Checker-Version: SpamAssassin 3.4.2 (2018-09-13) on phobos.denx.de X-Spam-Level: X-Spam-Status: No, score=-1.0 required=5.0 tests=BAYES_00,DKIM_SIGNED, DKIM_VALID,DKIM_VALID_AU,FORGED_SPF_HELO,SPF_HELO_PASS,URIBL_BLOCKED autolearn=no autolearn_force=no version=3.4.2 Received: from EUR04-DB3-obe.outbound.protection.outlook.com (mail-db3eur04on062f.outbound.protection.outlook.com [IPv6:2a01:111:f400:fe0c::62f]) (using TLSv1.2 with cipher ECDHE-RSA-AES256-GCM-SHA384 (256/256 bits)) (No client certificate requested) by phobos.denx.de (Postfix) with ESMTPS id 83F9E82431 for ; Fri, 18 Sep 2020 13:13:45 +0200 (CEST) Authentication-Results: phobos.denx.de; dmarc=pass (p=none dis=none) header.from=nxp.com Authentication-Results: phobos.denx.de; spf=pass smtp.mailfrom=ran.wang_1@nxp.com ARC-Seal: i=1; a=rsa-sha256; s=arcselector9901; d=microsoft.com; cv=none; b=lAIjSj3kUG72tjcyDptaIEBBdnySPm2QYKc2bYiMY4VUvgDz0doHi6lsscgineKK4xVILGHuUHjFFskX5hqMbtoufQpbAfhNdd68I4YxAkghfrVYi3MGqjcCKh59kjWgfhXJSWKIAzOKBGtrcMpbNaeFaKAQellBprmvmIWhV4JkHGZvh5PfpzDY1uviqU/dsUamqTk3blKEK8550770xesRezrUl3XFeIty70ox4z8fWi6+ksZYcUhKa45u5GwcrWfKwwpd0ipjpvrkYV4Yx9TH/Cn9XDyhfQjmd18u4wYCT+pA+6EsbgP/S5DP4tIO099kVnFZh+0O/VdLKY1XYA== ARC-Message-Signature: i=1; a=rsa-sha256; c=relaxed/relaxed; d=microsoft.com; s=arcselector9901; h=From:Date:Subject:Message-ID:Content-Type:MIME-Version:X-MS-Exchange-SenderADCheck; bh=uTc82T7+vlbXlwp/C2Vil3XJGOrodyhLv3mRKsudxDs=; b=HtoK8/uCrb/zcW7ObrMS8uDCV3k2XdAVLCivCT/ZbLDib6L2CBJKdcPHhyM9u9LkZKQzBHq7HeOW8S9mHnYaHieFr0VgR1q4vOtDDVxIGgGsfpN2fPXOorkJU7dNDMaSp+llWmbCX1+C2QgkS1UYo4Gl0KfRi2TWFaZVJ5YGfY7Bqy1c7c0yuuCDpSLJtDi2kF28M0tY1M+I7MlhPm1xPL2zrgbq+pcoJzH/JiU2U1YSH42L43ChxNd0fn6/qZkg0wCn6uKbmiXDYre05Zn/DoLyVx/C7SdnhxeTSRYKz9EUz+6ZMGGAQesz0wP3FKbLLJW7tQjch2r4bCT4u7qACw== ARC-Authentication-Results: i=1; mx.microsoft.com 1; spf=pass smtp.mailfrom=nxp.com; dmarc=pass action=none header.from=nxp.com; dkim=pass header.d=nxp.com; arc=none DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=nxp.com; s=selector2; h=From:Date:Subject:Message-ID:Content-Type:MIME-Version:X-MS-Exchange-SenderADCheck; bh=uTc82T7+vlbXlwp/C2Vil3XJGOrodyhLv3mRKsudxDs=; b=aYQiDzbMBkAGFrcImgrhdM8JAKXN/DssVvz5PMHlHmclvN9/PjHXqIjatX8mG/kCk1KCFnjwDG9VnzTNYaso9gG/AbtKa02ppJToYK9FuDk+yysWmXfXXcdcVzYdCtpL+rDqyPpaNkgx1M82FcwOycETmm/ed/D6FhqWq6Iz4yk= Received: from AM6PR04MB5413.eurprd04.prod.outlook.com (2603:10a6:20b:96::28) by AM6PR0402MB3336.eurprd04.prod.outlook.com (2603:10a6:209:12::29) with Microsoft SMTP Server (version=TLS1_2, cipher=TLS_ECDHE_RSA_WITH_AES_256_GCM_SHA384) id 15.20.3370.19; Fri, 18 Sep 2020 11:13:44 +0000 Received: from AM6PR04MB5413.eurprd04.prod.outlook.com ([fe80::1953:c81a:cca2:60ec]) by AM6PR04MB5413.eurprd04.prod.outlook.com ([fe80::1953:c81a:cca2:60ec%7]) with mapi id 15.20.3391.014; Fri, 18 Sep 2020 11:13:44 +0000 From: Ran Wang To: Bin Meng , Marek Vasut , Peter Chen , Jun Li , "u-boot@lists.denx.de" Subject: Function xhci_bulk_tx( ) failed to handle double transfer EVENT TRB case in one call Thread-Topic: Function xhci_bulk_tx( ) failed to handle double transfer EVENT TRB case in one call Thread-Index: AdaNqJCgzR6tkEDDS42ZI/K1skzxeA== Date: Fri, 18 Sep 2020 11:13:44 +0000 Message-ID: Accept-Language: en-US Content-Language: en-US X-MS-Has-Attach: X-MS-TNEF-Correlator: authentication-results: gmail.com; dkim=none (message not signed) header.d=none;gmail.com; dmarc=none action=none header.from=nxp.com; x-originating-ip: [119.31.174.73] x-ms-publictraffictype: Email x-ms-office365-filtering-ht: Tenant x-ms-office365-filtering-correlation-id: 1964eee4-798d-4dce-25d6-08d85bc3e801 x-ms-traffictypediagnostic: AM6PR0402MB3336: x-ms-exchange-transport-forked: True x-microsoft-antispam-prvs: x-ms-oob-tlc-oobclassifiers: OLM:8882; x-ms-exchange-senderadcheck: 1 x-microsoft-antispam: BCL:0; x-microsoft-antispam-message-info: Wkm6sP7sXNSmOeSHqF7KeC3/DjkTIw1rTZC9srXJ+3xnS4jJ+iS+aoAj6FRwTilLNK8nmHcK3xkC2RM0+9ZD4qDMUFrb052emuZc3ZWDlG4B8GxIAP7Uuv06Wt3AxyKSPD0ZzeC0m3SyzMPver9qfxCQ9cRQBtdaWD7oIuGnQ1FgeqBpSudo8nBAsrshTIhhEzHbd9c+q7I8ZQQxYZirZsLweAGeBbT6RvIJ0mFQSE31Vhyp9kr2fjPHQqlypkvdzVS5szIpymA3RQtzJvFoSNEVrzxMrRdATMYgSOjekcfnP0OIt1lNZPUFE6UQRghf6NZLVL7K1L1vVlSlHRylFdB8jCBM8pDLF79ca6DBLUulIHgVIJIFzKabldh6Q4dx x-forefront-antispam-report: CIP:255.255.255.255; CTRY:; LANG:en; SCL:1; SRV:; IPV:NLI; SFV:NSPM; H:AM6PR04MB5413.eurprd04.prod.outlook.com; PTR:; CAT:NONE; SFS:(4636009)(39860400002)(366004)(396003)(136003)(376002)(346002)(186003)(8676002)(7696005)(6506007)(8936002)(316002)(26005)(55016002)(2906002)(9686003)(478600001)(71200400001)(66446008)(86362001)(5660300002)(33656002)(64756008)(110136005)(52536014)(66556008)(66946007)(83380400001)(76116006)(66476007)(21314003); DIR:OUT; SFP:1101; x-ms-exchange-antispam-messagedata: ddnntR/OcKzhir5pBbqN0hQm2u5zjW+Bnhk/4hr0TkFxux7IVDbHGmWOCQyz0OZFxa255qZsWWouk/GgpVxLNXEPvelTINckJbijOBcF4QJQpGgSxu8iLcb0riB463FvQxBosHfevb63xiaolOFLPKLSJHvJJU+TSmqcSnebSq2ISAvEN5uUs6IMv2m4E+bhl/ntx5KLjJ877Rhk73Ms7y1FNles2Jm/Z2SFn4/gH2ikmXPZu8YNkYN9b3IkOTfPTmB8S3YrPEUSVDcX2FBq58dAScu4j6cxY24GZCQf+yZz167MCiexINwPvr6KkvVG9JYRd2G90OM/NdfBx2XdTEkm1mYSBHtfFzy0PGwD+psit35/fSNpfVrTGyYthWCX6ZKspFdiDmtPaFsr8NOYYwU1XaW9SnC3d2FwDYfRz0BeQZE9NxxtpKx8lvhdbMg1QPqrYjFm7QWxIQkeiEc/c9pHhHv3TIOD19o69DAKGmEgrUJl9ASjtUZ10731tTx2O1bNF8roJARuPqXVN7o750+mIyzz83qkUJNIDgX1g6EH19hPYnvhu7d+KEHweEgELNthgclqlkVH23nMARF3yLmOofh97i8i9rVd+2oV8y25RspFWBtEi4zYfMbJW5oHanY6IyJnpeCD9eqcVFPa/g== MIME-Version: 1.0 X-OriginatorOrg: nxp.com X-MS-Exchange-CrossTenant-AuthAs: Internal X-MS-Exchange-CrossTenant-AuthSource: AM6PR04MB5413.eurprd04.prod.outlook.com X-MS-Exchange-CrossTenant-Network-Message-Id: 1964eee4-798d-4dce-25d6-08d85bc3e801 X-MS-Exchange-CrossTenant-originalarrivaltime: 18 Sep 2020 11:13:44.1355 (UTC) X-MS-Exchange-CrossTenant-fromentityheader: Hosted X-MS-Exchange-CrossTenant-id: 686ea1d3-bc2b-4c6f-a92c-d99c5c301635 X-MS-Exchange-CrossTenant-mailboxtype: HOSTED X-MS-Exchange-CrossTenant-userprincipalname: y6I27qQnom7h9jrLyrufONn0aINc4J2En2+74fC11N4dNO3kqcdui+cLWkM3dMIjeBtA4X2+fOA2tuhrxFYa9Q== X-MS-Exchange-Transport-CrossTenantHeadersStamped: AM6PR0402MB3336 X-BeenThere: u-boot@lists.denx.de X-Mailman-Version: 2.1.34 Precedence: list List-Id: U-Boot discussion List-Unsubscribe: , List-Archive: List-Post: List-Help: List-Subscribe: , Errors-To: u-boot-bounces@lists.denx.de Sender: "U-Boot" X-Virus-Scanned: clamav-milter 0.102.3 at phobos.denx.de X-Virus-Status: Clean Hello, On platform LS1028ARDB, we observed USB3.0/2.0 dongle failed to do tftp data transfer and caused system reset, I have some analysis below but still your input for help: =>usb reset&&setenv ethact r8152_eth&&tftp a0000000 test_data resetting USB... Bus usb3@3100000: Register 200017f NbrPorts 2 Starting the controller USB XHCI 1.00 Bus usb3@3110000: Register 200017f NbrPorts 2 Starting the controller USB XHCI 1.00 scanning bus usb3@3100000 for devices... Warning: r8152_eth MAC addresses don't match: Address in ROM is d4:6e:0e:0c:8d:14 Address in environment is 00:0e:c6:c9:5e:0f 2 USB Device(s) found scanning bus usb3@3110000 for devices... 1 USB Device(s) found scanning usb for storage devices... 0 Storage Device(s) found Waiting for Ethernet connection... done. Using r8152_eth device TFTP from server 10.192.208.233; our IP address is 10.193.21.125 Filename 'test_data'. Load address: 0xa0000000 Loading: BUG at drivers/usb/host/xhci-ring.c:726/xhci_bulk_tx()! BUG! ### ERROR ### Please RESET the board ### Further debugging shows that is due to xhci_blk_tx() miss handling 2nd event TRB in one call, causing in next call (for different EP), it got that missed event TRB and found ep_index mismatched, then hold system. A typical scenario is shown as below (with my debug prints added): dev=00000000fbb4f3c0, pipe=c0010283, buffer=00000000fbb4fd80, length=2048----------------------------buffer would cross 64KB boundary, so we will send request in more than 1 TRB, this is the key issue trigger condition xhci_bulk_tx()#0.1.running_total:0x280 xhci_bulk_tx()#0.2.trb_buff_len:0x280 xhci_bulk_tx()#0.3.running_total:0x280 xhci_bulk_tx()#0.4.num_trbs:0x2--------------------------2 Transfer TRB xhci_bulk_tx()#0.5.running_total:0x10280 xhci_bulk_tx()#0.start_trb:0x00000000fbb47140 ----------xhci_bulk_tx()#0.&ring->enqueue->generic:0x00000000fbb47140----------Assemble 1st Transfer TRB xhci_bulk_tx()#0.addr:0xfbb4fd80 xhci_bulk_tx()#0.trb_buff_len:0x280 xhci_bulk_tx()#0.running_total:0x280 xhci_bulk_tx()#0.length:0x800 xhci_bulk_tx()#0.TRB_MAX_BUFF_SIZE:0x10000 ----------xhci_bulk_tx()#0.&ring->enqueue->generic:0x00000000fbb47150----------Assemble 2nd Transfer TRB xhci_bulk_tx()#0.addr:0xfbb50000 xhci_bulk_tx()#0.trb_buff_len:0x580 xhci_bulk_tx()#0.running_total:0x800 xhci_bulk_tx()#0.length:0x800 xhci_bulk_tx()#0.TRB_MAX_BUFF_SIZE:0x10000 xhci_bulk_tx()#0.event->trans_event.buffer:0x00000000fbb47140----------------handle event TRB for 1st Transfer TRB xhci_bulk_tx()#0.event->trans_event.transfer_len:0xd000180 xhci_bulk_tx()#0.event->trans_event.flags:0x1058001 xhci_bulk_tx()#0.event->len:384 xhci_bulk_tx()#0.event->complete_code:13 xhci_bulk_tx()#1.field:0x1058001 xhci_bulk_tx()#2.TRB_TO_EP_ENDEX(field):0x4 xhci_bulk_tx()#3.ep_index:0x4----------------------------------------------------------xhci_bulk_tx() return dev=00000000fbb4f3c0, pipe=c0018203, buffer=00000000fbb2f9c0, length=110----------an other call comming, and for different EP (ep_index = 05) xhci_bulk_tx()#0.1.running_total:0x640 xhci_bulk_tx()#0.2.trb_buff_len:0x640 xhci_bulk_tx()#0.3.running_total:0x640 xhci_bulk_tx()#0.4.num_trbs:0x1 xhci_bulk_tx()#0.5.running_total:0x640 xhci_bulk_tx()#0.start_trb:0x00000000fbb47610 ----------xhci_bulk_tx()#0.&ring->enqueue->generic:0x00000000fbb47610---------queue 1st transfer TRB xhci_bulk_tx()#0.addr:0xfbb2f9c0 xhci_bulk_tx()#0.trb_buff_len:0x6e xhci_bulk_tx()#0.running_total:0x6e xhci_bulk_tx()#0.length:0x6e xhci_bulk_tx()#0.TRB_MAX_BUFF_SIZE:0x10000 xhci_bulk_tx()#0.event->trans_event.buffer:0x00000000fbb47150------------hand event TRB, note that this buffer is for last Transfer TRB in last call (see above '2nd Transfer TRB') xhci_bulk_tx()#0.event->trans_event.transfer_len:0x1000000 xhci_bulk_tx()#0.event->trans_event.flags:0x1058000 xhci_bulk_tx()#0.event->len:0 xhci_bulk_tx()#0.event->complete_code:1 xhci_bulk_tx()#1.field:0x1058000 xhci_bulk_tx()#2.TRB_TO_EP_ENDEX(field):0x4----------------ep_index is 4 rather than 5, then cause BUG() xhci_bulk_tx()#3.ep_index:0x5------------------------------------- ep_index mis-match wait for event again!!!!!!!!!---------------------------------- BUG at drivers/usb/host/xhci-ring.c:759/xhci_bulk_tx()! BUG! ### ERROR ### Please RESET the board ### Basing on above analysis, I ever tried to remove below code from this function, issue disappear, which prove my assumption: So, any comment? Thanks in advance. Regards, Ran diff --git a/drivers/usb/host/xhci-ring.c b/drivers/usb/host/xhci-ring.c index 092ed6e..28197ef 100644 --- a/drivers/usb/host/xhci-ring.c +++ b/drivers/usb/host/xhci-ring.c @@ -591,14 +591,7 @@ int xhci_bulk_tx(struct usb_device *udev, unsigned long pipe, ep_ctx = xhci_get_ep_ctx(ctrl, virt_dev->out_ctx, ep_index); ring = virt_dev->eps[ep_index].ring; - /* - * How much data is (potentially) left before the 64KB boundary? - * XHCI Spec puts restriction( TABLE 49 and 6.4.1 section of XHCI Spec) - * that the buffer should not span 64KB boundary. if so - * we send request in more than 1 TRB by chaining them. - */ - running_total = TRB_MAX_BUFF_SIZE - - (lower_32_bits(val_64) & (TRB_MAX_BUFF_SIZE - 1)); + running_total = length; trb_buff_len = running_total; running_total &= TRB_MAX_BUFF_SIZE - 1; Besides that, I also ever tried to let xhci_bulk_tx() repeatedly handle multiple EVENT TRB in one call. However, things works for several rounds but end up with event TRB Ring hang finally, reason unknow. - Log: dev=00000000fbb4f3c0, pipe=c0010283, buffer=00000000fbb4fd80, length=2048 xhci_bulk_tx()#0.1.running_total:0x280 xhci_bulk_tx()#0.2.trb_buff_len:0x280 xhci_bulk_tx()#0.3.running_total:0x280 xhci_bulk_tx()#0.4.num_trbs:0x2 xhci_bulk_tx()#0.5.running_total:0x10280 xhci_bulk_tx()#0.start_trb:0x00000000fbb47160 ----------xhci_bulk_tx()#0.&ring->enqueue->generic:0x00000000fbb47160---------------1st Transfer TRB ----------xhci_bulk_tx()#0.&ring->enqueue->generic:0x00000000fbb47170-------------2nd TransferTRB xhci_bulk_tx()#0.num_trbs_count:2 num_trbs_count > 1!!!!!!!!!--------------------------------------Here I add code to handle another event TRB xhci_bulk_tx()#0.num_trbs_count:1 xhci_bulk_tx()#0.event->trans_event.buffer:0x00000000fbb47170----------------------Now we got the final event TRB xhci_bulk_tx()#0.event->trans_event.transfer_len:0x1000000 xhci_bulk_tx()#0.event->trans_event.flags:0x1058000 xhci_bulk_tx()#0.event->len:0 xhci_bulk_tx()#0.event->complete_code:1 xhci_bulk_tx()#1.field:0x1058000 xhci_bulk_tx()#2.TRB_TO_EP_ENDEX(field):0x4 xhci_bulk_tx()#3.ep_index:0x4 xhci_bulk_tx()#4.ret:0-------------------------------------Return success ...----------------------------------------------------------------This success can last for several round call for the same EP dev=00000000fbb4f3c0, pipe=c0010283, buffer=00000000fbb4fd80, length=2048--------------The last call when event Ring hang xhci_bulk_tx()#0.1.running_total:0x280 xhci_bulk_tx()#0.2.trb_buff_len:0x280 xhci_bulk_tx()#0.3.running_total:0x280 xhci_bulk_tx()#0.4.num_trbs:0x2 xhci_bulk_tx()#0.5.running_total:0x10280 xhci_bulk_tx()#0.start_trb:0x00000000fbb47180 ----------xhci_bulk_tx()#0.&ring->enqueue->generic:0x00000000fbb47180 xhci_bulk_tx()#0.addr:0xfbb4fd80 xhci_bulk_tx()#0.trb_buff_len:0x280 xhci_bulk_tx()#0.running_total:0x280 xhci_bulk_tx()#0.length:0x800 xhci_bulk_tx()#0.TRB_MAX_BUFF_SIZE:0x10000 ----------xhci_bulk_tx()#0.&ring->enqueue->generic:0x00000000fbb47190 xhci_bulk_tx()#0.addr:0xfbb50000 xhci_bulk_tx()#0.trb_buff_len:0x580 xhci_bulk_tx()#0.running_total:0x800 xhci_bulk_tx()#0.length:0x800 xhci_bulk_tx()#0.TRB_MAX_BUFF_SIZE:0x10000 xhci_bulk_tx()#0.num_trbs_count:2 num_trbs_count > 1!!!!!!!!! XHCI bulk transfer timed out, aborting.................................. Rx: failed to receive: -5 T - Related hacking: diff --git a/drivers/usb/host/xhci-ring.c b/drivers/usb/host/xhci-ring.c index 092ed6e..0b4da26 100644 --- a/drivers/usb/host/xhci-ring.c +++ b/drivers/usb/host/xhci-ring.c @@ -558,6 +558,7 @@ int xhci_bulk_tx(struct usb_device *udev, unsigned long pipe, int length, void *buffer) { int num_trbs = 0; + int num_trbs_count = 0; struct xhci_generic_trb *start_trb; bool first_trb = false; int start_cycle; @@ -614,6 +615,7 @@ int xhci_bulk_tx(struct usb_device *udev, unsigned long pipe, num_trbs++; running_total += TRB_MAX_BUFF_SIZE; } + num_trbs_count = num_trbs; /* * XXX: Calling routine prepare_ring() called in place of @@ -713,7 +715,7 @@ int xhci_bulk_tx(struct usb_device *udev, unsigned long pipe, } while (running_total < length); giveback_first_trb(udev, ep_index, start_cycle, start_trb); - +again: event = xhci_wait_for_event(ctrl, TRB_TRANSFER); if (!event) { debug("XHCI bulk transfer timed out, aborting...\n"); @@ -722,6 +724,12 @@ int xhci_bulk_tx(struct usb_device *udev, unsigned long pipe, udev->act_len = 0; return -ETIMEDOUT; } + if(num_trbs_count-- > 1) { + printf("num_trbs_count > 1!!!!!!!!!\n"); + xhci_acknowledge_event(ctrl); + goto again; + } + field = le32_to_cpu(event->trans_event.flags); BUG_ON(TRB_TO_SLOT_ID(field) != slot_id);