GNOME Bugzilla – Bug 777399
v4l2allocator: memory referenced too late
Last modified: 2017-02-22 09:19:47 UTC
In the gst_v4l2_allocator_qbuf() function, the memory ("group->mem[i]") is referenced ("gst_memory_ref") after the buffer has been queued ("VIDIOC_QBUF"). Once queued, this buffer might be handled by the V4L2 driver (e.g. decoded) and dequeued (see the gst_v4l2_allocator_dqbuf() function) through a different thread than the one that queued it: these actions might occur before the memory is referenced (gst_memory_ref) in the gst_v4l2_allocator_qbuf() function. In other words, the buffer might be dequeued through the gst_v4l2_allocator_dqbuf() function before the gst_v4l2_allocator_qbuf() function has completed its actions on this buffer. Then, in this situation, in the gst_v4l2_allocator_dqbuf() function, the memory is unreferenced (gst_memory_unref) before having been referenced (by the gst_v4l2_allocator_qbuf() function): the memory refcount reaches 0, and the memory is freed, which is not the expecting behavior. To avoid this crossing case, the proposition is to reference the memory before the buffer is queued, and to unreference it if the queueing fails, in the gst_v4l2_allocator_qbuf() function. A patch will be attached soon.
Created attachment 343660 [details] [review] v4l2allocator: reference memory before the buffer is queued
I think this report is invalid. gst_v4l2_allocator_qbuf() is called by gst_v4l2_buffer_pool_qbuf(). The second parameter of this function is GstBuffer which should be owned by the called (ref > 0). Which means when gst_v4l2_allocator_qbuf() is called, the GstMemory objects are still owned by this GstBuffer. The last reference to the GstMemory won't be dropped before the function returns. What those lines do, is that they raise the ref count of the memories to at least 2 (hence the read only comment), before returning. This way, if the last reference is later dropped, the allocator remains owner.
Created attachment 344022 [details] Temporary log messages added to ease the debug
Created attachment 344023 [details] Log file
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
Ok, might be a valid bug, but it's the wrong fix. You must have a ref when calling qbuf() in the allocator. If it's not the case, it means there is a bug somewhere else.
Please share how you reproduced this bug.
(In reply to Nicolas Dufresne (stormer) from comment #6) > Ok, might be a valid bug, but it's the wrong fix. You must have a ref when > calling qbuf() in the allocator. If it's not the case, it means there is a > bug somewhere else. As indicated in my previous comment (and as shown in the log), I have a reference when calling qbuf() in the allocator. When there's no problem, the sequence is: (1) In gst_v4l2_allocator_qbuf() GST_MINI_OBJECT_REFCOUNT_VALUE (GST_MINI_OBJECT_CAST (group->mem[i])) = 1 before calling v4l2_ioctl (allocator->video_fd, VIDIOC_QBUF, &group->buffer) (2) In gst_v4l2_allocator_qbuf() GST_MINI_OBJECT_REFCOUNT_VALUE (GST_MINI_OBJECT_CAST (group->mem[i])) = 2 after calling gst_memory_ref (group->mem[i]) [Thread switch to gst_v4l2_allocator_dqbuf] (3) In gst_v4l2_allocator_dqbuf() GST_MINI_OBJECT_REFCOUNT_VALUE (GST_MINI_OBJECT_CAST (group->mem[i])) = 2 after calling v4l2_ioctl (allocator->video_fd, VIDIOC_DQBUF, &buffer) (4) In gst_v4l2_allocator_dqbuf() GST_MINI_OBJECT_REFCOUNT_VALUE (GST_MINI_OBJECT_CAST (group->mem[i])) = 1 after calling gst_memory_unref (group->mem[i]) When there's a problem, the sequence is: (1) In gst_v4l2_allocator_qbuf() GST_MINI_OBJECT_REFCOUNT_VALUE (GST_MINI_OBJECT_CAST (group->mem[i])) = 1 before calling v4l2_ioctl (allocator->video_fd, VIDIOC_QBUF, &group->buffer) [Thread switch to gst_v4l2_allocator_dqbuf] (2) In gst_v4l2_allocator_dqbuf() GST_MINI_OBJECT_REFCOUNT_VALUE (GST_MINI_OBJECT_CAST (group->mem[i])) = 1 after calling v4l2_ioctl (allocator->video_fd, VIDIOC_DQBUF, &buffer) (3) In gst_v4l2_allocator_dqbuf() GST_MINI_OBJECT_REFCOUNT_VALUE (GST_MINI_OBJECT_CAST (group->mem[i])) = 0 after calling gst_memory_unref (group->mem[i]) => the memory is released [Thread switch: back to gst_v4l2_allocator_qbuf] (4) In gst_v4l2_allocator_qbuf() GST_MINI_OBJECT_REFCOUNT_VALUE (GST_MINI_OBJECT_CAST (group->mem[i])) => unspecified behavior as the memory is released
(In reply to Nicolas Dufresne (stormer) from comment #7) > Please share how you reproduced this bug. The problem is far from being easy to reproduce as it's very sensitive to the real-time. With the configuration (inc. the video stream) that I describe below, the occurrence is around 33%. I've not found (yet) a way to reproduce it with a higher frequency. My configuration to reproduce: * GStreamer 1.8.3 with V4L2 video driver (HW accelerated decoder: st-delta being upstreamed) * ST B2260 Development Board (Linaro 96Boards) * Video stream: big_buck_bunny_1080p_MPEG2_MP2_25fps_6600K_short.MPG from http://samplemedia.linaro.org/MPEG2/ * Command: gst-play-1.0 big_buck_bunny_1080p_MPEG2_MP2_25fps_6600K_short.MPG --gst-debug=*:3,*allocator*:6
I believe I need to apologies now. I think I finally understood this case and why it works with your fix. I tend to forget that all this allocator/buffer-stuff is trying to be lockless (a bit scary). So indeed, if one get pre-empted after QBUF, but before the ref, then another thread could DQUEUE and free immediatly. QDBUF bufs assume the allocater kept a ref (which may not have been taken yet). Again appology, not an easy one, clearly not what I expected for this code initially. p.s. to reproduce easily, add a sleep() after QBUF.
Review of attachment 343660 [details] [review]: Let's merge that. I'll give it few weeks in master, and then we'll be more confident if that should be backported to stable.
Attachment 343660 [details] pushed as 7f763f2 - v4l2allocator: reference memory before the buffer is queued
Thank you for the time you spent on this bug. At my turn, I apologize about my first description of the problem that was far from being clear enough: use case not described, no log, few details about the thread switches and the pre-emptions. I will try to improve the first description for the next bugs that I might enter.
In 1.10 as 4a57ff75449e1ba525df28c8b99ff9fd566430a3
Wrong ref, 1.10 as 3c911b5a6ba8d3e69240ec72a892afc36f40e923