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
11k stars 4.95k forks source link

The V4L2 H264 video decoder can't negotiate output buffers after a video resolution change #3390

Closed eocanha closed 4 months ago

eocanha commented 4 years ago

Bug description and context

I'm using a customized version of Buildroot with a custom defconfig on a Raspberry Pi 3B+ to try play YouTube videos on the WPE WebKit web engine using Media Source Extensions (not functional in the provided configuration, but keep reading).

WebKit uses GStreamer as its multimedia framework in this configuration, Wayland for graphics output and the V4L2 memory-to-memory video codecs instead of the OpenMAX ones. YouTube uses MSE to implement adaptive streaming (change video resolution/quality on the fly) so, at some point, the quality of the H264 video stream changes from 640x360 to 1920x768. GStreamer handles the changes properly by flushing the decoder, deallocating the input/output buffers from its buffer pools, renegotiating the capabilities with the V4L2 decoder and trying to allocate 2 new input buffers (H264 data) and 2 new output buffers (FullHD raw video data). This last allocation fails and the errors stop the pipeline and reach the browser.

At this point I got rid of the browser and could reproduce the issue just by using a gst-launch-1.0 command to play a video-quality-change.mp4 file generated by concatenating the 640x360 H264 header, the first data fragment, the 1920x1080 header, and a data fragment in that new resolution (exactly the same data that YouTube fetches and MSE provides to the pipeline). Note that the file is properly played by gst-play-1.0/gst-launch-1.0 on builds that use the OpenMAX GStreamer elements instead of the V4L2 ones. Also note that on desktop you can only properly play the file in GStreamer if you force "push mode" (sequential access to the file instead of random access):

cat video-quality-change.mp4 | gst-play-1.0 fd://0

As mentioned in https://www.raspberrypi.org/forums/viewtopic.php?t=220640#p1586156 , I tried to debug what's happening on the VideoCore 4 side but couldn't use vcgencmd and vcdbg (let's call them "vc tools") due to the vc4drmfb kernel framebuffer module not exposing the required ioctls that allow the vc tools to talk to videocore. To simplify debugging, I disabled dtoverlay=vc4-kms-v3d. That made the vc tools work again but left me without Wayland nor KMS to display the output. Anyway, at this point I could continue debugging just by using GStreamer's fakesink (basically, no output) and examining the GStreamer/kernel/vctools logs of the behaviour of the codecs. This is the scenario to be found if using the buildroot branch and defconfig provided above.

In this situation, the logs show how GStreamer renegotiates the new resolution with the driver, allocates a new buffer pool but only gets 1 of the 2 output buffers that were requested (only relevant lines pasted):

0:00:35.017824310   934   0x794980 DEBUG                   v4l2 gstv4l2object.c:3871:gst_v4l2_object_set_format:<v4l2h264dec0:src> Setting format to video/x-raw, format=(string)I420, width=(int)1920, height=(int)1080, framerate=(fraction)0/1, interlace-mode=(string)progressive, colorimetry=(string)bt601, pixel-aspect-ratio=(fraction)1/1
...
0:00:35.041597227   934   0x794980 DEBUG           videodecoder gstvideodecoder.c:3765:gst_video_decoder_negotiate_pool:<v4l2h264dec0> unref pool <videobufferpool0>
0:00:35.041818112   934   0x794980 DEBUG           videodecoder gstvideodecoder.c:3771:gst_video_decoder_negotiate_pool:<v4l2h264dec0> activate pool <videobufferpool1>
0:00:35.042229831   934   0x794980 DEBUG         v4l2bufferpool gstv4l2bufferpool.c:743:gst_v4l2_buffer_pool_start:<v4l2h264dec0:pool:src> activating pool
0:00:35.042408372   934   0x794980 DEBUG         v4l2bufferpool gstv4l2bufferpool.c:790:gst_v4l2_buffer_pool_start:<v4l2h264dec0:pool:src> requesting 2 MMAP buffers
0:00:35.184395612   934   0x794980 DEBUG          v4l2allocator gstv4l2allocator.c:707:gst_v4l2_allocator_start:<v4l2h264dec0:pool:src:allocator> allocated 1 mmap buffers out of 2 requested
0:00:35.197222383   934   0x794980 LOG            v4l2allocator gstv4l2allocator.c:303:gst_v4l2_memory_group_new:<v4l2h264dec0:pool:src:allocator> Got mmap buffer
0:00:35.197313424   934   0x794980 LOG            v4l2allocator gstv4l2allocator.c:304:gst_v4l2_memory_group_new:<v4l2h264dec0:pool:src:allocator>   index:     0
0:00:35.197364883   934   0x794980 LOG            v4l2allocator gstv4l2allocator.c:305:gst_v4l2_memory_group_new:<v4l2h264dec0:pool:src:allocator>   type:      9
0:00:35.197415924   934   0x794980 LOG            v4l2allocator gstv4l2allocator.c:306:gst_v4l2_memory_group_new:<v4l2h264dec0:pool:src:allocator>   flags:     00004000
0:00:35.197462904   934   0x794980 LOG            v4l2allocator gstv4l2allocator.c:307:gst_v4l2_memory_group_new:<v4l2h264dec0:pool:src:allocator>   field:     0
0:00:35.197569466   934   0x794980 LOG            v4l2allocator gstv4l2allocator.c:308:gst_v4l2_memory_group_new:<v4l2h264dec0:pool:src:allocator>   memory:    1
0:00:35.197617435   934   0x794980 LOG            v4l2allocator gstv4l2allocator.c:309:gst_v4l2_memory_group_new:<v4l2h264dec0:pool:src:allocator>   planes:    1
0:00:35.197827591   934   0x794980 LOG            v4l2allocator gstv4l2allocator.c:318:gst_v4l2_memory_group_new:<v4l2h264dec0:pool:src:allocator>   [0] bytesused: 0, length: 3133440, offset: 0
0:00:35.197923320   934   0x794980 LOG            v4l2allocator gstv4l2allocator.c:320:gst_v4l2_memory_group_new:<v4l2h264dec0:pool:src:allocator>   [0] MMAP offset:  1073741824
0:00:35.197991810   934   0x794980 ERROR         v4l2bufferpool gstv4l2bufferpool.c:908:gst_v4l2_buffer_pool_start:<v4l2h264dec0:pool:src> we received 1 buffer from device '/dev/video10', we want at least 2
0:00:35.198192435   934   0x794980 WARN            v4l2videodec gstv4l2videodec.c:759:gst_v4l2_video_dec_handle_frame:<v4l2h264dec0> error: Failed to allocate required memory.
0:00:35.198280560   934   0x794980 WARN            v4l2videodec gstv4l2videodec.c:759:gst_v4l2_video_dec_handle_frame:<v4l2h264dec0> error: Buffer pool activation failed

The kernel can only allocate one of the two requested buffers. Cma_alloc (whatever that is) fails for the second one:

[ 8893.477067] bcm2835-codec bcm2835-codec: Setting format for type 9, wxh: 1920x1088, fmt: YU12, size 3133440
[ 8893.477169] bcm2835-codec bcm2835-codec: Calulated bpl as 1920, size 3133440
[ 8893.477190] bcm2835_mmal_vchiq: setting port info port f756305c
[ 8893.477230] bcm2835_mmal_vchiq: port handle:0x2 enabled:0
[ 8893.477240] bcm2835_mmal_vchiq: buffer minimum num:1 size:3133440 align:0
[ 8893.477248] bcm2835_mmal_vchiq: buffer recommended num:1 size:0 align:0
[ 8893.477257] bcm2835_mmal_vchiq: buffer current values num:3 size:3133440 align:0
[ 8893.477266] bcm2835_mmal_vchiq: elementary stream: type:3 encoding:0x30323449 variant:0x0
[ 8893.477337] bcm2835_mmal_vchiq:                   bitrate:0 flags:0x0
[ 8893.477347] bcm2835_mmal_vchiq: es video format: width:1920 height:1088 colourspace:0x39303759
[ 8893.477356] bcm2835_mmal_vchiq:                : crop xywh 0,0,1920,1080
[ 8893.477365] bcm2835_mmal_vchiq:                : framerate 30/1  aspect 0/0
[ 8893.477752] bcm2835_mmal_vchiq: port_info_set:result:0 component:0x40 port:2
[ 8893.477857] bcm2835_mmal_vchiq: received port info
[ 8893.477865] bcm2835_mmal_vchiq: port handle:0x2 enabled:0
[ 8893.477874] bcm2835_mmal_vchiq: buffer minimum num:1 size:3133440 align:0
[ 8893.477882] bcm2835_mmal_vchiq: buffer recommended num:1 size:0 align:0
[ 8893.477890] bcm2835_mmal_vchiq: buffer current values num:3 size:3133440 align:0
[ 8893.477899] bcm2835_mmal_vchiq: elementary stream: type:3 encoding:0x30323449 variant:0x0
[ 8893.477906] bcm2835_mmal_vchiq:                   bitrate:0 flags:0x0
[ 8893.477915] bcm2835_mmal_vchiq: es video format: width:1920 height:1088 colourspace:0x39303759
[ 8893.477923] bcm2835_mmal_vchiq:                : crop xywh 0,0,1920,1080
[ 8893.477932] bcm2835_mmal_vchiq:                : framerate 1638400/65536  aspect 0/0
[ 8893.477941] bcm2835_mmal_vchiq: port_info_get:result:0 component:0x40 port:2
[ 8893.477953] bcm2835-codec bcm2835-codec: Set format for type 9, wxh: 1920x1088, fmt: 32315559, size 3133440
[ 8893.479665] videobuf2_common: vb2_verify_memory_type: USERPTR for current setup unsupported
[ 8893.500943] videobuf2_common: vb2_core_reqbufs: call_qop(a98c883c, queue_setup)

