[Bug 765391] New: vpx plugin fails to encode frame if duration is too short (breaks gnome shell's screen recorder)
GStreamer (GNOME Bugzilla)
bugzilla at gnome.org
Thu Apr 21 18:33:38 UTC 2016
https://bugzilla.gnome.org/show_bug.cgi?id=765391
Bug ID: 765391
Summary: vpx plugin fails to encode frame if duration is too
short (breaks gnome shell's screen recorder)
Classification: Platform
Product: GStreamer
Version: 1.8.1
OS: Linux
Status: NEW
Severity: normal
Priority: Normal
Component: gst-plugins-good
Assignee: gstreamer-bugs at lists.freedesktop.org
Reporter: msanchez at gnome.org
QA Contact: gstreamer-bugs at lists.freedesktop.org
GNOME version: ---
Created attachment 326515
--> https://bugzilla.gnome.org/attachment.cgi?id=326515&action=edit
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 at 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! :)
--
You are receiving this mail because:
You are the QA Contact for the bug.
You are the assignee for the bug.
More information about the gstreamer-bugs
mailing list