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;
From:   Minas Harutyunyan <minas.harutyunyan@synopsys.com>
To:     John Keeping <john@metanate.com>,
        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
Thread-Topic: [PATCH] usb: dwc2: gadget: fix ISOC frame overflow handling
Thread-Index: AQHUatZW7CBOg1jSlEOevZqXY6bG3Q==
Date:   Fri, 14 Dec 2018 09:00:08 +0000
Message-ID: <410670D7E743164D87FA6160E7907A56013A7BAB28@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>
 <20181109184246.33cb4487@donbot>
 <410670D7E743164D87FA6160E7907A56013A7A27D7@am04wembxa.internal.synopsys.com>
 <20181112224626.6b44568a@donbot>
Accept-Language: en-US
Content-Language: en-US
Content-Type: text/plain; charset="us-ascii"
Content-Transfer-Encoding: quoted-printable
MIME-Version: 1.0
Sender: linux-kernel-owner@vger.kernel.org
Precedence: bulk

Hi John,=0A=
=0A=
On 11/13/2018 2:46 AM, John Keeping wrote:=0A=
> Hi Minas,=0A=
> =0A=
> On Mon, 12 Nov 2018 08:53:36 +0000=0A=
> Minas Harutyunyan <minas.harutyunyan@synopsys.com> wrote:=0A=
>> On 11/9/2018 10:43 PM, John Keeping wrote:=0A=
>>> On Fri, 9 Nov 2018 14:36:36 +0000=0A=
>>> Minas Harutyunyan <minas.harutyunyan@synopsys.com> wrote:=0A=
>>>    =0A=
>>>> On 11/9/2018 12:43 PM, Minas Harutyunyan wrote:=0A=
>>>>> Hi John,=0A=
>>>>>=0A=
>>>>> On 11/8/2018 9:37 PM, John Keeping wrote:=0A=
>>>>>> Hi Minas,=0A=
>>>>>>=0A=
>>>>>> On Mon, 5 Nov 2018 08:28:07 +0000=0A=
>>>>>> Minas Harutyunyan <minas.harutyunyan@synopsys.com> wrote:=0A=
>>>>>>   =0A=
>>>>>>> On 10/23/2018 5:43 PM, John Keeping wrote:=0A=
>>>>>>>> By clearing the overrun flag as soon as the target frame is=0A=
>>>>>>>> next incremented, we can end up incrementing the target frame=0A=
>>>>>>>> more than expected in dwc2_gadget_handle_ep_disabled() when the=0A=
>>>>>>>> endpoint's interval is greater than 1.  This happens if the=0A=
>>>>>>>> target frame has just wrapped at the point when the endpoint is=0A=
>>>>>>>> disabled and the frame number has not yet done so.=0A=
>>>>>>>>=0A=
>>>>>>>> Instead, wait until the frame number also wraps and then clear=0A=
>>>>>>>> the overrun flag.=0A=
>>>>>>>>=0A=
>>>>>>>> Signed-off-by: John Keeping <john@metanate.com>=0A=
>>>>>>>> ---=0A=
>>>>>>>>       drivers/usb/dwc2/gadget.c | 2 +-=0A=
>>>>>>>>       1 file changed, 1 insertion(+), 1 deletion(-)=0A=
>>>>>>>>=0A=
>>>>>>>> diff --git a/drivers/usb/dwc2/gadget.c=0A=
>>>>>>>> b/drivers/usb/dwc2/gadget.c index 2d6d2c8244de..8da2c052dfa1=0A=
>>>>>>>> 100644 --- a/drivers/usb/dwc2/gadget.c=0A=
>>>>>>>> +++ b/drivers/usb/dwc2/gadget.c=0A=
>>>>>>>> @@ -117,7 +117,7 @@ static inline void=0A=
>>>>>>>> dwc2_gadget_incr_frame_num(struct dwc2_hsotg_ep *hs_ep) if=0A=
>>>>>>>> (hs_ep->target_frame > DSTS_SOFFN_LIMIT)=0A=
>>>>>>>> { hs_ep->frame_overrun =3D true; hs_ep->target_frame &=3D=0A=
>>>>>>>> DSTS_SOFFN_LIMIT;=0A=
>>>>>>>> -	} else {=0A=
>>>>>>>> +	} else if (hs_ep->parent->frame_number <=0A=
>>>>>>>> hs_ep->target_frame) { hs_ep->frame_overrun =3D false;=0A=
>>>>>>>>       	}=0A=
>>>>>>>>       }=0A=
>>>>>>>>         =0A=
>>>>>>> Did you tested mentioned by you scenario? If you see issue can=0A=
>>>>>>> you provide debug log and point the issue line in the log.=0A=
>>>>>>=0A=
>>>>>> It only reproduces very occasionally so it's difficult to capture=0A=
>>>>>> a full debug log containing the error.=0A=
>>>>>>=0A=
>>>>>> I applied this patch to capture logging specifically around this=0A=
>>>>>> scenario:=0A=
>>>>>>   =0A=
>>>>>> -- >8 --=0A=
>>>>>> diff --git a/drivers/usb/dwc2/gadget.c=0A=
>>>>>> b/drivers/usb/dwc2/gadget.c index 220c0f9b89b0..3770b9d3b523=0A=
>>>>>> 100644 --- a/drivers/usb/dwc2/gadget.c=0A=
>>>>>> +++ b/drivers/usb/dwc2/gadget.c=0A=
>>>>>> @@ -2722,13 +2722,20 @@ static void=0A=
>>>>>> dwc2_gadget_handle_ep_disabled(struct dwc2_hsotg_ep *hs_ep) }=0A=
>>>>>>      =0A=
>>>>>>             do {=0A=
>>>>>> +               unsigned int target_frame =3D hs_ep->target_frame;=
=0A=
>>>>>> +               bool frame_overrun =3D hs_ep->frame_overrun;=0A=
>>>>>> +=0A=
>>>>>>                     hs_req =3D get_ep_head(hs_ep);=0A=
>>>>>>                     if (hs_req)=0A=
>>>>>>                             dwc2_hsotg_complete_request(hsotg,=0A=
>>>>>> hs_ep, hs_req, -ENODATA);=0A=
>>>>>> +=0A=
>>>>>>                     dwc2_gadget_incr_frame_num(hs_ep);=0A=
>>>>>>                     /* Update current frame number value. */=0A=
>>>>>>                     hsotg->frame_number =3D=0A=
>>>>>> dwc2_hsotg_read_frameno(hsotg); +=0A=
>>>>>> +               dev_warn(hsotg->dev, "%s: expiring request=0A=
>>>>>> frame_number=3D0x%04x target_frame=3D0x%04x overrun=3D%u\n",=0A=
>>>>>> +                        __func__, hsotg->frame_number,=0A=
>>>>>> target_frame, frame_overrun); } while=0A=
>>>>>> (dwc2_gadget_target_frame_elapsed(hs_ep));=0A=
>>>>>>             dwc2_gadget_start_next_request(hs_ep);=0A=
>>>>>> -- 8< --=0A=
>>>>>>   =0A=
>>>>> According above patch in debug log should be printed overrun flag=0A=
>>>>> also. Could you please resend log with this flag.=0A=
>>>=0A=
>>> D'oh!  I included a log from an earlier version before I added the=0A=
>>> overrun flag.=0A=
>>>    =0A=
>>>> One more request. Please add EP number to debug print.=0A=
>>>=0A=
>>> Here's an updated log:=0A=
>>>    =0A=
>>> -- >8 --=0A=
>>> [  264.926385] dwc2 ff580000.usb: dwc2_gadget_handle_ep_disabled:=0A=
>>> expiring request ep=3D2 frame_number=3D0x2161 target_frame=3D0x2168=0A=
>>> overrun=3D0 [  265.905413] dwc2 ff580000.usb:=0A=
>>> dwc2_gadget_handle_ep_disabled: expiring request ep=3D2=0A=
>>> frame_number=3D0x3ff9 target_frame=3D0x0008 overrun=3D0 [  265.905421]=
=0A=
>>> dwc2 ff580000.usb: dwc2_gadget_handle_ep_disabled: expiring request=0A=
>>> ep=3D2 frame_number=3D0x3ff9 target_frame=3D0x0010 overrun=3D0=0A=
>>> [  265.905427] dwc2 ff580000.usb: dwc2_gadget_handle_ep_disabled:=0A=
>>> expiring request ep=3D2 frame_number=3D0x3ff9 target_frame=3D0x0018=0A=
>>> overrun=3D0 [  265.905432] dwc2 ff580000.usb:=0A=
>>> dwc2_gadget_handle_ep_disabled: expiring request ep=3D2=0A=
>>> frame_number=3D0x3ff9 target_frame=3D0x0020 overrun=3D0 [  265.905438]=
=0A=
>>> dwc2 ff580000.usb: dwc2_gadget_handle_ep_disabled: expiring request=0A=
>>> ep=3D2 frame_number=3D0x3ff9 target_frame=3D0x0028 overrun=3D0=0A=
>>> [  265.905443] dwc2 ff580000.usb: dwc2_gadget_handle_ep_disabled:=0A=
>>> expiring request ep=3D2 frame_number=3D0x3ff9 target_frame=3D0x0030=0A=
>>> overrun=3D0 [  265.905448] dwc2 ff580000.usb:=0A=
>>> dwc2_gadget_handle_ep_disabled: expiring request ep=3D2=0A=
>>> frame_number=3D0x3ff9 target_frame=3D0x0038 overrun=3D0 [  265.905454]=
=0A=
>>> dwc2 ff580000.usb: dwc2_gadget_handle_ep_disabled: expiring request=0A=
>>> ep=3D2 frame_number=3D0x3ff9 target_frame=3D0x0040 overrun=3D0=0A=
>>> [  265.905459] dwc2 ff580000.usb: dwc2_gadget_handle_ep_disabled:=0A=
>>> expiring request ep=3D2 frame_number=3D0x3ff9 target_frame=3D0x0048=0A=
>>> overrun=3D0 -- 8< --=0A=
>>>=0A=
>>> Once again there is an initial failure before it enters the failure=0A=
>>> mode my patch is trying to address.  This seems to be consistent,=0A=
>>> so it may be important, but there is ~80ms before the failure=0A=
>>> starts.=0A=
>>>>>> This was on v4.19 with an additional patch to disable descriptor=0A=
>>>>>> DMA because that seems to be causing problems on RK3288 although=0A=
>>>>>> I haven't figured out exactly why it's a problem.=0A=
>>>>>=0A=
>>>>> In which mode you run tests Slave or Buffer DMA?=0A=
>>>=0A=
>>> Buffer DMA but with descriptor DMA forced off (g_dma=3D1,=0A=
>>> g_dma_desc=3D0).=0A=
>>>=0A=
>>> For the record, my test case is the standard UAC2 gadget with:=0A=
>>>=0A=
>>> 	c_srate =3D p_srate =3D 44100=0A=
>>> 	c_ssize =3D p_ssize =3D 4=0A=
>>> 	c_chmask =3D 0xf=0A=
>>> 	p_chmask =3D 3=0A=
>>>=0A=
>>> and it seems that the failure only triggers when using arecord to=0A=
>>> capture from the gadget interface (this is with a host program both=0A=
>>> streaming in both directions over the USB connection); I suspect=0A=
>>> that actually it just makes it more likely because there is more=0A=
>>> work done in the completion handler, but I haven't seen the failure=0A=
>>> without arecord running.=0A=
>>>=0A=
>>>=0A=
>>> Regards,=0A=
>>> John=0A=
>>>    =0A=
>> I think cause of issue not in dwc2_gadget_target_frame_elapsed()=0A=
>> function, but in do-while loop in dwc2_gadget_handle_ep_disabled().=0A=
>> Could you please try below patch:=0A=
>>=0A=
>> diff --git a/drivers/usb/dwc2/gadget.c b/drivers/usb/dwc2/gadget.c=0A=
>> index 8eb25e3597b0..4ad869853bfa 100644=0A=
>> --- a/drivers/usb/dwc2/gadget.c=0A=
>> +++ b/drivers/usb/dwc2/gadget.c=0A=
>> @@ -2762,8 +2762,11 @@ static void=0A=
>> dwc2_gadget_handle_ep_disabled(struct dwc2_hsotg_ep *hs_ep)=0A=
>>=0A=
>>           do {=0A=
>>                   hs_req =3D get_ep_head(hs_ep);=0A=
>> -               if (hs_req)=0A=
>> -                       dwc2_hsotg_complete_request(hsotg, hs_ep,=0A=
>> hs_req,=0A=
>> +               if (!hs_req) {=0A=
>> +                       dev_warn(hsotg->dev, "%s: ISOC EP queue=0A=
>> empty\n", __func__);=0A=
>> +                       return;=0A=
>> +               }=0A=
>> +               dwc2_hsotg_complete_request(hsotg, hs_ep, hs_req,=0A=
>>                                                       -ENODATA);=0A=
>>                   dwc2_gadget_incr_frame_num(hs_ep);=0A=
>>                   /* Update current frame number value. */=0A=
> =0A=
> I don't see any difference after applying this patch, and the new=0A=
> dev_warn message does not appear.=0A=
> =0A=
> I think what happens is that dwc2_hsotg_complete_request() completes the=
=0A=
> outstanding request and the completion handler (in this case=0A=
> u_audio_iso_complete) enqueues a new request, so the queue is never=0A=
> empty.=0A=
=0A=
First of all, sorry for delayed answer.=0A=
Looks like similar issue seen by Andrzej Pietrasiewicz =0A=
<andrzej.p@samsung.com>: "dwc2 isochronous transfers issues". Same =0A=
feedback provided to Andrzej.=0A=
=0A=
I run tests on 4.20.0-rc4 in DDMA. By default IN ISOC traffic failed =0A=
because of BNA interrupts. It's happen because UAC2 requests count set =0A=
by default to 2. Our core and driver can't work in DDMA with descriptor =0A=
list length equal to 2. It's not possible on time prepare next =0A=
descriptors to avoid BNA interrupt.=0A=
=0A=
By changing UAC2_DEF_REQ_NUM to 4 all audio gadget tests passed smoothly.=
=0A=
Could you please apply this patch and run tests in DDMA mode:=0A=
=0A=
diff --git a/drivers/usb/gadget/function/u_uac2.h =0A=
b/drivers/usb/gadget/function/u_uac2.h=0A=
index 8362ee572e1e..5e649259ab76 100644=0A=
--- a/drivers/usb/gadget/function/u_uac2.h=0A=
+++ b/drivers/usb/gadget/function/u_uac2.h=0A=
@@ -21,7 +21,7 @@=0A=
  #define UAC2_DEF_CCHMASK 0x3=0A=
  #define UAC2_DEF_CSRATE 64000=0A=
  #define UAC2_DEF_CSSIZE 2=0A=
-#define UAC2_DEF_REQ_NUM 2=0A=
+#define UAC2_DEF_REQ_NUM 4=0A=
=0A=
  struct f_uac2_opts {=0A=
         struct usb_function_instance    func_inst;=0A=
=0A=
=0A=
If it will OK on your side also then will switch to BDMA mode and debug.=0A=
=0A=
Thanks,=0A=
Minas=0A=
> =0A=
> =0A=
> Regards,=0A=
> John=0A=
> =0A=
=0A=