Change potentially slow log statements to subroutines

Bug #1840053 reported by John Merriam
6
This bug affects 1 person
Affects Status Importance Assigned to Milestone
Evergreen
Undecided
Unassigned

Bug Description

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.

Revision history for this message
John Merriam (jmerriam) wrote :
Revision history for this message
John Merriam (jmerriam) wrote :

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.

John Merriam (jmerriam)
tags: added: pullrequest
Remington Steed (rjs7)
tags: added: performance
Revision history for this message
Mike Rylander (mrylander) wrote :

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.

Revision history for this message
John Merriam (jmerriam) wrote :

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.

Changed in evergreen:
milestone: none → 3.next
To post a comment you must log in.
This report contains Public information  Edit
Everyone can see this information.

Other bug subscribers