High CPU usage when video streaming on EHCI, 3.17.8 kernel with DMA enabled

High CPU usage when video streaming on EHCI, 3.17.8 kernel with DMA enabled

[Tom Mises]

Hi,

I posted this on linux-uvc-devel, but was told the data transfer part
is handled by the USB driver.

I am running 3.17.8 kernel with DMA enabled on TI DM3730 (Gumstix
Overo Firestorm-P COM). When streaming video frames in mmap or userptr
mode, I am
seeing very high CPU usage, up to 70%. This CPU usage is reported to
be in software interrupts. The captured frames are NOT corrupted.

Interestingly, when running 3.5 kernel, with DMA enabled as well, the
CPU usage is 30% and it is reported to be mostly in the user space.
So, it guess it suggests PIO not DMA is actually used here.

Neither of these results are satisfactory, I hoped DMA would take care
of the data transfer and the CPU resources would be available to run
data processing.

I used the video capture example from the V4L2 API documentation. This
behavior was tested and observed for two different cameras, one of
them working in isochronous mode, the other working in bulk mode.

Interrupts showing activity during the streaming are:
omap-dma-engine,
ehci_hcd:usb1.

I also ran another test with very low resolution and fps
settings, 160x90 5ps YUV422. In that case, on 3.5 kernel, CPU usage was
very low. However, on 3.17.8 kernel, it was still similar as before,
around 60% and all in software interrupts; it was dropping to zero
intermittently this time.

Perhaps, the problem is somewhere in the interaction between the UVC
driver and the DMA or USB driver. As far as I understand, the UVC
driver uses vmalloc(), which, again AFAIU, is not ideal for DMA
transfers. Is this known to work on other similar platforms?

I am aware this is a somewhat vague
description unfortunately, but I am not sure what other detail would
be helpful. UVC debugging messages do not show anything unusual.
Beyond that, debugging these drivers on my own exceeds my expertise,
so I will welcome any suggestions.

There is also the following error message from EDMA, I do not think it
is related though.
[    0.557342] edma-dma-engine edma-dma-engine.0: Can't allocate PaRAM
dummy slot
[    0.557434] edma-dma-engine: probe of edma-dma-engine.0 failed with error -22

Thanks,

Tom
--
To unsubscribe from this list: send the line "unsubscribe linux-usb" in
the body of a message to majordomo-u79uwXL29TY76Z2rM5mHXA@public.gmane.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html

Re: High CPU usage when video streaming on EHCI, 3.17.8 kernel with DMA enabled

[Alan Stern]

On Sun, 17 May 2015, Tom Mises wrote:

> Hi,
> 
> I posted this on linux-uvc-devel, but was told the data transfer part
> is handled by the USB driver.
> 
> I am running 3.17.8 kernel with DMA enabled on TI DM3730 (Gumstix
> Overo Firestorm-P COM). When streaming video frames in mmap or userptr
> mode, I am
> seeing very high CPU usage, up to 70%. This CPU usage is reported to
> be in software interrupts. The captured frames are NOT corrupted.
> 
> Interestingly, when running 3.5 kernel, with DMA enabled as well, the
> CPU usage is 30% and it is reported to be mostly in the user space.
> So, it guess it suggests PIO not DMA is actually used here.

EHCI always uses DMA.  It cannot use PIO.

> Neither of these results are satisfactory, I hoped DMA would take care
> of the data transfer and the CPU resources would be available to run
> data processing.
> 
> I used the video capture example from the V4L2 API documentation. This
> behavior was tested and observed for two different cameras, one of
> them working in isochronous mode, the other working in bulk mode.
> 
> Interrupts showing activity during the streaming are:
> omap-dma-engine,
> ehci_hcd:usb1.
> 
> I also ran another test with very low resolution and fps
> settings, 160x90 5ps YUV422. In that case, on 3.5 kernel, CPU usage was
> very low. However, on 3.17.8 kernel, it was still similar as before,
> around 60% and all in software interrupts; it was dropping to zero
> intermittently this time.
> 
> Perhaps, the problem is somewhere in the interaction between the UVC
> driver and the DMA or USB driver. As far as I understand, the UVC
> driver uses vmalloc(), which, again AFAIU, is not ideal for DMA
> transfers. Is this known to work on other similar platforms?

I haven't heard complaints about the UVC driver.

