GNOME Bugzilla – Bug 784383
GST_REFCOUNTING logging is not reliable
Last modified: 2017-07-15 10:59:41 UTC
It looks like GST_REFCOUNTING is not trustful. Here are some positive and negative examples: 0:17:04.750351068 12592 0000000018455A40 TRACE GST_REFCOUNTING gstminiobject.c:351:gst_mini_object_ref: 00000000186FE690 ref 0->1 0:17:04.780276938 12592 0000000018455B00 TRACE GST_REFCOUNTING gstminiobject.c:351:gst_mini_object_ref: 00000000186FE690 ref 1->2 0:17:04.820027254 12592 0000000018455B00 TRACE GST_REFCOUNTING gstminiobject.c:431:gst_mini_object_unref: 00000000186FE690 unref 2->1 0:17:04.820703683 12592 0000000018455B00 TRACE GST_REFCOUNTING gstminiobject.c:351:gst_mini_object_ref: 00000000186FE690 ref 1->2 0:17:04.821272539 12592 0000000018455B00 TRACE GST_REFCOUNTING gstminiobject.c:351:gst_mini_object_ref: 00000000186FE690 ref 2->3 0:17:04.821434809 12592 0000000018455B00 TRACE GST_REFCOUNTING gstminiobject.c:431:gst_mini_object_unref: 00000000186FE690 unref 3->2 0:17:04.821782687 12592 0000000018455B00 TRACE GST_REFCOUNTING gstminiobject.c:351:gst_mini_object_ref: 00000000186FE690 ref 2->3 0:17:04.822334405 12592 0000000018455B00 TRACE GST_REFCOUNTING gstminiobject.c:351:gst_mini_object_ref: 00000000186FE690 ref 3->4 0:17:04.822794595 12592 0000000018455B00 TRACE GST_REFCOUNTING gstminiobject.c:431:gst_mini_object_unref: 00000000186FE690 unref 4->3 0:17:04.823494362 12592 0000000018455A40 TRACE GST_REFCOUNTING gstminiobject.c:351:gst_mini_object_ref: 00000000186FE690 ref 3->4 0:17:04.824251379 12592 0000000018455A40 TRACE GST_REFCOUNTING gstminiobject.c:351:gst_mini_object_ref: 00000000186FE690 ref 4->5 0:17:04.824339989 12592 0000000018455A40 TRACE GST_REFCOUNTING gstminiobject.c:351:gst_mini_object_ref: 00000000186FE690 ref 5->6 0:17:04.824508458 12592 0000000018455A40 TRACE GST_REFCOUNTING gstminiobject.c:431:gst_mini_object_unref: 00000000186FE690 unref 6->5 0:17:04.826198619 12592 0000000018455A40 TRACE GST_REFCOUNTING gstminiobject.c:431:gst_mini_object_unref: 00000000186FE690 unref 5->4 0:17:04.826353960 12592 0000000018455A40 TRACE GST_REFCOUNTING gstminiobject.c:431:gst_mini_object_unref: 00000000186FE690 unref 4->3 0:17:04.831242481 12592 0000000018455AC0 TRACE GST_REFCOUNTING gstminiobject.c:431:gst_mini_object_unref: 00000000186FE690 unref 3->2 0:17:04.846848115 12592 0000000018455A40 TRACE GST_REFCOUNTING gstminiobject.c:431:gst_mini_object_unref: 00000000186FE690 unref 2->1 0:17:05.035832498 12592 0000000032E5AD00 TRACE GST_REFCOUNTING gstminiobject.c:431:gst_mini_object_unref: 00000000186FE690 unref 1->0 Ok, looks good till here… 0:17:05.035941893 12592 0000000032E5AD00 TRACE GST_REFCOUNTING gstminiobject.c:351:gst_mini_object_ref: 00000000186FE690 ref 0->1 0:17:05.054755003 12592 0000000018455B00 TRACE GST_REFCOUNTING gstminiobject.c:351:gst_mini_object_ref: 00000000186FE690 ref 1->2 0:17:05.073715067 12592 0000000018455B00 TRACE GST_REFCOUNTING gstminiobject.c:431:gst_mini_object_unref: 00000000186FE690 unref 2->1 0:17:05.074437442 12592 0000000018455B00 TRACE GST_REFCOUNTING gstminiobject.c:351:gst_mini_object_ref: 00000000186FE690 ref 1->2 0:17:05.075212692 12592 0000000018455B00 TRACE GST_REFCOUNTING gstminiobject.c:351:gst_mini_object_ref: 00000000186FE690 ref 2->3 0:17:05.075423096 12592 0000000018455B00 TRACE GST_REFCOUNTING gstminiobject.c:431:gst_mini_object_unref: 00000000186FE690 unref 3->2 0:17:05.075862501 12592 0000000018455B00 TRACE GST_REFCOUNTING gstminiobject.c:351:gst_mini_object_ref: 00000000186FE690 ref 2->3 0:17:05.076973960 12592 0000000018455B00 TRACE GST_REFCOUNTING gstminiobject.c:351:gst_mini_object_ref: 00000000186FE690 ref 3->4 0:17:05.077487024 12592 0000000018455B00 TRACE GST_REFCOUNTING gstminiobject.c:431:gst_mini_object_unref: 00000000186FE690 unref 4->3 0:17:05.077946121 12592 0000000018455B00 TRACE GST_REFCOUNTING gstminiobject.c:431:gst_mini_object_unref: 00000000186FE690 unref 3->2 0:17:05.095318127 12592 0000000018455A40 TRACE GST_REFCOUNTING gstminiobject.c:351:gst_mini_object_ref: 00000000186FE690 ref 2->3 0:17:05.096015341 12592 0000000018455A40 TRACE GST_REFCOUNTING gstminiobject.c:351:gst_mini_object_ref: 00000000186FE690 ref 3->4 0:17:05.096135676 12592 0000000018455A40 TRACE GST_REFCOUNTING gstminiobject.c:351:gst_mini_object_ref: 00000000186FE690 ref 4->5 0:17:05.096370877 12592 0000000018455A40 TRACE GST_REFCOUNTING gstminiobject.c:431:gst_mini_object_unref: 00000000186FE690 unref 5->4 0:17:05.096670620 12592 0000000018455A40 TRACE GST_REFCOUNTING gstminiobject.c:431:gst_mini_object_unref: 00000000186FE690 unref 4->3 0:17:05.096882118 12592 0000000018455A40 TRACE GST_REFCOUNTING gstminiobject.c:431:gst_mini_object_unref: 00000000186FE690 unref 3->2 Ok, still looks good till here… 0:17:05.098080728 12592 0000000018455A40 TRACE GST_REFCOUNTING gstminiobject.c:431:gst_mini_object_unref: 00000000186FE690 unref 2->1 0:17:05.087528438 12592 0000000018455AC0 TRACE GST_REFCOUNTING gstminiobject.c:431:gst_mini_object_unref: 00000000186FE690 unref 2->1 Two different threads, which both unref same object at the same time? Mutex not working??? Perhaps just debug output wrong, and we are now at value 0??? 0:17:05.103663546 12592 0000000018455AC0 TRACE GST_REFCOUNTING gstminiobject.c:351:gst_mini_object_ref: 00000000186FE690 ref 0->1 0:17:05.104035126 12592 0000000018455AC0 TRACE GST_REFCOUNTING gstminiobject.c:431:gst_mini_object_unref: 00000000186FE690 unref 1->0 0:17:14.963514410 12592 00000000328DF8C0 TRACE GST_REFCOUNTING gstminiobject.c:431:gst_mini_object_unref: 00000000186FE690 unref 1->0 0:17:15.294925179 12592 00000000328DF8C0 TRACE GST_REFCOUNTING gstminiobject.c:431:gst_mini_object_unref: 00000000186FE690 unref 1->0 0:17:15.298323368 12592 00000000328DF8C0 TRACE GST_REFCOUNTING gstminiobject.c:431:gst_mini_object_unref: 00000000186FE690 unref 1->0 0:17:15.938601043 12592 00000000328DF8C0 TRACE GST_REFCOUNTING gstminiobject.c:431:gst_mini_object_unref: 00000000186FE690 unref 1->0 0:17:16.004370715 12592 00000000328DF8C0 TRACE GST_REFCOUNTING gstminiobject.c:431:gst_mini_object_unref: 00000000186FE690 unref 1->0 A lot of time same object unref von 1 to 0??? But this is even from same thread? Counting backwards, we shall be at ref count 0 here.
> gstminiobject.c:431:gst_mini_object_unref: 00000000186FE690 unref 1->0 > 0:17:16.004370715 12592 00000000328DF8C0 TRACE GST_REFCOUNTING > gstminiobject.c:431:gst_mini_object_unref: 00000000186FE690 unref 1->0 > > A lot of time same object unref von 1 to 0??? > But this is even from same thread? Are you sure it's the *same* object? It's very possible that it was freed and the previous allocation slice is then re-used for a new mini object.
Similar code in 1.12.1 and 1.12.0, analysis based on 1.12.0. GstMiniObject * gst_mini_object_ref (GstMiniObject * mini_object) { g_return_val_if_fail (mini_object != NULL, NULL); /* we can't assert that the refcount > 0 since the _free functions * increments the refcount from 0 to 1 again to allow resurecting * the object g_return_val_if_fail (mini_object->refcount > 0, NULL); */ GST_TRACER_MINI_OBJECT_REFFED (mini_object, mini_object->refcount + 1); GST_CAT_TRACE (GST_CAT_REFCOUNTING, "%p ref %d->%d", mini_object, GST_MINI_OBJECT_REFCOUNT_VALUE (mini_object), GST_MINI_OBJECT_REFCOUNT_VALUE (mini_object) + 1); g_atomic_int_inc (&mini_object->refcount); return mini_object; } Debug Output is before semaphore/atomic int operation. If 2 threads reach this function, both time the same counter is displayed, even when second caller has to wait till integer is free to access again. void gst_mini_object_unref (GstMiniObject * mini_object) { g_return_if_fail (mini_object != NULL); GST_CAT_TRACE (GST_CAT_REFCOUNTING, "%p unref %d->%d", mini_object, GST_MINI_OBJECT_REFCOUNT_VALUE (mini_object), GST_MINI_OBJECT_REFCOUNT_VALUE (mini_object) - 1); g_return_if_fail (mini_object->refcount > 0); if (G_UNLIKELY (g_atomic_int_dec_and_test (&mini_object->refcount))) { gboolean do_free; GST_TRACER_MINI_OBJECT_UNREFFED (mini_object, mini_object->refcount); if (mini_object->dispose) do_free = mini_object->dispose (mini_object); else do_free = TRUE; /* if the subclass recycled the object (and returned FALSE) we don't * want to free the instance anymore */ if (G_LIKELY (do_free)) { /* there should be no outstanding locks */ g_return_if_fail ((g_atomic_int_get (&mini_object->lockstate) & LOCK_MASK) < 4); if (mini_object->n_qdata) { call_finalize_notify (mini_object); g_free (mini_object->qdata); } GST_TRACER_MINI_OBJECT_DESTROYED (mini_object); if (mini_object->free) mini_object->free (mini_object); } } else { GST_TRACER_MINI_OBJECT_UNREFFED (mini_object, mini_object->refcount); } } Same again here. Debug output is before atomic operation, not inside/part of atomic operation.
Too clarify: Bug report is about debug output, not the ref counting itself.
Looks like pooled object to me, nothing special.
Created attachment 354821 [details] [review] miniobject: make refcount tracing and debug logging reliable Proposed patch. This also affects the tracer hooks.
commit cce18426f756c0a17410020b0e5db06e7546257c Author: Tim-Philipp Müller <tim@centricular.com> Date: Mon Jul 3 09:03:24 2017 +0100 miniobject: make refcount tracing and debug logging reliable Tracing of the refcounts wasn't thread-safe, and log output of the refcount values before/after wasn't reliable. https://bugzilla.gnome.org/show_bug.cgi?id=784383
Need to add back a read-only guard in mini_object_unref() so we don't modify data if it's not kosher.
commit ea62c96b94272c974b2a92e6e4d2e759f14f3894 (HEAD -> master) Author: Tim-Philipp Müller <tim@centricular.com> Date: Sat Jul 15 11:54:18 2017 +0100 miniobject: don't modify memory if it's clearly not a valid miniobject Add back function guard that checks the refcount in a read-only operation first, and bail out without modifying the passed-in memory if it's clearly not a valid mini object. Otherwise we probably cause more harm than good. We keep the second sanity check based on the 'real refcount' at the time of the unref around for now too. https://bugzilla.gnome.org/show_bug.cgi?id=784383