2017-04-27 10:20:50

by Matwey V. Kornilov

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

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 <[email protected]>
---
drivers/usb/musb/musb_host.c | 54 +++++++++++++++++++++++++++++++++++++-------
1 file changed, 46 insertions(+), 8 deletions(-)

diff --git a/drivers/usb/musb/musb_host.c b/drivers/usb/musb/musb_host.c
index ac3a4952abb4..b590c2555dab 100644
--- a/drivers/usb/musb/musb_host.c
+++ b/drivers/usb/musb/musb_host.c
@@ -299,19 +299,24 @@ musb_start_urb(struct musb *musb, int is_in, struct musb_qh *qh)
}
}

-/* Context: caller owns controller lock, IRQs are blocked */
-static void musb_giveback(struct musb *musb, struct urb *urb, int status)
+static void __musb_giveback(struct musb *musb, struct urb *urb, int status)
__releases(musb->lock)
__acquires(musb->lock)
{
- trace_musb_urb_gb(musb, urb);
-
- usb_hcd_unlink_urb_from_ep(musb->hcd, urb);
spin_unlock(&musb->lock);
usb_hcd_giveback_urb(musb->hcd, urb, status);
spin_lock(&musb->lock);
}

+/* Context: caller owns controller lock, IRQs are blocked */
+static void musb_giveback(struct musb *musb, struct urb *urb, int status)
+{
+ trace_musb_urb_gb(musb, urb);
+
+ usb_hcd_unlink_urb_from_ep(musb->hcd, urb);
+ __musb_giveback(musb, urb, status);
+}
+
/* For bulk/interrupt endpoints only */
static inline void musb_save_toggle(struct musb_qh *qh, int is_in,
struct urb *urb)
@@ -346,6 +351,7 @@ static void musb_advance_schedule(struct musb *musb, struct urb *urb,
struct musb_hw_ep *ep = qh->hw_ep;
int ready = qh->is_ready;
int status;
+ int postponed_giveback = 0;

status = (urb->status == -EINPROGRESS) ? 0 : urb->status;

@@ -361,9 +367,35 @@ static void musb_advance_schedule(struct musb *musb, struct urb *urb,
break;
}

- qh->is_ready = 0;
- musb_giveback(musb, urb, status);
- qh->is_ready = ready;
+ usb_hcd_unlink_urb_from_ep(musb->hcd, urb);
+
+ /* 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.
+ */
+ if (is_in && qh->type == USB_ENDPOINT_XFER_ISOC
+ && !list_empty(&qh->hep->urb_list)) {
+ postponed_giveback = 1;
+ } else {
+ qh->is_ready = 0;
+ __musb_giveback(musb, urb, status);
+ qh->is_ready = ready;
+ }

/* reclaim resources (and bandwidth) ASAP; deschedule it, and
* invalidate qh as soon as list_empty(&hep->urb_list)
@@ -428,6 +460,12 @@ static void musb_advance_schedule(struct musb *musb, struct urb *urb,
hw_ep->epnum, is_in ? 'R' : 'T', next_urb(qh));
musb_start_urb(musb, is_in, qh);
}
+
+ if (postponed_giveback) {
+ qh->is_ready = 0;
+ __musb_giveback(musb, urb, status);
+ qh->is_ready = ready;
+ }
}

static u16 musb_h_flush_rxfifo(struct musb_hw_ep *hw_ep, u16 csr)
--
2.12.0

2017-04-27 15:35:30

by Bin Liu

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

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 <[email protected]>

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...

Ideally MUSB driver should be just using HCD_BH flag and let the core to
handle the urb callback, regardless the usb transfer types.

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.

Regards,
-Bin.

> ---
> drivers/usb/musb/musb_host.c | 54 +++++++++++++++++++++++++++++++++++++-------
> 1 file changed, 46 insertions(+), 8 deletions(-)
>
> diff --git a/drivers/usb/musb/musb_host.c b/drivers/usb/musb/musb_host.c
> index ac3a4952abb4..b590c2555dab 100644
> --- a/drivers/usb/musb/musb_host.c
> +++ b/drivers/usb/musb/musb_host.c
> @@ -299,19 +299,24 @@ musb_start_urb(struct musb *musb, int is_in, struct musb_qh *qh)
> }
> }
>
> -/* Context: caller owns controller lock, IRQs are blocked */
> -static void musb_giveback(struct musb *musb, struct urb *urb, int status)
> +static void __musb_giveback(struct musb *musb, struct urb *urb, int status)
> __releases(musb->lock)
> __acquires(musb->lock)
> {
> - trace_musb_urb_gb(musb, urb);
> -
> - usb_hcd_unlink_urb_from_ep(musb->hcd, urb);
> spin_unlock(&musb->lock);
> usb_hcd_giveback_urb(musb->hcd, urb, status);
> spin_lock(&musb->lock);
> }
>
> +/* Context: caller owns controller lock, IRQs are blocked */
> +static void musb_giveback(struct musb *musb, struct urb *urb, int status)
> +{
> + trace_musb_urb_gb(musb, urb);
> +
> + usb_hcd_unlink_urb_from_ep(musb->hcd, urb);
> + __musb_giveback(musb, urb, status);
> +}
> +
> /* For bulk/interrupt endpoints only */
> static inline void musb_save_toggle(struct musb_qh *qh, int is_in,
> struct urb *urb)
> @@ -346,6 +351,7 @@ static void musb_advance_schedule(struct musb *musb, struct urb *urb,
> struct musb_hw_ep *ep = qh->hw_ep;
> int ready = qh->is_ready;
> int status;
> + int postponed_giveback = 0;
>
> status = (urb->status == -EINPROGRESS) ? 0 : urb->status;
>
> @@ -361,9 +367,35 @@ static void musb_advance_schedule(struct musb *musb, struct urb *urb,
> break;
> }
>
> - qh->is_ready = 0;
> - musb_giveback(musb, urb, status);
> - qh->is_ready = ready;
> + usb_hcd_unlink_urb_from_ep(musb->hcd, urb);
> +
> + /* 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.
> + */
> + if (is_in && qh->type == USB_ENDPOINT_XFER_ISOC
> + && !list_empty(&qh->hep->urb_list)) {
> + postponed_giveback = 1;
> + } else {
> + qh->is_ready = 0;
> + __musb_giveback(musb, urb, status);
> + qh->is_ready = ready;
> + }
>
> /* reclaim resources (and bandwidth) ASAP; deschedule it, and
> * invalidate qh as soon as list_empty(&hep->urb_list)
> @@ -428,6 +460,12 @@ static void musb_advance_schedule(struct musb *musb, struct urb *urb,
> hw_ep->epnum, is_in ? 'R' : 'T', next_urb(qh));
> musb_start_urb(musb, is_in, qh);
> }
> +
> + if (postponed_giveback) {
> + qh->is_ready = 0;
> + __musb_giveback(musb, urb, status);
> + qh->is_ready = ready;
> + }
> }
>
> static u16 musb_h_flush_rxfifo(struct musb_hw_ep *hw_ep, u16 csr)
> --
> 2.12.0
>

2017-04-27 16:27:01

by Matwey V. Kornilov

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

2017-04-27 18:35 GMT+03:00 Bin Liu <[email protected]>:
> 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 <[email protected]>
>
> 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?

>
> 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.

>
> 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.
At the same time musb_host doesn't utilize AutoReq here. I think many
other USB host controllers (OHCI?) just rely on hardware to send IN
packets in time.

> Regards,
> -Bin.
>
>> ---
>> drivers/usb/musb/musb_host.c | 54 +++++++++++++++++++++++++++++++++++++-------
>> 1 file changed, 46 insertions(+), 8 deletions(-)
>>
>> diff --git a/drivers/usb/musb/musb_host.c b/drivers/usb/musb/musb_host.c
>> index ac3a4952abb4..b590c2555dab 100644
>> --- a/drivers/usb/musb/musb_host.c
>> +++ b/drivers/usb/musb/musb_host.c
>> @@ -299,19 +299,24 @@ musb_start_urb(struct musb *musb, int is_in, struct musb_qh *qh)
>> }
>> }
>>
>> -/* Context: caller owns controller lock, IRQs are blocked */
>> -static void musb_giveback(struct musb *musb, struct urb *urb, int status)
>> +static void __musb_giveback(struct musb *musb, struct urb *urb, int status)
>> __releases(musb->lock)
>> __acquires(musb->lock)
>> {
>> - trace_musb_urb_gb(musb, urb);
>> -
>> - usb_hcd_unlink_urb_from_ep(musb->hcd, urb);
>> spin_unlock(&musb->lock);
>> usb_hcd_giveback_urb(musb->hcd, urb, status);
>> spin_lock(&musb->lock);
>> }
>>
>> +/* Context: caller owns controller lock, IRQs are blocked */
>> +static void musb_giveback(struct musb *musb, struct urb *urb, int status)
>> +{
>> + trace_musb_urb_gb(musb, urb);
>> +
>> + usb_hcd_unlink_urb_from_ep(musb->hcd, urb);
>> + __musb_giveback(musb, urb, status);
>> +}
>> +
>> /* For bulk/interrupt endpoints only */
>> static inline void musb_save_toggle(struct musb_qh *qh, int is_in,
>> struct urb *urb)
>> @@ -346,6 +351,7 @@ static void musb_advance_schedule(struct musb *musb, struct urb *urb,
>> struct musb_hw_ep *ep = qh->hw_ep;
>> int ready = qh->is_ready;
>> int status;
>> + int postponed_giveback = 0;
>>
>> status = (urb->status == -EINPROGRESS) ? 0 : urb->status;
>>
>> @@ -361,9 +367,35 @@ static void musb_advance_schedule(struct musb *musb, struct urb *urb,
>> break;
>> }
>>
>> - qh->is_ready = 0;
>> - musb_giveback(musb, urb, status);
>> - qh->is_ready = ready;
>> + usb_hcd_unlink_urb_from_ep(musb->hcd, urb);
>> +
>> + /* 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.
>> + */
>> + if (is_in && qh->type == USB_ENDPOINT_XFER_ISOC
>> + && !list_empty(&qh->hep->urb_list)) {
>> + postponed_giveback = 1;
>> + } else {
>> + qh->is_ready = 0;
>> + __musb_giveback(musb, urb, status);
>> + qh->is_ready = ready;
>> + }
>>
>> /* reclaim resources (and bandwidth) ASAP; deschedule it, and
>> * invalidate qh as soon as list_empty(&hep->urb_list)
>> @@ -428,6 +460,12 @@ static void musb_advance_schedule(struct musb *musb, struct urb *urb,
>> hw_ep->epnum, is_in ? 'R' : 'T', next_urb(qh));
>> musb_start_urb(musb, is_in, qh);
>> }
>> +
>> + if (postponed_giveback) {
>> + qh->is_ready = 0;
>> + __musb_giveback(musb, urb, status);
>> + qh->is_ready = ready;
>> + }
>> }
>>
>> static u16 musb_h_flush_rxfifo(struct musb_hw_ep *hw_ep, u16 csr)
>> --
>> 2.12.0
>>
>



--
With best regards,
Matwey V. Kornilov.
Sternberg Astronomical Institute, Lomonosov Moscow State University, Russia
119234, Moscow, Universitetsky pr-k 13, +7 (495) 9392382

2017-04-27 17:14:10

by Bin Liu

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

On Thu, Apr 27, 2017 at 07:26:31PM +0300, Matwey V. Kornilov wrote:
> 2017-04-27 18:35 GMT+03:00 Bin Liu <[email protected]>:
> > 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 <[email protected]>
> >
> > 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.

> > 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.

> At the same time musb_host doesn't utilize AutoReq here. I think many
> other USB host controllers (OHCI?) just rely on hardware to send IN
> packets in time.

For Isoch transfer, MUSB has to be programmed for every transaction, but
urb callback takes too long with spinlock held, which cause MUSB misses
issuing IN tokens.

Regards,
-Bin.

2017-04-28 07:04:56

by Matwey V. Kornilov

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

2017-04-27 20:13 GMT+03:00 Bin Liu <[email protected]>:
> On Thu, Apr 27, 2017 at 07:26:31PM +0300, Matwey V. Kornilov wrote:
>> 2017-04-27 18:35 GMT+03:00 Bin Liu <[email protected]>:
>> > 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 <[email protected]>
>> >
>> > 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.

>
>> > 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?

>
>> At the same time musb_host doesn't utilize AutoReq here. I think many
>> other USB host controllers (OHCI?) just rely on hardware to send IN
>> packets in time.
>
> For Isoch transfer, MUSB has to be programmed for every transaction, but
> urb callback takes too long with spinlock held, which cause MUSB misses
> issuing IN tokens.
>
> Regards,
> -Bin.
>



--
With best regards,
Matwey V. Kornilov.
Sternberg Astronomical Institute, Lomonosov Moscow State University, Russia
119234, Moscow, Universitetsky pr-k 13, +7 (495) 9392382

2017-04-28 11:58:47

by Bin Liu

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

On Fri, Apr 28, 2017 at 10:04:30AM +0300, Matwey V. Kornilov wrote:
> 2017-04-27 20:13 GMT+03:00 Bin Liu <[email protected]>:
> > On Thu, Apr 27, 2017 at 07:26:31PM +0300, Matwey V. Kornilov wrote:
> >> 2017-04-27 18:35 GMT+03:00 Bin Liu <[email protected]>:
> >> > 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 <[email protected]>
> >> >
> >> > 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.

2017-04-28 12:14:29

by Matwey V. Kornilov

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

which i

2017-04-28 14:58 GMT+03:00 Bin Liu <[email protected]>:
> On Fri, Apr 28, 2017 at 10:04:30AM +0300, Matwey V. Kornilov wrote:
>> 2017-04-27 20:13 GMT+03:00 Bin Liu <[email protected]>:
>> > On Thu, Apr 27, 2017 at 07:26:31PM +0300, Matwey V. Kornilov wrote:
>> >> 2017-04-27 18:35 GMT+03:00 Bin Liu <[email protected]>:
>> >> > 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 <[email protected]>
>> >> >
>> >> > 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...

It is not clear how does it hold a spinlock on a BeagleBone which is
single-core system.
I mean if it is waiting for blocked lock it will be waiting forever,
because it is in interrupt context on single core system.
Here it is waiting for finite time amount. It is also quite unlikely
that spinlocks are implemented inefficiently for arm architecture.
So, I tested with CONFIG_SMP=y which is default in my distro kernel.
Do you think it is worth to try CONFIG_SMP=n or have you already tried
UP kernel configuration?

>
> Regards,
> -Bin.
>



--
With best regards,
Matwey V. Kornilov.
Sternberg Astronomical Institute, Lomonosov Moscow State University, Russia
119234, Moscow, Universitetsky pr-k 13, +7 (495) 9392382

2017-04-28 12:43:45

by Bin Liu

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

On Fri, Apr 28, 2017 at 03:13:55PM +0300, Matwey V. Kornilov wrote:
> which i
>
> 2017-04-28 14:58 GMT+03:00 Bin Liu <[email protected]>:
> > On Fri, Apr 28, 2017 at 10:04:30AM +0300, Matwey V. Kornilov wrote:
> >> 2017-04-27 20:13 GMT+03:00 Bin Liu <[email protected]>:
> >> > On Thu, Apr 27, 2017 at 07:26:31PM +0300, Matwey V. Kornilov wrote:
> >> >> 2017-04-27 18:35 GMT+03:00 Bin Liu <[email protected]>:
> >> >> > 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 <[email protected]>
> >> >> >
> >> >> > 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...
>
> It is not clear how does it hold a spinlock on a BeagleBone which is
> single-core system.

Sorry, I have to take it back, urb giveback doesn't hold a spinlock, but
disables irq. It has been a while (a year?) since the last time I looked
this issue. Please see the call below flow.

musb_giveback() -->
usb_hcd_giveback_urb() -->
__usb_hcd_giveback_urb() --> # it gets here regardless HCD_BH flag
1765 local_irq_save(flags);
1766 urb->complete(urb);
1767 local_irq_restore(flags);

so musb driver only gets a chance to re-program the controller after
line 1766 returns, which is the urb callback in the class driver (uvc in
this case). If urb->complete() takes too long, the controller will miss
the IN tokens.

HCD_BH flag could help the situation only if urb->complete() doesn't
take that long.

> I mean if it is waiting for blocked lock it will be waiting forever,
> because it is in interrupt context on single core system.

Hope my message above explains it.

> Here it is waiting for finite time amount. It is also quite unlikely
> that spinlocks are implemented inefficiently for arm architecture.
> So, I tested with CONFIG_SMP=y which is default in my distro kernel.
> Do you think it is worth to try CONFIG_SMP=n or have you already tried
> UP kernel configuration?

CONFIG_SMP is irrelevant here. BTY, because of my laziness, I use
CONFIG_SMP in most times, if not all.

Regards,
-Bin.

2017-04-28 13:15:41

by Matwey V. Kornilov

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

2017-04-28 15:43 GMT+03:00 Bin Liu <[email protected]>:
> On Fri, Apr 28, 2017 at 03:13:55PM +0300, Matwey V. Kornilov wrote:
>> which i
>>
>> 2017-04-28 14:58 GMT+03:00 Bin Liu <[email protected]>:
>> > On Fri, Apr 28, 2017 at 10:04:30AM +0300, Matwey V. Kornilov wrote:
>> >> 2017-04-27 20:13 GMT+03:00 Bin Liu <[email protected]>:
>> >> > On Thu, Apr 27, 2017 at 07:26:31PM +0300, Matwey V. Kornilov wrote:
>> >> >> 2017-04-27 18:35 GMT+03:00 Bin Liu <[email protected]>:
>> >> >> > 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 <[email protected]>
>> >> >> >
>> >> >> > 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...
>>
>> It is not clear how does it hold a spinlock on a BeagleBone which is
>> single-core system.
>
> Sorry, I have to take it back, urb giveback doesn't hold a spinlock, but
> disables irq. It has been a while (a year?) since the last time I looked
> this issue. Please see the call below flow.
>
> musb_giveback() -->
> usb_hcd_giveback_urb() -->
> __usb_hcd_giveback_urb() --> # it gets here regardless HCD_BH flag
> 1765 local_irq_save(flags);
> 1766 urb->complete(urb);
> 1767 local_irq_restore(flags);
>
> so musb driver only gets a chance to re-program the controller after
> line 1766 returns, which is the urb callback in the class driver (uvc in
> this case). If urb->complete() takes too long, the controller will miss
> the IN tokens.
>
> HCD_BH flag could help the situation only if urb->complete() doesn't
> take that long.

Sure, I think that the question is why urb->complete() itself takes so
long only (?) at am335x.

>
>> I mean if it is waiting for blocked lock it will be waiting forever,
>> because it is in interrupt context on single core system.
>
> Hope my message above explains it.
>
>> Here it is waiting for finite time amount. It is also quite unlikely
>> that spinlocks are implemented inefficiently for arm architecture.
>> So, I tested with CONFIG_SMP=y which is default in my distro kernel.
>> Do you think it is worth to try CONFIG_SMP=n or have you already tried
>> UP kernel configuration?
>
> CONFIG_SMP is irrelevant here. BTY, because of my laziness, I use
> CONFIG_SMP in most times, if not all.
>
> Regards,
> -Bin.
>



--
With best regards,
Matwey V. Kornilov.
Sternberg Astronomical Institute, Lomonosov Moscow State University, Russia
119234, Moscow, Universitetsky pr-k 13, +7 (495) 9392382

2017-04-28 13:30:35

by Bin Liu

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

On Fri, Apr 28, 2017 at 04:15:09PM +0300, Matwey V. Kornilov wrote:
> 2017-04-28 15:43 GMT+03:00 Bin Liu <[email protected]>:
> > On Fri, Apr 28, 2017 at 03:13:55PM +0300, Matwey V. Kornilov wrote:
> >> which i
> >>
> >> 2017-04-28 14:58 GMT+03:00 Bin Liu <[email protected]>:
> >> > On Fri, Apr 28, 2017 at 10:04:30AM +0300, Matwey V. Kornilov wrote:
> >> >> 2017-04-27 20:13 GMT+03:00 Bin Liu <[email protected]>:
> >> >> > On Thu, Apr 27, 2017 at 07:26:31PM +0300, Matwey V. Kornilov wrote:
> >> >> >> 2017-04-27 18:35 GMT+03:00 Bin Liu <[email protected]>:
> >> >> >> > 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 <[email protected]>
> >> >> >> >
> >> >> >> > 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...
> >>
> >> It is not clear how does it hold a spinlock on a BeagleBone which is
> >> single-core system.
> >
> > Sorry, I have to take it back, urb giveback doesn't hold a spinlock, but
> > disables irq. It has been a while (a year?) since the last time I looked
> > this issue. Please see the call below flow.
> >
> > musb_giveback() -->
> > usb_hcd_giveback_urb() -->
> > __usb_hcd_giveback_urb() --> # it gets here regardless HCD_BH flag
> > 1765 local_irq_save(flags);
> > 1766 urb->complete(urb);
> > 1767 local_irq_restore(flags);
> >
> > so musb driver only gets a chance to re-program the controller after
> > line 1766 returns, which is the urb callback in the class driver (uvc in
> > this case). If urb->complete() takes too long, the controller will miss
> > the IN tokens.
> >
> > HCD_BH flag could help the situation only if urb->complete() doesn't
> > take that long.
>
> Sure, I think that the question is why urb->complete() itself takes so
> long only (?) at am335x.

This is what I meant. I haven't checked other platforms yet, but at
least it seems the issue only reported on am335x as far as I am aware.

>
> >
> >> I mean if it is waiting for blocked lock it will be waiting forever,
> >> because it is in interrupt context on single core system.
> >
> > Hope my message above explains it.
> >
> >> Here it is waiting for finite time amount. It is also quite unlikely
> >> that spinlocks are implemented inefficiently for arm architecture.
> >> So, I tested with CONFIG_SMP=y which is default in my distro kernel.
> >> Do you think it is worth to try CONFIG_SMP=n or have you already tried
> >> UP kernel configuration?
> >
> > CONFIG_SMP is irrelevant here. BTY, because of my laziness, I use
> > CONFIG_SMP in most times, if not all.
> >
> > Regards,
> > -Bin.
> >
>
>
>
> --
> With best regards,
> Matwey V. Kornilov.
> Sternberg Astronomical Institute, Lomonosov Moscow State University, Russia
> 119234, Moscow, Universitetsky pr-k 13, +7 (495) 9392382

2017-04-29 08:17:21

by Matwey V. Kornilov

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

2017-04-28 16:30 GMT+03:00 Bin Liu <[email protected]>:
> On Fri, Apr 28, 2017 at 04:15:09PM +0300, Matwey V. Kornilov wrote:
>> 2017-04-28 15:43 GMT+03:00 Bin Liu <[email protected]>:
>> > On Fri, Apr 28, 2017 at 03:13:55PM +0300, Matwey V. Kornilov wrote:
>> >> which i
>> >>
>> >> 2017-04-28 14:58 GMT+03:00 Bin Liu <[email protected]>:
>> >> > On Fri, Apr 28, 2017 at 10:04:30AM +0300, Matwey V. Kornilov wrote:
>> >> >> 2017-04-27 20:13 GMT+03:00 Bin Liu <[email protected]>:
>> >> >> > On Thu, Apr 27, 2017 at 07:26:31PM +0300, Matwey V. Kornilov wrote:
>> >> >> >> 2017-04-27 18:35 GMT+03:00 Bin Liu <[email protected]>:
>> >> >> >> > 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 <[email protected]>
>> >> >> >> >
>> >> >> >> > 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...
>> >>
>> >> It is not clear how does it hold a spinlock on a BeagleBone which is
>> >> single-core system.
>> >
>> > Sorry, I have to take it back, urb giveback doesn't hold a spinlock, but
>> > disables irq. It has been a while (a year?) since the last time I looked
>> > this issue. Please see the call below flow.
>> >
>> > musb_giveback() -->
>> > usb_hcd_giveback_urb() -->
>> > __usb_hcd_giveback_urb() --> # it gets here regardless HCD_BH flag
>> > 1765 local_irq_save(flags);
>> > 1766 urb->complete(urb);
>> > 1767 local_irq_restore(flags);
>> >
>> > so musb driver only gets a chance to re-program the controller after
>> > line 1766 returns, which is the urb callback in the class driver (uvc in
>> > this case). If urb->complete() takes too long, the controller will miss
>> > the IN tokens.
>> >
>> > HCD_BH flag could help the situation only if urb->complete() doesn't
>> > take that long.
>>
>> Sure, I think that the question is why urb->complete() itself takes so
>> long only (?) at am335x.
>
> This is what I meant. I haven't checked other platforms yet, but at
> least it seems the issue only reported on am335x as far as I am aware.

Attached here are ftraces for am335x and x86 respectively.
pwc_isoc_handler() normally spends most of the time in usb_submit_urb() at x86.
same for am335x, expect that from some point pwc_isoc_handler() starts
spending much time for something else.

>
>>
>> >
>> >> I mean if it is waiting for blocked lock it will be waiting forever,
>> >> because it is in interrupt context on single core system.
>> >
>> > Hope my message above explains it.
>> >
>> >> Here it is waiting for finite time amount. It is also quite unlikely
>> >> that spinlocks are implemented inefficiently for arm architecture.
>> >> So, I tested with CONFIG_SMP=y which is default in my distro kernel.
>> >> Do you think it is worth to try CONFIG_SMP=n or have you already tried
>> >> UP kernel configuration?
>> >
>> > CONFIG_SMP is irrelevant here. BTY, because of my laziness, I use
>> > CONFIG_SMP in most times, if not all.
>> >
>> > Regards,
>> > -Bin.
>> >
>>
>>
>>
>> --
>> With best regards,
>> Matwey V. Kornilov.
>> Sternberg Astronomical Institute, Lomonosov Moscow State University, Russia
>> 119234, Moscow, Universitetsky pr-k 13, +7 (495) 9392382
>



--
With best regards,
Matwey V. Kornilov.
Sternberg Astronomical Institute, Lomonosov Moscow State University, Russia
119234, Moscow, Universitetsky pr-k 13, +7 (495) 9392382

Attachments:

2017-04-29 14:25:23

by Matwey V. Kornilov

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

2017-04-29 11:16 GMT+03:00 Matwey V. Kornilov <[email protected]>:
> 2017-04-28 16:30 GMT+03:00 Bin Liu <[email protected]>:
>> On Fri, Apr 28, 2017 at 04:15:09PM +0300, Matwey V. Kornilov wrote:
>>> 2017-04-28 15:43 GMT+03:00 Bin Liu <[email protected]>:
>>> > On Fri, Apr 28, 2017 at 03:13:55PM +0300, Matwey V. Kornilov wrote:
>>> >> which i
>>> >>
>>> >> 2017-04-28 14:58 GMT+03:00 Bin Liu <[email protected]>:
>>> >> > On Fri, Apr 28, 2017 at 10:04:30AM +0300, Matwey V. Kornilov wrote:
>>> >> >> 2017-04-27 20:13 GMT+03:00 Bin Liu <[email protected]>:
>>> >> >> > On Thu, Apr 27, 2017 at 07:26:31PM +0300, Matwey V. Kornilov wrote:
>>> >> >> >> 2017-04-27 18:35 GMT+03:00 Bin Liu <[email protected]>:
>>> >> >> >> > 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 <[email protected]>
>>> >> >> >> >
>>> >> >> >> > 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...
>>> >>
>>> >> It is not clear how does it hold a spinlock on a BeagleBone which is
>>> >> single-core system.
>>> >
>>> > Sorry, I have to take it back, urb giveback doesn't hold a spinlock, but
>>> > disables irq. It has been a while (a year?) since the last time I looked
>>> > this issue. Please see the call below flow.
>>> >
>>> > musb_giveback() -->
>>> > usb_hcd_giveback_urb() -->
>>> > __usb_hcd_giveback_urb() --> # it gets here regardless HCD_BH flag
>>> > 1765 local_irq_save(flags);
>>> > 1766 urb->complete(urb);
>>> > 1767 local_irq_restore(flags);
>>> >
>>> > so musb driver only gets a chance to re-program the controller after
>>> > line 1766 returns, which is the urb callback in the class driver (uvc in
>>> > this case). If urb->complete() takes too long, the controller will miss
>>> > the IN tokens.
>>> >
>>> > HCD_BH flag could help the situation only if urb->complete() doesn't
>>> > take that long.
>>>
>>> Sure, I think that the question is why urb->complete() itself takes so
>>> long only (?) at am335x.
>>
>> This is what I meant. I haven't checked other platforms yet, but at
>> least it seems the issue only reported on am335x as far as I am aware.
>
> Attached here are ftraces for am335x and x86 respectively.
> pwc_isoc_handler() normally spends most of the time in usb_submit_urb() at x86.
> same for am335x, expect that from some point pwc_isoc_handler() starts
> spending much time for something else.

Believe you or not, it takes 30usec to mempcy 950 bytes in
pwc_isoc_handler. Given urb has 10 packages, it takes 300usec only
just to copy memory from urb to internal data structures.

<idle>-0 [000] dnh1 53.428680:
pwc_isoc_handler_pre_compact: urb=cf816e00 status=0 nop=10
<idle>-0 [000] dnh1 53.428683:
pwc_isoc_handler_memcpy_begin: urb=cf816e00 len=956
<idle>-0 [000] dnh1 53.428713:
pwc_isoc_handler_memcpy_end: urb=cf816e00 status=0 nop=10
<idle>-0 [000] dnh1 53.428715:
pwc_isoc_handler_memcpy_begin: urb=cf816e00 len=956
<idle>-0 [000] dnh1 53.428743:
pwc_isoc_handler_memcpy_end: urb=cf816e00 status=0 nop=10
<idle>-0 [000] dnh1 53.428746:
pwc_isoc_handler_memcpy_begin: urb=cf816e00 len=956
<idle>-0 [000] dnh1 53.428775:
pwc_isoc_handler_memcpy_end: urb=cf816e00 status=0 nop=10
<idle>-0 [000] dnh1 53.428777:
pwc_isoc_handler_memcpy_begin: urb=cf816e00 len=956
<idle>-0 [000] dnh1 53.428807:
pwc_isoc_handler_memcpy_end: urb=cf816e00 status=0 nop=10
<idle>-0 [000] dnh1 53.428809:
pwc_isoc_handler_memcpy_begin: urb=cf816e00 len=956
<idle>-0 [000] dnh1 53.428838:
pwc_isoc_handler_memcpy_end: urb=cf816e00 status=0 nop=10
<idle>-0 [000] dnh1 53.428840:
pwc_isoc_handler_memcpy_begin: urb=cf816e00 len=956
<idle>-0 [000] dnh1 53.428869:
pwc_isoc_handler_memcpy_end: urb=cf816e00 status=0 nop=10
<idle>-0 [000] dnh1 53.428871:
pwc_isoc_handler_memcpy_begin: urb=cf816e00 len=956
<idle>-0 [000] dnh1 53.428900:
pwc_isoc_handler_memcpy_end: urb=cf816e00 status=0 nop=10
<idle>-0 [000] dnh1 53.428902:
pwc_isoc_handler_memcpy_begin: urb=cf816e00 len=956
<idle>-0 [000] dnh1 53.428932:
pwc_isoc_handler_memcpy_end: urb=cf816e00 status=0 nop=10
<idle>-0 [000] dnh1 53.428934:
pwc_isoc_handler_memcpy_begin: urb=cf816e00 len=956
<idle>-0 [000] dnh1 53.428963:
pwc_isoc_handler_memcpy_end: urb=cf816e00 status=0 nop=10
<idle>-0 [000] dnh1 53.428966:
pwc_isoc_handler_memcpy_begin: urb=cf816e00 len=956
<idle>-0 [000] dnh1 53.428995:
pwc_isoc_handler_memcpy_end: urb=cf816e00 status=0 nop=10
<idle>-0 [000] dnh1 53.428997:
pwc_isoc_handler_pre_submit_urb: urb=cf816e00 status=0 nop=10

>
>>
>>>
>>> >
>>> >> I mean if it is waiting for blocked lock it will be waiting forever,
>>> >> because it is in interrupt context on single core system.
>>> >
>>> > Hope my message above explains it.
>>> >
>>> >> Here it is waiting for finite time amount. It is also quite unlikely
>>> >> that spinlocks are implemented inefficiently for arm architecture.
>>> >> So, I tested with CONFIG_SMP=y which is default in my distro kernel.
>>> >> Do you think it is worth to try CONFIG_SMP=n or have you already tried
>>> >> UP kernel configuration?
>>> >
>>> > CONFIG_SMP is irrelevant here. BTY, because of my laziness, I use
>>> > CONFIG_SMP in most times, if not all.
>>> >
>>> > Regards,
>>> > -Bin.
>>> >
>>>
>>>
>>>
>>> --
>>> With best regards,
>>> Matwey V. Kornilov.
>>> Sternberg Astronomical Institute, Lomonosov Moscow State University, Russia
>>> 119234, Moscow, Universitetsky pr-k 13, +7 (495) 9392382
>>
>
>
>
> --
> With best regards,
> Matwey V. Kornilov.
> Sternberg Astronomical Institute, Lomonosov Moscow State University, Russia
> 119234, Moscow, Universitetsky pr-k 13, +7 (495) 9392382



--
With best regards,
Matwey V. Kornilov.
Sternberg Astronomical Institute, Lomonosov Moscow State University, Russia
119234, Moscow, Universitetsky pr-k 13, +7 (495) 9392382

2017-04-30 16:20:15

by Matwey V. Kornilov

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

2017-04-29 17:24 GMT+03:00 Matwey V. Kornilov <[email protected]>:
> 2017-04-29 11:16 GMT+03:00 Matwey V. Kornilov <[email protected]>:
>> 2017-04-28 16:30 GMT+03:00 Bin Liu <[email protected]>:
>>> On Fri, Apr 28, 2017 at 04:15:09PM +0300, Matwey V. Kornilov wrote:
>>>> 2017-04-28 15:43 GMT+03:00 Bin Liu <[email protected]>:
>>>> > On Fri, Apr 28, 2017 at 03:13:55PM +0300, Matwey V. Kornilov wrote:
>>>> >> which i
>>>> >>
>>>> >> 2017-04-28 14:58 GMT+03:00 Bin Liu <[email protected]>:
>>>> >> > On Fri, Apr 28, 2017 at 10:04:30AM +0300, Matwey V. Kornilov wrote:
>>>> >> >> 2017-04-27 20:13 GMT+03:00 Bin Liu <[email protected]>:
>>>> >> >> > On Thu, Apr 27, 2017 at 07:26:31PM +0300, Matwey V. Kornilov wrote:
>>>> >> >> >> 2017-04-27 18:35 GMT+03:00 Bin Liu <[email protected]>:
>>>> >> >> >> > 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 <[email protected]>
>>>> >> >> >> >
>>>> >> >> >> > 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...
>>>> >>
>>>> >> It is not clear how does it hold a spinlock on a BeagleBone which is
>>>> >> single-core system.
>>>> >
>>>> > Sorry, I have to take it back, urb giveback doesn't hold a spinlock, but
>>>> > disables irq. It has been a while (a year?) since the last time I looked
>>>> > this issue. Please see the call below flow.
>>>> >
>>>> > musb_giveback() -->
>>>> > usb_hcd_giveback_urb() -->
>>>> > __usb_hcd_giveback_urb() --> # it gets here regardless HCD_BH flag
>>>> > 1765 local_irq_save(flags);
>>>> > 1766 urb->complete(urb);
>>>> > 1767 local_irq_restore(flags);
>>>> >
>>>> > so musb driver only gets a chance to re-program the controller after
>>>> > line 1766 returns, which is the urb callback in the class driver (uvc in
>>>> > this case). If urb->complete() takes too long, the controller will miss
>>>> > the IN tokens.
>>>> >
>>>> > HCD_BH flag could help the situation only if urb->complete() doesn't
>>>> > take that long.
>>>>
>>>> Sure, I think that the question is why urb->complete() itself takes so
>>>> long only (?) at am335x.
>>>
>>> This is what I meant. I haven't checked other platforms yet, but at
>>> least it seems the issue only reported on am335x as far as I am aware.
>>
>> Attached here are ftraces for am335x and x86 respectively.
>> pwc_isoc_handler() normally spends most of the time in usb_submit_urb() at x86.
>> same for am335x, expect that from some point pwc_isoc_handler() starts
>> spending much time for something else.
>
> Believe you or not, it takes 30usec to mempcy 950 bytes in
> pwc_isoc_handler. Given urb has 10 packages, it takes 300usec only
> just to copy memory from urb to internal data structures.
>
> <idle>-0 [000] dnh1 53.428680:
> pwc_isoc_handler_pre_compact: urb=cf816e00 status=0 nop=10
> <idle>-0 [000] dnh1 53.428683:
> pwc_isoc_handler_memcpy_begin: urb=cf816e00 len=956
> <idle>-0 [000] dnh1 53.428713:
> pwc_isoc_handler_memcpy_end: urb=cf816e00 status=0 nop=10
> <idle>-0 [000] dnh1 53.428715:
> pwc_isoc_handler_memcpy_begin: urb=cf816e00 len=956
> <idle>-0 [000] dnh1 53.428743:
> pwc_isoc_handler_memcpy_end: urb=cf816e00 status=0 nop=10
> <idle>-0 [000] dnh1 53.428746:
> pwc_isoc_handler_memcpy_begin: urb=cf816e00 len=956
> <idle>-0 [000] dnh1 53.428775:
> pwc_isoc_handler_memcpy_end: urb=cf816e00 status=0 nop=10
> <idle>-0 [000] dnh1 53.428777:
> pwc_isoc_handler_memcpy_begin: urb=cf816e00 len=956
> <idle>-0 [000] dnh1 53.428807:
> pwc_isoc_handler_memcpy_end: urb=cf816e00 status=0 nop=10
> <idle>-0 [000] dnh1 53.428809:
> pwc_isoc_handler_memcpy_begin: urb=cf816e00 len=956
> <idle>-0 [000] dnh1 53.428838:
> pwc_isoc_handler_memcpy_end: urb=cf816e00 status=0 nop=10
> <idle>-0 [000] dnh1 53.428840:
> pwc_isoc_handler_memcpy_begin: urb=cf816e00 len=956
> <idle>-0 [000] dnh1 53.428869:
> pwc_isoc_handler_memcpy_end: urb=cf816e00 status=0 nop=10
> <idle>-0 [000] dnh1 53.428871:
> pwc_isoc_handler_memcpy_begin: urb=cf816e00 len=956
> <idle>-0 [000] dnh1 53.428900:
> pwc_isoc_handler_memcpy_end: urb=cf816e00 status=0 nop=10
> <idle>-0 [000] dnh1 53.428902:
> pwc_isoc_handler_memcpy_begin: urb=cf816e00 len=956
> <idle>-0 [000] dnh1 53.428932:
> pwc_isoc_handler_memcpy_end: urb=cf816e00 status=0 nop=10
> <idle>-0 [000] dnh1 53.428934:
> pwc_isoc_handler_memcpy_begin: urb=cf816e00 len=956
> <idle>-0 [000] dnh1 53.428963:
> pwc_isoc_handler_memcpy_end: urb=cf816e00 status=0 nop=10
> <idle>-0 [000] dnh1 53.428966:
> pwc_isoc_handler_memcpy_begin: urb=cf816e00 len=956
> <idle>-0 [000] dnh1 53.428995:
> pwc_isoc_handler_memcpy_end: urb=cf816e00 status=0 nop=10
> <idle>-0 [000] dnh1 53.428997:
> pwc_isoc_handler_pre_submit_urb: urb=cf816e00 status=0 nop=10
>

Both source and destination are 4-bytes aligned. dest is allocated
using vzalloc().

>>
>>>
>>>>
>>>> >
>>>> >> I mean if it is waiting for blocked lock it will be waiting forever,
>>>> >> because it is in interrupt context on single core system.
>>>> >
>>>> > Hope my message above explains it.
>>>> >
>>>> >> Here it is waiting for finite time amount. It is also quite unlikely
>>>> >> that spinlocks are implemented inefficiently for arm architecture.
>>>> >> So, I tested with CONFIG_SMP=y which is default in my distro kernel.
>>>> >> Do you think it is worth to try CONFIG_SMP=n or have you already tried
>>>> >> UP kernel configuration?
>>>> >
>>>> > CONFIG_SMP is irrelevant here. BTY, because of my laziness, I use
>>>> > CONFIG_SMP in most times, if not all.
>>>> >
>>>> > Regards,
>>>> > -Bin.
>>>> >
>>>>
>>>>
>>>>
>>>> --
>>>> With best regards,
>>>> Matwey V. Kornilov.
>>>> Sternberg Astronomical Institute, Lomonosov Moscow State University, Russia
>>>> 119234, Moscow, Universitetsky pr-k 13, +7 (495) 9392382
>>>
>>
>>
>>
>> --
>> With best regards,
>> Matwey V. Kornilov.
>> Sternberg Astronomical Institute, Lomonosov Moscow State University, Russia
>> 119234, Moscow, Universitetsky pr-k 13, +7 (495) 9392382
>
>
>
> --
> With best regards,
> Matwey V. Kornilov.
> Sternberg Astronomical Institute, Lomonosov Moscow State University, Russia
> 119234, Moscow, Universitetsky pr-k 13, +7 (495) 9392382



--
With best regards,
Matwey V. Kornilov.
Sternberg Astronomical Institute, Lomonosov Moscow State University, Russia
119234, Moscow, Universitetsky pr-k 13, +7 (495) 9392382

2017-11-16 23:26:50

by Matwey V. Kornilov

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

2017-11-16 19:32 GMT+03:00 Bin Liu <[email protected]>:
> Hi,
>
> On Wed, Nov 15, 2017 at 06:19:08PM +0300, Matwey V. Kornilov wrote:
>> The issue is also present in 4.9.60-ti-r75
>>
>> 2017-11-04 17:05 GMT+03:00 Matwey V. Kornilov <[email protected]>:
>> > Hi Bin,
>> >
>> > I've just checked that the issue is still present in 4.13.10.
>
> I am not aware of any work having been done for this yet.

Well, please tell If I can help somehow.

>
> Regards,
> -Bin.
>



--
With best regards,
Matwey V. Kornilov.
Sternberg Astronomical Institute, Lomonosov Moscow State University, Russia
119234, Moscow, Universitetsky pr-k 13, +7 (495) 9392382

From 1584256420378822113@xxx Thu Nov 16 20:37:38 +0000 2017
X-GM-THRID: 1583144674052621439
X-Gmail-Labels: Inbox,Category Forums,HistoricalUnread

2017-11-16 20:37:38

by Bin Liu

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

Hi,

On Wed, Nov 15, 2017 at 06:19:08PM +0300, Matwey V. Kornilov wrote:
> The issue is also present in 4.9.60-ti-r75
>
> 2017-11-04 17:05 GMT+03:00 Matwey V. Kornilov <[email protected]>:
> > Hi Bin,
> >
> > I've just checked that the issue is still present in 4.13.10.

I am not aware of any work having been done for this yet.

Regards,
-Bin.

From 1584150427298519412@xxx Wed Nov 15 16:32:55 +0000 2017
X-GM-THRID: 1583144674052621439
X-Gmail-Labels: Inbox,Category Forums,HistoricalUnread

2017-11-15 16:32:56

by Matwey V. Kornilov

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

The issue is also present in 4.9.60-ti-r75

2017-11-04 17:05 GMT+03:00 Matwey V. Kornilov <[email protected]>:
> Hi Bin,
>
> I've just checked that the issue is still present in 4.13.10.
>
> 2017-04-27 13:20 GMT+03:00 Matwey V. Kornilov <[email protected]>:
>> 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 <[email protected]>
>> ---
>> drivers/usb/musb/musb_host.c | 54 +++++++++++++++++++++++++++++++++++++-------
>> 1 file changed, 46 insertions(+), 8 deletions(-)
>>
>> diff --git a/drivers/usb/musb/musb_host.c b/drivers/usb/musb/musb_host.c
>> index ac3a4952abb4..b590c2555dab 100644
>> --- a/drivers/usb/musb/musb_host.c
>> +++ b/drivers/usb/musb/musb_host.c
>> @@ -299,19 +299,24 @@ musb_start_urb(struct musb *musb, int is_in, struct musb_qh *qh)
>> }
>> }
>>
>> -/* Context: caller owns controller lock, IRQs are blocked */
>> -static void musb_giveback(struct musb *musb, struct urb *urb, int status)
>> +static void __musb_giveback(struct musb *musb, struct urb *urb, int status)
>> __releases(musb->lock)
>> __acquires(musb->lock)
>> {
>> - trace_musb_urb_gb(musb, urb);
>> -
>> - usb_hcd_unlink_urb_from_ep(musb->hcd, urb);
>> spin_unlock(&musb->lock);
>> usb_hcd_giveback_urb(musb->hcd, urb, status);
>> spin_lock(&musb->lock);
>> }
>>
>> +/* Context: caller owns controller lock, IRQs are blocked */
>> +static void musb_giveback(struct musb *musb, struct urb *urb, int status)
>> +{
>> + trace_musb_urb_gb(musb, urb);
>> +
>> + usb_hcd_unlink_urb_from_ep(musb->hcd, urb);
>> + __musb_giveback(musb, urb, status);
>> +}
>> +
>> /* For bulk/interrupt endpoints only */
>> static inline void musb_save_toggle(struct musb_qh *qh, int is_in,
>> struct urb *urb)
>> @@ -346,6 +351,7 @@ static void musb_advance_schedule(struct musb *musb, struct urb *urb,
>> struct musb_hw_ep *ep = qh->hw_ep;
>> int ready = qh->is_ready;
>> int status;
>> + int postponed_giveback = 0;
>>
>> status = (urb->status == -EINPROGRESS) ? 0 : urb->status;
>>
>> @@ -361,9 +367,35 @@ static void musb_advance_schedule(struct musb *musb, struct urb *urb,
>> break;
>> }
>>
>> - qh->is_ready = 0;
>> - musb_giveback(musb, urb, status);
>> - qh->is_ready = ready;
>> + usb_hcd_unlink_urb_from_ep(musb->hcd, urb);
>> +
>> + /* 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.
>> + */
>> + if (is_in && qh->type == USB_ENDPOINT_XFER_ISOC
>> + && !list_empty(&qh->hep->urb_list)) {
>> + postponed_giveback = 1;
>> + } else {
>> + qh->is_ready = 0;
>> + __musb_giveback(musb, urb, status);
>> + qh->is_ready = ready;
>> + }
>>
>> /* reclaim resources (and bandwidth) ASAP; deschedule it, and
>> * invalidate qh as soon as list_empty(&hep->urb_list)
>> @@ -428,6 +460,12 @@ static void musb_advance_schedule(struct musb *musb, struct urb *urb,
>> hw_ep->epnum, is_in ? 'R' : 'T', next_urb(qh));
>> musb_start_urb(musb, is_in, qh);
>> }
>> +
>> + if (postponed_giveback) {
>> + qh->is_ready = 0;
>> + __musb_giveback(musb, urb, status);
>> + qh->is_ready = ready;
>> + }
>> }
>>
>> static u16 musb_h_flush_rxfifo(struct musb_hw_ep *hw_ep, u16 csr)
>> --
>> 2.12.0
>>
>
>
>
> --
> With best regards,
> Matwey V. Kornilov.
> Sternberg Astronomical Institute, Lomonosov Moscow State University, Russia
> 119234, Moscow, Universitetsky pr-k 13, +7 (495) 9392382



--
With best regards,
Matwey V. Kornilov.
Sternberg Astronomical Institute, Lomonosov Moscow State University, Russia
119234, Moscow, Universitetsky pr-k 13, +7 (495) 9392382

From 1583144674052621439@xxx Sat Nov 04 14:06:54 +0000 2017
X-GM-THRID: 1583144674052621439
X-Gmail-Labels: Inbox,Category Forums,HistoricalUnread

2017-11-04 14:06:54

by Matwey V. Kornilov

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

Hi Bin,

I've just checked that the issue is still present in 4.13.10.

2017-04-27 13:20 GMT+03:00 Matwey V. Kornilov <[email protected]>:
> 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 <[email protected]>
> ---
> drivers/usb/musb/musb_host.c | 54 +++++++++++++++++++++++++++++++++++++-------
> 1 file changed, 46 insertions(+), 8 deletions(-)
>
> diff --git a/drivers/usb/musb/musb_host.c b/drivers/usb/musb/musb_host.c
> index ac3a4952abb4..b590c2555dab 100644
> --- a/drivers/usb/musb/musb_host.c
> +++ b/drivers/usb/musb/musb_host.c
> @@ -299,19 +299,24 @@ musb_start_urb(struct musb *musb, int is_in, struct musb_qh *qh)
> }
> }
>
> -/* Context: caller owns controller lock, IRQs are blocked */
> -static void musb_giveback(struct musb *musb, struct urb *urb, int status)
> +static void __musb_giveback(struct musb *musb, struct urb *urb, int status)
> __releases(musb->lock)
> __acquires(musb->lock)
> {
> - trace_musb_urb_gb(musb, urb);
> -
> - usb_hcd_unlink_urb_from_ep(musb->hcd, urb);
> spin_unlock(&musb->lock);
> usb_hcd_giveback_urb(musb->hcd, urb, status);
> spin_lock(&musb->lock);
> }
>
> +/* Context: caller owns controller lock, IRQs are blocked */
> +static void musb_giveback(struct musb *musb, struct urb *urb, int status)
> +{
> + trace_musb_urb_gb(musb, urb);
> +
> + usb_hcd_unlink_urb_from_ep(musb->hcd, urb);
> + __musb_giveback(musb, urb, status);
> +}
> +
> /* For bulk/interrupt endpoints only */
> static inline void musb_save_toggle(struct musb_qh *qh, int is_in,
> struct urb *urb)
> @@ -346,6 +351,7 @@ static void musb_advance_schedule(struct musb *musb, struct urb *urb,
> struct musb_hw_ep *ep = qh->hw_ep;
> int ready = qh->is_ready;
> int status;
> + int postponed_giveback = 0;
>
> status = (urb->status == -EINPROGRESS) ? 0 : urb->status;
>
> @@ -361,9 +367,35 @@ static void musb_advance_schedule(struct musb *musb, struct urb *urb,
> break;
> }
>
> - qh->is_ready = 0;
> - musb_giveback(musb, urb, status);
> - qh->is_ready = ready;
> + usb_hcd_unlink_urb_from_ep(musb->hcd, urb);
> +
> + /* 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.
> + */
> + if (is_in && qh->type == USB_ENDPOINT_XFER_ISOC
> + && !list_empty(&qh->hep->urb_list)) {
> + postponed_giveback = 1;
> + } else {
> + qh->is_ready = 0;
> + __musb_giveback(musb, urb, status);
> + qh->is_ready = ready;
> + }
>
> /* reclaim resources (and bandwidth) ASAP; deschedule it, and
> * invalidate qh as soon as list_empty(&hep->urb_list)
> @@ -428,6 +460,12 @@ static void musb_advance_schedule(struct musb *musb, struct urb *urb,
> hw_ep->epnum, is_in ? 'R' : 'T', next_urb(qh));
> musb_start_urb(musb, is_in, qh);
> }
> +
> + if (postponed_giveback) {
> + qh->is_ready = 0;
> + __musb_giveback(musb, urb, status);
> + qh->is_ready = ready;
> + }
> }
>
> static u16 musb_h_flush_rxfifo(struct musb_hw_ep *hw_ep, u16 csr)
> --
> 2.12.0
>



--
With best regards,
Matwey V. Kornilov.
Sternberg Astronomical Institute, Lomonosov Moscow State University, Russia
119234, Moscow, Universitetsky pr-k 13, +7 (495) 9392382

From 1584268667058033944@xxx Thu Nov 16 23:52:18 +0000 2017
X-GM-THRID: 1584263785940925114
X-Gmail-Labels: Inbox,Category Forums,HistoricalUnread