Re: Logging GR 3.9

[Boris Marjanovic]

Thanks Jeff, that looks good from my perspective.

On Fri, 6 Aug 2021 at 03:44, Jeff Long <willcode4@gmail.com> wrote:

Draft PR for this: https://github.com/gnuradio/gnuradio/pull/4982

On Thu, Aug 5, 2021 at 8:58 AM Boris Marjanovic <bmarjanovic@gmail.com> wrote:

In our case the difference logging level was set to ERROR. There were no lines logged. I ran a valgrind with no special settings

- log4cpp was approximately 5% of total running time

- after modifying logging macros, it was 0.02%

The effect would depend on how one does logging. If the logging statements are simple strings, then I would not expect a huge impact. In our case the statements could look like

     GR_LOG_DEBUG(d_logger, fmt::format("frequency = {} sample rate = {}", freq, samplerate));

The formatting string will be evaluated to get a char* even if logging level is INFO due to being an _expression_ in an operator call.

With simple string literal for log statement, a CategoryStream would need to be created regardless of the logging level.

I had another look at log4cpp source and there are log calls that allow variadic parameter lists similar to sprintf statements after the level has been confirmed. Maybe they were deemed too heavy for the case of simple logging.

I essentially just did what Jeff mentioned - added priority check into the macro. So instead of

#define GR_LOG_INFO(logger, msg)                                     \
    {                                                                \
        *logger << log4cpp::Priority::INFO << (msg) << log4cpp::eol; \
    }

we use

#define ALB_LOG_INFO(logger, msg)                                       \
  {                                                                     \
    if (logger->isPriorityEnabled(log4cpp::Priority::INFO))             \
          *logger << log4cpp::Priority::INFO << (msg) << log4cpp::eol;        \
  }

This is just a stop-gap, really. It is not ideal since, if a logger is enabled, the isPriorityEnabled(..) is called twice. But in the short term, it does the job. If the logger is not enabled the priority is checked once and logging statement is not evaluated.

Hope that made sense. 

Cheers

Boris

On Thu, 5 Aug 2021 at 20:16, Jeff Long <willcode4@gmail.com> wrote:

How badly is this affecting performance? I could see adding something like a GR_CHECK_LEVEL() to all the logging macros if the call to log4cpp's getPriority() is cheaper than executing the (msg) code. It probably is.

On Wed, Aug 4, 2021 at 2:28 PM Marcus Müller <mmueller@gnuradio.org> wrote:

Hi Boris,

I honestly thought, up to last week, the same as you. So, this is not intended, and we'll
fix it, but sadly probably not on 3.9.

Best regards,
Marcus

On 29.07.21 07:39, Boris Marjanovic wrote:
> Hi,
>
> I've been profiling the flowgraph I've been working on and discovered that there is a lot
> of time spent in logging infrastructure even when logging levels were not enabled.
> The logging statements are not simple strings but a call to the formatting library in my
> case. I used the fmt library. So the statement looks something like :
>     GR_LOG_DEBUG(this->d_logger, fmt::format("a = {} b = {}", a, b));
> (equivalent for any other formatting lib)
> So even when the logging level is at INFO, the formatting statement will evaluate to
> create a string that could/should be logged.
>
> This did not make sense to me. If the logging level is set to INFO, I would not expect the
> system to evaluate the above formatting statement. But it does due to the way macros are
> done and log4cpp manages logging statements and priority levels.
>
> I'm curious if this is desired/expected behaviour?
>
> I worked around this by defining a set of macros that check logger's logging level before
> attempting to stream a log line to the logger object.
>
> Regards
> Boris