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

[Niklas Söderlund]

Hello Jean-Michel,

Thanks for your feedback.

On 2021-01-19 09:04:57 +0100, Jean-Michel Hautbois wrote:

<snip>

> 
> 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

I have reproduced this issue based on-top of your test-ipu3-ae-stats
branch and as you say I can observer that writing RAW frames to a USB 
stick gets slower over time (no big surprise as the writhe cache gets 
full :-) But the expected number of frames do get written to the USB 
eventually. As a reference in my tests I rather quickly end up at around 
just under 0.3 FPS.

With the --capture=200 option and without the bugfix in [1] 
203 frames are written to the USB stick and cam hangs. With the bugfix 
for cam added on-top of your work I do get the expected 200 frames and 
the cam terminates. Are you experience any other issues that it's dead 
slow?

With [1] applied (so that is correct cam behavior of writing 200 frames 
to the USB) running on CrOS,

$ rm -f /mnt/usb/abc.raw && sync && time cam --camera=1 --capture=200 -s role=raw --file=/mnt/usb/abc.raw
<snip>
3249.220644 (0.29 fps) stream0 seq: 012686 bytesused: 17059840
3252.860304 (0.27 fps) stream0 seq: 012795 bytesused: 17059840
3256.767112 (0.26 fps) stream0 seq: 012912 bytesused: 17059840
3260.173049 (0.29 fps) stream0 seq: 013014 bytesused: 17059840
3263.111829 (0.34 fps) stream0 seq: 013102 bytesused: 17059840
3266.283734 (0.32 fps) stream0 seq: 013197 bytesused: 17059840
3269.589472 (0.30 fps) stream0 seq: 013296 bytesused: 17059840
3272.861826 (0.31 fps) stream0 seq: 013394 bytesused: 17059840
3276.167671 (0.30 fps) stream0 seq: 013493 bytesused: 17059840
3280.174598 (0.25 fps) stream0 seq: 013613 bytesused: 17059840
3284.949541 (0.21 fps) stream0 seq: 013756 bytesused: 17059840
3288.388970 (0.29 fps) stream0 seq: 013859 bytesused: 17059840
3291.527759 (0.32 fps) stream0 seq: 013953 bytesused: 17059840
3294.633184 (0.32 fps) stream0 seq: 014046 bytesused: 17059840
3297.805284 (0.32 fps) stream0 seq: 014141 bytesused: 17059840
3300.944136 (0.32 fps) stream0 seq: 014235 bytesused: 17059840
3304.183093 (0.31 fps) stream0 seq: 014332 bytesused: 17059840
3307.889588 (0.27 fps) stream0 seq: 014443 bytesused: 17059840
3311.696245 (0.26 fps) stream0 seq: 014557 bytesused: 17059840
3315.035314 (0.30 fps) stream0 seq: 014657 bytesused: 17059840

real	8m23.083s
user	0m4.317s
sys	0m8.940s

Size of each buffer is 17059840 => expected file size 17059840 * 200 = 
3411968000, which checks out.

$ ls -l /mnt/usb/abc.raw
-rw-r--r--. 1 root root 3411968000 Jan 19 16:12 /mnt/usb/abc.raw

Total time was ~ 8min 23 sec => 503 seconds. That gives a wall clock 
write speed of 3411968000 / 503 => ~ 6783237 bytes / sec or 6.46 Mbit / 
sec. It's not a completely fair comparison but simulated workload using 
dd to get some ballpark numbers,

$ rm -f /mnt/usb/abc.raw && sync && time dd if=/dev/urandom of=/mnt/usb/abc.raw bs=17059840 count=200 status=progress
3411968000 bytes (3.4 GB, 3.2 GiB) copied, 494.853 s, 6.9 MB/s  
200+0 records in
200+0 records out
3411968000 bytes (3.4 GB, 3.2 GiB) copied, 494.853 s, 6.9 MB/s

real	8m14.884s
user	0m0.004s
sys	2m29.831s

So I'd say cam does an OK job of pushing frames to USB stick. That 
libcamera informs you it's probably not what you want is a different 
story ;-)

<snip>

> [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

Well yes and no. The DEBUG messages you see are indeed from 
DelayedControls, it's a cry for help informing the user that it's in a 
under-run situation and that it can't perform the operations it's asked 
to do as the something is not feeding the camera fast enough (in this 
case the cam application). But if you let it run for enough time the cam 
application will correctly capture the frames to the USB stick but even 
with complete IPA the quality of them would likely be bad due to the low 
frequency in the control loop :-)

A similar patch as this one for IPU3 is needed for other reasons and it 
will "hide" some of the "Queue is empty" messages. Not because it makes 
the situation any better for a control loop starved of resource, but as
we get better control on when we queue buffers so we won't even attempt 
to do anything i this scenario :-)

1. [PATCH 0/2] cam: Fix races in event loop and long request processing times

-- 
Regards,
Niklas Söderlund