LP#1824184: Change potentially slow log statements to subroutines
authorJohn Merriam <jmerriam@biblio.org>
Wed, 10 Apr 2019 15:06:14 +0000 (11:06 -0400)
committerGalen Charlton <gmc@equinoxinitiative.org>
Fri, 7 Jun 2019 15:31:59 +0000 (11:31 -0400)
commit32c6058def9336eaf4f36da2930a147240392e9d
tree006dafbdcc8d29fbb6c2cb169e06bce1a96ed0c5
parent703809d19a3336ee975d39efc3372363f6268365
LP#1824184: Change potentially slow log statements to subroutines

The OpenSRF 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. This is in reaction to LP1823338 where a
slow debug logging statement was slowing down SIP checkins even though
debug logging was not turned on.

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 });

With this change, 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 that logging level).

********
If/when this is committed, please use delayed execution subroutines for
any logging statements that could be slow in the future. 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.
********

Testing notes
-------------
[1] This patch reduced the duration of open-ils.storage.actor.user.total_owed
    calls on a test system from an average of 0.13 seconds to an overage
    of 0.009 seconds.
[2] It didn't materially affect the duration of calls to
    open-ils.actor.user.opac.vital_stats.
[3] This make sense: open-ils.storage has far more generated methods
    than open-ils.actor.
[4] There are enough instances in Evergreen of using method_lookup to find
    routines in open-ils.storage that the speed improvement may well be
    perceptible to humans, not just SIP sorters.

Signed-off-by: John Merriam <jmerriam@biblio.org>
Signed-off-by: Galen Charlton <gmc@equinoxinitiative.org>
src/perl/lib/OpenSRF/AppSession.pm
src/perl/lib/OpenSRF/Application.pm
src/perl/lib/OpenSRF/DomainObject/oilsMessage.pm
src/perl/lib/OpenSRF/EX.pm
src/perl/lib/OpenSRF/MultiSession.pm
src/perl/lib/OpenSRF/Server.pm
src/perl/lib/OpenSRF/Transport.pm
src/perl/lib/OpenSRF/Transport/SlimJabber/Client.pm