[Bug 777399] v4l2allocator: memory referenced too late

Mon Jan 23 10:10:56 UTC 2017

https://bugzilla.gnome.org/show_bug.cgi?id=777399

--- Comment #5 from Jean-Christophe Trotin <jean-christophe.trotin at st.com> ---
I would like to clarify the scenario of the problem that I tried to describe in
my previous comment:

Preamble: this problem occurs during a simple video playback (gst-play-1.0
<video_stream>); an V4L2 video driver (HW accelerated decoder) is used; the
occurrence of the problem is low, but it's systematic with some streams; this
problem is due to concurrent threads, and thus it's very sensitive to the
real-time.

(1) A thread (let's name it TA) is blocked on VIDIOC_DQBUF ioctl
(gst_v4l2_allocator_dqbuf function ~line 1292) because there's no output buffer
available from the driver

(2) Another thread (let's name it TB) is queueing an output buffer (let's name
it B) in the same driver through VIDIOC_QBUF ioctl (gst_v4l2_allocator_qbuf
function ~line 1243).
At this time, the reference counter of the memory associated with the buffer B
is 1: GST_MINI_OBJECT_REFCOUNT_VALUE(GST_MINI_OBJECT_CAST(group->mem[i])) = 1

(3) In the thread TB context, the V4L2 decoder manages the queued buffer B,
decodes it and doesn't need it anymore
At this time, the reference counter of the memory associated with the buffer B
is still 1, since the following lines of code (gst_v4l2_allocator_qbuf()
function ~line 1265) haven't been executed yet:
  /* Ensure the memory will stay around and is RO */
  for (i = 0; i < group->n_mem; i++)
    gst_memory_ref (group->mem[i]);

(4) Thread switch from TB to TA

(5) The thread TA is unblocked (the buffer B is now available). The execution
of the gst_v4l2_allocator_dqbuf() function continues.
At this time, the reference counter of the memory associated with the buffer B
is still 1. The following lines of code (gst_v4l2_allocator_dqbuf() function
~line 1344) are executed:
  /* Release the memory, possibly making it RW again */
  for (i = 0; i < group->n_mem; i++)
    gst_memory_unref (group->mem[i]);

Then, the reference counter of the memory reaches 0, and the memory is released
through the gst_v4l2_allocator_release() function.

(6) Thread switch from TA to TB

(7) The thread TB continues. The following lines of code
(gst_v4l2_allocator_qbuf() function ~line 1265) are executed:
  /* Ensure the memory will stay around and is RO */
  for (i = 0; i < group->n_mem; i++)
    gst_memory_ref (group->mem[i]);

The problem here is that the memory has already been released, so group->mem[i]
has no meaning.

(8) Later, this situation leads to the following critical message raised by
GStreamer when trying to unreference the memory associated with the buffer B,
that has already been released:
(gst-play-1.0:18793): GStreamer-CRITICAL **: gst_mini_object_unref: assertion
'mini_object->refcount > 0' failed

I've encountered such situation on GStreamer v1.8.3, but since there was no
modification between v1.8.3 and v1.11.1 in gstv4l2allocator.c, I think that
this situation might also occur on last GStreamer version.
I've attached a patch that contains log messages (starting with "Bug 777399")
that I added in the gst_v4l2_allocator_qbuf() and gst_v4l2_allocator_dqbuf()
functions to ease this specific debug.
I've also attached an extract from a log file about this problem.
When there's no thread switch, there's no problem and the log messages sequence
is as follows:
0:00:02.371694899 11545   0x197920 LOG            v4l2allocator
gstv4l2allocator.c:1244:gst_v4l2_allocator_qbuf:<v4l2video3dec0:pool:src:allocator>
Bug 777399 mark 1 group->buffer.index 7, group->n_mem 1
0:00:02.371933566 11545   0x197920 LOG            v4l2allocator
gstv4l2allocator.c:1249:gst_v4l2_allocator_qbuf:<v4l2video3dec0:pool:src:allocator>
Bug 777399 mark 1 group->n_mem[0] 0x18f468 refcount 1
0:00:02.384750466 11545   0x197920 LOG            v4l2allocator
gstv4l2allocator.c:1264:gst_v4l2_allocator_qbuf:<v4l2video3dec0:pool:src:allocator>
queued buffer 7 (flags 0x4003)
0:00:02.385122699 11545   0x197920 LOG            v4l2allocator
gstv4l2allocator.c:1273:gst_v4l2_allocator_qbuf:<v4l2video3dec0:pool:src:allocator>
Bug 777399 mark 2 group->buffer.index 7, group->n_mem 1
0:00:02.385391566 11545   0x197920 LOG            v4l2allocator
gstv4l2allocator.c:1278:gst_v4l2_allocator_qbuf:<v4l2video3dec0:pool:src:allocator>
Bug 777399 mark 2 group->n_mem[0] 0x18f468 refcount 1
[...]
[Note: thread switch]
0:00:02.487634133 11545   0x19caf0 LOG            v4l2allocator
gstv4l2allocator.c:1322:gst_v4l2_allocator_dqbuf:<v4l2video3dec0:pool:src:allocator>
dequeued buffer 7 (flags 0x4021)
0:00:02.487874533 11545   0x19caf0 LOG            v4l2allocator
gstv4l2allocator.c:1351:gst_v4l2_allocator_dqbuf:<v4l2video3dec0:pool:src:allocator>
Bug 777399 mark 3 group->buffer.index 7, group->n_mem 1
0:00:02.488094133 11545   0x19caf0 LOG            v4l2allocator
gstv4l2allocator.c:1356:gst_v4l2_allocator_dqbuf:<v4l2video3dec0:pool:src:allocator>
Bug 777399 mark 3 group->n_mem[0] 0x18f468 refcount 2

=> Sequence = mark 1 / mark 2 / mark 3
=> The memory reference counter is 2 before being unreferenced in
gst_v4l2_allocator_dqbuf (Bug 777399 mark 3)

When there's a thread switch, the problem occurs and the log messages sequence
is as follows:
0:00:02.661521266 11545   0x197920 LOG            v4l2allocator
gstv4l2allocator.c:1244:gst_v4l2_allocator_qbuf:<v4l2video3dec0:pool:src:allocator>
Bug 777399 mark 1 group->buffer.index 7, group->n_mem 1
0:00:02.661783766 11545   0x197920 LOG            v4l2allocator
gstv4l2allocator.c:1249:gst_v4l2_allocator_qbuf:<v4l2video3dec0:pool:src:allocator>
Bug 777399 mark 1 group->n_mem[0] 0x18f468 refcount 1
[Note: thread switch]
0:00:02.678298999 11545   0x19caf0 LOG            v4l2allocator
gstv4l2allocator.c:1322:gst_v4l2_allocator_dqbuf:<v4l2video3dec0:pool:src:allocator>
dequeued buffer 7 (flags 0x4021)
0:00:02.678470666 11545   0x19caf0 LOG            v4l2allocator
gstv4l2allocator.c:1351:gst_v4l2_allocator_dqbuf:<v4l2video3dec0:pool:src:allocator>
Bug 777399 mark 3 group->buffer.index 7, group->n_mem 1
0:00:02.678580533 11545   0x19caf0 LOG            v4l2allocator
gstv4l2allocator.c:1356:gst_v4l2_allocator_dqbuf:<v4l2video3dec0:pool:src:allocator>
Bug 777399 mark 3 group->n_mem[0] 0x18f468 refcount 1
0:00:02.678684766 11545   0x19caf0 LOG            v4l2allocator
gstv4l2allocator.c:351:gst_v4l2_allocator_release:<v4l2video3dec0:pool:src:allocator>
plane 0 of buffer 7 released
0:00:02.678778266 11545   0x19caf0 LOG            v4l2allocator
gstv4l2allocator.c:367:gst_v4l2_allocator_release:<v4l2video3dec0:pool:src:allocator>
buffer 7 released
[Note: memory released]
[Note: thread switch]
0:00:02.679203299 11545   0x197920 LOG            v4l2allocator
gstv4l2allocator.c:1264:gst_v4l2_allocator_qbuf:<v4l2video3dec0:pool:src:allocator>
queued buffer 7 (flags 0x4021)
0:00:02.679383366 11545   0x197920 DEBUG          v4l2allocator
gstv4l2allocator.c:1268:gst_v4l2_allocator_qbuf:<v4l2video3dec0:pool:src:allocator>
driver pretends buffer is not queued even if queue succeeded
0:00:02.679495266 11545   0x197920 LOG            v4l2allocator
gstv4l2allocator.c:1273:gst_v4l2_allocator_qbuf:<v4l2video3dec0:pool:src:allocator>
Bug 777399 mark 2 group->buffer.index 7, group->n_mem 1
0:00:02.679610599 11545   0x197920 LOG            v4l2allocator
gstv4l2allocator.c:1278:gst_v4l2_allocator_qbuf:<v4l2video3dec0:pool:src:allocator>
Bug 777399 mark 2 group->n_mem[0] 0xb4705450 refcount 1

=> Sequence = mark 1 / mark 3 / mark 2
=> The memory reference counter is 1 before being unreferenced in
gst_v4l2_allocator_dqbuf (Bug 777399 mark 3) = memory is released

-- 
You are receiving this mail because:
You are the QA Contact for the bug.
You are the assignee for the bug.