On 3/24/2022 6:51 PM, Thinh Nguyen wrote:
> Wesley Cheng wrote:
>> Hi Thinh,
>>
>> On 3/23/2022 5:39 PM, Thinh Nguyen wrote:
>>> Hi Wesley,
>>>
>>> Wesley Cheng wrote:
>>>> Hi Thinh,
>>>>
>>>> On 3/22/2022 6:31 PM, Thinh Nguyen wrote:
>>>>> Hi Wesley,
>>>>>
>>>>> Wesley Cheng wrote:
>>>>>> Hi Thinh,
>>>>>>
>>>>>> On 2/15/2022 4:08 PM, Wesley Cheng wrote:
>>>>>>> While running the pullup disable sequence, if there are pending SETUP
>>>>>>> transfers stored in the controller, then the ENDTRANSFER commands on non
>>>>>>> control eps will fail w/ ETIMEDOUT. As a suggestion from SNPS, in order
>>>>>>> to drain potentially cached SETUP packets, SW needs to issue a
>>>>>>> STARTTRANSFER command. After issuing the STARTTRANSFER, and retrying the
>>>>>>> ENDTRANSFER, the command should succeed. Else, if the endpoints are not
>>>>>>> properly stopped, the controller halt sequence will fail as well.
>>>>>>>
>>>>>>> One limitation is that the current logic will drop the SETUP data
>>>>>>> being received (ie dropping the SETUP packet), however, it should be
>>>>>>> acceptable in the pullup disable case, as the device is eventually
>>>>>>> going to disconnect from the host.
>>>>>>>
>>>>>>> Signed-off-by: Wesley Cheng <quic_wcheng@xxxxxxxxxxx>
>>>>>>> ---
>>>>>> Just wondering if you had any inputs for this particular change? I
>>>>>> think on the dequeue path discussion you had some concerns with parts of
>>>>>> this change? I think the difficult part for the pullup disable path is
>>>>>> that we have this API running w/ interrupts disabled, so the EP0 state
>>>>>> won't be able to advance compared to the dequeue case.
>>>>>
>>>>> This doesn't sound right. The pullup disable (or device initiated
>>>>> disconnect) should wait for the EP0 state to be EP0_SETUP_PHASE before
>>>>> proceeding, which it does.
>>>>>
>>>> That is correct, but even though that check is passed, it doesn't
>>>> prevent the host from sending another SETUP token between the pending
>>>> setup packet check and run/stop clear.
>>>>
>>>
>>> That should be fine, because we would have the TRB ready for that SETUP
>>> packet.
>>>
>> I agree, its valid for the controller to be able to receive the next
>> setup packet.
>>
>>>>>>
>>>>>> Ideally, if there is a way to ensure that we avoid reading further setup
>>>>>> packets, that would be nice, but from our discussions with Synopsys,
>>>>>> this was not possible. (controller is always armed and ready to ACK
>>>>>> setup tokens)
>>>>>>
>>>>>> I did evaluate keeping IRQs enabled and periodically releasing/attaining
>>>>>> the lock between the stop active xfer calls, but that opened another can
>>>>>> of worms. If you think this is the approach we should take, I can take
>>>>>> a look at this implementation further.
>>>>>>
>>>>>
>>>>> This patch doesn't look right to me. The change I suggested before
>>>>> should address this (I believe Greg already picked it up). What other
>>>>> problem do you see, I'm not clear what's the problem here. One potential
>>>>> problem that I can see is that currently dwc3 driver doesn't wait for
>>>>> active endpoints to complete/end before clearing the run_stop bit on
>>>>> device initiated disconnect, but I'm not sure if that's what you're seeing.
>>>>>
>>>>> Please help clarify further. If there's trace points log, that'd help.
>>>>>
>>>> Main difference between the issue Greg recently pulled in and this one
>>>> is that this is on the pullup disable patch (no dequeue involved). In
>>>> this situation we will also stop active transfers, so that the
>>>> controller can halt properly.
>>>>
>>>> I attached a few files, and will give a summary of them below:
>>>> 1. pullup_disable_timeout.txt - ftrace of an instance of when we see
>>>> several endxfer timeouts. Refer to line#2016.
>>>>
>>>> 2. lecroy+ftrace_snip.png - picture showing a matching bus sniffer log
>>>> and a ftrace collected (difference instance to #1)
>>>>
>>>> #2 will show that we completed a SETUP transfer before entering into
>>>> dwc3_gadget_stop_active_transfers(). In here, we then see DWC ACK
>>>> another SETUP token, which leads to endxfer timeouts on all subsequent
>>>> endpoints.
>>>
>>> Thanks for the captures. I think the problem here is because the dwc3
>>> driver disables the control endpoint. It shouldn't do that.
>>>
>>> Can you try this:
>>>
>>> diff --git a/drivers/usb/dwc3/gadget.c b/drivers/usb/dwc3/gadget.c
>>> index ab725d2262d6..f0b9ea353620 100644
>>> --- a/drivers/usb/dwc3/gadget.c
>>> +++ b/drivers/usb/dwc3/gadget.c
>>> @@ -1010,12 +1010,12 @@ static int __dwc3_gadget_ep_disable(struct
>>> dwc3_ep *dep)
>>> if (dep->flags & DWC3_EP_STALL)
>>> __dwc3_gadget_ep_set_halt(dep, 0, false);
>>>
>>> - reg = dwc3_readl(dwc->regs, DWC3_DALEPENA);
>>> - reg &= ~DWC3_DALEPENA_EP(dep->number);
>>> - dwc3_writel(dwc->regs, DWC3_DALEPENA, reg);
>>> -
>>> - /* Clear out the ep descriptors for non-ep0 */
>>> if (dep->number > 1) {
>>> + reg = dwc3_readl(dwc->regs, DWC3_DALEPENA);
>>> + reg &= ~DWC3_DALEPENA_EP(dep->number);
>>> + dwc3_writel(dwc->regs, DWC3_DALEPENA, reg);
>>> +
>>> + /* Clear out the ep descriptors for non-ep0 */
>>> dep->endpoint.comp_desc = NULL;
>>> dep->endpoint.desc = NULL;
>>> }
>>>
>> I was able to reproduce the endxfer timeout w/ the above change. I'm
>> assuming you didn't want me to include any parts of my change while
>> testing, right?
>>
Hi Thinh,
>
> Right, please don't add additional code. I can't review knowing what
> else was changed.
>
Sure. There was one change from my patch that I pulled over, which
resolved some enumeration issues I saw (while testing your change, as well):
@@ -885,12 +885,13 @@ static int __dwc3_gadget_ep_enable(struct dwc3_ep
*dep, unsigned int action)
reg |= DWC3_DALEPENA_EP(dep->number);
dwc3_writel(dwc->regs, DWC3_DALEPENA, reg);
- if (usb_endpoint_xfer_control(desc))
- goto out;
-
/* Initialize the TRB ring */
dep->trb_dequeue = 0;
dep->trb_enqueue = 0;
+
+ if (usb_endpoint_xfer_control(desc))
+ goto out;
+
memset(dep->trb_pool, 0,
sizeof(struct dwc3_trb) * DWC3_TRB_NUM);
This was added because I saw that there were instances where the SETUP
TRB was referencing dwc->ep0_trb[1]. However, I believe that for the
SETUP phase, we should always be using dwc->ep0_trb[0] as we are passing
in the ep0_trb_addr (DMA addr for ep0_trb[0]) as part of
dwc3_ep0_start_trans()
>> Current sequence in dwc3_gadget_pullup(0) is that we should call
>> dwc3_stop_active_transfers() before we call __dwc3_gadget_stop().
>> (gadget stop will call the ep disable for EP[0] and EP[1]) This might
>> be why the issue would still be occurring.
>>
>> The attached ftrace that captures a situation where a forced BUG will
>> occur on the first instance of the timeout.
>>
>> [ 1573.687689437 0x724885c22] event (000020c0): ep0out: Transfer
>> Not Ready [0] (Not Active) [Status Phase]
>> [ 1573.687738707 0x724885fd3] dbg_send_ep_cmd: ep0out: cmd
>> 'Start Transfer' [406] params 00000000 efffa000 00000000 --> status:
>> Successful
>> [ 1573.698040582 0x7248b6477] dbg_send_ep_cmd: ep1out: cmd 'End
>> Transfer' [20c08] params 00000000 00000000 00000000 --> status: Timed Out
>>
>> We definitely started the STATUS phase, so host could have read it and
>> sent the next SETUP packet while we were already in the
>> dwc3_stop_active_transfers() loop.
>
> Yeah, pullup() is another async call that can trigger the same problem.
>
>
>
> [ 1573.687193134 0x7248836e8] dbg_send_ep_cmd: ep0out: cmd 'Start Transfer' [406] params 00000000 efffa000 00000000 --> status: Successful
> [ 1573.687263291 0x724883c2b] event (0000c040): ep0out: Transfer Complete (sIL) [Setup Phase]
> [ 1573.687287145 0x724883df6] dbg_trace_log_ctrl: Clear Interface Feature(Function Suspend)
>
> Trace indicates that this is ClearFeature(Interface.FuncSuspend)
>
>
> [ 1573.687372301 0x724884459] dbg_send_ep_cmd: ep0in: cmd 'Start Transfer' [406] params 00000000 efffa000 00000000 --> status: Successful
> [ 1573.687400634 0x724884679] event (000010c2): ep0in: Transfer Not Ready [0] (Not Active) [Data Phase]
> [ 1573.687471155 0x724884bc2] event (000090c2): ep0in: Transfer Not Ready [0] (Active) [Data Phase]
> [ 1573.687495009 0x724884d8d] event (0000c042): ep0in: Transfer Complete (sIL) [Data Phase]
> [ 1573.687544697 0x724885146] dbg_gadget_giveback: ep0out: req ffffff87a6768800 length 20/20 ZsI ==> 0
>
> But there's data stage. Is this non-standard/vendor request?
> We probably need to fix the tracepoint to properly print vendor
> requests.
>
Correct, its most likely a vendor specific command handled by our
function driver.
>
> [ 1573.687593187 0x7248854e9] dbg_ep_queue: ep5in: req ffffff87a6769000 length 0/8 zsI ==> -115
> [ 1573.687619645 0x7248856e6] dbg_prepare: ep5in: trb ffffffc05a97d1a0 (E27:D26) buf 00000000ee07f600 size 1x 8 ctrl 00000811 (Hlcs:sC:normal)
> [ 1573.687660270 0x7248859f2] dbg_send_ep_cmd: ep5in: cmd 'Update Transfer' [b0007] params 00000000 00000000 00000000 --> status: Successful
> [ 1573.687689437 0x724885c22] event (000020c0): ep0out: Transfer Not Ready [0] (Not Active) [Status Phase]
> [ 1573.687738707 0x724885fd3] dbg_send_ep_cmd: ep0out: cmd 'Start Transfer' [406] params 00000000 efffa000 00000000 --> status: Successful
>
> It's still in status stage, it never reached Setup phase.
>
>
> [ 1573.698040582 0x7248b6477] dbg_send_ep_cmd: ep1out: cmd 'End Transfer' [20c08] params 00000000 00000000 00000000 --> status: Timed Out
>
> That's why it's possible to time out here. The Setup Phase should
> have been prepared before we can issue End Transfer.
>
> I can't see where the pullup() begins as this log is missing register
> read/write trace events. Looks like the wait_for_completion_timeout()
> is insufficient. I assume it happens right after previous Setup
Yes, I've noticed that the wait_for_completion() call isn't too reliable
as it isn't under a spinlock. This mechanism worked well for the
dequeue case since we checked for the EP0 state while the lock was held.
> phase. There's no spin_lock, so the driver can proceed with the
> new control request before it reaches dwc3_stop_active_transfers().
>
> Can you try this. (yes, the code looks ugly right now, but it's just
> to confirm my suspicion)
>
Sure, I think I did something earlier as well, where I just manually
polled for EP0state to reach back to SETUP, but there was always a
possibility for host to initiate a SETUP packet while we loop across all
15 eps. If this doesn't work, I can take it a step further and check
EP0 state in between each stop active transfer call. I'll try to repro
it w/ this change and get you some traces.
Thanks
Wesley Cheng
> diff --git a/drivers/usb/dwc3/gadget.c b/drivers/usb/dwc3/gadget.c
> index ab725d2262d6..3b40411556ff 100644
> --- a/drivers/usb/dwc3/gadget.c
> +++ b/drivers/usb/dwc3/gadget.c
> @@ -2506,6 +2506,8 @@ static int dwc3_gadget_pullup(struct usb_gadget *g, int is_on)
>
> is_on = !!is_on;
> dwc->softconnect = is_on;
> +
> +retry:
> /*
> * Per databook, when we want to stop the gadget, if a control transfer
> * is still in process, complete it and get the core into setup phase.
> @@ -2541,6 +2543,24 @@ static int dwc3_gadget_pullup(struct usb_gadget *g, int is_on)
> return 0;
> }
>
> + if (!is_on) {
> + spin_lock_irqsave(&dwc->lock, flags);
> + if (dwc->ep0state != EP0_SETUP_PHASE) {
> + spin_unlock_irqrestore(&dwc->lock, flags);
> + goto retry;
> + }
> +
> + /*
> + * In the Synopsis DesignWare Cores USB3 Databook Rev. 3.30a
> + * Section 4.1.8 Table 4-7, it states that for a device-initiated
> + * disconnect, the SW needs to ensure that it sends "a DEPENDXFER
> + * command for any active transfers" before clearing the RunStop
> + * bit.
> + */
> + dwc3_stop_active_transfers(dwc);
> + spin_unlock_irqrestore(&dwc->lock, flags);
> + }
> +
> /*
> * Synchronize and disable any further event handling while controller
> * is being enabled/disabled.
> @@ -2553,14 +2573,6 @@ static int dwc3_gadget_pullup(struct usb_gadget *g, int is_on)
> u32 count;
>
> dwc->connected = false;
> - /*
> - * In the Synopsis DesignWare Cores USB3 Databook Rev. 3.30a
> - * Section 4.1.8 Table 4-7, it states that for a device-initiated
> - * disconnect, the SW needs to ensure that it sends "a DEPENDXFER
> - * command for any active transfers" before clearing the RunStop
> - * bit.
> - */
> - dwc3_stop_active_transfers(dwc);
> __dwc3_gadget_stop(dwc);
>
> /*
>
> Thanks,
> Thinh
