[libcamera-devel] [PATCH] libcamera: pipeline: rkisp1: Avoid race when processing parameter buffers

Tue Jan 19 09:04:57 CET 2021

Hi Niklas, Sebastian,

On 19/01/2021 07:23, Sebastian Fricke wrote:
> Hello Niklas,
> 
> I have tested your patch on my board. The tests I performed were:
> `LIBCAMERA_LOG_LEVELS=0 cam --camera=1 --capture=200 --file=~/test.raw`
> * without the delayed ctrls and without this patch
> * with the delayed ctrls and without this patch
> * with the delayed ctrls and with this patch
> 
> Here are some snippets of my tests: https://paste.debian.net/1181697/
> 
> All in all, it looks way smoother with this patch.
> 
> There is one thing that I noticed, that we might have to address in
> another set of patches. When I run the command:
> `cam --camera=1 --capture=200`, the cam command stops at 200 frames
> without issues. If I start this command:
> `cam --camera=1 --capture=200 --file=test.raw`, the cam command keeps
> running until I `ctrl+c` it. While the output looks like this:
> ```
> 3969.152837 (4.29 fps) stream0 seq: 000381 bytesused: 5529600
> [1:06:10.137876560] [7219] DEBUG V4L2 v4l2_videodevice.cpp:1440
> /dev/video4[out]: Queueing buffer 0
> [1:06:10.138091809] [7219] DEBUG V4L2 v4l2_videodevice.cpp:1440
> /dev/video3[cap]: Queueing buffer 0
> [1:06:10.138238808] [7219] DEBUG V4L2 v4l2_videodevice.cpp:1440
> /dev/video1[cap]: Queueing buffer 0
> [1:06:10.151352654] [7219] DEBUG V4L2 v4l2_videodevice.cpp:1509
> /dev/video3[cap]: Dequeuing buffer 0
> [1:06:10.151674944] [7219] DEBUG V4L2 v4l2_videodevice.cpp:1509
> /dev/video4[out]: Dequeuing buffer 0
> [1:06:10.153216102] [7219] DEBUG DelayedControls
> delayed_controls.cpp:209 frame 412 started
> [1:06:10.153342685] [7219] DEBUG DelayedControls
> delayed_controls.cpp:239 Queue is empty, auto queue no-op.
> [1:06:10.186488090] [7219] DEBUG DelayedControls
> delayed_controls.cpp:209 frame 413 started
> [1:06:10.186597173] [7219] DEBUG DelayedControls
> delayed_controls.cpp:239 Queue is empty, auto queue no-op.
> [1:06:10.217897505] [7219] DEBUG V4L2 v4l2_videodevice.cpp:1509
> /dev/video1[cap]: Dequeuing buffer 0
> [1:06:10.218134628] [7219] DEBUG Request request.cpp:266 Request has
> completed - cookie: 0
> [1:06:10.219763286] [7219] DEBUG DelayedControls
> delayed_controls.cpp:209 frame 414 started
> [1:06:10.219870619] [7219] DEBUG DelayedControls
> delayed_controls.cpp:239 Queue is empty, auto queue no-op.
> [1:06:10.253048107] [7219] DEBUG DelayedControls
> delayed_controls.cpp:209 frame 415 started
> [1:06:10.253153690] [7219] DEBUG DelayedControls
> delayed_controls.cpp:239 Queue is empty, auto queue no-op.
> [1:06:10.286324762] [7219] DEBUG DelayedControls
> delayed_controls.cpp:209 frame 416 started
> [1:06:10.286432094] [7219] DEBUG DelayedControls
> delayed_controls.cpp:239 Queue is empty, auto queue no-op.
> [1:06:10.319640791] [7219] DEBUG DelayedControls
> delayed_controls.cpp:209 frame 417 started
> [1:06:10.319792457] [7219] DEBUG DelayedControls
> delayed_controls.cpp:239 Queue is empty, auto queue no-op.
> [1:06:10.352930278] [7219] DEBUG DelayedControls
> delayed_controls.cpp:209 frame 418 started
> [1:06:10.353086319] [7219] DEBUG DelayedControls
> delayed_controls.cpp:239 Queue is empty, auto queue no-op.
> [1:06:10.386194683] [7219] DEBUG DelayedControls
> delayed_controls.cpp:209 frame 419 started
> [1:06:10.386338182] [7219] DEBUG DelayedControls
> delayed_controls.cpp:239 Queue is empty, auto queue no-op.
> 3969.452358 (3.34 fps) stream0 seq: 000390 bytesused: 5529600
> ```

