Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

misc: Add MPI0 logging level #2130

Merged
merged 3 commits into from
Apr 18, 2024
Merged

misc: Add MPI0 logging level #2130

merged 3 commits into from
Apr 18, 2024

Conversation

georgebisbas
Copy link
Contributor

@georgebisbas georgebisbas commented May 17, 2023

This logging mode helps to reduce the output of MPI runs to only emit performance numbers once per MPI rank.
It is mostly aimed to reduce the redundant verbose performance output.

e.g. instead of:

Allocating host memory for u(2, 52, 72, 72) [2 MB]
Allocating host memory for u(2, 52, 72, 72) [2 MB]
Operator `Kernel` generated in 1.72 s
  * lowering.IET: 0.71 s (41.5 %)
     * specializing.IET: 0.66 s (38.6 %)
        * make_mpi: 0.45 s (26.3 %)
  * lowering.Expressions: 0.56 s (32.8 %)
  * lowering.Clusters: 0.41 s (24.0 %)
Flops reduction after symbolic optimization: [209 --> 90]
Operator `Kernel` generated in 1.81 s
  * lowering.IET: 0.72 s (40.0 %)
     * specializing.IET: 0.66 s (36.6 %)
        * make_mpi: 0.45 s (25.0 %)
  * lowering.Expressions: 0.58 s (32.2 %)
  * lowering.Clusters: 0.48 s (26.7 %)
Flops reduction after symbolic optimization: [209 --> 90]
Operator `Kernel` fetched `/tmp/devito-jitcache-uid1000/562b2d8ee0a6d254108e1dfb5522a645f2d8d8e2.c` in 0.06 s from jit-cache
Operator `Kernel` fetched `/tmp/devito-jitcache-uid1000/562b2d8ee0a6d254108e1dfb5522a645f2d8d8e2.c` in 0.06 s from jit-cache
Operator `Kernel` ran in 0.01 s
Operator `Kernel` ran in 0.01 s
Global performance: [OI=2.81, 11.16 GFlops/s, 0.14 GPts/s]
Global performance: [OI=2.81, 11.16 GFlops/s, 0.14 GPts/s]
Local performance:
Local performance:
  * section0[rank0]<21,2,5,8,8,40> ran in 0.01 s [OI=2.81, 10.95 GFlops/s, 0.14 GPts/s]
  * section0[rank0]<21,2,5,8,8,40> ran in 0.01 s [OI=2.81, 10.95 GFlops/s, 0.14 GPts/s]
  * section0[rank1]<21,2,5,8,8,40> ran in 0.01 s [OI=2.81, 10.95 GFlops/s, 0.14 GPts/s]
Performance[mode=advanced] arguments: {'x0_blk0_size': 8, 'y0_blk0_size': 8}
  * section0[rank1]<21,2,5,8,8,40> ran in 0.01 s [OI=2.81, 10.95 GFlops/s, 0.14 GPts/s]
Performance[mode=advanced] arguments: {'x0_blk0_size': 8, 'y0_blk0_size': 8}
Norm u is 2325.5583
Norm u is 2325.5583

we get:

Allocating host memory for u(2, 52, 72, 72) [2 MB]
Allocating host memory for u(2, 52, 72, 72) [2 MB]
Operator `Kernel` generated in 1.81 s
  * lowering.IET: 0.73 s (40.6 %)
     * specializing.IET: 0.67 s (37.3 %)
        * make_mpi: 0.46 s (25.6 %)
  * lowering.Expressions: 0.54 s (30.0 %)
  * lowering.Clusters: 0.51 s (28.4 %)
     * specializing.Clusters: 0.39 s (21.7 %)
Flops reduction after symbolic optimization: [209 --> 90]
Operator `Kernel` generated in 1.80 s
  * lowering.IET: 0.75 s (41.8 %)
     * specializing.IET: 0.69 s (38.4 %)
        * make_mpi: 0.48 s (26.8 %)
  * lowering.Expressions: 0.56 s (31.2 %)
  * lowering.Clusters: 0.46 s (25.6 %)