> I am aware this is a somewhat vague
> description unfortunately, but I am not sure what other detail would
> be helpful. UVC debugging messages do not show anything unusual.
> Beyond that, debugging these drivers on my own exceeds my expertise,
> so I will welcome any suggestions.

You might be able to learn more from ftrace.  See the instructions in
Documentation/trace/ftrace.txt.  The "irqsoff" tracer may be the best
one to try.

> There is also the following error message from EDMA, I do not think it
> is related though.
> [    0.557342] edma-dma-engine edma-dma-engine.0: Can't allocate PaRAM
> dummy slot
> [    0.557434] edma-dma-engine: probe of edma-dma-engine.0 failed with error -22

It seems unlikely to be related.

Alan Stern

--
To unsubscribe from this list: send the line "unsubscribe linux-usb" in
the body of a message to majordomo-u79uwXL29TY76Z2rM5mHXA@public.gmane.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html

Re: High CPU usage when video streaming on EHCI, 3.17.8 kernel with DMA enabled

[Matthieu CASTET]

Hi,

last time I checked uvc driver, it was doing memcpy of video buffer : see uvc_video_decode_data.

It your video resolution is big, this can eat lot's of cpu.

Doing a trace should help you.

Matthieu




Le Sun, 17 May 2015 10:06:11 -0400,
Alan Stern <stern@rowland.harvard.edu> a écrit :

> On Sun, 17 May 2015, Tom Mises wrote:
> 
> > Hi,
> > 
> > I posted this on linux-uvc-devel, but was told the data transfer part
> > is handled by the USB driver.
> > 
> > I am running 3.17.8 kernel with DMA enabled on TI DM3730 (Gumstix
> > Overo Firestorm-P COM). When streaming video frames in mmap or userptr
> > mode, I am
> > seeing very high CPU usage, up to 70%. This CPU usage is reported to
> > be in software interrupts. The captured frames are NOT corrupted.
> > 
> > Interestingly, when running 3.5 kernel, with DMA enabled as well, the
> > CPU usage is 30% and it is reported to be mostly in the user space.
> > So, it guess it suggests PIO not DMA is actually used here.
> 
> EHCI always uses DMA.  It cannot use PIO.
> 
> > Neither of these results are satisfactory, I hoped DMA would take care
> > of the data transfer and the CPU resources would be available to run
> > data processing.
> > 
> > I used the video capture example from the V4L2 API documentation. This
> > behavior was tested and observed for two different cameras, one of
> > them working in isochronous mode, the other working in bulk mode.
> > 
> > Interrupts showing activity during the streaming are:
> > omap-dma-engine,
> > ehci_hcd:usb1.
> > 
> > I also ran another test with very low resolution and fps
> > settings, 160x90 5ps YUV422. In that case, on 3.5 kernel, CPU usage was
> > very low. However, on 3.17.8 kernel, it was still similar as before,
> > around 60% and all in software interrupts; it was dropping to zero
> > intermittently this time.
> > 
> > Perhaps, the problem is somewhere in the interaction between the UVC
> > driver and the DMA or USB driver. As far as I understand, the UVC
> > driver uses vmalloc(), which, again AFAIU, is not ideal for DMA
> > transfers. Is this known to work on other similar platforms?
> 
> I haven't heard complaints about the UVC driver.
> 
> > I am aware this is a somewhat vague
> > description unfortunately, but I am not sure what other detail would
> > be helpful. UVC debugging messages do not show anything unusual.
> > Beyond that, debugging these drivers on my own exceeds my expertise,
> > so I will welcome any suggestions.
> 
> You might be able to learn more from ftrace.  See the instructions in
> Documentation/trace/ftrace.txt.  The "irqsoff" tracer may be the best
> one to try.
> 
> > There is also the following error message from EDMA, I do not think it
> > is related though.
> > [    0.557342] edma-dma-engine edma-dma-engine.0: Can't allocate PaRAM
> > dummy slot
> > [    0.557434] edma-dma-engine: probe of edma-dma-engine.0 failed with error -22
> 
> It seems unlikely to be related.
> 
> Alan Stern
> 
> --
> To unsubscribe from this list: send the line "unsubscribe linux-usb" in
> the body of a message to majordomo@vger.kernel.org
> More majordomo info at  http://vger.kernel.org/majordomo-info.html

--
To unsubscribe from this list: send the line "unsubscribe linux-omap" in
the body of a message to majordomo@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html

Re: High CPU usage when video streaming on EHCI, 3.17.8 kernel with DMA enabled

