Date:   Wed, 23 Feb 2022 02:59:14 +0000
From:   Thinh Nguyen <Thinh.Nguyen@...opsys.com>
To:     Wesley Cheng <wcheng@...eaurora.org>,
        Thinh Nguyen <Thinh.Nguyen@...opsys.com>,
        Wesley Cheng <quic_wcheng@...cinc.com>,
        Jung Daehwan <dh10.jung@...sung.com>
CC:     Felipe Balbi <balbi@...nel.org>,
        Greg Kroah-Hartman <gregkh@...uxfoundation.org>,
        "linux-usb@...r.kernel.org" <linux-usb@...r.kernel.org>,
        open list <linux-kernel@...r.kernel.org>,
        "quic_jackp@...cinc.com" <quic_jackp@...cinc.com>
Subject: Re: [PATCH v2 1/2] usb: dwc3: Not set DWC3_EP_END_TRANSFER_PENDING in
 ep cmd fails

Hi Wesley,

Wesley Cheng wrote:
> Hi Thinh,
> 
> On 2/17/2022 3:43 PM, Thinh Nguyen wrote:
>> Wesley Cheng wrote:
>>> Hi Thinh,
>>>
>>> On 2/15/2022 9:14 AM, Thinh Nguyen wrote:
>>>> Jung Daehwan wrote:
>>>>> Hi Thinh,
>>>>>
>>>>> On Mon, Feb 14, 2022 at 06:44:33PM +0000, Thinh Nguyen wrote:
>>>>>> Hi,
>>>>>>
>>>>>> Daehwan Jung wrote:
>>>>>>> It always sets DWC3_EP_END_TRANSFER_PENDING in dwc3_stop_active_transfer
>>>>>>> even if dwc3_send_gadget_ep_cmd fails. It can cause some problems like
>>>>>>
>>>>>> How does it fail? Timed out?
>>>>>
>>>>> Yes, timed out.
>>>>>>
>>>>>>> skipping clear stall commmand or giveback from dequeue. We fix to set it
>>>>>>> only when ep cmd success. Additionally, We clear DWC3_EP_TRANSFER_STARTED
>>>>>>> for next trb to start transfer not update transfer.
>>>>>>
>>>>>> We shouldn't do this. Things will be out of sync. It may work for 1
>>>>>> scenario, but it won't work for others.
>>>>>>
>>>>>> Please help me understand a few things:
>>>>>>
>>>>>> 1) What is the scenario that triggers this? Is it random?
>>>>>>
>>>>> ep cmd timeout occurs on dequeue request from user side. End Transfer command
>>>>> would be sent in dwc3_stop_active transfer.
>>>>
>>>> At the high level, what's triggering the request dequeue? Is it from a
>>>> disconnect, change of interface, or simply function driver protocol that
>>>> changes it.
>>>>
>>>> What application was used to trigger this?
>>>>
>>> Sorry for jumping in here, but looks like Daehwan is running into a
>>> similar issue I am seeing as well.
>>>
>>> At least in my scenario, the dequeue is coming from a function driver
>>> which exposes a device to userspace.  Once that device is closed, it
>>> will issue a dequeue on all pending/submitted requests.
>>
>> Dequeuing request is coming from the function driver, but what causes
>> the dequeue. For example, the End Transfer command due to a disconnect
>> may give a different clues than a dequeue from a change of interface.
>>
> For us, once the application exits, the corresponding userspace
> device/port is closed.  This triggers the function driver to clean up
> any pending/queued USB requests.  It doesn't have any association w/ any
> USB cable disconnect, or interface change in this case, it is controlled
> solely on the application exiting/stopped.
>>>
>>>>>
>>>>>> 2) Are there other traffics pending while issuing the End Transfer
>>>>>> command? If so, what transfer type(s)?
>>>>>>
>>>>> I haven't checked it yet. 
>>>>
>>>> Can you check?
>>>>
>>> For the cases where we've collected a crash log, we can see that during
>>> the END transfer timeouts there was always a pending EP0 transaction.
>>> We had reached out to our internal HW folks to get some inputs on what
>>> could be causing this kind of issue, and we were able to get some
>>> recommendations from their Synopsis POCs.
>>
>> It's "Synopsys" :)
>>
> Sorry! :)
>>>
>>> It was mentioned that if there was an active EP0 transfer, an end
>>> transfer command on a non-control EP can fail w/ timed out.
>>>
>>
>> What controller version are you using? And what version is Jung using?
>> Do you have the STAR number of the issue. If you're using a different
>> version than Jung's, then it may not be the same issue.
>>
> We're using 1.90a.
> 
>>>>>
>>>>>> 3) Have you tried increasing the timeout?
>>>>>>
>>>>> No, I haven't.
>>>>
>>>> Can you try up to 10 seconds (just for experiment)
>>>>
>>> I've tried this too, and it did not help.
>>>
>>>>>> BR,
>>>>>> Thinh
>>>>>>
>>>>>
>>>>> This issue occurs very rarely on customer. I only have restricted
>>>>> information. That's why I've been trying to reproduce it.
>>>>
>>>> How did you test your fix if you can't reproduce it?
>>>>
>>>>>
>>>>> Wesley may have run into same issue and you can see this issue in detail.
>>>>> https://urldefense.com/v3/__https://protect2.fireeye.com/v1/url?k=9d423b69-fc3fd32e-9d43b026-74fe485fff30-77a099b52659410d&q=1&e=20b4d9f5-2599-4f57-8b6a-7c4ec167d228&u=https*3A*2F*2Flore.kernel.org*2Flinux-usb*2F20220203080017.27339-1-quic_wcheng*40quicinc.com*2F__;JSUlJSUlJQ!!A4F2R9G_pg!JWPzNLoO3BFX_IZCVzmHPtxq6frr_VFbSNNaxSQylunt1Y4EauTOefth2LCIcVEuTx8E$ 
>>>>>
>>>>
>>>> I can take a look, but please provide the tracepoints of the failure if
>>>> you can reproduce it.
>>>>
>>> Let me see if I have any previous traces I can share.  If not, I have a
>>> pretty reliable repro set up I can collect a trace for you.  For now, I
>>> will focus on just getting the endxfer timeout seen during ep dequeue.
>>> As mentioned on my patchset, this can happen during device-initiated
>>> disconnect as well.
>>>
>>
>> Your patch set is still on my todo list. I haven't reviewed it. There's
>> some concern looking at it from a first glance, I'll check it out more
>> thoroughly later.
>>
>> Can you provide the tracepoints?
>>
> I can provide the full trace if you need it, just let me know.  However
> here is a quick snippet:
> 
> [ 1865.070397670       0x8724e2f18]   dbg_send_ep_cmd: ep2in: cmd
> 'Update Transfer' [50007] params 00000000 00000000 00000000 --> status:
> Successful
> [ 1865.070449389       0x8724e32fa]   dbg_ep_queue: ep2in: req
> ffffff87a36bd300 length 0/65536 zsI ==> -115
> [ 1865.070480222       0x8724e3549]   dbg_send_ep_cmd: ep2in: cmd
> 'Update Transfer' [50007] params 00000000 00000000 00000000 --> status:
> Successful
> [ 1865.070529962       0x8724e3904]   dbg_ep_queue: ep2in: req
> ffffff88708dfc00 length 0/65536 zsI ==> -115
> [ 1865.070559545       0x8724e3b3c]   dbg_send_ep_cmd: ep2in: cmd
> 'Update Transfer' [50007] params 00000000 00000000 00000000 --> status:
> Successful
> [ 1865.070610639       0x8724e3f11]   dbg_ep_queue: ep2in: req
> ffffff8042a98200 length 0/65536 zsI ==> -115
> [ 1865.070640691       0x8724e4152]   dbg_send_ep_cmd: ep2in: cmd
> 'Update Transfer' [50007] params 00000000 00000000 00000000 --> status:
> Successful
> [ 1865.070692983       0x8724e453e]   dbg_ep_queue: ep2in: req
> ffffff8042a98900 length 0/65536 zsI ==> -115
> [ 1865.070728972       0x8724e47f1]   dbg_send_ep_cmd: ep2in: cmd
> 'Update Transfer' [50007] params 00000000 00000000 00000000 --> status:
> Successful
> 
> //EP halt setup packet is received from the PC
> [ 1865.166579233       0x8726a5cb7]   dbg_trace_log_ctrl: Clear Endpoint
> Feature(Halt ep6in)
> [ 1865.166716785       0x8726a6708]   dbg_send_ep_cmd: ep6in: cmd 'Clear
> Stall' [405] params 00000000 00000000 00000000 --> status: Successful
> 
> //This should be the EP0 status phase, as it is on ep0in
> [ 1865.166849598       0x8726a70fd]   dbg_send_ep_cmd: ep0in: cmd 'Start
> Transfer' [406] params 00000000 efffa000 00000000 --> status: Successful
> [ 1865.173668817       0x8726c706e]   dbg_ep_dequeue: ep2in: req
> ffffff885f293f00 length 0/62848 zsI ==> -115
> 
> //Dequeue timeout occurs here
> [ 1865.192420900       0x87271eed6]   dbg_send_ep_cmd: ep2in: cmd 'End
> Transfer' [50d08] params 00000000 00000000 00000000 --> status: Timed Out
> 

Can you provide a full trace?

Btw, when you experiment with increasing the timeout to 10 seconds, did
you use the mdelay() in each loop? The delta time for End Transfer
timeout here seems very small.

Note: The End Transfer command should _only_ gets stuck if the DMA for a
the Setup packet isn’t completed, which should be a short time. It
doesn't look like the case here. (Hopefully the full driver tracepoint
give more clues).

Thanks,
Thinh

Powered by blists - more mailing lists