BCM2835-V4L2 triggers warning of bad buffer handling on stop_streaming.

[6by9]

From raspberrypi/firmware#347 the V4L2 driver is tripping a warning in V4L2-core of buffers not being returned on stop_streaming().
New issue to fix the warning, as the original issue in mjpeg-streamer turned out to be a client issue.

https://github.com/raspberrypi/linux/blob/rpi-3.18.y/drivers/media/v4l2-core/videobuf2-core.c#L2135

    /*
    * If you see this warning, then the driver isn't cleaning up properly
    * in stop_streaming(). See the stop_streaming() documentation in
    * videobuf2-core.h for more information how buffers should be returned
    * to vb2 in stop_streaming().
    */

The docs for stop_streaming then say

    * @stop_streaming: called when 'streaming' state must be disabled; driver
    * should stop any DMA transactions or wait until they
    * finish and give back all buffers it got from buf_queue()
    * callback by calling @vb2_buffer_done() with either
    * VB2_BUF_STATE_DONE or VB2_BUF_STATE_ERROR; may use
    * vb2_wait_for_all_buffers() function

Somehow it seems there is a case where buffers aren't being returned to the core when stopping.

[popcornmix]

Is this something you can investigate?

[6by9]

Yes, more creating the issue so I don't forget. I'll also be adding it to my own list of jobs to look into.

I did have a quick look before but couldn't see an obvious reason as all the buffers should be returned on flush, and on being returned from the GPU they should be released back to V4L2 core. Some extra logging in the core might show up some more information.

[brguy]

I have the same issue here using Raspian and a Pi NoIR camera.

[74093.661302] ------------[ cut here ]------------
[74093.661426] WARNING: CPU: 0 PID: 27775 at drivers/media/v4l2-core/videobuf2-core.c:2135 __vb2_queue_cancel+0xf4/0x160 [videobuf2_core]()
[74093.661530] Modules linked in: evdev uinput rfcomm bnep bcm2835_v4l2 videobuf2_vmalloc videobuf2_memops videobuf2_core v4l2_common videodev media snd_bcm2835 snd_pcm snd_seq snd_seq_device snd_timer snd spi_bcm2708 i2c_bcm2708 i2c_dev ecb btusb bluetooth 8192cu rfkill uio_pdrv_genirq uio
[74093.661717] CPU: 0 PID: 27775 Comm: v4l2-ctl Tainted: G        W      3.18.7+ #755
[74093.661795] [<c00151fc>] (unwind_backtrace) from [<c0012710>] (show_stack+0x20/0x24)
[74093.661837] [<c0012710>] (show_stack) from [<c0555b30>] (dump_stack+0x20/0x28)
[74093.661882] [<c0555b30>] (dump_stack) from [<c0022ef4>] (warn_slowpath_common+0x7c/0x9c)
[74093.661952] [<c0022ef4>] (warn_slowpath_common) from [<c0022fd0>] (warn_slowpath_null+0x2c/0x34)
[74093.662016] [<c0022fd0>] (warn_slowpath_null) from [<bf263a1c>] (__vb2_queue_cancel+0xf4/0x160 [videobuf2_core])
[74093.662086] [<bf263a1c>] (__vb2_queue_cancel [videobuf2_core]) from [<bf265548>] (vb2_internal_streamoff+0x40/0xdc [videobuf2_core])
[74093.662150] [<bf265548>] (vb2_internal_streamoff [videobuf2_core]) from [<bf2656d8>] (vb2_streamoff+0x3c/0x60 [videobuf2_core])
[74093.662208] [<bf2656d8>] (vb2_streamoff [videobuf2_core]) from [<bf26574c>] (vb2_ioctl_streamoff+0x50/0x54 [videobuf2_core])
[74093.662393] [<bf26574c>] (vb2_ioctl_streamoff [videobuf2_core]) from [<bf228658>] (v4l_streamoff+0x28/0x2c [videodev])
[74093.662575] [<bf228658>] (v4l_streamoff [videodev]) from [<bf22baf4>] (__video_do_ioctl+0x254/0x2e8 [videodev])
[74093.662837] [<bf22baf4>] (__video_do_ioctl [videodev]) from [<bf22b49c>] (video_usercopy+0x180/0x560 [videodev])
[74093.663078] [<bf22b49c>] (video_usercopy [videodev]) from [<bf22b898>] (video_ioctl2+0x1c/0x24 [videodev])
[74093.663301] [<bf22b898>] (video_ioctl2 [videodev]) from [<bf2266b0>] (v4l2_ioctl+0x11c/0x14c [videodev])
[74093.663417] [<bf2266b0>] (v4l2_ioctl [videodev]) from [<c014c478>] (do_vfs_ioctl+0x3f0/0x5d4)
[74093.663454] [<c014c478>] (do_vfs_ioctl) from [<c014c6a0>] (SyS_ioctl+0x44/0x6c)
[74093.663490] [<c014c6a0>] (SyS_ioctl) from [<c000e8c0>] (ret_fast_syscall+0x0/0x48)
[74093.663549] ---[ end trace 9a211324166d1547 ]---

[6by9]

It'll happen on all Pi's with all Pi cameras! "Me too"s aren't going to help on this one.

