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

[Jacopo Mondi]

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

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

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