[Tony Lindgren]

* Matthieu CASTET <matthieu.castet@parrot.com> [150518 01:34]:
> Hi,
> 
> last time I checked uvc driver, it was doing memcpy of video buffer : see uvc_video_decode_data.
> 
> It your video resolution is big, this can eat lot's of cpu.
> 
> Doing a trace should help you.

For the memcpy part with DMA this patch should help too:

[PATCH] dmaengine: omap-dma: Add support for memcpy

Regards,

Tony

Re: High CPU usage when video streaming on EHCI, 3.17.8 kernel with DMA enabled

[Ash Charles]

On Mon, May 18, 2015 at 7:59 AM, Tony Lindgren <tony-4v6yS6AI5VpBDgjK7y7TUQ@public.gmane.org> wrote:
> [PATCH] dmaengine: omap-dma: Add support for memcpy

Hi Tom,

To follow up on your corresponding mail to the gumstix list [1], I
tried on the 3.17.8 kernel on an Overo COM (DM37390) with the
suggested dmaengine patch applied.  Using "hdparm -t --DIRECT
/dev/sda" with a USB hard drive attached via the USB EHCI port, I see
a read speed of ~24MB/s (vs ~33MB/s on my laptop).  I see the same
behaviour on a recent kernel (from tony/omap-for-v4.2/cleanup,
otherwise works nicely on an Overo FWIW) with and without the
dmaengine patch.

What would be the expected USB read speed for an OMAP3 platform?

--Ash
[1] http://gumstix.8.x6.nabble.com/Low-USB-speed-on-Overo-td4969907.html
--
To unsubscribe from this list: send the line "unsubscribe linux-usb" in
the body of a message to majordomo-u79uwXL29TY76Z2rM5mHXA@public.gmane.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html

Re: High CPU usage when video streaming on EHCI, 3.17.8 kernel with DMA enabled

[Tom Mises]

I has been some time, but I have an update to share.

On Sun, May 17, 2015 at 8:06 AM, Alan Stern <stern-nwvwT67g6+6dFdvTe/nMLpVzexx5G7lz@public.gmane.org> wrote:
> You might be able to learn more from ftrace.  See the instructions in
> Documentation/trace/ftrace.txt.  The "irqsoff" tracer may be the best
> one to try.

I used ftrace with the irqoff tracer as recommended. irqoff seems to
have some known issues on ARM and it traces the idle process, however,
I was able to get some meaningful output when running this tracer for
a very short time. I ran the function_graph tracer as well, which is
quite informative, but it also adds a lot of overhead.

On Mon, May 18, 2015 at 2:27 AM, Matthieu CASTET
<matthieu.castet-ITF29qwbsa/QT0dZR+AlfA@public.gmane.org> wrote:
> last time I checked uvc driver, it was doing memcpy of video buffer : see uvc_video_decode_data.

I found out Matthieu was on the right track and most of the time is
indeed spent in uvc_video_decode_data(), which uses memcpy() to copy
the URBs to the video buffers. For 1280x960px 15fps single 8-bit
channel,  uvc_video_decode_data() seems to consume between 40% and
50%. What is still a mystery to me is why I see relatively high CPU
usage even for a very tiny resolution. I was able to confirm that it
is not uvc_video_decode_data() in that case, however, given
function_graph overhead and irqoff being partially broken I was unable
to figure out much more.

I attached some tracer outputs at the end.

On Mon, May 18, 2015 at 8:59 AM, Tony Lindgren <tony-4v6yS6AI5VpBDgjK7y7TUQ@public.gmane.org> wrote:
> For the memcpy part with DMA this patch should help too:
>
> [PATCH] dmaengine: omap-dma: Add support for memcpy

The patch should help, but not out of the box as far as I understand.
My understanding is that to take advantage of this, it would be
necessary to explicitly call the DMA API either by replacing memcpy()
in uvc_video_decode_data() or by modyfying the memcpy()
implementation. Is that correct?


