Re: [PATCH] usb: dwc3: gadget: Disable gadget IRQ during pullup disable

[Wesley Cheng <wcheng@codeaurora.org>]

On 6/10/2021 11:21 AM, Wesley Cheng wrote:
> 
> 
> On 6/10/2021 4:09 AM, Felipe Balbi wrote:
>> Wesley Cheng <wcheng@codeaurora.org> writes:
>>
>>> Current sequence utilizes dwc3_gadget_disable_irq() alongside
>>> synchronize_irq() to ensure that no further DWC3 events are generated.
>>> However, the dwc3_gadget_disable_irq() API only disables device
>>> specific events.  Endpoint events can still be generated.  Briefly
>>> disable the interrupt line, so that the cleanup code can run to
>>> prevent device and endpoint events. (i.e. __dwc3_gadget_stop() and
>>> dwc3_stop_active_transfers() respectively)
>>>
>>> Without doing so, it can lead to both the interrupt handler and the
>>> pullup disable routine both writing to the GEVNTCOUNT register, which
>>> will cause an incorrect count being read from future interrupts.
>>>
>>> Fixes: ae7e86108b12 ("usb: dwc3: Stop active transfers before halting the controller")
>>> Signed-off-by: Wesley Cheng <wcheng@codeaurora.org>
>>> ---
>>>  drivers/usb/dwc3/gadget.c | 11 +++++------
>>>  1 file changed, 5 insertions(+), 6 deletions(-)
>>>
>>> diff --git a/drivers/usb/dwc3/gadget.c b/drivers/usb/dwc3/gadget.c
>>> index 49ca5da..89aa9ac 100644
>>> --- a/drivers/usb/dwc3/gadget.c
>>> +++ b/drivers/usb/dwc3/gadget.c
>>> @@ -2260,13 +2260,10 @@ static int dwc3_gadget_pullup(struct usb_gadget *g, int is_on)
>>>  	}
>>>  
>>>  	/*
>>> -	 * Synchronize any pending event handling before executing the controller
>>> -	 * halt routine.
>>> +	 * Synchronize and disable any further event handling while controller
>>> +	 * is being enabled/disabled.
>>>  	 */
>>> -	if (!is_on) {
>>> -		dwc3_gadget_disable_irq(dwc);
>>> -		synchronize_irq(dwc->irq_gadget);
>>> -	}
>>> +	disable_irq(dwc->irq_gadget);
>>>  
>>>  	spin_lock_irqsave(&dwc->lock, flags);
>>
>> spin_lock_irqsave() is already disabling interrupt, right? Why do we
>> need another call to disable_irq()?
>>
> 
> Hi Felipe,
> 
> Yes, I remember you brought up that point as well before.  So when I
> checked the logs (USB and scheduler ftrace) for this issue, I clearly
> saw that we were handling a soft disconnect on CPU3 and then an DWC3 IRQ
> being scheduled into CPU0.  Last time we discussed, I mentioned that
> spin_lock_irqsave() only disables interrupts on that particular CPU the
> thread is running on.
> 
Hi Felipe,

Let me share the ftrace snippets as well:

USB FTRACE:

<idle>-0    [002]   304.567900:  dwc3_gadget_ep_cmd   name=ep0out
cmd=1030  param0=0  param1=4026523648  param2=0  cmd_status=0
<idle>-0    [004]   304.583225:  dwc3_gadget_ep_cmd   name=ep1out
cmd=134152  param0=0  param1=0  param2=0  cmd_status=0

//We don't have any logging in pullup disable, but this is when that
occurs, as we start to see -ESHUTDOWN statuses due to stop active
transfer.
<idle>-0    [004]   304.583237:  dwc3_gadget_giveback   name=ep1out
req=1243650560  actual=0  length=16384  status=4294967188  zero=0
short_not_ok=0  no_interrupt=0
<idle>-0    [004]   304.583275:  dwc3_gadget_giveback   name=ep1out
req=1243645440  actual=0  length=16384  status=4294967188  zero=0
short_not_ok=0  no_interrupt=0
<idle>-0    [004]   304.583282:  dwc3_gadget_giveback   name=ep1out
req=1243648256  actual=0  length=16384  status=4294967188  zero=0
short_not_ok=0  no_interrupt=0
<idle>-0    [004]   304.583312:  dwc3_gadget_giveback   name=ep1out
req=4075146240  actual=0  length=16384  status=4294967188  zero=0
short_not_ok=0  no_interrupt=0
...
//USB gadget disconnect is printed AFTER the pullup(0) routine is complete.
<idle>-0    [004]   304.584240:  usb_gadget_disconnect   speed=3
max_speed=6  state=7  mA=500  sg_supported=1  is_otg=0
is_a_peripheral=0  b_hnp_enable=0  a_hnp_support=0
hnp_polling_support=0  host_request_flag=0  quirk_ep_out_aligned_size=0
 quirk_altset_not_supp=0  quirk_stall_not_supp=0  quirk_zlp_not_supp=0
is_selfpowered=0  deactivated=0  connected=1  ret=4294967186

---------------------------------------------------------
CPU2 SCHED FTRACE:

kworker/u16:5-192    [002]   304.583354:  irq_handler_entry   irq=343
name=dwc3-msm
kworker/u16:5-192    [002]   304.583356:  irq_handler_exit   irq=343
ret=0
kworker/u16:5-192    [002]   304.583358:  irq_handler_entry   irq=343
name=dwc3
kworker/u16:5-192    [002]   304.583366:  irq_handler_exit   irq=343
ret=2
kworker/u16:5-192    [002]   304.583377:  sched_wakeup
comm=irq/343-dwc3  pid=20174  prio=100  success=1  target_cpu=2
kworker/u16:5-192   [002]  304.583411: sched_switch:
prev_comm=kworker/u16:5 prev_pid=192 prev_prio=120 prev_state=R ==>
next_comm=irq/343-dwc3 next_pid=20174 next_prio=100
irq/343-dwc3-20174    [002]   304.583454:  irq_handler_entry   irq=343
name=dwc3-msm
irq/343-dwc3-20174    [002]   304.583455:  irq_handler_exit   irq=343
ret=0
irq/343-dwc3-20174    [002]   304.583458:  irq_handler_entry   irq=343
name=dwc3
irq/343-dwc3-20174    [002]   304.583465:  irq_handler_exit   irq=343
ret=2

So if we assume that the point of error happens @ 304.567900 due to the
below points:
- DWC3 pullup disable routine synchronized IRQs (w/ previous logic)
before calling stop active transfers.
- DWC3 request statuses shows ESHUTDOWN, which occurs during stop active
transfer, as we call giveback w/ that error code

Then we can see that on CPU2, we're still getting DWC3 core IRQs, and
DWC3 IRQ handler is returning --> 2, which is IRQ_WAKE_THREAD.

Thanks
Wesley Cheng

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