v4l2src: playback failure observed as the allocated memory in the previous iteration is not properly released
Hello All,
I have observed an issue with v4l2src using the following test setup.
- GStreamer pipeline with v4l2src is running on thread 1 and the pipeline state is being controlled from thread 2.
- From thread 2, will trigger state change (PLAY->NULL->PLAY...) multiple times.
playback failure is observed after a few iterations and log snippet for issue scenario is provided below:
0:05:30.206554817 [335m 3184[00m 0x40003c12f210 [36mINFO [00m [00;01;31m GST_STATES ../../gstreamer-1.12.4/gst/gstelement.c:2467:gst_element_continue_state:<hdmi_v4lsrc>[00m completed state change to NULL
0:05:30.224707772 [335m 3184[00m 0x40003c12f210 [36mINFO [00m [00;01;31m GST_STATES ../../gstreamer-1.12.4/gst/gstelement.c:2467:gst_element_continue_state:<hdmi_v4lsrc>[00m completed state change to READY
0:05:30.244085030 [335m 3184[00m 0x40003c12f210 [36mINFO [00m [00;01;31m GST_STATES ../../gstreamer-1.12.4/gst/gstelement.c:2467:gst_element_continue_state:<hdmi_v4lsrc>[00m completed state change to PAUSED
0:05:30.259031264 [335m 3184[00m 0x40003c12f210 [33;01mLOG [00m [00m v4l2 ../../../git/sys/v4l2/gstv4l2object.c:4050:gst_v4l2_object_unlock_stop:<hdmi_v4lsrc>[00m stop flushing
0:05:30.259530814 [335m 3184[00m 0x40003c12f210 [36mINFO [00m [00;01;31m GST_STATES ../../gstreamer-1.12.4/gst/gstelement.c:2467:gst_element_continue_state:<hdmi_v4lsrc>[00m completed state change to PLAYING
0:05:30.265820223 [335m 3184[00m 0x40003c12f210 [33;01mLOG [00m [00m v4l2 ../../../git/sys/v4l2/gstv4l2object.c:4037:gst_v4l2_object_unlock:<hdmi_v4lsrc>[00m start flushing
0:05:30.265905252 [335m 3184[00m 0x40003c12f210 [36mINFO [00m [00;01;31m GST_STATES ../../gstreamer-1.12.4/gst/gstelement.c:2467:gst_element_continue_state:<hdmi_v4lsrc>[00m completed state change to PAUSED
0:05:30.267381039 [335m 3184[00m 0x400060005ad0 [37mDEBUG [00m [00m v4l2 ../../../git/sys/v4l2/gstv4l2object.c:4061:gst_v4l2_object_stop:<hdmi_v4lsrc>[00m stopping
0:05:30.267439785 [335m 3184[00m 0x400060005ad0 [37mDEBUG [00m [00m v4l2 ../../../git/sys/v4l2/gstv4l2object.c:3836:gst_v4l2_object_set_format:<hdmi_v4lsrc>[00m Setting format to video/x-raw, format=(string)RGB16, width=(int)720, height=(int)480, framerate=(fraction)120/1, pixel-aspect-ratio=(fraction)1/1
0:05:30.268182600 [335m 3184[00m 0x400060005ad0 [37mDEBUG [00m [00m v4l2 ../../../git/sys/v4l2/gstv4l2object.c:2897:gst_v4l2_object_setup_pool:<hdmi_v4lsrc>[00m initializing the capture system
0:05:30.268220523 [335m 3184[00m 0x400060005ad0 [36mINFO [00m [00m v4l2 ../../../git/sys/v4l2/gstv4l2object.c:2921:gst_v4l2_object_setup_pool:<hdmi_v4lsrc>[00m accessing buffers via mode 4
0:05:30.268248546 [335m 3184[00m 0x400060005ad0 [33;01mLOG [00m [00m v4l2 ../../../git/sys/v4l2/gstv4l2object.c:2930:gst_v4l2_object_setup_pool:<hdmi_v4lsrc>[00m initiating buffer pool
0:05:30.282816743 [335m 3184[00m 0x40003c12f210 [37mDEBUG [00m [00m basesrc ../../../../gstreamer-1.12.4/libs/gst/base/gstbasesrc.c:3526:gst_base_src_stop:<hdmi_v4lsrc>[00m stopping source
0:05:30.282878189 [335m 3184[00m 0x40003c12f210 [33;01mLOG [00m [00m v4l2 ../../../git/sys/v4l2/gstv4l2object.c:4037:gst_v4l2_object_unlock:<hdmi_v4lsrc>[00m start flushing
0:05:30.282893431 [335m 3184[00m 0x40003c12f210 [33;01mLOG [00m [00m v4l2 ../../../git/sys/v4l2/gstv4l2object.c:4050:gst_v4l2_object_unlock_stop:<hdmi_v4lsrc>[00m stop flushing
0:05:30.289003182 [335m 3184[00m 0x400060005ad0 [37mDEBUG [00m [00m v4l2allocator ../../../git/sys/v4l2/gstv4l2allocator.c:706:gst_v4l2_allocator_start:<hdmi_v4lsrc:pool:src:allocator>[00m allocated 6 mmap buffers out of 6 requested
0:05:30.291062768 [335m 3184[00m 0x400060005ad0 [33;01mLOG [00m [00m v4l2allocator ../../../git/sys/v4l2/gstv4l2allocator.c:880:gst_v4l2_allocator_alloc_dmabuf:<hdmi_v4lsrc:pool:src:allocator>[00m exported DMABUF as fd 45 plane 0
0:05:30.291606722 [335m 3184[00m 0x400060005ad0 [33;01mLOG [00m [00m v4l2allocator ../../../git/sys/v4l2/gstv4l2allocator.c:880:gst_v4l2_allocator_alloc_dmabuf:<hdmi_v4lsrc:pool:src:allocator>[00m exported DMABUF as fd 55 plane 0
0:05:30.292018123 [335m 3184[00m 0x400060005ad0 [33;01mLOG [00m [00m v4l2allocator ../../../git/sys/v4l2/gstv4l2allocator.c:880:gst_v4l2_allocator_alloc_dmabuf:<hdmi_v4lsrc:pool:src:allocator>[00m exported DMABUF as fd 57 plane 0
0:05:30.292377379 [335m 3184[00m 0x400060005ad0 [33;01mLOG [00m [00m v4l2allocator ../../../git/sys/v4l2/gstv4l2allocator.c:880:gst_v4l2_allocator_alloc_dmabuf:<hdmi_v4lsrc:pool:src:allocator>[00m exported DMABUF as fd 59 plane 0
0:05:30.292640325 [335m 3184[00m 0x400060005ad0 [33;01mLOG [00m [00m v4l2allocator ../../../git/sys/v4l2/gstv4l2allocator.c:880:gst_v4l2_allocator_alloc_dmabuf:<hdmi_v4lsrc:pool:src:allocator>[00m exported DMABUF as fd 61 plane 0
0:05:30.292951036 [335m 3184[00m 0x400060005ad0 [33;01mLOG [00m [00m v4l2allocator ../../../git/sys/v4l2/gstv4l2allocator.c:880:gst_v4l2_allocator_alloc_dmabuf:<hdmi_v4lsrc:pool:src:allocator>[00m exported DMABUF as fd 63 plane 0
0:05:30.293244226 [335m 3184[00m 0x400060005ad0 [37mDEBUG [00m [00m v4l2bufferpool ../../../git/sys/v4l2/gstv4l2bufferpool.c:1081:gst_v4l2_buffer_pool_flush_stop:<hdmi_v4lsrc:pool:src>[00m stop flushing
0:05:30.301586680 [335m 3184[00m 0x400060005ad0 [31;01mERROR [00m [00m v4l2bufferpool ../../../git/sys/v4l2/gstv4l2bufferpool.c:757:gst_v4l2_buffer_pool_streamon:<hdmi_v4lsrc:pool:src>[00m error with STREAMON 61 (No data available)
0:05:30.303071888 [335m 3184[00m 0x40003c12f210 [37mDEBUG [00m [00m v4l2 ../../../git/sys/v4l2/gstv4l2object.c:4061:gst_v4l2_object_stop:<hdmi_v4lsrc>[00m stopping
0:05:30.303186260 [335m 3184[00m 0x40003c12f210 [37mDEBUG [00m [00m v4l2bufferpool ../../../git/sys/v4l2/gstv4l2bufferpool.c:1060:gst_v4l2_buffer_pool_flush_start:<hdmi_v4lsrc:pool:src>[00m start flushing
0:05:30.303344736 [335m 3184[00m 0x40003c12f210 [33;01mLOG [00m [00m bufferpool ../../gstreamer-1.12.4/gst/gstbufferpool.c:427:do_stop:<hdmi_v4lsrc:pool:src>[00m stopping
0:05:30.303367838 [335m 3184[00m 0x40003c12f210 [37mDEBUG [00m [00m v4l2bufferpool ../../../git/sys/v4l2/gstv4l2bufferpool.c:1000:gst_v4l2_buffer_pool_stop:<hdmi_v4lsrc:pool:src>[00m stopping pool
0:05:30.303367838 [335m 3184[00m 0x40003c12f210 [37mDEBUG [00m [00m v4l2bufferpool ../../../git/sys/v4l2/gstv4l2bufferpool.c:1000:gst_v4l2_buffer_pool_stop:<hdmi_v4lsrc:pool:src>[00m stopping pool
0:05:30.304122473 [335m 3184[00m 0x40003c12f210 [37mDEBUG [00m [00m v4l2allocator ../../../git/sys/v4l2/gstv4l2allocator.c:757:gst_v4l2_allocator_stop:<hdmi_v4lsrc:pool:src:allocator>[00m stop allocator
0:05:30.304144376 [335m 3184[00m 0x40003c12f210 [37mDEBUG [00m [00m v4l2allocator ../../../git/sys/v4l2/gstv4l2allocator.c:765:gst_v4l2_allocator_stop:<hdmi_v4lsrc:pool:src:allocator>[00m allocator is still in use
0:05:30.304165978 [335m 3184[00m 0x40003c12f210 [33;01mWARN [00m [00m v4l2bufferpool ../../../git/sys/v4l2/gstv4l2bufferpool.c:1047:gst_v4l2_buffer_pool_stop:<hdmi_v4lsrc:pool:src>[00m some buffers are still outstanding
0:05:30.304187280 [335m 3184[00m 0x40003c12f210 [33;01mWARN [00m [00m bufferpool ../../gstreamer-1.12.4/gst/gstbufferpool.c:567:gst_buffer_pool_set_active:<hdmi_v4lsrc:pool:src>[00m stop failed
0:05:30.304345216 [335m 3184[00m 0x40003c12f210 [33;01mLOG [00m [00m bufferpool ../../gstreamer-1.12.4/gst/gstbufferpool.c:427:do_stop:<hdmi_v4lsrc:pool:src>[00m stopping
0:05:30.304362197 [335m 3184[00m 0x40003c12f210 [37mDEBUG [00m [00m v4l2bufferpool ../../../git/sys/v4l2/gstv4l2bufferpool.c:1000:gst_v4l2_buffer_pool_stop:<hdmi_v4lsrc:pool:src>[00m stopping pool
0:05:30.304362197 [335m 3184[00m 0x40003c12f210 [37mDEBUG [00m [00m v4l2bufferpool ../../../git/sys/v4l2/gstv4l2bufferpool.c:1000:gst_v4l2_buffer_pool_stop:<hdmi_v4lsrc:pool:src>[00m stopping pool
0:05:30.304398681 [335m 3184[00m 0x40003c12f210 [37mDEBUG [00m [00m v4l2allocator ../../../git/sys/v4l2/gstv4l2allocator.c:757:gst_v4l2_allocator_stop:<hdmi_v4lsrc:pool:src:allocator>[00m stop allocator
0:05:30.304417763 [335m 3184[00m 0x40003c12f210 [37mDEBUG [00m [00m v4l2allocator ../../../git/sys/v4l2/gstv4l2allocator.c:765:gst_v4l2_allocator_stop:<hdmi_v4lsrc:pool:src:allocator>[00m allocator is still in use
0:05:30.304436905 [335m 3184[00m 0x40003c12f210 [33;01mWARN [00m [00m v4l2bufferpool ../../../git/sys/v4l2/gstv4l2bufferpool.c:1047:gst_v4l2_buffer_pool_stop:<hdmi_v4lsrc:pool:src>[00m some buffers are still outstanding
0:05:30.304455507 [335m 3184[00m 0x40003c12f210 [33;01mWARN [00m [00m bufferpool ../../gstreamer-1.12.4/gst/gstbufferpool.c:567:gst_buffer_pool_set_active:<hdmi_v4lsrc:pool:src>[00m stop failed
0:05:30.304717613 [335m 3184[00m 0x40003c12f210 [33;01mLOG [00m [00m bufferpool ../../gstreamer-1.12.4/gst/gstbufferpool.c:427:do_stop:<hdmi_v4lsrc:pool:src>[00m stopping
0:05:30.304734295 [335m 3184[00m 0x40003c12f210 [37mDEBUG [00m [00m v4l2bufferpool ../../../git/sys/v4l2/gstv4l2bufferpool.c:1000:gst_v4l2_buffer_pool_stop:<hdmi_v4lsrc:pool:src>[00m stopping pool
0:05:30.304734295 [335m 3184[00m 0x40003c12f210 [37mDEBUG [00m [00m v4l2bufferpool ../../../git/sys/v4l2/gstv4l2bufferpool.c:1000:gst_v4l2_buffer_pool_stop:<hdmi_v4lsrc:pool:src>[00m stopping pool
0:05:30.304904232 [335m 3184[00m 0x40003c12f210 [37mDEBUG [00m [00;01;31;41m GST_PADS ../../gstreamer-1.12.4/gst/gstpad.c:1044:post_activate:<hdmi_v4lsrc:src>[00m stopped streaming
0:05:30.305274349 [335m 3184[00m 0x40003c12f210 [36mINFO [00m [00;01;31m GST_STATES ../../gstreamer-1.12.4/gst/gstelement.c:2467:gst_element_continue_state:<hdmi_v4lsrc>[00m completed state change to READY
All the future playback attempts result in a failure as the VIDIOC_S_FMT ioctl fails with Device or resource busy error.
0:05:30.313760217 [335m 3184[00m 0x40003c12f210 [36mINFO [00m [00;01;31m GST_STATES ../../gstreamer-1.12.4/gst/gstelement.c:2467:gst_element_continue_state:<hdmi_v4lsrc>[00m completed state change to NULL
0:05:33.462624002 [335m 3184[00m 0x40003c12f210 [36mINFO [00m [00;01;31m GST_STATES ../../gstreamer-1.12.4/gst/gstelement.c:2467:gst_element_continue_state:<hdmi_v4lsrc>[00m completed state change to READY
0:05:33.477616322 [335m 3184[00m 0x40003c12f210 [36mINFO [00m [00;01;31m GST_STATES ../../gstreamer-1.12.4/gst/gstelement.c:2467:gst_element_continue_state:<hdmi_v4lsrc>[00m completed state change to PAUSED
0:05:33.491577678 [335m 3184[00m 0x40003c12f210 [33;01mLOG [00m [00m v4l2 ../../../git/sys/v4l2/gstv4l2object.c:4050:gst_v4l2_object_unlock_stop:<hdmi_v4lsrc>[00m stop flushing
0:05:33.491691389 [335m 3184[00m 0x40003c12f210 [36mINFO [00m [00;01;31m GST_STATES ../../gstreamer-1.12.4/gst/gstelement.c:2467:gst_element_continue_state:<hdmi_v4lsrc>[00m completed state change to PLAYING
0:05:33.493787579 [335m 3184[00m 0x400060005b70 [31;01mERROR [00m [00m v4l2src ../../../git/sys/v4l2/gstv4l2src.c:516:gst_v4l2src_fixate:[00m v4l2_ioctl (fd = 44, VIDIOC_S_FMT, &format) failed, errno is 16 (Device or resource busy)
...
0:05:35.508819561 [335m 3184[00m 0x40003c12f210 [36mINFO [00m [00;01;31m GST_STATES ../../gstreamer-1.12.4/gst/gstelement.c:2467:gst_element_continue_state:<hdmi_v4lsrc>[00m completed state change to READY
0:05:35.516542394 [335m 3184[00m 0x40003c12f210 [36mINFO [00m [00;01;31m GST_STATES ../../gstreamer-1.12.4/gst/gstelement.c:2467:gst_element_continue_state:<hdmi_v4lsrc>[00m completed state change to NULL
Here is the issue scenario:
- bufferpool is activated during the PAUSED -> READY transition. Memory is allocated in gst_v4l2_buffer_pool_start().
- then the VIDIOC_STREAMON ioctl fails (pool is not streaming)
- when gst_v4l2_buffer_pool_stop() is called, memory is not released as gst_v4l2_allocator_flush() is only triggered when the pool is streaming.
So memory allocated by in the particular iteration is not released.
I wanted to know whether the above-presented scenario is a valid corner case.
And should we release the allocated memory while performing pool_stop regardless of whether the pool is streaming or not?