Received-SPF: pass (google.com: best guess record for domain of linux-kernel-owner@vger.kernel.org designates 209.132.180.67 as permitted sender) client-ip=209.132.180.67;
Date:   Fri, 9 Nov 2018 18:42:46 +0000
From:   John Keeping <john@metanate.com>
To:     Minas Harutyunyan <minas.harutyunyan@synopsys.com>
Cc:     Greg Kroah-Hartman <gregkh@linuxfoundation.org>,
        "linux-usb@vger.kernel.org" <linux-usb@vger.kernel.org>,
        "linux-kernel@vger.kernel.org" <linux-kernel@vger.kernel.org>,
        "arthur.petrosyan@synopsys.com" <arthur.petrosyan@synopsys.com>
Subject: Re: [PATCH] usb: dwc2: gadget: fix ISOC frame overflow handling
Message-ID: <20181109184246.33cb4487@donbot>
In-Reply-To: <410670D7E743164D87FA6160E7907A56013A7A12C1@am04wembxa.internal.synopsys.com>
References: <20181023134355.29829-1-john@metanate.com>
        <410670D7E743164D87FA6160E7907A56013A79E7CE@am04wembxa.internal.synopsys.com>
        <20181108173654.118f9e3e@donbot>
        <410670D7E743164D87FA6160E7907A56013A7A0F2B@am04wembxa.internal.synopsys.com>
        <410670D7E743164D87FA6160E7907A56013A7A12C1@am04wembxa.internal.synopsys.com>
MIME-Version: 1.0
Content-Type: text/plain; charset=US-ASCII
Content-Transfer-Encoding: 7bit
Sender: linux-kernel-owner@vger.kernel.org
Precedence: bulk

Hi Minas,

On Fri, 9 Nov 2018 14:36:36 +0000
Minas Harutyunyan <minas.harutyunyan@synopsys.com> wrote:

> On 11/9/2018 12:43 PM, Minas Harutyunyan wrote:
> > Hi John,
> > 
> > On 11/8/2018 9:37 PM, John Keeping wrote:
> >> Hi Minas,
> >>
> >> On Mon, 5 Nov 2018 08:28:07 +0000
> >> Minas Harutyunyan <minas.harutyunyan@synopsys.com> wrote:
> >>
> >>> On 10/23/2018 5:43 PM, John Keeping wrote:
> >>>> By clearing the overrun flag as soon as the target frame is next
> >>>> incremented, we can end up incrementing the target frame more
> >>>> than expected in dwc2_gadget_handle_ep_disabled() when the
> >>>> endpoint's interval is greater than 1.  This happens if the
> >>>> target frame has just wrapped at the point when the endpoint is
> >>>> disabled and the frame number has not yet done so.
> >>>>
> >>>> Instead, wait until the frame number also wraps and then clear
> >>>> the overrun flag.
> >>>>
> >>>> Signed-off-by: John Keeping <john@metanate.com>
> >>>> ---
> >>>>     drivers/usb/dwc2/gadget.c | 2 +-
> >>>>     1 file changed, 1 insertion(+), 1 deletion(-)
> >>>>
> >>>> diff --git a/drivers/usb/dwc2/gadget.c
> >>>> b/drivers/usb/dwc2/gadget.c index 2d6d2c8244de..8da2c052dfa1
> >>>> 100644 --- a/drivers/usb/dwc2/gadget.c
> >>>> +++ b/drivers/usb/dwc2/gadget.c
> >>>> @@ -117,7 +117,7 @@ static inline void
> >>>> dwc2_gadget_incr_frame_num(struct dwc2_hsotg_ep *hs_ep) if
> >>>> (hs_ep->target_frame > DSTS_SOFFN_LIMIT) { hs_ep->frame_overrun =
> >>>> true; hs_ep->target_frame &= DSTS_SOFFN_LIMIT;
> >>>> -	} else {
> >>>> +	} else if (hs_ep->parent->frame_number <
> >>>> hs_ep->target_frame) { hs_ep->frame_overrun = false;
> >>>>     	}
> >>>>     }
> >>>>     
> >>> Did you tested mentioned by you scenario? If you see issue can you
> >>> provide debug log and point the issue line in the log.
> >>
> >> It only reproduces very occasionally so it's difficult to capture
> >> a full debug log containing the error.
> >>
> >> I applied this patch to capture logging specifically around this
> >> scenario:
> >>
> >> -- >8 --
> >> diff --git a/drivers/usb/dwc2/gadget.c b/drivers/usb/dwc2/gadget.c
> >> index 220c0f9b89b0..3770b9d3b523 100644
> >> --- a/drivers/usb/dwc2/gadget.c
> >> +++ b/drivers/usb/dwc2/gadget.c
> >> @@ -2722,13 +2722,20 @@ static void
> >> dwc2_gadget_handle_ep_disabled(struct dwc2_hsotg_ep *hs_ep) }
> >>    
> >>           do {
> >> +               unsigned int target_frame = hs_ep->target_frame;
> >> +               bool frame_overrun = hs_ep->frame_overrun;
> >> +
> >>                   hs_req = get_ep_head(hs_ep);
> >>                   if (hs_req)
> >>                           dwc2_hsotg_complete_request(hsotg,
> >> hs_ep, hs_req, -ENODATA);
> >> +
> >>                   dwc2_gadget_incr_frame_num(hs_ep);
> >>                   /* Update current frame number value. */
> >>                   hsotg->frame_number =
> >> dwc2_hsotg_read_frameno(hsotg); +
> >> +               dev_warn(hsotg->dev, "%s: expiring request
> >> frame_number=0x%04x target_frame=0x%04x overrun=%u\n",
> >> +                        __func__, hsotg->frame_number,
> >> target_frame, frame_overrun); } while
> >> (dwc2_gadget_target_frame_elapsed(hs_ep)); 
> >>           dwc2_gadget_start_next_request(hs_ep);
> >> -- 8< --
> >>
> > According above patch in debug log should be printed overrun flag
> > also. Could you please resend log with this flag.

