GNOME Bugzilla – Bug 765391
vpxenc: Handle frames with too low duration correctly
Last modified: 2016-04-24 20:39:13 UTC
Created attachment 326515 [details] Simplified full diff between the output of the two cases As found while working on an issue on our fork of GNOME Shell (renamed eos-shell) observed when trying to record an screencast (using GNOME shell's keyboard accel "Ctrl+Shift+Alt+R"), it seems that the libgstvpx plugin is not working as expected if the passed duration for a frame is too short. This, in our particular case trying to record an screencast, means that the shell simply outputs a 0-byte .webm file on disk, while spitting the following messages in the output: * When starting to record (first time you press "Ctrl+Shift+Alt+R"): ** (eos-shell:18509): WARNING **: Error in recording pipeline: Failed to encode frame * When stopping the recording (second time you press "Ctrl+Shift+Alt+R"): ** (eos-shell:18509): CRITICAL **: shell_recorder_close: assertion 'recorder->state != RECORDER_STATE_CLOSED' failed Notice that, besides using our custom fork of gnome-shell, I'm currently using unmodified packages from debian for gstreamer and libvpx: libvpx3:i386 1.5.0-2 gir1.2-gst-plugins-base-1.0 1.8.1-1 gir1.2-gstreamer-1.0 1.8.1-1 gstreamer1.0-alsa:i386 1.8.1-1 gstreamer1.0-plugins-base:i386 1.8.1-1 gstreamer1.0-plugins-base-apps 1.8.1-1 gstreamer1.0-plugins-good:i386 1.8.1-1 gstreamer1.0-pulseaudio:i386 1.8.1-1 gstreamer1.0-tools 1.8.1-1 gstreamer1.0-x:i386 1.8.1-1 libgstreamer-plugins-base1.0-0:i386 1.8.1-1 libgstreamer1.0-0:i386 1.8.1-1 Doing some experiments, I found out something a bit strange that could be a clue: I can reliably AVOID the issue when running with GST_DEBUG >= 5, meaning that the following would allow me to record a screencast: $ GST_DEBUG=5 eos-shell --replace ..while this will 99% of the times expose the issue (sometimes works -not very often- works, though): $ GST_DEBUG=4 eos-shell --replace So, I did some digging and dumped the output from those two cases to a text file, massaged a bit the output to be easier to diff (removed DEBUG lines from the first case, timestamps, hexadecimal values...), and I found the following bits are ONLY present in the failing scenario with GST_DEBUG < 5 (full diff attached to this bug description): WARN vpxenc gstvpxenc.c:1904:gst_vpx_enc_handle_frame:<vp8enc0> error: Failed to encode frame WARN vpxenc gstvpxenc.c:1904:gst_vpx_enc_handle_frame:<vp8enc0> error: invalid parameter INFO GST_ERROR_SYSTEM gstelement.c:1879:gst_element_message_full:<vp8enc0> posting message: Failed to encode frame INFO GST_ERROR_SYSTEM gstelement.c:1902:gst_element_message_full:<vp8enc0> posted error message: Failed to encode frame INFO basesrc gstbasesrc.c:2856:gst_base_src_loop:<shellrecordersrc0> pausing after gst_pad_push() = error WARN basesrc gstbasesrc.c:2948:gst_base_src_loop:<shellrecordersrc0> error: Internal data flow error. WARN basesrc gstbasesrc.c:2948:gst_base_src_loop:<shellrecordersrc0> error: streaming task paused, reason error (-5) INFO GST_ERROR_SYSTEM gstelement.c:1879:gst_element_message_full:<shellrecordersrc0> posting message: Internal data flow error. INFO GST_ERROR_SYSTEM gstelement.c:1902:gst_element_message_full:<shellrecordersrc0> posted error message: Internal data flow error. And investigating a bit the "invalid parameter" error with gdb I found that the problem seems to be happening in gst_vpx_enc_handle_frame(): In cases with GST_DEBUG < 5, the value of frame->duration is normally very small (e.g. 1140, 1875...) compared to the other scenario (e.g. 28262, 1408600...), which cause the call to gst_util_uint64_scale() to return 0 in the first case and something > 0 in the second. This seems to be the reason of the "invalid parameter" error, since vpx_codec_encode() will exit with VPX_CODEC_INVALID_PARAM in that case (see https://chromium.googlesource.com/webm/libvpx/+/master/vpx/src/vpx_encoder.c#208), which I guess is behind the problem. In case it's useful, I've also observed that, in my particular case the calls to gst_util_uint64_scale() always use the same numerator & denominator for the scale operation to be performed, so perhaps that's part of the issue? Perhaps those values need to be adjusted depending on the magnitude of the "duration" passed, so that we don't truncate to 0 too aggressively? If it helps, this is a snapshot of the calls to those functions from gdb, in both scenarios: * FAILING scenario (GST_DEBUG < 5): gst_util_uint64_scale (val=1875, num=90000, denom=1000000000) at gstutils.c:529 * OK scenario (GST_DEBUG >= 5): gst_util_uint64_scale (val=28262, num=90000, denom=1000000000) at gstutils.c:529 Last, to complete this massive report, I'm pasting below the output of the FAILING scenario when running it with GST_DEBUG=videoencoder:6, as requested by __tim in order to know what the incoming buffer timestamps/duration: DEBUG videoencoder gstvideoencoder.c:441:gst_video_encoder_init:<GstVideoEncoder@0xb1c0498> gst_video_encoder_init DEBUG videoencoder gstvideoencoder.c:1323:gst_video_encoder_src_query:<vp8enc0> received query 43523, caps LOG videoencoder gstvideoencoder.c:1260:gst_video_encoder_src_query_default:<vp8enc0> handling query: caps query: 0xb7378f0, GstQueryCaps, filter=(GstCaps)"NULL", caps=(GstCaps)"NULL"; DEBUG videoencoder gstvideoencoder.c:1323:gst_video_encoder_src_query:<vp8enc0> received query 43523, caps LOG videoencoder gstvideoencoder.c:1260:gst_video_encoder_src_query_default:<vp8enc0> handling query: caps query: 0xb7378f0, GstQueryCaps, filter=(GstCaps)"NULL", caps=(GstCaps)"NULL"; DEBUG videoencoder gstvideoencoder.c:1323:gst_video_encoder_src_query:<vp8enc0> received query 43523, caps LOG videoencoder gstvideoencoder.c:1260:gst_video_encoder_src_query_default:<vp8enc0> handling query: caps query: 0xb7378f0, GstQueryCaps, filter=(GstCaps)"NULL", caps=(GstCaps)"NULL"; DEBUG videoencoder gstvideoencoder.c:1323:gst_video_encoder_src_query:<vp8enc0> received query 43523, caps LOG videoencoder gstvideoencoder.c:1260:gst_video_encoder_src_query_default:<vp8enc0> handling query: caps query: 0xb737860, GstQueryCaps, filter=(GstCaps)"NULL", caps=(GstCaps)"NULL"; DEBUG videoencoder gstvideoencoder.c:866:gst_video_encoder_sink_query:<vp8enc0> received query 43523, caps LOG videoencoder gstvideoencoder.c:728:gst_video_encoder_sink_getcaps:<vp8enc0> Returning caps video/x-raw, width=(int)[ 16, 4096 ], height=(int)[ 16, 4096 ], framerate=(fraction)[ 0/1, 2147483647/1 ], format=(string)I420 DEBUG videoencoder gstvideoencoder.c:1178:gst_video_encoder_sink_event:<vp8enc0> received event 10254, stream-start DEBUG videoencoder gstvideoencoder.c:1080:gst_video_encoder_sink_event_default:<vp8enc0> STREAM_START, clearing upstream tags DEBUG videoencoder gstvideoencoder.c:866:gst_video_encoder_sink_query:<vp8enc0> received query 43523, caps LOG videoencoder gstvideoencoder.c:728:gst_video_encoder_sink_getcaps:<vp8enc0> Returning caps video/x-raw, width=(int)1024, height=(int)768, framerate=(fraction)30/1, format=(string)I420 DEBUG videoencoder gstvideoencoder.c:866:gst_video_encoder_sink_query:<vp8enc0> received query 40963, accept-caps DEBUG videoencoder gstvideoencoder.c:866:gst_video_encoder_sink_query:<vp8enc0> received query 40963, accept-caps DEBUG videoencoder gstvideoencoder.c:1178:gst_video_encoder_sink_event:<vp8enc0> received event 12814, caps DEBUG videoencoder gstvideoencoder.c:633:gst_video_encoder_setcaps:<vp8enc0> setcaps video/x-raw, width=(int)1024, height=(int)768, framerate=(fraction)30/1, format=(string)I420 DEBUG videoencoder gstvideoencoder.c:1323:gst_video_encoder_src_query:<vp8enc0> received query 43523, caps LOG videoencoder gstvideoencoder.c:1260:gst_video_encoder_src_query_default:<vp8enc0> handling query: caps query: 0xb6408f0, GstQueryCaps, filter=(GstCaps)"NULL", caps=(GstCaps)"NULL"; DEBUG videoencoder gstvideoencoder.c:1673:gst_video_encoder_negotiate_default:<vp8enc0> didn't get downstream ALLOCATION hints DEBUG videoencoder gstvideoencoder.c:1680:gst_video_encoder_negotiate_default:<vp8enc0> ALLOCATION (1) params: allocation query: 0xa8a1780, GstQueryAllocation, caps=(GstCaps)"video/x-vp8\,\ profile\=\(string\)0\,\ streamheader\=\(buffer\)\<\ 4f56503830010100040003000000010000010000001e00000001\ \>\,\ width\=\(int\)1024\,\ height\=\(int\)768\,\ pixel-aspect-ratio\=\(fraction\)1/1\,\ framerate\=\(fraction\)30/1", need-pool=(boolean)true, allocator=(GArray)NULL; DEBUG videoencoder gstvideoencoder.c:866:gst_video_encoder_sink_query:<vp8enc0> received query 35846, allocation DEBUG videoencoder gstvideoencoder.c:1178:gst_video_encoder_sink_event:<vp8enc0> received event 17934, segment DEBUG videoencoder gstvideoencoder.c:1035:gst_video_encoder_sink_event_default:<vp8enc0> segment time segment start=0:00:00.000000000, offset=0:00:00.000000000, stop=99:99:99.999999999, rate=1.000000, applied_rate=1.000000, flags=0x00, time=0:00:00.000000000, base=0:00:00.000000000, position 0:00:00.000000000, duration 99:99:99.999999999 LOG videoencoder gstvideoencoder.c:1391:gst_video_encoder_chain:<vp8enc0> received buffer of size 1179648 with PTS 0:00:00.002575000, DTS 99:99:99.999999999, duration 0:00:00.000002132 LOG videoencoder gstvideoencoder.c:1478:gst_video_encoder_chain:<vp8enc0> passing frame pfn 0 to subclass DEBUG videoencoder gstvideoencoder.c:1178:gst_video_encoder_sink_event:<vp8enc0> received event 28174, eos DEBUG videoencoder gstvideoencoder.c:1323:gst_video_encoder_src_query:<vp8enc0> received query 5123, duration LOG videoencoder gstvideoencoder.c:1260:gst_video_encoder_src_query_default:<vp8enc0> handling query: duration query: 0xeeb58b50, GstQueryDuration, format=(GstFormat)GST_FORMAT_TIME, duration=(gint64)-1; DEBUG videoencoder gstvideoencoder.c:879:gst_video_encoder_finalize:<vp8enc0> finalize Thanks for helping and congratulations for making it all the way down here! :)
So the first question would be if such a small duration is actually correct here. Are you really capturing with such a high framerate and also want to record it like that? My guess is that those duration values are wrong to begin with. Then in vpxenc we should catch the 0 duration and do something about it, e.g. replacing it by 1 or erroring out in a more meaningful way. For the rate, there's the timebase property on vpxenc that you can use to manually set it. It defaults to 90000 because that's usually a good default for various reasons.
I'm not explicitly doing anything in any particular way so I can't really answer that question. This is the shell using gstreamer to record the screencast, so I suppose I'll have to look in there for the answer. Any particular pointer on where to look at, or what to search for?
Check where the durations come from. 1875 nanoseconds seems very short for a frame duration :)
Thanks, that was very helpful. I think I found the issue, or at least how to fix it: looks like all we need is to cherry-pick this commit from Wim: https://git.gnome.org/browse/gnome-shell/commit/?id=43ae3b8140f0052b43a8d95c2d9d8f4b6f6dd4af Applying that on top of our old shell seems to fix things, at least with my current Frankenstein-EOS with manually built installations of gstreamer, libvpx and other things. Will try with a pristine VM and get back here with extra...
We should still catch the case in vpxenc and at least log a warning in the debug log.
Yes, just checking for 0 there and do something with it then instead of failing in a weird way.
Just ignoring the duration might be the best option, i.e. going the code path that we would without duration anyway.
Ignoring it in this corner case you mean, or in general? Not sure we should ignore it in general, it's valuable info for the bitrate estimation engine I suppose?
Ignoring it if it ends up being 0 after scaling
(In reply to Tim-Philipp Müller from comment #5) > We should still catch the case in vpxenc and at least log a warning in the > debug log. Quick question, since I'm pretty new to this: what would you use for domain/code? I'm hesitating between STREAM/FORMAT and CORE/CLOCK but I kind of miss context to decide which one is the right one.
You're probably looking at GST_ELEMENT_WARNING(), I was thinking of just a line in the debug log, like GST_WARNING_OBJECT (encoder, "ignoring super small duration %" GST_TIME_FORMAT, GST_TIME_ARGS (GST_BUFFER_DURATION (buffer)); or somesuch.
Yes, I was looking into GST_ELEMENT_WARNING() but I suppose I can use GST_WARNING_OBJECT, thanks for the tip. The only doubt I have now is about only showing it in the debug log: since this particular case does not happen with GST_DEBUG < 5, wouldn't the message never show up in the logs if we make it debug-only? For reference, and at risk of being totallywrong, this is what I had and was about to try now (building), which is probably wrong anyway: GST_ELEMENT_WARNING (encoder, STREAM, FORMAT, ("Too small value for frame duration. Ignoring..."), ("Too small value for frame duration, truncated to zero after" " scaling (original value: %llu). Ignoring...", frame->duration));
Forget it. I've just tested what you suggested and can clearly see the message when running with GST_DEBUG=4: 0:00:00.174721955 14931 0x92902c0 WARN vpxenc gstvpxenc.c:1899:gst_vpx_enc_handle_frame:<vp8enc0> Ignoring too small frame duration 1294:00:00.150978384
Doesn't seem to print the duration value properly though..
(In reply to Tim-Philipp Müller from comment #14) > Doesn't seem to print the duration value properly though.. Another mistake: forgot to use GST_TIME_ARGS to format the value according to what GST_TIME_FORMAT expects. Looks better now: 0:00:00.162561108 21791 0xa2a4830 WARN vpxenc gstvpxenc.c:1899:gst_vpx_enc_handle_frame:<vp8enc0> Ignoring too small frame duration 0:00:00.000001760
Created attachment 326553 [details] [review] Patch proposal I've tested this patch in the very same VM where I reproduced the problem I reported here with the latest stable version of gstreamer from Debian sid (1.8.1), and verified that it fixes the problem with the shell's screen recording use case (tested without the patch from Wim mentioned in comment #4). Besides, it also prints the warning message in the log as suggested.
Thanks, pushed to master and 1.8 branch (might also pick into 1.6) ommit 87403135041470b4fa101dd2930777b6d3ea2cb6 Author: Mario Sanchez Prada <mario@endlessm.com> Date: Fri Apr 22 15:02:16 2016 +0100 vpxenc: Properly handle frames with too low duration When a frame's duration is too low, calling gst_util_uint64_scale() to scale its value can result into it being truncated to zero, which will cause the vpx encoder to return an VPX_CODEC_INVALID_PARAM error when trying to encode. To prevent this from happening, we simply ignore the duration when encoding if it becomes zero after scaling, logging a warning message. https://bugzilla.gnome.org/show_bug.cgi?id=765391
Thanks, I'll make sure we backport it downstream too anyway in the meantime