It is only a warning which the framework then cleans up after, and this issue was only logged so that I don't forget to look into it (I'm one the ex-Broadcom people, and originally wrote a large chunk of the V4L2 driver).

[melroy89]

I'm using MotionEye with the Raspberry Pi Camera I got simular issues:
Mar 16 01:37:53 raspcam kernel: [ 120.314824] bcm2835-v4l2: error 0 waiting for frame completion
Mar 16 01:38:29 raspcam kernel: [ 156.344834] bcm2835-v4l2: error 0 waiting for frame completion
Mar 16 01:40:24 raspcam kernel: [ 271.934879] bcm2835-v4l2: error 0 waiting for frame completion
Mar 16 01:41:00 raspcam kernel: [ 307.464841] bcm2835-v4l2: error 0 waiting for frame completion
Mar 16 01:43:25 raspcam kernel: [ 452.964878] bcm2835-v4l2: error 0 waiting for frame completion

The live stream gets disconnect after 20 sec. It is NOT just a warning. Please help me!

uname:
Linux raspcam 3.18.9+ #768 PREEMPT Sun Mar 15 18:59:03 GMT 2015 armv6l GNU/Linux

modinfo  bcm2835-v4l2
filename:       /lib/modules/3.18.9+/kernel/drivers/media/platform/bcm2835/bcm2835-v4l2.ko
version:        0.0.2
license:        GPL
author:         Vincent Sanders
description:    Broadcom 2835 MMAL video capture
srcversion:     A53F05DC7F5805EF1F9152C
depends:        videobuf2-core,videodev,videobuf2-vmalloc,v4l2-common
intree:         Y
vermagic:       3.18.9+ preempt mod_unload modversions ARMv6 
parm:           debug:int
parm:           bcm2835_v4l2_debug:Debug level 0-2
parm:           max_video_width:Threshold for video mode (int)
parm:           max_video_height:Threshold for video mode (int)
parm:           gst_v4l2src_is_broken:If non-zero, enable workaround for Gstreamer (int)

And firmware version:
/opt/vc/bin/vcgencmd version
Mar 15 2015 19:51:38 
Copyright (c) 2012 Broadcom
version fef371701296941551f3b8375d5680a427c04f48 (clean) (release)

[6by9]

This issue is solely linked to the error message
[74093.661426] WARNING: CPU: 0 PID: 27775 at drivers/media/v4l2-core/videobuf2-core.c:2135 __vb2_queue_cancel+0xf4/0x160 [videobuf2_core]()
That IS only a warning.

If you have an issue with one particular app then please either raise a new issue, or post on the forums as more people who may be able to help read those. You'll need to provide LOTS more detail as to how you are configuring MotionEye - resolution, encoding, and framerate as an absolute minimum.

[6by9]

I know the reason behind the warning now - only waiting for one buffer to come back, rather than all. I haven't had a chance to fix it yet. Probably need a counting semaphore (as MMAL does normally) rather than just waiting on a completion.

[melroy89]

You think my issue is related to MotionEye? Uhm..

[6by9]

I know that your problem is not related to this issue, which is just there as a reminder to me to look into this warning. (The V4L2 framework got updated between 3.12 and 3.18, and now does a sanity check on all buffers being returned. The Pi driver currently doesn't do that)

(a) Look at the first post on http://www.raspberrypi.org/forums/viewtopic.php?f=43&t=62364 which lists a few simple steps for exercising the V4L2 driver (the v4l2-ctl commands). Do those work for you? If yes, then it isn't a generic V4L2 driver issue. (If no, then I'd suspect your camera module to be at fault)
(b) Have you checked your sensor works using Raspistill or raspivid?
(c) It seems MotionEye is referenced heavily from http://www.raspberrypi.org/forums/viewtopic.php?f=43&t=83369 Have you read that thread?
(d) Post on the forums asking for assistance.
(e) If you have a test case that you can demonstrably show that the kernel is at fault, then create a new issue here with full details for reproducing the issue.

This is not a good place to post if you want help triaging an issue.

[melroy89]

Thanks for your reply 6by9.

[pelwell]

Ping @6by9 - this is still an issue.

[6by9]

I know - I still haven't looked at it in detail (looking after small children and having to go to work gets in the way).

Multiple buffers are submitted to the GPU. On stop, we flush the component, but only wait for one buffer to be returned before declaring "job done" and returning. If the GPU had more than one buffer, then they will all have been flushed and returned to the driver, but not released back to videobuf2 so it objects that nominally buffers are still in flight.

Actually by the looks of it, even if only one buffer is with the GPU, getting that buffer back signals the completion but doesn't return the buffer to videobuf2 (https://github.com/raspberrypi/linux/blob/rpi-4.0.y/drivers/media/platform/bcm2835/bcm2835-camera.c#L335) - a call to vb2_buffer_done(&buf->vb, VB2_BUF_STATE_ERROR); from there may be sufficient to shut the warning up in a fair percentage of cases.
In fact that may be all that is required (mmal-vchiq.c function port_disable() is waiting for all callbacks to have been made before completing, therefore buffer_cb should have been called the necessary number of times to make videobuf2 happy.

It is only a warning (the GPU will have flushed all buffers and therefore won't be writing to them), so annoying rather than critical.