*******************************************
/sys/kernel/debug/tracing# echo 0 > tracing_max_latency && echo 1 >
tracing_on && usleep 10 && echo 0 > tracing_on
# tracer: irqsoff
#
# irqsoff latency trace v1.1.5 on 3.17.8-custom
# --------------------------------------------------------------------
# latency: 579 us, #26/26, CPU#0 | (M:server VP:0, KP:0, SP:0 HP:0 #P:1)
#    -----------------
#    | task: sshd-2980 (uid:0 nice:0 policy:0 rt_prio:0)
#    -----------------
#  => started at: __usb_hcd_giveback_urb
#  => ended at:   __usb_hcd_giveback_urb
#
#
#                  _------=> CPU#
#                 / _-----=> irqs-off
#                | / _----=> need-resched
#                || / _---=> hardirq/softirq
#                ||| / _--=> preempt-depth
#                |||| /     delay
#  cmd     pid   ||||| time  |   caller
#     \   /      |||||  \    |   /
    sshd-2980    0d.s.    0us : trace_hardirqs_on <-tasklet_action
    sshd-2980    0d.s.    0us : time_hardirqs_on <-tasklet_action
    sshd-2980    0d.s.    0us : trace_hardirqs_off <-_raw_spin_lock_irq
    sshd-2980    0d.s.    0us : trace_hardirqs_on <-_raw_spin_unlock_irq
    sshd-2980    0d.s.    0us : time_hardirqs_on <-_raw_spin_unlock_irq
    sshd-2980    0d.s.    0us+: trace_hardirqs_off <-__usb_hcd_giveback_urb
    sshd-2980    0d.s.   31us : uvc_video_complete <-__usb_hcd_giveback_urb
    sshd-2980    0d.s.   31us : uvc_video_decode_bulk <-uvc_video_complete
    sshd-2980    0d.s.   31us : uvc_video_decode_start <-uvc_video_decode_bulk
    sshd-2980    0d.s.   31us : ktime_get_ts64 <-uvc_video_decode_start
    sshd-2980    0d.s.   31us : clocksource_mmio_readl_up <-ktime_get_ts64
    sshd-2980    0d.s.   31us!: uvc_video_decode_data.isra.17
<-uvc_video_decode_bulk
    sshd-2980    0d.s.  519us : usb_submit_urb <-uvc_video_complete
    sshd-2980    0d.s.  519us : usb_hcd_submit_urb <-usb_submit_urb
    sshd-2980    0d.s.  519us : usb_get_urb <-usb_hcd_submit_urb
    sshd-2980    0d.s.  519us : usb_hcd_map_urb_for_dma <-usb_hcd_submit_urb
    sshd-2980    0d.s.  519us+: ehci_urb_enqueue <-usb_hcd_submit_urb
    sshd-2980    0d.s.  549us : qh_urb_transaction <-ehci_urb_enqueue
    sshd-2980    0d.s.  549us : ehci_qtd_alloc.isra.71 <-qh_urb_transaction
    sshd-2980    0d.s.  549us : dma_pool_alloc <-ehci_qtd_alloc.isra.71
    sshd-2980    0d.s.  549us : qtd_fill.isra.54 <-qh_urb_transaction
    sshd-2980    0d.s.  549us : usb_hcd_link_urb_to_ep <-ehci_urb_enqueue
    sshd-2980    0d.s.  549us+: qh_append_tds <-ehci_urb_enqueue
    sshd-2980    0d.s.  580us : trace_hardirqs_on <-__usb_hcd_giveback_urb
    sshd-2980    0d.s.  580us+: time_hardirqs_on <-__usb_hcd_giveback_urb
    sshd-2980    0d.s.  671us : <stack trace>
 => trace_hardirqs_on
 => __usb_hcd_giveback_urb
 => usb_giveback_urb_bh
 => tasklet_action
 => __do_softirq
 => irq_exit
 => handle_IRQ
 => omap3_intc_handle_irq
 => __irq_usr
 =>
*******************************************


