[{"id":14728,"web_url":"https://patchwork.libcamera.org/comment/14728/","msgid":"","date":"2021-01-23T11:15:33","subject":"Re: [libcamera-devel] [PATCH 2/5] ipa: raspberrypi: alsc: Replace\n\tRaspberry Pi debug with libcamera debug","submitter":{"id":2,"url":"https://patchwork.libcamera.org/api/people/2/","name":"Laurent Pinchart","email":"laurent.pinchart@ideasonboard.com"},"content":"Hi David,\n\nThank you for the patch.\n\nOn Fri, Jan 22, 2021 at 10:22:08AM +0000, David Plowman wrote:\n> Signed-off-by: David Plowman \n> ---\n> src/ipa/raspberrypi/controller/rpi/alsc.cpp | 59 +++++++++++----------\n> 1 file changed, 32 insertions(+), 27 deletions(-)\n> \n> diff --git a/src/ipa/raspberrypi/controller/rpi/alsc.cpp b/src/ipa/raspberrypi/controller/rpi/alsc.cpp\n> index c354c985..4777238c 100644\n> --- a/src/ipa/raspberrypi/controller/rpi/alsc.cpp\n> +++ b/src/ipa/raspberrypi/controller/rpi/alsc.cpp\n> @@ -6,12 +6,17 @@\n> */\n> #include \n> \n> +#include \"libcamera/internal/log.h\"\n> +\n> #include \"../awb_status.h\"\n> #include \"alsc.hpp\"\n> \n> // Raspberry Pi ALSC (Auto Lens Shading Correction) algorithm.\n> \n> using namespace RPiController;\n> +using namespace libcamera;\n> +\n> +LOG_DEFINE_CATEGORY(RPiAlsc)\n> \n> #define NAME \"rpi.alsc\"\n> \n> @@ -110,15 +115,15 @@ static void read_calibrations(std::vector &calibrations,\n> \t\t\t\t\t\"Alsc: too few values for ct \" +\n> \t\t\t\t\tstd::to_string(ct) + \" in \" + name);\n> \t\t\tcalibrations.push_back(calibration);\n> -\t\t\tRPI_LOG(\"Read \" << name << \" calibration for ct \"\n> -\t\t\t\t\t<< ct);\n> +\t\t\tLOG(RPiAlsc, Debug) << \"Read \" << name << \" calibration for ct \"\n> +\t\t\t\t\t << ct;\n\nIf you want to keep line shorters, we often write\n\n\t\t\tLOG(RPiAlsc, Debug)\n\t\t\t\t<< \"Read \" << name << \" calibration for ct \"\n\t\t\t\t<< ct;\n\n(single tab indentation instead of variable-length indentation depending\non the name of the catory) for messages that span multiple lines.\n\n> \t\t}\n> \t}\n> }\n> \n> void Alsc::Read(boost::property_tree::ptree const ¶ms)\n> {\n> -\tRPI_LOG(\"Alsc\");\n> +\tLOG(RPiAlsc, Debug) << \"Alsc\";\n> \tconfig_.frame_period = params.get(\"frame_period\", 12);\n> \tconfig_.startup_frames = params.get(\"startup_frames\", 10);\n> \tconfig_.speed = params.get(\"speed\", 0.05);\n> @@ -139,7 +144,7 @@ void Alsc::Read(boost::property_tree::ptree const ¶ms)\n> \t\tread_lut(config_.luminance_lut,\n> \t\t\t params.get_child(\"luminance_lut\"));\n> \telse\n> -\t\tRPI_WARN(\"Alsc: no luminance table - assume unity everywhere\");\n> +\t\tLOG(RPiAlsc, Warning) << \"Alsc: no luminance table - assume unity everywhere\";\n\nYou can drop the \"Alsc:\" prefix in messages, the name of the category is\nprinted in the log already. Same for messages that just print \"Alsc\" as\nabove, maybe you could replace this one with \"Reading parameters\" and\nsomething similar for the ones below ?\n\n> \tread_calibrations(config_.calibrations_Cr, params, \"calibrations_Cr\");\n> \tread_calibrations(config_.calibrations_Cb, params, \"calibrations_Cb\");\n> \tconfig_.default_ct = params.get(\"default_ct\", 4500.0);\n> @@ -164,7 +169,7 @@ static void add_luminance_to_tables(double results[3][Y][X],\n> \n> void Alsc::Initialise()\n> {\n> -\tRPI_LOG(\"Alsc\");\n> +\tLOG(RPiAlsc, Debug) << \"Alsc\";\n> \tframe_count2_ = frame_count_ = frame_phase_ = 0;\n> \tfirst_time_ = true;\n> \tct_ = config_.default_ct;\n> @@ -252,7 +257,7 @@ void Alsc::SwitchMode(CameraMode const &camera_mode,\n> \n> void Alsc::fetchAsyncResults()\n> {\n> -\tRPI_LOG(\"Fetch ALSC results\");\n> +\tLOG(RPiAlsc, Debug) << \"Fetch ALSC results\";\n> \tasync_finished_ = false;\n> \tasync_started_ = false;\n> \tmemcpy(sync_results_, async_results_, sizeof(sync_results_));\n> @@ -263,11 +268,11 @@ double get_ct(Metadata *metadata, double default_ct)\n> \tAwbStatus awb_status;\n> \tawb_status.temperature_K = default_ct; // in case nothing found\n> \tif (metadata->Get(\"awb.status\", awb_status) != 0)\n> -\t\tRPI_WARN(\"Alsc: no AWB results found, using \"\n> -\t\t\t << awb_status.temperature_K);\n> +\t\tLOG(RPiAlsc, Warning) << \"Alsc: no AWB results found, using \"\n> +\t\t\t\t << awb_status.temperature_K;\n> \telse\n> -\t\tRPI_LOG(\"Alsc: AWB results found, using \"\n> -\t\t\t<< awb_status.temperature_K);\n> +\t\tLOG(RPiAlsc, Debug) << \"Alsc: AWB results found, using \"\n> +\t\t\t\t << awb_status.temperature_K;\n\nThis is fine for now, but I think this may be a candidate for the\ntracing infrastructure.\n\n> \treturn awb_status.temperature_K;\n> }\n> \n> @@ -289,7 +294,7 @@ static void copy_stats(bcm2835_isp_stats_region regions[XY], StatisticsPtr &stat\n> \n> void Alsc::restartAsync(StatisticsPtr &stats, Metadata *image_metadata)\n> {\n> -\tRPI_LOG(\"Starting ALSC thread\");\n> +\tLOG(RPiAlsc, Debug) << \"Starting ALSC thread\";\n\nThis starts the computation asynchronously, not the thread, right ?\n\n> \t// Get the current colour temperature. It's all we need from the\n> \t// metadata. Default to the last CT value (which could be the default).\n> \tct_ = get_ct(image_metadata, ct_);\n> @@ -297,7 +302,7 @@ void Alsc::restartAsync(StatisticsPtr &stats, Metadata *image_metadata)\n> \t// the LSC table that the pipeline applied to them.\n> \tAlscStatus alsc_status;\n> \tif (image_metadata->Get(\"alsc.status\", alsc_status) != 0) {\n> -\t\tRPI_WARN(\"No ALSC status found for applied gains!\");\n> +\t\tLOG(RPiAlsc, Warning) << \"No ALSC status found for applied gains!\";\n> \t\tfor (int y = 0; y < Y; y++)\n> \t\t\tfor (int x = 0; x < X; x++) {\n> \t\t\t\talsc_status.r[y][x] = 1.0;\n> @@ -324,11 +329,11 @@ void Alsc::Prepare(Metadata *image_metadata)\n> \tdouble speed = frame_count_ < (int)config_.startup_frames\n> \t\t\t ? 1.0\n> \t\t\t : config_.speed;\n> -\tRPI_LOG(\"Alsc: frame_count \" << frame_count_ << \" speed \" << speed);\n\nUnrelated to this patch, but if a frame count is useful for other\nalgorithms too, maybe it could be moved to Metadata and handled by the\ncontroller ?\n\n> +\tLOG(RPiAlsc, Debug) << \"Alsc: frame_count \" << frame_count_ << \" speed \" << speed;\n> \t{\n> \t\tstd::unique_lock lock(mutex_);\n> \t\tif (async_started_ && async_finished_) {\n> -\t\t\tRPI_LOG(\"ALSC thread finished\");\n> +\t\t\tLOG(RPiAlsc, Debug) << \"ALSC thread finished\";\n\nSame here, maybe \"ALSC computation complete\" ?\n\n> \t\t\tfetchAsyncResults();\n> \t\t}\n> \t}\n> @@ -354,11 +359,11 @@ void Alsc::Process(StatisticsPtr &stats, Metadata *image_metadata)\n> \t\tframe_phase_++;\n> \tif (frame_count2_ < (int)config_.startup_frames)\n> \t\tframe_count2_++;\n> -\tRPI_LOG(\"Alsc: frame_phase \" << frame_phase_);\n> +\tLOG(RPiAlsc, Debug) << \"Alsc: frame_phase \" << frame_phase_;\n> \tif (frame_phase_ >= (int)config_.frame_period ||\n> \t frame_count2_ < (int)config_.startup_frames) {\n> \t\tif (async_started_ == false) {\n> -\t\t\tRPI_LOG(\"ALSC thread starting\");\n> +\t\t\tLOG(RPiAlsc, Debug) << \"ALSC thread starting\";\n> \t\t\trestartAsync(stats, image_metadata);\n> \t\t}\n> \t}\n> @@ -391,25 +396,25 @@ void get_cal_table(double ct, std::vector const &calibrations,\n> \tif (calibrations.empty()) {\n> \t\tfor (int i = 0; i < XY; i++)\n> \t\t\tcal_table[i] = 1.0;\n> -\t\tRPI_LOG(\"Alsc: no calibrations found\");\n> +\t\tLOG(RPiAlsc, Debug) << \"Alsc: no calibrations found\";\n> \t} else if (ct <= calibrations.front().ct) {\n> \t\tmemcpy(cal_table, calibrations.front().table,\n> \t\t XY * sizeof(double));\n> -\t\tRPI_LOG(\"Alsc: using calibration for \"\n> -\t\t\t<< calibrations.front().ct);\n> +\t\tLOG(RPiAlsc, Debug) << \"Alsc: using calibration for \"\n> +\t\t\t\t << calibrations.front().ct;\n> \t} else if (ct >= calibrations.back().ct) {\n> \t\tmemcpy(cal_table, calibrations.back().table,\n> \t\t XY * sizeof(double));\n> -\t\tRPI_LOG(\"Alsc: using calibration for \"\n> -\t\t\t<< calibrations.front().ct);\n> +\t\tLOG(RPiAlsc, Debug) << \"Alsc: using calibration for \"\n> +\t\t\t\t << calibrations.front().ct;\n> \t} else {\n> \t\tint idx = 0;\n> \t\twhile (ct > calibrations[idx + 1].ct)\n> \t\t\tidx++;\n> \t\tdouble ct0 = calibrations[idx].ct,\n> \t\t ct1 = calibrations[idx + 1].ct;\n> -\t\tRPI_LOG(\"Alsc: ct is \" << ct << \", interpolating between \"\n> -\t\t\t\t << ct0 << \" and \" << ct1);\n> +\t\tLOG(RPiAlsc, Debug) << \"Alsc: ct is \" << ct << \", interpolating between \"\n> +\t\t\t\t << ct0 << \" and \" << ct1;\n> \t\tfor (int i = 0; i < XY; i++)\n> \t\t\tcal_table[i] =\n> \t\t\t\t(calibrations[idx].table[i] * (ct1 - ct) +\n> @@ -660,15 +665,15 @@ static void run_matrix_iterations(double const C[XY], double lambda[XY],\n> \tfor (int i = 0; i < n_iter; i++) {\n> \t\tdouble max_diff = fabs(gauss_seidel2_SOR(M, omega, lambda));\n> \t\tif (max_diff < threshold) {\n> -\t\t\tRPI_LOG(\"Stop after \" << i + 1 << \" iterations\");\n> +\t\t\tLOG(RPiAlsc, Debug) << \"Stop after \" << i + 1 << \" iterations\";\n> \t\t\tbreak;\n> \t\t}\n> \t\t// this happens very occasionally (so make a note), though\n> \t\t// doesn't seem to matter\n> \t\tif (max_diff > last_max_diff)\n> -\t\t\tRPI_LOG(\"Iteration \" << i << \": max_diff gone up \"\n> -\t\t\t\t\t << last_max_diff << \" to \"\n> -\t\t\t\t\t << max_diff);\n> +\t\t\tLOG(RPiAlsc, Debug) << \"Iteration \" << i << \": max_diff gone up \"\n> +\t\t\t\t\t << last_max_diff << \" to \"\n> +\t\t\t\t\t << max_diff;\n> \t\tlast_max_diff = max_diff;\n> \t}\n> \t// We're going to normalise the lambdas so the smallest is 1. Not sure","headers":{"Return-Path":"","X-Original-To":"parsemail@patchwork.libcamera.org","Delivered-To":"parsemail@patchwork.libcamera.org","Received":["from lancelot.ideasonboard.com (lancelot.ideasonboard.com\n\t[92.243.16.209])\n\tby patchwork.libcamera.org (Postfix) with ESMTPS id 971B0BD808\n\tfor ;\n\tSat, 23 Jan 2021 11:15:55 +0000 (UTC)","from lancelot.ideasonboard.com (localhost [IPv6:::1])\n\tby lancelot.ideasonboard.com (Postfix) with ESMTP id 3BB0668299;\n\tSat, 23 Jan 2021 12:15:55 +0100 (CET)","from perceval.ideasonboard.com (perceval.ideasonboard.com\n\t[213.167.242.64])\n\tby lancelot.ideasonboard.com (Postfix) with ESMTPS id 0FDD9681DC\n\tfor ;\n\tSat, 23 Jan 2021 12:15:53 +0100 (CET)","from pendragon.ideasonboard.com (62-78-145-57.bb.dnainternet.fi\n\t[62.78.145.57])\n\tby perceval.ideasonboard.com (Postfix) with ESMTPSA id 9C489DA;\n\tSat, 23 Jan 2021 12:15:52 +0100 (CET)"],"Authentication-Results":"lancelot.ideasonboard.com;\n\tdkim=fail reason=\"signature verification failed\" (1024-bit key;\n\tunprotected) header.d=ideasonboard.com header.i=@ideasonboard.com\n\theader.b=\"b9BGaH5S\"; dkim-atps=neutral","DKIM-Signature":"v=1; a=rsa-sha256; c=relaxed/simple; d=ideasonboard.com;\n\ts=mail; t=1611400552;\n\tbh=TKtiNyuShMGWV2+jpkKJktcQD7tyuFEYlxVxU7sNAYc=;\n\th=Date:From:To:Cc:Subject:References:In-Reply-To:From;\n\tb=b9BGaH5ScAlkWCekfbcgqp2IKX69xsmHIVf6f8P4QYhP3EKgejCZAM0guE6qs0lY/\n\tq4KAZjFXbC4g/BgdopNcnX7uBu0YdUd29fR3bQPYz1pITF1TvudEzsVgSp4W7TxOxD\n\tDpLiFPEmxe9wh/HhjsDSeBG2iWrOfnTcO3rjCevM=","Date":"Sat, 23 Jan 2021 13:15:33 +0200","From":"Laurent Pinchart ","To":"David Plowman ","Message-ID":"","References":"<20210122102211.12768-1-david.plowman@raspberrypi.com>\n\t<20210122102211.12768-3-david.plowman@raspberrypi.com>","MIME-Version":"1.0","Content-Disposition":"inline","In-Reply-To":"<20210122102211.12768-3-david.plowman@raspberrypi.com>","Subject":"Re: [libcamera-devel] [PATCH 2/5] ipa: raspberrypi: alsc: Replace\n\tRaspberry Pi debug with libcamera debug","X-BeenThere":"libcamera-devel@lists.libcamera.org","X-Mailman-Version":"2.1.29","Precedence":"list","List-Id":"","List-Unsubscribe":",\n\t","List-Archive":"","List-Post":"","List-Help":"","List-Subscribe":",\n\t","Cc":"libcamera-devel@lists.libcamera.org","Content-Type":"text/plain; charset=\"us-ascii\"","Content-Transfer-Encoding":"7bit","Errors-To":"libcamera-devel-bounces@lists.libcamera.org","Sender":"\"libcamera-devel\" "}}]