search

raspberrypi / linux

Kernel source tree for Raspberry Pi-provided kernel builds. Issues unrelated to the linux kernel should be posted on the community forum at https://forums.raspberrypi.com/
Other
10.98k stars 4.94k forks source link

Kernel OOPS under load on camera video capture - bcm2835_v4l2 driver #2387

Open cstavaru opened 6 years ago

cstavaru commented 6 years ago

Hello everyone,

I am using a Raspberry Pi Zero W with camera module V2 and the official 5.1V/2.5A PSU (tried other PSUs too - same result), and I'm trying to capture hardware-accelerated H264 video at 720p/25fps, via gstreamer/omx/v4l2, and the stream is made available in web browsers via Janus WebRTC Gateway. All the software used is compiled at the latest version available on GitHub (or via apt-get dist-upgrade).

Things work fine until enough load is applied to the Pi Zero W device. For example, starting Octoprint server (consumes a lot of CPU while starting up) and opening a second stream session in an Android Firefox browser) is sure to consistently trigger the issue.

A kernel OOPS error is generated, always at the same function with the same stack. The system remains active but camera capture is not possible again until reboot. I am thinking that if it was a hardware failure of some sort it would happen at slightly different points in the source code. Below you can find the relevant kernel logs (I have also activated debug flag on the bcm2835_v4l2 driver):