[ 8893.513401] videobuf2_common: __vb2_buf_mem_alloc: call_memop(a98c883c, 0, alloc)
^^^ Allocation of the first buffer goes fine

[ 8893.530737] videobuf2_common: __setup_offsets: buffer 0, plane 0 offset 0x00000000
[ 8893.543292] videobuf2_common: __vb2_queue_alloc: call_vb_qop(a98c883c, 0, buf_init)
[ 8893.555831] bcm2835-codec bcm2835-codec: bcm2835_codec_buf_init: ctx:d0a1935a, vb e1d0d19e
[ 8893.555842] videobuf2_common: vb2_plane_vaddr: call_memop(a98c883c, 0, vaddr)

[ 8893.567863] videobuf2_common: __vb2_buf_mem_alloc: call_memop(a98c883c, 1, alloc)
[ 8893.580246] cma: cma_alloc: alloc failed, req-size: 765 pages, ret: -12
[ 8893.591781] bcm2835-codec bcm2835-codec: dma_alloc_coherent of size 3133440 failed
^^^ Allocation of the second buffer fails

[ 8893.604269] videobuf2_common: __vb2_queue_alloc: failed allocating memory for buffer 1
[ 8893.617153] videobuf2_common: __vb2_queue_alloc: allocated 1 buffers, 1 plane(s) each

At this point I hoped that the vcdbg logs (after "vcgencmd set_logging level=2147483647") would be of some help to explain why the allocation failed, but they aren't:

307966.701: IN: setting flush state to FLUSH_WARN
307966.716: IN: setting flush state to FLUSH_ACTIVE
307966.756: IN: discarding input 3f50d30c (0 bytes of 0, ud=00000000) flags=07000060
307966.768: IN: terminating flush state at sync request
307966.795: H264#0: MSG: SyncEnd[size=32 AU=00000080]
307966.841: sysman_set_user_request( 0x3f26ded4, 5, 0 1 )
307966.865: sysman_deregister_user ( 0x3f26ded4 )
307966.882: dfree: pool 0xbf3188d8, ptr 0xbf522250
307966.909: h264pwr_close() handle=5
307966.925: dfree: pool 0xbf3188d8, ptr 0xbf5221f0
307966.943: cabac_close handle=3f522100
307966.962: h264pwr_disable(00000010,00000000)
307966.983: h264pwr_disable newa newb (00000001,00000001)
307966.997: h264pwr_close() handle=4
307967.013: dfree: pool 0xbf3188d8, ptr 0xbf5220f0
307967.030: h264pwr_close() handle=3
307967.046: dfree: pool 0xbf3188d8, ptr 0xbf522090
307967.064: h264pwr_close() handle=2
307967.083: dfree: pool 0xbf3188d8, ptr 0xbf522050
307967.112: sysman_set_user_request( 0x3f26deb8, 10, 0 1 )
307967.147: clockman_setup_clock( 28, 0, 0 )
307967.182: sysman_deregister_user ( 0x3f26deb8 )
307967.192: h264pwr_close() handle=1
307967.223: dfree: pool 0xbf3188d8, ptr 0xbf50d210
307967.259: dmalloc: size 88 pool 0xbf3188d8 ptr 0xbf50d210
307967.285: sysman_register_user ( 0x3f26deb8 )
307967.307: sysman_set_user_request( 0x3f26deb8, 10, 1 1 )
307967.343: clockman_setup_clock( 28, 19200000, 0 )
307967.378: clockman_setup_clock( 28, 0, 0 )
307967.409: clockman_setup_clock( 28, 250000000, 0 )
307967.432: h264pwr_open()
307967.449: h264pwr_enable(08000040,00000000)
307967.466: h264pwr_enable newa newb (08000041,00000001)
307967.486: h264pwr_disable(08000040,00000000)
307967.507: h264pwr_disable newa newb (00000001,00000001)
307967.526: dfree: pool 0xbf3188d8, ptr 0xbf50d210
307967.554: sysman_set_user_request( 0x3f26deb8, 10, 0 1 )
307967.584: clockman_setup_clock( 28, 0, 0 )
307967.611: sysman_deregister_user ( 0x3f26deb8 )
307967.623: h264pwr_close() handle=1
307967.661: dfree: pool 0xbf3188d8, ptr 0xbf508790
307968.733: dfree: pool 0xbf3188d8, ptr 0xbf5078d0
307968.752: dfree: pool 0xbf3188d8, ptr 0xbf507830
307968.772: dfree: pool 0xbf3188d8, ptr 0xbf507870
307979.625: dfree: pool 0xbf3188d8, ptr 0xbf523270
307979.679: dfree: pool 0xbf3188d8, ptr 0xbf508730
308018.321: HDMI:CEC interrupt Tx, good:1, len:1, eom:1
308018.409: HDMI:CEC Tx len (1)  10 83 00 00 00 00 00 00 00 00 00 00 00 00 00 00
308024.857: HDMI:CEC sent local reply <Give Physical Address> (0x83) to address 0 - success
308024.877: HDMI:CEC setting 1 timer for device 0 to reply phy addr
308288.605: dfree: pool 0xbf3188d8, ptr 0xbf508050
308288.626: dfree: pool 0xbf3188d8, ptr 0xbf507fb0
308288.646: dfree: pool 0xbf3188d8, ptr 0xbf507ff0
308312.802: dfree: pool 0xbf3188d8, ptr 0xbf507e90
308312.829: dfree: pool 0xbf3188d8, ptr 0xbf508610
308349.211: dfree: pool 0xbf3188d8, ptr 0xbf50d1b0
308349.255: dfree: pool 0xbf3188d8, ptr 0xbf50d150
308643.264: video_decode:8:RIL:GetParameter(3f5000a4)
308643.280: video_decode:8:RIL:GetParameter(3f5000a4)
308643.300: video_decode:8:RIL:SetParameter(7f0000f4)
308643.318: video_decode:8:RIL:GetParameter(3f5000a4)
308643.342: video_decode:8:RIL:SetParameter(2000001)
308643.359: video_decode:8:RIL:PortDef, port 130
308643.368: video_decode:8:RIL: set input format
308643.384: video_decode:8:RIL:SetParameter(7f00004d)
308643.400: video_decode:8:RIL:SetParameter(7f0000bb)
308643.418: video_decode:8:RIL:SetParameter(6f600003)
308643.435: video_decode:8:RIL:GetParameter(3f5000a4)
308643.458: video_decode:8:RIL:GetParameter(3f5000a4)
308643.474: video_decode:8:RIL:GetParameter(3f5000a4)
308643.495: video_decode:8:RIL:GetParameter(3f5000a4)
308643.513: video_decode:8:RIL:GetParameter(3f5000a4)
308643.531: video_decode:8:RIL:GetParameter(3f5000a4)
308643.968: video_decode:8:RIL:GetParameter(3f5000a4)
308643.987: video_decode:8:RIL:GetParameter(3f5000a4)
308644.002: video_decode:8:RIL:SetParameter(7f0000f4)
308644.023: video_decode:8:RIL:GetParameter(3f5000a4)
308644.038: video_decode:8:RIL:SetParameter(2000001)
308644.054: video_decode:8:RIL:PortDef, port 131
308644.071: video_decode:8:RIL: set output format 20
308644.092: video_decode:8:RIL:SetParameter(7f00004d)
308644.110: video_decode:8:RIL:SetParameter(7f0000bb)
308644.129: video_decode:8:RIL:GetParameter(3f5000a4)
308644.148: video_decode:8:RIL:GetParameter(3f5000a4)
308644.167: video_decode:8:RIL:GetParameter(3f5000a4)
308969.526: dmalloc: size 56 pool 0xbf3188d8 ptr 0xbf507830
308969.556: dmalloc: size 88 pool 0xbf3188d8 ptr 0xbf507870
308969.587: dmalloc: size 1464 pool 0xbf3188d8 ptr 0xbf5078d0
308969.639: dmalloc: size 280 pool 0xbf3188d8 ptr 0xbf507e90
308987.041: video_decode:8:RIL:GetParameter(3f5000a4)
308987.062: video_decode:8:RIL:GetParameter(3f5000a4)
308987.080: video_decode:8:RIL:SetParameter(7f0000f4)
308987.101: video_decode:8:RIL:GetParameter(3f5000a4)
308987.119: video_decode:8:RIL:SetParameter(2000001)
308987.135: video_decode:8:RIL:PortDef, port 131
308987.151: video_decode:8:RIL: set output format 20
308987.172: video_decode:8:RIL:SetParameter(7f00004d)
308987.190: video_decode:8:RIL:SetParameter(7f0000bb)
308987.206: video_decode:8:RIL:GetParameter(3f5000a4)
308987.228: video_decode:8:RIL:GetParameter(3f5000a4)
308987.244: video_decode:8:RIL:GetParameter(3f5000a4)
309024.651: HDMI:CEC timer expired to send <Give Physical Address> to 0 again
309024.689: HDMI:CEC queued local Tx reply <Give Physical Address> (0x83) len 1 to device 0
309024.801: HDMI:CEC write 1->0 (len 1)  83 00 00 00 00 00 00 00 00 00 00 00 00 00 00
309078.327: HDMI:CEC interrupt Tx, good:1, len:1, eom:1
309078.414: HDMI:CEC Tx len (1)  10 83 00 00 00 00 00 00 00 00 00 00 00 00 00 00
309084.844: HDMI:CEC sent local reply <Give Physical Address> (0x83) to address 0 - success
309084.866: HDMI:CEC setting 1 timer for device 0 to reply phy addr
309199.393: dfree: pool 0xbf3188d8, ptr 0xbf507e90
309199.422: dfree: pool 0xbf3188d8, ptr 0xbf5078d0
309199.442: dfree: pool 0xbf3188d8, ptr 0xbf507830
309199.463: dfree: pool 0xbf3188d8, ptr 0xbf507870
309691.589: dfree: pool 0xbf3188d8, ptr 0xbf505950
309691.610: dfree: pool 0xbf3188d8, ptr 0xbf5062f0
309691.638: dmalloc: size 56 pool 0xbf3188d8 ptr 0xbf505950
309691.682: dfree: pool 0xbf3188d8, ptr 0xbf4fe750
309691.705: dfree: pool 0xbf3188d8, ptr 0xbf505950
309691.731: dfree: pool 0xbf3188d8, ptr 0xbf4fe710
309691.757: dfree: pool 0xbf3188d8, ptr 0xbf504870
309691.777: dfree: pool 0xbf3188d8, ptr 0xbf503910
309691.799: dfree: pool 0xbf3188d8, ptr 0xbf5038d0
309691.823: dfree: pool 0xbf3188d8, ptr 0xbf5058b0
309691.845: dfree: pool 0xbf3188d8, ptr 0xbf504950
309691.867: dfree: pool 0xbf3188d8, ptr 0xbf504910
309691.891: dfree: pool 0xbf3188d8, ptr 0xbf5062b0
309691.913: dfree: pool 0xbf3188d8, ptr 0xbf505bb0
309691.935: dfree: pool 0xbf3188d8, ptr 0xbf505b10
309691.958: dfree: pool 0xbf3188d8, ptr 0xbf5059d0
309691.979: dfree: pool 0xbf3188d8, ptr 0xbf505990
309692.003: dfree: pool 0xbf3188d8, ptr 0xbf506b70
309692.027: dfree: pool 0xbf3188d8, ptr 0xbf506e90
309692.048: dfree: pool 0xbf3188d8, ptr 0xbf5071b0
309692.069: dfree: pool 0xbf3188d8, ptr 0xbf5074d0
309692.090: dfree: pool 0xbf3188d8, ptr 0xbf5063d0
309692.111: dfree: pool 0xbf3188d8, ptr 0xbf506330
309692.132: dfree: pool 0xbf3188d8, ptr 0xbf506370
309692.155: dfree: pool 0xbf3188d8, ptr 0xbf4fe670
309692.175: dfree: pool 0xbf3188d8, ptr 0xbf4fe530
309692.197: dfree: pool 0xbf3188d8, ptr 0xbf5077f0
309692.217: dfree: pool 0xbf3188d8, ptr 0xbf4fe2f0

