Return-Path: Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand id S1755493AbcK2DkT (ORCPT ); Mon, 28 Nov 2016 22:40:19 -0500 Received: from fllnx210.ext.ti.com ([198.47.19.17]:39359 "EHLO fllnx210.ext.ti.com" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP id S1752592AbcK2DkK (ORCPT ); Mon, 28 Nov 2016 22:40:10 -0500 Date: Mon, 28 Nov 2016 21:39:30 -0600 From: Bin Liu To: Max Uvarov CC: , , Subject: Re: [PATCH] b: re-queue tx dma request on herror Message-ID: <20161129033930.GA19342@uda0271908> Mail-Followup-To: Bin Liu , Max Uvarov , linux-kernel@vger.kernel.org, linux-usb@vger.kernel.org, gregkh@linuxfoundation.org References: <1479282123-14316-1-git-send-email-muvarov@gmail.com> MIME-Version: 1.0 Content-Type: text/plain; charset="us-ascii" Content-Disposition: inline In-Reply-To: <1479282123-14316-1-git-send-email-muvarov@gmail.com> User-Agent: Mutt/1.5.21 (2010-09-15) Sender: linux-kernel-owner@vger.kernel.org List-ID: X-Mailing-List: linux-kernel@vger.kernel.org Content-Length: 4664 Lines: 112 Hi, On Wed, Nov 16, 2016 at 10:42:03AM +0300, Max Uvarov wrote: > Some times dma transfer to usb endpoint fails: > > [ 78.378283] musb-hdrc musb-hdrc.1.auto: Start TX10 dma > [ 78.410763] musb-hdrc musb-hdrc.1.auto: OUT/TX10 end, csr 3400, dma > [ 78.410896] musb-hdrc musb-hdrc.1.auto: complete dc01eb00 usb_api_blocking_completion+0x0/0x24 [usbcore] (0), dev4 ep1out, 10/10 > [ 78.411181] musb-hdrc musb-hdrc.1.auto: qh dc01ed00 periodic slot 10 > [ 78.411205] musb-hdrc musb-hdrc.1.auto: qh dc01ed00 urb dc01eb00 dev4 ep1out-intr, hw_ep 10, dd624d00/10 > [ 78.411223] musb-hdrc musb-hdrc.1.auto: --> hw10 urb dc01eb00 spd2 dev4 ep1out h_addr83 h_port02 bytes 10 > [ 78.411244] musb-hdrc musb-hdrc.1.auto: check whether there's still time for periodic Tx > [ 78.411256] musb-hdrc musb-hdrc.1.auto: Start TX10 dma > [ 78.443762] musb-hdrc musb-hdrc.1.auto: OUT/TX10 end, csr 3500, dma What kernel version is this? Log format looks old. > success transmition: > > [ 78.443889] musb-hdrc musb-hdrc.1.auto: complete dc01eb00 usb_api_blocking_completion+0x0/0x24 [usbcore] (0), dev4 ep1out, 10/10 > [ 78.444170] musb-hdrc musb-hdrc.1.auto: qh dc01ed00 periodic slot 10 > [ 78.444195] musb-hdrc musb-hdrc.1.auto: qh dc01ed00 urb dc01eb00 dev4 ep1out-intr, hw_ep 10, dd624d00/10 > [ 78.444213] musb-hdrc musb-hdrc.1.auto: --> hw10 urb dc01eb00 spd2 dev4 ep1out h_addr83 h_port02 bytes 10 > [ 78.444232] musb-hdrc musb-hdrc.1.auto: check whether there's still time for periodic Tx > [ 78.444245] musb-hdrc musb-hdrc.1.auto: Start TX10 dma > [ 78.540761] musb-hdrc musb-hdrc.1.auto: OUT/TX10 end, csr 3504, dma > > failed transmission: > > [ 78.540780] musb-hdrc musb-hdrc.1.auto: TX 3strikes on ep=10 set ETIMEDOUT > [ 78.540897] musb-hdrc musb-hdrc.1.auto: complete dc01eb00 usb_api_blocking_completion+0x0/0x24 [usbcore] (-110), dev4 ep1out, 10/10 > [ 78.540945] musb-hdrc musb-hdrc.1.auto: extra TX10 ready, csr 2500 > [ 78.540989] usb 2-1.1.2: urb wait ok but retval -110 > > Use to reproduce is writes to /dev/hidraw0 device which end up with early > unexpected timeout and -110 errno set. > > Code sets timeout to 5 seconds > vfs_write()->hidraw_write()->hidraw_send_report()->usbhid_output_report() > ret = usb_interrupt_msg(dev, usbhid->urbout->pipe, > buf, count, &actual_length, > USB_CTRL_SET_TIMEOUT); > where is set to 5 second: The two timeout here are completely different - ETIMEOUT on 3strikes vs. USB_CTRL_SET_TIMEOUT. USB_CTRL_SET_TIMEOUT only takes effects when the usb device NAK the interrupt transaction for 5 seconds. But when MUSB reports 3strikes ETIMEOUT, it means the usb device doesn't respond, no handshake packet at all. The host tried TX 3 times, all received no response handshake, so ETIMEOUT. > when it wents to usb_start_wait_urb() where waits for completition: > retval = usb_submit_urb(urb, GFP_NOIO); > > expire = timeout ? msecs_to_jiffies(timeout) : MAX_SCHEDULE_TIMEOUT; > if (!wait_for_completion_timeout(&ctx.done, expire)) { > > So user space application expects that write will be done in 5 seconds or > error will happen. But musb driver exists this logic on first dma error This ETIMEOUT is not a dma error, but something wrong on the wire which causes the usb device is unable to respond, typically not received the TX packet at all. > without trying to retransmit current urb. This patch adds current request The host does trying to retransmit the TX packet 3 times, before reports ETIMEOUT. > to the end of list, destroys current dma transfer and renew transmission. > In that case this urb transmitted in next cycle and not failing with error > before timeout. NAK. It is up to the application to retry the transaction, Regards, -Bin. > > Signed-off-by: Max Uvarov > --- > drivers/usb/musb/musb_host.c | 8 ++++---- > 1 file changed, 4 insertions(+), 4 deletions(-) > > diff --git a/drivers/usb/musb/musb_host.c b/drivers/usb/musb/musb_host.c > index 53bc4ce..e44ae95 100644 > --- a/drivers/usb/musb/musb_host.c > +++ b/drivers/usb/musb/musb_host.c > @@ -1293,11 +1293,11 @@ void musb_host_tx(struct musb *musb, u8 epnum) > status = -EPIPE; > > } else if (tx_csr & MUSB_TXCSR_H_ERROR) { > - /* (NON-ISO) dma was disabled, fifo flushed */ > musb_dbg(musb, "TX 3strikes on ep=%d", epnum); > - > - status = -ETIMEDOUT; > - > + if (dma) > + musb_bulk_nak_timeout(musb, hw_ep, 0); > + else > + status = -ETIMEDOUT; > } else if (tx_csr & MUSB_TXCSR_H_NAKTIMEOUT) { > if (USB_ENDPOINT_XFER_BULK == qh->type && qh->mux == 1 > && !list_is_singular(&musb->out_bulk)) { > -- > 1.9.1 >