D'oh!  I included a log from an earlier version before I added the
overrun flag.

> One more request. Please add EP number to debug print.

Here's an updated log:

-- >8 --
[  264.926385] dwc2 ff580000.usb: dwc2_gadget_handle_ep_disabled: expiring request ep=2 frame_number=0x2161 target_frame=0x2168 overrun=0
[  265.905413] dwc2 ff580000.usb: dwc2_gadget_handle_ep_disabled: expiring request ep=2 frame_number=0x3ff9 target_frame=0x0008 overrun=0
[  265.905421] dwc2 ff580000.usb: dwc2_gadget_handle_ep_disabled: expiring request ep=2 frame_number=0x3ff9 target_frame=0x0010 overrun=0
[  265.905427] dwc2 ff580000.usb: dwc2_gadget_handle_ep_disabled: expiring request ep=2 frame_number=0x3ff9 target_frame=0x0018 overrun=0
[  265.905432] dwc2 ff580000.usb: dwc2_gadget_handle_ep_disabled: expiring request ep=2 frame_number=0x3ff9 target_frame=0x0020 overrun=0
[  265.905438] dwc2 ff580000.usb: dwc2_gadget_handle_ep_disabled: expiring request ep=2 frame_number=0x3ff9 target_frame=0x0028 overrun=0
[  265.905443] dwc2 ff580000.usb: dwc2_gadget_handle_ep_disabled: expiring request ep=2 frame_number=0x3ff9 target_frame=0x0030 overrun=0
[  265.905448] dwc2 ff580000.usb: dwc2_gadget_handle_ep_disabled: expiring request ep=2 frame_number=0x3ff9 target_frame=0x0038 overrun=0
[  265.905454] dwc2 ff580000.usb: dwc2_gadget_handle_ep_disabled: expiring request ep=2 frame_number=0x3ff9 target_frame=0x0040 overrun=0
[  265.905459] dwc2 ff580000.usb: dwc2_gadget_handle_ep_disabled: expiring request ep=2 frame_number=0x3ff9 target_frame=0x0048 overrun=0
-- 8< --

Once again there is an initial failure before it enters the failure mode
my patch is trying to address.  This seems to be consistent, so it may
be important, but there is ~80ms before the failure starts.

> >> This was on v4.19 with an additional patch to disable descriptor
> >> DMA because that seems to be causing problems on RK3288 although I
> >> haven't figured out exactly why it's a problem.
> > 
> > In which mode you run tests Slave or Buffer DMA?

Buffer DMA but with descriptor DMA forced off (g_dma=1, g_dma_desc=0).

For the record, my test case is the standard UAC2 gadget with:

	c_srate = p_srate = 44100
	c_ssize = p_ssize = 4
	c_chmask = 0xf
	p_chmask = 3

and it seems that the failure only triggers when using arecord to
capture from the gadget interface (this is with a host program both
streaming in both directions over the USB connection); I suspect that
actually it just makes it more likely because there is more work done in
the completion handler, but I haven't seen the failure without arecord
running.


Regards,
John