Flops reduction after symbolic optimization: [209 --> 90]
Operator `Kernel` fetched `/tmp/devito-jitcache-uid1000/562b2d8ee0a6d254108e1dfb5522a645f2d8d8e2.c` in 0.06 s from jit-cache
Operator `Kernel` fetched `/tmp/devito-jitcache-uid1000/562b2d8ee0a6d254108e1dfb5522a645f2d8d8e2.c` in 0.06 s from jit-cache
Operator `Kernel` ran in 0.01 s
Global performance: [OI=2.81, 11.16 GFlops/s, 0.14 GPts/s]
Local performance:
  * section0[rank0]<21,2,5,8,8,40> ran in 0.01 s [OI=2.81, 11.65 GFlops/s, 0.15 GPts/s]
  * section0[rank1]<21,2,5,8,8,40> ran in 0.01 s [OI=2.81, 11.67 GFlops/s, 0.15 GPts/s]
Performance[mode=advanced] arguments: {'x0_blk0_size': 8, 'y0_blk0_size': 8}
Norm u is 2325.5583
Norm u is 2325.558

@codecov
Copy link

codecov bot commented May 17, 2023

Codecov Report

Attention: Patch coverage is 93.75000% with 1 lines in your changes are missing coverage. Please review.

Project coverage is 79.46%. Comparing base (8729cd2) to head (e459d52).

Files Patch % Lines
devito/operator/profiling.py 0.00% 0 Missing and 1 partial ⚠️
Additional details and impacted files
@@            Coverage Diff             @@
##           master    #2130      +/-   ##
==========================================
+ Coverage   79.44%   79.46%   +0.01%     
==========================================
  Files         232      232              
  Lines       43607    43618      +11     
  Branches     8072     8073       +1     
==========================================
+ Hits        34645    34660      +15     
+ Misses       8207     8203       -4     
  Partials      755      755              

☔ View full report in Codecov by Sentry.
📢 Have feedback on the report? Share it here.

@@ -190,6 +191,10 @@ def __init__(self, shape, dimensions, input_comm=None, topology=None):
global init_by_devito
init_by_devito = True

# If MPI0 logging is selected, only emit from rank 0
Copy link
Contributor

Choose a reason for hiding this comment

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

I don't think this is a safe way to do it. You also end up here quite often when devito is called from an external program that initialized MPI already and that would completely turn off the logging on all ranks including 0.

Copy link
Contributor

Choose a reason for hiding this comment

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

If this is something we want it needs to be done outside MPI.Is_initialized() and on a per-rank base using get_Rank

Copy link
Contributor

Choose a reason for hiding this comment

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

I second Mathias. Here you're potentially altering the overarching application behavior.

Also you probably don't need to add a new log level... just restrict logging to rank 0 (if MPI active) inside op._emit_perf_profile or whatever is called. No?

Copy link
Contributor Author

Choose a reason for hiding this comment

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

I think this is addressed now

@@ -190,6 +191,10 @@ def __init__(self, shape, dimensions, input_comm=None, topology=None):
global init_by_devito
init_by_devito = True

# If MPI0 logging is selected, only emit from rank 0
Copy link
Contributor

Choose a reason for hiding this comment

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

I second Mathias. Here you're potentially altering the overarching application behavior.

Also you probably don't need to add a new log level... just restrict logging to rank 0 (if MPI active) inside op._emit_perf_profile or whatever is called. No?

@georgebisbas georgebisbas force-pushed the mpi0_logging branch 2 times, most recently from ef111d5 to 76cca39 Compare May 18, 2023 15:22
@georgebisbas georgebisbas self-assigned this May 18, 2023
@georgebisbas georgebisbas requested a review from mloubout May 19, 2023 07:48

# In case 'MPI0' is selected for logging, restrict result printing to one rank
if configuration['mpi']:
set_log_level(configuration['log-level'], comm=args.comm)
Copy link
Contributor

Choose a reason for hiding this comment

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

I still don't really like changing configuration like that unless it's a temporary swithconfig

Copy link
Contributor Author

Choose a reason for hiding this comment

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

Based on this comment: #2130 (comment)

I thought that we would be happy to happen here?

Copy link
Contributor

Choose a reason for hiding this comment

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

no, this would change user-level setup after the first Operator run, so afterwards we would only see output from one rank

@georgebisbas georgebisbas requested a review from mloubout June 19, 2023 16:02
@georgebisbas georgebisbas force-pushed the mpi0_logging branch 2 times, most recently from 6a21332 to 3544c7a Compare June 27, 2023 10:15

