GNOME Bugzilla – Bug 765456
vtdec: Strange bug re-encoding video with GST 1.8.1 on Mac OS 10.10
Last modified: 2016-05-06 06:49:14 UTC
GST 1.8.1 on Mac OS 10.10 Here are commands for copy-and-copy-again of a video: gst-launch-1.0 filesrc location=Bear.wmv ! decodebin ! videoconvert ! x264enc bitrate=1280 ! mp4mux ! filesink location=out1.mp4 gst-launch-1.0 filesrc location=out1.mp4 ! decodebin ! videoconvert ! x264enc bitrate=1280 ! mp4mux ! filesink location=out2.mp4 On Windows 10, GST 1.8.1, this works fine. But on Mac OS 10.10 the first copy succeeds but the second one produces this: Setting pipeline to PAUSED ... Pipeline is PREROLLING ... Redistribute latency... Got context from element 'vtdechw0': gst.gl.GLDisplay=context, gst.gl.GLDisplay=(GstGLDisplay)"\(GstGLDisplayCocoa\)\ gldisplaycocoa0"; ERROR: from element /GstPipeline:pipeline0/GstDecodeBin:decodebin0/GstQTDemux:qtdemux0: GStreamer encountered a general stream error. Additional debug info: qtdemux.c(5423): gst_qtdemux_loop (): /GstPipeline:pipeline0/GstDecodeBin:decodebin0/GstQTDemux:qtdemux0: streaming stopped, reason not-negotiated ERROR: pipeline doesn't want to preroll. Setting pipeline to NULL ... Freeing pipeline ... For completeness I have placed the source file Bear.wmv here: http://www.seventhstring.com/other2/Bear.wmv though my impression is that this problem happens with pretty much any video. Using GST 1.6.3 there is again no problem on Windows but on Mac both copies appear to succeed: however the second copy won't play, QuickTime Player says the file is corrupt. Andy Robinson
Please try: gst-launch-1.0 videotestsrc num-buffers=600 ! x264enc bitrate=1280 ! mp4mux ! filesink location=out2.mp4 and gst-launch-1.0 videotestsrc num-buffers=600 ! x264enc bitrate=1280 ! video/x-h264,profile=main ! mp4mux ! filesink location=out2.mp4
And > gst-launch-1.0 filesrc location=out1.mp4 ! decodebin ! fakesink My guess is that this is related to vtdec usage on OSX. Can you also get a debug log with GST_DEBUG=3,vtdec:6 if the above already fails?
These two both work fine: gst-launch-1.0 videotestsrc num-buffers=600 ! x264enc bitrate=1280 ! mp4mux ! filesink location=out2.mp4 gst-launch-1.0 videotestsrc num-buffers=600 ! x264enc bitrate=1280 ! video/x-h264,profile=main ! mp4mux ! filesink location=out2.mp4 This fails as before on the 2nd copy: gst-launch-1.0 filesrc location=Bear.wmv ! decodebin ! videoconvert ! x264enc bitrate=1280 ! video/x-h264,profile=main ! mp4mux ! filesink location=out1.mp4 gst-launch-1.0 filesrc location=out1.mp4 ! decodebin ! videoconvert ! x264enc bitrate=1280 ! video/x-h264,profile=main ! mp4mux ! filesink location=out2.mp4 To my surprise this works, using videotestsrc instead of a video file, both copies are good: gst-launch-1.0 videotestsrc num-buffers=600 ! x264enc bitrate=1280 ! mp4mux ! filesink location=out1.mp4 gst-launch-1.0 filesrc location=out1.mp4 ! decodebin ! videoconvert ! x264enc bitrate=1280 ! mp4mux ! filesink location=out2.mp4 This crashes on the 2nd command: gst-launch-1.0 filesrc location=Bear.wmv ! decodebin ! videoconvert ! x264enc bitrate=1280 ! mp4mux ! filesink location=out1.mp4 gst-launch-1.0 filesrc location=out1.mp4 ! decodebin ! fakesink Here is the output from the 2nd command: gst-launch-1.0 filesrc location=out1.mp4 ! decodebin ! fakesink Setting pipeline to PAUSED ... Pipeline is PREROLLING ... Redistribute latency... Got context from element 'vtdechw0': gst.gl.GLDisplay=context, gst.gl.GLDisplay=(GstGLDisplay)"\(GstGLDisplayCocoa\)\ gldisplaycocoa0"; Pipeline is PREROLLED ... Setting pipeline to PLAYING ... New clock: GstSystemClock Caught SIGSEGV exec gdb failed: No such file or directory Spinning. Please run 'gdb gst-launch-1.0 1895' to continue debugging, Ctrl-C to quit, or Ctrl-\ to dump core. And here is that second command again, with debug log: Andys-MacBook-Pro:Temp1 andy$ export GST_DEBUG=3,vtdec:6 Andys-MacBook-Pro:Temp1 andy$ gst-launch-1.0 filesrc location=out1.mp4 ! decodebin ! fakesink Setting pipeline to PAUSED ... 0:00:00.021891000 1909 0x7fe9badb1890 WARN basesrc gstbasesrc.c:3486:void gst_base_src_start_complete(GstBaseSrc *, GstFlowReturn):<filesrc0> pad not activated yet Pipeline is PREROLLING ... 0:00:00.028758000 1909 0x7fe9bd005d40 WARN qtdemux qtdemux.c:2642:qtdemux_parse_trex:<qtdemux0> failed to find fragment defaults for stream 1 0:00:00.028914000 1909 0x7fe9bd005d40 WARN basesrc gstbasesrc.c:2396:gboolean gst_base_src_update_length(GstBaseSrc *, guint64, guint *, gboolean):<filesrc0> processing at or past EOS 0:00:00.034947000 1909 0x7fe9bc00c8a0 DEBUG vtdec vtdec.c:179:gst_vtdec_start:<vtdechw0> start 0:00:00.034971000 1909 0x7fe9bc00c8a0 FIXME videodecoder gstvideodecoder.c:1057:GstFlowReturn gst_video_decoder_drain_out(GstVideoDecoder *, gboolean):<vtdechw0> Sub-class should implement drain() 0:00:00.035147000 1909 0x7fe9bc00c8a0 DEBUG vtdec vtdec.c:318:gst_vtdec_set_format:<vtdechw0> set_format 0:00:00.035168000 1909 0x7fe9bc00c8a0 INFO vtdec vtdec.c:941:compute_h264_decode_picture_buffer_length:<vtdechw0> parsed profile 100, level 30 0:00:00.035186000 1909 0x7fe9bc00c8a0 INFO vtdec vtdec.c:977:gst_vtdec_set_latency:<vtdechw0> setting latency frames:6 time:0:00:00.200199996 0:00:00.035286000 1909 0x7fe9bc00c8a0 INFO vtdec vtdec.c:271:gst_vtdec_negotiate:<vtdechw0> negotiated output format video/x-raw(memory:GLMemory), format=(string)NV12, width=(int)720, height=(int)480, interlace-mode=(string)progressive, pixel-aspect-ratio=(fraction)8/9, chroma-site=(string)jpeg, colorimetry=(string)bt601, framerate=(fraction)30000/1001, texture-target=(string)rectangle Redistribute latency... 0:00:00.056271000 1909 0x7fe9bc00c8a0 INFO vtdec vtdec.c:987:gst_vtdec_set_context:<vtdechw0> setting context gst.gl.GLDisplay Got context from element 'vtdechw0': gst.gl.GLDisplay=context, gst.gl.GLDisplay=(GstGLDisplay)"\(GstGLDisplayCocoa\)\ gldisplaycocoa0"; 0:00:00.066304000 1909 0x7fe9bc00c8a0 INFO vtdec vtdec.c:289:gst_vtdec_negotiate:<vtdechw0> pushing textures, context 0x7fe9bb8139d0 old context 0x0 0:00:00.066570000 1909 0x7fe9bc00c8a0 FIXME videodecoder gstvideodecoder.c:1057:GstFlowReturn gst_video_decoder_drain_out(GstVideoDecoder *, gboolean):<vtdechw0> Sub-class should implement drain() 0:00:00.067007000 1909 0x7fe9bc00c8a0 LOG vtdec vtdec.c:402:gst_vtdec_handle_frame:<vtdechw0> got input frame 0 0:00:00.067859000 1909 0x7fe9bc00c8a0 LOG vtdec vtdec.c:423:gst_vtdec_handle_frame:<vtdechw0> submitted input frame 0 0:00:00.067935000 1909 0x7fe9bc00c8a0 LOG vtdec vtdec.c:402:gst_vtdec_handle_frame:<vtdechw0> got input frame 1 0:00:00.068243000 1909 0x7fe9bc00c8a0 LOG vtdec vtdec.c:423:gst_vtdec_handle_frame:<vtdechw0> submitted input frame 1 0:00:00.068288000 1909 0x7fe9bc00c8a0 LOG vtdec vtdec.c:402:gst_vtdec_handle_frame:<vtdechw0> got input frame 2 0:00:00.068552000 1909 0x7fe9bc00c8a0 LOG vtdec vtdec.c:423:gst_vtdec_handle_frame:<vtdechw0> submitted input frame 2 0:00:00.068597000 1909 0x7fe9bc00c8a0 LOG vtdec vtdec.c:402:gst_vtdec_handle_frame:<vtdechw0> got input frame 3 0:00:00.068803000 1909 0x7fe9badde040 LOG vtdec vtdec.c:731:gst_vtdec_session_output_callback:<vtdechw0> got output frame 0x7fe9bf004d70 0 and VT buffer 0x7fe9bac80bb0 0:00:00.069107000 1909 0x7fe9bc00c8a0 LOG vtdec vtdec.c:423:gst_vtdec_handle_frame:<vtdechw0> submitted input frame 3 0:00:00.069149000 1909 0x7fe9bc00c8a0 LOG vtdec vtdec.c:402:gst_vtdec_handle_frame:<vtdechw0> got input frame 4 0:00:00.069441000 1909 0x7fe9badde040 LOG vtdec vtdec.c:731:gst_vtdec_session_output_callback:<vtdechw0> got output frame 0x7fe9bb07a660 1 and VT buffer 0x7fe9bac90280 0:00:00.069473000 1909 0x7fe9bc00c8a0 LOG vtdec vtdec.c:423:gst_vtdec_handle_frame:<vtdechw0> submitted input frame 4 0:00:00.069541000 1909 0x7fe9bc00c8a0 LOG vtdec vtdec.c:402:gst_vtdec_handle_frame:<vtdechw0> got input frame 5 0:00:00.069881000 1909 0x7fe9badde040 LOG vtdec vtdec.c:731:gst_vtdec_session_output_callback:<vtdechw0> got output frame 0x7fe9bf004e80 2 and VT buffer 0x7fe9bac908b0 0:00:00.069919000 1909 0x7fe9bc00c8a0 LOG vtdec vtdec.c:423:gst_vtdec_handle_frame:<vtdechw0> submitted input frame 5 0:00:00.069981000 1909 0x7fe9bc00c8a0 LOG vtdec vtdec.c:402:gst_vtdec_handle_frame:<vtdechw0> got input frame 6 0:00:00.070343000 1909 0x7fe9badde040 LOG vtdec vtdec.c:731:gst_vtdec_session_output_callback:<vtdechw0> got output frame 0x7fe9bf004c60 3 and VT buffer 0x7fe9bc832df0 0:00:00.070379000 1909 0x7fe9bc00c8a0 LOG vtdec vtdec.c:423:gst_vtdec_handle_frame:<vtdechw0> submitted input frame 6 0:00:00.070467000 1909 0x7fe9bc00c8a0 LOG vtdec vtdec.c:402:gst_vtdec_handle_frame:<vtdechw0> got input frame 7 0:00:00.070695000 1909 0x7fe9badde040 LOG vtdec vtdec.c:731:gst_vtdec_session_output_callback:<vtdechw0> got output frame 0x7fe9bb07a990 4 and VT buffer 0x7fe9bae31ff0 0:00:00.070923000 1909 0x7fe9bc00c8a0 LOG vtdec vtdec.c:423:gst_vtdec_handle_frame:<vtdechw0> submitted input frame 7 0:00:00.071001000 1909 0x7fe9bc00c8a0 LOG vtdec vtdec.c:402:gst_vtdec_handle_frame:<vtdechw0> got input frame 8 0:00:00.071445000 1909 0x7fe9badde040 LOG vtdec vtdec.c:731:gst_vtdec_session_output_callback:<vtdechw0> got output frame 0x7fe9bb07add0 5 and VT buffer 0x7fe9bca07b80 0:00:00.071486000 1909 0x7fe9bc00c8a0 LOG vtdec vtdec.c:423:gst_vtdec_handle_frame:<vtdechw0> submitted input frame 8 0:00:00.071644000 1909 0x7fe9bc00c8a0 LOG vtdec vtdec.c:402:gst_vtdec_handle_frame:<vtdechw0> got input frame 9 0:00:00.071826000 1909 0x7fe9badde040 LOG vtdec vtdec.c:731:gst_vtdec_session_output_callback:<vtdechw0> got output frame 0x7fe9bf0081a0 6 and VT buffer 0x7fe9bc9015f0 0:00:00.072318000 1909 0x7fe9badde040 LOG vtdec vtdec.c:731:gst_vtdec_session_output_callback:<vtdechw0> got output frame 0x7fe9bf0084d0 7 and VT buffer 0x7fe9bc832bf0 0:00:00.072684000 1909 0x7fe9badde040 LOG vtdec vtdec.c:731:gst_vtdec_session_output_callback:<vtdechw0> got output frame 0x7fe9bb07abb0 8 and VT buffer 0x7fe9bae33c20 (gst-launch-1.0:1909): GStreamer-CRITICAL **: gst_debug_log_valist: assertion 'category != NULL' failed Pipeline is PREROLLED ... Setting pipeline to PLAYING ... New clock: GstSystemClock 0:00:00.103659000 1909 0x7fe9bc00c8a0 INFO vtdec vtdec.c:289:gst_vtdec_negotiate:<vtdechw0> pushing textures, context 0x7fe9bb8139d0 old context 0x7fe9bb8139d0 Caught SIGSEGV exec gdb failed: No such file or directory Spinning. Please run 'gdb gst-launch-1.0 1909' to continue debugging, Ctrl-C to quit, or Ctrl-\ to dump core.
Ok so it's clearly related to the decoding with vtdec and not with the encoding afterwards (vtdec is used for H264 but not for WMV). Can you get a backtrace of the crash with the last pipeline, with gdb or lldb? It's also interesting that the case of decoding, reencoding and muxing errors out with a not-negotiated. Can you get a GST_DEBUG=6 log for that one? Please attach all debug logs to the bug, not inline into comments. Backtraces should go inline into comments though.
I've done a log with backtrace of the crash in bt1.txt which I willl attach. Here is the backtrace part of it: * frame #0: 0x00007fff978f035a libsystem_platform.dylib`OSAtomicAdd32Barrier$VARIANT$mp + 2 frame #1: 0x00007fff952b8709 IOSurface`IOSurfaceClientDecrementUseCount + 26 frame #2: 0x0000000105f99047 libgstapplemedia.so`_io_surface_memory_destroy + 39 frame #3: 0x0000000105fdaaa1 libgstgl-1.0.0.dylib`_destroy_gl_objects + 33 frame #4: 0x0000000105ff033d libgstgl-1.0.0.dylib`_run_message_sync + 29 frame #5: 0x0000000105ff02f7 libgstgl-1.0.0.dylib`_run_message_async + 23 frame #6: 0x000000010021f9c6 libglib-2.0.0.dylib`g_main_context_dispatch + 326 frame #7: 0x000000010021fcf4 libglib-2.0.0.dylib`g_main_context_iterate + 420 frame #8: 0x000000010022001f libglib-2.0.0.dylib`g_main_loop_run + 223 frame #9: 0x0000000105fd76af libgstgl-1.0.0.dylib`gst_gl_context_create_thread + 575 frame #10: 0x000000010024744a libglib-2.0.0.dylib`g_thread_proxy + 90 frame #11: 0x00007fff9790905a libsystem_pthread.dylib`_pthread_body + 131 frame #12: 0x00007fff97908fd7 libsystem_pthread.dylib`_pthread_start + 176 frame #13: 0x00007fff979063ed libsystem_pthread.dylib`thread_start + 13 The GST_DEBUG=6 log for the not-negotiated case is 42 MB, is it appropriate to attach something that big?
Created attachment 326597 [details] Log with backtrace of crash.
Please compress the debug log and if it's still too large, upload it to something like dropbox. The crash looks like some reference counting problem with the IOSurfaces
I've just done the GST_DEBUG=6 again and for some reason the output is smaller - only 9 MB, or 500 KB compressed, so I thing that means I can upload it here... (Result is still "not-negotiated").
Created attachment 326853 [details] Debug=6 log of not-negotiated case.
Created attachment 327259 [details] [review] Proposed fix As discussed on IRC, the problem is that vtdec configures GLMemory by default, then while it can renegotiate to sysmem, because decodebin exposes the pad too late renegotiation can't happen and we get not-negotiated. This change fixes it for me. Someone please double check before I commit. (Separately I now already made vtdec default to sysmem).
Review of attachment 327259 [details] [review]: Makes sense to me but seems like if it caused any problems before then this will still cause problems in a racy way. We might expose the pad before the first buffer, or not, depending on timing. ::: gst/playback/gstdecodebin2.c @@ +5064,3 @@ + + caps = gst_pad_get_current_caps (GST_PAD_CAST (endpad)); + has_fixed_caps = gst_caps_is_fixed (caps); Current caps are always fixed, they might just be NULL too. You can just check gst_pad_has_current_caps() here instead (and calling gst_caps_is_fixed(NULL) gives an assertion).
Created attachment 327267 [details] [review] decodebin: an element can negotiate before we block it When we initialize an element in decodebin, we 1) set it to PAUSED and push sticky events on its sinkpad to trigger negotiation 2) block its src pad(s) to detect CAPS events. We can't block before 1) as that would lead to a deadlock. It's possible (and common) tho that an element configures its srcpad during 1) and before 2). Therefore before this change we would typically block and expose an element's pad only once the element output its first buffer, triggering sticky events to be resent. One consequence of this behaviour is that it sometimes broke renegotiation. With this change now we consider a pad ready to be exposed when it's ->blocked or has fixed caps (which were set before we could block it).
The original bug should be fixed by https://cgit.freedesktop.org/gstreamer/gst-plugins-bad/commit/?id=5228238715a3d73bbfe9a7de1c02941096e95576
Attachment 327267 [details] pushed as fe4e9bb - decodebin: an element can negotiate before we block it
gst-validate is also happy about this, so let's get it in. Alessandro, the change in gst-plugins-bad should also go into 1.8 I assume?
https://cgit.freedesktop.org/gstreamer/gst-plugins-bad/commit/?id=5228238715a3d73bbfe9a7de1c02941096e95576 is backported to 1.8.2 now