Change potentially slow log statements to subroutines

[John Merriam]

See OpenSRF LP#1824181 https://bugs.launchpad.net/opensrf/+bug/1824181

This depends on the above change which was released in OpenSRF 3.0.3 and 3.1.1.

The Evergreen code was searched for potentially slow logging statements at log level info or above. We then changed those logging statements to be delayed execution subroutines.

Here is some pseudocode that shows what is being done here:

$log->debug("Some text " . $some->slow_method);

would be changed to:

$log->debug(sub{return "Some text " . $some->slow_method });

In the example change above, an unnamed sub is passed to the OpenSRF logger module and it will not be executed unless the global logging level is set to debug or higher (the slow_method will not be called unless it is needed for the global logging level).

********
If/when this is committed, please use delayed execution subroutines in the future for any logging statements that could be slow. It is recommend that any logging statements that do not consist entirely of quoted text and/or already available scalar variables use delayed execution subroutines.
********

Branch to follow.

[John Merriam (jmerriam)]

Evergreen branch is working/user/jmerriam/use_log_subs: https://git.evergreen-ils.org/?p=working/Evergreen.git;a=shortlog;h=refs/heads/user/jmerriam/use_log_subs

[John Merriam (jmerriam)]

These changes should result in increased responsiveness and reduced resource utilization for the Evergreen system. They only affect the Perl portions of Evergreen though. We have been running with similar changes to the Evergreen 3.1 releases for months now with no problems.

[Mike Rylander (mrylander)]

Hi John, thanks for working on this.

Do you have timing information on the improvements, and confirmation that the closures are never reporting old information?

I think it's a good idea to move some logging to the function syntax, but several of these changes make me nervous. In particular, there are logging statements that have side effects (incrementing a variable, say) that won't happen unless the logging level is high enough. I'm also not convinced that the cost of closure creation (and the memory increase it would incur) is worth it for trivial log lines that just stitch together short strings, or run sprintf or the like. Info and error level lines are almost always logged, and should probably have a pretty high bar for function-ification, IMO. If an info or error log line is costly (or noisy) it should probably be lowered to debug or otherwise reworked.

As a general rule, I would be in favor of changing logging that requires an expensive function call IFF it doesn't have any side effects. That may mean removing the side effect, which is probably a good idea anyway. It might be worth evaluating the memory and time cost of moving, say, substantially all debug and internal log lines to the function syntax, compared to always building the log string.

[John Merriam (jmerriam)]

Hi Mike.

I do not have any timing information beyond a general seat of the pants feel that Evergreen seems a bit faster with these changes.

I'm not sure how it would be possible for old information to be reported?

Regarding side effects, I would argue that it is a bad idea to use logging statements to do anything other than log information. I didn't analyze every logging statement that I touched in detail but I didn't notice anything that looked like it was doing that.

The only logging statements that were changed in my branch are those that are at log level info or higher (not level error or warn) that are also doing something more than pulling together quoted strings and scalar variables. The ones that were changed involve something like calling methods, pulling data from arrays or hashes (which could be slow if they are large), or using the data dumper.

We run at log level warn because info is too noisy for us. warn seems to give a good balance of information vs noise.

[Bill Erickson (berick)]

I got excited about this and decided to run some tests. I ran the hold targeter 4 times in a row (with a 1-second recheck interval to force updates) both pre and post patch. Much to my surprise, the delayed logging mechanism actually made things very slightly slower :\

-- pre-patch timing at WARN loglevel

real 0m23.509s
user 0m0.309s
sys 0m0.028s

real 0m23.737s
user 0m0.304s
sys 0m0.041s

real 0m23.825s
user 0m0.313s
sys 0m0.020s

real 0m22.847s
user 0m0.310s
sys 0m0.032s

avg: 23.4795

-- post-patch timing at WARN loglevel

real 0m25.774s
user 0m0.304s
sys 0m0.037s

real 0m24.530s
user 0m0.332s
sys 0m0.020s

real 0m22.944s
user 0m0.322s
sys 0m0.053s

real 0m24.090s
user 0m0.309s
sys 0m0.033s

avg: 24.3345

I also tested at ...

[John Merriam (jmerriam)]

It may be a bit slower. The idea was to try to not call potentially slow methods gathering things for logging when we aren't running at a log level where they would actually be logged.

Another approach would be to export the global logging level from the logging module and then put if statements around all logging code above log level error.

[Bill Erickson (berick)]

On Thu, Apr 7, 2022 at 1:11 PM John Merriam <email address hidden>
wrote:

> It may be a bit slower. The idea was to try to not call potentially
> slow methods gathering things for logging when we aren't running at a
> log level where they would actually be logged.
>

Right, and like I said, other work flows may benefit, possibly a lot. I
was just surprised the first thing I tested was a hair slower and it gives
me pause. Maybe the patch could be more targeted?

>
> Another approach would be to export the global logging level from the
> logging module and then put if statements around all logging code above
> log level error.
>

I could certainly see this helping. We take a similar approach in
OpenSRF's Server module. See the $chatty variable -- which, incidentally,
is enabled by default.

https://git.evergreen-ils.org/?p=OpenSRF.git;a=blob;f=src/perl/lib/OpenSRF/Server.pm;h=52c53d244c63a91bc1364ca471b6a1ae09dfc0e9;hb=refs/heads/master