...
rpi1 kernel: [  102.133148] bcm2835-v4l2: Buffer has ts 102024919000
rpi1 kernel: [  102.177035] bcm2835-v4l2: buffer_cb: status:0, buf:c431c800, length:1382400, flags 4, pts 105707068
rpi1 kernel: [  102.177055] bcm2835-v4l2: Buffer time set as converted timestamp - 102064901000 = (pts [105707068 usec] - vc start time [79762446 usec]) + kernel start time [76120279000 nsec]
rpi1 kernel: [  102.177061] bcm2835-v4l2: Buffer has ts 102064901000
rpi1 kernel: [  102.218151] bcm2835-v4l2: buffer_cb: status:0, buf:c4323000, length:1382400, flags 4, pts 105747049
rpi1 kernel: [  102.218172] bcm2835-v4l2: Buffer time set as converted timestamp - 102104882000 = (pts [105747049 usec] - vc start time [79762446 usec]) + kernel start time [76120279000 nsec]
rpi1 kernel: [  102.218177] bcm2835-v4l2: Buffer has ts 102104882000
rpi1 kernel: [  102.241227] bcm2835-v4l2: queue_setup: dev:d697b000
rpi1 kernel: [  102.262073] Unable to handle kernel paging request at virtual address 313fb504
rpi1 kernel: [  102.263862] pgd = d2164000
rpi1 kernel: [  102.265522] [313fb504] *pgd=00000000
rpi1 kernel: [  102.267233] Internal error: Oops: 805 [#1] ARM
rpi1 kernel: [  102.268965] Modules linked in: cmac bnep hci_uart btbcm bluetooth brcmfmac brcmutil snd_bcm2835 snd_pcm snd_timer cfg80211 snd rfkill bcm2835_gpiomem uio_pdrv_genirq fixed uio bcm2835_v4l2 v4l2_common videobuf2_vmalloc videobuf2_memops videobuf2_v4l2 videobuf2_core videodev media ip_tables x_tables ipv6
rpi1 kernel: [  102.278292] CPU: 0 PID: 553 Comm: v4l2src0:src Not tainted 4.9.79+ #1091
rpi1 kernel: [  102.280255] Hardware name: BCM2835
rpi1 kernel: [  102.282191] task: d11b9b40 task.stack: d11f4000
rpi1 kernel: [  102.285425] PC is at __vb2_queue_alloc+0xc8/0x3dc [videobuf2_core]
rpi1 kernel: [  102.287922] LR is at 0x0
rpi1 kernel: [  102.289937] pc : [<bf0d89b0>]    lr : [<00000000>]    psr: 60000013
rpi1 kernel: [  102.289937] sp : d11f5c70  ip : 00000000  fp : d11f5cbc
rpi1 kernel: [  102.294044] r10: 00000001  r9 : 00000001  r8 : d6aa0020
rpi1 kernel: [  102.296082] r7 : 00000002  r6 : d6aa0002  r5 : d697b4b0  r4 : d6aa0400
rpi1 kernel: [  102.298124] r3 : 313fb4b8  r2 : 00000001  r1 : d11f5cd0  r0 : d6aa0420
rpi1 kernel: [  102.300206] Flags: nZCv  IRQs on  FIQs on  Mode SVC_32  ISA ARM  Segment user
rpi1 kernel: [  102.302350] Control: 00c5387d  Table: 12164008  DAC: 00000055
rpi1 kernel: [  102.304503] Process v4l2src0:src (pid: 553, stack limit = 0xd11f4188)
rpi1 kernel: [  102.306673] Stack: (0xd11f5c70 to 0xd11f6000)
rpi1 kernel: [  102.308804] 5c60:                                     00000000 d11f5c80 00000001 00000001
rpi1 kernel: [  102.313386] 5c80: bf0dde00 00000020 00000003 00000001 bf0fe388 d697b4b0 00000001 c4255004
...
rpi1 kernel: [  102.469149] 5fe0: 00000000 b1cfe7fc b678d15c b6bbb8ac 20000010 0000000b 00000000 00000000
rpi1 kernel: [  102.475796] [<bf0d89b0>] (__vb2_queue_alloc [videobuf2_core]) from [<bf0d905c>] (vb2_core_create_bufs+0xe4/0x28c [videobuf2_core])
rpi1 kernel: [  102.482011] [<bf0d905c>] (vb2_core_create_bufs [videobuf2_core]) from [<bf0e50f0>] (vb2_create_bufs+0xf0/0x180 [videobuf2_v4l2])
rpi1 kernel: [  102.489470] [<bf0e50f0>] (vb2_create_bufs [videobuf2_v4l2]) from [<bf0e566c>] (vb2_ioctl_create_bufs+0x8c/0xa8 [videobuf2_v4l2])
rpi1 kernel: [  102.495454] [<bf0e566c>] (vb2_ioctl_create_bufs [videobuf2_v4l2]) from [<bf0a2f58>] (v4l_create_bufs+0x60/0x7c [videodev])
rpi1 kernel: [  102.501392] [<bf0a2f58>] (v4l_create_bufs [videodev]) from [<bf0a1ac8>] (__video_do_ioctl+0x2a0/0x320 [videodev])
rpi1 kernel: [  102.507426] [<bf0a1ac8>] (__video_do_ioctl [videodev]) from [<bf0a14f8>] (video_usercopy+0x234/0x540 [videodev])
rpi1 kernel: [  102.513990] [<bf0a14f8>] (video_usercopy [videodev]) from [<bf0a1820>] (video_ioctl2+0x1c/0x24 [videodev])
rpi1 kernel: [  102.521205] [<bf0a1820>] (video_ioctl2 [videodev]) from [<bf09b688>] (v4l2_ioctl+0xd4/0xec [videodev])
rpi1 kernel: [  102.529016] [<bf09b688>] (v4l2_ioctl [videodev]) from [<c0157a58>] (do_vfs_ioctl+0x9c/0x7d4)
rpi1 kernel: [  102.534828] [<c0157a58>] (do_vfs_ioctl) from [<c01581d4>] (SyS_ioctl+0x44/0x6c)
rpi1 kernel: [  102.537755] [<c01581d4>] (SyS_ioctl) from [<c000fe40>] (ret_fast_syscall+0x0/0x1c)
rpi1 kernel: [  102.543332] Code: 1afffff9 e51b2030 e0853106 e3520001 (e583404c) 
rpi1 kernel: [  102.546442] ---[ end trace c017786695322689 ]---

My gstreamer pipeline looks like this:

gst-launch-1.0 -v v4l2src device=/dev/video0 do-timestamp=true ! video/x-raw,width=1280,height=720,framerate=25/1 ! omxh264enc target-bitrate=1500000 control-rate=1 ! video/x-h264,profile=high ! h264parse ! rtph264pay name=pay0 config-interval=10 pt=96 ! udpsink host=0.0.0.0 port=5004

Thanks for looking into it !

cstavaru commented 6 years ago

I have an important update on this:

It seems that the issue only happens if the 'nice' value of the gstreamer process is +5 or more. In this case, I can reproduce the issue in a few seconds. If I use a nice value of +4 or less, I could not reproduce the issue until now.

I was using a high nice value for the streaming process (started with +19, and tried lower values by binary search until I got to the +4), in order for the streaming to not disturb more important services like Octoprint (which sends commands to a 3D printer and must not be disturbed)

6by9 commented 6 years ago

That sounds strange if it is failing in videbuf2 allocation as that is standard code. That also shouldn't be being called whilst streaming, which is the implication of queue_setup being in the middle at all those buffer_cb lines.

Two thoughts:

cstavaru commented 6 years ago

Thank you for your response.

When letting the V4L2 driver spit out H264 720p25, the lag is around 15 seconds and the image is quite choppy (but the CPU utilization is very low), while when using the omxh264enc on raw camera output, the lag is around 300 milliseconds and the image is fluid (and the CPU utilization is around 20%). Is this normal ? Or maybe I am using the wrong settings ?

About the driver compilation, I will try to do it over the next days. I am now using kernel 4.14.18+ (same issue).

By the way, here is my gstreamer pipeline using h264 output from v4l2. Maybe I am doing something wrong ?

I used this:

gst-launch-1.0 -v v4l2src device=/dev/video0 do-timestamp=true ! video/x-h264,width=1280,height=720,framerate=25/1,bitrate=1500000 ! h264parse ! rtph264pay name=pay0 config-interval=10 pt=96 ! udpsink host=0.0.0.0 port=5004

and also this (same 15-second lag)

raspivid -t 0 -h 720 -w 1280 -fps 25 -hf -b 1500000 -o - | gst-launch-1.0 -v fdsrc ! h264parse ! rtph264pay name=pay0 config-interval=10 pt=96 ! udpsink host=0.0.0.0 port=5004

6by9 commented 6 years ago

There's nothing in the firmware that would be introducing that sort of latency. Use v4l2-ctl and it'll be down at the normal 80ish ms, so there's nothing fundamentally wrong in the V4L2 driver. Using omxh264enc is doing a bundle more work shuffling image data around (ie 1.4MB per frame), as V4L2 is copying the data to userspace, only for GST to have to copy it all back to the GPU. There are several image conversions required too.

One thing to try with the raspivid line is adding -fl to your command line for flush. Linux uses a fairly sizeable buffer within pipes and some other file operations, and calling fflush triggers it to actually pass the data on rather than buffering it.

I'm wondering if GStreamer is trying to increase the number of buffers that it has requested from V4L2 whilst streaming. That would explain the CREATE_BUFS ioctl call whilst streaming. It'll take a modest amount of digging in to the GST code to see if that is what is going on, and I'm not sure if it is a valid thing to do within V4L2 (need to reread the spec).

cstavaru commented 6 years ago

I have tried adding the -fl flag to raspivid and nothing has changed. Is there any possibility that the v4l2 driver does software instead of hardware encoding ? Like, maybe (due to some strange issue) not finding the required capabilities for hardware encoding and silently falling back to software ? The choppiness and lag almost feel like software encoding taking place. The low CPU utilization in this case may be because the kernel activity is not reflected in the CPU stats (not sure about this thing though).

However, the more worrying issue is that in this case (v4l2 doing the H264 encoding) I get another kernel OOPS (reproduced it multiple times), and it does not depend on the process priority. Below you can find the trace (unfortunately the debug flag is not enabled on the driver, please let me know if it would help you):

...
rpi1 kernel: [  149.491130] Unable to handle kernel NULL pointer dereference at virtual address 00000000
rpi1 kernel: [  149.494507] pgd = cacac000
rpi1 kernel: [  149.496159] [00000000] *pgd=0ac2c831, *pte=00000000, *ppte=00000000
rpi1 kernel: [  149.497959] Internal error: Oops: 17 [#1] ARM
rpi1 kernel: [  149.500068] Modules linked in: cmac bnep hci_uart bluetooth ecdh_generic brcmfmac brcmutil cfg80211 snd_bcm2835(C) rfkill snd_pcm snd_timer snd uio_pdrv_genirq uio fixed bcm2835_v4l2(C) v4l2_common videobuf2_vmalloc videobuf2_memops videobuf2_v4l2 videobuf2_core videodev media ip_tables x_tables ipv6
rpi1 kernel: [  149.509090] CPU: 0 PID: 798 Comm: v4l2src0:src Tainted: G        WC      4.14.18+ #1093
rpi1 kernel: [  149.514365] Hardware name: BCM2835
rpi1 kernel: [  149.516891] task: cac96120 task.stack: cadc6000
rpi1 kernel: [  149.518991] PC is at vchiq_mmal_port_enable+0x70/0x124 [bcm2835_v4l2]
rpi1 kernel: [  149.521087] LR is at mutex_lock_interruptible+0x1c/0x5c
rpi1 kernel: [  149.523196] pc : [<bf100ba8>]    lr : [<c0631728>]    psr: 00000113
rpi1 kernel: [  149.525365] sp : cadc7ce0  ip : cadc7cc8  fp : cadc7d0c
rpi1 kernel: [  149.527531] r10: d3bf0140  r9 : 00000000  r8 : bf0fc610
rpi1 kernel: [  149.529747] r7 : d6b803fc  r6 : d6b80004  r5 : d6b80000  r4 : d6ac8000
rpi1 kernel: [  149.532055] r3 : 00000001  r2 : 00000000  r1 : d6b80484  r0 : 00000000
rpi1 kernel: [  149.534496] Flags: nzcv  IRQs on  FIQs on  Mode SVC_32  ISA ARM  Segment user
rpi1 kernel: [  149.536845] Control: 00c5387d  Table: 0acac008  DAC: 00000055
rpi1 kernel: [  149.539956] Process v4l2src0:src (pid: 798, stack limit = 0xcadc6188)
rpi1 kernel: [  149.542214] Stack: (0xcadc7ce0 to 0xcadc8000)
rpi1 kernel: [  149.544440] 7ce0: d6b803fc d6ac8000 d6ac85e0 d6ac85d0 d6ac8058 00000012 00000000 d3bf0140
...
rpi1 kernel: [  149.685612] 7fe0: b6cf4054 b1d8bc04 b67df574 b6bfc8ac a0000010 0000000e 00000000 00000000
rpi1 kernel: [  149.691206] [<bf100ba8>] (vchiq_mmal_port_enable [bcm2835_v4l2]) from [<bf0fca60>] (start_streaming+0xf4/0x22c [bcm2835_v4l2])
rpi1 kernel: [  149.696980] [<bf0fca60>] (start_streaming [bcm2835_v4l2]) from [<bf0d84e0>] (vb2_start_streaming+0x6c/0x160 [videobuf2_core])
rpi1 kernel: [  149.703085] [<bf0d84e0>] (vb2_start_streaming [videobuf2_core]) from [<bf0d9a48>] (vb2_core_streamon+0x110/0x168 [videobuf2_core])
rpi1 kernel: [  149.709950] [<bf0d9a48>] (vb2_core_streamon [videobuf2_core]) from [<bf0e51e8>] (vb2_streamon+0x3c/0x60 [videobuf2_v4l2])
rpi1 kernel: [  149.717404] [<bf0e51e8>] (vb2_streamon [videobuf2_v4l2]) from [<bf0e525c>] (vb2_ioctl_streamon+0x50/0x54 [videobuf2_v4l2])
rpi1 kernel: [  149.723285] [<bf0e525c>] (vb2_ioctl_streamon [videobuf2_v4l2]) from [<bf09f830>] (v4l_streamon+0x28/0x2c [videodev])
rpi1 kernel: [  149.729294] [<bf09f830>] (v4l_streamon [videodev]) from [<bf0a3f5c>] (__video_do_ioctl+0x2a0/0x320 [videodev])
rpi1 kernel: [  149.735743] [<bf0a3f5c>] (__video_do_ioctl [videodev]) from [<bf0a39f8>] (video_usercopy+0x2d4/0x574 [videodev])
rpi1 kernel: [  149.743011] [<bf0a39f8>] (video_usercopy [videodev]) from [<bf0a3cb4>] (video_ioctl2+0x1c/0x24 [videodev])
rpi1 kernel: [  149.750922] [<bf0a3cb4>] (video_ioctl2 [videodev]) from [<bf09d688>] (v4l2_ioctl+0xd4/0xec [videodev])
rpi1 kernel: [  149.757107] [<bf09d688>] (v4l2_ioctl [videodev]) from [<c016c4a8>] (do_vfs_ioctl+0x9c/0x754)
rpi1 kernel: [  149.762922] [<c016c4a8>] (do_vfs_ioctl) from [<c016cba4>] (SyS_ioctl+0x44/0x6c)
rpi1 kernel: [  149.766172] [<c016cba4>] (SyS_ioctl) from [<c000fe00>] (ret_fast_syscall+0x0/0x28)
rpi1 kernel: [  149.773062] Code: e1a01007 e5b12088 e1520001 0a000003 (e5922000) 
rpi1 kernel: [  149.776163] ---[ end trace f2e6ff78e0ff38d1 ]---

Thanks !

cstavaru commented 6 years ago

Hello,

I have compiled the kernel from the branch you have indicated and used your latest driver modifications and the flags in config.txt and cmdline.txt. Unfortunately, running the raspivid -> gstreamer pipeline gets the same results (extremely choppy video, a fraction of a second of movement every 10-15 seconds or so) and running the gstreamer with omx264enc doesn't work because the device /dev/video0 doesn't seem to exist (but a device probably does exist, since the raspivid works. Please note, vcgencmd get_camera reports detected=1 and supported=1.).

ERROR: Pipeline doesn't want to pause. ERROR: from element /GstPipeline:pipeline0/GstV4l2Src:v4l2src0: Cannot identify device '/dev/video0'. Additional debug info: ../subprojects/gst-plugins-good/sys/v4l2/v4l2_calls.c(616): gst_v4l2_open (): /GstPipeline:pipeline0/GstV4l2Src:v4l2src0: system error: No such file or directory

Please let me know if you would like me to try different things/new source code/debug flags, etc.

cstavaru commented 6 years ago

Hello,

I think I have solved the problem, at least I have a good solution.

The extremely choppy video was caused by the "do-timestamp=true" flag in the v4l2src parameters for gstreamer. Once I removed that, everything worked great.

The raspivid -> gstreamer pipeline still does not work. I think it is also connected with the above issue. The problem seems to be that gstreamer sees the framerate as being "0/1" upstream instead of the correct "25/1" in my case. I'm not sure what raspivid does that causes this, I have even compiled the latest available version with no luck.

So, for reference and those needing a good pipeline for gstreamer on Pi Zero W and camera V2, this is the best one that works for me (with only 5-6% CPU usage on Pi Zero W):

gst-launch-1.0 -v v4l2src ! video/x-h264,width=1280,height=720,framerate=25/1,profile=high,bitrate=1850000 ! h264parse ! rtph264pay name=pay0 config-interval=10 pt=96 ! udpsink host=127.0.0.1 port=5004

6by9 commented 6 years ago

Not having /dev/video0 means something in the setup didn't work. You'd need to go through the device tree logs to confim that the relevant node under /soc/v4l2 (you can either check the firmware logs by adding "dtdebug=1" to /boot/config.txt, and using sudo vcdbg log msg to look at those logs, or look under /proc/device-tree to be able to browse a full representation of the active device tree).

The bcm2835-camera V4L2 driver will never do software encoding - the code simply isn't there to do it.

do-timestamp=true

pi@raspberrypi:~ $ gst-inspect-1.0 v4l2src
...
  do-timestamp        : Apply current stream time to buffers
                        flags: readable, writable
                        Boolean. Default: false

That doesn't seem like a sensible option to use unless you have reason to distrust the timestamps from the source component. AFAIK the V4L2 driver is producing sensible timestamps, so removing them will potentially add A/V sync issues as you're throwing away any information on processing latency.

raspivid->gstreamer framerate is likely to be down to the fact that storing a frame rate in H264 headers is optional. https://github.com/raspberrypi/firmware/issues/245 added a parameter MMAL_PARAMETER_VIDEO_ENCODE_SPS_TIMING / OMX_IndexParamBrcmVideoAVCSPSTimingEnable to insert the timing section into the H264 SPS header. It's off by default, but a quick hack to raspivid function create_encoder_component to add

mmal_port_parameter_set(encoder_output, MMAL_PARAMETER_VIDEO_ENCODE_SPS_TIMING, MMAL_TRUE);

may result in GStreamer's h264parse being happier and picking up a frame rate. Either that or you should be able to override the frame rate in the GStreamer

I'm glad you have a workaround, but please leave this issue open until I've had a chance to look into what GStreamer is actually up to with queue_setup whilst streaming. https://linuxtv.org/downloads/v4l-dvb-apis-new/uapi/v4l/buffer.html does mention being able to reset the format with buffers allocated, but that's not this situation. I can't see anything about the validity of updating the buffer count whilst streaming (if it is allowed then I need to explicitly block it in my new branch).

cstavaru commented 6 years ago

Hello 6by9,

Thanks a lot for your insights on the issue. I now understand it a bit better. When I will have a bit of free time I will re-compile raspivid with the code you suggested and I will report here the outcome.

About the custom kernel, I kind of gave up because it seemed like it was going nowhere (same issues).

JamesH65 commented 6 years ago

@6by9 Any recently changed on this, or leave open?

6by9 commented 6 years ago

Leave open for now.