Interestingly, I can reproduce it on my IPU3 pipeline device (of course
not with this patch).
If I am writing the file in a fast block device (like tmpfs) then I
can't see an issue.
But if I write it to an external USB drive, and force the role to be
raw, then, I have the same behaviour :

$> LIBCAMERA_LOG_LEVELS=*:0 cam --camera=1 --capture=200 -s role=raw
--file=/media/jm/JM_USB/test.raw
<snip>
[24:14:13.898015939] [26821] DEBUG V4L2 v4l2_videodevice.cpp:1440
/dev/video1[cap]: Queueing buffer 2
[24:14:13.913085892] [26821] DEBUG DelayedControls
delayed_controls.cpp:214 frame 282 started
[24:14:13.913251668] [26821] DEBUG DelayedControls
delayed_controls.cpp:244 Queue is empty, auto queue no-op.
[24:14:13.945774836] [26821] DEBUG V4L2 v4l2_videodevice.cpp:1509
/dev/video1[cap]: Dequeuing buffer 1
[24:14:13.946118989] [26821] DEBUG Request request.cpp:266 Request has
completed - cookie: 0
[24:14:13.946337806] [26821] DEBUG DelayedControls
delayed_controls.cpp:214 frame 283 started
[24:14:13.946444586] [26821] DEBUG DelayedControls
delayed_controls.cpp:244 Queue is empty, auto queue no-op.
87253.845588 (15.00 fps) stream0 seq: 000279 bytesused: 6469632
[24:14:13.979069027] [26821] DEBUG V4L2 v4l2_videodevice.cpp:1509
/dev/video1[cap]: Dequeuing buffer 2
[24:14:13.979201412] [26821] DEBUG Request request.cpp:266 Request has
completed - cookie: 0
[24:14:13.979840259] [26821] DEBUG DelayedControls
delayed_controls.cpp:214 frame 284 started
[24:14:13.979938538] [26821] DEBUG DelayedControls
delayed_controls.cpp:244 Queue is empty, auto queue no-op.
87253.878892 (30.03 fps) stream0 seq: 000280 bytesused: 6469632
[24:14:14.013340775] [26821] DEBUG DelayedControls
delayed_controls.cpp:214 frame 285 started
[24:14:14.013426832] [26821] DEBUG DelayedControls
delayed_controls.cpp:244 Queue is empty, auto queue no-op.
87253.945623 (14.99 fps) stream0 seq: 000282 bytesused: 6469632
[24:14:14.046635119] [26821] DEBUG DelayedControls
delayed_controls.cpp:214 frame 286 started
[24:14:14.046801827] [26821] DEBUG DelayedControls
delayed_controls.cpp:244 Queue is empty, auto queue no-op.
[24:14:14.080099336] [26821] DEBUG DelayedControls
delayed_controls.cpp:214 frame 287 started
[24:14:14.080279361] [26821] DEBUG DelayedControls
delayed_controls.cpp:244 Queue is empty, auto queue no-op.
87253.978990 (29.97 fps) stream0 seq: 000283 bytesused: 6469632
[24:14:14.113361019] [26821] DEBUG DelayedControls
delayed_controls.cpp:214 frame 288 started
[24:14:14.113535093] [26821] DEBUG DelayedControls
delayed_controls.cpp:244 Queue is empty, auto queue no-op.
[24:14:14.146657763] [26821] DEBUG DelayedControls
delayed_controls.cpp:214 frame 289 started
[24:14:14.146839192] [26821] DEBUG DelayedControls
delayed_controls.cpp:244 Queue is empty, auto queue no-op.
[24:14:14.179926886] [26821] DEBUG DelayedControls
delayed_controls.cpp:214 frame 290 started
[24:14:14.180116036] [26821] DEBUG DelayedControls
delayed_controls.cpp:244 Queue is empty, auto queue no-op.
[24:14:14.213435640] [26821] DEBUG DelayedControls
delayed_controls.cpp:214 frame 291 started
[24:14:14.213649312] [26821] DEBUG DelayedControls
delayed_controls.cpp:244 Queue is empty, auto queue no-op.
[24:14:14.246721869] [26821] DEBUG DelayedControls
delayed_controls.cpp:214 frame 292 started
...

It looks like it is related to DelayedControls but I can't find out
why... yet :-)
JM