# In case 'MPI0' is selected for logging, restrict result printing to one rank
if configuration['mpi']:
set_log_level(configuration['log-level'], comm=args.comm)
Copy link
Contributor

Choose a reason for hiding this comment

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

no, this would change user-level setup after the first Operator run, so afterwards we would only see output from one rank

@@ -952,7 +957,12 @@ def _emit_apply_profiling(self, args):
if a in args:
perf_args[a] = args[a]
break
perf("Performance[mode=%s] arguments: %s" % (self._mode, perf_args))

if configuration['mpi']:
Copy link
Contributor

Choose a reason for hiding this comment

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

nitpicking: the following way more easily generalisable to any number of items

items = []
items.append('mode=%s' % self._mode)
if configuration['mpi']: #Do we really want this `if` ? maybe we just spell it out regardless
    items.append('mpi=%s' % configuration['mpi'])
perf("Performance[%s] arguments: %s" % (', '.join(items), perf_args))

@georgebisbas
Copy link
Contributor Author

To add:
-Until Devito v3.5 included, domain decomposition occurs along the fastest axis. As of later versions, domain decomposition occurs along the slowest axis, for performance reasons. And yes, it is possible to control the domain decomposition in user code, but this is not neatly documented. Take a look at test_custom_topology in this file. In essence, Grid accepts the optional argument topology, which allows the user to pass a custom topology as an n-tuple, where n is the number of distributed dimensions. For example, for a two-dimensional grid, the topology (4, 1) will decompose the slowest axis into four partitions, one partition per MPI rank, while the fastest axis will be replicated over all MPI ranks.
+Until Devito v3.5 included, domain decomposition occurs along the fastest axis. As of later versions, domain decomposition occurs along the slowest axis, for performance reasons. And yes, it is possible to control the domain decomposition in user code, but this is not neatly documented. Take a look at
+class CustomTopology in distributed.py
+and test_custom_topology in this file. In essence, Grid accepts the optional argument topology, which allows the user to pass a custom topology as an n-tuple, where n is the number of distributed dimensions. For example, for a two-dimensional grid, the topology (4, 1) will decompose the slowest axis into four partitions, one partition per MPI rank, while the fastest axis will be replicated over all MPI ranks.

@georgebisbas
Copy link
Contributor Author

Would this PR help: #2175
to avoid changing the user-level setup and only make a temp switchconfig as per the original plan?

FAQ.md Show resolved Hide resolved
@georgebisbas
Copy link
Contributor Author

Is this PR fine?

FAQ.md Outdated Show resolved Hide resolved
else:
perf("Performance[mode=%s] arguments: %s" % (self._mode, perf_args))

# Restore logging configuration to all ranks
Copy link
Contributor

Choose a reason for hiding this comment

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

why don't u use switchconfig?

Copy link
Contributor Author

Choose a reason for hiding this comment

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

@georgebisbas
Copy link
Contributor Author

Converting to draft as apprantly switchcongfig does not work

@georgebisbas georgebisbas force-pushed the mpi0_logging branch 2 times, most recently from 00a4c34 to c67c473 Compare January 17, 2024 13:58
# In case MPI is used restrict result logging to one rank only
if configuration['mpi']:
# Only temporarily change configuration
with switchconfig(mpi=True):
Copy link
Contributor

Choose a reason for hiding this comment

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

what does mpi=True mean?

if configuration['mpi']:
# Only temporarily change configuration
with switchconfig(mpi=True):
set_log_level('DEBUG', comm=args.comm)
Copy link
Contributor

Choose a reason for hiding this comment

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

Again: you're switching to DEBUG and then it remains DEBUG once control is handed back to the user

it shouldn't be DEBUG either, it should be whatever was set up to this point

and finally we shouldn't switch to mpi=True (why btw?) because it will trigger a compiler rebuild which we should (can) avoid: https://github.com/devitocodes/devito/blob/master/devito/__init__.py#L74

Copy link
Contributor Author

Choose a reason for hiding this comment

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

Oh right. Makes sense. Thanks

Copy link
Contributor

@FabioLuporini FabioLuporini left a comment

Choose a reason for hiding this comment

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

