avdec_h264 performance regression in 1.22.1 against 1.18.4 (Debian Bullseye)
Problem is discovered this slower Celeron machine (i3, i7 works fine), running Debian 11 Bullseye (amd54):
$ lscpu | fgrep "Model name"
Model name: Intel(R) Celeron(R) CPU J1900 @ 1.99GHz
Default gstreamer
on this system is:
$ gst-launch-1.0 --version
gst-launch-1.0 version 1.18.4
GStreamer 1.18.4
http://packages.qa.debian.org/gstreamer1.0
ffmpeg:
$ apt-cache policy libavcodec58 | fgrep Installed
Installed: 7:4.3.5-0+deb11u1
If I run this pipeline (originally I use rtsp source, but it does not matter) using default Debian GStreamer 1.18.4, have no issues, just rarely some frames being dropped:
$ GST_DEBUG=3 gst-launch-1.0 filesrc location=bbb_sunflower_1080p_30fps_normal.mp4 ! qtdemux ! h264parse ! avdec_h264 ! glupload ! glimagesink
Setting pipeline to PAUSED ...
Xlib: sequence lost (0x1002e > 0x30) in reply type 0x0!
0:00:00.488589900 191886 0x558025e43190 WARN basesrc gstbasesrc.c:3688:gst_base_src_start_complete:<filesrc0> pad not activated yet
Pipeline is PREROLLING ...
Got context from element 'sink': gst.gl.GLDisplay=context, gst.gl.GLDisplay=(GstGLDisplay)"\(GstGLDisplayX11\)\ gldisplayx11-0";
0:00:00.489848160 191886 0x7fe4a80020c0 WARN qtdemux qtdemux_types.c:244:qtdemux_type_get: unknown QuickTime node type iods
0:00:00.489983484 191886 0x7fe4a80020c0 WARN qtdemux qtdemux_types.c:244:qtdemux_type_get: unknown QuickTime node type ac-3
0:00:00.490041756 191886 0x7fe4a80020c0 WARN qtdemux qtdemux_types.c:244:qtdemux_type_get: unknown QuickTime node type .com
0:00:00.490234920 191886 0x7fe4a80020c0 WARN qtdemux qtdemux.c:3066:qtdemux_parse_trex:<qtdemux0> failed to find fragment defaults for stream 1
0:00:00.490847856 191886 0x7fe4a80020c0 WARN qtdemux qtdemux.c:3066:qtdemux_parse_trex:<qtdemux0> failed to find fragment defaults for stream 2
0:00:00.491037924 191886 0x7fe4a80020c0 WARN qtdemux qtdemux.c:3066:qtdemux_parse_trex:<qtdemux0> failed to find fragment defaults for stream 3
Redistribute latency...
Redistribute latency...
Pipeline is PREROLLED ...0 %)
Setting pipeline to PLAYING ...
New clock: GstSystemClock
0:00:00.865790496 191886 0x7fe4a80020c0 WARN videodecoder gstvideodecoder.c:3298:gst_video_decoder_clip_and_push_buf:<avdec_h264-0> Dropping frame due to QoS. start:0:00:00.200000000 deadline:0:00:00.200000000 earliest_time:0:00:00.200824835
0:00:16.918082568 191886 0x7fe4a80020c0 WARN videodecoder gstvideodecoder.c:3298:gst_video_decoder_clip_and_push_buf:<avdec_h264-0> Dropping frame due to QoS. start:0:00:16.266666666 deadline:0:00:16.266666666 earliest_time:0:00:16.278571344
sudo perf top -F 10000 -p $(pgrep gst-launch-1.0) -K -g
output:
Now, if I use my own built (using Conan package manager recipes, modified to use 1.22.1 instead of 1.19) GStreamer with ffmpeg 4.3.2 (tried 4.4, 5.0 with same results, as Conan packages exist for them):
$ ./gst-inspect-1.0 --version
gst-inspect-1.0 version 1.22.1
GStreamer 1.22.1
Unknown package origin
Using same pipeline I get most of frames being dropped (unusable), and increased CPU usage around to 230%:
$ GST_DEBUG=3 ./gst-launch-1.0 filesrc location=bbb_sunflower_1080p_30fps_normal.mp4 ! qtdemux ! h264parse ! avdec_h264 ! glupload ! glimagesink
Setting pipeline to PAUSED ...
Xlib: sequence lost (0x1002e > 0x30) in reply type 0x0!
0:00:00.181625340 200336 0x56521bf45800 WARN basesrc gstbasesrc.c:3693:gst_base_src_start_complete:<filesrc0> pad not activated yet
Pipeline is PREROLLING ...
Got context from element 'sink': gst.gl.GLDisplay=context, gst.gl.GLDisplay=(GstGLDisplay)"\(GstGLDisplayX11\)\ gldisplayx11-0";
0:00:00.182743128 200336 0x7f4d9c002300 WARN qtdemux qtdemux_types.c:264:qtdemux_type_get: unknown QuickTime node type iods
0:00:00.182836500 200336 0x7f4d9c002300 WARN qtdemux qtdemux_types.c:264:qtdemux_type_get: unknown QuickTime node type ac-3
0:00:00.182899272 200336 0x7f4d9c002300 WARN qtdemux qtdemux_types.c:264:qtdemux_type_get: unknown QuickTime node type .com
0:00:00.183071688 200336 0x7f4d9c002300 WARN qtdemux qtdemux.c:3240:qtdemux_parse_trex:<qtdemux0> failed to find fragment defaults for stream 1
0:00:00.183715104 200336 0x7f4d9c002300 WARN qtdemux qtdemux.c:3240:qtdemux_parse_trex:<qtdemux0> failed to find fragment defaults for stream 2
0:00:00.183897972 200336 0x7f4d9c002300 WARN qtdemux qtdemux.c:3240:qtdemux_parse_trex:<qtdemux0> failed to find fragment defaults for stream 3
Redistribute latency...
Redistribute latency...
Redistribute latency...
Redistribute latency...
Pipeline is PREROLLED ...0 %)
Setting pipeline to PLAYING ...
Redistribute latency...
New clock: GstSystemClock
0:00:00.590498088 200336 0x7f4d9c002300 WARN videodecoder gstvideodecoder.c:3668:gst_video_decoder_clip_and_push_buf:<avdec_h264-0> Dropping frame due to QoS. start:0:00:00.166666666 deadline:0:00:00.166666666 earliest_time:0:00:00.180211760
0:00:00.740400432 200336 0x7f4d9c002300 WARN videodecoder gstvideodecoder.c:3668:gst_video_decoder_clip_and_push_buf:<avdec_h264-0> Dropping frame due to QoS. start:0:00:00.233333333 deadline:0:00:00.233333333 earliest_time:0:00:00.254439445
0:00:01.986741360 200336 0x7f4d9c002300 WARN basesink gstbasesink.c:3143:gst_base_sink_is_too_late:<sink> warning: A lot of buffers are being dropped.
0:00:01.986786180 200336 0x7f4d9c002300 WARN basesink gstbasesink.c:3143:gst_base_sink_is_too_late:<sink> warning: There may be a timestamping problem, or this computer is too slow.
0:00:01.987076028 200336 0x7f4d9c002300 WARN basesink gstbasesink.c:3143:gst_base_sink_is_too_late:<sink> warning: A lot of buffers are being dropped.
WARNING: from element /GstPipeline:pipeline0/GstGLImageSinkBin:glimagesinkbin0/GstGLImageSink:sink: A lot of buffers are being dropped.
0:00:01.987103208 200336 0x7f4d9c002300 WARN basesink gstbasesink.c:3143:gst_base_sink_is_too_late:<sink> warning: There may be a timestamping problem, or this computer is too slow.
Additional debug info:
../src/libs/gst/base/gstbasesink.c(3143): gst_base_sink_is_too_late (): /GstPipeline:pipeline0/GstGLImageSinkBin:glimagesinkbin0/GstGLImageSink:sink:
There may be a timestamping problem, or this computer is too slow.
WARNING: from element /GstPipeline:pipeline0/GstGLImageSinkBin:glimagesinkbin0/GstGLImageSink:sink: A lot of buffers are being dropped.
Additional debug info:
../src/libs/gst/base/gstbasesink.c(3143): gst_base_sink_is_too_late (): /GstPipeline:pipeline0/GstGLImageSinkBin:glimagesinkbin0/GstGLImageSink:sink:
There may be a timestamping problem, or this computer is too slow.
0:00:02.060476824 200336 0x7f4d9c002300 WARN videodecoder gstvideodecoder.c:3668:gst_video_decoder_clip_and_push_buf:<avdec_h264-0> Dropping frame due to QoS. start:0:00:01.266666666 deadline:0:00:01.266666666 earliest_time:0:00:01.930497888
0:00:02.086263348 200336 0x7f4d9c002300 WARN videodecoder gstvideodecoder.c:3668:gst_video_decoder_clip_and_push_buf:<avdec_h264-0> Dropping frame due to QoS. start:0:00:01.300000000 deadline:0:00:01.300000000 earliest_time:0:00:01.930497888
0:00:02.167794300 200336 0x7f4d9c002300 WARN videodecoder gstvideodecoder.c:3668:gst_video_decoder_clip_and_push_buf:<avdec_h264-0> Dropping frame due to QoS. start:0:00:01.333333333 deadline:0:00:01.333333333 earliest_time:0:00:01.930497888
0:00:02.185953540 200336 0x7f4d9c002300 WARN videodecoder gstvideodecoder.c:3668:gst_video_decoder_clip_and_push_buf:<avdec_h264-0> Dropping frame due to QoS. start:0:00:01.366666666 deadline:0:00:01.366666666 earliest_time:0:00:01.930497888
0:00:02.203559892 200336 0x7f4d9c002300 WARN videodecoder gstvideodecoder.c:3668:gst_video_decoder_clip_and_push_buf:<avdec_h264-0> Dropping frame due to QoS. start:0:00:01.400000000 deadline:0:00:01.400000000 earliest_time:0:00:01.930497888
0:00:02.297347956 200336 0x7f4d9c002300 WARN videodecoder gstvideodecoder.c:3668:gst_video_decoder_clip_and_push_buf:<avdec_h264-0> Dropping frame due to QoS. start:0:00:01.466666666 deadline:0:00:01.466666666 earliest_time:0:00:01.930497888
0:00:02.318142312 200336 0x7f4d9c002300 WARN videodecoder gstvideodecoder.c:3668:gst_video_decoder_clip_and_push_buf:<avdec_h264-0> Dropping frame due to QoS. start:0:00:01.533333333 deadline:0:00:01.533333333 earliest_time:0:00:01.930497888
0:00:02.429438556 200336 0x7f4d9c002300 WARN videodecoder gstvideodecoder.c:3668:gst_video_decoder_clip_and_push_buf:<avdec_h264-0> Dropping frame due to QoS. start:0:00:01.600000000 deadline:0:00:01.600000000 earliest_time:0:00:01.930497888
0:00:02.521305528 200336 0x7f4d9c002300 WARN videodecoder gstvideodecoder.c:3668:gst_video_decoder_clip_and_push_buf:<avdec_h264-0> Dropping frame due to QoS. start:0:00:01.700000000 deadline:0:00:01.700000000 earliest_time:0:00:01.930497888
0:00:02.560126488 200336 0x7f4d9c002300 WARN videodecoder gstvideodecoder.c:3668:gst_video_decoder_clip_and_push_buf:<avdec_h264-0> Dropping frame due to QoS. start:0:00:01.766666666 deadline:0:00:01.766666666 earliest_time:0:00:01.930497888
0:00:02.653258296 200336 0x7f4d9c002300 WARN videodecoder gstvideodecoder.c:3668:gst_video_decoder_clip_and_push_buf:<avdec_h264-0> Dropping frame due to QoS. start:0:00:01.866666666 deadline:0:00:01.866666666 earliest_time:0:00:01.930497888
We were using software decoder to get smaller RTSP video latency (avdec_h264
results in just bout 200ms).
Now, with 1.22.1 we get same latency with new vah264dec
, which is great and thanks to that, but software fallback is now too hard for cheaper Celeron machines for some reason...
This is ffmpeg
Conan build log, where I do see optimizations enabled, so I doubt it's Conan build issue:
https://paste.mozilla.org/oiD2mmX0
This is gstreamer-libav
Conan build log, where I do see release
mode being used: