Message-ID: <20221019190819.m35ai5fm3g5qpgqj@synopsys.com>
Date:   Wed, 19 Oct 2022 19:08:27 +0000
From:   Thinh Nguyen <Thinh.Nguyen@...opsys.com>
To:     Jeff Vanhoof <jdv1029@...il.com>
CC:     Thinh Nguyen <Thinh.Nguyen@...opsys.com>,
        Jeffrey Vanhoof <jvanhoof@...orola.com>,
        "balbi@...nel.org" <balbi@...nel.org>,
        "corbet@....net" <corbet@....net>,
        "dan.scally@...asonboard.com" <dan.scally@...asonboard.com>,
        "gregkh@...uxfoundation.org" <gregkh@...uxfoundation.org>,
        "laurent.pinchart@...asonboard.com" 
        <laurent.pinchart@...asonboard.com>,
        "linux-doc@...r.kernel.org" <linux-doc@...r.kernel.org>,
        "linux-kernel@...r.kernel.org" <linux-kernel@...r.kernel.org>,
        "linux-usb@...r.kernel.org" <linux-usb@...r.kernel.org>,
        "m.grzeschik@...gutronix.de" <m.grzeschik@...gutronix.de>,
        "paul.elder@...asonboard.com" <paul.elder@...asonboard.com>,
        "stable@...r.kernel.org" <stable@...r.kernel.org>,
        Dan Vacura <W36195@...orola.com>
Subject: Re: [PATCH v3 2/6] usb: dwc3: gadget: cancel requests instead of
 release after missed isoc

