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

[paul.elder at ideasonboard.com]

Hi Jacopo,

On Thu, Jan 28, 2021 at 10:04:54AM +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:
> 
> 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
> HAL camera_device.cpp:1813 '\_SB_.PCI0.I2C2.CAM0': 0 - (640x480)[0x00000022] -> (640x480)[NV12] (direct)
> ...
> ...
> 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
> 
> Signed-off-by: Jacopo Mondi <jacopo at jmondi.org>

Ooh, good idea!

Reviewed-by: Paul Elder <paul.elder at ideasonboard.com>

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