@georgebisbas georgebisbas force-pushed the mpi0_logging branch 2 times, most recently from 9dcab9f to 5ff0adf Compare April 10, 2024 14:01
@georgebisbas georgebisbas marked this pull request as ready for review April 10, 2024 14:14
devito/logger.py Outdated
# Add extra logging levels (note: INFO has value=20, WARNING has value=30)
DEBUG = logging.DEBUG
# Add extra logging levels
DEBUG = logging.DEBUG # value=10
Copy link
Contributor

Choose a reason for hiding this comment

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

implementation detail

Copy link
Contributor Author

Choose a reason for hiding this comment

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

Not sure I understand what to change here

Copy link
Contributor

Choose a reason for hiding this comment

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

I think the numbers should be dropped

Copy link
Contributor Author

Choose a reason for hiding this comment

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

I am reverting as before, some detail is useful

# Output summary of performance achieved
return self._emit_apply_profiling(args)
# In case MPI is used restrict result logging to one rank only
if configuration['mpi']:
Copy link
Contributor

Choose a reason for hiding this comment

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

this shouldn't be needed

Copy link
Contributor Author

Choose a reason for hiding this comment

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

This is needed only if the user accidentally asks for copies of an execution.
i.e. DEVITO_MPI=0 mpirun -n 2.
if not it will break with:

Attempting to use an MPI routine (internal_Comm_rank) before initializing or after finalizing MPICH

Copy link
Contributor Author

Choose a reason for hiding this comment

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

I can get away with a try-except in mpi_switch_log ?

Copy link
Contributor

Choose a reason for hiding this comment

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

probably

Copy link
Contributor Author

Choose a reason for hiding this comment

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

added another condition in set_log_level

return self._emit_apply_profiling(args)
# In case MPI is used restrict result logging to one rank only
if configuration['mpi']:
with mpi_switch_log(log_level='DEBUG', comm=args.comm):
Copy link
Contributor

Choose a reason for hiding this comment

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

why make the "switch log" mpi-specific?

Copy link
Contributor Author

Choose a reason for hiding this comment

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

I wanted to avoid confusion between having sth like set_log_level and switch_log
I am happy if you propose a name for that

Copy link
Contributor

Choose a reason for hiding this comment

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

switch_log_level is fine

Copy link
Contributor Author

Choose a reason for hiding this comment

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

done


def __init__(self, **params):
self.params = {k.replace('_', '-'): v for k, v in params.items()}
self.previous = {}
Copy link
Contributor

Choose a reason for hiding this comment

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

this is never updated, how can this even work?

Copy link
Contributor Author

Choose a reason for hiding this comment

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

it was using the parent class enter

"""

def __init__(self, **params):
self.params = {k.replace('_', '-'): v for k, v in params.items()}
Copy link
Contributor

Choose a reason for hiding this comment

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

what's params for?

this function should expect, imho, two arguments: a level and a comm (the latter being optional)

Copy link
Contributor Author

Choose a reason for hiding this comment

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

Yes, maybe I can do it simpler

@@ -77,7 +77,7 @@ def set_log_level(level, comm=None):
"""
from devito import configuration

if comm is not None:
if comm is not None and configuration['mpi']:
Copy link
Contributor

Choose a reason for hiding this comment

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

why is this addition needed?

Copy link
Contributor Author

Choose a reason for hiding this comment

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

To elegantly alleviate the case of DEVITO_MPI=0 mpirun -n 2 (running copies of the problem) as discussed

# In case MPI is used restrict result logging to one rank only
with switch_log_level(comm=args.comm):
return self._emit_apply_profiling(args)

return self._emit_apply_profiling(args)
Copy link
Contributor

Choose a reason for hiding this comment

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

emitting twice ?

Copy link
Contributor Author

Choose a reason for hiding this comment

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

ha! Actually not emmiting twice, but dead code never executed! dropping

