Re: [PATCH v2 1/2] usb: dwc3: Not set DWC3_EP_END_TRANSFER_PENDING in ep cmd fails

[Wesley Cheng <wcheng@codeaurora.org>]

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

Thanks
Wesley Cheng

-- 
The Qualcomm Innovation Center, Inc. is a member of the Code Aurora Forum,
a Linux Foundation Collaborative Project