[libcamera-devel,2/5] ipa: raspberrypi: alsc: Replace Raspberry Pi debug with libcamera debug

10953 diff mbox series

Signed-off-by: David Plowman <david.plowman@raspberrypi.com>
---
 src/ipa/raspberrypi/controller/rpi/alsc.cpp | 59 +++++++++++----------
 1 file changed, 32 insertions(+), 27 deletions(-)

Hi David,

Thank you for the patch.

On Fri, Jan 22, 2021 at 10:22:08AM +0000, David Plowman wrote:
> Signed-off-by: David Plowman <david.plowman@raspberrypi.com>
> ---
>  src/ipa/raspberrypi/controller/rpi/alsc.cpp | 59 +++++++++++----------
>  1 file changed, 32 insertions(+), 27 deletions(-)
> 
> diff --git a/src/ipa/raspberrypi/controller/rpi/alsc.cpp b/src/ipa/raspberrypi/controller/rpi/alsc.cpp
> index c354c985..4777238c 100644
> --- a/src/ipa/raspberrypi/controller/rpi/alsc.cpp
> +++ b/src/ipa/raspberrypi/controller/rpi/alsc.cpp
> @@ -6,12 +6,17 @@
>   */
>  #include <math.h>
>  
> +#include "libcamera/internal/log.h"
> +
>  #include "../awb_status.h"
>  #include "alsc.hpp"
>  
>  // Raspberry Pi ALSC (Auto Lens Shading Correction) algorithm.
>  
>  using namespace RPiController;
> +using namespace libcamera;
> +
> +LOG_DEFINE_CATEGORY(RPiAlsc)
>  
>  #define NAME "rpi.alsc"
>  
> @@ -110,15 +115,15 @@ static void read_calibrations(std::vector<AlscCalibration> &calibrations,
>  					"Alsc: too few values for ct " +
>  					std::to_string(ct) + " in " + name);
>  			calibrations.push_back(calibration);
> -			RPI_LOG("Read " << name << " calibration for ct "
> -					<< ct);
> +			LOG(RPiAlsc, Debug) << "Read " << name << " calibration for ct "
> +					    << ct;

If you want to keep line shorters, we often write

			LOG(RPiAlsc, Debug)
				<< "Read " << name << " calibration for ct "
				<< ct;

(single tab indentation instead of variable-length indentation depending
on the name of the catory) for messages that span multiple lines.

