Skip to content

Fix LoggerWrapper inefficiency#1213

Merged
rmjarvis merged 4 commits intoreleases/2.4from
logger_wrapper
Mar 22, 2023
Merged

Fix LoggerWrapper inefficiency#1213
rmjarvis merged 4 commits intoreleases/2.4from
logger_wrapper

Conversation

@rmjarvis
Copy link
Member

We have a class in GalSim config called LoggerWrapper, which is intended to avoid communicating with the main logger via the proxy when we aren't actually going to output anything. E.g. logger.debug statements when the logging level is only INFO or WARNING. This is mostly a big improvement.

However, @beckermr and @jchiang87 have each recently found huge inefficiencies when running on Perlmutter with ~128 processes. I tracked it down to when we make a new LoggerWrapper instance and call logger.getEffectiveLevel(). This had always been going back to the original proxy logger instance even when we already have a wrapped one. And for lots of processes, this can end up clogging the inter-process communication completely unnecessarily.

This PR makes the fairly trivial change that when we're re-wrapping something that is already wrapped, it doesn't call getEffectiveLevel. It just gets the already received value stored as an attribute. This seems to resolve the blockage that Matt (and I presume Jim) was seeing.

Copy link
Contributor

@beckermr beckermr left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I don't think there's a good test for this so LGTM!

@rmjarvis rmjarvis merged commit 9932ea2 into releases/2.4 Mar 22, 2023
@rmjarvis rmjarvis deleted the logger_wrapper branch March 22, 2023 21:19
@beckermr
Copy link
Contributor

For posterity, here is the timing of a simple test on perlmutter:

timing 128 processes...
128 5.450411558151245
timing 128 processes...
128 5.5901055335998535
timing 64 processes...
64 5.405612945556641
timing 32 processes...
32 7.624440431594849
timing 16 processes...
16 11.752846002578735
timing 8 processes...
8 20.898335933685303
timing 4 processes...
4 39.02970886230469
timing 2 processes...
2 81.31851077079773

@rmjarvis rmjarvis added this to the v2.4 milestone Mar 22, 2023
@rmjarvis rmjarvis added config Related to the config-processing functionality. optimization/performance Related to the speed and/or memory consumption of some aspect of the code labels Mar 22, 2023
@rmjarvis rmjarvis added the desc Of possible interest to LSST DESC members looking for a project label Jul 21, 2023
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

config Related to the config-processing functionality. desc Of possible interest to LSST DESC members looking for a project optimization/performance Related to the speed and/or memory consumption of some aspect of the code

Projects

None yet

Development

Successfully merging this pull request may close these issues.

2 participants