[{"id":14591,"web_url":"https://patchwork.libcamera.org/comment/14591/","msgid":"<20210119062330.o6ys6dq3yve325u4@basti-TUXEDO-Book-XA1510>","date":"2021-01-19T06:23:30","subject":"Re: [libcamera-devel] [PATCH] libcamera: pipeline: rkisp1: Avoid\n\trace when processing parameter buffers","submitter":{"id":78,"url":"https://patchwork.libcamera.org/api/people/78/","name":"Sebastian Fricke","email":"sebastian.fricke@posteo.net"},"content":"Hello Niklas,\n\nI have tested your patch on my board. The tests I performed were:\n`LIBCAMERA_LOG_LEVELS=0 cam --camera=1 --capture=200 --file=~/test.raw`\n* without the delayed ctrls and without this patch\n* with the delayed ctrls and without this patch\n* with the delayed ctrls and with this patch\n\nHere are some snippets of my tests: https://paste.debian.net/1181697/\n\nAll in all, it looks way smoother with this patch.\n\nThere is one thing that I noticed, that we might have to address in\nanother set of patches. When I run the command:\n`cam --camera=1 --capture=200`, the cam command stops at 200 frames\nwithout issues. If I start this command:\n`cam --camera=1 --capture=200 --file=test.raw`, the cam command keeps\nrunning until I `ctrl+c` it. While the output looks like this:\n```\n3969.152837 (4.29 fps) stream0 seq: 000381 bytesused: 5529600\n[1:06:10.137876560] [7219] DEBUG V4L2 v4l2_videodevice.cpp:1440 /dev/video4[out]: Queueing buffer 0\n[1:06:10.138091809] [7219] DEBUG V4L2 v4l2_videodevice.cpp:1440 /dev/video3[cap]: Queueing buffer 0\n[1:06:10.138238808] [7219] DEBUG V4L2 v4l2_videodevice.cpp:1440 /dev/video1[cap]: Queueing buffer 0\n[1:06:10.151352654] [7219] DEBUG V4L2 v4l2_videodevice.cpp:1509 /dev/video3[cap]: Dequeuing buffer 0\n[1:06:10.151674944] [7219] DEBUG V4L2 v4l2_videodevice.cpp:1509 /dev/video4[out]: Dequeuing buffer 0\n[1:06:10.153216102] [7219] DEBUG DelayedControls delayed_controls.cpp:209 frame 412 started\n[1:06:10.153342685] [7219] DEBUG DelayedControls delayed_controls.cpp:239 Queue is empty, auto queue no-op.\n[1:06:10.186488090] [7219] DEBUG DelayedControls delayed_controls.cpp:209 frame 413 started\n[1:06:10.186597173] [7219] DEBUG DelayedControls delayed_controls.cpp:239 Queue is empty, auto queue no-op.\n[1:06:10.217897505] [7219] DEBUG V4L2 v4l2_videodevice.cpp:1509 /dev/video1[cap]: Dequeuing buffer 0\n[1:06:10.218134628] [7219] DEBUG Request request.cpp:266 Request has completed - cookie: 0\n[1:06:10.219763286] [7219] DEBUG DelayedControls delayed_controls.cpp:209 frame 414 started\n[1:06:10.219870619] [7219] DEBUG DelayedControls delayed_controls.cpp:239 Queue is empty, auto queue no-op.\n[1:06:10.253048107] [7219] DEBUG DelayedControls delayed_controls.cpp:209 frame 415 started\n[1:06:10.253153690] [7219] DEBUG DelayedControls delayed_controls.cpp:239 Queue is empty, auto queue no-op.\n[1:06:10.286324762] [7219] DEBUG DelayedControls delayed_controls.cpp:209 frame 416 started\n[1:06:10.286432094] [7219] DEBUG DelayedControls delayed_controls.cpp:239 Queue is empty, auto queue no-op.\n[1:06:10.319640791] [7219] DEBUG DelayedControls delayed_controls.cpp:209 frame 417 started\n[1:06:10.319792457] [7219] DEBUG DelayedControls delayed_controls.cpp:239 Queue is empty, auto queue no-op.\n[1:06:10.352930278] [7219] DEBUG DelayedControls delayed_controls.cpp:209 frame 418 started\n[1:06:10.353086319] [7219] DEBUG DelayedControls delayed_controls.cpp:239 Queue is empty, auto queue no-op.\n[1:06:10.386194683] [7219] DEBUG DelayedControls delayed_controls.cpp:209 frame 419 started\n[1:06:10.386338182] [7219] DEBUG DelayedControls delayed_controls.cpp:239 Queue is empty, auto queue no-op.\n3969.452358 (3.34 fps) stream0 seq: 000390 bytesused: 5529600\n```\n\nAnyway, this seems to be another issue, I have corrected two small typos\nbelow. And if you like to you can add a:\nTested-by: Sebastian Fricke \n\nGreetings,\nSebastian\n\nOn 18.01.2021 15:06, Niklas Söderlund wrote:\n>When moving the pipeline away from the Timeline design it was discovered\n>that the design of queuing the buffers to the device as soon as possible\n>was not the best idea. The parameter buffers where queued to the device\n\ns/where queued/were queued/\n\n>before the IPA had processed them and this violates the V4L2 API.\n>\n>Fix this by waiting to queue any buffer to the device until the IPA have\n\ns/until the IPA have/until the IPA has/\n\n>filled in the parameters buffer.\n>\n>Signed-off-by: Niklas Söderlund \n>---\n>Hello,\n>\n>This patch is based on-top of '[PATCH v5 0/8] libcamera: Add helper for\n>controls that take effect with a delay' as the change is much cleaner\n>on-top of the removal of the Timeline.\n>---\n> src/libcamera/pipeline/rkisp1/rkisp1.cpp | 41 ++++++++----------------\n> 1 file changed, 13 insertions(+), 28 deletions(-)\n>\n>diff --git a/src/libcamera/pipeline/rkisp1/rkisp1.cpp b/src/libcamera/pipeline/rkisp1/rkisp1.cpp\n>index 58ae8f98a5c683d5..e85979a719b7ced6 100644\n>--- a/src/libcamera/pipeline/rkisp1/rkisp1.cpp\n>+++ b/src/libcamera/pipeline/rkisp1/rkisp1.cpp\n>@@ -51,7 +51,6 @@ struct RkISP1FrameInfo {\n> \tFrameBuffer *mainPathBuffer;\n> \tFrameBuffer *selfPathBuffer;\n>\n>-\tbool paramFilled;\n> \tbool paramDequeued;\n> \tbool metadataProcessed;\n> };\n>@@ -219,7 +218,6 @@ RkISP1FrameInfo *RkISP1Frames::create(const RkISP1CameraData *data, Request *req\n> \tinfo->mainPathBuffer = mainPathBuffer;\n> \tinfo->selfPathBuffer = selfPathBuffer;\n> \tinfo->statBuffer = statBuffer;\n>-\tinfo->paramFilled = false;\n> \tinfo->paramDequeued = false;\n> \tinfo->metadataProcessed = false;\n>\n>@@ -322,9 +320,20 @@ void RkISP1CameraData::queueFrameAction(unsigned int frame,\n> \t\tbreak;\n> \t}\n> \tcase RKISP1_IPA_ACTION_PARAM_FILLED: {\n>+\t\tPipelineHandlerRkISP1 *pipe = static_cast(pipe_);\n> \t\tRkISP1FrameInfo *info = frameInfo_.find(frame);\n>-\t\tif (info)\n>-\t\t\tinfo->paramFilled = true;\n>+\t\tif (!info)\n>+\t\t\tbreak;\n>+\n>+\t\tpipe->param_->queueBuffer(info->paramBuffer);\n>+\t\tpipe->stat_->queueBuffer(info->statBuffer);\n>+\n>+\t\tif (info->mainPathBuffer)\n>+\t\t\tmainPath_->queueBuffer(info->mainPathBuffer);\n>+\n>+\t\tif (info->selfPathBuffer)\n>+\t\t\tselfPath_->queueBuffer(info->selfPathBuffer);\n>+\n> \t\tbreak;\n> \t}\n> \tcase RKISP1_IPA_ACTION_METADATA:\n>@@ -852,15 +861,6 @@ int PipelineHandlerRkISP1::queueRequestDevice(Camera *camera, Request *request)\n> \top.controls = { request->controls() };\n> \tdata->ipa_->processEvent(op);\n>\n>-\tparam_->queueBuffer(info->paramBuffer);\n>-\tstat_->queueBuffer(info->statBuffer);\n>-\n>-\tif (info->mainPathBuffer)\n>-\t\tmainPath_.queueBuffer(info->mainPathBuffer);\n>-\n>-\tif (info->selfPathBuffer)\n>-\t\tselfPath_.queueBuffer(info->selfPathBuffer);\n>-\n> \tdata->frame_++;\n>\n> \treturn 0;\n>@@ -1009,7 +1009,6 @@ bool PipelineHandlerRkISP1::match(DeviceEnumerator *enumerator)\n> \tmainPath_.bufferReady().connect(this, &PipelineHandlerRkISP1::bufferReady);\n> \tselfPath_.bufferReady().connect(this, &PipelineHandlerRkISP1::bufferReady);\n> \tstat_->bufferReady.connect(this, &PipelineHandlerRkISP1::statReady);\n>-\tisp_->frameStart.connect(this, &PipelineHandlerRkISP1::frameStart);\n> \tparam_->bufferReady.connect(this, &PipelineHandlerRkISP1::paramReady);\n>\n> \t/*\n>@@ -1097,20 +1096,6 @@ void PipelineHandlerRkISP1::statReady(FrameBuffer *buffer)\n> \tdata->ipa_->processEvent(op);\n> }\n>\n>-void PipelineHandlerRkISP1::frameStart(uint32_t sequence)\n>-{\n>-\tif (!activeCamera_)\n>-\t\treturn;\n>-\n>-\tRkISP1CameraData *data = cameraData(activeCamera_);\n>-\n>-\tRkISP1FrameInfo *info = data->frameInfo_.find(sequence);\n>-\tif (!info || !info->paramFilled)\n>-\t\tLOG(RkISP1, Info)\n>-\t\t\t<< \"Parameters not ready on time for frame \"\n>-\t\t\t<< sequence;\n>-}\n>-\n> REGISTER_PIPELINE_HANDLER(PipelineHandlerRkISP1)\n>\n> } /* namespace libcamera */\n>-- \n>2.30.0\n>\n>_______________________________________________\n>libcamera-devel mailing list\n>libcamera-devel@lists.libcamera.org\n>https://lists.libcamera.org/listinfo/libcamera-devel","headers":{"Return-Path":"","X-Original-To":"parsemail@patchwork.libcamera.org","Delivered-To":"parsemail@patchwork.libcamera.org","Received":["from lancelot.ideasonboard.com (lancelot.ideasonboard.com\n\t[92.243.16.209])\n\tby patchwork.libcamera.org (Postfix) with ESMTPS id BCFE7C0F1C\n\tfor ;\n\tTue, 19 Jan 2021 06:23:35 +0000 (UTC)","from lancelot.ideasonboard.com (localhost [IPv6:::1])\n\tby lancelot.ideasonboard.com (Postfix) with ESMTP id 3800D68138;\n\tTue, 19 Jan 2021 07:23:35 +0100 (CET)","from mout02.posteo.de (mout02.posteo.de [185.67.36.66])\n\tby lancelot.ideasonboard.com (Postfix) with ESMTPS id 9518760310\n\tfor ;\n\tTue, 19 Jan 2021 07:23:32 +0100 (CET)","from submission (posteo.de [89.146.220.130]) \n\tby mout02.posteo.de (Postfix) with ESMTPS id F109F2400FB\n\tfor ;\n\tTue, 19 Jan 2021 07:23:31 +0100 (CET)","from customer (localhost [127.0.0.1])\n\tby submission (posteo.de) with ESMTPSA id 4DKdrg2gPJz9rxS;\n\tTue, 19 Jan 2021 07:23:31 +0100 (CET)"],"Authentication-Results":"lancelot.ideasonboard.com;\n\tdkim=fail reason=\"signature verification failed\" (2048-bit key;\n\tunprotected) header.d=posteo.net header.i=@posteo.net\n\theader.b=\"ms3pBrnN\"; dkim-atps=neutral","DKIM-Signature":"v=1; a=rsa-sha256; c=relaxed/simple; d=posteo.net; s=2017;\n\tt=1611037412; bh=unmpoqHEvd97nxOiig7oA/pZ27tJaReEEB0x1uMIQGQ=;\n\th=Date:From:To:Cc:Subject:From;\n\tb=ms3pBrnNusGb/w50fYgNi9Za+M4ZBuRbTqgjIw1JInElcfbJd1WcFUHHlJzpQ4IFK\n\tYMEHCK+CmFwVDVOdR12imxA6LZbIk+SxxxOHmMSH1egl1uOv2frhCRYH391pKaaeSx\n\txzXjvqKZJTXJzq7gPDVee6/OrH/LgWOKhrOCeIxc8WTUrVxVCXXXVCs1FMct3gaEqa\n\tYUcPl7B4PXMmKvEU79uZeLZXFTKDWYa+kepeptD9DUiuYX5toKj60zwozl3z5IWiAo\n\tXwuQz9/GY+fau7ID5QYAijzNdiFbD2/61Jp1NoZX74wCnRgpP5Zv2gn9ItxbntEosx\n\thJYsL4enDiGWA==","Date":"Tue, 19 Jan 2021 07:23:30 +0100","From":"Sebastian Fricke ","To":"Niklas =?utf-8?q?S=C3=B6derlund?= ","Message-ID":"<20210119062330.o6ys6dq3yve325u4@basti-TUXEDO-Book-XA1510>","References":"<20210118140615.2332504-1-niklas.soderlund@ragnatech.se>","MIME-Version":"1.0","Content-Disposition":"inline","In-Reply-To":"<20210118140615.2332504-1-niklas.soderlund@ragnatech.se>","Subject":"Re: [libcamera-devel] [PATCH] libcamera: pipeline: rkisp1: Avoid\n\trace when processing parameter buffers","X-BeenThere":"libcamera-devel@lists.libcamera.org","X-Mailman-Version":"2.1.29","Precedence":"list","List-Id":"","List-Unsubscribe":",\n\t","List-Archive":"","List-Post":"","List-Help":"","List-Subscribe":",\n\t","Reply-To":"Sebastian Fricke ","Cc":"libcamera-devel@lists.libcamera.org","Content-Transfer-Encoding":"base64","Content-Type":"text/plain; charset=\"utf-8\"; Format=\"flowed\"","Errors-To":"libcamera-devel-bounces@lists.libcamera.org","Sender":"\"libcamera-devel\" "}},{"id":14593,"web_url":"https://patchwork.libcamera.org/comment/14593/","msgid":"","date":"2021-01-19T08:04:57","subject":"Re: [libcamera-devel] [PATCH] libcamera: pipeline: rkisp1: Avoid\n\trace when processing parameter buffers","submitter":{"id":75,"url":"https://patchwork.libcamera.org/api/people/75/","name":"Jean-Michel Hautbois","email":"jeanmichel.hautbois@ideasonboard.com"},"content":"Hi Niklas, Sebastian,\n\nOn 19/01/2021 07:23, Sebastian Fricke wrote:\n> Hello Niklas,\n> \n> I have tested your patch on my board. The tests I performed were:\n> `LIBCAMERA_LOG_LEVELS=0 cam --camera=1 --capture=200 --file=~/test.raw`\n> * without the delayed ctrls and without this patch\n> * with the delayed ctrls and without this patch\n> * with the delayed ctrls and with this patch\n> \n> Here are some snippets of my tests: https://paste.debian.net/1181697/\n> \n> All in all, it looks way smoother with this patch.\n> \n> There is one thing that I noticed, that we might have to address in\n> another set of patches. When I run the command:\n> `cam --camera=1 --capture=200`, the cam command stops at 200 frames\n> without issues. If I start this command:\n> `cam --camera=1 --capture=200 --file=test.raw`, the cam command keeps\n> running until I `ctrl+c` it. While the output looks like this:\n> ```\n> 3969.152837 (4.29 fps) stream0 seq: 000381 bytesused: 5529600\n> [1:06:10.137876560] [7219] DEBUG V4L2 v4l2_videodevice.cpp:1440\n> /dev/video4[out]: Queueing buffer 0\n> [1:06:10.138091809] [7219] DEBUG V4L2 v4l2_videodevice.cpp:1440\n> /dev/video3[cap]: Queueing buffer 0\n> [1:06:10.138238808] [7219] DEBUG V4L2 v4l2_videodevice.cpp:1440\n> /dev/video1[cap]: Queueing buffer 0\n> [1:06:10.151352654] [7219] DEBUG V4L2 v4l2_videodevice.cpp:1509\n> /dev/video3[cap]: Dequeuing buffer 0\n> [1:06:10.151674944] [7219] DEBUG V4L2 v4l2_videodevice.cpp:1509\n> /dev/video4[out]: Dequeuing buffer 0\n> [1:06:10.153216102] [7219] DEBUG DelayedControls\n> delayed_controls.cpp:209 frame 412 started\n> [1:06:10.153342685] [7219] DEBUG DelayedControls\n> delayed_controls.cpp:239 Queue is empty, auto queue no-op.\n> [1:06:10.186488090] [7219] DEBUG DelayedControls\n> delayed_controls.cpp:209 frame 413 started\n> [1:06:10.186597173] [7219] DEBUG DelayedControls\n> delayed_controls.cpp:239 Queue is empty, auto queue no-op.\n> [1:06:10.217897505] [7219] DEBUG V4L2 v4l2_videodevice.cpp:1509\n> /dev/video1[cap]: Dequeuing buffer 0\n> [1:06:10.218134628] [7219] DEBUG Request request.cpp:266 Request has\n> completed - cookie: 0\n> [1:06:10.219763286] [7219] DEBUG DelayedControls\n> delayed_controls.cpp:209 frame 414 started\n> [1:06:10.219870619] [7219] DEBUG DelayedControls\n> delayed_controls.cpp:239 Queue is empty, auto queue no-op.\n> [1:06:10.253048107] [7219] DEBUG DelayedControls\n> delayed_controls.cpp:209 frame 415 started\n> [1:06:10.253153690] [7219] DEBUG DelayedControls\n> delayed_controls.cpp:239 Queue is empty, auto queue no-op.\n> [1:06:10.286324762] [7219] DEBUG DelayedControls\n> delayed_controls.cpp:209 frame 416 started\n> [1:06:10.286432094] [7219] DEBUG DelayedControls\n> delayed_controls.cpp:239 Queue is empty, auto queue no-op.\n> [1:06:10.319640791] [7219] DEBUG DelayedControls\n> delayed_controls.cpp:209 frame 417 started\n> [1:06:10.319792457] [7219] DEBUG DelayedControls\n> delayed_controls.cpp:239 Queue is empty, auto queue no-op.\n> [1:06:10.352930278] [7219] DEBUG DelayedControls\n> delayed_controls.cpp:209 frame 418 started\n> [1:06:10.353086319] [7219] DEBUG DelayedControls\n> delayed_controls.cpp:239 Queue is empty, auto queue no-op.\n> [1:06:10.386194683] [7219] DEBUG DelayedControls\n> delayed_controls.cpp:209 frame 419 started\n> [1:06:10.386338182] [7219] DEBUG DelayedControls\n> delayed_controls.cpp:239 Queue is empty, auto queue no-op.\n> 3969.452358 (3.34 fps) stream0 seq: 000390 bytesused: 5529600\n> ```\n\nInterestingly, I can reproduce it on my IPU3 pipeline device (of course\nnot with this patch).\nIf I am writing the file in a fast block device (like tmpfs) then I\ncan't see an issue.\nBut if I write it to an external USB drive, and force the role to be\nraw, then, I have the same behaviour :\n\n$> LIBCAMERA_LOG_LEVELS=*:0 cam --camera=1 --capture=200 -s role=raw\n--file=/media/jm/JM_USB/test.raw\n\n[24:14:13.898015939] [26821] DEBUG V4L2 v4l2_videodevice.cpp:1440\n/dev/video1[cap]: Queueing buffer 2\n[24:14:13.913085892] [26821] DEBUG DelayedControls\ndelayed_controls.cpp:214 frame 282 started\n[24:14:13.913251668] [26821] DEBUG DelayedControls\ndelayed_controls.cpp:244 Queue is empty, auto queue no-op.\n[24:14:13.945774836] [26821] DEBUG V4L2 v4l2_videodevice.cpp:1509\n/dev/video1[cap]: Dequeuing buffer 1\n[24:14:13.946118989] [26821] DEBUG Request request.cpp:266 Request has\ncompleted - cookie: 0\n[24:14:13.946337806] [26821] DEBUG DelayedControls\ndelayed_controls.cpp:214 frame 283 started\n[24:14:13.946444586] [26821] DEBUG DelayedControls\ndelayed_controls.cpp:244 Queue is empty, auto queue no-op.\n87253.845588 (15.00 fps) stream0 seq: 000279 bytesused: 6469632\n[24:14:13.979069027] [26821] DEBUG V4L2 v4l2_videodevice.cpp:1509\n/dev/video1[cap]: Dequeuing buffer 2\n[24:14:13.979201412] [26821] DEBUG Request request.cpp:266 Request has\ncompleted - cookie: 0\n[24:14:13.979840259] [26821] DEBUG DelayedControls\ndelayed_controls.cpp:214 frame 284 started\n[24:14:13.979938538] [26821] DEBUG DelayedControls\ndelayed_controls.cpp:244 Queue is empty, auto queue no-op.\n87253.878892 (30.03 fps) stream0 seq: 000280 bytesused: 6469632\n[24:14:14.013340775] [26821] DEBUG DelayedControls\ndelayed_controls.cpp:214 frame 285 started\n[24:14:14.013426832] [26821] DEBUG DelayedControls\ndelayed_controls.cpp:244 Queue is empty, auto queue no-op.\n87253.945623 (14.99 fps) stream0 seq: 000282 bytesused: 6469632\n[24:14:14.046635119] [26821] DEBUG DelayedControls\ndelayed_controls.cpp:214 frame 286 started\n[24:14:14.046801827] [26821] DEBUG DelayedControls\ndelayed_controls.cpp:244 Queue is empty, auto queue no-op.\n[24:14:14.080099336] [26821] DEBUG DelayedControls\ndelayed_controls.cpp:214 frame 287 started\n[24:14:14.080279361] [26821] DEBUG DelayedControls\ndelayed_controls.cpp:244 Queue is empty, auto queue no-op.\n87253.978990 (29.97 fps) stream0 seq: 000283 bytesused: 6469632\n[24:14:14.113361019] [26821] DEBUG DelayedControls\ndelayed_controls.cpp:214 frame 288 started\n[24:14:14.113535093] [26821] DEBUG DelayedControls\ndelayed_controls.cpp:244 Queue is empty, auto queue no-op.\n[24:14:14.146657763] [26821] DEBUG DelayedControls\ndelayed_controls.cpp:214 frame 289 started\n[24:14:14.146839192] [26821] DEBUG DelayedControls\ndelayed_controls.cpp:244 Queue is empty, auto queue no-op.\n[24:14:14.179926886] [26821] DEBUG DelayedControls\ndelayed_controls.cpp:214 frame 290 started\n[24:14:14.180116036] [26821] DEBUG DelayedControls\ndelayed_controls.cpp:244 Queue is empty, auto queue no-op.\n[24:14:14.213435640] [26821] DEBUG DelayedControls\ndelayed_controls.cpp:214 frame 291 started\n[24:14:14.213649312] [26821] DEBUG DelayedControls\ndelayed_controls.cpp:244 Queue is empty, auto queue no-op.\n[24:14:14.246721869] [26821] DEBUG DelayedControls\ndelayed_controls.cpp:214 frame 292 started\n...\n\nIt looks like it is related to DelayedControls but I can't find out\nwhy... yet :-)\nJM","headers":{"Return-Path":"","X-Original-To":"parsemail@patchwork.libcamera.org","Delivered-To":"parsemail@patchwork.libcamera.org","Received":["from lancelot.ideasonboard.com (lancelot.ideasonboard.com\n\t[92.243.16.209])\n\tby patchwork.libcamera.org (Postfix) with ESMTPS id CF588C0F1C\n\tfor ;\n\tTue, 19 Jan 2021 08:04:59 +0000 (UTC)","from lancelot.ideasonboard.com (localhost [IPv6:::1])\n\tby lancelot.ideasonboard.com (Postfix) with ESMTP id 5C7DD68138;\n\tTue, 19 Jan 2021 09:04:59 +0100 (CET)","from perceval.ideasonboard.com (perceval.ideasonboard.com\n\t[IPv6:2001:4b98:dc2:55:216:3eff:fef7:d647])\n\tby lancelot.ideasonboard.com (Postfix) with ESMTPS id A0C0460313\n\tfor ;\n\tTue, 19 Jan 2021 09:04:58 +0100 (CET)","from [IPv6:2a01:e0a:169:7140:5a68:3eab:6917:5f91] (unknown\n\t[IPv6:2a01:e0a:169:7140:5a68:3eab:6917:5f91])\n\tby perceval.ideasonboard.com (Postfix) with ESMTPSA id 37EE44FB;\n\tTue, 19 Jan 2021 09:04:58 +0100 (CET)"],"Authentication-Results":"lancelot.ideasonboard.com;\n\tdkim=fail reason=\"signature verification failed\" (1024-bit key;\n\tunprotected) header.d=ideasonboard.com header.i=@ideasonboard.com\n\theader.b=\"whcIVVlN\"; dkim-atps=neutral","DKIM-Signature":"v=1; a=rsa-sha256; c=relaxed/simple; d=ideasonboard.com;\n\ts=mail; t=1611043498;\n\tbh=9yT7+fQ1XkpemanohAG1IOQPrXlFnSoJMc4PHh4xjrM=;\n\th=Subject:To:Cc:References:From:Date:In-Reply-To:From;\n\tb=whcIVVlNE33hxeNOMWQMwRf5wh0tBZ2aA1CwSJxZDfTKiaL91J29eTl/DUYKub3do\n\tuPM/5hnMqMc2ovsK8LWPTIfymk6vwDToz22TN/6nUj3bxS8Bd61Xeape92rGozTPJn\n\tV72OrAj7J8wrKT0zdYlTPGBT1hywDb1bYOs7xMZs=","To":"Sebastian Fricke , =?utf-8?q?Niklas_S?=\n\t=?utf-8?b?w7ZkZXJsdW5k?= ","References":"<20210118140615.2332504-1-niklas.soderlund@ragnatech.se>\n\t<20210119062330.o6ys6dq3yve325u4@basti-TUXEDO-Book-XA1510>","From":"Jean-Michel Hautbois ","Message-ID":"","Date":"Tue, 19 Jan 2021 09:04:57 +0100","User-Agent":"Mozilla/5.0 (X11; Linux x86_64; rv:78.0) Gecko/20100101\n\tThunderbird/78.5.0","MIME-Version":"1.0","In-Reply-To":"<20210119062330.o6ys6dq3yve325u4@basti-TUXEDO-Book-XA1510>","Content-Language":"en-US","Subject":"Re: [libcamera-devel] [PATCH] libcamera: pipeline: rkisp1: Avoid\n\trace when processing parameter buffers","X-BeenThere":"libcamera-devel@lists.libcamera.org","X-Mailman-Version":"2.1.29","Precedence":"list","List-Id":"","List-Unsubscribe":",\n\t","List-Archive":"","List-Post":"","List-Help":"","List-Subscribe":",\n\t","Cc":"libcamera-devel@lists.libcamera.org","Content-Type":"text/plain; charset=\"us-ascii\"","Content-Transfer-Encoding":"7bit","Errors-To":"libcamera-devel-bounces@lists.libcamera.org","Sender":"\"libcamera-devel\" "}},{"id":14596,"web_url":"https://patchwork.libcamera.org/comment/14596/","msgid":"","date":"2021-01-19T12:06:15","subject":"Re: [libcamera-devel] [PATCH] libcamera: pipeline: rkisp1: Avoid\n\trace when processing parameter buffers","submitter":{"id":5,"url":"https://patchwork.libcamera.org/api/people/5/","name":"Niklas Söderlund","email":"niklas.soderlund@ragnatech.se"},"content":"Hi Sebastian,\n\nThanks for you feedback.\n\nOn 2021-01-19 07:23:30 +0100, Sebastian Fricke wrote:\n> Hello Niklas,\n> \n> I have tested your patch on my board. The tests I performed were:\n> `LIBCAMERA_LOG_LEVELS=0 cam --camera=1 --capture=200 --file=~/test.raw`\n> * without the delayed ctrls and without this patch\n> * with the delayed ctrls and without this patch\n> * with the delayed ctrls and with this patch\n> \n> Here are some snippets of my tests: https://paste.debian.net/1181697/\n> \n> All in all, it looks way smoother with this patch.\n\nNice catch!\n\nThis patch mitigates the problem you describe but reveals another \nproblem in cam's event loop. I believe the problem in cam is the true\nproblem in your report. While this patch is still needed for the \noriginal problem in the RkISP1 pipeline handler.\n\nI will post patches shortly to solve this issue as well in cam.\n\n> \n> There is one thing that I noticed, that we might have to address in\n> another set of patches. When I run the command:\n> `cam --camera=1 --capture=200`, the cam command stops at 200 frames\n> without issues. If I start this command:\n> `cam --camera=1 --capture=200 --file=test.raw`, the cam command keeps\n> running until I `ctrl+c` it. While the output looks like this:\n> ```\n> 3969.152837 (4.29 fps) stream0 seq: 000381 bytesused: 5529600\n> [1:06:10.137876560] [7219] DEBUG V4L2 v4l2_videodevice.cpp:1440 /dev/video4[out]: Queueing buffer 0\n> [1:06:10.138091809] [7219] DEBUG V4L2 v4l2_videodevice.cpp:1440 /dev/video3[cap]: Queueing buffer 0\n> [1:06:10.138238808] [7219] DEBUG V4L2 v4l2_videodevice.cpp:1440 /dev/video1[cap]: Queueing buffer 0\n> [1:06:10.151352654] [7219] DEBUG V4L2 v4l2_videodevice.cpp:1509 /dev/video3[cap]: Dequeuing buffer 0\n> [1:06:10.151674944] [7219] DEBUG V4L2 v4l2_videodevice.cpp:1509 /dev/video4[out]: Dequeuing buffer 0\n> [1:06:10.153216102] [7219] DEBUG DelayedControls delayed_controls.cpp:209 frame 412 started\n> [1:06:10.153342685] [7219] DEBUG DelayedControls delayed_controls.cpp:239 Queue is empty, auto queue no-op.\n> [1:06:10.186488090] [7219] DEBUG DelayedControls delayed_controls.cpp:209 frame 413 started\n> [1:06:10.186597173] [7219] DEBUG DelayedControls delayed_controls.cpp:239 Queue is empty, auto queue no-op.\n> [1:06:10.217897505] [7219] DEBUG V4L2 v4l2_videodevice.cpp:1509 /dev/video1[cap]: Dequeuing buffer 0\n> [1:06:10.218134628] [7219] DEBUG Request request.cpp:266 Request has completed - cookie: 0\n> [1:06:10.219763286] [7219] DEBUG DelayedControls delayed_controls.cpp:209 frame 414 started\n> [1:06:10.219870619] [7219] DEBUG DelayedControls delayed_controls.cpp:239 Queue is empty, auto queue no-op.\n> [1:06:10.253048107] [7219] DEBUG DelayedControls delayed_controls.cpp:209 frame 415 started\n> [1:06:10.253153690] [7219] DEBUG DelayedControls delayed_controls.cpp:239 Queue is empty, auto queue no-op.\n> [1:06:10.286324762] [7219] DEBUG DelayedControls delayed_controls.cpp:209 frame 416 started\n> [1:06:10.286432094] [7219] DEBUG DelayedControls delayed_controls.cpp:239 Queue is empty, auto queue no-op.\n> [1:06:10.319640791] [7219] DEBUG DelayedControls delayed_controls.cpp:209 frame 417 started\n> [1:06:10.319792457] [7219] DEBUG DelayedControls delayed_controls.cpp:239 Queue is empty, auto queue no-op.\n> [1:06:10.352930278] [7219] DEBUG DelayedControls \n> delayed_controls.cpp:209 frame 418 started\n> [1:06:10.353086319] [7219] DEBUG DelayedControls delayed_controls.cpp:239 Queue is empty, auto queue no-op.\n> [1:06:10.386194683] [7219] DEBUG DelayedControls delayed_controls.cpp:209 frame 419 started\n> [1:06:10.386338182] [7219] DEBUG DelayedControls delayed_controls.cpp:239 Queue is empty, auto queue no-op.\n> 3969.452358 (3.34 fps) stream0 seq: 000390 bytesused: 5529600\n> ```\n> \n> Anyway, this seems to be another issue, I have corrected two small typos\n> below. And if you like to you can add a:\n> Tested-by: Sebastian Fricke \n\nThanks.\n\n> \n> Greetings,\n> Sebastian\n> \n> On 18.01.2021 15:06, Niklas Söderlund wrote:\n> > When moving the pipeline away from the Timeline design it was discovered\n> > that the design of queuing the buffers to the device as soon as possible\n> > was not the best idea. The parameter buffers where queued to the device\n> \n> s/where queued/were queued/\n> \n> > before the IPA had processed them and this violates the V4L2 API.\n> > \n> > Fix this by waiting to queue any buffer to the device until the IPA have\n> \n> s/until the IPA have/until the IPA has/\n> \n> > filled in the parameters buffer.\n> > \n> > Signed-off-by: Niklas Söderlund \n> > ---\n> > Hello,\n> > \n> > This patch is based on-top of '[PATCH v5 0/8] libcamera: Add helper for\n> > controls that take effect with a delay' as the change is much cleaner\n> > on-top of the removal of the Timeline.\n> > ---\n> > src/libcamera/pipeline/rkisp1/rkisp1.cpp | 41 ++++++++----------------\n> > 1 file changed, 13 insertions(+), 28 deletions(-)\n> > \n> > diff --git a/src/libcamera/pipeline/rkisp1/rkisp1.cpp b/src/libcamera/pipeline/rkisp1/rkisp1.cpp\n> > index 58ae8f98a5c683d5..e85979a719b7ced6 100644\n> > --- a/src/libcamera/pipeline/rkisp1/rkisp1.cpp\n> > +++ b/src/libcamera/pipeline/rkisp1/rkisp1.cpp\n> > @@ -51,7 +51,6 @@ struct RkISP1FrameInfo {\n> > \tFrameBuffer *mainPathBuffer;\n> > \tFrameBuffer *selfPathBuffer;\n> > \n> > -\tbool paramFilled;\n> > \tbool paramDequeued;\n> > \tbool metadataProcessed;\n> > };\n> > @@ -219,7 +218,6 @@ RkISP1FrameInfo *RkISP1Frames::create(const RkISP1CameraData *data, Request *req\n> > \tinfo->mainPathBuffer = mainPathBuffer;\n> > \tinfo->selfPathBuffer = selfPathBuffer;\n> > \tinfo->statBuffer = statBuffer;\n> > -\tinfo->paramFilled = false;\n> > \tinfo->paramDequeued = false;\n> > \tinfo->metadataProcessed = false;\n> > \n> > @@ -322,9 +320,20 @@ void RkISP1CameraData::queueFrameAction(unsigned int frame,\n> > \t\tbreak;\n> > \t}\n> > \tcase RKISP1_IPA_ACTION_PARAM_FILLED: {\n> > +\t\tPipelineHandlerRkISP1 *pipe = static_cast(pipe_);\n> > \t\tRkISP1FrameInfo *info = frameInfo_.find(frame);\n> > -\t\tif (info)\n> > -\t\t\tinfo->paramFilled = true;\n> > +\t\tif (!info)\n> > +\t\t\tbreak;\n> > +\n> > +\t\tpipe->param_->queueBuffer(info->paramBuffer);\n> > +\t\tpipe->stat_->queueBuffer(info->statBuffer);\n> > +\n> > +\t\tif (info->mainPathBuffer)\n> > +\t\t\tmainPath_->queueBuffer(info->mainPathBuffer);\n> > +\n> > +\t\tif (info->selfPathBuffer)\n> > +\t\t\tselfPath_->queueBuffer(info->selfPathBuffer);\n> > +\n> > \t\tbreak;\n> > \t}\n> > \tcase RKISP1_IPA_ACTION_METADATA:\n> > @@ -852,15 +861,6 @@ int PipelineHandlerRkISP1::queueRequestDevice(Camera *camera, Request *request)\n> > \top.controls = { request->controls() };\n> > \tdata->ipa_->processEvent(op);\n> > \n> > -\tparam_->queueBuffer(info->paramBuffer);\n> > -\tstat_->queueBuffer(info->statBuffer);\n> > -\n> > -\tif (info->mainPathBuffer)\n> > -\t\tmainPath_.queueBuffer(info->mainPathBuffer);\n> > -\n> > -\tif (info->selfPathBuffer)\n> > -\t\tselfPath_.queueBuffer(info->selfPathBuffer);\n> > -\n> > \tdata->frame_++;\n> > \n> > \treturn 0;\n> > @@ -1009,7 +1009,6 @@ bool PipelineHandlerRkISP1::match(DeviceEnumerator *enumerator)\n> > \tmainPath_.bufferReady().connect(this, &PipelineHandlerRkISP1::bufferReady);\n> > \tselfPath_.bufferReady().connect(this, &PipelineHandlerRkISP1::bufferReady);\n> > \tstat_->bufferReady.connect(this, &PipelineHandlerRkISP1::statReady);\n> > -\tisp_->frameStart.connect(this, &PipelineHandlerRkISP1::frameStart);\n> > \tparam_->bufferReady.connect(this, &PipelineHandlerRkISP1::paramReady);\n> > \n> > \t/*\n> > @@ -1097,20 +1096,6 @@ void PipelineHandlerRkISP1::statReady(FrameBuffer *buffer)\n> > \tdata->ipa_->processEvent(op);\n> > }\n> > \n> > -void PipelineHandlerRkISP1::frameStart(uint32_t sequence)\n> > -{\n> > -\tif (!activeCamera_)\n> > -\t\treturn;\n> > -\n> > -\tRkISP1CameraData *data = cameraData(activeCamera_);\n> > -\n> > -\tRkISP1FrameInfo *info = data->frameInfo_.find(sequence);\n> > -\tif (!info || !info->paramFilled)\n> > -\t\tLOG(RkISP1, Info)\n> > -\t\t\t<< \"Parameters not ready on time for frame \"\n> > -\t\t\t<< sequence;\n> > -}\n> > -\n> > REGISTER_PIPELINE_HANDLER(PipelineHandlerRkISP1)\n> > \n> > } /* namespace libcamera */\n> > -- \n> > 2.30.0\n> > \n> > _______________________________________________\n> > libcamera-devel mailing list\n> > libcamera-devel@lists.libcamera.org\n> > https://lists.libcamera.org/listinfo/libcamera-devel","headers":{"Return-Path":"","X-Original-To":"parsemail@patchwork.libcamera.org","Delivered-To":"parsemail@patchwork.libcamera.org","Received":["from lancelot.ideasonboard.com (lancelot.ideasonboard.com\n\t[92.243.16.209])\n\tby patchwork.libcamera.org (Postfix) with ESMTPS id 07A3EBD808\n\tfor ;\n\tTue, 19 Jan 2021 12:06:25 +0000 (UTC)","from lancelot.ideasonboard.com (localhost [IPv6:::1])\n\tby lancelot.ideasonboard.com (Postfix) with ESMTP id 74CC36813F;\n\tTue, 19 Jan 2021 13:06:24 +0100 (CET)","from mail-lf1-x132.google.com (mail-lf1-x132.google.com\n\t[IPv6:2a00:1450:4864:20::132])\n\tby lancelot.ideasonboard.com (Postfix) with ESMTPS id 4C0F060314\n\tfor ;\n\tTue, 19 Jan 2021 13:06:19 +0100 (CET)","by mail-lf1-x132.google.com with SMTP id v67so28725952lfa.0\n\tfor ;\n\tTue, 19 Jan 2021 04:06:19 -0800 (PST)","from localhost (h-209-203.A463.priv.bahnhof.se. [155.4.209.203])\n\tby smtp.gmail.com with ESMTPSA id\n\th23sm2259851lfc.246.2021.01.19.04.06.17\n\t(version=TLS1_3 cipher=TLS_AES_256_GCM_SHA384 bits=256/256);\n\tTue, 19 Jan 2021 04:06:17 -0800 (PST)"],"Authentication-Results":"lancelot.ideasonboard.com;\n\tdkim=fail reason=\"signature verification failed\" (2048-bit key;\n\tunprotected) header.d=ragnatech-se.20150623.gappssmtp.com\n\theader.i=@ragnatech-se.20150623.gappssmtp.com\n\theader.b=\"FjqarI4b\"; dkim-atps=neutral","DKIM-Signature":"v=1; a=rsa-sha256; c=relaxed/relaxed;\n\td=ragnatech-se.20150623.gappssmtp.com; s=20150623;\n\th=date:from:to:cc:subject:message-id:references:mime-version\n\t:content-disposition:content-transfer-encoding:in-reply-to;\n\tbh=DMgZOzZAo92t9iypjVwTtiiImVHk7R61VOqwlKOrK0U=;\n\tb=FjqarI4be9U9H0e5AhFUfomEz4XNyS1/ZqBQWlaMES5PuzxzVd4HjR4H/HUCh3IF6q\n\tWdKKokSGIfmKwjRPQJS0oCQ12AisP8R0CuYYy2aSdkH4wDn5BSOjRwuHrefRmXvbaJCm\n\ttp/sZznM3vLI8R/FgrSo22OHAZCt37iXgLOAGV8OHewHqxq1xfl1loDasO0yk7d60UjW\n\tw/ceyvqw4iSdjpQKAN2f8oQVBvz0oEYIWuKi9nb7xnPjlYiw+QqeftM8NTcXP4b3Cjfk\n\tz2luoG4TxyYEm5vFHzxoHB6f7/l9r3awCXMO2rB46eQz1lSV4odNWjkURIYzvE0sByvr\n\tk6HQ==","X-Google-DKIM-Signature":"v=1; a=rsa-sha256; c=relaxed/relaxed;\n\td=1e100.net; s=20161025;\n\th=x-gm-message-state:date:from:to:cc:subject:message-id:references\n\t:mime-version:content-disposition:content-transfer-encoding\n\t:in-reply-to;\n\tbh=DMgZOzZAo92t9iypjVwTtiiImVHk7R61VOqwlKOrK0U=;\n\tb=WEH+umRfN1JOMq4de3lERuEbi84pa3eIOutclTcJ3DglR8Uzg+ARZZ8WDbhrcc5zwE\n\tcK3JSMQfrVLZFB7HYx/LcUaxulu3Yr36g99OhOiUKRWYTwDmXlAoX64AA5N2yMnJK2B9\n\t8BIHBepnTNi2ixQ4rXnajZ31WIB+qGcEmyXhvK85vuLgzoDAAt7d9Uae9d4I7jwNPlVT\n\tKoAdBIyG7YHNbudeeO4YgVY8KOi8K3Kj8Zh0s5GkzytlTZZewJMV96lOmL50BbuIPu5f\n\tKNGIRkks1V6qTINGpwSYCCk403bbPsqmY8WVvOV6pA58+HMWOz0bHhmw9zb+pNyqp+R9\n\txUvw==","X-Gm-Message-State":"AOAM531BPHbB9J4oCzxqvLTtmupr4t2maLiYSrytQDReGj2FoirD1i8p\n\t8PiBEwLjDl2kHpRPTBI0VyUqHw==","X-Google-Smtp-Source":"ABdhPJw5Yql8vdL9xq3m3jq78QmyeS9zCSt/eWGnFoj0WOl+TGXzF3czS4rBL7Z4dDek9DcFZRTgYQ==","X-Received":"by 2002:a19:4054:: with SMTP id\n\tn81mr1827090lfa.458.1611057978471; \n\tTue, 19 Jan 2021 04:06:18 -0800 (PST)","Date":"Tue, 19 Jan 2021 13:06:15 +0100","From":"Niklas =?iso-8859-1?q?S=F6derlund?= ","To":"Sebastian Fricke ","Message-ID":"","References":"<20210118140615.2332504-1-niklas.soderlund@ragnatech.se>\n\t<20210119062330.o6ys6dq3yve325u4@basti-TUXEDO-Book-XA1510>","MIME-Version":"1.0","Content-Disposition":"inline","In-Reply-To":"<20210119062330.o6ys6dq3yve325u4@basti-TUXEDO-Book-XA1510>","Subject":"Re: [libcamera-devel] [PATCH] libcamera: pipeline: rkisp1: Avoid\n\trace when processing parameter buffers","X-BeenThere":"libcamera-devel@lists.libcamera.org","X-Mailman-Version":"2.1.29","Precedence":"list","List-Id":"","List-Unsubscribe":",\n\t","List-Archive":"","List-Post":"","List-Help":"","List-Subscribe":",\n\t","Cc":"libcamera-devel@lists.libcamera.org","Content-Type":"text/plain; charset=\"iso-8859-1\"","Content-Transfer-Encoding":"quoted-printable","Errors-To":"libcamera-devel-bounces@lists.libcamera.org","Sender":"\"libcamera-devel\" "}},{"id":14606,"web_url":"https://patchwork.libcamera.org/comment/14606/","msgid":"","date":"2021-01-19T15:30:56","subject":"Re: [libcamera-devel] [PATCH] libcamera: pipeline: rkisp1: Avoid\n\trace when processing parameter buffers","submitter":{"id":5,"url":"https://patchwork.libcamera.org/api/people/5/","name":"Niklas Söderlund","email":"niklas.soderlund@ragnatech.se"},"content":"Hello Jean-Michel,\n\nThanks for your feedback.\n\nOn 2021-01-19 09:04:57 +0100, Jean-Michel Hautbois wrote:\n\n\n\n> \n> Interestingly, I can reproduce it on my IPU3 pipeline device (of course\n> not with this patch).\n> If I am writing the file in a fast block device (like tmpfs) then I\n> can't see an issue.\n> But if I write it to an external USB drive, and force the role to be\n> raw, then, I have the same behaviour :\n> \n> $> LIBCAMERA_LOG_LEVELS=*:0 cam --camera=1 --capture=200 -s role=raw\n> --file=/media/jm/JM_USB/test.raw\n\nI have reproduced this issue based on-top of your test-ipu3-ae-stats\nbranch and as you say I can observer that writing RAW frames to a USB \nstick gets slower over time (no big surprise as the writhe cache gets \nfull :-) But the expected number of frames do get written to the USB \neventually. As a reference in my tests I rather quickly end up at around \njust under 0.3 FPS.\n\nWith the --capture=200 option and without the bugfix in [1] \n203 frames are written to the USB stick and cam hangs. With the bugfix \nfor cam added on-top of your work I do get the expected 200 frames and \nthe cam terminates. Are you experience any other issues that it's dead \nslow?\n\nWith [1] applied (so that is correct cam behavior of writing 200 frames \nto the USB) running on CrOS,\n\n$ rm -f /mnt/usb/abc.raw && sync && time cam --camera=1 --capture=200 -s role=raw --file=/mnt/usb/abc.raw\n\n3249.220644 (0.29 fps) stream0 seq: 012686 bytesused: 17059840\n3252.860304 (0.27 fps) stream0 seq: 012795 bytesused: 17059840\n3256.767112 (0.26 fps) stream0 seq: 012912 bytesused: 17059840\n3260.173049 (0.29 fps) stream0 seq: 013014 bytesused: 17059840\n3263.111829 (0.34 fps) stream0 seq: 013102 bytesused: 17059840\n3266.283734 (0.32 fps) stream0 seq: 013197 bytesused: 17059840\n3269.589472 (0.30 fps) stream0 seq: 013296 bytesused: 17059840\n3272.861826 (0.31 fps) stream0 seq: 013394 bytesused: 17059840\n3276.167671 (0.30 fps) stream0 seq: 013493 bytesused: 17059840\n3280.174598 (0.25 fps) stream0 seq: 013613 bytesused: 17059840\n3284.949541 (0.21 fps) stream0 seq: 013756 bytesused: 17059840\n3288.388970 (0.29 fps) stream0 seq: 013859 bytesused: 17059840\n3291.527759 (0.32 fps) stream0 seq: 013953 bytesused: 17059840\n3294.633184 (0.32 fps) stream0 seq: 014046 bytesused: 17059840\n3297.805284 (0.32 fps) stream0 seq: 014141 bytesused: 17059840\n3300.944136 (0.32 fps) stream0 seq: 014235 bytesused: 17059840\n3304.183093 (0.31 fps) stream0 seq: 014332 bytesused: 17059840\n3307.889588 (0.27 fps) stream0 seq: 014443 bytesused: 17059840\n3311.696245 (0.26 fps) stream0 seq: 014557 bytesused: 17059840\n3315.035314 (0.30 fps) stream0 seq: 014657 bytesused: 17059840\n\nreal\t8m23.083s\nuser\t0m4.317s\nsys\t0m8.940s\n\nSize of each buffer is 17059840 => expected file size 17059840 * 200 = \n3411968000, which checks out.\n\n$ ls -l /mnt/usb/abc.raw\n-rw-r--r--. 1 root root 3411968000 Jan 19 16:12 /mnt/usb/abc.raw\n\nTotal time was ~ 8min 23 sec => 503 seconds. That gives a wall clock \nwrite speed of 3411968000 / 503 => ~ 6783237 bytes / sec or 6.46 Mbit / \nsec. It's not a completely fair comparison but simulated workload using \ndd to get some ballpark numbers,\n\n$ rm -f /mnt/usb/abc.raw && sync && time dd if=/dev/urandom of=/mnt/usb/abc.raw bs=17059840 count=200 status=progress\n3411968000 bytes (3.4 GB, 3.2 GiB) copied, 494.853 s, 6.9 MB/s \n200+0 records in\n200+0 records out\n3411968000 bytes (3.4 GB, 3.2 GiB) copied, 494.853 s, 6.9 MB/s\n\nreal\t8m14.884s\nuser\t0m0.004s\nsys\t2m29.831s\n\nSo I'd say cam does an OK job of pushing frames to USB stick. That \nlibcamera informs you it's probably not what you want is a different \nstory ;-)\n\n\n\n> [24:14:14.213435640] [26821] DEBUG DelayedControls\n> delayed_controls.cpp:214 frame 291 started\n> [24:14:14.213649312] [26821] DEBUG DelayedControls\n> delayed_controls.cpp:244 Queue is empty, auto queue no-op.\n> [24:14:14.246721869] [26821] DEBUG DelayedControls\n> delayed_controls.cpp:214 frame 292 started\n> ...\n> \n> It looks like it is related to DelayedControls but I can't find out\n> why... yet :-)\n> JM\n\nWell yes and no. The DEBUG messages you see are indeed from \nDelayedControls, it's a cry for help informing the user that it's in a \nunder-run situation and that it can't perform the operations it's asked \nto do as the something is not feeding the camera fast enough (in this \ncase the cam application). But if you let it run for enough time the cam \napplication will correctly capture the frames to the USB stick but even \nwith complete IPA the quality of them would likely be bad due to the low \nfrequency in the control loop :-)\n\nA similar patch as this one for IPU3 is needed for other reasons and it \nwill \"hide\" some of the \"Queue is empty\" messages. Not because it makes \nthe situation any better for a control loop starved of resource, but as\nwe get better control on when we queue buffers so we won't even attempt \nto do anything i this scenario :-)\n\n1. [PATCH 0/2] cam: Fix races in event loop and long request processing times","headers":{"Return-Path":"","X-Original-To":"parsemail@patchwork.libcamera.org","Delivered-To":"parsemail@patchwork.libcamera.org","Received":["from lancelot.ideasonboard.com (lancelot.ideasonboard.com\n\t[92.243.16.209])\n\tby patchwork.libcamera.org (Postfix) with ESMTPS id 11B6AC0F1C\n\tfor ;\n\tTue, 19 Jan 2021 15:31:00 +0000 (UTC)","from lancelot.ideasonboard.com (localhost [IPv6:::1])\n\tby lancelot.ideasonboard.com (Postfix) with ESMTP id D0AAC6815F;\n\tTue, 19 Jan 2021 16:30:59 +0100 (CET)","from mail-lf1-x12c.google.com (mail-lf1-x12c.google.com\n\t[IPv6:2a00:1450:4864:20::12c])\n\tby lancelot.ideasonboard.com (Postfix) with ESMTPS id C049F6815B\n\tfor ;\n\tTue, 19 Jan 2021 16:30:58 +0100 (CET)","by mail-lf1-x12c.google.com with SMTP id q12so2600245lfo.12\n\tfor ;\n\tTue, 19 Jan 2021 07:30:58 -0800 (PST)","from localhost (h-209-203.A463.priv.bahnhof.se. [155.4.209.203])\n\tby smtp.gmail.com with ESMTPSA id\n\tl6sm233253ljg.119.2021.01.19.07.30.57\n\t(version=TLS1_3 cipher=TLS_AES_256_GCM_SHA384 bits=256/256);\n\tTue, 19 Jan 2021 07:30:57 -0800 (PST)"],"Authentication-Results":"lancelot.ideasonboard.com;\n\tdkim=fail reason=\"signature verification failed\" (2048-bit key;\n\tunprotected) header.d=ragnatech-se.20150623.gappssmtp.com\n\theader.i=@ragnatech-se.20150623.gappssmtp.com\n\theader.b=\"ykyRjYaW\"; dkim-atps=neutral","DKIM-Signature":"v=1; a=rsa-sha256; c=relaxed/relaxed;\n\td=ragnatech-se.20150623.gappssmtp.com; s=20150623;\n\th=date:from:to:cc:subject:message-id:references:mime-version\n\t:content-disposition:content-transfer-encoding:in-reply-to;\n\tbh=7skgITR2+XT+XcsqRIK2L744YUwZLZH555HF4iTMU7k=;\n\tb=ykyRjYaW2U/OQp/lEZ5aDUS7XGaXpjCqTrBxrM1Z3xTZSn9Nm20bsjV5cYVuubB3+e\n\tzEFREcXnyaSTo6WvMhs3NmJSNq58+bqh4VGO49j1LM+weqL427PsxebAzZgib4/vmr4r\n\tgyv09Jxhz+u1cAqhbCluezNEDxINGa7iqT/L8DVaD+VGBw8WwrS+eVoKCwkOYcDHtwKE\n\t2NNv7pYLZHxe72VgbODvseuL0udjDhbZgVnfNvVA7PuwtE6wIus1pWVIpFo/qaqFl8iJ\n\tei0qQMqIws5KTzqhlmsCrFeF1rt3P0hu6JLaezW4kt43yKK2jISAuoJ7yFIQP4oEaom9\n\ttj0g==","X-Google-DKIM-Signature":"v=1; a=rsa-sha256; c=relaxed/relaxed;\n\td=1e100.net; s=20161025;\n\th=x-gm-message-state:date:from:to:cc:subject:message-id:references\n\t:mime-version:content-disposition:content-transfer-encoding\n\t:in-reply-to;\n\tbh=7skgITR2+XT+XcsqRIK2L744YUwZLZH555HF4iTMU7k=;\n\tb=R8sWeI5H9p1/F1B7xkJ9+SVEma/5xNOrqaXHCmCKy0jXM8Av39lbVhfGlTjGIdHGfG\n\th72x8CGse5otKyI5/hCuq1kXo2KZ45XsKNKyMosx/jRs3PrbBYUCWOuDvagKk/LgGMD0\n\tteFetFPhfSK2bPC/hAljdtgTNWszvAxpu96SxOAoaTRPLsApMA30efFEG5pO5zW/Y7dF\n\t+eRGxJi0lkcc6XdGKbQX/vxbAgzo50Yjh3sGZ+3RXOMJxmD1aZDcYLGi+jD2MVKv85ey\n\tf+pFvMFZ0wyPyFfMtfOjduw040Ya6nL0qhTPV1p9x0JM5NdgdPL17uSwwQje1LnQLqw3\n\tcdUg==","X-Gm-Message-State":"AOAM532Z40D6Y90PxyonBf4GeEMOrfUT8JzPLP7BHDf/qEisNddM3cVQ\n\tLR6GBoQIYxyAWMiKT/isbTv6xg==","X-Google-Smtp-Source":"ABdhPJylTED1B9WcIwT58fBRCZ68EcPDCS5L2OFOG825Mx4OPiQ5O5heO75cmgYz7n+BooL93gtUoQ==","X-Received":"by 2002:a19:385e:: with SMTP id\n\td30mr2292758lfj.187.1611070258222; \n\tTue, 19 Jan 2021 07:30:58 -0800 (PST)","Date":"Tue, 19 Jan 2021 16:30:56 +0100","From":"Niklas =?iso-8859-1?q?S=F6derlund?= ","To":"Jean-Michel Hautbois ","Message-ID":"","References":"<20210118140615.2332504-1-niklas.soderlund@ragnatech.se>\n\t<20210119062330.o6ys6dq3yve325u4@basti-TUXEDO-Book-XA1510>\n\t","MIME-Version":"1.0","Content-Disposition":"inline","In-Reply-To":"","Subject":"Re: [libcamera-devel] [PATCH] libcamera: pipeline: rkisp1: Avoid\n\trace when processing parameter buffers","X-BeenThere":"libcamera-devel@lists.libcamera.org","X-Mailman-Version":"2.1.29","Precedence":"list","List-Id":"","List-Unsubscribe":",\n\t","List-Archive":"","List-Post":"","List-Help":"","List-Subscribe":",\n\t","Cc":"libcamera-devel@lists.libcamera.org","Content-Type":"text/plain; charset=\"iso-8859-1\"","Content-Transfer-Encoding":"quoted-printable","Errors-To":"libcamera-devel-bounces@lists.libcamera.org","Sender":"\"libcamera-devel\" "}},{"id":14609,"web_url":"https://patchwork.libcamera.org/comment/14609/","msgid":"","date":"2021-01-19T16:28:42","subject":"Re: [libcamera-devel] [PATCH] libcamera: pipeline: rkisp1: Avoid\n\trace when processing parameter buffers","submitter":{"id":2,"url":"https://patchwork.libcamera.org/api/people/2/","name":"Laurent Pinchart","email":"laurent.pinchart@ideasonboard.com"},"content":"Hi Niklas,\n\nThank you for the patch.\n\nOn Mon, Jan 18, 2021 at 03:06:15PM +0100, Niklas Söderlund wrote:\n> When moving the pipeline away from the Timeline design it was discovered\n> that the design of queuing the buffers to the device as soon as possible\n> was not the best idea. The parameter buffers where queued to the device\n> before the IPA had processed them and this violates the V4L2 API.\n> \n> Fix this by waiting to queue any buffer to the device until the IPA have\n> filled in the parameters buffer.\n> \n> Signed-off-by: Niklas Söderlund \n> ---\n> Hello,\n> \n> This patch is based on-top of '[PATCH v5 0/8] libcamera: Add helper for\n> controls that take effect with a delay' as the change is much cleaner\n> on-top of the removal of the Timeline.\n\nIt should probably be squashed in the appropriate patch from that\nseries.\n\n> ---\n> src/libcamera/pipeline/rkisp1/rkisp1.cpp | 41 ++++++++----------------\n> 1 file changed, 13 insertions(+), 28 deletions(-)\n> \n> diff --git a/src/libcamera/pipeline/rkisp1/rkisp1.cpp b/src/libcamera/pipeline/rkisp1/rkisp1.cpp\n> index 58ae8f98a5c683d5..e85979a719b7ced6 100644\n> --- a/src/libcamera/pipeline/rkisp1/rkisp1.cpp\n> +++ b/src/libcamera/pipeline/rkisp1/rkisp1.cpp\n> @@ -51,7 +51,6 @@ struct RkISP1FrameInfo {\n> \tFrameBuffer *mainPathBuffer;\n> \tFrameBuffer *selfPathBuffer;\n> \n> -\tbool paramFilled;\n> \tbool paramDequeued;\n> \tbool metadataProcessed;\n> };\n> @@ -219,7 +218,6 @@ RkISP1FrameInfo *RkISP1Frames::create(const RkISP1CameraData *data, Request *req\n> \tinfo->mainPathBuffer = mainPathBuffer;\n> \tinfo->selfPathBuffer = selfPathBuffer;\n> \tinfo->statBuffer = statBuffer;\n> -\tinfo->paramFilled = false;\n> \tinfo->paramDequeued = false;\n> \tinfo->metadataProcessed = false;\n> \n> @@ -322,9 +320,20 @@ void RkISP1CameraData::queueFrameAction(unsigned int frame,\n> \t\tbreak;\n> \t}\n> \tcase RKISP1_IPA_ACTION_PARAM_FILLED: {\n> +\t\tPipelineHandlerRkISP1 *pipe = static_cast(pipe_);\n> \t\tRkISP1FrameInfo *info = frameInfo_.find(frame);\n> -\t\tif (info)\n> -\t\t\tinfo->paramFilled = true;\n> +\t\tif (!info)\n> +\t\t\tbreak;\n> +\n> +\t\tpipe->param_->queueBuffer(info->paramBuffer);\n> +\t\tpipe->stat_->queueBuffer(info->statBuffer);\n> +\n> +\t\tif (info->mainPathBuffer)\n> +\t\t\tmainPath_->queueBuffer(info->mainPathBuffer);\n> +\n> +\t\tif (info->selfPathBuffer)\n> +\t\t\tselfPath_->queueBuffer(info->selfPathBuffer);\n> +\n\nThe IPA generates RKISP1_IPA_ACTION_PARAM_FILLED when the request is\nqueued to the IPA, so the buffers will be queued early to the driver,\nensuring we won't have a queue underrun.\n\nReviewed-by: Laurent Pinchart \n\nHowever, this means that the IPA will fill the parameters buffer with\ndata that is based on much earlier frames. We'll need to find a proper\nmiddleground here, waiting as long as possible before asking the IPA for\nparameters, but not too long to ensure we won't get underruns.\n\n> \t\tbreak;\n> \t}\n> \tcase RKISP1_IPA_ACTION_METADATA:\n> @@ -852,15 +861,6 @@ int PipelineHandlerRkISP1::queueRequestDevice(Camera *camera, Request *request)\n> \top.controls = { request->controls() };\n> \tdata->ipa_->processEvent(op);\n> \n> -\tparam_->queueBuffer(info->paramBuffer);\n> -\tstat_->queueBuffer(info->statBuffer);\n> -\n> -\tif (info->mainPathBuffer)\n> -\t\tmainPath_.queueBuffer(info->mainPathBuffer);\n> -\n> -\tif (info->selfPathBuffer)\n> -\t\tselfPath_.queueBuffer(info->selfPathBuffer);\n> -\n> \tdata->frame_++;\n> \n> \treturn 0;\n> @@ -1009,7 +1009,6 @@ bool PipelineHandlerRkISP1::match(DeviceEnumerator *enumerator)\n> \tmainPath_.bufferReady().connect(this, &PipelineHandlerRkISP1::bufferReady);\n> \tselfPath_.bufferReady().connect(this, &PipelineHandlerRkISP1::bufferReady);\n> \tstat_->bufferReady.connect(this, &PipelineHandlerRkISP1::statReady);\n> -\tisp_->frameStart.connect(this, &PipelineHandlerRkISP1::frameStart);\n> \tparam_->bufferReady.connect(this, &PipelineHandlerRkISP1::paramReady);\n> \n> \t/*\n> @@ -1097,20 +1096,6 @@ void PipelineHandlerRkISP1::statReady(FrameBuffer *buffer)\n> \tdata->ipa_->processEvent(op);\n> }\n> \n> -void PipelineHandlerRkISP1::frameStart(uint32_t sequence)\n> -{\n> -\tif (!activeCamera_)\n> -\t\treturn;\n> -\n> -\tRkISP1CameraData *data = cameraData(activeCamera_);\n> -\n> -\tRkISP1FrameInfo *info = data->frameInfo_.find(sequence);\n> -\tif (!info || !info->paramFilled)\n> -\t\tLOG(RkISP1, Info)\n> -\t\t\t<< \"Parameters not ready on time for frame \"\n> -\t\t\t<< sequence;\n> -}\n> -\n> REGISTER_PIPELINE_HANDLER(PipelineHandlerRkISP1)\n> \n> } /* namespace libcamera */","headers":{"Return-Path":"","X-Original-To":"parsemail@patchwork.libcamera.org","Delivered-To":"parsemail@patchwork.libcamera.org","Received":["from lancelot.ideasonboard.com (lancelot.ideasonboard.com\n\t[92.243.16.209])\n\tby patchwork.libcamera.org (Postfix) with ESMTPS id 06802BD808\n\tfor ;\n\tTue, 19 Jan 2021 16:29:02 +0000 (UTC)","from lancelot.ideasonboard.com (localhost [IPv6:::1])\n\tby lancelot.ideasonboard.com (Postfix) with ESMTP id 81A6B68161;\n\tTue, 19 Jan 2021 17:29:01 +0100 (CET)","from perceval.ideasonboard.com (perceval.ideasonboard.com\n\t[213.167.242.64])\n\tby lancelot.ideasonboard.com (Postfix) with ESMTPS id 555A26814E\n\tfor ;\n\tTue, 19 Jan 2021 17:29:00 +0100 (CET)","from pendragon.ideasonboard.com (62-78-145-57.bb.dnainternet.fi\n\t[62.78.145.57])\n\tby perceval.ideasonboard.com (Postfix) with ESMTPSA id BC071813;\n\tTue, 19 Jan 2021 17:28:59 +0100 (CET)"],"Authentication-Results":"lancelot.ideasonboard.com;\n\tdkim=fail reason=\"signature verification failed\" (1024-bit key;\n\tunprotected) header.d=ideasonboard.com header.i=@ideasonboard.com\n\theader.b=\"KgO4F0vz\"; dkim-atps=neutral","DKIM-Signature":"v=1; a=rsa-sha256; c=relaxed/simple; d=ideasonboard.com;\n\ts=mail; t=1611073740;\n\tbh=GU67BWJwC46qBn072CDgFsnmR1szduF/0IFqK6l+Dt8=;\n\th=Date:From:To:Cc:Subject:References:In-Reply-To:From;\n\tb=KgO4F0vzUq3IBi024MNzcoynUwyLsJVGdmrmbbD86yZn+I1iVHO81vWi4vSTYYwXH\n\tWxLItiBf3IWF9WXQfI0nU1v3IGN64+FEi7iIGn1jLc2Dz+YqTU4n1FrGDjEE/JVPQ2\n\tdX8lzkz4skjH6dVFyKFD9Lzm28K4Gl69LfV/oppI=","Date":"Tue, 19 Jan 2021 18:28:42 +0200","From":"Laurent Pinchart ","To":"Niklas =?utf-8?q?S=C3=B6derlund?= ","Message-ID":"","References":"<20210118140615.2332504-1-niklas.soderlund@ragnatech.se>","MIME-Version":"1.0","Content-Disposition":"inline","In-Reply-To":"<20210118140615.2332504-1-niklas.soderlund@ragnatech.se>","Subject":"Re: [libcamera-devel] [PATCH] libcamera: pipeline: rkisp1: Avoid\n\trace when processing parameter buffers","X-BeenThere":"libcamera-devel@lists.libcamera.org","X-Mailman-Version":"2.1.29","Precedence":"list","List-Id":"","List-Unsubscribe":",\n\t","List-Archive":"","List-Post":"","List-Help":"","List-Subscribe":",\n\t","Cc":"libcamera-devel@lists.libcamera.org","Content-Type":"text/plain; charset=\"utf-8\"","Content-Transfer-Encoding":"base64","Errors-To":"libcamera-devel-bounces@lists.libcamera.org","Sender":"\"libcamera-devel\" "}}]