Steps to reproduce

1A. Short way: Format an sdcard with an vfat (boot) partition and an ext4 (root) partition and uncompress the boot.tar.gz and root.tar.gz archives. 1B. Long way: Clone the https://github.com/eocanha/buildroot repository and check out the upstream-v4l-codecs-newkernel branch. From the buildroot directory, copy configs/raspberrypi3_wpe_wayland_v4l2_debug_experimental_defconfig as .config. make menuconfig, save it, make. Copy output/images/*.dtb, output/images/zImage, output/images/rpi-firmware/* to the boot partition of the sdcard. Uncompress output/images/rootfs.tar in the root partition of the sdcard. Copy output/build/rpi-firmware-0c01dbefba45a08c47f8538d5a071a0fba6b7e83/hardfp to root/ in the root partition of the sdcard. Also copy the root/script.sh launcher script and the video-quality-change.mp4 video from the root.tar.gz archive of the 1A step to root/ in the sdcard.

  1. Boot and log into the Raspberry Pi (root/root).
  2. Launch the helper script.sh, which will enable and collect some logs, define some useful environment variables and play the video using gst-launch-1.0.
  3. Check that there's a buffer pool negotiation error in the generated logs (eg: grep 'ERROR').

Expected behaviour

There should be no errors in the logs, which should show lines logging produced frames after the quality change. No images will be displayed in any case with this setup (fakesink), so don't expect them.

Actual behaviour

The buffer pool negotiation errors explained in the description of this bug are shown in the logs.

System

6by9 commented 4 years ago

Thank you for a fairly comprehensive bug report.

It sounds like you're just running out of CMA heap, in which case the VideoCore side logs won't help much. If neither vc4-fkms-v3d nor vc4-kms-v3d are loaded, then the default CMA heap is only around 16MB in size. You won't fit many 1080p YU12 frames in that after the other allocations. With either of those overlays it normally defaults to 256MB, which should be plenty. If you grep the normal dmesg output, the size of the CMA heap is normally listed within the first few lines during boot.

Please note that during format renegotiation the buffers are not immediately released. They are retained until the VideoCore side has confirmed that it really has finished with them. This shouldn't take any significant time, but may leave a window where both sets of buffers are allocated.

I'll have a look when I'm back in the office next week.

6by9 commented 4 years ago

I'm not convinced that file is valid.

Taking the first 200 frames of two H264 elementary streams at different resolutions (Big Buck Bunny at 720p and 1080p) and concatenating them into a combined elementary stream produces an output that omxplayer likes.

pi@raspberrypi:~/ssd $ cat short_bbb.h264 | gst-play-1.0 fd://0
Interactive keyboard handling in terminal not available.
Now playing fd://0
ERROR Device '/dev/video10' has no supported format for fd://0
ERROR debug information: gstv4l2object.c(3764): gst_v4l2_object_set_format_full (): /GstPlayBin:playbin/GstURIDecodeBin:uridecodebin0/GstDecodeBin:decodebin0/v4l2h264dec:v4l2h264dec0:
Call to S_FMT failed for H264 @ 1920x1080: Invalid argument
Reached end of play list.

I don't see the CMA issues you do. From the kernel logs I see

