Hi Wesley,
Wesley Cheng wrote:
> Hi Thinh,
>
> On 5/25/2022 5:25 PM, Thinh Nguyen wrote:
>> Wesley Cheng wrote:
>>> Hi Thinh,
>>>
>>> On 5/23/2022 6:34 PM, Wesley Cheng wrote:
>>>> Hi Thinh,
>>>>
>>>> Welcome back! :)
>>>>
>>>> On 5/23/2022 5:30 PM, Thinh Nguyen wrote:
>>>>> Wesley Cheng wrote:
>>>>>> Hi Thinh,
>>>>>>
>>>>>> On 4/26/2022 2:05 PM, Wesley Cheng wrote:
>>>>>>> Hi Thinh,
>>>>>>>
>>>>>>> On 4/21/2022 7:22 PM, Thinh Nguyen wrote:
>>>>>>>> This series cleanup and enhance dwc3 pullup() handling to cover
>>>>>>>> different
>>>>>>>> corner cases.
>>>>>>>>
>>>>>>>> Would be great to have some Tested-by before picking this series
>>>>>>>> up.
>>>>>>>> Thanks!
>>>>>>>>
>>>>>>>>
>>>>>>>> Thinh Nguyen (6):
>>>>>>>> usb: dwc3: gadget: Prevent repeat pullup()
>>>>>>>> usb: dwc3: gadget: Refactor pullup()
>>>>>>>> usb: dwc3: gadget: Don't modify GEVNTCOUNT in pullup()
>>>>>>>> usb: dwc3: ep0: Don't prepare beyond Setup stage
>>>>>>>> usb: dwc3: gadget: Only End Transfer for ep0 data phase
>>>>>>>> usb: dwc3: gadget: Delay issuing End Transfer
>>>>>>>>
>>>>>>>> drivers/usb/dwc3/ep0.c | 2 +-
>>>>>>>> drivers/usb/dwc3/gadget.c | 126
>>>>>>>> ++++++++++++++++++++------------------
>>>>>>>> 2 files changed, 69 insertions(+), 59 deletions(-)
>>>>>>>>
>>>>>>>>
>>>>>>>> base-commit: 5c29e864999763baec9eedb9ea5bd557aa4cbd77
>>>>>>>
>>>>>>> Thanks for this series. Running the tests w/ the changes now and
>>>>>>> will
>>>>>>> debug if I run into any issues. I will need to run the previous
>>>>>>> test
>>>>>>> cases I had as well, since the change removes the GEVNTCOUNT
>>>>>>> clearing
>>>>>>> during pullup disable (this was added for some controller halt
>>>>>>> failures).
>>>>>>>
>>>>>>
>>>>>> Going to summarize some of the things I've found so far:
>>>>>> 1. DWC3_EP_DELAY_STOP flag set for EPs:
>>>>>> The test case being run will have usb ep dequeue running closely in
>>>>>> parallel to soft disconnect. There is a chance that we run into
>>>>>> controller halt due to active EPs, since we are not
>>>>>> waiting/synchronizing for DWC3_EP_DELAY_STOP to be cleared or
>>>>>> complete.
>>>>>
>>>>> I sent an update. Can you test it out?
>>>>>
>>>>>>
>>>>>> Attached thinh_newest_delayed_status_causing_ep_stop_delay_flag.txt
>>>>>> - Force device crash if run/stop routine fails w/ -ETIMEDOUT.
>>>>>
>>>>> Can you clarify here? Did you force the crash or did the crash
>>>>> occur due
>>>>> to the change?
>>>>>
>>>> Just injecting a kernel panic if there is an -ETIMEDOUT condition
>>>> during run/stop clear. The end of the traces will be at the point of
>>>> which the error occurred.
>>>>
>>>>>> - There is a situation where a function will return
>>>>>> delayed_status, and
>>>>>> we can see "timed out waiting for SETUP phase" print during pullup
>>>>>> disable.
>>>>>
>>>>> It should be fine that the warning gets printed. The programming guide
>>>>> suggested that the driver should wait for all the control transfers to
>>>>> complete. This deviates from the programming guide. If it happens
>>>>> often
>>>>> enough, we may need to increase the timeout.
>>>>>
>>>> Yes, agreed.
>>>>
>>>>>>
>>>>>> 2. Controller halt failure due to non-zero GEVNTCOUNT
>>>>>> So with this patch series, and removing the GEVNTCOUNT clearing, I'm
>>>>>> running into controller halt failures again. When I printed the
>>>>>> GEVNTCOUNT register at the time of failure, it showed that there were
>>>>>> several pending events.
>>>>>
>>>>> Do you have the log for this? What's the IO delay for each register
>>>>> read
>>>>> on your platform? I suspect that the polling for halt status is too
>>>>> quick, we may need to add some delay between polls.
>>>>>
>>>> Will try to collect a log for you after adding the new changes (if I
>>>> run into this). I tried to increase the number of loops as well, but
>>>> that didn't help.
>>>>
>>> I think the reason for the non-zero GEVNTCOUNT is probably due to the
>>> fact that we're still getting EP0 events:
>>>
>>> [ 3548.040859][T20051] dwc3 a600000.dwc3: unexpected direction for Data
>>> Phase
>>> [ 3548.061282][T20051] dwc3 a600000.dwc3: unexpected direction for Data
>>> Phase
>>> [ 3548.071429][T20051] dwc3 a600000.dwc3: unexpected direction for Data
>>> Phase
>>> [ 3548.083499][T20051] dwc3 a600000.dwc3: unexpected direction for Data
>>> Phase
>>> [ 3548.095546][T20051] dwc3 a600000.dwc3: unexpected direction for Data
>>> Phase
>>> [ 3548.105820][T20051] dwc3 a600000.dwc3: unexpected direction for Data
>>> Phase
>>> [ 3548.122027][ T2189] dwc3_gadget_run_stop: pullups_connected = 0
>>> [ 3548.156770][ T2189] GEVENT COUNT = 8
>>>
>>> In the changes proposed, you're blocking the inspect setup API if
>>> !dwc->connected, but due to ret = -EINVAL, the exit routine will go and
>>> issue a stall and restart on EP0. I think your main intention was just
>>> to ignore it, correct?
>>>
>>
>> No, not just ignoring it. The intention is that while polling for the
>> halted state, the driver will continue to service any interrupt
>> generated by the controller. If it's a control transfer, then the
>> controller will respond with a STALL and rejects any new control
>> transfer and setup a new TRB for the next setup stage. The interrupt
>> handler will clear the GEVNTCOUNT while polling for halted state. The
>> expectation here is to poll for the halted state long enough for the
>> interrupt handler to come and clear the GEVNTCOUNT before the timeout.
>>
>> Looks like somehow the polling for the halted state block the irq
>> handler:
>>
>> [ 3548.117872285 0xff828a6ab] dbg_gadget_giveback: ep7in: req
>> ffffff8041575600 length 0/65536 zsI ==> -108
>> [ 3548.120646816 0xff82976c3] dbg_send_ep_cmd: ep8in: cmd 'End
>> Transfer' [110c08] params 00000000 00000000 00000000 --> status:
>> Successful
>>
>> There's a 30ms gap here. Probably during the polling? (would be good to
>> have more register read/write tracepoints)
>>
>> [ 3548.151314473 0xff83272d7] event (080001c0): ep0out:
>> Endpoint Command Complete
>> [ 3548.151760931 0xff8329451] event (080001c0): ep0out:
>> Endpoint Command Complete
>> [ 3548.152104577 0xff832ae18] event (080001c0): ep0out:
>> Endpoint Command Complete
>> [ 3548.152452441 0xff832c82e] event (080001c0): ep0out:
>> Endpoint Command Complete
>> [ 3548.152842702 0xff832e574] event (080001c0): ep0out:
>> Endpoint Command Complete
>> [ 3548.153250150 0xff8330403] event (080001c0): ep0out:
>> Endpoint Command Complete
>> [ 3548.153657285 0xff833228b] event (080001c0): ep0out:
>> Endpoint Command Complete
>>
>>
>> Can you add msleep(1) in between the polling:
>>
>> diff --git a/drivers/usb/dwc3/gadget.c b/drivers/usb/dwc3/gadget.c
>> index ee8e8974302d..9c0d61a2dd82 100644
>> --- a/drivers/usb/dwc3/gadget.c
>> +++ b/drivers/usb/dwc3/gadget.c
>> @@ -2814,6 +2814,8 @@ static int dwc3_gadget_run_stop(struct dwc3
>> *dwc, int is_on, int suspend)
>> dwc3_gadget_dctl_write_safe(dwc, reg);
>> do {
>> + msleep(1);
>> +
>> reg = dwc3_readl(dwc->regs, DWC3_DSTS);
>> reg &= DWC3_DSTS_DEVCTRLHLT;
>> } while (--timeout && !(!is_on ^ !reg));
>>
>>
>> (If this works, we can slightly modify this logic to save 1ms)
>>
>> BTW, is there a problem with enabling other tracepoint events? I have to
>> make some guesses when reading the log.
>>
>
> With the test I'm running, I have to make some changes to hook into the
> DWC3 tracepoints we have and save it into a different logging mechanism
> we have. The default ftrace is being routed to a different path while
> this test is running.
>
> I'll see if I can add some reg reads/writes logs.
>
> With the current changes (I've also seen this w/o the latest msleep()
> change), I'm getting into a situation where there is a controller halt.
> In this case though, GEVNTCNT is 0, but I think what is happening is
> that we are interweaving pullup enable and pullup disable calls, and
> some pullup enable sequences are failing, which lead to the next pullup
> disable to fail halting of the controller.
How can the pullup() enable fail? There should be a soft reset if
there's pullup() enable, which should reset the controller. Do you have
the driver log for that failure?
>
> if (dwc->pullups_connected == is_on)
> return 0;
>
> If the pullup disable routine is running the run/stop path, and USB
> gadget attempts to call pullup enable, this IF condition will allow the
> pullup enable to continue. This is because pullups_connected is set to
> FALSE before the controller halt polling, so 0->1 transition is valid.
Why is it not protected? The caller of pullup() should prevent the
interweaving of the pullup calls. A pullup() should be completed before
the next call. From what I see, the caller of this pullup()
(usb_gadget_connect/disconnect in udc/core.c) handles it properly with a
mutex in gadget binding and sysfs connect.
>
> I'm not sure how most USB composite devices behave, but I don't think
> most will retry if the pullup enable returns an error. (?) I say this
> because we can modify the IF condition to block the subsequent pullup
> enable call, if we have not yet finished the controller halt.
The composite device uses the udc core api, so it should be protected.
>
> In the snippet below, we can see that, we disabled the run/stop bit and
> halted the controller shortly after receiving the RESET event. This
> means that the dwc3 gadget stop was called, and EP0 was disabled as well
> (flags were also cleared). This is leading to the CONNDONE event to
> then re-do the start config, as EP0 is not "enabled." I think that is
> not the expected sequence.
If the pullup() disable completed successfully, then the device is
halted and remains disconnected. The conndone event doesn't connect the
device back unless there's pullup enable. The next pullup() enable will
re-initialize the device again after a soft reset.
>
> [ 3899.673491795 0x118aae3bf1] dbg_send_ep_cmd: ep0out: cmd 'Set
> Endpoint Configuration' [401] params 00001000 00000500 00000000 -->
> status: Successful
> [ 3899.673534504 0x118aae3f25] dbg_send_ep_cmd: ep0in: cmd 'Set
> Endpoint Configuration' [401] params 00001000 02000500 00000000 -->
> status: Successful
> [ 3899.673584920 0x118aae42ed] dbg_send_ep_cmd: ep0out: cmd
> 'Start Transfer' [406] params 00000000 efffa000 00000000 --> status:
> Successful
> [ 3899.700573][T24732] dwc3_gadget_run_stop: pullups_connected = 1
>
> [ 3899.744634556 0x118ac313a7] event (00030601): Suspend [U3]
> [ 3899.838616483 0x118ade9c4d] event (00000101): Reset [U0]
>
> [ 3899.922413][ T2186] dwc3_gadget_run_stop: pullups_connected = 0
>
> [ 3900.147395911 0x118b3912c0] event (00000201): Connection Done
> [U0]
> [ 3900.147486276 0x118b391988] dbg_send_ep_cmd: ep0out: cmd
> 'Start New Configuration' [409] params 00000000 00000000 00000000 -->
> status: Successful
> [ 3900.147535234 0x118b391d34] dbg_send_ep_cmd: ep0out: cmd 'Set
> Endpoint Transfer Resource' [402] params 00000001 00000000 00000000 -->
> status: Successful
>
I'm not clear what's the failure here. You noted that pullup() enable
fails now, but I don't see it. Can you help clarify further.
Thanks,
Thinh