>  		}
>  	}
>  }
>  
>  void Alsc::Read(boost::property_tree::ptree const &params)
>  {
> -	RPI_LOG("Alsc");
> +	LOG(RPiAlsc, Debug) << "Alsc";
>  	config_.frame_period = params.get<uint16_t>("frame_period", 12);
>  	config_.startup_frames = params.get<uint16_t>("startup_frames", 10);
>  	config_.speed = params.get<double>("speed", 0.05);
> @@ -139,7 +144,7 @@ void Alsc::Read(boost::property_tree::ptree const &params)
>  		read_lut(config_.luminance_lut,
>  			 params.get_child("luminance_lut"));
>  	else
> -		RPI_WARN("Alsc: no luminance table - assume unity everywhere");
> +		LOG(RPiAlsc, Warning) << "Alsc: no luminance table - assume unity everywhere";

You can drop the "Alsc:" prefix in messages, the name of the category is
printed in the log already. Same for messages that just print "Alsc" as
above, maybe you could replace this one with "Reading parameters" and
something similar for the ones below ?

>  	read_calibrations(config_.calibrations_Cr, params, "calibrations_Cr");
>  	read_calibrations(config_.calibrations_Cb, params, "calibrations_Cb");
>  	config_.default_ct = params.get<double>("default_ct", 4500.0);
> @@ -164,7 +169,7 @@ static void add_luminance_to_tables(double results[3][Y][X],
>  
>  void Alsc::Initialise()
>  {
> -	RPI_LOG("Alsc");
> +	LOG(RPiAlsc, Debug) << "Alsc";
>  	frame_count2_ = frame_count_ = frame_phase_ = 0;
>  	first_time_ = true;
>  	ct_ = config_.default_ct;
> @@ -252,7 +257,7 @@ void Alsc::SwitchMode(CameraMode const &camera_mode,
>  
>  void Alsc::fetchAsyncResults()
>  {
> -	RPI_LOG("Fetch ALSC results");
> +	LOG(RPiAlsc, Debug) << "Fetch ALSC results";
>  	async_finished_ = false;
>  	async_started_ = false;
>  	memcpy(sync_results_, async_results_, sizeof(sync_results_));
> @@ -263,11 +268,11 @@ double get_ct(Metadata *metadata, double default_ct)
>  	AwbStatus awb_status;
>  	awb_status.temperature_K = default_ct; // in case nothing found
>  	if (metadata->Get("awb.status", awb_status) != 0)
> -		RPI_WARN("Alsc: no AWB results found, using "
> -			 << awb_status.temperature_K);
> +		LOG(RPiAlsc, Warning) << "Alsc: no AWB results found, using "
> +				      << awb_status.temperature_K;
>  	else
> -		RPI_LOG("Alsc: AWB results found, using "
> -			<< awb_status.temperature_K);
> +		LOG(RPiAlsc, Debug) << "Alsc: AWB results found, using "
> +				    << awb_status.temperature_K;

This is fine for now, but I think this may be a candidate for the
tracing infrastructure.

>  	return awb_status.temperature_K;
>  }
>  
> @@ -289,7 +294,7 @@ static void copy_stats(bcm2835_isp_stats_region regions[XY], StatisticsPtr &stat
>  
>  void Alsc::restartAsync(StatisticsPtr &stats, Metadata *image_metadata)
>  {
> -	RPI_LOG("Starting ALSC thread");
> +	LOG(RPiAlsc, Debug) << "Starting ALSC thread";

This starts the computation asynchronously, not the thread, right ?

>  	// Get the current colour temperature. It's all we need from the
>  	// metadata. Default to the last CT value (which could be the default).
>  	ct_ = get_ct(image_metadata, ct_);
> @@ -297,7 +302,7 @@ void Alsc::restartAsync(StatisticsPtr &stats, Metadata *image_metadata)
>  	// the LSC table that the pipeline applied to them.
>  	AlscStatus alsc_status;
>  	if (image_metadata->Get("alsc.status", alsc_status) != 0) {
> -		RPI_WARN("No ALSC status found for applied gains!");
> +		LOG(RPiAlsc, Warning) << "No ALSC status found for applied gains!";
>  		for (int y = 0; y < Y; y++)
>  			for (int x = 0; x < X; x++) {
>  				alsc_status.r[y][x] = 1.0;
> @@ -324,11 +329,11 @@ void Alsc::Prepare(Metadata *image_metadata)
>  	double speed = frame_count_ < (int)config_.startup_frames
>  			       ? 1.0
>  			       : config_.speed;
> -	RPI_LOG("Alsc: frame_count " << frame_count_ << " speed " << speed);

Unrelated to this patch, but if a frame count is useful for other
algorithms too, maybe it could be moved to Metadata and handled by the
controller ?

> +	LOG(RPiAlsc, Debug) << "Alsc: frame_count " << frame_count_ << " speed " << speed;
>  	{
>  		std::unique_lock<std::mutex> lock(mutex_);
>  		if (async_started_ && async_finished_) {
> -			RPI_LOG("ALSC thread finished");
> +			LOG(RPiAlsc, Debug) << "ALSC thread finished";

Same here, maybe "ALSC computation complete" ?

>  			fetchAsyncResults();
>  		}
>  	}
> @@ -354,11 +359,11 @@ void Alsc::Process(StatisticsPtr &stats, Metadata *image_metadata)
>  		frame_phase_++;
>  	if (frame_count2_ < (int)config_.startup_frames)
>  		frame_count2_++;
> -	RPI_LOG("Alsc: frame_phase " << frame_phase_);
> +	LOG(RPiAlsc, Debug) << "Alsc: frame_phase " << frame_phase_;
>  	if (frame_phase_ >= (int)config_.frame_period ||
>  	    frame_count2_ < (int)config_.startup_frames) {
>  		if (async_started_ == false) {
> -			RPI_LOG("ALSC thread starting");
> +			LOG(RPiAlsc, Debug) << "ALSC thread starting";
>  			restartAsync(stats, image_metadata);
>  		}
>  	}
> @@ -391,25 +396,25 @@ void get_cal_table(double ct, std::vector<AlscCalibration> const &calibrations,
>  	if (calibrations.empty()) {
>  		for (int i = 0; i < XY; i++)
>  			cal_table[i] = 1.0;
> -		RPI_LOG("Alsc: no calibrations found");
> +		LOG(RPiAlsc, Debug) << "Alsc: no calibrations found";
>  	} else if (ct <= calibrations.front().ct) {
>  		memcpy(cal_table, calibrations.front().table,
>  		       XY * sizeof(double));
> -		RPI_LOG("Alsc: using calibration for "
> -			<< calibrations.front().ct);
> +		LOG(RPiAlsc, Debug) << "Alsc: using calibration for "
> +				    << calibrations.front().ct;
>  	} else if (ct >= calibrations.back().ct) {
>  		memcpy(cal_table, calibrations.back().table,
>  		       XY * sizeof(double));
> -		RPI_LOG("Alsc: using calibration for "
> -			<< calibrations.front().ct);
> +		LOG(RPiAlsc, Debug) << "Alsc: using calibration for "
> +				    << calibrations.front().ct;
>  	} else {
>  		int idx = 0;
>  		while (ct > calibrations[idx + 1].ct)
>  			idx++;
>  		double ct0 = calibrations[idx].ct,
>  		       ct1 = calibrations[idx + 1].ct;
> -		RPI_LOG("Alsc: ct is " << ct << ", interpolating between "
> -				       << ct0 << " and " << ct1);
> +		LOG(RPiAlsc, Debug) << "Alsc: ct is " << ct << ", interpolating between "
> +				    << ct0 << " and " << ct1;
>  		for (int i = 0; i < XY; i++)
>  			cal_table[i] =
>  				(calibrations[idx].table[i] * (ct1 - ct) +
> @@ -660,15 +665,15 @@ static void run_matrix_iterations(double const C[XY], double lambda[XY],
>  	for (int i = 0; i < n_iter; i++) {
>  		double max_diff = fabs(gauss_seidel2_SOR(M, omega, lambda));
>  		if (max_diff < threshold) {
> -			RPI_LOG("Stop after " << i + 1 << " iterations");
> +			LOG(RPiAlsc, Debug) << "Stop after " << i + 1 << " iterations";
>  			break;
>  		}
>  		// this happens very occasionally (so make a note), though
>  		// doesn't seem to matter
>  		if (max_diff > last_max_diff)
> -			RPI_LOG("Iteration " << i << ": max_diff gone up "
> -					     << last_max_diff << " to "
> -					     << max_diff);
> +			LOG(RPiAlsc, Debug) << "Iteration " << i << ": max_diff gone up "
> +					    << last_max_diff << " to "
> +					    << max_diff;
>  		last_max_diff = max_diff;
>  	}
>  	// We're going to normalise the lambdas so the smallest is 1. Not sure