[v1,3/3] libcamera: base: log: Do not instantiate disabled `LogMessage`s

22912 diff mbox series

At the moment every `LOG()` macro invocation results in a `LogMessage`
being created, the message serialized into an `std::stringstream`.
Only in the destructor is is actually checked whether the corresponding
`LogCategory` enables the given log level.

This is not too efficient, it would be better to skip the log message
construction and all the `operator<<()` invocations if the message will
just be discarded.

This could be easily if the `LOG()` macro accepted its arguments
like a traditional function as in that case an appropriate `if`
statement can be injected in a do-while loop. However, that is
not the case, the `LOG()` macro should effectively "return"
a stream.

It is not possible inject an `if` statement directly as that would
lead to issues:

  if (...)
    LOG(...)
  else
   ...

The `else` would bind the to the `if` in the `LOG()` macro. This is
diagnosed by `-Wdangling-else`.

An alternative approach would be to use a `for` loop and force
a single iteration using a boolean flag or similar. This is entirely
doable but I think the implemented approach is easier to understand.

This change implements the early log level checking using a `switch`
statement as this avoids the dangling else related issues. One small
issue arises because having a boolean controlling expression is diagnosed
by clang (`-Wswitch-bool`); the result is cast to `int` to avoid the warning.

Signed-off-by: Barnabás Pőcze <barnabas.pocze@ideasonboard.com>
---

One remaining questions is the handling of "Fatal" log messages. I think
it would make sense to handle them separately because that way the compiler
could be told that it is actually a `[[noreturn]]` function call.

---
 include/libcamera/base/log.h | 9 +++++++--
 1 file changed, 7 insertions(+), 2 deletions(-)

--
2.48.1

Hi Barnabás,

Thank you for the patch.

On Mon, Mar 03, 2025 at 04:48:44PM +0100, Barnabás Pőcze wrote:
> At the moment every `LOG()` macro invocation results in a `LogMessage`
> being created, the message serialized into an `std::stringstream`.
> Only in the destructor is is actually checked whether the corresponding
> `LogCategory` enables the given log level.
> 
> This is not too efficient, it would be better to skip the log message
> construction and all the `operator<<()` invocations if the message will
> just be discarded.

This means that the behaviour of a LOG() statement where operands have
side effects would differ depending on the log level. We should really
not use any expression with side effects when logging, but if we happen
to do so, the resulting issue would be fairly hard to debug.

Would it be possible for the LOG() macro to return a "blackhole" object
when the severity would result in the message being discarded ?

