| Message ID | 20210118140615.2332504-1-niklas.soderlund@ragnatech.se |
|---|---|
| State | Accepted |
| Commit | 3809fd77463f8f9f30d8da56fc3b103c683fba72 |
| Delegated to: | Niklas Söderlund |
| Headers | show |
| Series |
|
| Related | show |
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 ``` Anyway, this seems to be another issue, I have corrected two small typos below. And if you like to you can add a: Tested-by: Sebastian Fricke <sebastian.fricke@posteo.net> Greetings, Sebastian On 18.01.2021 15:06, Niklas Söderlund wrote: >When moving the pipeline away from the Timeline design it was discovered >that the design of queuing the buffers to the device as soon as possible >was not the best idea. The parameter buffers where queued to the device s/where queued/were queued/ >before the IPA had processed them and this violates the V4L2 API. > >Fix this by waiting to queue any buffer to the device until the IPA have s/until the IPA have/until the IPA has/ >filled in the parameters buffer. > >Signed-off-by: Niklas Söderlund <niklas.soderlund@ragnatech.se> >--- >Hello, > >This patch is based on-top of '[PATCH v5 0/8] libcamera: Add helper for >controls that take effect with a delay' as the change is much cleaner >on-top of the removal of the Timeline. >--- > src/libcamera/pipeline/rkisp1/rkisp1.cpp | 41 ++++++++---------------- > 1 file changed, 13 insertions(+), 28 deletions(-) > >diff --git a/src/libcamera/pipeline/rkisp1/rkisp1.cpp b/src/libcamera/pipeline/rkisp1/rkisp1.cpp >index 58ae8f98a5c683d5..e85979a719b7ced6 100644 >--- a/src/libcamera/pipeline/rkisp1/rkisp1.cpp >+++ b/src/libcamera/pipeline/rkisp1/rkisp1.cpp >@@ -51,7 +51,6 @@ struct RkISP1FrameInfo { > FrameBuffer *mainPathBuffer; > FrameBuffer *selfPathBuffer; > >- bool paramFilled; > bool paramDequeued; > bool metadataProcessed; > }; >@@ -219,7 +218,6 @@ RkISP1FrameInfo *RkISP1Frames::create(const RkISP1CameraData *data, Request *req > info->mainPathBuffer = mainPathBuffer; > info->selfPathBuffer = selfPathBuffer; > info->statBuffer = statBuffer; >- info->paramFilled = false; > info->paramDequeued = false; > info->metadataProcessed = false; > >@@ -322,9 +320,20 @@ void RkISP1CameraData::queueFrameAction(unsigned int frame, > break; > } > case RKISP1_IPA_ACTION_PARAM_FILLED: { >+ PipelineHandlerRkISP1 *pipe = static_cast<PipelineHandlerRkISP1 *>(pipe_); > RkISP1FrameInfo *info = frameInfo_.find(frame); >- if (info) >- info->paramFilled = true; >+ if (!info) >+ break; >+ >+ pipe->param_->queueBuffer(info->paramBuffer); >+ pipe->stat_->queueBuffer(info->statBuffer); >+ >+ if (info->mainPathBuffer) >+ mainPath_->queueBuffer(info->mainPathBuffer); >+ >+ if (info->selfPathBuffer) >+ selfPath_->queueBuffer(info->selfPathBuffer); >+ > break; > } > case RKISP1_IPA_ACTION_METADATA: >@@ -852,15 +861,6 @@ int PipelineHandlerRkISP1::queueRequestDevice(Camera *camera, Request *request) > op.controls = { request->controls() }; > data->ipa_->processEvent(op); > >- param_->queueBuffer(info->paramBuffer); >- stat_->queueBuffer(info->statBuffer); >- >- if (info->mainPathBuffer) >- mainPath_.queueBuffer(info->mainPathBuffer); >- >- if (info->selfPathBuffer) >- selfPath_.queueBuffer(info->selfPathBuffer); >- > data->frame_++; > > return 0; >@@ -1009,7 +1009,6 @@ bool PipelineHandlerRkISP1::match(DeviceEnumerator *enumerator) > mainPath_.bufferReady().connect(this, &PipelineHandlerRkISP1::bufferReady); > selfPath_.bufferReady().connect(this, &PipelineHandlerRkISP1::bufferReady); > stat_->bufferReady.connect(this, &PipelineHandlerRkISP1::statReady); >- isp_->frameStart.connect(this, &PipelineHandlerRkISP1::frameStart); > param_->bufferReady.connect(this, &PipelineHandlerRkISP1::paramReady); > > /* >@@ -1097,20 +1096,6 @@ void PipelineHandlerRkISP1::statReady(FrameBuffer *buffer) > data->ipa_->processEvent(op); > } > >-void PipelineHandlerRkISP1::frameStart(uint32_t sequence) >-{ >- if (!activeCamera_) >- return; >- >- RkISP1CameraData *data = cameraData(activeCamera_); >- >- RkISP1FrameInfo *info = data->frameInfo_.find(sequence); >- if (!info || !info->paramFilled) >- LOG(RkISP1, Info) >- << "Parameters not ready on time for frame " >- << sequence; >-} >- > REGISTER_PIPELINE_HANDLER(PipelineHandlerRkISP1) > > } /* namespace libcamera */ >-- >2.30.0 > >_______________________________________________ >libcamera-devel mailing list >libcamera-devel@lists.libcamera.org >https://lists.libcamera.org/listinfo/libcamera-devel
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
Hi Sebastian, Thanks for you feedback. On 2021-01-19 07:23:30 +0100, 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. Nice catch! This patch mitigates the problem you describe but reveals another problem in cam's event loop. I believe the problem in cam is the true problem in your report. While this patch is still needed for the original problem in the RkISP1 pipeline handler. I will post patches shortly to solve this issue as well in cam. > > 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 > ``` > > Anyway, this seems to be another issue, I have corrected two small typos > below. And if you like to you can add a: > Tested-by: Sebastian Fricke <sebastian.fricke@posteo.net> Thanks. > > Greetings, > Sebastian > > On 18.01.2021 15:06, Niklas Söderlund wrote: > > When moving the pipeline away from the Timeline design it was discovered > > that the design of queuing the buffers to the device as soon as possible > > was not the best idea. The parameter buffers where queued to the device > > s/where queued/were queued/ > > > before the IPA had processed them and this violates the V4L2 API. > > > > Fix this by waiting to queue any buffer to the device until the IPA have > > s/until the IPA have/until the IPA has/ > > > filled in the parameters buffer. > > > > Signed-off-by: Niklas Söderlund <niklas.soderlund@ragnatech.se> > > --- > > Hello, > > > > This patch is based on-top of '[PATCH v5 0/8] libcamera: Add helper for > > controls that take effect with a delay' as the change is much cleaner > > on-top of the removal of the Timeline. > > --- > > src/libcamera/pipeline/rkisp1/rkisp1.cpp | 41 ++++++++---------------- > > 1 file changed, 13 insertions(+), 28 deletions(-) > > > > diff --git a/src/libcamera/pipeline/rkisp1/rkisp1.cpp b/src/libcamera/pipeline/rkisp1/rkisp1.cpp > > index 58ae8f98a5c683d5..e85979a719b7ced6 100644 > > --- a/src/libcamera/pipeline/rkisp1/rkisp1.cpp > > +++ b/src/libcamera/pipeline/rkisp1/rkisp1.cpp > > @@ -51,7 +51,6 @@ struct RkISP1FrameInfo { > > FrameBuffer *mainPathBuffer; > > FrameBuffer *selfPathBuffer; > > > > - bool paramFilled; > > bool paramDequeued; > > bool metadataProcessed; > > }; > > @@ -219,7 +218,6 @@ RkISP1FrameInfo *RkISP1Frames::create(const RkISP1CameraData *data, Request *req > > info->mainPathBuffer = mainPathBuffer; > > info->selfPathBuffer = selfPathBuffer; > > info->statBuffer = statBuffer; > > - info->paramFilled = false; > > info->paramDequeued = false; > > info->metadataProcessed = false; > > > > @@ -322,9 +320,20 @@ void RkISP1CameraData::queueFrameAction(unsigned int frame, > > break; > > } > > case RKISP1_IPA_ACTION_PARAM_FILLED: { > > + PipelineHandlerRkISP1 *pipe = static_cast<PipelineHandlerRkISP1 *>(pipe_); > > RkISP1FrameInfo *info = frameInfo_.find(frame); > > - if (info) > > - info->paramFilled = true; > > + if (!info) > > + break; > > + > > + pipe->param_->queueBuffer(info->paramBuffer); > > + pipe->stat_->queueBuffer(info->statBuffer); > > + > > + if (info->mainPathBuffer) > > + mainPath_->queueBuffer(info->mainPathBuffer); > > + > > + if (info->selfPathBuffer) > > + selfPath_->queueBuffer(info->selfPathBuffer); > > + > > break; > > } > > case RKISP1_IPA_ACTION_METADATA: > > @@ -852,15 +861,6 @@ int PipelineHandlerRkISP1::queueRequestDevice(Camera *camera, Request *request) > > op.controls = { request->controls() }; > > data->ipa_->processEvent(op); > > > > - param_->queueBuffer(info->paramBuffer); > > - stat_->queueBuffer(info->statBuffer); > > - > > - if (info->mainPathBuffer) > > - mainPath_.queueBuffer(info->mainPathBuffer); > > - > > - if (info->selfPathBuffer) > > - selfPath_.queueBuffer(info->selfPathBuffer); > > - > > data->frame_++; > > > > return 0; > > @@ -1009,7 +1009,6 @@ bool PipelineHandlerRkISP1::match(DeviceEnumerator *enumerator) > > mainPath_.bufferReady().connect(this, &PipelineHandlerRkISP1::bufferReady); > > selfPath_.bufferReady().connect(this, &PipelineHandlerRkISP1::bufferReady); > > stat_->bufferReady.connect(this, &PipelineHandlerRkISP1::statReady); > > - isp_->frameStart.connect(this, &PipelineHandlerRkISP1::frameStart); > > param_->bufferReady.connect(this, &PipelineHandlerRkISP1::paramReady); > > > > /* > > @@ -1097,20 +1096,6 @@ void PipelineHandlerRkISP1::statReady(FrameBuffer *buffer) > > data->ipa_->processEvent(op); > > } > > > > -void PipelineHandlerRkISP1::frameStart(uint32_t sequence) > > -{ > > - if (!activeCamera_) > > - return; > > - > > - RkISP1CameraData *data = cameraData(activeCamera_); > > - > > - RkISP1FrameInfo *info = data->frameInfo_.find(sequence); > > - if (!info || !info->paramFilled) > > - LOG(RkISP1, Info) > > - << "Parameters not ready on time for frame " > > - << sequence; > > -} > > - > > REGISTER_PIPELINE_HANDLER(PipelineHandlerRkISP1) > > > > } /* namespace libcamera */ > > -- > > 2.30.0 > > > > _______________________________________________ > > libcamera-devel mailing list > > libcamera-devel@lists.libcamera.org > > https://lists.libcamera.org/listinfo/libcamera-devel
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
Hi Niklas, Thank you for the patch. On Mon, Jan 18, 2021 at 03:06:15PM +0100, Niklas Söderlund wrote: > When moving the pipeline away from the Timeline design it was discovered > that the design of queuing the buffers to the device as soon as possible > was not the best idea. The parameter buffers where queued to the device > before the IPA had processed them and this violates the V4L2 API. > > Fix this by waiting to queue any buffer to the device until the IPA have > filled in the parameters buffer. > > Signed-off-by: Niklas Söderlund <niklas.soderlund@ragnatech.se> > --- > Hello, > > This patch is based on-top of '[PATCH v5 0/8] libcamera: Add helper for > controls that take effect with a delay' as the change is much cleaner > on-top of the removal of the Timeline. It should probably be squashed in the appropriate patch from that series. > --- > src/libcamera/pipeline/rkisp1/rkisp1.cpp | 41 ++++++++---------------- > 1 file changed, 13 insertions(+), 28 deletions(-) > > diff --git a/src/libcamera/pipeline/rkisp1/rkisp1.cpp b/src/libcamera/pipeline/rkisp1/rkisp1.cpp > index 58ae8f98a5c683d5..e85979a719b7ced6 100644 > --- a/src/libcamera/pipeline/rkisp1/rkisp1.cpp > +++ b/src/libcamera/pipeline/rkisp1/rkisp1.cpp > @@ -51,7 +51,6 @@ struct RkISP1FrameInfo { > FrameBuffer *mainPathBuffer; > FrameBuffer *selfPathBuffer; > > - bool paramFilled; > bool paramDequeued; > bool metadataProcessed; > }; > @@ -219,7 +218,6 @@ RkISP1FrameInfo *RkISP1Frames::create(const RkISP1CameraData *data, Request *req > info->mainPathBuffer = mainPathBuffer; > info->selfPathBuffer = selfPathBuffer; > info->statBuffer = statBuffer; > - info->paramFilled = false; > info->paramDequeued = false; > info->metadataProcessed = false; > > @@ -322,9 +320,20 @@ void RkISP1CameraData::queueFrameAction(unsigned int frame, > break; > } > case RKISP1_IPA_ACTION_PARAM_FILLED: { > + PipelineHandlerRkISP1 *pipe = static_cast<PipelineHandlerRkISP1 *>(pipe_); > RkISP1FrameInfo *info = frameInfo_.find(frame); > - if (info) > - info->paramFilled = true; > + if (!info) > + break; > + > + pipe->param_->queueBuffer(info->paramBuffer); > + pipe->stat_->queueBuffer(info->statBuffer); > + > + if (info->mainPathBuffer) > + mainPath_->queueBuffer(info->mainPathBuffer); > + > + if (info->selfPathBuffer) > + selfPath_->queueBuffer(info->selfPathBuffer); > + The IPA generates RKISP1_IPA_ACTION_PARAM_FILLED when the request is queued to the IPA, so the buffers will be queued early to the driver, ensuring we won't have a queue underrun. Reviewed-by: Laurent Pinchart <laurent.pinchart@ideasonboard.com> However, this means that the IPA will fill the parameters buffer with data that is based on much earlier frames. We'll need to find a proper middleground here, waiting as long as possible before asking the IPA for parameters, but not too long to ensure we won't get underruns. > break; > } > case RKISP1_IPA_ACTION_METADATA: > @@ -852,15 +861,6 @@ int PipelineHandlerRkISP1::queueRequestDevice(Camera *camera, Request *request) > op.controls = { request->controls() }; > data->ipa_->processEvent(op); > > - param_->queueBuffer(info->paramBuffer); > - stat_->queueBuffer(info->statBuffer); > - > - if (info->mainPathBuffer) > - mainPath_.queueBuffer(info->mainPathBuffer); > - > - if (info->selfPathBuffer) > - selfPath_.queueBuffer(info->selfPathBuffer); > - > data->frame_++; > > return 0; > @@ -1009,7 +1009,6 @@ bool PipelineHandlerRkISP1::match(DeviceEnumerator *enumerator) > mainPath_.bufferReady().connect(this, &PipelineHandlerRkISP1::bufferReady); > selfPath_.bufferReady().connect(this, &PipelineHandlerRkISP1::bufferReady); > stat_->bufferReady.connect(this, &PipelineHandlerRkISP1::statReady); > - isp_->frameStart.connect(this, &PipelineHandlerRkISP1::frameStart); > param_->bufferReady.connect(this, &PipelineHandlerRkISP1::paramReady); > > /* > @@ -1097,20 +1096,6 @@ void PipelineHandlerRkISP1::statReady(FrameBuffer *buffer) > data->ipa_->processEvent(op); > } > > -void PipelineHandlerRkISP1::frameStart(uint32_t sequence) > -{ > - if (!activeCamera_) > - return; > - > - RkISP1CameraData *data = cameraData(activeCamera_); > - > - RkISP1FrameInfo *info = data->frameInfo_.find(sequence); > - if (!info || !info->paramFilled) > - LOG(RkISP1, Info) > - << "Parameters not ready on time for frame " > - << sequence; > -} > - > REGISTER_PIPELINE_HANDLER(PipelineHandlerRkISP1) > > } /* namespace libcamera */
diff --git a/src/libcamera/pipeline/rkisp1/rkisp1.cpp b/src/libcamera/pipeline/rkisp1/rkisp1.cpp index 58ae8f98a5c683d5..e85979a719b7ced6 100644 --- a/src/libcamera/pipeline/rkisp1/rkisp1.cpp +++ b/src/libcamera/pipeline/rkisp1/rkisp1.cpp @@ -51,7 +51,6 @@ struct RkISP1FrameInfo { FrameBuffer *mainPathBuffer; FrameBuffer *selfPathBuffer; - bool paramFilled; bool paramDequeued; bool metadataProcessed; }; @@ -219,7 +218,6 @@ RkISP1FrameInfo *RkISP1Frames::create(const RkISP1CameraData *data, Request *req info->mainPathBuffer = mainPathBuffer; info->selfPathBuffer = selfPathBuffer; info->statBuffer = statBuffer; - info->paramFilled = false; info->paramDequeued = false; info->metadataProcessed = false; @@ -322,9 +320,20 @@ void RkISP1CameraData::queueFrameAction(unsigned int frame, break; } case RKISP1_IPA_ACTION_PARAM_FILLED: { + PipelineHandlerRkISP1 *pipe = static_cast<PipelineHandlerRkISP1 *>(pipe_); RkISP1FrameInfo *info = frameInfo_.find(frame); - if (info) - info->paramFilled = true; + if (!info) + break; + + pipe->param_->queueBuffer(info->paramBuffer); + pipe->stat_->queueBuffer(info->statBuffer); + + if (info->mainPathBuffer) + mainPath_->queueBuffer(info->mainPathBuffer); + + if (info->selfPathBuffer) + selfPath_->queueBuffer(info->selfPathBuffer); + break; } case RKISP1_IPA_ACTION_METADATA: @@ -852,15 +861,6 @@ int PipelineHandlerRkISP1::queueRequestDevice(Camera *camera, Request *request) op.controls = { request->controls() }; data->ipa_->processEvent(op); - param_->queueBuffer(info->paramBuffer); - stat_->queueBuffer(info->statBuffer); - - if (info->mainPathBuffer) - mainPath_.queueBuffer(info->mainPathBuffer); - - if (info->selfPathBuffer) - selfPath_.queueBuffer(info->selfPathBuffer); - data->frame_++; return 0; @@ -1009,7 +1009,6 @@ bool PipelineHandlerRkISP1::match(DeviceEnumerator *enumerator) mainPath_.bufferReady().connect(this, &PipelineHandlerRkISP1::bufferReady); selfPath_.bufferReady().connect(this, &PipelineHandlerRkISP1::bufferReady); stat_->bufferReady.connect(this, &PipelineHandlerRkISP1::statReady); - isp_->frameStart.connect(this, &PipelineHandlerRkISP1::frameStart); param_->bufferReady.connect(this, &PipelineHandlerRkISP1::paramReady); /* @@ -1097,20 +1096,6 @@ void PipelineHandlerRkISP1::statReady(FrameBuffer *buffer) data->ipa_->processEvent(op); } -void PipelineHandlerRkISP1::frameStart(uint32_t sequence) -{ - if (!activeCamera_) - return; - - RkISP1CameraData *data = cameraData(activeCamera_); - - RkISP1FrameInfo *info = data->frameInfo_.find(sequence); - if (!info || !info->paramFilled) - LOG(RkISP1, Info) - << "Parameters not ready on time for frame " - << sequence; -} - REGISTER_PIPELINE_HANDLER(PipelineHandlerRkISP1) } /* namespace libcamera */
When moving the pipeline away from the Timeline design it was discovered that the design of queuing the buffers to the device as soon as possible was not the best idea. The parameter buffers where queued to the device before the IPA had processed them and this violates the V4L2 API. Fix this by waiting to queue any buffer to the device until the IPA have filled in the parameters buffer. Signed-off-by: Niklas Söderlund <niklas.soderlund@ragnatech.se> --- Hello, This patch is based on-top of '[PATCH v5 0/8] libcamera: Add helper for controls that take effect with a delay' as the change is much cleaner on-top of the removal of the Timeline. --- src/libcamera/pipeline/rkisp1/rkisp1.cpp | 41 ++++++++---------------- 1 file changed, 13 insertions(+), 28 deletions(-)