Re: [PATCH] usb: musb: musb_host: Introduce postponed URB giveback

[Bin Liu <b-liu@ti.com>]

On Fri, Apr 28, 2017 at 10:04:30AM +0300, Matwey V. Kornilov wrote:
> 2017-04-27 20:13 GMT+03:00 Bin Liu <b-liu@ti.com>:
> > On Thu, Apr 27, 2017 at 07:26:31PM +0300, Matwey V. Kornilov wrote:
> >> 2017-04-27 18:35 GMT+03:00 Bin Liu <b-liu@ti.com>:
> >> > Hi Matwey,
> >> >
> >> > On Thu, Apr 27, 2017 at 01:20:33PM +0300, Matwey V. Kornilov wrote:
> >> >> This commit changes the order of actions undertaken in
> >> >> musb_advance_schedule() in order to overcome issue with broken
> >> >> isochronous transfer [1].
> >> >>
> >> >> There is no harm to split musb_giveback into two pieces.  The first
> >> >> unlinks finished urb, the second givebacks it. The issue here that
> >> >> givebacking may be quite time-consuming due to urb->complete() call.
> >> >> As it happens in case of pwc-driven web cameras. It may take about 0.5
> >> >> ms to call __musb_giveback() that calls urb->callback() internally.
> >> >> Under specific circumstances setting MUSB_RXCSR_H_REQPKT in subsequent
> >> >> musb_start_urb() for the next urb will be too late to produce physical
> >> >> IN packet. Since auto req is not used by this module the exchange
> >> >> would be as the following:
> >> >>
> >> >> [        ]   7.220456 d=  0.000997 [182   +  3.667] [  3] IN   : 4.5
> >> >> [    T   ]   7.220459 d=  0.000003 [182   +  7.000] [800] DATA0: [skipped]
> >> >> [        ]   7.222456 d=  0.001997 [184   +  3.667] [  3] IN   : 4.5
> >> >> [        ]   7.222459 d=  0.000003 [184   +  7.000] [  3] DATA0: 00 00
> >> >>
> >> >> It is known that missed IN in isochronous mode makes some
> >> >> perepherial broken. For instance, pwc-driven or uvc-driven
> >> >> web cameras.
> >> >> In order to workaround this issue we postpone calling
> >> >> urb->callback() after setting MUSB_RXCSR_H_REQPKT for the
> >> >> next urb if there is the next urb pending in queue.
> >> >>
> >> >> [1] https://www.spinics.net/lists/linux-usb/msg145747.html
> >> >>
> >> >> Fixes: f551e1352983 ("Revert "usb: musb: musb_host: Enable HCD_BH flag to handle urb return in bottom half"")
> >> >> Signed-off-by: Matwey V. Kornilov <matwey@sai.msu.ru>
> >> >
> >> > Thanks for the effort of working on this long standing issue, I know you
> >> > have spent alot of time on it, but what I am thinking is instead of
> >> > workaround the problem we need to understand the root cause - why
> >> > uvc-video takes longer to exec the urb callback, why only am335x
> >> > reported this issue. This is on my backlog, just seems never got time
> >> > for it...
> >>
> >> Have you tried other SoCs with Invetra MUSB?
> >
> > That is the plan, I got an A20 board, but haven't bring it up yet.
> >
> >>
> >> >
> >> > Ideally MUSB driver should be just using HCD_BH flag and let the core to
> >> > handle the urb callback, regardless the usb transfer types.
> >>
> >> I think the only reason why everything worked before with HCD_BH is
> >> that execution of urb->callback() was placed after musb_start(). The
> >> order of operations matters.
> >> However, you said that something was also wrong with HCD_BH and other
> >> peripherals.
> >
> > HCD_BH flag cause some issues which are docummented in the commit log of
> > f551e1352983.
> > But even with HCD_BH flag, it didn't work for uvc webcams, it still misses
> > IN tokens. It might helps pwc webcams though.
> 
> pwc webcams work with HCD_BH fine indeed.

yeah, this is what you told long time ago.

> 
> >
> >> > The MUSB drivers are already messy and complicated enough for
> >> > maintenance, I'd like to understand the root cause of the delay first
> >> > before decide how to solve the issue.
> >> >
> >>
> >> I feel from playing with OpenVizsla that REQPKT should be set well in
> >> advance. So, time window to set the flag is actually smaller than 1
> >> ms.
> >> urb->callback() is never takes longer than 0.4 ms for pwc driver, but
> >> INs are skipped.
> >
> > Setting REQPKT in advance might be the solution, but I'd like to
> > understand why only Isoch transfer shows such issue, and why only am335x
> > reports this issue. The later concerns me more if this would be a
> > system issue not only in usb module.
> 
> 0.4 ms is about 100000 CPU cycles given that CPU is running at 275Mhz
> (which is the lowest cpufreq). Long time ago, I run pwc webcam with
> SIS Vortex86 at 200Mhz It worked fine. I would not say that it is
> extraordinary value.
> Do you think that somewhere CPU cycles are wasted globally for some reason?

Depends on how to interpret 'wasted', my understanding the issue is the
core urb giveback holds a spinlock and in uvc case the giveback takes
longer to finish (I guess the same in pwc case), so the musb driver
doesn't get a chance to re-program the controller on time, which causes
missing issuingIN tokens.

The questions are, why uvc takes longer to run urb giveback (which holds
a spinlock), and is it am335x specific issue...

Regards,
-Bin.