> This could be easily if the `LOG()` macro accepted its arguments
> like a traditional function as in that case an appropriate `if`
> statement can be injected in a do-while loop. However, that is
> not the case, the `LOG()` macro should effectively "return"
> a stream.
> 
> It is not possible inject an `if` statement directly as that would
> lead to issues:
> 
>   if (...)
>     LOG(...)
>   else
>    ...
> 
> The `else` would bind the to the `if` in the `LOG()` macro. This is
> diagnosed by `-Wdangling-else`.
> 
> An alternative approach would be to use a `for` loop and force
> a single iteration using a boolean flag or similar. This is entirely
> doable but I think the implemented approach is easier to understand.
> 
> This change implements the early log level checking using a `switch`
> statement as this avoids the dangling else related issues. One small
> issue arises because having a boolean controlling expression is diagnosed
> by clang (`-Wswitch-bool`); the result is cast to `int` to avoid the warning.
> 
> Signed-off-by: Barnabás Pőcze <barnabas.pocze@ideasonboard.com>
> ---
> 
> One remaining questions is the handling of "Fatal" log messages. I think
> it would make sense to handle them separately because that way the compiler
> could be told that it is actually a `[[noreturn]]` function call.
> 
> ---
>  include/libcamera/base/log.h | 9 +++++++--
>  1 file changed, 7 insertions(+), 2 deletions(-)
> 
> diff --git a/include/libcamera/base/log.h b/include/libcamera/base/log.h
> index 958cb488d..1a14b8dbc 100644
> --- a/include/libcamera/base/log.h
> +++ b/include/libcamera/base/log.h
> @@ -108,10 +108,15 @@ LogMessage _log(const LogCategory &category, LogSeverity severity,
>  #ifndef __DOXYGEN__
>  #define _LOG_CATEGORY(name) logCategory##name
> 
> +#define _LOG(cat, sev) \
> +	switch (const auto &_logCategory = (cat); int(_logCategory.severity() <= Log##sev)) \
> +	case 1: \
> +		_log(_logCategory, Log##sev).stream()
> +
>  #define _LOG1(severity) \
> -	_log(LogCategory::defaultCategory(), Log##severity).stream()
> +	_LOG(LogCategory::defaultCategory(), severity)
>  #define _LOG2(category, severity) \
> -	_log(_LOG_CATEGORY(category)(), Log##severity).stream()
> +	_LOG(_LOG_CATEGORY(category)(), severity)
> 
>  /*
>   * Expand the LOG() macro to _LOG1() or _LOG2() based on the number of

Hi


2025. 03. 03. 22:15 keltezéssel, Laurent Pinchart írta:
> Hi Barnabás,
> 
> Thank you for the patch.
> 
> On Mon, Mar 03, 2025 at 04:48:44PM +0100, Barnabás Pőcze wrote:
>> At the moment every `LOG()` macro invocation results in a `LogMessage`
>> being created, the message serialized into an `std::stringstream`.
>> Only in the destructor is is actually checked whether the corresponding
>> `LogCategory` enables the given log level.
>>
>> This is not too efficient, it would be better to skip the log message
>> construction and all the `operator<<()` invocations if the message will
>> just be discarded.
> 
> This means that the behaviour of a LOG() statement where operands have
> side effects would differ depending on the log level. We should really
> not use any expression with side effects when logging, but if we happen
> to do so, the resulting issue would be fairly hard to debug.

That is true, but how likely is it? Do you think the likelihood is big
enough to warrant this? I would assume it is unlikely.


> 
> Would it be possible for the LOG() macro to return a "blackhole" object
> when the severity would result in the message being discarded ?

If we had `LOG(X, Y, args...)`, then it would be more or less trivial.
But with the current status quo I think something like this is needed:

   struct LogMessageStream {
     std::ostringstream *const s = nullptr;

     template<typename T, typename = std::void_t<decltype(*s << std::declval<const T&>())>>
     LogMessageStream operator<<(const T& x) const
     {
       if (s) *s << x;
       return *this;
     }
   };

I am not sure how well the optimizer can handle this (probably not too bad).
Also there are still many `x.toString()` calls, and especially in log messages,
which would unfortunately still be evaluated unnecessarily.


Regards,
Barnabás Pőcze


> 
>> This could be easily if the `LOG()` macro accepted its arguments
>> like a traditional function as in that case an appropriate `if`
>> statement can be injected in a do-while loop. However, that is
>> not the case, the `LOG()` macro should effectively "return"
>> a stream.
>>
>> It is not possible inject an `if` statement directly as that would
>> lead to issues:
>>
>>    if (...)
>>      LOG(...)
>>    else
>>     ...
>>
>> The `else` would bind the to the `if` in the `LOG()` macro. This is
>> diagnosed by `-Wdangling-else`.
>>
>> An alternative approach would be to use a `for` loop and force
>> a single iteration using a boolean flag or similar. This is entirely
>> doable but I think the implemented approach is easier to understand.
>>
>> This change implements the early log level checking using a `switch`
>> statement as this avoids the dangling else related issues. One small
>> issue arises because having a boolean controlling expression is diagnosed
>> by clang (`-Wswitch-bool`); the result is cast to `int` to avoid the warning.
>>
>> Signed-off-by: Barnabás Pőcze <barnabas.pocze@ideasonboard.com>
>> ---
>>
>> One remaining questions is the handling of "Fatal" log messages. I think
>> it would make sense to handle them separately because that way the compiler
>> could be told that it is actually a `[[noreturn]]` function call.
>>
>> ---
>>   include/libcamera/base/log.h | 9 +++++++--
>>   1 file changed, 7 insertions(+), 2 deletions(-)
>>
>> diff --git a/include/libcamera/base/log.h b/include/libcamera/base/log.h
>> index 958cb488d..1a14b8dbc 100644
>> --- a/include/libcamera/base/log.h
>> +++ b/include/libcamera/base/log.h
>> @@ -108,10 +108,15 @@ LogMessage _log(const LogCategory &category, LogSeverity severity,
>>   #ifndef __DOXYGEN__
>>   #define _LOG_CATEGORY(name) logCategory##name
>>
>> +#define _LOG(cat, sev) \
>> +	switch (const auto &_logCategory = (cat); int(_logCategory.severity() <= Log##sev)) \
>> +	case 1: \
>> +		_log(_logCategory, Log##sev).stream()
>> +
>>   #define _LOG1(severity) \
>> -	_log(LogCategory::defaultCategory(), Log##severity).stream()
>> +	_LOG(LogCategory::defaultCategory(), severity)
>>   #define _LOG2(category, severity) \
>> -	_log(_LOG_CATEGORY(category)(), Log##severity).stream()
>> +	_LOG(_LOG_CATEGORY(category)(), severity)
>>
>>   /*
>>    * Expand the LOG() macro to _LOG1() or _LOG2() based on the number of
>