Message-ID: <410670D7E743164D87FA6160E7907A56013A7BAB28@am04wembxa.internal.synopsys.com>
Date:   Fri, 14 Dec 2018 09:00:08 +0000
From:   Minas Harutyunyan <minas.harutyunyan@...opsys.com>
To:     John Keeping <john@...anate.com>,
        Minas Harutyunyan <minas.harutyunyan@...opsys.com>
CC:     Greg Kroah-Hartman <gregkh@...uxfoundation.org>,
        "linux-usb@...r.kernel.org" <linux-usb@...r.kernel.org>,
        "linux-kernel@...r.kernel.org" <linux-kernel@...r.kernel.org>,
        "arthur.petrosyan@...opsys.com" <arthur.petrosyan@...opsys.com>
Subject: Re: [PATCH] usb: dwc2: gadget: fix ISOC frame overflow handling

Hi John,

On 11/13/2018 2:46 AM, John Keeping wrote:
> Hi Minas,
> 
> On Mon, 12 Nov 2018 08:53:36 +0000
> Minas Harutyunyan <minas.harutyunyan@...opsys.com> wrote:
>> On 11/9/2018 10:43 PM, John Keeping wrote:
>>> On Fri, 9 Nov 2018 14:36:36 +0000
>>> Minas Harutyunyan <minas.harutyunyan@...opsys.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@...opsys.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@...anate.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
>>>    
>> I think cause of issue not in dwc2_gadget_target_frame_elapsed()
>> function, but in do-while loop in dwc2_gadget_handle_ep_disabled().
>> Could you please try below patch:
>>
>> diff --git a/drivers/usb/dwc2/gadget.c b/drivers/usb/dwc2/gadget.c
>> index 8eb25e3597b0..4ad869853bfa 100644
>> --- a/drivers/usb/dwc2/gadget.c
>> +++ b/drivers/usb/dwc2/gadget.c
>> @@ -2762,8 +2762,11 @@ static void
>> dwc2_gadget_handle_ep_disabled(struct dwc2_hsotg_ep *hs_ep)
>>
>>           do {
>>                   hs_req = get_ep_head(hs_ep);
>> -               if (hs_req)
>> -                       dwc2_hsotg_complete_request(hsotg, hs_ep,
>> hs_req,
>> +               if (!hs_req) {
>> +                       dev_warn(hsotg->dev, "%s: ISOC EP queue
>> empty\n", __func__);
>> +                       return;
>> +               }
>> +               dwc2_hsotg_complete_request(hsotg, hs_ep, hs_req,
>>                                                       -ENODATA);
>>                   dwc2_gadget_incr_frame_num(hs_ep);
>>                   /* Update current frame number value. */
> 
> I don't see any difference after applying this patch, and the new
> dev_warn message does not appear.
> 
> I think what happens is that dwc2_hsotg_complete_request() completes the
> outstanding request and the completion handler (in this case
> u_audio_iso_complete) enqueues a new request, so the queue is never
> empty.

First of all, sorry for delayed answer.
Looks like similar issue seen by Andrzej Pietrasiewicz 
<andrzej.p@...sung.com>: "dwc2 isochronous transfers issues". Same 
feedback provided to Andrzej.

I run tests on 4.20.0-rc4 in DDMA. By default IN ISOC traffic failed 
because of BNA interrupts. It's happen because UAC2 requests count set 
by default to 2. Our core and driver can't work in DDMA with descriptor 
list length equal to 2. It's not possible on time prepare next 
descriptors to avoid BNA interrupt.

By changing UAC2_DEF_REQ_NUM to 4 all audio gadget tests passed smoothly.
Could you please apply this patch and run tests in DDMA mode:

diff --git a/drivers/usb/gadget/function/u_uac2.h 
b/drivers/usb/gadget/function/u_uac2.h
index 8362ee572e1e..5e649259ab76 100644
--- a/drivers/usb/gadget/function/u_uac2.h
+++ b/drivers/usb/gadget/function/u_uac2.h
@@ -21,7 +21,7 @@
  #define UAC2_DEF_CCHMASK 0x3
  #define UAC2_DEF_CSRATE 64000
  #define UAC2_DEF_CSSIZE 2
-#define UAC2_DEF_REQ_NUM 2
+#define UAC2_DEF_REQ_NUM 4

  struct f_uac2_opts {
         struct usb_function_instance    func_inst;


If it will OK on your side also then will switch to BDMA mode and debug.

Thanks,
Minas
> 
> 
> Regards,
> John
> 

Powered by blists - more mailing lists