On Wed, Oct 19, 2022, Jeff Vanhoof wrote:
> Hi Thinh,
> 
> On Wed, Oct 19, 2022 at 02:02:53AM +0000, Thinh Nguyen wrote:
> > On Tue, Oct 18, 2022, Jeff Vanhoof wrote:
> > > Hi Thinh,
> > > 
> > > On Tue, Oct 18, 2022 at 10:35:30PM +0000, Thinh Nguyen wrote:
> > > > On Tue, Oct 18, 2022, Jeffrey Vanhoof wrote:
> > > > > Hi Thinh,
> > > > > 
> > > > > On Tue, Oct 18, 2022 at 06:45:40PM +0000, Thinh Nguyen wrote:
> > > > > > Hi Dan,
> > > > > > 
> > > > > > On Mon, Oct 17, 2022, Dan Vacura wrote:
> > > > > > > Hi Thinh,
> > > > > > > 
> > > > > > > On Mon, Oct 17, 2022 at 09:30:38PM +0000, Thinh Nguyen wrote:
> > > > > > > > On Mon, Oct 17, 2022, Dan Vacura wrote:
> > > > > > > > > From: Jeff Vanhoof <qjv001@...orola.com>
> > > > > > > > > 
> > > > > > > > > arm-smmu related crashes seen after a Missed ISOC interrupt when
> > > > > > > > > no_interrupt=1 is used. This can happen if the hardware is still using
> > > > > > > > > the data associated with a TRB after the usb_request's ->complete call
> > > > > > > > > has been made.  Instead of immediately releasing a request when a Missed
> > > > > > > > > ISOC interrupt has occurred, this change will add logic to cancel the
> > > > > > > > > request instead where it will eventually be released when the
> > > > > > > > > END_TRANSFER command has completed. This logic is similar to some of the
> > > > > > > > > cleanup done in dwc3_gadget_ep_dequeue.
> > > > > > > > 
> > > > > > > > This doesn't sound right. How did you determine that the hardware is
> > > > > > > > still using the data associated with the TRB? Did you check the TRB's
> > > > > > > > HWO bit?
> > > > > > > 
> > > > > > > The problem we're seeing was mentioned in the summary of this patch
> > > > > > > series, issue #1. Basically, with the following patch
> > > > > > > https://urldefense.com/v3/__https://patchwork.kernel.org/project/linux-usb/patch/20210628155311.16762-6-m.grzeschik@pengutronix.de/__;!!A4F2R9G_pg!aSNZ-IjMcPgL47A4NR5qp9qhVlP91UGTuCxej5NRTv8-FmTrMkKK7CjNToQQVEgtpqbKzLU2HXET9O226AEN$  
> > > > > > > integrated a smmu panic is occurring on our Android device with the 5.15
> > > > > > > kernel which is:
> > > > > > > 
> > > > > > >     <3>[  718.314900][  T803] arm-smmu 15000000.apps-smmu: Unhandled arm-smmu context fault from a600000.dwc3!
> > > > > > > 
> > > > > > > The uvc gadget driver appears to be the first (and only) gadget that
> > > > > > > uses the no_interrupt=1 logic, so this seems to be a new condition for
> > > > > > > the dwc3 driver. In our configuration, we have up to 64 requests and the
> > > > > > > no_interrupt=1 for up to 15 requests. The list size of dep->started_list
> > > > > > > would get up to that amount when looping through to cleanup the
> > > > > > > completed requests. From testing and debugging the smmu panic occurs
> > > > > > > when a -EXDEV status shows up and right after
> > > > > > > dwc3_gadget_ep_cleanup_completed_request() was visited. The conclusion
> > > > > > > we had was the requests were getting returned to the gadget too early.
> > > > > > 
> > > > > > As I mentioned, if the status is updated to missed isoc, that means that
> > > > > > the controller returned ownership of the TRB to the driver. At least for
> > > > > > the particular request with -EXDEV, its TRBs are completed. I'm not
> > > > > > clear on your conclusion.
> > > > > > 
> > > > > > Do we know where did the crash occur? Is it from dwc3 driver or from uvc
> > > > > > driver, and at what line? It'd great if we can see the driver log.
> > > > > >
> > > > > 
> > > > > To interject, what should happen in dwc3_gadget_ep_reclaim_completed_trb if the
> > > > > IOC bit is not set (but the IMI bit is) and -EXDEV status is passed into it?
> > > > 
> > > > Hm... we may have overlooked this case for no_interrupt scenario. If IMI
> > > > is set, then there will be an interrupt when there's missed isoc
> > > > regardless of whether no_interrupt is set by the gadget driver.
> > > > 
> > > > > If the function returns 0, another attempt to reclaim may occur. If this
> > > > > happens and the next request did have the HWO bit set, the function would
> > > > > return 1 but dwc3_gadget_ep_cleanup_completed_request would still call
> > > > > dwc3_gadget_giveback.
> > > > > 
> > > > > As a test (without this patch), I added a check to see if HWO bit was set in
> > > > > dwc3_gadget_ep_cleanup_completed_requests(). If the usecase was ISOC and the
> > > > > HWO bit was set I avoided calling dwc3_gadget_ep_cleanup_completed_request().
> > > > > This seemed to also avoid the iommu related crash being seen.
> > > > > 
> > > > > Is there an issue in this area that needs to be corrected instead? Not having
> > > > > interrupts set for each request may be causing some new issues to be uncovered.
> > > > > 
> > > > > As far as the crash seen without this patch, no good stacktrace is given. Line
> > > > > provided for crash varied a bit, but tended to appear towards the end of
> > > > > dwc3_stop_active_transfer() or dwc3_gadget_endpoint_trbs_complete().
> > > > > 
> > > > > Since dwc3_gadget_endpoint_trbs_complete() can be called from multiple
> > > > > locations, I duplicated the function to help identify which path it was likely
> > > > > being called from. At the time of the crashes seen,
> > > > > dwc3_gadget_endpoint_transfer_in_progress() appeared to be the caller.
> > > > > 
> > > > > dwc3_gadget_endpoint_transfer_in_progress()
> > > > > ->dwc3_gadget_endpoint_trbs_complete() (crashed towards end of here)
> > > > > ->dwc3_stop_active_transfer() (sometimes crashed towards end of here)
> > > > > 
> > > > > I hope this clarifies things a bit.
> > > > >  
> > > > 
> > > > Can we try this? Let me know if it resolves your issue.
> > > > 
> > > > diff --git a/drivers/usb/dwc3/gadget.c b/drivers/usb/dwc3/gadget.c
> > > > index 61fba2b7389b..8352f4b5dd9f 100644
> > > > --- a/drivers/usb/dwc3/gadget.c
> > > > +++ b/drivers/usb/dwc3/gadget.c
> > > > @@ -3657,6 +3657,10 @@ static int dwc3_gadget_ep_reclaim_completed_trb(struct dwc3_ep *dep,
> > > >  	if (event->status & DEPEVT_STATUS_SHORT && !chain)
> > > >  		return 1;
> > > >  
> > > > +	if (usb_endpoint_xfer_isoc(dep->endpoint.desc) &&
> > > > +	    (event->status & DEPEVT_STATUS_MISSED_ISOC) && !chain)
> > > > +		return 1;
> > > > +
> > > >  	if ((trb->ctrl & DWC3_TRB_CTRL_IOC) ||
> > > >  	    (trb->ctrl & DWC3_TRB_CTRL_LST))
> > > >  		return 1;
> > > >
> > > 
> > > With this change it doesn't seem to crash but unfortunately the output
> > > completely hangs after the first missed isoc. At the moment I do not understand
> > > why this might happen. 
> > > 
> > 
> > Can you capture the driver tracepoints with the change above?
> >
> 
> Due to the size of the log, have sent it to directly to you.

Just got it. Thanks.

> 
> From what I can gather from the log, with the current changes it seems that
> after a missed isoc event few requests are staying longer than expected in the
> started_list (not getting reclaimed) and this is preventing the transmission
> from stopping/starting again, and opening the door for continuous stream of
> missed isoc events that cause what appears to the user as a frozen video.
> 
> So one thought, if IOC bit is not set every frame, but IMI bit is, when a
> missed isoc related interrupt occurs it seems likely that more than one trb
> request will need to be reclaimed, but the current set of changes is not
> handling this.
> 
> In the good transfer case this issue seems to be taken care of since the IOC
> bit is not set every frame and the reclaimation will loop through every item in
> the started_list and only stop if there are no additional trbs or if one has

It should stop at the request that associated with the interrupt event,
whether it's because of IMI or IOC.

> its HWO bit set. Although I am a bit surprised that we are not yet seeing iommu
> related panics here too since the trb is being reclaimed and given back even
> the HWO bit still set, but maybe I am misunderstanding something. In my earlier
> testing, if a missed isoc event was received and we attempted to
> reclaim/giveback a trb with its HWO bit set, a iommu related panic would be
> seen.

If the controller processed the TRB, it would clear the HWO bit after
completion. There are cases which the HWO bit is still set for some
TRBs, but the request is completed (e.g. short transfers causing the
controller to stop processing further). That those cases, the driver
would clear the HWO bit manually.

> 
> Can you propose an additional change to handle freeing up the extra trbs in the
> missed isoc case? I think that somehow the HWO bit should be checked before
> entering dwc3_gadget_ep_cleanup_completed_request in order to avoid the trb
> being given back too soon.

We should not check for TRBs of requests beyond the request associated
with the interrupt event.

> 
> Your thoughts?
> 

The capture shows underrun, and it causes missed isoc.

Let's take a look at the first missed isoc request (req ffffff88f834db00)

           <...>-22551   [002] d..2 13985.789684: dwc3_ep_queue: ep2in: req ffffff88f834db00 length 0/49152 zsi ==> -115
           <...>-22551   [002] dn.2 13985.789728: dwc3_prepare_trb: ep2in: trb ffffffc016071970 (E152:D149) buf 00000000ea800000 size 1x 49152 ctrl 00000461 (Hlcs:Sc:isoc-first)

Each request uses a one TRB. From above, you can see that there are only
3 intervals prepared (E152 - D149 = 3).

The timestamp of the last request completion is 13985.788919.
The timestamp which the queued request is 13985.789728.
We can roughly estimate the diff is at least 809us.

3 intervals (3x125us) is less than 809us. So missed isoc is expected:

    irq/399-dwc3-15269   [002] d..1 13985.790754: dwc3_event: event (f9acc08a): ep2in: Transfer In Progress [63916] (sIM)
    irq/399-dwc3-15269   [002] d..1 13985.790758: dwc3_complete_trb: ep2in: trb ffffffc016071970 (E154:D152) buf 00000000ea800000 size 1x 49152 ctrl 3e6a0460 (hlcs:Sc:isoc-first)
    irq/399-dwc3-15269   [002] d..1 13985.790808: dwc3_gadget_giveback: ep2in: req ffffff88f834db00 length 0/49152 zsi ==> -18


After this point, the uvc driver keeps playing catch up to stay in sync
with the host. It tries, but it couldn't catch up. Also, occasionally
something seems to be blocking dwc3, creating time gaps. Maybe because
of a spin_lock held somewhere?

The logic to detect underrun doesn't trigger because the queued list is
always non-empty, but the queued requests are expected to be missed
already. So you keep seeing missed isoc.

There are a few things you can mitigate this issue:
1) Don't set IMI if the request indicates no_interrupt. This reduces the
   time software needs to handle interrupts.
