[libcamera-devel] [PATCH] libcamera: Improve Request life cycle tracking

[Jacopo Mondi]

Hi Niklas,

On Sat, Jan 30, 2021 at 12:26:39AM +0100, Niklas Söderlund wrote:
> Hi Jacopo,
>
> Thanks for your bikeshedding opportunity :-)
>
> On 2021-01-28 10:04:54 +0100, Jacopo Mondi wrote:
> > The current logging to track the status of a Request when running the
> > Android camera HAL provide the following information:
> >
> > When a Request is queued to libcamera:
> > HAL camera_device.cpp:1776 '\_SB_.PCI0.I2C2.CAM0': Queueing Request to libcamera with 1 HAL streams
> >
> > When a Request completes:
> > Request request.cpp:268 Request has completed - cookie: 138508601719648
> >
> > The queueing of a Request reports the number of streams it contains
> > while the completion of a Request reports the address of the associated
> > cookie.
> >
> > This makes very hard to keep track of what Requests have completed, as
> > the logging associated with a queue/complete event does not allow to identify
> > a Request easily.
> >
> > Add two more printouts to make it easier to track a Request life cycle.
> >
> > The result looks like the following trace:
> >
>
> I like the improvement, but I would alter it slightly. I think having
> the cookie value is the real value here as it makes it possible to trace
> a request.
>
> > Request request.cpp:92 Created request - cookie: 138508601718368
> > HAL camera_device.cpp:1776 '\_SB_.PCI0.I2C2.CAM0': Queueing Request to libcamera with 1 HAL streams
>
> I would remove this print to increase signal to noise. If the number of
> streams really are important I would do a 1/n thing on the line below.
> If the line is keept I would also print the cookie.

I'm sorry I didn't fully get this one. What do you mean with "a 1/n
thing on the line below" ?

Also, I think identifying how many streams the request contains is
relevant.

>
> > HAL camera_device.cpp:1813 '\_SB_.PCI0.I2C2.CAM0': 0 - (640x480)[0x00000022] -> (640x480)[NV12] (direct)
>
> I would add the cookie.
>
> > ...
> > ...
> > Request request.cpp:268 Request has completed - cookie: 138508601718368
> > HAL camera_device.cpp:1866 '\_SB_.PCI0.I2C2.CAM0': Request completed by libcamera with 1 streams
>
> I would add the cookie and possibly s/with 1 streams//

If we remove the stream count and add the cookie, I would then rather
drop the printout in camera_device.cpp completely, as it will provide
the exact same information that the one in request.cpp provides...

>
> Bikeshedding is fun but take only what you like. At the end if all lines
> have the cookie you can also take my,
>
> Reviewed-by: Niklas Söderlund <niklas.soderlund at ragnatech.se>
>
> >
> > Signed-off-by: Jacopo Mondi <jacopo at jmondi.org>
> > ---
> >  src/android/camera_device.cpp | 3 +++
> >  src/libcamera/request.cpp     | 2 ++
> >  2 files changed, 5 insertions(+)
> >
> > diff --git a/src/android/camera_device.cpp b/src/android/camera_device.cpp
> > index a9634f4e4198..513f000b1854 100644
> > --- a/src/android/camera_device.cpp
> > +++ b/src/android/camera_device.cpp
> > @@ -1863,6 +1863,9 @@ void CameraDevice::requestComplete(Request *request)
> >  		status = CAMERA3_BUFFER_STATUS_ERROR;
> >  	}
> >
> > +	LOG(HAL, Debug) << "Request completed by libcamera with "
> > +			<< descriptor->numBuffers_ << " streams";
> > +
> >  	/*
> >  	 * \todo The timestamp used for the metadata is currently always taken
> >  	 * from the first buffer (which may be the first stream) in the Request.
> > diff --git a/src/libcamera/request.cpp b/src/libcamera/request.cpp
> > index a68684ef9fd3..e561ce1d5d0e 100644
> > --- a/src/libcamera/request.cpp
> > +++ b/src/libcamera/request.cpp
> > @@ -88,6 +88,8 @@ Request::Request(Camera *camera, uint64_t cookie)
> >  	metadata_ = new ControlList(controls::controls);
> >
> >  	LIBCAMERA_TRACEPOINT(request_construct, this);
> > +
> > +	LOG(Request, Debug) << "Created request - cookie: " << cookie_;
> >  }
> >
> >  Request::~Request()
> > --
> > 2.30.0
> >
> > _______________________________________________
> > libcamera-devel mailing list
> > libcamera-devel at lists.libcamera.org
> > https://lists.libcamera.org/listinfo/libcamera-devel
>
> --
> Regards,
> Niklas Söderlund