*******************************************
# tracer: function_graph
#
#     TIME      DURATION            FUNCTION CALLS
#      |         |   |              |   |   |   |
 5853.350952   0.000 us    | do_raw_spin_lock();
 5853.350952   0.000 us    | do_raw_spin_unlock();
 5853.350952               | __usb_hcd_giveback_urb() {
 5853.350952               |   unmap_urb_for_dma() {
 5853.350982               |     usb_hcd_unmap_urb_for_dma() {
 5853.350982   0.000 us    |       usb_hcd_unmap_urb_setup_for_dma();
 5853.350982   0.000 us    |     } /* usb_hcd_unmap_urb_for_dma */
 5853.350982 + 30.517 us   |   } /* unmap_urb_for_dma */
 5853.350982   0.000 us    |   usb_anchor_suspend_wakeups();
 5853.350982   0.000 us    |   usb_unanchor_urb();
 5853.351013               |   uvc_video_complete [uvcvideo]() {
 5853.351013   0.000 us    |     do_raw_spin_lock();
 5853.351013   0.000 us    |     do_raw_spin_unlock();
 5853.351043               |     uvc_video_decode_bulk [uvcvideo]() {
 5853.351043 ! 457.763 us  |       uvc_video_decode_data.isra.17 [uvcvideo]();
 5853.351501 ! 457.763 us  |     } /* uvc_video_decode_bulk [uvcvideo] */
 5853.351501               |     usb_submit_urb() {
 5853.351501               |       usb_hcd_submit_urb() {
 5853.351501   0.000 us    |         usb_get_urb();
 5853.351501   0.000 us    |         usb_hcd_map_urb_for_dma();
 5853.351531               |         ehci_urb_enqueue() {
 5853.351531               |           qh_urb_transaction() {
 5853.351531               |             ehci_qtd_alloc.isra.71() {
 5853.351531               |               dma_pool_alloc() {
 5853.351531   0.000 us    |                 do_raw_spin_lock();
 5853.351562   0.000 us    |                 do_raw_spin_unlock();
 5853.351562 + 30.517 us   |               } /* dma_pool_alloc */
 5853.351562 + 30.517 us   |             } /* ehci_qtd_alloc.isra.71 */
 5853.351562   0.000 us    |             qtd_fill.isra.54();
 5853.351562 + 30.517 us   |           } /* qh_urb_transaction */
 5853.351593   0.000 us    |           do_raw_spin_lock();
 5853.351593               |           usb_hcd_link_urb_to_ep() {
 5853.351593               |             _raw_spin_lock() {
 5853.351593   0.000 us    |               do_raw_spin_lock();
 5853.351593   0.000 us    |             } /* _raw_spin_lock */
 5853.351623               |             _raw_spin_unlock() {
 5853.351623   0.000 us    |               do_raw_spin_unlock();
 5853.351623   0.000 us    |             } /* _raw_spin_unlock */
 5853.351623 + 30.518 us   |           } /* usb_hcd_link_urb_to_ep */
 5853.351623   0.000 us    |           qh_append_tds();
 5853.351654   0.000 us    |           do_raw_spin_unlock();
 5853.351654 ! 122.070 us  |         } /* ehci_urb_enqueue */
 5853.351654 ! 152.588 us  |       } /* usb_hcd_submit_urb */
 5853.351654 ! 152.588 us  |     } /* usb_submit_urb */
 5853.351654 ! 640.869 us  |   } /* uvc_video_complete [uvcvideo] */
 5853.351654               |   handle_IRQ() {
 5853.351715   0.000 us    |     idle_cpu();
 5853.351715 + 30.517 us   |   } /* handle_IRQ */
 5853.351715   0.000 us    |   usb_anchor_resume_wakeups();
 5853.351715 + 30.518 us   |   usb_free_urb();
 5853.351745 ! 793.457 us  | } /* __usb_hcd_giveback_urb */
*******************************************


Tom
--
To unsubscribe from this list: send the line "unsubscribe linux-usb" in
the body of a message to majordomo-u79uwXL29TY76Z2rM5mHXA@public.gmane.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html

Re: High CPU usage when video streaming on EHCI, 3.17.8 kernel with DMA enabled

[Tony Lindgren]

* Tom Mises <tommises-Re5JQEeQqe8AvxtiuMwx3w@public.gmane.org> [150701 11:24]:
> On Mon, May 18, 2015 at 8:59 AM, Tony Lindgren <tony-4v6yS6AI5VpBDgjK7y7TUQ@public.gmane.org> wrote:
> > For the memcpy part with DMA this patch should help too:
> >
> > [PATCH] dmaengine: omap-dma: Add support for memcpy
> 
> The patch should help, but not out of the box as far as I understand.
> My understanding is that to take advantage of this, it would be
> necessary to explicitly call the DMA API either by replacing memcpy()
> in uvc_video_decode_data() or by modyfying the memcpy()
> implementation. Is that correct?

Yes you should be able to configure the DMA to do memory-to-memory
copy where both source and destination address is looping over
the desired buffer size. Ideally you would move the data from camera
directly to the buffer without doing a memcpy inbetween.

Regards,

Tony
--
To unsubscribe from this list: send the line "unsubscribe linux-usb" in
the body of a message to majordomo-u79uwXL29TY76Z2rM5mHXA@public.gmane.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html