* [PATCH] usb: musb: musb_host: Introduce postponed URB giveback @ 2017-04-27 10:20 Matwey V. Kornilov 2017-04-27 15:35 ` Bin Liu 2017-11-04 14:05 ` Matwey V. Kornilov 0 siblings, 2 replies; 17+ messages in thread From: Matwey V. Kornilov @ 2017-04-27 10:20 UTC (permalink / raw) To: b-liu, gregkh; +Cc: linux-usb, linux-kernel, Matwey V. Kornilov This commit changes the order of actions undertaken in musb_advance_schedule() in order to overcome issue with broken isochronous transfer [1]. There is no harm to split musb_giveback into two pieces. The first unlinks finished urb, the second givebacks it. The issue here that givebacking may be quite time-consuming due to urb->complete() call. As it happens in case of pwc-driven web cameras. It may take about 0.5 ms to call __musb_giveback() that calls urb->callback() internally. Under specific circumstances setting MUSB_RXCSR_H_REQPKT in subsequent musb_start_urb() for the next urb will be too late to produce physical IN packet. Since auto req is not used by this module the exchange would be as the following: [ ] 7.220456 d= 0.000997 [182 + 3.667] [ 3] IN : 4.5 [ T ] 7.220459 d= 0.000003 [182 + 7.000] [800] DATA0: [skipped] [ ] 7.222456 d= 0.001997 [184 + 3.667] [ 3] IN : 4.5 [ ] 7.222459 d= 0.000003 [184 + 7.000] [ 3] DATA0: 00 00 It is known that missed IN in isochronous mode makes some perepherial broken. For instance, pwc-driven or uvc-driven web cameras. In order to workaround this issue we postpone calling urb->callback() after setting MUSB_RXCSR_H_REQPKT for the next urb if there is the next urb pending in queue. [1] https://www.spinics.net/lists/linux-usb/msg145747.html Fixes: f551e1352983 ("Revert "usb: musb: musb_host: Enable HCD_BH flag to handle urb return in bottom half"") Signed-off-by: Matwey V. Kornilov <matwey@sai.msu.ru> --- 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 ^ permalink raw reply related [flat|nested] 17+ messages in thread
* Re: [PATCH] usb: musb: musb_host: Introduce postponed URB giveback 2017-04-27 10:20 [PATCH] usb: musb: musb_host: Introduce postponed URB giveback Matwey V. Kornilov @ 2017-04-27 15:35 ` Bin Liu 2017-04-27 16:26 ` Matwey V. Kornilov 2017-11-04 14:05 ` Matwey V. Kornilov 1 sibling, 1 reply; 17+ messages in thread From: Bin Liu @ 2017-04-27 15:35 UTC (permalink / raw) To: Matwey V. Kornilov; +Cc: gregkh, linux-usb, linux-kernel Hi Matwey, On Thu, Apr 27, 2017 at 01:20:33PM +0300, Matwey V. Kornilov wrote: > This commit changes the order of actions undertaken in > musb_advance_schedule() in order to overcome issue with broken > isochronous transfer [1]. > > There is no harm to split musb_giveback into two pieces. The first > unlinks finished urb, the second givebacks it. The issue here that > givebacking may be quite time-consuming due to urb->complete() call. > As it happens in case of pwc-driven web cameras. It may take about 0.5 > ms to call __musb_giveback() that calls urb->callback() internally. > Under specific circumstances setting MUSB_RXCSR_H_REQPKT in subsequent > musb_start_urb() for the next urb will be too late to produce physical > IN packet. Since auto req is not used by this module the exchange > would be as the following: > > [ ] 7.220456 d= 0.000997 [182 + 3.667] [ 3] IN : 4.5 > [ T ] 7.220459 d= 0.000003 [182 + 7.000] [800] DATA0: [skipped] > [ ] 7.222456 d= 0.001997 [184 + 3.667] [ 3] IN : 4.5 > [ ] 7.222459 d= 0.000003 [184 + 7.000] [ 3] DATA0: 00 00 > > It is known that missed IN in isochronous mode makes some > perepherial broken. For instance, pwc-driven or uvc-driven > web cameras. > In order to workaround this issue we postpone calling > urb->callback() after setting MUSB_RXCSR_H_REQPKT for the > next urb if there is the next urb pending in queue. > > [1] https://www.spinics.net/lists/linux-usb/msg145747.html > > Fixes: f551e1352983 ("Revert "usb: musb: musb_host: Enable HCD_BH flag to handle urb return in bottom half"") > Signed-off-by: Matwey V. Kornilov <matwey@sai.msu.ru> Thanks for the effort of working on this long standing issue, I know you have spent alot of time on it, but what I am thinking is instead of workaround the problem we need to understand the root cause - why uvc-video takes longer to exec the urb callback, why only am335x reported this issue. This is on my backlog, just seems never got time for it... 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 > ^ permalink raw reply [flat|nested] 17+ messages in thread
* Re: [PATCH] usb: musb: musb_host: Introduce postponed URB giveback 2017-04-27 15:35 ` Bin Liu @ 2017-04-27 16:26 ` Matwey V. Kornilov 2017-04-27 17:13 ` Bin Liu 0 siblings, 1 reply; 17+ messages in thread From: Matwey V. Kornilov @ 2017-04-27 16:26 UTC (permalink / raw) To: Bin Liu, Matwey V. Kornilov, gregkh, linux-usb, linux-kernel 2017-04-27 18:35 GMT+03:00 Bin Liu <b-liu@ti.com>: > Hi Matwey, > > On Thu, Apr 27, 2017 at 01:20:33PM +0300, Matwey V. Kornilov wrote: >> This commit changes the order of actions undertaken in >> musb_advance_schedule() in order to overcome issue with broken >> isochronous transfer [1]. >> >> There is no harm to split musb_giveback into two pieces. The first >> unlinks finished urb, the second givebacks it. The issue here that >> givebacking may be quite time-consuming due to urb->complete() call. >> As it happens in case of pwc-driven web cameras. It may take about 0.5 >> ms to call __musb_giveback() that calls urb->callback() internally. >> Under specific circumstances setting MUSB_RXCSR_H_REQPKT in subsequent >> musb_start_urb() for the next urb will be too late to produce physical >> IN packet. Since auto req is not used by this module the exchange >> would be as the following: >> >> [ ] 7.220456 d= 0.000997 [182 + 3.667] [ 3] IN : 4.5 >> [ T ] 7.220459 d= 0.000003 [182 + 7.000] [800] DATA0: [skipped] >> [ ] 7.222456 d= 0.001997 [184 + 3.667] [ 3] IN : 4.5 >> [ ] 7.222459 d= 0.000003 [184 + 7.000] [ 3] DATA0: 00 00 >> >> It is known that missed IN in isochronous mode makes some >> perepherial broken. For instance, pwc-driven or uvc-driven >> web cameras. >> In order to workaround this issue we postpone calling >> urb->callback() after setting MUSB_RXCSR_H_REQPKT for the >> next urb if there is the next urb pending in queue. >> >> [1] https://www.spinics.net/lists/linux-usb/msg145747.html >> >> Fixes: f551e1352983 ("Revert "usb: musb: musb_host: Enable HCD_BH flag to handle urb return in bottom half"") >> Signed-off-by: Matwey V. Kornilov <matwey@sai.msu.ru> > > Thanks for the effort of working on this long standing issue, I know you > have spent alot of time on it, but what I am thinking is instead of > workaround the problem we need to understand the root cause - why > uvc-video takes longer to exec the urb callback, why only am335x > reported this issue. This is on my backlog, just seems never got time > for it... Have you tried other SoCs with Invetra MUSB? > > 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 ^ permalink raw reply [flat|nested] 17+ messages in thread
* Re: [PATCH] usb: musb: musb_host: Introduce postponed URB giveback 2017-04-27 16:26 ` Matwey V. Kornilov @ 2017-04-27 17:13 ` Bin Liu 2017-04-28 7:04 ` Matwey V. Kornilov 0 siblings, 1 reply; 17+ messages in thread From: Bin Liu @ 2017-04-27 17:13 UTC (permalink / raw) To: Matwey V. Kornilov; +Cc: gregkh, linux-usb, linux-kernel On Thu, Apr 27, 2017 at 07:26:31PM +0300, Matwey V. Kornilov wrote: > 2017-04-27 18:35 GMT+03:00 Bin Liu <b-liu@ti.com>: > > Hi Matwey, > > > > On Thu, Apr 27, 2017 at 01:20:33PM +0300, Matwey V. Kornilov wrote: > >> This commit changes the order of actions undertaken in > >> musb_advance_schedule() in order to overcome issue with broken > >> isochronous transfer [1]. > >> > >> There is no harm to split musb_giveback into two pieces. The first > >> unlinks finished urb, the second givebacks it. The issue here that > >> givebacking may be quite time-consuming due to urb->complete() call. > >> As it happens in case of pwc-driven web cameras. It may take about 0.5 > >> ms to call __musb_giveback() that calls urb->callback() internally. > >> Under specific circumstances setting MUSB_RXCSR_H_REQPKT in subsequent > >> musb_start_urb() for the next urb will be too late to produce physical > >> IN packet. Since auto req is not used by this module the exchange > >> would be as the following: > >> > >> [ ] 7.220456 d= 0.000997 [182 + 3.667] [ 3] IN : 4.5 > >> [ T ] 7.220459 d= 0.000003 [182 + 7.000] [800] DATA0: [skipped] > >> [ ] 7.222456 d= 0.001997 [184 + 3.667] [ 3] IN : 4.5 > >> [ ] 7.222459 d= 0.000003 [184 + 7.000] [ 3] DATA0: 00 00 > >> > >> It is known that missed IN in isochronous mode makes some > >> perepherial broken. For instance, pwc-driven or uvc-driven > >> web cameras. > >> In order to workaround this issue we postpone calling > >> urb->callback() after setting MUSB_RXCSR_H_REQPKT for the > >> next urb if there is the next urb pending in queue. > >> > >> [1] https://www.spinics.net/lists/linux-usb/msg145747.html > >> > >> Fixes: f551e1352983 ("Revert "usb: musb: musb_host: Enable HCD_BH flag to handle urb return in bottom half"") > >> Signed-off-by: Matwey V. Kornilov <matwey@sai.msu.ru> > > > > Thanks for the effort of working on this long standing issue, I know you > > have spent alot of time on it, but what I am thinking is instead of > > workaround the problem we need to understand the root cause - why > > uvc-video takes longer to exec the urb callback, why only am335x > > reported this issue. This is on my backlog, just seems never got time > > for it... > > Have you tried other SoCs with Invetra MUSB? That is the plan, I got an A20 board, but haven't bring it up yet. > > > > > Ideally MUSB driver should be just using HCD_BH flag and let the core to > > handle the urb callback, regardless the usb transfer types. > > I think the only reason why everything worked before with HCD_BH is > that execution of urb->callback() was placed after musb_start(). The > order of operations matters. > However, you said that something was also wrong with HCD_BH and other > peripherals. HCD_BH flag cause some issues which are docummented in the commit log of f551e1352983. But even with HCD_BH flag, it didn't work for uvc webcams, it still misses IN tokens. It might helps pwc webcams though. > > 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. ^ permalink raw reply [flat|nested] 17+ messages in thread
* Re: [PATCH] usb: musb: musb_host: Introduce postponed URB giveback 2017-04-27 17:13 ` Bin Liu @ 2017-04-28 7:04 ` Matwey V. Kornilov 2017-04-28 11:58 ` Bin Liu 0 siblings, 1 reply; 17+ messages in thread From: Matwey V. Kornilov @ 2017-04-28 7:04 UTC (permalink / raw) To: Bin Liu, Matwey V. Kornilov, gregkh, linux-usb, linux-kernel 2017-04-27 20:13 GMT+03:00 Bin Liu <b-liu@ti.com>: > On Thu, Apr 27, 2017 at 07:26:31PM +0300, Matwey V. Kornilov wrote: >> 2017-04-27 18:35 GMT+03:00 Bin Liu <b-liu@ti.com>: >> > Hi Matwey, >> > >> > On Thu, Apr 27, 2017 at 01:20:33PM +0300, Matwey V. Kornilov wrote: >> >> This commit changes the order of actions undertaken in >> >> musb_advance_schedule() in order to overcome issue with broken >> >> isochronous transfer [1]. >> >> >> >> There is no harm to split musb_giveback into two pieces. The first >> >> unlinks finished urb, the second givebacks it. The issue here that >> >> givebacking may be quite time-consuming due to urb->complete() call. >> >> As it happens in case of pwc-driven web cameras. It may take about 0.5 >> >> ms to call __musb_giveback() that calls urb->callback() internally. >> >> Under specific circumstances setting MUSB_RXCSR_H_REQPKT in subsequent >> >> musb_start_urb() for the next urb will be too late to produce physical >> >> IN packet. Since auto req is not used by this module the exchange >> >> would be as the following: >> >> >> >> [ ] 7.220456 d= 0.000997 [182 + 3.667] [ 3] IN : 4.5 >> >> [ T ] 7.220459 d= 0.000003 [182 + 7.000] [800] DATA0: [skipped] >> >> [ ] 7.222456 d= 0.001997 [184 + 3.667] [ 3] IN : 4.5 >> >> [ ] 7.222459 d= 0.000003 [184 + 7.000] [ 3] DATA0: 00 00 >> >> >> >> It is known that missed IN in isochronous mode makes some >> >> perepherial broken. For instance, pwc-driven or uvc-driven >> >> web cameras. >> >> In order to workaround this issue we postpone calling >> >> urb->callback() after setting MUSB_RXCSR_H_REQPKT for the >> >> next urb if there is the next urb pending in queue. >> >> >> >> [1] https://www.spinics.net/lists/linux-usb/msg145747.html >> >> >> >> Fixes: f551e1352983 ("Revert "usb: musb: musb_host: Enable HCD_BH flag to handle urb return in bottom half"") >> >> Signed-off-by: Matwey V. Kornilov <matwey@sai.msu.ru> >> > >> > Thanks for the effort of working on this long standing issue, I know you >> > have spent alot of time on it, but what I am thinking is instead of >> > workaround the problem we need to understand the root cause - why >> > uvc-video takes longer to exec the urb callback, why only am335x >> > reported this issue. This is on my backlog, just seems never got time >> > for it... >> >> Have you tried other SoCs with Invetra MUSB? > > That is the plan, I got an A20 board, but haven't bring it up yet. > >> >> > >> > Ideally MUSB driver should be just using HCD_BH flag and let the core to >> > handle the urb callback, regardless the usb transfer types. >> >> I think the only reason why everything worked before with HCD_BH is >> that execution of urb->callback() was placed after musb_start(). The >> order of operations matters. >> However, you said that something was also wrong with HCD_BH and other >> peripherals. > > HCD_BH flag cause some issues which are docummented in the commit log of > f551e1352983. > But even with HCD_BH flag, it didn't work for uvc webcams, it still misses > IN tokens. It might helps pwc webcams though. pwc webcams work with HCD_BH fine indeed. > >> > 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 ^ permalink raw reply [flat|nested] 17+ messages in thread
* Re: [PATCH] usb: musb: musb_host: Introduce postponed URB giveback 2017-04-28 7:04 ` Matwey V. Kornilov @ 2017-04-28 11:58 ` Bin Liu 2017-04-28 12:13 ` Matwey V. Kornilov 0 siblings, 1 reply; 17+ messages in thread From: Bin Liu @ 2017-04-28 11:58 UTC (permalink / raw) To: Matwey V. Kornilov; +Cc: gregkh, linux-usb, linux-kernel On Fri, Apr 28, 2017 at 10:04:30AM +0300, Matwey V. Kornilov wrote: > 2017-04-27 20:13 GMT+03:00 Bin Liu <b-liu@ti.com>: > > On Thu, Apr 27, 2017 at 07:26:31PM +0300, Matwey V. Kornilov wrote: > >> 2017-04-27 18:35 GMT+03:00 Bin Liu <b-liu@ti.com>: > >> > Hi Matwey, > >> > > >> > On Thu, Apr 27, 2017 at 01:20:33PM +0300, Matwey V. Kornilov wrote: > >> >> This commit changes the order of actions undertaken in > >> >> musb_advance_schedule() in order to overcome issue with broken > >> >> isochronous transfer [1]. > >> >> > >> >> There is no harm to split musb_giveback into two pieces. The first > >> >> unlinks finished urb, the second givebacks it. The issue here that > >> >> givebacking may be quite time-consuming due to urb->complete() call. > >> >> As it happens in case of pwc-driven web cameras. It may take about 0.5 > >> >> ms to call __musb_giveback() that calls urb->callback() internally. > >> >> Under specific circumstances setting MUSB_RXCSR_H_REQPKT in subsequent > >> >> musb_start_urb() for the next urb will be too late to produce physical > >> >> IN packet. Since auto req is not used by this module the exchange > >> >> would be as the following: > >> >> > >> >> [ ] 7.220456 d= 0.000997 [182 + 3.667] [ 3] IN : 4.5 > >> >> [ T ] 7.220459 d= 0.000003 [182 + 7.000] [800] DATA0: [skipped] > >> >> [ ] 7.222456 d= 0.001997 [184 + 3.667] [ 3] IN : 4.5 > >> >> [ ] 7.222459 d= 0.000003 [184 + 7.000] [ 3] DATA0: 00 00 > >> >> > >> >> It is known that missed IN in isochronous mode makes some > >> >> perepherial broken. For instance, pwc-driven or uvc-driven > >> >> web cameras. > >> >> In order to workaround this issue we postpone calling > >> >> urb->callback() after setting MUSB_RXCSR_H_REQPKT for the > >> >> next urb if there is the next urb pending in queue. > >> >> > >> >> [1] https://www.spinics.net/lists/linux-usb/msg145747.html > >> >> > >> >> Fixes: f551e1352983 ("Revert "usb: musb: musb_host: Enable HCD_BH flag to handle urb return in bottom half"") > >> >> Signed-off-by: Matwey V. Kornilov <matwey@sai.msu.ru> > >> > > >> > Thanks for the effort of working on this long standing issue, I know you > >> > have spent alot of time on it, but what I am thinking is instead of > >> > workaround the problem we need to understand the root cause - why > >> > uvc-video takes longer to exec the urb callback, why only am335x > >> > reported this issue. This is on my backlog, just seems never got time > >> > for it... > >> > >> Have you tried other SoCs with Invetra MUSB? > > > > That is the plan, I got an A20 board, but haven't bring it up yet. > > > >> > >> > > >> > Ideally MUSB driver should be just using HCD_BH flag and let the core to > >> > handle the urb callback, regardless the usb transfer types. > >> > >> I think the only reason why everything worked before with HCD_BH is > >> that execution of urb->callback() was placed after musb_start(). The > >> order of operations matters. > >> However, you said that something was also wrong with HCD_BH and other > >> peripherals. > > > > HCD_BH flag cause some issues which are docummented in the commit log of > > f551e1352983. > > But even with HCD_BH flag, it didn't work for uvc webcams, it still misses > > IN tokens. It might helps pwc webcams though. > > pwc webcams work with HCD_BH fine indeed. yeah, this is what you told long time ago. > > > > >> > The MUSB drivers are already messy and complicated enough for > >> > maintenance, I'd like to understand the root cause of the delay first > >> > before decide how to solve the issue. > >> > > >> > >> I feel from playing with OpenVizsla that REQPKT should be set well in > >> advance. So, time window to set the flag is actually smaller than 1 > >> ms. > >> urb->callback() is never takes longer than 0.4 ms for pwc driver, but > >> INs are skipped. > > > > Setting REQPKT in advance might be the solution, but I'd like to > > understand why only Isoch transfer shows such issue, and why only am335x > > reports this issue. The later concerns me more if this would be a > > system issue not only in usb module. > > 0.4 ms is about 100000 CPU cycles given that CPU is running at 275Mhz > (which is the lowest cpufreq). Long time ago, I run pwc webcam with > SIS Vortex86 at 200Mhz It worked fine. I would not say that it is > extraordinary value. > Do you think that somewhere CPU cycles are wasted globally for some reason? Depends on how to interpret 'wasted', my understanding the issue is the core urb giveback holds a spinlock and in uvc case the giveback takes longer to finish (I guess the same in pwc case), so the musb driver doesn't get a chance to re-program the controller on time, which causes missing issuingIN tokens. The questions are, why uvc takes longer to run urb giveback (which holds a spinlock), and is it am335x specific issue... Regards, -Bin. ^ permalink raw reply [flat|nested] 17+ messages in thread
* Re: [PATCH] usb: musb: musb_host: Introduce postponed URB giveback 2017-04-28 11:58 ` Bin Liu @ 2017-04-28 12:13 ` Matwey V. Kornilov 2017-04-28 12:43 ` Bin Liu 0 siblings, 1 reply; 17+ messages in thread From: Matwey V. Kornilov @ 2017-04-28 12:13 UTC (permalink / raw) To: Bin Liu, Matwey V. Kornilov, gregkh, linux-usb, linux-kernel which i 2017-04-28 14:58 GMT+03:00 Bin Liu <b-liu@ti.com>: > On Fri, Apr 28, 2017 at 10:04:30AM +0300, Matwey V. Kornilov wrote: >> 2017-04-27 20:13 GMT+03:00 Bin Liu <b-liu@ti.com>: >> > On Thu, Apr 27, 2017 at 07:26:31PM +0300, Matwey V. Kornilov wrote: >> >> 2017-04-27 18:35 GMT+03:00 Bin Liu <b-liu@ti.com>: >> >> > Hi Matwey, >> >> > >> >> > On Thu, Apr 27, 2017 at 01:20:33PM +0300, Matwey V. Kornilov wrote: >> >> >> This commit changes the order of actions undertaken in >> >> >> musb_advance_schedule() in order to overcome issue with broken >> >> >> isochronous transfer [1]. >> >> >> >> >> >> There is no harm to split musb_giveback into two pieces. The first >> >> >> unlinks finished urb, the second givebacks it. The issue here that >> >> >> givebacking may be quite time-consuming due to urb->complete() call. >> >> >> As it happens in case of pwc-driven web cameras. It may take about 0.5 >> >> >> ms to call __musb_giveback() that calls urb->callback() internally. >> >> >> Under specific circumstances setting MUSB_RXCSR_H_REQPKT in subsequent >> >> >> musb_start_urb() for the next urb will be too late to produce physical >> >> >> IN packet. Since auto req is not used by this module the exchange >> >> >> would be as the following: >> >> >> >> >> >> [ ] 7.220456 d= 0.000997 [182 + 3.667] [ 3] IN : 4.5 >> >> >> [ T ] 7.220459 d= 0.000003 [182 + 7.000] [800] DATA0: [skipped] >> >> >> [ ] 7.222456 d= 0.001997 [184 + 3.667] [ 3] IN : 4.5 >> >> >> [ ] 7.222459 d= 0.000003 [184 + 7.000] [ 3] DATA0: 00 00 >> >> >> >> >> >> It is known that missed IN in isochronous mode makes some >> >> >> perepherial broken. For instance, pwc-driven or uvc-driven >> >> >> web cameras. >> >> >> In order to workaround this issue we postpone calling >> >> >> urb->callback() after setting MUSB_RXCSR_H_REQPKT for the >> >> >> next urb if there is the next urb pending in queue. >> >> >> >> >> >> [1] https://www.spinics.net/lists/linux-usb/msg145747.html >> >> >> >> >> >> Fixes: f551e1352983 ("Revert "usb: musb: musb_host: Enable HCD_BH flag to handle urb return in bottom half"") >> >> >> Signed-off-by: Matwey V. Kornilov <matwey@sai.msu.ru> >> >> > >> >> > Thanks for the effort of working on this long standing issue, I know you >> >> > have spent alot of time on it, but what I am thinking is instead of >> >> > workaround the problem we need to understand the root cause - why >> >> > uvc-video takes longer to exec the urb callback, why only am335x >> >> > reported this issue. This is on my backlog, just seems never got time >> >> > for it... >> >> >> >> Have you tried other SoCs with Invetra MUSB? >> > >> > That is the plan, I got an A20 board, but haven't bring it up yet. >> > >> >> >> >> > >> >> > Ideally MUSB driver should be just using HCD_BH flag and let the core to >> >> > handle the urb callback, regardless the usb transfer types. >> >> >> >> I think the only reason why everything worked before with HCD_BH is >> >> that execution of urb->callback() was placed after musb_start(). The >> >> order of operations matters. >> >> However, you said that something was also wrong with HCD_BH and other >> >> peripherals. >> > >> > HCD_BH flag cause some issues which are docummented in the commit log of >> > f551e1352983. >> > But even with HCD_BH flag, it didn't work for uvc webcams, it still misses >> > IN tokens. It might helps pwc webcams though. >> >> pwc webcams work with HCD_BH fine indeed. > > yeah, this is what you told long time ago. > >> >> > >> >> > The MUSB drivers are already messy and complicated enough for >> >> > maintenance, I'd like to understand the root cause of the delay first >> >> > before decide how to solve the issue. >> >> > >> >> >> >> I feel from playing with OpenVizsla that REQPKT should be set well in >> >> advance. So, time window to set the flag is actually smaller than 1 >> >> ms. >> >> urb->callback() is never takes longer than 0.4 ms for pwc driver, but >> >> INs are skipped. >> > >> > Setting REQPKT in advance might be the solution, but I'd like to >> > understand why only Isoch transfer shows such issue, and why only am335x >> > reports this issue. The later concerns me more if this would be a >> > system issue not only in usb module. >> >> 0.4 ms is about 100000 CPU cycles given that CPU is running at 275Mhz >> (which is the lowest cpufreq). Long time ago, I run pwc webcam with >> SIS Vortex86 at 200Mhz It worked fine. I would not say that it is >> extraordinary value. >> Do you think that somewhere CPU cycles are wasted globally for some reason? > > Depends on how to interpret 'wasted', my understanding the issue is the > core urb giveback holds a spinlock and in uvc case the giveback takes > longer to finish (I guess the same in pwc case), so the musb driver > doesn't get a chance to re-program the controller on time, which causes > missing issuingIN tokens. > > The questions are, why uvc takes longer to run urb giveback (which holds > a spinlock), and is it am335x specific issue... 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 ^ permalink raw reply [flat|nested] 17+ messages in thread
* Re: [PATCH] usb: musb: musb_host: Introduce postponed URB giveback 2017-04-28 12:13 ` Matwey V. Kornilov @ 2017-04-28 12:43 ` Bin Liu 2017-04-28 13:15 ` Matwey V. Kornilov 0 siblings, 1 reply; 17+ messages in thread From: Bin Liu @ 2017-04-28 12:43 UTC (permalink / raw) To: Matwey V. Kornilov; +Cc: gregkh, linux-usb, linux-kernel 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 <b-liu@ti.com>: > > On Fri, Apr 28, 2017 at 10:04:30AM +0300, Matwey V. Kornilov wrote: > >> 2017-04-27 20:13 GMT+03:00 Bin Liu <b-liu@ti.com>: > >> > On Thu, Apr 27, 2017 at 07:26:31PM +0300, Matwey V. Kornilov wrote: > >> >> 2017-04-27 18:35 GMT+03:00 Bin Liu <b-liu@ti.com>: > >> >> > Hi Matwey, > >> >> > > >> >> > On Thu, Apr 27, 2017 at 01:20:33PM +0300, Matwey V. Kornilov wrote: > >> >> >> This commit changes the order of actions undertaken in > >> >> >> musb_advance_schedule() in order to overcome issue with broken > >> >> >> isochronous transfer [1]. > >> >> >> > >> >> >> There is no harm to split musb_giveback into two pieces. The first > >> >> >> unlinks finished urb, the second givebacks it. The issue here that > >> >> >> givebacking may be quite time-consuming due to urb->complete() call. > >> >> >> As it happens in case of pwc-driven web cameras. It may take about 0.5 > >> >> >> ms to call __musb_giveback() that calls urb->callback() internally. > >> >> >> Under specific circumstances setting MUSB_RXCSR_H_REQPKT in subsequent > >> >> >> musb_start_urb() for the next urb will be too late to produce physical > >> >> >> IN packet. Since auto req is not used by this module the exchange > >> >> >> would be as the following: > >> >> >> > >> >> >> [ ] 7.220456 d= 0.000997 [182 + 3.667] [ 3] IN : 4.5 > >> >> >> [ T ] 7.220459 d= 0.000003 [182 + 7.000] [800] DATA0: [skipped] > >> >> >> [ ] 7.222456 d= 0.001997 [184 + 3.667] [ 3] IN : 4.5 > >> >> >> [ ] 7.222459 d= 0.000003 [184 + 7.000] [ 3] DATA0: 00 00 > >> >> >> > >> >> >> It is known that missed IN in isochronous mode makes some > >> >> >> perepherial broken. For instance, pwc-driven or uvc-driven > >> >> >> web cameras. > >> >> >> In order to workaround this issue we postpone calling > >> >> >> urb->callback() after setting MUSB_RXCSR_H_REQPKT for the > >> >> >> next urb if there is the next urb pending in queue. > >> >> >> > >> >> >> [1] https://www.spinics.net/lists/linux-usb/msg145747.html > >> >> >> > >> >> >> Fixes: f551e1352983 ("Revert "usb: musb: musb_host: Enable HCD_BH flag to handle urb return in bottom half"") > >> >> >> Signed-off-by: Matwey V. Kornilov <matwey@sai.msu.ru> > >> >> > > >> >> > Thanks for the effort of working on this long standing issue, I know you > >> >> > have spent alot of time on it, but what I am thinking is instead of > >> >> > workaround the problem we need to understand the root cause - why > >> >> > uvc-video takes longer to exec the urb callback, why only am335x > >> >> > reported this issue. This is on my backlog, just seems never got time > >> >> > for it... > >> >> > >> >> Have you tried other SoCs with Invetra MUSB? > >> > > >> > That is the plan, I got an A20 board, but haven't bring it up yet. > >> > > >> >> > >> >> > > >> >> > Ideally MUSB driver should be just using HCD_BH flag and let the core to > >> >> > handle the urb callback, regardless the usb transfer types. > >> >> > >> >> I think the only reason why everything worked before with HCD_BH is > >> >> that execution of urb->callback() was placed after musb_start(). The > >> >> order of operations matters. > >> >> However, you said that something was also wrong with HCD_BH and other > >> >> peripherals. > >> > > >> > HCD_BH flag cause some issues which are docummented in the commit log of > >> > f551e1352983. > >> > But even with HCD_BH flag, it didn't work for uvc webcams, it still misses > >> > IN tokens. It might helps pwc webcams though. > >> > >> pwc webcams work with HCD_BH fine indeed. > > > > yeah, this is what you told long time ago. > > > >> > >> > > >> >> > The MUSB drivers are already messy and complicated enough for > >> >> > maintenance, I'd like to understand the root cause of the delay first > >> >> > before decide how to solve the issue. > >> >> > > >> >> > >> >> I feel from playing with OpenVizsla that REQPKT should be set well in > >> >> advance. So, time window to set the flag is actually smaller than 1 > >> >> ms. > >> >> urb->callback() is never takes longer than 0.4 ms for pwc driver, but > >> >> INs are skipped. > >> > > >> > Setting REQPKT in advance might be the solution, but I'd like to > >> > understand why only Isoch transfer shows such issue, and why only am335x > >> > reports this issue. The later concerns me more if this would be a > >> > system issue not only in usb module. > >> > >> 0.4 ms is about 100000 CPU cycles given that CPU is running at 275Mhz > >> (which is the lowest cpufreq). Long time ago, I run pwc webcam with > >> SIS Vortex86 at 200Mhz It worked fine. I would not say that it is > >> extraordinary value. > >> Do you think that somewhere CPU cycles are wasted globally for some reason? > > > > Depends on how to interpret 'wasted', my understanding the issue is the > > core urb giveback holds a spinlock and in uvc case the giveback takes > > longer to finish (I guess the same in pwc case), so the musb driver > > doesn't get a chance to re-program the controller on time, which causes > > missing issuingIN tokens. > > > > The questions are, why uvc takes longer to run urb giveback (which holds > > a spinlock), and is it am335x specific issue... > > 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. ^ permalink raw reply [flat|nested] 17+ messages in thread
* Re: [PATCH] usb: musb: musb_host: Introduce postponed URB giveback 2017-04-28 12:43 ` Bin Liu @ 2017-04-28 13:15 ` Matwey V. Kornilov 2017-04-28 13:30 ` Bin Liu 0 siblings, 1 reply; 17+ messages in thread From: Matwey V. Kornilov @ 2017-04-28 13:15 UTC (permalink / raw) To: Bin Liu, Matwey V. Kornilov, gregkh, linux-usb, linux-kernel 2017-04-28 15:43 GMT+03:00 Bin Liu <b-liu@ti.com>: > 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 <b-liu@ti.com>: >> > On Fri, Apr 28, 2017 at 10:04:30AM +0300, Matwey V. Kornilov wrote: >> >> 2017-04-27 20:13 GMT+03:00 Bin Liu <b-liu@ti.com>: >> >> > On Thu, Apr 27, 2017 at 07:26:31PM +0300, Matwey V. Kornilov wrote: >> >> >> 2017-04-27 18:35 GMT+03:00 Bin Liu <b-liu@ti.com>: >> >> >> > Hi Matwey, >> >> >> > >> >> >> > On Thu, Apr 27, 2017 at 01:20:33PM +0300, Matwey V. Kornilov wrote: >> >> >> >> This commit changes the order of actions undertaken in >> >> >> >> musb_advance_schedule() in order to overcome issue with broken >> >> >> >> isochronous transfer [1]. >> >> >> >> >> >> >> >> There is no harm to split musb_giveback into two pieces. The first >> >> >> >> unlinks finished urb, the second givebacks it. The issue here that >> >> >> >> givebacking may be quite time-consuming due to urb->complete() call. >> >> >> >> As it happens in case of pwc-driven web cameras. It may take about 0.5 >> >> >> >> ms to call __musb_giveback() that calls urb->callback() internally. >> >> >> >> Under specific circumstances setting MUSB_RXCSR_H_REQPKT in subsequent >> >> >> >> musb_start_urb() for the next urb will be too late to produce physical >> >> >> >> IN packet. Since auto req is not used by this module the exchange >> >> >> >> would be as the following: >> >> >> >> >> >> >> >> [ ] 7.220456 d= 0.000997 [182 + 3.667] [ 3] IN : 4.5 >> >> >> >> [ T ] 7.220459 d= 0.000003 [182 + 7.000] [800] DATA0: [skipped] >> >> >> >> [ ] 7.222456 d= 0.001997 [184 + 3.667] [ 3] IN : 4.5 >> >> >> >> [ ] 7.222459 d= 0.000003 [184 + 7.000] [ 3] DATA0: 00 00 >> >> >> >> >> >> >> >> It is known that missed IN in isochronous mode makes some >> >> >> >> perepherial broken. For instance, pwc-driven or uvc-driven >> >> >> >> web cameras. >> >> >> >> In order to workaround this issue we postpone calling >> >> >> >> urb->callback() after setting MUSB_RXCSR_H_REQPKT for the >> >> >> >> next urb if there is the next urb pending in queue. >> >> >> >> >> >> >> >> [1] https://www.spinics.net/lists/linux-usb/msg145747.html >> >> >> >> >> >> >> >> Fixes: f551e1352983 ("Revert "usb: musb: musb_host: Enable HCD_BH flag to handle urb return in bottom half"") >> >> >> >> Signed-off-by: Matwey V. Kornilov <matwey@sai.msu.ru> >> >> >> > >> >> >> > Thanks for the effort of working on this long standing issue, I know you >> >> >> > have spent alot of time on it, but what I am thinking is instead of >> >> >> > workaround the problem we need to understand the root cause - why >> >> >> > uvc-video takes longer to exec the urb callback, why only am335x >> >> >> > reported this issue. This is on my backlog, just seems never got time >> >> >> > for it... >> >> >> >> >> >> Have you tried other SoCs with Invetra MUSB? >> >> > >> >> > That is the plan, I got an A20 board, but haven't bring it up yet. >> >> > >> >> >> >> >> >> > >> >> >> > Ideally MUSB driver should be just using HCD_BH flag and let the core to >> >> >> > handle the urb callback, regardless the usb transfer types. >> >> >> >> >> >> I think the only reason why everything worked before with HCD_BH is >> >> >> that execution of urb->callback() was placed after musb_start(). The >> >> >> order of operations matters. >> >> >> However, you said that something was also wrong with HCD_BH and other >> >> >> peripherals. >> >> > >> >> > HCD_BH flag cause some issues which are docummented in the commit log of >> >> > f551e1352983. >> >> > But even with HCD_BH flag, it didn't work for uvc webcams, it still misses >> >> > IN tokens. It might helps pwc webcams though. >> >> >> >> pwc webcams work with HCD_BH fine indeed. >> > >> > yeah, this is what you told long time ago. >> > >> >> >> >> > >> >> >> > The MUSB drivers are already messy and complicated enough for >> >> >> > maintenance, I'd like to understand the root cause of the delay first >> >> >> > before decide how to solve the issue. >> >> >> > >> >> >> >> >> >> I feel from playing with OpenVizsla that REQPKT should be set well in >> >> >> advance. So, time window to set the flag is actually smaller than 1 >> >> >> ms. >> >> >> urb->callback() is never takes longer than 0.4 ms for pwc driver, but >> >> >> INs are skipped. >> >> > >> >> > Setting REQPKT in advance might be the solution, but I'd like to >> >> > understand why only Isoch transfer shows such issue, and why only am335x >> >> > reports this issue. The later concerns me more if this would be a >> >> > system issue not only in usb module. >> >> >> >> 0.4 ms is about 100000 CPU cycles given that CPU is running at 275Mhz >> >> (which is the lowest cpufreq). Long time ago, I run pwc webcam with >> >> SIS Vortex86 at 200Mhz It worked fine. I would not say that it is >> >> extraordinary value. >> >> Do you think that somewhere CPU cycles are wasted globally for some reason? >> > >> > Depends on how to interpret 'wasted', my understanding the issue is the >> > core urb giveback holds a spinlock and in uvc case the giveback takes >> > longer to finish (I guess the same in pwc case), so the musb driver >> > doesn't get a chance to re-program the controller on time, which causes >> > missing issuingIN tokens. >> > >> > The questions are, why uvc takes longer to run urb giveback (which holds >> > a spinlock), and is it am335x specific issue... >> >> 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 ^ permalink raw reply [flat|nested] 17+ messages in thread
* Re: [PATCH] usb: musb: musb_host: Introduce postponed URB giveback 2017-04-28 13:15 ` Matwey V. Kornilov @ 2017-04-28 13:30 ` Bin Liu 2017-04-29 8:16 ` Matwey V. Kornilov 0 siblings, 1 reply; 17+ messages in thread From: Bin Liu @ 2017-04-28 13:30 UTC (permalink / raw) To: Matwey V. Kornilov; +Cc: gregkh, linux-usb, linux-kernel On Fri, Apr 28, 2017 at 04:15:09PM +0300, Matwey V. Kornilov wrote: > 2017-04-28 15:43 GMT+03:00 Bin Liu <b-liu@ti.com>: > > 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 <b-liu@ti.com>: > >> > On Fri, Apr 28, 2017 at 10:04:30AM +0300, Matwey V. Kornilov wrote: > >> >> 2017-04-27 20:13 GMT+03:00 Bin Liu <b-liu@ti.com>: > >> >> > On Thu, Apr 27, 2017 at 07:26:31PM +0300, Matwey V. Kornilov wrote: > >> >> >> 2017-04-27 18:35 GMT+03:00 Bin Liu <b-liu@ti.com>: > >> >> >> > Hi Matwey, > >> >> >> > > >> >> >> > On Thu, Apr 27, 2017 at 01:20:33PM +0300, Matwey V. Kornilov wrote: > >> >> >> >> This commit changes the order of actions undertaken in > >> >> >> >> musb_advance_schedule() in order to overcome issue with broken > >> >> >> >> isochronous transfer [1]. > >> >> >> >> > >> >> >> >> There is no harm to split musb_giveback into two pieces. The first > >> >> >> >> unlinks finished urb, the second givebacks it. The issue here that > >> >> >> >> givebacking may be quite time-consuming due to urb->complete() call. > >> >> >> >> As it happens in case of pwc-driven web cameras. It may take about 0.5 > >> >> >> >> ms to call __musb_giveback() that calls urb->callback() internally. > >> >> >> >> Under specific circumstances setting MUSB_RXCSR_H_REQPKT in subsequent > >> >> >> >> musb_start_urb() for the next urb will be too late to produce physical > >> >> >> >> IN packet. Since auto req is not used by this module the exchange > >> >> >> >> would be as the following: > >> >> >> >> > >> >> >> >> [ ] 7.220456 d= 0.000997 [182 + 3.667] [ 3] IN : 4.5 > >> >> >> >> [ T ] 7.220459 d= 0.000003 [182 + 7.000] [800] DATA0: [skipped] > >> >> >> >> [ ] 7.222456 d= 0.001997 [184 + 3.667] [ 3] IN : 4.5 > >> >> >> >> [ ] 7.222459 d= 0.000003 [184 + 7.000] [ 3] DATA0: 00 00 > >> >> >> >> > >> >> >> >> It is known that missed IN in isochronous mode makes some > >> >> >> >> perepherial broken. For instance, pwc-driven or uvc-driven > >> >> >> >> web cameras. > >> >> >> >> In order to workaround this issue we postpone calling > >> >> >> >> urb->callback() after setting MUSB_RXCSR_H_REQPKT for the > >> >> >> >> next urb if there is the next urb pending in queue. > >> >> >> >> > >> >> >> >> [1] https://www.spinics.net/lists/linux-usb/msg145747.html > >> >> >> >> > >> >> >> >> Fixes: f551e1352983 ("Revert "usb: musb: musb_host: Enable HCD_BH flag to handle urb return in bottom half"") > >> >> >> >> Signed-off-by: Matwey V. Kornilov <matwey@sai.msu.ru> > >> >> >> > > >> >> >> > Thanks for the effort of working on this long standing issue, I know you > >> >> >> > have spent alot of time on it, but what I am thinking is instead of > >> >> >> > workaround the problem we need to understand the root cause - why > >> >> >> > uvc-video takes longer to exec the urb callback, why only am335x > >> >> >> > reported this issue. This is on my backlog, just seems never got time > >> >> >> > for it... > >> >> >> > >> >> >> Have you tried other SoCs with Invetra MUSB? > >> >> > > >> >> > That is the plan, I got an A20 board, but haven't bring it up yet. > >> >> > > >> >> >> > >> >> >> > > >> >> >> > Ideally MUSB driver should be just using HCD_BH flag and let the core to > >> >> >> > handle the urb callback, regardless the usb transfer types. > >> >> >> > >> >> >> I think the only reason why everything worked before with HCD_BH is > >> >> >> that execution of urb->callback() was placed after musb_start(). The > >> >> >> order of operations matters. > >> >> >> However, you said that something was also wrong with HCD_BH and other > >> >> >> peripherals. > >> >> > > >> >> > HCD_BH flag cause some issues which are docummented in the commit log of > >> >> > f551e1352983. > >> >> > But even with HCD_BH flag, it didn't work for uvc webcams, it still misses > >> >> > IN tokens. It might helps pwc webcams though. > >> >> > >> >> pwc webcams work with HCD_BH fine indeed. > >> > > >> > yeah, this is what you told long time ago. > >> > > >> >> > >> >> > > >> >> >> > The MUSB drivers are already messy and complicated enough for > >> >> >> > maintenance, I'd like to understand the root cause of the delay first > >> >> >> > before decide how to solve the issue. > >> >> >> > > >> >> >> > >> >> >> I feel from playing with OpenVizsla that REQPKT should be set well in > >> >> >> advance. So, time window to set the flag is actually smaller than 1 > >> >> >> ms. > >> >> >> urb->callback() is never takes longer than 0.4 ms for pwc driver, but > >> >> >> INs are skipped. > >> >> > > >> >> > Setting REQPKT in advance might be the solution, but I'd like to > >> >> > understand why only Isoch transfer shows such issue, and why only am335x > >> >> > reports this issue. The later concerns me more if this would be a > >> >> > system issue not only in usb module. > >> >> > >> >> 0.4 ms is about 100000 CPU cycles given that CPU is running at 275Mhz > >> >> (which is the lowest cpufreq). Long time ago, I run pwc webcam with > >> >> SIS Vortex86 at 200Mhz It worked fine. I would not say that it is > >> >> extraordinary value. > >> >> Do you think that somewhere CPU cycles are wasted globally for some reason? > >> > > >> > Depends on how to interpret 'wasted', my understanding the issue is the > >> > core urb giveback holds a spinlock and in uvc case the giveback takes > >> > longer to finish (I guess the same in pwc case), so the musb driver > >> > doesn't get a chance to re-program the controller on time, which causes > >> > missing issuingIN tokens. > >> > > >> > The questions are, why uvc takes longer to run urb giveback (which holds > >> > a spinlock), and is it am335x specific issue... > >> > >> 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 ^ permalink raw reply [flat|nested] 17+ messages in thread
* Re: [PATCH] usb: musb: musb_host: Introduce postponed URB giveback 2017-04-28 13:30 ` Bin Liu @ 2017-04-29 8:16 ` Matwey V. Kornilov 2017-04-29 14:24 ` Matwey V. Kornilov 0 siblings, 1 reply; 17+ messages in thread From: Matwey V. Kornilov @ 2017-04-29 8:16 UTC (permalink / raw) To: Bin Liu, Matwey V. Kornilov, gregkh, linux-usb, linux-kernel [-- Attachment #1: Type: text/plain, Size: 8431 bytes --] 2017-04-28 16:30 GMT+03:00 Bin Liu <b-liu@ti.com>: > On Fri, Apr 28, 2017 at 04:15:09PM +0300, Matwey V. Kornilov wrote: >> 2017-04-28 15:43 GMT+03:00 Bin Liu <b-liu@ti.com>: >> > 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 <b-liu@ti.com>: >> >> > On Fri, Apr 28, 2017 at 10:04:30AM +0300, Matwey V. Kornilov wrote: >> >> >> 2017-04-27 20:13 GMT+03:00 Bin Liu <b-liu@ti.com>: >> >> >> > On Thu, Apr 27, 2017 at 07:26:31PM +0300, Matwey V. Kornilov wrote: >> >> >> >> 2017-04-27 18:35 GMT+03:00 Bin Liu <b-liu@ti.com>: >> >> >> >> > Hi Matwey, >> >> >> >> > >> >> >> >> > On Thu, Apr 27, 2017 at 01:20:33PM +0300, Matwey V. Kornilov wrote: >> >> >> >> >> This commit changes the order of actions undertaken in >> >> >> >> >> musb_advance_schedule() in order to overcome issue with broken >> >> >> >> >> isochronous transfer [1]. >> >> >> >> >> >> >> >> >> >> There is no harm to split musb_giveback into two pieces. The first >> >> >> >> >> unlinks finished urb, the second givebacks it. The issue here that >> >> >> >> >> givebacking may be quite time-consuming due to urb->complete() call. >> >> >> >> >> As it happens in case of pwc-driven web cameras. It may take about 0.5 >> >> >> >> >> ms to call __musb_giveback() that calls urb->callback() internally. >> >> >> >> >> Under specific circumstances setting MUSB_RXCSR_H_REQPKT in subsequent >> >> >> >> >> musb_start_urb() for the next urb will be too late to produce physical >> >> >> >> >> IN packet. Since auto req is not used by this module the exchange >> >> >> >> >> would be as the following: >> >> >> >> >> >> >> >> >> >> [ ] 7.220456 d= 0.000997 [182 + 3.667] [ 3] IN : 4.5 >> >> >> >> >> [ T ] 7.220459 d= 0.000003 [182 + 7.000] [800] DATA0: [skipped] >> >> >> >> >> [ ] 7.222456 d= 0.001997 [184 + 3.667] [ 3] IN : 4.5 >> >> >> >> >> [ ] 7.222459 d= 0.000003 [184 + 7.000] [ 3] DATA0: 00 00 >> >> >> >> >> >> >> >> >> >> It is known that missed IN in isochronous mode makes some >> >> >> >> >> perepherial broken. For instance, pwc-driven or uvc-driven >> >> >> >> >> web cameras. >> >> >> >> >> In order to workaround this issue we postpone calling >> >> >> >> >> urb->callback() after setting MUSB_RXCSR_H_REQPKT for the >> >> >> >> >> next urb if there is the next urb pending in queue. >> >> >> >> >> >> >> >> >> >> [1] https://www.spinics.net/lists/linux-usb/msg145747.html >> >> >> >> >> >> >> >> >> >> Fixes: f551e1352983 ("Revert "usb: musb: musb_host: Enable HCD_BH flag to handle urb return in bottom half"") >> >> >> >> >> Signed-off-by: Matwey V. Kornilov <matwey@sai.msu.ru> >> >> >> >> > >> >> >> >> > Thanks for the effort of working on this long standing issue, I know you >> >> >> >> > have spent alot of time on it, but what I am thinking is instead of >> >> >> >> > workaround the problem we need to understand the root cause - why >> >> >> >> > uvc-video takes longer to exec the urb callback, why only am335x >> >> >> >> > reported this issue. This is on my backlog, just seems never got time >> >> >> >> > for it... >> >> >> >> >> >> >> >> Have you tried other SoCs with Invetra MUSB? >> >> >> > >> >> >> > That is the plan, I got an A20 board, but haven't bring it up yet. >> >> >> > >> >> >> >> >> >> >> >> > >> >> >> >> > Ideally MUSB driver should be just using HCD_BH flag and let the core to >> >> >> >> > handle the urb callback, regardless the usb transfer types. >> >> >> >> >> >> >> >> I think the only reason why everything worked before with HCD_BH is >> >> >> >> that execution of urb->callback() was placed after musb_start(). The >> >> >> >> order of operations matters. >> >> >> >> However, you said that something was also wrong with HCD_BH and other >> >> >> >> peripherals. >> >> >> > >> >> >> > HCD_BH flag cause some issues which are docummented in the commit log of >> >> >> > f551e1352983. >> >> >> > But even with HCD_BH flag, it didn't work for uvc webcams, it still misses >> >> >> > IN tokens. It might helps pwc webcams though. >> >> >> >> >> >> pwc webcams work with HCD_BH fine indeed. >> >> > >> >> > yeah, this is what you told long time ago. >> >> > >> >> >> >> >> >> > >> >> >> >> > The MUSB drivers are already messy and complicated enough for >> >> >> >> > maintenance, I'd like to understand the root cause of the delay first >> >> >> >> > before decide how to solve the issue. >> >> >> >> > >> >> >> >> >> >> >> >> I feel from playing with OpenVizsla that REQPKT should be set well in >> >> >> >> advance. So, time window to set the flag is actually smaller than 1 >> >> >> >> ms. >> >> >> >> urb->callback() is never takes longer than 0.4 ms for pwc driver, but >> >> >> >> INs are skipped. >> >> >> > >> >> >> > Setting REQPKT in advance might be the solution, but I'd like to >> >> >> > understand why only Isoch transfer shows such issue, and why only am335x >> >> >> > reports this issue. The later concerns me more if this would be a >> >> >> > system issue not only in usb module. >> >> >> >> >> >> 0.4 ms is about 100000 CPU cycles given that CPU is running at 275Mhz >> >> >> (which is the lowest cpufreq). Long time ago, I run pwc webcam with >> >> >> SIS Vortex86 at 200Mhz It worked fine. I would not say that it is >> >> >> extraordinary value. >> >> >> Do you think that somewhere CPU cycles are wasted globally for some reason? >> >> > >> >> > Depends on how to interpret 'wasted', my understanding the issue is the >> >> > core urb giveback holds a spinlock and in uvc case the giveback takes >> >> > longer to finish (I guess the same in pwc case), so the musb driver >> >> > doesn't get a chance to re-program the controller on time, which causes >> >> > missing issuingIN tokens. >> >> > >> >> > The questions are, why uvc takes longer to run urb giveback (which holds >> >> > a spinlock), and is it am335x specific issue... >> >> >> >> 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 [-- Attachment #2: trace.am335x.dat.xz --] [-- Type: application/x-xz, Size: 46144 bytes --] [-- Attachment #3: trace.x86.dat.xz --] [-- Type: application/x-xz, Size: 12552 bytes --] ^ permalink raw reply [flat|nested] 17+ messages in thread
* Re: [PATCH] usb: musb: musb_host: Introduce postponed URB giveback 2017-04-29 8:16 ` Matwey V. Kornilov @ 2017-04-29 14:24 ` Matwey V. Kornilov 2017-04-30 16:19 ` Matwey V. Kornilov 0 siblings, 1 reply; 17+ messages in thread From: Matwey V. Kornilov @ 2017-04-29 14:24 UTC (permalink / raw) To: Bin Liu, Matwey V. Kornilov, gregkh, linux-usb, linux-kernel 2017-04-29 11:16 GMT+03:00 Matwey V. Kornilov <matwey@sai.msu.ru>: > 2017-04-28 16:30 GMT+03:00 Bin Liu <b-liu@ti.com>: >> On Fri, Apr 28, 2017 at 04:15:09PM +0300, Matwey V. Kornilov wrote: >>> 2017-04-28 15:43 GMT+03:00 Bin Liu <b-liu@ti.com>: >>> > 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 <b-liu@ti.com>: >>> >> > On Fri, Apr 28, 2017 at 10:04:30AM +0300, Matwey V. Kornilov wrote: >>> >> >> 2017-04-27 20:13 GMT+03:00 Bin Liu <b-liu@ti.com>: >>> >> >> > On Thu, Apr 27, 2017 at 07:26:31PM +0300, Matwey V. Kornilov wrote: >>> >> >> >> 2017-04-27 18:35 GMT+03:00 Bin Liu <b-liu@ti.com>: >>> >> >> >> > Hi Matwey, >>> >> >> >> > >>> >> >> >> > On Thu, Apr 27, 2017 at 01:20:33PM +0300, Matwey V. Kornilov wrote: >>> >> >> >> >> This commit changes the order of actions undertaken in >>> >> >> >> >> musb_advance_schedule() in order to overcome issue with broken >>> >> >> >> >> isochronous transfer [1]. >>> >> >> >> >> >>> >> >> >> >> There is no harm to split musb_giveback into two pieces. The first >>> >> >> >> >> unlinks finished urb, the second givebacks it. The issue here that >>> >> >> >> >> givebacking may be quite time-consuming due to urb->complete() call. >>> >> >> >> >> As it happens in case of pwc-driven web cameras. It may take about 0.5 >>> >> >> >> >> ms to call __musb_giveback() that calls urb->callback() internally. >>> >> >> >> >> Under specific circumstances setting MUSB_RXCSR_H_REQPKT in subsequent >>> >> >> >> >> musb_start_urb() for the next urb will be too late to produce physical >>> >> >> >> >> IN packet. Since auto req is not used by this module the exchange >>> >> >> >> >> would be as the following: >>> >> >> >> >> >>> >> >> >> >> [ ] 7.220456 d= 0.000997 [182 + 3.667] [ 3] IN : 4.5 >>> >> >> >> >> [ T ] 7.220459 d= 0.000003 [182 + 7.000] [800] DATA0: [skipped] >>> >> >> >> >> [ ] 7.222456 d= 0.001997 [184 + 3.667] [ 3] IN : 4.5 >>> >> >> >> >> [ ] 7.222459 d= 0.000003 [184 + 7.000] [ 3] DATA0: 00 00 >>> >> >> >> >> >>> >> >> >> >> It is known that missed IN in isochronous mode makes some >>> >> >> >> >> perepherial broken. For instance, pwc-driven or uvc-driven >>> >> >> >> >> web cameras. >>> >> >> >> >> In order to workaround this issue we postpone calling >>> >> >> >> >> urb->callback() after setting MUSB_RXCSR_H_REQPKT for the >>> >> >> >> >> next urb if there is the next urb pending in queue. >>> >> >> >> >> >>> >> >> >> >> [1] https://www.spinics.net/lists/linux-usb/msg145747.html >>> >> >> >> >> >>> >> >> >> >> Fixes: f551e1352983 ("Revert "usb: musb: musb_host: Enable HCD_BH flag to handle urb return in bottom half"") >>> >> >> >> >> Signed-off-by: Matwey V. Kornilov <matwey@sai.msu.ru> >>> >> >> >> > >>> >> >> >> > Thanks for the effort of working on this long standing issue, I know you >>> >> >> >> > have spent alot of time on it, but what I am thinking is instead of >>> >> >> >> > workaround the problem we need to understand the root cause - why >>> >> >> >> > uvc-video takes longer to exec the urb callback, why only am335x >>> >> >> >> > reported this issue. This is on my backlog, just seems never got time >>> >> >> >> > for it... >>> >> >> >> >>> >> >> >> Have you tried other SoCs with Invetra MUSB? >>> >> >> > >>> >> >> > That is the plan, I got an A20 board, but haven't bring it up yet. >>> >> >> > >>> >> >> >> >>> >> >> >> > >>> >> >> >> > Ideally MUSB driver should be just using HCD_BH flag and let the core to >>> >> >> >> > handle the urb callback, regardless the usb transfer types. >>> >> >> >> >>> >> >> >> I think the only reason why everything worked before with HCD_BH is >>> >> >> >> that execution of urb->callback() was placed after musb_start(). The >>> >> >> >> order of operations matters. >>> >> >> >> However, you said that something was also wrong with HCD_BH and other >>> >> >> >> peripherals. >>> >> >> > >>> >> >> > HCD_BH flag cause some issues which are docummented in the commit log of >>> >> >> > f551e1352983. >>> >> >> > But even with HCD_BH flag, it didn't work for uvc webcams, it still misses >>> >> >> > IN tokens. It might helps pwc webcams though. >>> >> >> >>> >> >> pwc webcams work with HCD_BH fine indeed. >>> >> > >>> >> > yeah, this is what you told long time ago. >>> >> > >>> >> >> >>> >> >> > >>> >> >> >> > The MUSB drivers are already messy and complicated enough for >>> >> >> >> > maintenance, I'd like to understand the root cause of the delay first >>> >> >> >> > before decide how to solve the issue. >>> >> >> >> > >>> >> >> >> >>> >> >> >> I feel from playing with OpenVizsla that REQPKT should be set well in >>> >> >> >> advance. So, time window to set the flag is actually smaller than 1 >>> >> >> >> ms. >>> >> >> >> urb->callback() is never takes longer than 0.4 ms for pwc driver, but >>> >> >> >> INs are skipped. >>> >> >> > >>> >> >> > Setting REQPKT in advance might be the solution, but I'd like to >>> >> >> > understand why only Isoch transfer shows such issue, and why only am335x >>> >> >> > reports this issue. The later concerns me more if this would be a >>> >> >> > system issue not only in usb module. >>> >> >> >>> >> >> 0.4 ms is about 100000 CPU cycles given that CPU is running at 275Mhz >>> >> >> (which is the lowest cpufreq). Long time ago, I run pwc webcam with >>> >> >> SIS Vortex86 at 200Mhz It worked fine. I would not say that it is >>> >> >> extraordinary value. >>> >> >> Do you think that somewhere CPU cycles are wasted globally for some reason? >>> >> > >>> >> > Depends on how to interpret 'wasted', my understanding the issue is the >>> >> > core urb giveback holds a spinlock and in uvc case the giveback takes >>> >> > longer to finish (I guess the same in pwc case), so the musb driver >>> >> > doesn't get a chance to re-program the controller on time, which causes >>> >> > missing issuingIN tokens. >>> >> > >>> >> > The questions are, why uvc takes longer to run urb giveback (which holds >>> >> > a spinlock), and is it am335x specific issue... >>> >> >>> >> 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 ^ permalink raw reply [flat|nested] 17+ messages in thread
* Re: [PATCH] usb: musb: musb_host: Introduce postponed URB giveback 2017-04-29 14:24 ` Matwey V. Kornilov @ 2017-04-30 16:19 ` Matwey V. Kornilov 0 siblings, 0 replies; 17+ messages in thread From: Matwey V. Kornilov @ 2017-04-30 16:19 UTC (permalink / raw) To: Bin Liu, Matwey V. Kornilov, gregkh, linux-usb, linux-kernel 2017-04-29 17:24 GMT+03:00 Matwey V. Kornilov <matwey@sai.msu.ru>: > 2017-04-29 11:16 GMT+03:00 Matwey V. Kornilov <matwey@sai.msu.ru>: >> 2017-04-28 16:30 GMT+03:00 Bin Liu <b-liu@ti.com>: >>> On Fri, Apr 28, 2017 at 04:15:09PM +0300, Matwey V. Kornilov wrote: >>>> 2017-04-28 15:43 GMT+03:00 Bin Liu <b-liu@ti.com>: >>>> > 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 <b-liu@ti.com>: >>>> >> > On Fri, Apr 28, 2017 at 10:04:30AM +0300, Matwey V. Kornilov wrote: >>>> >> >> 2017-04-27 20:13 GMT+03:00 Bin Liu <b-liu@ti.com>: >>>> >> >> > On Thu, Apr 27, 2017 at 07:26:31PM +0300, Matwey V. Kornilov wrote: >>>> >> >> >> 2017-04-27 18:35 GMT+03:00 Bin Liu <b-liu@ti.com>: >>>> >> >> >> > Hi Matwey, >>>> >> >> >> > >>>> >> >> >> > On Thu, Apr 27, 2017 at 01:20:33PM +0300, Matwey V. Kornilov wrote: >>>> >> >> >> >> This commit changes the order of actions undertaken in >>>> >> >> >> >> musb_advance_schedule() in order to overcome issue with broken >>>> >> >> >> >> isochronous transfer [1]. >>>> >> >> >> >> >>>> >> >> >> >> There is no harm to split musb_giveback into two pieces. The first >>>> >> >> >> >> unlinks finished urb, the second givebacks it. The issue here that >>>> >> >> >> >> givebacking may be quite time-consuming due to urb->complete() call. >>>> >> >> >> >> As it happens in case of pwc-driven web cameras. It may take about 0.5 >>>> >> >> >> >> ms to call __musb_giveback() that calls urb->callback() internally. >>>> >> >> >> >> Under specific circumstances setting MUSB_RXCSR_H_REQPKT in subsequent >>>> >> >> >> >> musb_start_urb() for the next urb will be too late to produce physical >>>> >> >> >> >> IN packet. Since auto req is not used by this module the exchange >>>> >> >> >> >> would be as the following: >>>> >> >> >> >> >>>> >> >> >> >> [ ] 7.220456 d= 0.000997 [182 + 3.667] [ 3] IN : 4.5 >>>> >> >> >> >> [ T ] 7.220459 d= 0.000003 [182 + 7.000] [800] DATA0: [skipped] >>>> >> >> >> >> [ ] 7.222456 d= 0.001997 [184 + 3.667] [ 3] IN : 4.5 >>>> >> >> >> >> [ ] 7.222459 d= 0.000003 [184 + 7.000] [ 3] DATA0: 00 00 >>>> >> >> >> >> >>>> >> >> >> >> It is known that missed IN in isochronous mode makes some >>>> >> >> >> >> perepherial broken. For instance, pwc-driven or uvc-driven >>>> >> >> >> >> web cameras. >>>> >> >> >> >> In order to workaround this issue we postpone calling >>>> >> >> >> >> urb->callback() after setting MUSB_RXCSR_H_REQPKT for the >>>> >> >> >> >> next urb if there is the next urb pending in queue. >>>> >> >> >> >> >>>> >> >> >> >> [1] https://www.spinics.net/lists/linux-usb/msg145747.html >>>> >> >> >> >> >>>> >> >> >> >> Fixes: f551e1352983 ("Revert "usb: musb: musb_host: Enable HCD_BH flag to handle urb return in bottom half"") >>>> >> >> >> >> Signed-off-by: Matwey V. Kornilov <matwey@sai.msu.ru> >>>> >> >> >> > >>>> >> >> >> > Thanks for the effort of working on this long standing issue, I know you >>>> >> >> >> > have spent alot of time on it, but what I am thinking is instead of >>>> >> >> >> > workaround the problem we need to understand the root cause - why >>>> >> >> >> > uvc-video takes longer to exec the urb callback, why only am335x >>>> >> >> >> > reported this issue. This is on my backlog, just seems never got time >>>> >> >> >> > for it... >>>> >> >> >> >>>> >> >> >> Have you tried other SoCs with Invetra MUSB? >>>> >> >> > >>>> >> >> > That is the plan, I got an A20 board, but haven't bring it up yet. >>>> >> >> > >>>> >> >> >> >>>> >> >> >> > >>>> >> >> >> > Ideally MUSB driver should be just using HCD_BH flag and let the core to >>>> >> >> >> > handle the urb callback, regardless the usb transfer types. >>>> >> >> >> >>>> >> >> >> I think the only reason why everything worked before with HCD_BH is >>>> >> >> >> that execution of urb->callback() was placed after musb_start(). The >>>> >> >> >> order of operations matters. >>>> >> >> >> However, you said that something was also wrong with HCD_BH and other >>>> >> >> >> peripherals. >>>> >> >> > >>>> >> >> > HCD_BH flag cause some issues which are docummented in the commit log of >>>> >> >> > f551e1352983. >>>> >> >> > But even with HCD_BH flag, it didn't work for uvc webcams, it still misses >>>> >> >> > IN tokens. It might helps pwc webcams though. >>>> >> >> >>>> >> >> pwc webcams work with HCD_BH fine indeed. >>>> >> > >>>> >> > yeah, this is what you told long time ago. >>>> >> > >>>> >> >> >>>> >> >> > >>>> >> >> >> > The MUSB drivers are already messy and complicated enough for >>>> >> >> >> > maintenance, I'd like to understand the root cause of the delay first >>>> >> >> >> > before decide how to solve the issue. >>>> >> >> >> > >>>> >> >> >> >>>> >> >> >> I feel from playing with OpenVizsla that REQPKT should be set well in >>>> >> >> >> advance. So, time window to set the flag is actually smaller than 1 >>>> >> >> >> ms. >>>> >> >> >> urb->callback() is never takes longer than 0.4 ms for pwc driver, but >>>> >> >> >> INs are skipped. >>>> >> >> > >>>> >> >> > Setting REQPKT in advance might be the solution, but I'd like to >>>> >> >> > understand why only Isoch transfer shows such issue, and why only am335x >>>> >> >> > reports this issue. The later concerns me more if this would be a >>>> >> >> > system issue not only in usb module. >>>> >> >> >>>> >> >> 0.4 ms is about 100000 CPU cycles given that CPU is running at 275Mhz >>>> >> >> (which is the lowest cpufreq). Long time ago, I run pwc webcam with >>>> >> >> SIS Vortex86 at 200Mhz It worked fine. I would not say that it is >>>> >> >> extraordinary value. >>>> >> >> Do you think that somewhere CPU cycles are wasted globally for some reason? >>>> >> > >>>> >> > Depends on how to interpret 'wasted', my understanding the issue is the >>>> >> > core urb giveback holds a spinlock and in uvc case the giveback takes >>>> >> > longer to finish (I guess the same in pwc case), so the musb driver >>>> >> > doesn't get a chance to re-program the controller on time, which causes >>>> >> > missing issuingIN tokens. >>>> >> > >>>> >> > The questions are, why uvc takes longer to run urb giveback (which holds >>>> >> > a spinlock), and is it am335x specific issue... >>>> >> >>>> >> 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 ^ permalink raw reply [flat|nested] 17+ messages in thread
* Re: [PATCH] usb: musb: musb_host: Introduce postponed URB giveback 2017-04-27 10:20 [PATCH] usb: musb: musb_host: Introduce postponed URB giveback Matwey V. Kornilov 2017-04-27 15:35 ` Bin Liu @ 2017-11-04 14:05 ` Matwey V. Kornilov 2017-11-15 15:19 ` Matwey V. Kornilov 1 sibling, 1 reply; 17+ messages in thread From: Matwey V. Kornilov @ 2017-11-04 14:05 UTC (permalink / raw) To: Bin Liu, Greg KH; +Cc: linux-usb, linux-kernel, Matwey V. Kornilov 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 <matwey@sai.msu.ru>: > This commit changes the order of actions undertaken in > musb_advance_schedule() in order to overcome issue with broken > isochronous transfer [1]. > > There is no harm to split musb_giveback into two pieces. The first > unlinks finished urb, the second givebacks it. The issue here that > givebacking may be quite time-consuming due to urb->complete() call. > As it happens in case of pwc-driven web cameras. It may take about 0.5 > ms to call __musb_giveback() that calls urb->callback() internally. > Under specific circumstances setting MUSB_RXCSR_H_REQPKT in subsequent > musb_start_urb() for the next urb will be too late to produce physical > IN packet. Since auto req is not used by this module the exchange > would be as the following: > > [ ] 7.220456 d= 0.000997 [182 + 3.667] [ 3] IN : 4.5 > [ T ] 7.220459 d= 0.000003 [182 + 7.000] [800] DATA0: [skipped] > [ ] 7.222456 d= 0.001997 [184 + 3.667] [ 3] IN : 4.5 > [ ] 7.222459 d= 0.000003 [184 + 7.000] [ 3] DATA0: 00 00 > > It is known that missed IN in isochronous mode makes some > perepherial broken. For instance, pwc-driven or uvc-driven > web cameras. > In order to workaround this issue we postpone calling > urb->callback() after setting MUSB_RXCSR_H_REQPKT for the > next urb if there is the next urb pending in queue. > > [1] https://www.spinics.net/lists/linux-usb/msg145747.html > > Fixes: f551e1352983 ("Revert "usb: musb: musb_host: Enable HCD_BH flag to handle urb return in bottom half"") > Signed-off-by: Matwey V. Kornilov <matwey@sai.msu.ru> > --- > 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 ^ permalink raw reply [flat|nested] 17+ messages in thread
* Re: [PATCH] usb: musb: musb_host: Introduce postponed URB giveback 2017-11-04 14:05 ` Matwey V. Kornilov @ 2017-11-15 15:19 ` Matwey V. Kornilov 2017-11-16 16:32 ` Bin Liu 0 siblings, 1 reply; 17+ messages in thread From: Matwey V. Kornilov @ 2017-11-15 15:19 UTC (permalink / raw) To: Bin Liu, Greg KH; +Cc: linux-usb, linux-kernel, Matwey V. Kornilov The issue is also present in 4.9.60-ti-r75 2017-11-04 17:05 GMT+03:00 Matwey V. Kornilov <matwey@sai.msu.ru>: > 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 <matwey@sai.msu.ru>: >> This commit changes the order of actions undertaken in >> musb_advance_schedule() in order to overcome issue with broken >> isochronous transfer [1]. >> >> There is no harm to split musb_giveback into two pieces. The first >> unlinks finished urb, the second givebacks it. The issue here that >> givebacking may be quite time-consuming due to urb->complete() call. >> As it happens in case of pwc-driven web cameras. It may take about 0.5 >> ms to call __musb_giveback() that calls urb->callback() internally. >> Under specific circumstances setting MUSB_RXCSR_H_REQPKT in subsequent >> musb_start_urb() for the next urb will be too late to produce physical >> IN packet. Since auto req is not used by this module the exchange >> would be as the following: >> >> [ ] 7.220456 d= 0.000997 [182 + 3.667] [ 3] IN : 4.5 >> [ T ] 7.220459 d= 0.000003 [182 + 7.000] [800] DATA0: [skipped] >> [ ] 7.222456 d= 0.001997 [184 + 3.667] [ 3] IN : 4.5 >> [ ] 7.222459 d= 0.000003 [184 + 7.000] [ 3] DATA0: 00 00 >> >> It is known that missed IN in isochronous mode makes some >> perepherial broken. For instance, pwc-driven or uvc-driven >> web cameras. >> In order to workaround this issue we postpone calling >> urb->callback() after setting MUSB_RXCSR_H_REQPKT for the >> next urb if there is the next urb pending in queue. >> >> [1] https://www.spinics.net/lists/linux-usb/msg145747.html >> >> Fixes: f551e1352983 ("Revert "usb: musb: musb_host: Enable HCD_BH flag to handle urb return in bottom half"") >> Signed-off-by: Matwey V. Kornilov <matwey@sai.msu.ru> >> --- >> 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 ^ permalink raw reply [flat|nested] 17+ messages in thread
* Re: [PATCH] usb: musb: musb_host: Introduce postponed URB giveback 2017-11-15 15:19 ` Matwey V. Kornilov @ 2017-11-16 16:32 ` Bin Liu 2017-11-16 17:59 ` Matwey V. Kornilov 0 siblings, 1 reply; 17+ messages in thread From: Bin Liu @ 2017-11-16 16:32 UTC (permalink / raw) To: Matwey V. Kornilov; +Cc: Greg KH, linux-usb, linux-kernel 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 <matwey@sai.msu.ru>: > > 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. ^ permalink raw reply [flat|nested] 17+ messages in thread
* Re: [PATCH] usb: musb: musb_host: Introduce postponed URB giveback 2017-11-16 16:32 ` Bin Liu @ 2017-11-16 17:59 ` Matwey V. Kornilov 0 siblings, 0 replies; 17+ messages in thread From: Matwey V. Kornilov @ 2017-11-16 17:59 UTC (permalink / raw) To: Bin Liu, Matwey V. Kornilov, Greg KH, linux-usb, linux-kernel 2017-11-16 19:32 GMT+03:00 Bin Liu <b-liu@ti.com>: > 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 <matwey@sai.msu.ru>: >> > 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 ^ permalink raw reply [flat|nested] 17+ messages in thread
end of thread, other threads:[~2017-11-16 18:00 UTC | newest] Thread overview: 17+ messages (download: mbox.gz / follow: Atom feed) -- links below jump to the message on this page -- 2017-04-27 10:20 [PATCH] usb: musb: musb_host: Introduce postponed URB giveback Matwey V. Kornilov 2017-04-27 15:35 ` Bin Liu 2017-04-27 16:26 ` Matwey V. Kornilov 2017-04-27 17:13 ` Bin Liu 2017-04-28 7:04 ` Matwey V. Kornilov 2017-04-28 11:58 ` Bin Liu 2017-04-28 12:13 ` Matwey V. Kornilov 2017-04-28 12:43 ` Bin Liu 2017-04-28 13:15 ` Matwey V. Kornilov 2017-04-28 13:30 ` Bin Liu 2017-04-29 8:16 ` Matwey V. Kornilov 2017-04-29 14:24 ` Matwey V. Kornilov 2017-04-30 16:19 ` Matwey V. Kornilov 2017-11-04 14:05 ` Matwey V. Kornilov 2017-11-15 15:19 ` Matwey V. Kornilov 2017-11-16 16:32 ` Bin Liu 2017-11-16 17:59 ` Matwey V. Kornilov
This is a public inbox, see mirroring instructions for how to clone and mirror all data and code used for this inbox; as well as URLs for NNTP newsgroup(s).