[ 1889.804776] bcm2835-codec bcm2835-codec: op_buffer_cb: length 0, flags 1, idx 5
[ 1889.804783] bcm2835-codec bcm2835-codec: op_buffer_cb: Empty buffer - flags 0001
[ 1889.804785] bcm2835-codec bcm2835-codec: Sending EOS event
[ 1889.804795] bcm2835-codec bcm2835-codec: op_buffer_cb: done 201 output buffers
[ 1889.805927] bcm2835-codec bcm2835-codec: bcm2835_codec_buf_prepare: type: 9 ptr e8d4a125
[ 1889.805937] bcm2835-codec bcm2835-codec: bcm2835_codec_buf_queue: type: 9 ptr e8d4a125 vbuf->flags 0, seq 0, bytesused 1382400
[ 1889.805948] bcm2835-codec bcm2835-codec: device_run: off we go
[ 1889.805969] bcm2835-codec bcm2835-codec: device_run: Submitted src 023bbc5e, dst e8d4a125
[ 1889.806519] bcm2835-codec bcm2835-codec: bcm2835_codec_stop_streaming: type: 10 - return buffers
[ 1889.808747] bcm2835-codec bcm2835-codec: bcm2835_codec_stop_streaming: done
[ 1889.809226] bcm2835-codec bcm2835-codec: bcm2835_codec_buffer_cleanup: ctx:2538f4ab, vb cb8ebd79
[ 1889.809232] bcm2835-codec bcm2835-codec: bcm2835_codec_buffer_cleanup: ctx:2538f4ab, vb 7360890b
[ 1889.810889] bcm2835-codec bcm2835-codec: bcm2835_codec_buf_prepare: type: 9 ptr 53d72dbb
[ 1889.810929] bcm2835-codec bcm2835-codec: bcm2835_codec_buf_queue: type: 9 ptr 53d72dbb vbuf->flags 0, seq 0, bytesused 1382400
[ 1889.826417] bcm2835-codec bcm2835-codec: bcm2835_codec_buf_prepare: type: 9 ptr 62b31fb1
[ 1889.826433] bcm2835-codec bcm2835-codec: bcm2835_codec_buf_queue: type: 9 ptr 62b31fb1 vbuf->flags 0, seq 0, bytesused 1382400
[ 1889.843041] bcm2835-codec bcm2835-codec: bcm2835_codec_buf_prepare: type: 9 ptr f5b171dc
[ 1889.843051] bcm2835-codec bcm2835-codec: bcm2835_codec_buf_queue: type: 9 ptr f5b171dc vbuf->flags 0, seq 0, bytesused 1382400
[ 1889.859899] bcm2835-codec bcm2835-codec: Setting format for type 10, wxh: 1920x1080, fmt: H264, size 786432
[ 1889.859906] bcm2835-codec bcm2835-codec: Calulated bpl as 0, size 786432
[ 1889.860105] bcm2835-codec bcm2835-codec: Set format for type 10, wxh: 1920x1080, fmt: 34363248, size 786432
<<<<<<
[ 1889.861831] bcm2835-codec bcm2835-codec: vidioc_s_fmt: Failed vchiq_mmal_port_set_format on output port, ret -3 
<<<<<<
[ 1889.863179] bcm2835-codec bcm2835-codec: bcm2835_codec_buf_prepare: type: 9 ptr bbfc748f
[ 1889.863186] bcm2835-codec bcm2835-codec: bcm2835_codec_buf_prepare data will not fit into plane (1382400 < 3133440)
[ 1889.864107] bcm2835-codec bcm2835-codec: bcm2835_codec_stop_streaming: type: 9 - return buffers
[ 1889.864117] bcm2835-codec bcm2835-codec: bcm2835_codec_stop_streaming: return buffer 53d72dbb
[ 1889.864126] bcm2835-codec bcm2835-codec: bcm2835_codec_stop_streaming: return buffer 62b31fb1
[ 1889.864134] bcm2835-codec bcm2835-codec: bcm2835_codec_stop_streaming: return buffer f5b171dc
[ 1889.864250] bcm2835-codec bcm2835-codec: op_buffer_cb: status:0, buf:1a6eb50f, length:0, flags 0, pts -9223372036854775808
[ 1889.864257] bcm2835-codec bcm2835-codec: op_buffer_cb: length 0, flags 0, idx 6
[ 1889.864263] bcm2835-codec bcm2835-codec: op_buffer_cb: Empty buffer - flags 0000
[ 1889.864274] bcm2835-codec bcm2835-codec: op_buffer_cb: status:0, buf:08963833, length:0, flags 0, pts -9223372036854775808
[ 1889.864280] bcm2835-codec bcm2835-codec: op_buffer_cb: length 0, flags 0, idx 5
[ 1889.864285] bcm2835-codec bcm2835-codec: op_buffer_cb: Empty buffer - flags 0000
[ 1889.864370] bcm2835-codec bcm2835-codec: bcm2835_codec_stop_streaming: Waiting for buffers to be returned - 3 outstanding
[ 1889.864377] bcm2835-codec bcm2835-codec: bcm2835_codec_stop_streaming: Waiting for buffers to be returned - 3 outstanding
[ 1889.864383] bcm2835-codec bcm2835-codec: bcm2835_codec_stop_streaming: Waiting for buffers to be returned - 3 outstanding
[ 1890.897137] bcm2835-codec bcm2835-codec: bcm2835_codec_stop_streaming: Timeout waiting for buffers to be returned - 3 outstanding
[ 1890.897413] bcm2835-codec bcm2835-codec: bcm2835_codec_stop_streaming: done
[ 1890.897427] ------------[ cut here ]------------
[ 1890.897484] WARNING: CPU: 3 PID: 5554 at /home/dave/Pi/linux2711/drivers/media/common/videobuf2/videobuf2-core.c:1882 __vb2_queue_cancel+0x210/0x288 [videobuf2_common]
[ 1890.897496] Modules linked in: rfcomm bnep hci_uart btbcm serdev bluetooth ecdh_generic ecc libaes 8021q garp stp llc binfmt_misc imx477 sg evdev vc4 brcmfmac v3d gpu_sched brcmutil drm_kms_helper sha256_generic libsha256 drm raspberrypi_hwmon cfg80211 hwmon drm_panel_orientation_quirks snd_soc_core snd_compress snd_pcm_dmaengine syscopyarea sysfillrect sysimgblt snd_bcm2835(C) fb_sys_fops rfkill snd_pcm snd_timer bcm2835_unicam v4l2_dv_timings v4l2_fwnode snd bcm2835_codec(C) v4l2_mem2mem bcm2835_v4l2(C) bcm2835_isp(C) i2c_bcm2835 bcm2835_mmal_vchiq(C) videobuf2_vmalloc videobuf2_dma_contig videobuf2_memops videobuf2_v4l2 videobuf2_common videodev mc vc_sm_cma(C) rpivid_mem uio_pdrv_genirq uio fixed i2c_dev ip_tables x_tables ipv6 nf_defrag_ipv6
[ 1890.897786] CPU: 3 PID: 5554 Comm: gst-play-1.0 Tainted: G        WC        5.4.13-v7l+ #24
[ 1890.897794] Hardware name: BCM2711
[ 1890.897802] Backtrace: 
[ 1890.897832] [<c020d51c>] (dump_backtrace) from [<c020d81c>] (show_stack+0x20/0x24)
[ 1890.897846]  r6:ef928000 r5:00000000 r4:c129abf8 r3:bd01255d
[ 1890.897864] [<c020d7fc>] (show_stack) from [<c0a21c90>] (dump_stack+0xe0/0x124)
[ 1890.897882] [<c0a21bb0>] (dump_stack) from [<c0221dfc>] (__warn+0xec/0x104)
[ 1890.897896]  r8:0000075a r7:00000009 r6:bf1de7c4 r5:00000000 r4:00000000 r3:bd01255d
[ 1890.897911] [<c0221d10>] (__warn) from [<c0221ed0>] (warn_slowpath_fmt+0xbc/0xc4)
[ 1890.897924]  r9:bf1de7c4 r8:0000075a r7:bf1d91a4 r6:00000009 r5:00000000 r4:ef928000
[ 1890.897959] [<c0221e18>] (warn_slowpath_fmt) from [<bf1d91a4>] (__vb2_queue_cancel+0x210/0x288 [videobuf2_common])
[ 1890.897973]  r9:d7014808 r8:40045613 r7:bf0ecee8 r6:d7014808 r5:00000009 r4:d7014808
[ 1890.898020] [<bf1d8f94>] (__vb2_queue_cancel [videobuf2_common]) from [<bf1dab14>] (vb2_core_streamoff+0x44/0xb4 [videobuf2_common])
[ 1890.898033]  r10:d73903d8 r9:00000020 r8:40045613 r7:bf0ecee8 r6:d7014808 r5:00000009
[ 1890.898042]  r4:d7014808 r3:00000009
[ 1890.898085] [<bf1daad0>] (vb2_core_streamoff [videobuf2_common]) from [<bf1f8064>] (vb2_streamoff+0x40/0x60 [videobuf2_v4l2])
[ 1890.898094]  r4:d7014800 r3:00000000
[ 1890.898130] [<bf1f8024>] (vb2_streamoff [videobuf2_v4l2]) from [<bf187a98>] (v4l2_m2m_streamoff+0x3c/0xf4 [v4l2_mem2mem])
[ 1890.898164] [<bf187a5c>] (v4l2_m2m_streamoff [v4l2_mem2mem]) from [<bf187b70>] (v4l2_m2m_ioctl_streamoff+0x20/0x24 [v4l2_mem2mem])
[ 1890.898179]  r10:d73903d8 r9:00000020 r8:40045613 r7:bf0ecee8 r6:ef928000 r5:00000000
[ 1890.898188]  r4:d73900a0 r3:d67b6000
[ 1890.898291] [<bf187b50>] (v4l2_m2m_ioctl_streamoff [v4l2_mem2mem]) from [<bf0ecf10>] (v4l_streamoff+0x28/0x2c [videodev])
[ 1890.898454] [<bf0ecee8>] (v4l_streamoff [videodev]) from [<bf0f1c00>] (__video_do_ioctl+0x244/0x474 [videodev])
[ 1890.898609] [<bf0f19bc>] (__video_do_ioctl [videodev]) from [<bf0f3cb0>] (video_usercopy+0x224/0x610 [videodev])
[ 1890.898623]  r10:bf0f19bc r9:40045613 r8:00000000 r7:ef929e04 r6:00000004 r5:00000000
[ 1890.898631]  r4:ef928000
[ 1890.898782] [<bf0f3a8c>] (video_usercopy [videodev]) from [<bf0f40bc>] (video_ioctl2+0x20/0x24 [videodev])
[ 1890.898796]  r10:00000036 r9:ef928000 r8:00000017 r7:d6f40c00 r6:d731b378 r5:a5601f90
[ 1890.898804]  r4:ef928000
[ 1890.898953] [<bf0f409c>] (video_ioctl2 [videodev]) from [<bf0eb144>] (v4l2_ioctl+0x4c/0x60 [videodev])
[ 1890.899039] [<bf0eb0f8>] (v4l2_ioctl [videodev]) from [<c040f130>] (do_vfs_ioctl+0xc0/0x808)
[ 1890.899055] [<c040f070>] (do_vfs_ioctl) from [<c040f8bc>] (ksys_ioctl+0x44/0x6c)
[ 1890.899068]  r10:00000036 r9:ef928000 r8:00000017 r7:40045613 r6:d6f40c00 r5:a5601f90
[ 1890.899075]  r4:d6f40c01
[ 1890.899089] [<c040f878>] (ksys_ioctl) from [<c040f8fc>] (sys_ioctl+0x18/0x1c)
[ 1890.899100]  r8:c02011c4 r7:00000036 r6:a71fe7d0 r5:a71fe000 r4:a56102c0 r3:b690f510
[ 1890.899118] [<c040f8e4>] (sys_ioctl) from [<c0201000>] (ret_fast_syscall+0x0/0x28)
[ 1890.899127] Exception stack(0xef929fa8 to 0xef929ff0)
[ 1890.899139] 9fa0:                   a56102c0 a71fe000 00000017 40045613 a5601f90 b690f510
[ 1890.899151] 9fc0: a56102c0 a71fe000 a71fe7d0 00000036 adcfe6c8 b6cd0000 b6cd192c b6bddf18
[ 1890.899161] 9fe0: b6ba5c60 bed7482c a71c6954 b690f51c
[ 1890.899173] ---[ end trace 68adbf8b236093c6 ]---
[ 1890.899189] videobuf2_common: driver bug: stop_streaming operation is leaving buf 7ea6b65a in active state
[ 1890.899270] bcm2835-codec bcm2835-codec: Setting format for type 10, wxh: 1920x1080, fmt: H264, size 786432
[ 1890.899286] bcm2835-codec bcm2835-codec: Calulated bpl as 0, size 786432
[ 1890.899954] bcm2835-codec bcm2835-codec: Set format for type 10, wxh: 1920x1080, fmt: 34363248, size 786432
[ 1890.903816] bcm2835-codec bcm2835-codec: bcm2835_codec_buf_init: ctx:2538f4ab, vb cb8ebd79
[ 1890.905462] bcm2835-codec bcm2835-codec: bcm2835_codec_buf_init: ctx:2538f4ab, vb db8cf726
[ 1890.928104] bcm2835-codec bcm2835-codec: bcm2835_codec_buf_prepare: type: 10 ptr cb8ebd79
[ 1890.928437] bcm2835-codec bcm2835-codec: bcm2835_codec_buf_queue: type: 10 ptr cb8ebd79 vbuf->flags 0, seq 0, bytesused 1162
[ 1890.928457] bcm2835-codec bcm2835-codec: bcm2835_codec_start_streaming: type: 10 count 1
[ 1890.935712] bcm2835-codec bcm2835-codec: bcm2835_codec_buffer_cleanup: ctx:2538f4ab, vb 53d72dbb
[ 1890.935732] bcm2835-codec bcm2835-codec: bcm2835_codec_buffer_cleanup: ctx:2538f4ab, vb 62b31fb1
[ 1890.935747] bcm2835-codec bcm2835-codec: bcm2835_codec_buffer_cleanup: ctx:2538f4ab, vb f5b171dc
[ 1890.935762] bcm2835-codec bcm2835-codec: bcm2835_codec_buffer_cleanup: ctx:2538f4ab, vb bbfc748f
[ 1890.935779] bcm2835-codec bcm2835-codec: bcm2835_codec_buffer_cleanup: ctx:2538f4ab, vb 7ea6b65a
[ 1890.935794] bcm2835-codec bcm2835-codec: bcm2835_codec_buffer_cleanup: ctx:2538f4ab, vb e8d4a125
[ 1890.935808] bcm2835-codec bcm2835-codec: bcm2835_codec_buffer_cleanup: ctx:2538f4ab, vb da284fd3
[ 1890.976156] bcm2835-codec bcm2835-codec: Setting format for type 9, wxh: 1920x1088, fmt: YU12, size 3133440
[ 1890.976165] bcm2835-codec bcm2835-codec: Calulated bpl as 1920, size 3133440
[ 1890.976357] bcm2835-codec bcm2835-codec: Set format for type 9, wxh: 1920x1088, fmt: 32315559, size 3133440
[ 1890.979037] bcm2835-codec bcm2835-codec: bcm2835_codec_stop_streaming: type: 10 - return buffers
[ 1890.979048] bcm2835-codec bcm2835-codec: bcm2835_codec_stop_streaming: return buffer cb8ebd79
[ 1890.981244] bcm2835-codec bcm2835-codec: bcm2835_codec_stop_streaming: done
[ 1890.983189] bcm2835-codec bcm2835-codec: bcm2835_codec_buffer_cleanup: ctx:2538f4ab, vb cb8ebd79
[ 1890.983196] bcm2835-codec bcm2835-codec: bcm2835_codec_buffer_cleanup: ctx:2538f4ab, vb db8cf726
[ 1890.986359] bcm2835-codec bcm2835-codec: bcm2835_codec_release: Releasing instance 2538f4ab

