v4l2sink with MPEG-TS stalls when caps are changed due to streamheader
Issue
When using v4l2sink to push an MPEG-TS stream to a device it appears to stall after the caps get changed to add the streamheader. This does not stall the whole pipeline (e.g. if the data is tee'd into udpsink and the v4l2sink the data still goes over the network) and no errors or warnings are generated when this occurs.
Expected Behavior
buffers should either be pushed into the sink or warnings should be generated that they aren't being processed.
Observed Behavior
no output is observed after the first 2 buffers.
Setup
- linux
- ZCU106 Xilinx development board
- 1.20.5
- gst-launch-1.0 filesrc location=test.ts ! tsparse alignment=7 ! v4l2sink device=/dev/video4
Steps to reproduce the bug
- open terminal
- type
gst-launch-1.0 filesrc location=test.ts ! tsparse alignment=7 ! v4l2sink device=/dev/video4
How reproducible is the bug?
always with this configuration
Solutions you have tried
if a capssetter is added before the v4l2sink to set the caps always to "" and prevent it from seeing the streamheader then it streams data continually without issue.
Additional Information
log of failure
Note that while pipeline is running no more output appears from the sink the shown below0:00:00.046477320 31377 0x557312c200 DEBUG v4l2sink gstv4l2sink.c:490:gst_v4l2sink_get_caps:<v4l2sink0> device is not open
0:00:00.046559240 31377 0x557312c200 DEBUG v4l2sink gstv4l2sink.c:490:gst_v4l2sink_get_caps:<v4l2sink0> device is not open
0:00:00.046686320 31377 0x557312c200 DEBUG v4l2sink gstv4l2sink.c:444:gst_v4l2sink_change_state:<v4l2sink0> 1 -> 2
0:00:00.046711800 31377 0x557312c200 DEBUG v4l2 v4l2_calls.c:524:gst_v4l2_open:<v4l2sink0:sink> Trying to open device /dev/video4
0:00:00.046759480 31377 0x557312c200 DEBUG v4l2 v4l2_calls.c:66:gst_v4l2_get_capabilities:<v4l2sink0> getting capabilities
0:00:00.046801420 31377 0x557312c200 LOG v4l2 v4l2_calls.c:80:gst_v4l2_get_capabilities:<v4l2sink0> driver: 'xilinx-dvb-vipp'
0:00:00.046824020 31377 0x557312c200 LOG v4l2 v4l2_calls.c:81:gst_v4l2_get_capabilities:<v4l2sink0> card: 'dvb_output input 0'
0:00:00.046844620 31377 0x557312c200 LOG v4l2 v4l2_calls.c:82:gst_v4l2_get_capabilities:<v4l2sink0> bus_info: 'platform:dvb_output:0'
0:00:00.046863880 31377 0x557312c200 LOG v4l2 v4l2_calls.c:83:gst_v4l2_get_capabilities:<v4l2sink0> version: 00050f13
0:00:00.046882660 31377 0x557312c200 LOG v4l2 v4l2_calls.c:84:gst_v4l2_get_capabilities:<v4l2sink0> capabilities: 04200002
0:00:00.046936260 31377 0x557312c200 DEBUG v4l2 v4l2_calls.c:138:gst_v4l2_fill_lists:<v4l2sink0> getting enumerations
0:00:00.046956440 31377 0x557312c200 DEBUG v4l2 v4l2_calls.c:141:gst_v4l2_fill_lists:<v4l2sink0> channels
0:00:00.046976180 31377 0x557312c200 DEBUG v4l2 v4l2_calls.c:213:gst_v4l2_fill_lists:<v4l2sink0> norms
0:00:00.046994700 31377 0x557312c200 DEBUG v4l2 v4l2_calls.c:261:gst_v4l2_fill_lists:<v4l2sink0> controls+menus
0:00:00.047015080 31377 0x557312c200 DEBUG v4l2 v4l2_calls.c:281:gst_v4l2_fill_lists:<v4l2sink0> checking control 00000000
0:00:00.047042840 31377 0x557312c200 DEBUG v4l2 v4l2_calls.c:323:gst_v4l2_fill_lists:<v4l2sink0> starting control class 'User Controls'
0:00:00.047062780 31377 0x557312c200 DEBUG v4l2 v4l2_calls.c:281:gst_v4l2_fill_lists:<v4l2sink0> checking control 00980001
0:00:00.047235620 31377 0x557312c200 DEBUG v4l2 v4l2_calls.c:323:gst_v4l2_fill_lists:<v4l2sink0> starting control class 'Codec Controls'
0:00:00.047255820 31377 0x557312c200 DEBUG v4l2 v4l2_calls.c:281:gst_v4l2_fill_lists:<v4l2sink0> checking control 00990001
0:00:00.047321700 31377 0x557312c200 DEBUG v4l2 v4l2_calls.c:288:gst_v4l2_fill_lists:<v4l2sink0> controls finished
0:00:00.047337120 31377 0x557312c200 DEBUG v4l2 v4l2_calls.c:457:gst_v4l2_fill_lists:<v4l2sink0> done
0:00:00.047357820 31377 0x557312c200 INFO v4l2 v4l2_calls.c:591:gst_v4l2_open:<v4l2sink0:sink> Opened device 'dvb_output input 0' (/dev/video4) successfully
0:00:00.047380820 31377 0x557312c200 DEBUG v4l2 gstv4l2object.c:904:gst_v4l2_set_defaults:<v4l2sink0:sink> tv_norm=0x0, norm=(nil)
0:00:00.047398180 31377 0x557312c200 DEBUG v4l2 v4l2_calls.c:740:gst_v4l2_get_norm:<v4l2sink0:sink> getting norm
0:00:00.047435100 31377 0x557312c200 DEBUG v4l2 v4l2_calls.c:1168:gst_v4l2_get_output:<v4l2sink0:sink> trying to get output
0:00:00.591809400 31377 0x557312c200 DEBUG v4l2sink gstv4l2sink.c:444:gst_v4l2sink_change_state:<v4l2sink0> 2 -> 3
0:00:00.662375860 31377 0x55731a2700 DEBUG v4l2 gstv4l2object.c:1231:gst_v4l2_object_fill_format_list:<v4l2sink0:sink> getting src format enumerations
0:00:00.662445480 31377 0x55731a2700 LOG v4l2 gstv4l2object.c:1249:gst_v4l2_object_fill_format_list:<v4l2sink0:sink> index: 0
0:00:00.662468220 31377 0x55731a2700 LOG v4l2 gstv4l2object.c:1250:gst_v4l2_object_fill_format_list:<v4l2sink0:sink> type: 2
0:00:00.662492300 31377 0x55731a2700 LOG v4l2 gstv4l2object.c:1251:gst_v4l2_object_fill_format_list:<v4l2sink0:sink> flags: 00000001
0:00:00.662515460 31377 0x55731a2700 LOG v4l2 gstv4l2object.c:1252:gst_v4l2_object_fill_format_list:<v4l2sink0:sink> description: 'MPEG-1/2/4'
0:00:00.662541980 31377 0x55731a2700 LOG v4l2 gstv4l2object.c:1254:gst_v4l2_object_fill_format_list:<v4l2sink0:sink> pixelformat: MPEG
0:00:00.662566760 31377 0x55731a2700 INFO v4l2 gstv4l2object.c:1268:gst_v4l2_object_fill_format_list:<v4l2sink0:sink> got 1 format(s):
0:00:00.662591900 31377 0x55731a2700 INFO v4l2 gstv4l2object.c:1272:gst_v4l2_object_fill_format_list:<v4l2sink0:sink> MPEG
0:00:00.662649300 31377 0x55731a2700 INFO v4l2 gstv4l2object.c:4811:gst_v4l2_object_probe_caps:<v4l2sink0:sink> probed caps: video/mpegts, systemstream=(boolean)true
0:00:00.664053920 31377 0x557319fb60 DEBUG v4l2sink gstv4l2sink.c:505:gst_v4l2sink_set_caps:<v4l2sink0> caps: video/mpegts, systemstream=(boolean)true, packetsize=(int)188
0:00:00.664086980 31377 0x557319fb60 DEBUG v4l2 gstv4l2object.c:4690:gst_v4l2_object_stop:<v4l2sink0:sink> stopping
0:00:00.664120800 31377 0x557319fb60 DEBUG v4l2 gstv4l2object.c:4322:gst_v4l2_object_set_format:<v4l2sink0:sink> Setting format to video/mpegts, systemstream=(boolean)true, packetsize=(int)188
0:00:00.664167760 31377 0x557319fb60 DEBUG v4l2 gstv4l2object.c:3702:gst_v4l2_object_set_format_full:<v4l2sink0> progressive video
0:00:00.664205180 31377 0x557319fb60 DEBUG v4l2 gstv4l2object.c:3854:gst_v4l2_object_set_format_full:<v4l2sink0:sink> Desired format 0x0, format MPEG stride: 0
0:00:00.664234720 31377 0x557319fb60 DEBUG v4l2 gstv4l2object.c:3910:gst_v4l2_object_set_format_full:<v4l2sink0:sink> Desired format is 0x0, format MPEG, nb planes 1
0:00:00.664253700 31377 0x557319fb60 DEBUG v4l2 gstv4l2object.c:3922:gst_v4l2_object_set_format_full:<v4l2sink0:sink> stride 0
0:00:00.664280900 31377 0x557319fb60 DEBUG v4l2 gstv4l2object.c:3940:gst_v4l2_object_set_format_full:<v4l2sink0:sink> Desired colorspace is 0:0:0:0
0:00:00.664326540 31377 0x557319fb60 DEBUG v4l2 gstv4l2object.c:3963:gst_v4l2_object_set_format_full:<v4l2sink0:sink> Got format of 0x0, format MPEG, nb planes 1, colorspace 0:0:0:0 field: none
0:00:00.664349200 31377 0x557319fb60 DEBUG v4l2 gstv4l2object.c:3977:gst_v4l2_object_set_format_full:<v4l2sink0:sink> stride 65536, sizeimage 65536
0:00:00.664392800 31377 0x557319fb60 DEBUG v4l2 gstv4l2object.c:4056:gst_v4l2_object_set_format_full:<v4l2sink0:sink> Desired framerate: 0/1
0:00:00.664420320 31377 0x557319fb60 DEBUG v4l2 gstv4l2object.c:3490:gst_v4l2_object_save_format:<v4l2sink0:sink> Got sizeimage 65536
0:00:00.664461760 31377 0x557319fb60 DEBUG v4l2 gstv4l2object.c:3236:gst_v4l2_object_setup_pool:<v4l2sink0:sink> initializing the output system
0:00:00.664485920 31377 0x557319fb60 INFO v4l2 gstv4l2object.c:3268:gst_v4l2_object_setup_pool:<v4l2sink0:sink> accessing buffers via mode 4
0:00:00.664510480 31377 0x557319fb60 LOG v4l2 gstv4l2object.c:3277:gst_v4l2_object_setup_pool:<v4l2sink0:sink> initiating buffer pool
0:00:00.664761860 31377 0x557319fb60 DEBUG v4l2bufferpool gstv4l2bufferpool.c:550:gst_v4l2_buffer_pool_set_config:<v4l2sink0:pool0:sink> config GstBufferPoolConfig, caps=(GstCaps)"video/mpegts\,\ systemstream\=\(boolean\)true\,\ packetsize\=\(int\)188", size=(uint)65536, min-buffers=(uint)0, max-buffers=(uint)0, allocator=(GstAllocator)"NULL", params=(GstAllocationParams)NULL;
0:00:00.664808180 31377 0x557319fb60 INFO v4l2bufferpool gstv4l2bufferpool.c:598:gst_v4l2_buffer_pool_set_config:<v4l2sink0:pool0:sink> increasing minimum buffers to 2
0:00:00.664829780 31377 0x557319fb60 INFO v4l2bufferpool gstv4l2bufferpool.c:611:gst_v4l2_buffer_pool_set_config:<v4l2sink0:pool0:sink> reducing maximum buffers to 32
0:00:00.664875620 31377 0x557319fb60 INFO v4l2sink gstv4l2sink.c:525:gst_v4l2sink_set_caps:<v4l2sink0> outputting buffers via mode 4
0:00:00.665061780 31377 0x557319fb60 DEBUG v4l2sink gstv4l2sink.c:505:gst_v4l2sink_set_caps:<v4l2sink0> caps: video/mpegts, systemstream=(boolean)true, packetsize=(int)188, streamheader=(buffer)< 47400031a600ffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffff0000b00d0001c100000001e06485412fea >
0:00:00.665098100 31377 0x557319fb60 DEBUG v4l2 gstv4l2object.c:4690:gst_v4l2_object_stop:<v4l2sink0:sink> stopping
0:00:00.665136140 31377 0x557319fb60 DEBUG v4l2bufferpool gstv4l2bufferpool.c:1111:gst_v4l2_buffer_pool_orphan:<v4l2sink0:pool0:sink> orphaning pool
0:00:00.665280000 31377 0x557319fb60 DEBUG v4l2 gstv4l2object.c:4322:gst_v4l2_object_set_format:<v4l2sink0:sink> Setting format to video/mpegts, systemstream=(boolean)true, packetsize=(int)188, streamheader=(buffer)< 47400031a600ffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffff0000b00d0001c100000001e06485412fea >
0:00:00.665312540 31377 0x557319fb60 DEBUG v4l2 gstv4l2object.c:3702:gst_v4l2_object_set_format_full:<v4l2sink0> progressive video
0:00:00.665343360 31377 0x557319fb60 DEBUG v4l2 gstv4l2object.c:3854:gst_v4l2_object_set_format_full:<v4l2sink0:sink> Desired format 0x0, format MPEG stride: 0
0:00:00.665375640 31377 0x557319fb60 DEBUG v4l2 gstv4l2object.c:3910:gst_v4l2_object_set_format_full:<v4l2sink0:sink> Desired format is 0x0, format MPEG, nb planes 1
0:00:00.665395780 31377 0x557319fb60 DEBUG v4l2 gstv4l2object.c:3922:gst_v4l2_object_set_format_full:<v4l2sink0:sink> stride 0
0:00:00.665419500 31377 0x557319fb60 DEBUG v4l2 gstv4l2object.c:3940:gst_v4l2_object_set_format_full:<v4l2sink0:sink> Desired colorspace is 0:0:0:0
0:00:00.665463520 31377 0x557319fb60 DEBUG v4l2 gstv4l2object.c:3963:gst_v4l2_object_set_format_full:<v4l2sink0:sink> Got format of 0x0, format MPEG, nb planes 1, colorspace 0:0:0:0 field: none
0:00:00.665486700 31377 0x557319fb60 DEBUG v4l2 gstv4l2object.c:3977:gst_v4l2_object_set_format_full:<v4l2sink0:sink> stride 65536, sizeimage 65536
0:00:00.665529880 31377 0x557319fb60 DEBUG v4l2 gstv4l2object.c:4056:gst_v4l2_object_set_format_full:<v4l2sink0:sink> Desired framerate: 0/1
0:00:00.665555140 31377 0x557319fb60 DEBUG v4l2 gstv4l2object.c:3490:gst_v4l2_object_save_format:<v4l2sink0:sink> Got sizeimage 65536
0:00:00.665576380 31377 0x557319fb60 DEBUG v4l2 gstv4l2object.c:3236:gst_v4l2_object_setup_pool:<v4l2sink0:sink> initializing the output system
0:00:00.665596600 31377 0x557319fb60 INFO v4l2 gstv4l2object.c:3268:gst_v4l2_object_setup_pool:<v4l2sink0:sink> accessing buffers via mode 4
0:00:00.665618000 31377 0x557319fb60 LOG v4l2 gstv4l2object.c:3277:gst_v4l2_object_setup_pool:<v4l2sink0:sink> initiating buffer pool
0:00:00.665910300 31377 0x557319fb60 DEBUG v4l2bufferpool gstv4l2bufferpool.c:550:gst_v4l2_buffer_pool_set_config:<v4l2sink0:pool1:sink> config GstBufferPoolConfig, caps=(GstCaps)"video/mpegts\,\ systemstream\=\(boolean\)true\,\ packetsize\=\(int\)188\,\ streamheader\=\(buffer\)\<\ 47400031a600ffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffff0000b00d0001c100000001e06485412fea\ \>", size=(uint)65536, min-buffers=(uint)0, max-buffers=(uint)0, allocator=(GstAllocator)"NULL", params=(GstAllocationParams)NULL;
0:00:00.665949660 31377 0x557319fb60 INFO v4l2bufferpool gstv4l2bufferpool.c:598:gst_v4l2_buffer_pool_set_config:<v4l2sink0:pool1:sink> increasing minimum buffers to 2
0:00:00.665970840 31377 0x557319fb60 INFO v4l2bufferpool gstv4l2bufferpool.c:611:gst_v4l2_buffer_pool_set_config:<v4l2sink0:pool1:sink> reducing maximum buffers to 32
0:00:00.666008700 31377 0x557319fb60 INFO v4l2sink gstv4l2sink.c:525:gst_v4l2sink_set_caps:<v4l2sink0> outputting buffers via mode 4
0:00:00.666111620 31377 0x557319fb60 DEBUG v4l2sink gstv4l2sink.c:592:gst_v4l2sink_show_frame:<v4l2sink0> render buffer: 0x7f9000f7e0
0:00:00.666132260 31377 0x557319fb60 DEBUG v4l2sink gstv4l2sink.c:601:gst_v4l2sink_show_frame:<v4l2sink0> activating pool
0:00:00.666326820 31377 0x557319fb60 DEBUG v4l2bufferpool gstv4l2bufferpool.c:550:gst_v4l2_buffer_pool_set_config:<v4l2sink0:pool1:sink> config GstBufferPoolConfig, caps=(GstCaps)"video/mpegts\,\ systemstream\=\(boolean\)true\,\ packetsize\=\(int\)188\,\ streamheader\=\(buffer\)\<\ 47400031a600ffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffff0000b00d0001c100000001e06485412fea\ \>", size=(uint)65536, min-buffers=(uint)2, max-buffers=(uint)32, allocator=(GstAllocator)"NULL", params=(GstAllocationParams)NULL, options=(string)< GstBufferPoolOptionVideoMeta >;
0:00:00.666393980 31377 0x557319fb60 DEBUG v4l2bufferpool gstv4l2bufferpool.c:820:gst_v4l2_buffer_pool_start:<v4l2sink0:pool1:sink> activating pool
0:00:00.666426820 31377 0x557319fb60 DEBUG v4l2bufferpool gstv4l2bufferpool.c:883:gst_v4l2_buffer_pool_start:<v4l2sink0:pool1:sink> requesting 2 MMAP buffers
0:00:00.666672000 31377 0x557319fb60 DEBUG v4l2allocator gstv4l2allocator.c:706:gst_v4l2_allocator_start:<v4l2sink0:pool1:sink:allocator> allocated 2 mmap buffers out of 2 requested
0:00:00.666706540 31377 0x557319fb60 LOG v4l2allocator gstv4l2allocator.c:303:gst_v4l2_memory_group_new:<v4l2sink0:pool1:sink:allocator> Got mmap buffer
0:00:00.666727380 31377 0x557319fb60 LOG v4l2allocator gstv4l2allocator.c:304:gst_v4l2_memory_group_new:<v4l2sink0:pool1:sink:allocator> index: 0
0:00:00.666746660 31377 0x557319fb60 LOG v4l2allocator gstv4l2allocator.c:305:gst_v4l2_memory_group_new:<v4l2sink0:pool1:sink:allocator> type: 2
0:00:00.666766420 31377 0x557319fb60 LOG v4l2allocator gstv4l2allocator.c:306:gst_v4l2_memory_group_new:<v4l2sink0:pool1:sink:allocator> flags: 00002000
0:00:00.666786520 31377 0x557319fb60 LOG v4l2allocator gstv4l2allocator.c:307:gst_v4l2_memory_group_new:<v4l2sink0:pool1:sink:allocator> field: 0
0:00:00.666805320 31377 0x557319fb60 LOG v4l2allocator gstv4l2allocator.c:308:gst_v4l2_memory_group_new:<v4l2sink0:pool1:sink:allocator> memory: 1
0:00:00.666823960 31377 0x557319fb60 LOG v4l2allocator gstv4l2allocator.c:309:gst_v4l2_memory_group_new:<v4l2sink0:pool1:sink:allocator> planes: 1
0:00:00.666848960 31377 0x557319fb60 LOG v4l2allocator gstv4l2allocator.c:315:gst_v4l2_memory_group_new:<v4l2sink0:pool1:sink:allocator> [0] bytesused: 0, length: 65536, offset: 0
0:00:00.666870600 31377 0x557319fb60 LOG v4l2allocator gstv4l2allocator.c:319:gst_v4l2_memory_group_new:<v4l2sink0:pool1:sink:allocator> [0] MMAP offset: 0
0:00:00.666894380 31377 0x557319fb60 LOG v4l2allocator gstv4l2allocator.c:303:gst_v4l2_memory_group_new:<v4l2sink0:pool1:sink:allocator> Got mmap buffer
0:00:00.666913540 31377 0x557319fb60 LOG v4l2allocator gstv4l2allocator.c:304:gst_v4l2_memory_group_new:<v4l2sink0:pool1:sink:allocator> index: 1
0:00:00.666932280 31377 0x557319fb60 LOG v4l2allocator gstv4l2allocator.c:305:gst_v4l2_memory_group_new:<v4l2sink0:pool1:sink:allocator> type: 2
0:00:00.666951100 31377 0x557319fb60 LOG v4l2allocator gstv4l2allocator.c:306:gst_v4l2_memory_group_new:<v4l2sink0:pool1:sink:allocator> flags: 00002000
0:00:00.666969540 31377 0x557319fb60 LOG v4l2allocator gstv4l2allocator.c:307:gst_v4l2_memory_group_new:<v4l2sink0:pool1:sink:allocator> field: 0
0:00:00.666987940 31377 0x557319fb60 LOG v4l2allocator gstv4l2allocator.c:308:gst_v4l2_memory_group_new:<v4l2sink0:pool1:sink:allocator> memory: 1
0:00:00.667006220 31377 0x557319fb60 LOG v4l2allocator gstv4l2allocator.c:309:gst_v4l2_memory_group_new:<v4l2sink0:pool1:sink:allocator> planes: 1
0:00:00.667030340 31377 0x557319fb60 LOG v4l2allocator gstv4l2allocator.c:315:gst_v4l2_memory_group_new:<v4l2sink0:pool1:sink:allocator> [0] bytesused: 0, length: 65536, offset: 0
0:00:00.667051940 31377 0x557319fb60 LOG v4l2allocator gstv4l2allocator.c:319:gst_v4l2_memory_group_new:<v4l2sink0:pool1:sink:allocator> [0] MMAP offset: 65536
0:00:00.667105100 31377 0x557319fb60 LOG v4l2allocator gstv4l2allocator.c:912:gst_v4l2_allocator_alloc_dmabuf:<v4l2sink0:pool1:sink:allocator> exported DMABUF as fd 89 plane 0
0:00:00.667164140 31377 0x557319fb60 LOG v4l2bufferpool gstv4l2bufferpool.c:1854:gst_v4l2_buffer_pool_release_buffer:<v4l2sink0:pool1:sink> mark buffer 0 not outstanding
0:00:00.667190740 31377 0x557319fb60 DEBUG v4l2bufferpool gstv4l2bufferpool.c:1722:gst_v4l2_buffer_pool_complete_release_buffer:<v4l2sink0:pool1:sink> complete release buffer 0x7f7800b900 (queued = no)
0:00:00.667214280 31377 0x557319fb60 LOG v4l2bufferpool gstv4l2bufferpool.c:1809:gst_v4l2_buffer_pool_complete_release_buffer:<v4l2sink0:pool1:sink> buffer 0 not queued, putting on free list
0:00:00.667253020 31377 0x557319fb60 LOG v4l2allocator gstv4l2allocator.c:912:gst_v4l2_allocator_alloc_dmabuf:<v4l2sink0:pool1:sink:allocator> exported DMABUF as fd 90 plane 0
0:00:00.667285440 31377 0x557319fb60 LOG v4l2bufferpool gstv4l2bufferpool.c:1854:gst_v4l2_buffer_pool_release_buffer:<v4l2sink0:pool1:sink> mark buffer 1 not outstanding
0:00:00.667310180 31377 0x557319fb60 DEBUG v4l2bufferpool gstv4l2bufferpool.c:1722:gst_v4l2_buffer_pool_complete_release_buffer:<v4l2sink0:pool1:sink> complete release buffer 0x7f7800b5a0 (queued = no)
0:00:00.667332280 31377 0x557319fb60 LOG v4l2bufferpool gstv4l2bufferpool.c:1809:gst_v4l2_buffer_pool_complete_release_buffer:<v4l2sink0:pool1:sink> buffer 1 not queued, putting on free list
0:00:00.667351720 31377 0x557319fb60 DEBUG v4l2bufferpool gstv4l2bufferpool.c:1167:gst_v4l2_buffer_pool_flush_stop:<v4l2sink0:pool1:sink> stop flushing
0:00:00.667373920 31377 0x557319fb60 DEBUG v4l2bufferpool gstv4l2bufferpool.c:2104:gst_v4l2_buffer_pool_process:<v4l2sink0:pool1:sink> process buffer 0x7f9000f7e0
0:00:00.667391920 31377 0x557319fb60 LOG v4l2bufferpool gstv4l2bufferpool.c:2287:gst_v4l2_buffer_pool_process:<v4l2sink0:pool1:sink> alloc buffer from our pool
0:00:00.667408440 31377 0x557319fb60 DEBUG v4l2bufferpool gstv4l2bufferpool.c:1625:gst_v4l2_buffer_pool_acquire_buffer:<v4l2sink0:pool1:sink> acquire
0:00:00.667430460 31377 0x557319fb60 LOG v4l2bufferpool gstv4l2bufferpool.c:1697:gst_v4l2_buffer_pool_acquire_buffer:<v4l2sink0:pool1:sink> mark buffer 0 outstanding
0:00:00.667448720 31377 0x557319fb60 LOG v4l2bufferpool gstv4l2bufferpool.c:148:gst_v4l2_buffer_pool_copy_buffer:<v4l2sink0:pool1:sink> copying buffer
0:00:00.667465880 31377 0x557319fb60 DEBUG v4l2bufferpool gstv4l2bufferpool.c:173:gst_v4l2_buffer_pool_copy_buffer:<v4l2sink0:pool1:sink> copy raw bytes
0:00:00.667545360 31377 0x557319fb60 LOG v4l2bufferpool gstv4l2bufferpool.c:1300:gst_v4l2_buffer_pool_qbuf:<v4l2sink0:pool1:sink> queuing buffer 0, previous-state = 1
0:00:00.667581240 31377 0x557319fb60 LOG v4l2allocator gstv4l2allocator.c:1288:gst_v4l2_allocator_qbuf:<v4l2sink0:pool1:sink:allocator> queued buffer 0 (flags 0x2003)
0:00:00.690951480 31377 0x557319fb60 DEBUG v4l2bufferpool gstv4l2bufferpool.c:735:gst_v4l2_buffer_pool_streamon:<v4l2sink0:pool1:sink> Started streaming
0:00:00.690986100 31377 0x557319fb60 LOG v4l2bufferpool gstv4l2bufferpool.c:1854:gst_v4l2_buffer_pool_release_buffer:<v4l2sink0:pool1:sink> mark buffer 0 not outstanding
0:00:00.691011160 31377 0x557319fb60 DEBUG v4l2bufferpool gstv4l2bufferpool.c:1722:gst_v4l2_buffer_pool_complete_release_buffer:<v4l2sink0:pool1:sink> complete release buffer 0x7f7800b900 (queued = yes)
0:00:00.691033600 31377 0x557319fb60 LOG v4l2bufferpool gstv4l2bufferpool.c:1825:gst_v4l2_buffer_pool_complete_release_buffer:<v4l2sink0:pool1:sink> buffer 0 is queued
0:00:00.691053160 31377 0x557319fb60 LOG v4l2bufferpool gstv4l2bufferpool.c:1209:gst_v4l2_buffer_pool_poll:<v4l2sink0:pool1:sink> polling device
0:00:00.691082120 31377 0x557319fb60 LOG v4l2bufferpool gstv4l2bufferpool.c:1440:gst_v4l2_buffer_pool_dqbuf:<v4l2sink0:pool1:sink> nothing to dequeue
0:00:00.693005300 31377 0x7f58019f60 DEBUG v4l2sink gstv4l2sink.c:444:gst_v4l2sink_change_state:<v4l2sink0> 3 -> 4
0:00:01.789425940 31377 0x557319fb60 DEBUG v4l2sink gstv4l2sink.c:592:gst_v4l2sink_show_frame:<v4l2sink0> render buffer: 0x7f9000f7e0
0:00:02.377437500 31377 0x557319fb60 DEBUG v4l2bufferpool gstv4l2bufferpool.c:2104:gst_v4l2_buffer_pool_process:<v4l2sink0:pool1:sink> process buffer 0x7f9000f7e0
0:00:02.377480160 31377 0x557319fb60 LOG v4l2bufferpool gstv4l2bufferpool.c:2287:gst_v4l2_buffer_pool_process:<v4l2sink0:pool1:sink> alloc buffer from our pool
0:00:02.377514740 31377 0x557319fb60 DEBUG v4l2bufferpool gstv4l2bufferpool.c:1625:gst_v4l2_buffer_pool_acquire_buffer:<v4l2sink0:pool1:sink> acquire
0:00:02.377567820 31377 0x557319fb60 LOG v4l2bufferpool gstv4l2bufferpool.c:1697:gst_v4l2_buffer_pool_acquire_buffer:<v4l2sink0:pool1:sink> mark buffer 1 outstanding
0:00:02.377605120 31377 0x557319fb60 LOG v4l2bufferpool gstv4l2bufferpool.c:148:gst_v4l2_buffer_pool_copy_buffer:<v4l2sink0:pool1:sink> copying buffer
0:00:02.377638860 31377 0x557319fb60 DEBUG v4l2bufferpool gstv4l2bufferpool.c:173:gst_v4l2_buffer_pool_copy_buffer:<v4l2sink0:pool1:sink> copy raw bytes
0:00:02.377789080 31377 0x557319fb60 LOG v4l2bufferpool gstv4l2bufferpool.c:1300:gst_v4l2_buffer_pool_qbuf:<v4l2sink0:pool1:sink> queuing buffer 1, previous-state = 1
0:00:02.377878640 31377 0x557319fb60 LOG v4l2allocator gstv4l2allocator.c:1288:gst_v4l2_allocator_qbuf:<v4l2sink0:pool1:sink:allocator> queued buffer 1 (flags 0x2003)
0:00:02.377934400 31377 0x557319fb60 LOG v4l2bufferpool gstv4l2bufferpool.c:1854:gst_v4l2_buffer_pool_release_buffer:<v4l2sink0:pool1:sink> mark buffer 1 not outstanding
0:00:02.377982180 31377 0x557319fb60 DEBUG v4l2bufferpool gstv4l2bufferpool.c:1722:gst_v4l2_buffer_pool_complete_release_buffer:<v4l2sink0:pool1:sink> complete release buffer 0x7f7800b5a0 (queued = yes)
0:00:02.378024800 31377 0x557319fb60 LOG v4l2bufferpool gstv4l2bufferpool.c:1825:gst_v4l2_buffer_pool_complete_release_buffer:<v4l2sink0:pool1:sink> buffer 1 is queued
0:00:02.378062360 31377 0x557319fb60 LOG v4l2bufferpool gstv4l2bufferpool.c:1209:gst_v4l2_buffer_pool_poll:<v4l2sink0:pool1:sink> polling device
0:00:02.378117860 31377 0x557319fb60 LOG v4l2bufferpool gstv4l2bufferpool.c:1449:gst_v4l2_buffer_pool_dqbuf:<v4l2sink0:pool1:sink> dequeueing a buffer
0:00:02.378918200 31377 0x557319fb60 LOG v4l2allocator gstv4l2allocator.c:1335:gst_v4l2_allocator_dqbuf:<v4l2sink0:pool1:sink:allocator> dequeued buffer 0 (flags 0x2001)
0:00:02.379011520 31377 0x557319fb60 LOG v4l2bufferpool gstv4l2bufferpool.c:1486:gst_v4l2_buffer_pool_dqbuf:<v4l2sink0:pool1:sink> dequeued buffer 0x7f7800b900 seq:0 (ix=0), mem 0x7f94016360 used 65536, plane=0, flags 00002001, ts 0:01:53.245462000, pool-queued=1, buffer=0x7f7800b900, previous-state=2
0:00:02.379060780 31377 0x557319fb60 DEBUG v4l2bufferpool gstv4l2bufferpool.c:1722:gst_v4l2_buffer_pool_complete_release_buffer:<v4l2sink0:pool1:sink> complete release buffer 0x7f7800b900 (queued = no)
0:00:02.379107800 31377 0x557319fb60 LOG v4l2bufferpool gstv4l2bufferpool.c:1809:gst_v4l2_buffer_pool_complete_release_buffer:<v4l2sink0:pool1:sink> buffer 0 not queued, putting on free list
0:00:02.379151340 31377 0x557319fb60 LOG v4l2bufferpool gstv4l2bufferpool.c:1209:gst_v4l2_buffer_pool_poll:<v4l2sink0:pool1:sink> polling device
0:00:02.379210000 31377 0x557319fb60 LOG v4l2bufferpool gstv4l2bufferpool.c:1449:gst_v4l2_buffer_pool_dqbuf:<v4l2sink0:pool1:sink> dequeueing a buffer
0:00:02.379266220 31377 0x557319fb60 LOG v4l2allocator gstv4l2allocator.c:1335:gst_v4l2_allocator_dqbuf:<v4l2sink0:pool1:sink:allocator> dequeued buffer 1 (flags 0x2001)
0:00:02.379350860 31377 0x557319fb60 LOG v4l2bufferpool gstv4l2bufferpool.c:1486:gst_v4l2_buffer_pool_dqbuf:<v4l2sink0:pool1:sink> dequeued buffer 0x7f7800b5a0 seq:1 (ix=1), mem 0x7f94016480 used 65536, plane=0, flags 00002001, ts 0:01:53.245469000, pool-queued=0, buffer=0x7f7800b5a0, previous-state=2
0:00:02.379398280 31377 0x557319fb60 DEBUG v4l2bufferpool gstv4l2bufferpool.c:1722:gst_v4l2_buffer_pool_complete_release_buffer:<v4l2sink0:pool1:sink> complete release buffer 0x7f7800b5a0 (queued = no)
0:00:02.379442760 31377 0x557319fb60 LOG v4l2bufferpool gstv4l2bufferpool.c:1809:gst_v4l2_buffer_pool_complete_release_buffer:<v4l2sink0:pool1:sink> buffer 1 not queued, putting on free list
0:00:02.379481160 31377 0x557319fb60 LOG v4l2bufferpool gstv4l2bufferpool.c:1440:gst_v4l2_buffer_pool_dqbuf:<v4l2sink0:pool1:sink> nothing to dequeue