class switch_log_level(object):
"""
A context manager subclassing `switchconfig` to temporarily change
MPI logging.
Copy link
Contributor

Choose a reason for hiding this comment

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

old docstring

Copy link
Contributor Author

Choose a reason for hiding this comment

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

fixed

self.comm = comm

# Limit logging to rank 0
set_log_level(self.level, comm)
Copy link
Contributor

Choose a reason for hiding this comment

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

theoretically shouldn't this be inside __enter__? though in practice it might not change much

Copy link
Contributor Author

Choose a reason for hiding this comment

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

fixed

@@ -258,6 +258,29 @@ def wrapper(*args, **kwargs):
return wrapper


class switch_log_level(object):
Copy link
Contributor

Choose a reason for hiding this comment

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

doesn't this belong to logger.py?

Copy link
Contributor Author

Choose a reason for hiding this comment

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

moved, but inserted import configuration in in __init__ to avoid circular imports

devito/parameters.py Outdated Show resolved Hide resolved
devito/parameters.py Outdated Show resolved Hide resolved
devito/logger.py Outdated Show resolved Hide resolved
Copy link
Contributor

@FabioLuporini FabioLuporini left a comment

Choose a reason for hiding this comment

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

couple of nitpicks, but this is now GTG basically

devito/logger.py Outdated

def __exit__(self, *args):
set_log_level(self.level)
logger.addHandler(stream_handler)
Copy link
Contributor

Choose a reason for hiding this comment

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

shouldn't this line go inside set_log_level in an else branch representing the comm is None case? this way, a set_log_level in user code will behave as expected

Copy link
Contributor

Choose a reason for hiding this comment

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

note: the above is nitpicking


Until Devito v3.5 included, domain decomposition occurs along the fastest axis. As of later versions, domain decomposition occurs along the slowest axis, for performance reasons. And yes, it is possible to control the domain decomposition in user code, but this is not neatly documented. Take a look at `test_custom_topology` in [this file](https://github.com/devitocodes/devito/blob/master/tests/test_mpi.py). In essence, `Grid` accepts the optional argument `topology`, which allows the user to pass a custom topology as an n-tuple, where `n` is the number of distributed dimensions. For example, for a two-dimensional grid, the topology `(4, 1)` will decompose the slowest axis into four partitions, one partition per MPI rank, while the fastest axis will be replicated over all MPI ranks.
Until Devito v3.5 included, domain decomposition occurs along the fastest axis. As of later versions, domain decomposition occurs along the slowest axis, for performance reasons. And yes, it is possible to control the domain decomposition in user code, but this is not neatly documented. Take a look at `class CustomTopology` in [distributed.py](https://github.com/devitocodes/devito/blob/master/devito/mpi/distributed.py) and `test_custom_topology` in [this file](https://github.com/devitocodes/devito/blob/master/tests/test_mpi.py). In essence, `Grid` accepts the optional argument `topology`, which allows the user to pass a custom topology as an n-tuple, where `n` is the number of distributed dimensions. For example, for a two-dimensional grid, the topology `(4, 1)` will decompose the slowest axis into four partitions, one partition per MPI rank, while the fastest axis will be replicated over all MPI ranks.
Copy link
Contributor

Choose a reason for hiding this comment

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

"Up to and including Devito v3.5," would be a more natural wording


# Triggers a callback to `_set_log_level`
configuration['log-level'] = level


class switch_log_level(object):
Copy link
Contributor

Choose a reason for hiding this comment

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

object is no longer needed. Just class switch_log_level:

Copy link
Contributor

Choose a reason for hiding this comment

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

nitpicking: class names start with upercase and don't use underscore

Copy link
Contributor

Choose a reason for hiding this comment

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

For context managers lower case is probably acceptable


# Triggers a callback to `_set_log_level`
configuration['log-level'] = level


class switch_log_level(object):
Copy link
Contributor

Choose a reason for hiding this comment

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

nitpicking: class names start with upercase and don't use underscore

A context manager to temporarily change MPI logging.
"""

def __init__(self, comm):
Copy link
Contributor

Choose a reason for hiding this comment

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

comm is confusing we use it everywhere for the MPI comm, rename to level

Copy link
Contributor

Choose a reason for hiding this comment

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

it is actually an MPI comm

# Output summary of performance achieved
return self._emit_apply_profiling(args)
# In case MPI is used restrict result logging to one rank only
with switch_log_level(comm=args.comm):
Copy link
Contributor

Choose a reason for hiding this comment

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

remind me why switchconfig doesn't work here?

Copy link
Contributor

Choose a reason for hiding this comment

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

you have to pass the comm

@mloubout mloubout merged commit 3294158 into master Apr 18, 2024
31 checks passed
@mloubout mloubout deleted the mpi0_logging branch April 18, 2024 12:28
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
Projects
None yet
Development

Successfully merging this pull request may close these issues.

4 participants