vchiq_mmal_port_set_format failing is the issue. Our decoder is upset as whilst the output queue (data into the codec) has been disabled, the capture queue hasn't. Reality is that there is no need for GStreamer to disable the output queue as the header bytes that are about to be provided will tell the codec what resolution is required.

Simplest fix is probably to remove the passing of the resolution on a compressed port, so then there is no change. In theory you could change from (eg) H264 to H263 encoding and whilst only the output queue is disabled, but I think it's fair enough to fail that sort of use case.

eocanha commented 4 years ago

I'm not convinced that file is valid.

  • VLC under Windows won't play it back correctly.
  • VLC under Linux complains of missing reference pictures and general bitstream issues.
  • ffmpeg -i video-quality-change.mp4 -c:v copy -bsf:v h264_mp4toannexb video-quality-change.h264 to extract the raw elementary stream complains [mov,mp4,m4a,3gp,3g2,mj2 @ 0x2149b80] Found duplicated MOOV Atom. Skipped it. I believe the MOOV atom is the one containing the header bytes, so skipping it would be a very bad thing.

I know the file isn't a regular mp4 file, but that's because the data provided using Media Source Extensions (MSE) isn't "normal" either, it follows the ISO BMFF bytestream format. On MSE, data is "appended" and can be either an "init segment" (containing a MOOV atom and other headers used to configure the H264 decoder with a "codec-data") or a "media segment" (encoded audio/video frames). Init segments can appear more than once (eg: when providing data for the first time or for a second time but with a different video quality).

Regular video players don't necessarily have to work properly with MSE data. Actually, the browser demuxes it in a seperate pipeline (what we call the AppendPipeline) and stores H264 video frames and their caps (which contain video type (H264), dimensions and codec-data) in memory. When needed at playback time, those caps are used to properly configure a "PlaybackPipeline" and provide encoded H264 data to it. Note that the PlaybackPipeline doesn't have a demuxer, it just receives raw H264 data after having properly configured (or reconfigured) the video decoder. This setup works fine in GStreamer in push mode, or at least has worked until now both with the OMX decoders on the Raspberry Pi and with avdec (libav, ffmpeg) on desktop.

Taking the first 200 frames of two H264 elementary streams at different resolutions (Big Buck Bunny at 720p and 1080p) and concatenating them into a combined elementary stream produces an output that omxplayer likes.

pi@raspberrypi:~/ssd $ cat short_bbb.h264 | gst-play-1.0 fd://0
Interactive keyboard handling in terminal not available.
Now playing fd://0
ERROR Device '/dev/video10' has no supported format for fd://0
ERROR debug information: gstv4l2object.c(3764): gst_v4l2_object_set_format_full (): /GstPlayBin:playbin/GstURIDecodeBin:uridecodebin0/GstDecodeBin:decodebin0/v4l2h264dec:v4l2h264dec0:
Call to S_FMT failed for H264 @ 1920x1080: Invalid argument
Reached end of play list.

I see. I've also reproduced the concatenation trick here and was able to play the resulting video both with omxplayer and with gst-play-1.0 (using OMX). The steps I did to generate and play the new test.h264 file on desktop were:

wget http://yt-dash-mse-test.commondatastorage.googleapis.com/unit-tests/media/car-20120827-86.mp4 # 640x360
wget http://yt-dash-mse-test.commondatastorage.googleapis.com/unit-tests/media/car-20120827-89.mp4 # 1920x1080
ffmpeg -i car-20120827-86.mp4 -an -vcodec libx264 -crf 23 -ss 0 -t 0:00:10 test1.h264
ffmpeg -i car-20120827-89.mp4 -an -vcodec libx264 -crf 23 -ss 0:00:10 -t 0:00:20 test2.h264
cat test1.h264 test2.h264 > test.h264
ffplay -x 1920 -y 1080 test.h264

The concatenation trick only works when the H264 streams are in byte-stream format because the codec-data is embedded in the stream, instead of being supplied by specific avc1 (and maybe other) atoms in the MP4 container. The video-quality-change.mp4 example video I supplied was in avc format and needed extra work from the media player to process the new header and reconfigure the decoder. In the case of GStreamer in push mode, concatenating avc streams encapsulated as mp4 "just works", but in pull mode or with other players it's expected that it doesn't work. Anyway, now we have the more compatible test.h264 file to discuss about.

I don't see the CMA issues you do. From the kernel logs I see

...
[ 1889.859899] bcm2835-codec bcm2835-codec: Setting format for type 10, wxh: 1920x1080, fmt: H264, size 786432
[ 1889.859906] bcm2835-codec bcm2835-codec: Calulated bpl as 0, size 786432
[ 1889.860105] bcm2835-codec bcm2835-codec: Set format for type 10, wxh: 1920x1080, fmt: 34363248, size 786432
<<<<<<
[ 1889.861831] bcm2835-codec bcm2835-codec: vidioc_s_fmt: Failed vchiq_mmal_port_set_format on output port, ret -3 
<<<<<<
[ 1889.863179] bcm2835-codec bcm2835-codec: bcm2835_codec_buf_prepare: type: 9 ptr bbfc748f
[ 1889.863186] bcm2835-codec bcm2835-codec: bcm2835_codec_buf_prepare data will not fit into plane (1382400 < 3133440)
...
[ 1890.899189] videobuf2_common: driver bug: stop_streaming operation is leaving buf 7ea6b65a in active state
[ 1890.899270] bcm2835-codec bcm2835-codec: Setting format for type 10, wxh: 1920x1080, fmt: H264, size 786432
[ 1890.899286] bcm2835-codec bcm2835-codec: Calulated bpl as 0, size 786432
[ 1890.899954] bcm2835-codec bcm2835-codec: Set format for type 10, wxh: 1920x1080, fmt: 34363248, size 786432
[ 1890.903816] bcm2835-codec bcm2835-codec: bcm2835_codec_buf_init: ctx:2538f4ab, vb cb8ebd79
[ 1890.905462] bcm2835-codec bcm2835-codec: bcm2835_codec_buf_init: ctx:2538f4ab, vb db8cf726
[ 1890.928104] bcm2835-codec bcm2835-codec: bcm2835_codec_buf_prepare: type: 10 ptr cb8ebd79
[ 1890.928437] bcm2835-codec bcm2835-codec: bcm2835_codec_buf_queue: type: 10 ptr cb8ebd79 vbuf->flags 0, seq 0, bytesused 1162
[ 1890.928457] bcm2835-codec bcm2835-codec: bcm2835_codec_start_streaming: type: 10 count 1
...

vchiq_mmal_port_set_format failing is the issue. Our decoder is upset as whilst the output queue (data into the codec) has been disabled, the capture queue hasn't. Reality is that there is no need for GStreamer to disable the output queue as the header bytes that are about to be provided will tell the codec what resolution is required.

Simplest fix is probably to remove the passing of the resolution on a compressed port, so then there is no change. In theory you could change from (eg) H264 to H263 encoding and whilst only the output queue is disabled, but I think it's fair enough to fail that sort of use case.

Looks like you're getting an error in an earlier point than I am (I'm using GStreamer 1.16, maybe something has improved there). I'm able to get past the point of the format change because in my case the ports are already disabled before the change, but later I find the allocation issue:

Low quality video comes now:

