GNOME Bugzilla – Bug 774332
Latency tracer fails when asserting on GST_IS_EVENT (event)
Last modified: 2016-12-07 20:56:02 UTC
Using GST_TRACERS=latency with gst-play (with playbin2 or playbin3) throws gst_mini_obbject_unref assertion fail. Here a snippet: $ USE_PLAYBIN3=1 GST_DEBUG="GST_TRACER:7" GST_TRACERS=latency gst-play-1.0 file:///home/francisv/media/Hydrate-Kenny_Beltrey.ogg 0:00:00.058056360 811 0x1f9c750 DEBUG GST_TRACER gsttracer.c:163:gst_tracer_register:<registry0> update existing feature 0x1db21c0 (latency) 0:00:00.058127640 811 0x1f9c750 DEBUG GST_TRACER gsttracer.c:163:gst_tracer_register:<registry0> update existing feature 0x1db2280 (log) 0:00:00.058148160 811 0x1f9c750 DEBUG GST_TRACER gsttracer.c:163:gst_tracer_register:<registry0> update existing feature 0x1db2340 (rusage) 0:00:00.058165760 811 0x1f9c750 DEBUG GST_TRACER gsttracer.c:163:gst_tracer_register:<registry0> update existing feature 0x1db2400 (stats) 0:00:00.058182880 811 0x1f9c750 DEBUG GST_TRACER gsttracer.c:163:gst_tracer_register:<registry0> update existing feature 0x1db24c0 (leaks) 0:00:00.058251760 811 0x1f9c750 TRACE GST_TRACER gsttracerrecord.c:110:gst_tracer_record_build_format: latency.class, src=(structure)"scope\,\ type\=\(GType\)NULL\,\ related-to\=\(GstTracerValueScope\)GST_TRACER_VALUE_SCOPE_PAD\;", sink=(structure)"scope\,\ type\=\(GType\)NULL\,\ related-to\=\(GstTracerValueScope\)GST_TRACER_VALUE_SCOPE_PAD\;", time=(structure)"value\,\ type\=\(GType\)NULL\,\ description\=\(string\)\"time\\\ it\\\ took\\\ for\\\ the\\\ buffer\\\ to\\\ go\\\ from\\\ src\\\ to\\\ sink\\\ ns\"\,\ flags\=\(GstTracerValueFlags\)GST_TRACER_VALUE_FLAGS_AGGREGATED\,\ min\=\(guint64\)0\,\ max\=\(guint64\)18446744073709551615\;"; 0:00:00.058318520 811 0x1f9c750 DEBUG GST_TRACER gsttracerrecord.c:124:gst_tracer_record_build_format: new format string: latency, src=(string)%s, sink=(string)%s, time=(guint64)%lu; Press 'k' to see a list of keyboard shortcuts. Now playing /home/francisv/media/Hydrate-Kenny_Beltrey.ogg Redistribute latency... 0:00:00.154579720 811 0x7fb13807d370 TRACE GST_TRACER :0:: latency, src=(string)source_src, sink=(string)audiosink-actual-sink-pulse_sink, time=(guint64)76523480; (gst-play-1.0:811): GStreamer-CRITICAL **: gst_event_get_structure: assertion 'GST_IS_EVENT (event)' failed (gst-play-1.0:811): GStreamer-CRITICAL **: gst_structure_id_get: assertion 'GST_IS_STRUCTURE (structure)' failed 0:00:00.154707920 811 0x7fb13807d370 TRACE GST_TRACER :0:: latency, src=(string)''_'', sink=(string)audiosink-actual-sink-pulse_sink, time=(guint64)18446603674379275032; (gst-play-1.0:811): GStreamer-CRITICAL **: gst_mini_object_unref: assertion 'mini_object->refcount > 0' failed (gst-play-1.0:811): GStreamer-CRITICAL **: gst_event_get_structure: assertion 'GST_IS_EVENT (event)' failed (gst-play-1.0:811): GStreamer-CRITICAL **: gst_structure_id_get: assertion 'GST_IS_STRUCTURE (structure)' failed 0:00:00.154936720 811 0x7fb13807d370 TRACE GST_TRACER :0:: latency, src=(string)''_'', sink=(string)audiosink-actual-sink-pulse_sink, time=(guint64)18446603674400764363; (gst-play-1.0:811): GStreamer-CRITICAL **: gst_mini_object_unref: assertion 'mini_object->refcount > 0' failed (gst-play-1.0:811): GStreamer-CRITICAL **: gst_event_get_structure: assertion 'GST_IS_EVENT (event)' failed (gst-play-1.0:811): GStreamer-CRITICAL **: gst_structure_id_get: assertion 'GST_IS_STRUCTURE (structure)' failed 0:00:00.155028520 811 0x7fb13807d370 TRACE GST_TRACER :0:: latency, src=(string)''_'', sink=(string)audiosink-actual-sink-pulse_sink, time=(guint64)18446603674400856723; (gst-play-1.0:811): GStreamer-CRITICAL **: gst_mini_object_unref: assertion 'mini_object->refcount > 0' failed ... This issue does not occur with tracers: leaks, log, rusage, and stats.
This is weird memory management in the latency tracer, or assumptions it makes are not true. Something's clearly not right.
Just tried and it works for me :/ Could you please retry as below: G_DEBUG="fatal-criticals" USE_PLAYBIN3=1 GST_DEBUG="GST_TRACER:7" GST_TRACERS=latency gdb --args gst-play-1.0 file:///home/francisv/media/Hydrate-Kenny_Beltrey.ogg Inside gdb, type "r" for "run". Once the error happens the program will be terminated. Then type "bt" to get a backtrace. Copy and paste this here. Thanks!
francisv@francisv-MacBookPro:~/gst/master$ G_DEBUG="fatal-criticals" USE_PLAYBIN3=1 GST_DEBUG="GST_TRACER:7" GST_TRACERS=latency gdb -q --args /home/francisv/gst/master/gst-plugins-base/tools/.libs/gst-play-1.0 file:///home/francisv/media/Hydrate-Kenny_Beltrey.ogg Reading symbols from /home/francisv/gst/master/gst-plugins-base/tools/.libs/gst-play-1.0...done. (gdb) r Starting program: /home/francisv/gst/master/gst-plugins-base/tools/.libs/gst-play-1.0 file:///home/francisv/media/Hydrate-Kenny_Beltrey.ogg [Thread debugging using libthread_db enabled] Using host libthread_db library "/lib/x86_64-linux-gnu/libthread_db.so.1". 0:00:00.070111480 6669 0x813840 DEBUG GST_TRACER gsttracer.c:163:gst_tracer_register:<registry0> update existing feature 0x61f1c0 (latency) 0:00:00.070209160 6669 0x813840 DEBUG GST_TRACER gsttracer.c:163:gst_tracer_register:<registry0> update existing feature 0x61f280 (log) 0:00:00.070339480 6669 0x813840 DEBUG GST_TRACER gsttracer.c:163:gst_tracer_register:<registry0> update existing feature 0x61f340 (rusage) 0:00:00.070370680 6669 0x813840 DEBUG GST_TRACER gsttracer.c:163:gst_tracer_register:<registry0> update existing feature 0x61f400 (stats) 0:00:00.070399840 6669 0x813840 DEBUG GST_TRACER gsttracer.c:163:gst_tracer_register:<registry0> update existing feature 0x61f4c0 (leaks) 0:00:00.070500560 6669 0x813840 TRACE GST_TRACER gsttracerrecord.c:110:gst_tracer_record_build_format: latency.class, src=(structure)"scope\,\ type\=\(GType\)NULL\,\ related-to\=\(GstTracerValueScope\)GST_TRACER_VALUE_SCOPE_PAD\;", sink=(structure)"scope\,\ type\=\(GType\)NULL\,\ related-to\=\(GstTracerValueScope\)GST_TRACER_VALUE_SCOPE_PAD\;", time=(structure)"value\,\ type\=\(GType\)NULL\,\ description\=\(string\)\"time\\\ it\\\ took\\\ for\\\ the\\\ buffer\\\ to\\\ go\\\ from\\\ src\\\ to\\\ sink\\\ ns\"\,\ flags\=\(GstTracerValueFlags\)GST_TRACER_VALUE_FLAGS_AGGREGATED\,\ min\=\(guint64\)0\,\ max\=\(guint64\)18446744073709551615\;"; 0:00:00.070605640 6669 0x813840 DEBUG GST_TRACER gsttracerrecord.c:124:gst_tracer_record_build_format: new format string: latency, src=(string)%s, sink=(string)%s, time=(guint64)%lu; Press 'k' to see a list of keyboard shortcuts. Now playing /home/francisv/media/Hydrate-Kenny_Beltrey.ogg [New Thread 0x7ffff4473700 (LWP 6673)] [New Thread 0x7ffff33fa700 (LWP 6674)] [New Thread 0x7ffff2bf9700 (LWP 6675)] [New Thread 0x7fffe3999700 (LWP 6676)] [New Thread 0x7fffdeb7f700 (LWP 6678)] Redistribute latency... [New Thread 0x7fffde37e700 (LWP 6679)] 0:00:00.276862200 6669 0x7fffe8049770 TRACE GST_TRACER :0:: latency, src=(string)source_src, sink=(string)audiosink-actual-sink-pulse_sink, time=(guint64)129491480; (gst-play-1.0:6669): GStreamer-CRITICAL **: gst_event_get_structure: assertion 'GST_IS_EVENT (event)' failed Program received signal SIGTRAP, Trace/breakpoint trap.
+ Trace 236939
Thread 140736929986304 (LWP 6678)
commit cfb6c7d4f5f52b1a927f5c67c9b41bc868d114f8 Author: Stefan Sauer <ensonic@users.sf.net> Date: Wed Dec 7 21:53:49 2016 +0100 tracer/latency: clear qdata When reading the qdata, clear it to avoid it being read and unreffed again. Fixes #774332