2) Improve the underrun detection logic.
3) Increase the queuing frequency from the uvc to keep the request queue
   full. Note that reduce/avoid setting no_interrupt will allow the
   controller driver to update uvc often to keep requeuing new requests.

Best option is 3), but maybe we can do all 3.

For 2), you can set IMI for all isoc request as it is now. On missed
isoc, check for the TRB's scheduled uframe (from TRB info) and compare
it to the current uframe (from DSTS) for the number of intervals in
between. With the number of queued requests, you can calculate whether
the gadget driver queued enough requests. If it doesn't, send End
Transfer command and cancel all the queued requests. The next set of
requests will be in-sync again.

BR,
Thinh

PS. On a side note, I notice that there are reports of issue when using
SG right? Please note that dwc3 driver only allocates 256 TRBs
(including a link TRB). Each SG entry takes a TRB. If a request has many
SG entries, that eats up the available TRBs. So, even though the UVC may
queue many requests, not all of them are prepared immediately. If the
TRB ring is full, the driver need to wait for more TRBs to free up
before preparing more. From the log, I see that it's sending 48KB. Let's
say the uvc splits it into PAGE_SIZE of 4KB, that would take at least 12
TRB per request. (Side thought: I'm not sure why UVC needs SG in the
first place with its current implementation)

Powered by blists - more mailing lists