KERNEL [ 6536.180096] bcm2835-codec bcm2835-codec: Setting format for type 10, wxh: 640x360, fmt: H264, size 524288
KERNEL [ 6537.948322] videobuf2_common: __vb2_queue_alloc: allocated 2 buffers, 1 plane(s) each
KERNEL [ 6538.118943] bcm2835_mmal_vchiq: port_action_port:result:0 component:0x40 port:1 action:ENABLE(1)
^^^ H264 port configured and enabled
KERNEL [ 6538.217994] bcm2835-codec bcm2835-codec: Setting format for type 9, wxh: 640x368, fmt: YU12, size 353280
KERNEL [ 6538.218541] bcm2835-codec bcm2835-codec: Set format for type 9, wxh: 640x368, fmt: 32315559, size 353280
KERNEL [ 6540.238095] videobuf2_common: __vb2_queue_alloc: allocated 2 buffers, 1 plane(s) each
KERNEL [ 6540.491053] bcm2835_mmal_vchiq: port_action_port:result:0 component:0x40 port:2 action:ENABLE(1)
^^^ YU12 port configured and enabled. Time passes now while the 10s of low quality video is being decoded.
KERNEL [ 6598.253675] bcm2835_mmal_vchiq: port_action_port:result:0 component:0x40 port:1 action:DISABLE(2)
^^^ Port 1 disabled
KERNEL [ 6598.277521] vc_sm_vpu_event: Released addr f9700000, size 524288, id 00000004, mem_handle c0000005
KERNEL [ 6598.277562] vc_sm_vpu_event: Released addr f9680000, size 524288, id 00000001, mem_handle c0000004
KERNEL [ 6598.587055] bcm2835_mmal_vchiq: port_action_port:result:0 component:0x40 port:2 action:DISABLE(2)
^^^ Port 2 disabled
KERNEL [ 6598.648501] vc_sm_vpu_event: Released addr f9800000, size 356352, id 00000003, mem_handle c0000003
KERNEL [ 6598.648546] vc_sm_vpu_event: Released addr f9780000, size 356352, id 00000002, mem_handle c0000002

High quality video comes now:

KERNEL [ 6598.940619] bcm2835-codec bcm2835-codec: Setting format for type 10, wxh: 1920x1080, fmt: H264, size 786432
KERNEL [ 6598.941119] bcm2835-codec bcm2835-codec: Set format for type 10, wxh: 1920x1080, fmt: 34363248, size 786432
KERNEL [ 6599.069710] videobuf2_common: __vb2_queue_alloc: allocated 2 buffers, 1 plane(s) each
KERNEL [ 6599.240851] bcm2835_mmal_vchiq: port_action_port:result:0 component:0x40 port:1 action:ENABLE(1)
^^^ H264 port configured and enabled
KERNEL [ 6599.286769] bcm2835-codec bcm2835-codec: Setting format for type 9, wxh: 1920x1088, fmt: YU12, size 3133440
KERNEL [ 6599.287268] bcm2835-codec bcm2835-codec: Set format for type 9, wxh: 1920x1088, fmt: 32315559, size 3133440
KERNEL [ 6599.498231] cma: cma_alloc: alloc failed, req-size: 765 pages, ret: -12
^^^ Allocation issue after configuring YU12 port
KERNEL [ 6599.523153] videobuf2_common: __vb2_queue_alloc: failed allocating memory for buffer 1
KERNEL [ 6599.536126] videobuf2_common: __vb2_queue_alloc: allocated 1 buffers, 1 plane(s) each
KERNEL [ 6599.623998] bcm2835_mmal_vchiq: port_action_port:result:0 component:0x40 port:1 action:DISABLE(2)

You can get the unfiltered log here. Note that the "KERNEL" lines are dumped each second, so it's "normal" that you see first the GStreamer error line and later the kernel errors that originated it.

Still, returning to your comment from Jan 3rd, I think you're right and the CMA reserved memory is only 8MB (not enough for a few full hd raw video frames). From dmesg at boot:

[    0.000000] cma: Reserved 8 MiB at 0x39400000
[    0.000000] Memory: 914660K/946176K available (8192K kernel code, 713K rwdata, 2332K rodata, 1024K init, 821K bss, 23324K reserved, 8192K cma-reserved)

Let's see if I can find where that limit is set in the kernel sources and try to rise it.

Thanks!

6by9 commented 4 years ago

Let's see if I can find where that limit is set in the kernel sources and try to rise it.

Stick cma=256M into /boot/cmdline.txt Sorry, I'm too used to playing on a Pi4 these days where FKMS is enabled by default. The overlay for that increases the CMA heap to 256M as well.

6by9 commented 4 years ago

I have a GST 1.16 build already. For me all the allocations succeed, but the decoder appears to be sitting waiting for something else to be provided. I'll try to find a few minutes to see what the codec is really up to at that point.

6by9 commented 4 years ago

I will add that I'm on the 5.4 kernel branch, and have development firmware. The kernel change shouldn't make much difference as the 4.19 and 5.4 branches should be pretty much in track.

eocanha commented 4 years ago

I think I'm pretty much at the same point as you now:

Low quality video:

KERNEL [  155.453300] bcm2835-codec bcm2835-codec: Setting format for type 10, wxh: 640x360, fmt: H264, size 524288
KERNEL [  157.223160] videobuf2_common: __vb2_queue_alloc: allocated 2 buffers, 1 plane(s) each
KERNEL [  157.413427] bcm2835_mmal_vchiq: port_action_port:result:0 component:0x40 port:1 action:ENABLE(1)
KERNEL [  157.508318] bcm2835-codec bcm2835-codec: Setting format for type 9, wxh: 640x368, fmt: YU12, size 353280
KERNEL [  157.508824] bcm2835-codec bcm2835-codec: Set format for type 9, wxh: 640x368, fmt: 32315559, size 353280
KERNEL [  159.495150] videobuf2_common: __vb2_queue_alloc: allocated 2 buffers, 1 plane(s) each
KERNEL [  159.746788] bcm2835_mmal_vchiq: port_action_port:result:0 component:0x40 port:2 action:ENABLE(1)
KERNEL [  159.759502] bcm2835-codec bcm2835-codec: ip_buffer_cb: port afb25065 buf 0ecd4b0d length 0, flags 0
KERNEL [  159.759511] bcm2835-codec bcm2835-codec: ip_buffer_cb: no error. Return buffer 1b8d458d
KERNEL [  159.771730] bcm2835-codec bcm2835-codec: ip_buffer_cb: done 1 input buffers
KERNEL [  159.926924] bcm2835-codec bcm2835-codec: ip_buffer_cb: port afb25065 buf 63922178 length 0, flags 0
KERNEL [  159.951268] bcm2835-codec bcm2835-codec: ip_buffer_cb: no error. Return buffer 0afa6cee
KERNEL [  160.000682] bcm2835-codec bcm2835-codec: ip_buffer_cb: done 2 input buffers
KERNEL [  160.072184] bcm2835-codec bcm2835-codec: ip_buffer_cb: port afb25065 buf 0ecd4b0d length 0, flags 0
KERNEL [  160.096222] bcm2835-codec bcm2835-codec: ip_buffer_cb: no error. Return buffer 1b8d458d
KERNEL [  160.144615] bcm2835-codec bcm2835-codec: ip_buffer_cb: done 3 input buffers
KERNEL [  160.144652] bcm2835-codec bcm2835-codec: op_buffer_cb: status:0, buf:8317de6d, length:353280, flags 4, pts 0
KERNEL [  160.144662] bcm2835-codec bcm2835-codec: op_buffer_cb: length 353280, flags 4, idx 0
KERNEL [  160.144703] bcm2835-codec bcm2835-codec: ip_buffer_cb: port afb25065 buf 63922178 length 0, flags 0
KERNEL [  160.144711] bcm2835-codec bcm2835-codec: ip_buffer_cb: no error. Return buffer 0afa6cee
KERNEL [  160.144728] bcm2835-codec bcm2835-codec: ip_buffer_cb: done 4 input buffers
KERNEL [  160.144741] bcm2835-codec bcm2835-codec: op_buffer_cb: status:0, buf:2c2dbb88, length:353280, flags 4, pts 0
KERNEL [  160.144749] bcm2835-codec bcm2835-codec: op_buffer_cb: length 353280, flags 4, idx 1
KERNEL [  160.144768] bcm2835-codec bcm2835-codec: op_buffer_cb: done 1 output buffers
KERNEL [  160.167439] bcm2835-codec bcm2835-codec: op_buffer_cb: done 2 output buffers
...
KERNEL [  216.524638] bcm2835-codec bcm2835-codec: ip_buffer_cb: port afb25065 buf 2b0da326 length 0, flags 0
KERNEL [  216.548438] bcm2835-codec bcm2835-codec: ip_buffer_cb: eos buffer returned.
KERNEL [  216.552082] bcm2835-codec bcm2835-codec: op_buffer_cb: status:0, buf:2c2dbb88, length:353280, flags 4, pts 0
KERNEL [  216.552091] bcm2835-codec bcm2835-codec: op_buffer_cb: length 353280, flags 4, idx 1
KERNEL [  216.552112] bcm2835-codec bcm2835-codec: op_buffer_cb: done 235 output buffers
KERNEL [  216.704210] bcm2835-codec bcm2835-codec: op_buffer_cb: status:0, buf:8317de6d, length:353280, flags 4, pts 0
KERNEL [  216.716385] bcm2835-codec bcm2835-codec: op_buffer_cb: length 353280, flags 4, idx 0
KERNEL [  216.739937] bcm2835-codec bcm2835-codec: op_buffer_cb: done 236 output buffers
KERNEL [  216.823993] bcm2835-codec bcm2835-codec: op_buffer_cb: status:0, buf:2c2dbb88, length:353280, flags 4, pts 0
KERNEL [  216.835884] bcm2835-codec bcm2835-codec: op_buffer_cb: length 353280, flags 4, idx 1
KERNEL [  216.859369] bcm2835-codec bcm2835-codec: op_buffer_cb: done 237 output buffers
KERNEL [  216.930379] bcm2835-codec bcm2835-codec: op_buffer_cb: status:0, buf:8317de6d, length:353280, flags 4, pts 0
KERNEL [  216.943000] bcm2835-codec bcm2835-codec: op_buffer_cb: length 353280, flags 4, idx 0
KERNEL [  216.955246] bcm2835-codec bcm2835-codec: op_buffer_cb: done 238 output buffers
KERNEL [  217.062666] bcm2835-codec bcm2835-codec: op_buffer_cb: status:0, buf:2c2dbb88, length:353280, flags 4, pts 0
KERNEL [  217.086267] bcm2835-codec bcm2835-codec: op_buffer_cb: length 353280, flags 4, idx 1
KERNEL [  217.110920] bcm2835-codec bcm2835-codec: op_buffer_cb: done 239 output buffers
KERNEL [  217.170410] bcm2835-codec bcm2835-codec: op_buffer_cb: status:0, buf:8317de6d, length:353280, flags 4, pts 0
KERNEL [  217.183019] bcm2835-codec bcm2835-codec: op_buffer_cb: length 353280, flags 4, idx 0
KERNEL [  217.194811] bcm2835-codec bcm2835-codec: op_buffer_cb: done 240 output buffers
KERNEL [  217.281242] bcm2835-codec bcm2835-codec: op_buffer_cb: status:0, buf:2c2dbb88, length:0, flags 1, pts 41711
KERNEL [  217.281252] bcm2835-codec bcm2835-codec: op_buffer_cb: length 0, flags 1, idx 1
KERNEL [  217.281260] bcm2835-codec bcm2835-codec: op_buffer_cb: Empty buffer - flags 0001
KERNEL [  217.293090] bcm2835-codec bcm2835-codec: op_buffer_cb: done 241 output buffers
KERNEL [  217.526411] bcm2835_mmal_vchiq: port_action_port:result:0 component:0x40 port:1 action:DISABLE(2)
KERNEL [  217.550310] vc_sm_vpu_event: Released addr dd300000, size 524288, id 00000004, mem_handle c0000005
KERNEL [  217.550358] vc_sm_vpu_event: Released addr dd280000, size 524288, id 00000001, mem_handle c0000002
KERNEL [  217.856408] bcm2835-codec bcm2835-codec: op_buffer_cb: status:0, buf:8317de6d, length:0, flags 0, pts -9223372036854775808
KERNEL [  217.856417] bcm2835-codec bcm2835-codec: op_buffer_cb: length 0, flags 0, idx 0
KERNEL [  217.856426] bcm2835-codec bcm2835-codec: op_buffer_cb: Empty buffer - flags 0000
KERNEL [  217.868253] bcm2835-codec bcm2835-codec: op_buffer_cb: status:0, buf:2c2dbb88, length:0, flags 0, pts -9223372036854775808
KERNEL [  217.868268] bcm2835-codec bcm2835-codec: op_buffer_cb: length 0, flags 0, idx 1
KERNEL [  217.868278] bcm2835_mmal_vchiq: port_action_port:result:0 component:0x40 port:2 action:DISABLE(2)
KERNEL [  217.868293] bcm2835-codec bcm2835-codec: op_buffer_cb: Empty buffer - flags 0000
KERNEL [  217.916265] vc_sm_vpu_event: Released addr dd400000, size 356352, id 00000003, mem_handle c0000004
KERNEL [  217.916314] vc_sm_vpu_event: Released addr dd380000, size 356352, id 00000002, mem_handle c0000003

