After an evaluation, GNOME has moved from Bugzilla to GitLab. Learn more about GitLab.
No new issues can be reported in GNOME Bugzilla anymore.
To report an issue in a GNOME project, go to GNOME GitLab.
Do not go to GNOME Gitlab for: Bluefish, Doxygen, GnuCash, GStreamer, java-gnome, LDTP, NetworkManager, Tomboy.
Bug 774332 - Latency tracer fails when asserting on GST_IS_EVENT (event)
Latency tracer fails when asserting on GST_IS_EVENT (event)
Status: RESOLVED FIXED
Product: GStreamer
Classification: Platform
Component: gstreamer (core)
git master
Other Linux
: Normal normal
: 1.11.1
Assigned To: GStreamer Maintainers
GStreamer Maintainers
Depends on:
Blocks:
 
 
Reported: 2016-11-12 16:47 UTC by Francisco Velazquez
Modified: 2016-12-07 20:56 UTC
See Also:
GNOME target: ---
GNOME version: ---



Description Francisco Velazquez 2016-11-12 16:47:12 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.
Comment 1 Tim-Philipp Müller 2016-11-12 17:59:37 UTC
This is weird memory management in the latency tracer, or assumptions it makes are not true. Something's clearly not right.
Comment 2 Stefan Sauer (gstreamer, gtkdoc dev) 2016-12-07 20:17:48 UTC
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!
Comment 3 Francisco Velazquez 2016-12-07 20:23:05 UTC
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.

Thread 140736929986304 (LWP 6678)

  • #0 g_logv
    at /build/buildd/glib2.0-2.40.2/./glib/gmessages.c line 1038
  • #1 g_log
    at /build/buildd/glib2.0-2.40.2/./glib/gmessages.c line 1071
  • #2 gst_event_get_structure
    at gstevent.c line 344
  • #3 calculate_latency
    at gstlatency.c line 152
  • #4 do_push_buffer_post
    at gstlatency.c line 163
  • #5 gst_pad_push
    at gstpad.c line 4579
  • #6 gst_proxy_pad_chain_default
    at gstghostpad.c line 126
  • #7 gst_pad_chain_data_unchecked
    at gstpad.c line 4206
  • #8 gst_pad_push_data
    at gstpad.c line 4458
  • #9 gst_pad_push
    at gstpad.c line 4577
  • #10 gst_proxy_pad_chain_default
    at gstghostpad.c line 126
  • #11 gst_pad_chain_data_unchecked
    at gstpad.c line 4206
  • #12 gst_pad_push_data
    at gstpad.c line 4458
  • #13 gst_pad_push
    at gstpad.c line 4577
  • #14 gst_base_transform_chain
    at gstbasetransform.c line 2378
  • #15 gst_pad_chain_data_unchecked
    at gstpad.c line 4206
  • #16 gst_pad_push_data
    at gstpad.c line 4458
  • #17 gst_pad_push
    at gstpad.c line 4577
  • #18 gst_base_transform_chain
    at gstbasetransform.c line 2378
  • #19 gst_pad_chain_data_unchecked
    at gstpad.c line 4206
  • #20 gst_pad_push_data
    at gstpad.c line 4458
  • #21 gst_pad_push
    at gstpad.c line 4577
  • #22 gst_proxy_pad_chain_default
    at gstghostpad.c line 126
  • #23 gst_pad_chain_data_unchecked
    at gstpad.c line 4206
  • #24 gst_pad_push_data
    at gstpad.c line 4458
  • #25 gst_pad_push
    at gstpad.c line 4577
  • #26 gst_queue_push_one
    at gstqueue.c line 1359
  • #27 gst_queue_loop
    at gstqueue.c line 1506
  • #28 gst_task_func
    at gsttask.c line 334
  • #29 default_func
    at gsttaskpool.c line 68
  • #30 g_thread_pool_thread_proxy
    at /build/buildd/glib2.0-2.40.2/./glib/gthreadpool.c line 307
  • #31 g_thread_proxy
    at /build/buildd/glib2.0-2.40.2/./glib/gthread.c line 764
  • #32 start_thread
    at pthread_create.c line 312
  • #33 clone
    at ../sysdeps/unix/sysv/linux/x86_64/clone.S line 111

Comment 4 Stefan Sauer (gstreamer, gtkdoc dev) 2016-12-07 20:56:02 UTC
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