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

Tue Feb 2 13:56:16 CET 2021

Hi Jacopo,

On 2021-02-02 12:40:56 +0100, Jacopo Mondi wrote:
> Hi Niklas,
> 
> On Mon, Feb 01, 2021 at 05:08:20PM +0100, Niklas Söderlund wrote:
> > Hi Jacopo,
> >
> > On 2021-02-01 11:36:48 +0100, Jacopo Mondi wrote:
> > > 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.
> >
> > I was thinking of if it make sens to instead of
> >
> >   HAL camera_device.cpp:1776 '\_SB_.PCI0.I2C2.CAM0': Queueing Request to libcamera with 2 HAL streams
> >   HAL camera_device.cpp:1813 '\_SB_.PCI0.I2C2.CAM0': 0 - 640x480)[0x00000022] -> (640x480)[NV12] (direct)
> >   HAL camera_device.cpp:1813 '\_SB_.PCI0.I2C2.CAM0': 1 - 640x480)[0x00000022] -> (640x480)[NV12] (direct)
> >
> > Have something like,
> >
> >   HAL camera_device.cpp:1813 '\_SB_.PCI0.I2C2.CAM0': cookie: 138508601718368 stream: 1/2 - 640x480)[0x00000022] -> (640x480)[NV12] (direct)
> >   HAL camera_device.cpp:1813 '\_SB_.PCI0.I2C2.CAM0': cookie: 138508601718368 stream: 2/2 - 640x480)[0x00000022] -> (640x480)[NV12] (direct)
> >
> > I find the later more compact while at the same time providing more
> > information in a situation where you have to debug from a log file.
> 
> So, that might be a matter of tastes, but:
> 1) I try to avoid creating too long log lines
>    I always run with terminals one side to the other, spanning more
>    than the usual 80-cols is ok, as it's reasonable to suppose most
>    people have larger screens nowadays, but I think we should try to
>    be compact to ease debug/development
> 
> 2) I try to separate information in lines, as log can be filtered,
>    either by using libcamera log infrastructure or by piping the usual
>    unix tools. In your example, reporting the same cookie in two lines
>    to me add noise and makes debug more confusing than having
>    information separated on multiple lines. I can easily filter/grep
>    on lines I'm interested in, and I prefer one more line to parse
>    than parsing information on a single long line
> 
> Might be a matter of tastes indeed

I agree, it's a matter of taste.

> 
> >
> > >
> > > >
> > > > > 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...
> >
> > Is it a problem that the same information is printed at different
> > levels? I like to see such things as it allows me to from a log file
> > track how a request moved thru the layers. Also if I'm only interested
> > in debugging a specific component maybe I have a
> > LIBCAMERA_LOG_LEVELS=HAL:0 or such set?
> 
> Ok addin the cookie to the request complete log
> 
> >
> > In either case as stated in my first reply this is all bikeshedding so I
> > don't feel strongly about any of it :-)
> >
> > >
> > > >
> > > > 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>
> 
> Thanks, I'll send a new version and I'll retain the tag, but please
> feel free to comment on that one as well.

Please retain the tag, I'm just bikeshedding.

> 
> Thanks
>   j
> 
> > > >
> > > > >
> > > > > 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
> >
> > --
> > Regards,
> > Niklas Söderlund

-- 
Regards,
Niklas Söderlund