High quality video:

KERNEL [  218.207782] bcm2835-codec bcm2835-codec: Setting format for type 10, wxh: 1920x1080, fmt: H264, size 786432
KERNEL [  218.208306] bcm2835-codec bcm2835-codec: Set format for type 10, wxh: 1920x1080, fmt: 34363248, size 786432
KERNEL [  218.337282] videobuf2_common: __vb2_queue_alloc: allocated 2 buffers, 1 plane(s) each
KERNEL [  218.508567] bcm2835_mmal_vchiq: port_action_port:result:0 component:0x40 port:1 action:ENABLE(1)
KERNEL [  218.554608] bcm2835-codec bcm2835-codec: Setting format for type 9, wxh: 1920x1088, fmt: YU12, size 3133440
KERNEL [  218.555114] bcm2835-codec bcm2835-codec: Set format for type 9, wxh: 1920x1088, fmt: 32315559, size 3133440
KERNEL [  218.807465] videobuf2_common: __vb2_queue_alloc: allocated 2 buffers, 1 plane(s) each
KERNEL [  219.058412] bcm2835_mmal_vchiq: port_action_port:result:0 component:0x40 port:2 action:ENABLE(1)

Note that there are no ip_buffer_cb() callbacks (and obviously, no op_buffer_cb() either). Does it mean that the decoder never provides input buffers to be fed with H264 data (assuming I'm right and "ip"="input"="H264" and "op"="output"="YU12")? That's really strange!

After 20 sec waiting, I just interrupted gst-play-1.0. What follows are the teardown kernel logs. The output buffer callbacks appear now, just returning empty buffers (makes sense).

KERNEL [  239.079503] bcm2835-codec bcm2835-codec: op_buffer_cb: status:0, buf:a6c1f0b6, length:0, flags 0, pts -9223372036854775808
KERNEL [  239.079519] bcm2835-codec bcm2835-codec: op_buffer_cb: length 0, flags 0, idx 0
KERNEL [  239.079529] bcm2835-codec bcm2835-codec: op_buffer_cb: Empty buffer - flags 0000
KERNEL [  239.079912] bcm2835_mmal_vchiq: port_action_port:result:0 component:0x40 port:2 action:DISABLE(2)
KERNEL [  239.091687] bcm2835-codec bcm2835-codec: op_buffer_cb: status:0, buf:40b3e624, length:0, flags 0, pts -9223372036854775808
KERNEL [  239.091695] bcm2835-codec bcm2835-codec: op_buffer_cb: length 0, flags 0, idx 1
KERNEL [  239.091700] bcm2835-codec bcm2835-codec: op_buffer_cb: Empty buffer - flags 0000

The unfiltered log might give some interesting information from 219.058412 to 219.147171. It shows that several input and output buffers are submitted to the component.

I think now I'm in a similar point where I was in my original vc4-kms-v3d/KMS/Wayland setup, but with the "classic" bcm2708fb driver, which allows me to get logs from vcgencmd and vcdebug.

eocanha commented 4 years ago

Unfortunately, the vcdbg logs aren't very conclusive. They are very "chatty" during the low quality video decoding, with lines about how it starts decoding:

KERNEL [   44.138957] bcm2835-codec bcm2835-codec: Setting format for type 9, wxh: 640x368, fmt: YU12, size 353280
KERNEL [   44.139642] bcm2835-codec bcm2835-codec: Set format for type 9, wxh: 640x368, fmt: 32315559, size 353280
VCDBGLOG 049475.768: video_decode:4:RIL:GetParameter(3f500104)
VCDBGLOG 051725.857: video_decode:4:RIL: setup image requirements (1920x1088(1920x1088)x5)
VCDBGLOG 051727.290: video_decode:4:RIL: extract from fifo: len:943 flags:10 time:0
VCDBGLOG 051727.323: video_decode:4:RIL: decoding 943 bytes, 0us, flags 10, (cb:0x3f5005a8)
VCDBGLOG 051727.343: video_decode:4:RIL: asking for more

But later becomes silent when high quality video comes:

VCDBGLOG 109022.171: video_decode:4:RIL: finished passing image
VCDBGLOG 109022.221: video_decode:4:RIL:output done, dec_frames_full:3f502a74 out:0
VCDBGLOG 109141.185: video_decode:4:RIL:output dec_frames_full:3f502a74 out:3f5086d0
VCDBGLOG 109141.974: video_decode:4:RIL: finished passing image
VCDBGLOG 109142.022: video_decode:4:RIL:output done, dec_frames_full:3f502ae8 out:0
VCDBGLOG 109261.124: video_decode:4:RIL:output dec_frames_full:3f502ae8 out:3f5086d0
VCDBGLOG 109261.147: video_decode:4:RIL:unknown time to 41711
KERNEL [  103.828425] bcm2835-codec bcm2835-codec: op_buffer_cb: status:0, buf:2b39bd04, length:353280, flags 4, pts 0
KERNEL [  103.852402] bcm2835-codec bcm2835-codec: op_buffer_cb: length 353280, flags 4, idx 0
KERNEL [  103.876645] bcm2835-codec bcm2835-codec: op_buffer_cb: done 240 output buffers
KERNEL [  103.924707] bcm2835-codec bcm2835-codec: op_buffer_cb: status:0, buf:ebe82755, length:0, flags 1, pts 41711
KERNEL [  103.924716] bcm2835-codec bcm2835-codec: op_buffer_cb: length 0, flags 1, idx 1
KERNEL [  103.924724] bcm2835-codec bcm2835-codec: op_buffer_cb: Empty buffer - flags 0001
KERNEL [  103.936638] bcm2835-codec bcm2835-codec: op_buffer_cb: done 241 output buffers
VCDBGLOG 109261.191: video_decode:4:RIL:output done, dec_frames_full:0 out:0
VCDBGLOG 110180.780: video_decode:4:RIL:GetParameter(3f500104)
VCDBGLOG 110180.796: video_decode:4:RIL:GetParameter(3f500104)
VCDBGLOG 110180.814: video_decode:4:RIL:SetParameter(7f0000f4)
VCDBGLOG 110180.831: video_decode:4:RIL:GetParameter(3f500104)
VCDBGLOG 110180.855: video_decode:4:RIL:SetParameter(2000001)
VCDBGLOG 110180.869: video_decode:4:RIL:PortDef, port 130
VCDBGLOG 110180.879: video_decode:4:RIL: set input format
VCDBGLOG 110180.896: video_decode:4:RIL:SetParameter(7f00004d)
VCDBGLOG 110180.912: video_decode:4:RIL:SetParameter(7f0000bb)
VCDBGLOG 110180.930: video_decode:4:RIL:SetParameter(6f600003)
VCDBGLOG 110180.947: video_decode:4:RIL:GetParameter(3f500104)
VCDBGLOG 110180.968: video_decode:4:RIL:GetParameter(3f500104)
VCDBGLOG 110180.983: video_decode:4:RIL:GetParameter(3f500104)
VCDBGLOG 110181.001: video_decode:4:RIL:GetParameter(3f500104)
VCDBGLOG 110181.019: video_decode:4:RIL:GetParameter(3f500104)
VCDBGLOG 110181.038: video_decode:4:RIL:GetParameter(3f500104)
VCDBGLOG 110181.481: video_decode:4:RIL:GetParameter(3f500104)
VCDBGLOG 110181.500: video_decode:4:RIL:GetParameter(3f500104)
VCDBGLOG 110181.517: video_decode:4:RIL:SetParameter(7f0000f4)
VCDBGLOG 110181.537: video_decode:4:RIL:GetParameter(3f500104)
VCDBGLOG 110181.552: video_decode:4:RIL:SetParameter(2000001)
VCDBGLOG 110181.567: video_decode:4:RIL:PortDef, port 131
VCDBGLOG 110181.583: video_decode:4:RIL: set output format 20
VCDBGLOG 110181.604: video_decode:4:RIL:SetParameter(7f00004d)
VCDBGLOG 110181.623: video_decode:4:RIL:SetParameter(7f0000bb)
VCDBGLOG 110181.639: video_decode:4:RIL:GetParameter(3f500104)
VCDBGLOG 110181.657: video_decode:4:RIL:GetParameter(3f500104)
KERNEL [  104.171536] bcm2835_mmal_vchiq: port_action_port:result:0 component:0x40 port:1 action:DISABLE(2)
KERNEL [  104.182392] vc_sm_vpu_event: Released addr dd300000, size 524288, id 00000004, mem_handle c0000005
KERNEL [  104.182438] vc_sm_vpu_event: Released addr dd280000, size 524288, id 00000001, mem_handle c0000002
KERNEL [  104.491145] bcm2835-codec bcm2835-codec: op_buffer_cb: status:0, buf:2b39bd04, length:0, flags 0, pts -9223372036854775808
KERNEL [  104.491155] bcm2835-codec bcm2835-codec: op_buffer_cb: length 0, flags 0, idx 0
KERNEL [  104.491163] bcm2835-codec bcm2835-codec: op_buffer_cb: Empty buffer - flags 0000
KERNEL [  104.491926] bcm2835_mmal_vchiq: port_action_port:result:0 component:0x40 port:2 action:DISABLE(2)
KERNEL [  104.503132] bcm2835-codec bcm2835-codec: op_buffer_cb: status:0, buf:ebe82755, length:0, flags 0, pts -9223372036854775808
KERNEL [  104.503149] bcm2835-codec bcm2835-codec: op_buffer_cb: length 0, flags 0, idx 1
KERNEL [  104.503164] bcm2835-codec bcm2835-codec: op_buffer_cb: Empty buffer - flags 0000
KERNEL [  104.551643] vc_sm_vpu_event: Released addr dd400000, size 356352, id 00000003, mem_handle c0000004
KERNEL [  104.551685] vc_sm_vpu_event: Released addr dd380000, size 356352, id 00000002, mem_handle c0000003
KERNEL [  104.844002] bcm2835-codec bcm2835-codec: Setting format for type 10, wxh: 1920x1080, fmt: H264, size 786432
KERNEL [  104.844757] bcm2835-codec bcm2835-codec: Set format for type 10, wxh: 1920x1080, fmt: 34363248, size 786432
KERNEL [  104.974112] videobuf2_common: __vb2_queue_alloc: allocated 2 buffers, 1 plane(s) each
KERNEL [  105.146620] bcm2835_mmal_vchiq: port_action_port:result:0 component:0x40 port:1 action:ENABLE(1)
VCDBGLOG 110181.672: video_decode:4:RIL:GetParameter(3f500104)
VCDBGLOG 110533.676: video_decode:4:RIL:GetParameter(3f500104)
VCDBGLOG 110533.694: video_decode:4:RIL:GetParameter(3f500104)
VCDBGLOG 110533.713: video_decode:4:RIL:SetParameter(7f0000f4)
VCDBGLOG 110533.731: video_decode:4:RIL:GetParameter(3f500104)
VCDBGLOG 110533.749: video_decode:4:RIL:SetParameter(2000001)
VCDBGLOG 110533.764: video_decode:4:RIL:PortDef, port 131
VCDBGLOG 110533.778: video_decode:4:RIL: set output format 20
VCDBGLOG 110533.798: video_decode:4:RIL:SetParameter(7f00004d)
VCDBGLOG 110533.816: video_decode:4:RIL:SetParameter(7f0000bb)
VCDBGLOG 110533.832: video_decode:4:RIL:GetParameter(3f500104)
VCDBGLOG 110533.848: video_decode:4:RIL:GetParameter(3f500104)
KERNEL [  105.196881] bcm2835-codec bcm2835-codec: Setting format for type 9, wxh: 1920x1088, fmt: YU12, size 3133440
KERNEL [  105.197581] bcm2835-codec bcm2835-codec: Set format for type 9, wxh: 1920x1088, fmt: 32315559, size 3133440
KERNEL [  105.463087] videobuf2_common: __vb2_queue_alloc: allocated 2 buffers, 1 plane(s) each
KERNEL [  105.715116] bcm2835_mmal_vchiq: port_action_port:result:0 component:0x40 port:2 action:ENABLE(1)

Again, remember that the interleaving of the KERNEL lines is approximate and likely "late" (they're dumped every second).

I enabled the vcdbg log lines like this (I got the levels from this VideoCore Tools wikipage):

LD_LIBRARY_PATH=/root/hardfp/opt/vc/lib /root/hardfp/opt/vc/bin/vcgencmd set_logging level=128
LD_LIBRARY_PATH=/root/hardfp/opt/vc/lib /root/hardfp/opt/vc/bin/vcdbg log -f msg 2>&1 | sed 's/^/VCDBGLOG /'

I also tried more aggressive log levels, such as 2147483647 (all the bits to 1), but it only served to get corrupted logs after some time (buffer full?) and didn't give any extra info even when I started configuring and getting logs after 60 seconds, near the runtime where the quality change happens for me.

Unfiltered log here.

RogerHardiman commented 3 years ago

Hitting the same issues as in the problem report on a Pi 3b+ ith 5.4.83-v7+ kernel I have a program that uses ffmpeg to talk to the v4l2_m2m API and after around 16 changes of resolution I'll get

[h264_v4l2m2m @ 0x7338c810] Using device /dev/video11
[h264_v4l2m2m @ 0x7338c810] driver 'bcm2835-codec' on card 'bcm2835-codec-encode' in mplane mode
[h264_v4l2m2m @ 0x7338c810] requesting formats: output=NV12 capture=H264
[h264_v4l2m2m @ 0x7338c810] output VIDIOC_REQBUFS failed: Invalid argument
[h264_v4l2m2m @ 0x7338c810] no v4l2 output context's buffers
[h264_v4l2m2m @ 0x7338c810] can't configure encoder

and then an inability to use the hardware encoder.

Was there any fixes for this issue?

eocanha commented 3 years ago

From my side (bug reporter) this task just got stalled and deprioritized and I couldn't devote more time to it. It's buried deep in my TODO.

cadubentzen commented 4 months ago

FWIW, I tested this issue today on a RPi 3B+ with buildroot 2024.02.1, linux kernel 6.1.61-v7, gstreamer 1.22.9, and with dtoverlay=vc4-kms-v3d,cma-128 in config.txt, and I could play the MP4 file attached in the issue by forcing sequential access as described as required for playing in the desktop.

cat video-quality-change.mp4 | gst-play-1.0 fd://0

It also works if I extract the separate H.264 bitstreams from each quality (embedding SPS/PPS in the bitstream, thus generating "Annex-B" files) and concatenate them:

# separate the parts (counted bytes via mp4dump)
head -c 405966 video-quality-change.mp4 > 640x360.mp4
tail -c 2788777 video-quality-change.mp4 > 1920x1080.mp4
# extract H.264 bitstreams
ffmpeg -i 640x360.mp4 -c:v copy 640x360.h264
ffmpeg -i 1920x1080.mp4 -c:v copy 1920x1080.h264
# concatenate bitstreams
cat 640x360.h264 1920x1080.h264 > concatenated.h264
# then it's playable via
gst-play-1.0 concatenated.h264

Not sure if something was fixed between my version and the one tested before, either in the kernel or gstreamer, but from what I can see here this isn't looking like a decoder issue, but rather an issue with the file or demuxer element when handling that file. I see that if sequential read isn't forced, then caps were never renegotiated to 1080p when changing quality at ~5s (looking for <v4l2h264dec0:sink> accept caps of video/x-h264 with GST_DEBUG=GST_CAPS:TRACE), so the decoder outputs garbage frames after changing quality.

From the decoder's side, all it cares about is receiving SPS/PPS data whenever there's a quality switch. If the decoder receives this, it seems to work, as least for this one quality transition from the file in this issue.

eocanha commented 4 months ago

Those are really great news!

The sequential read forcing is to force push mode in all the GStreamer elements involved in the pipeline. This is how the pipelines on MSE work (in comparison to progressive video, where qtdemux usually works in pull mode upstream (and push mode downstream, but that's not relevant).

Qtdemux has very different codepaths for push and pull modes, but for the sake of this issue, whatever happens in pull mode isn't relevant (so don't worry about it). The important stuff here was quality changes in push mode, and if that seems to work now, then I think we can close this issue as solved.

Thank you!