diff --git a/devito/operator/operator.py b/devito/operator/operator.py index 3a36952a58..61464120c5 100644 --- a/devito/operator/operator.py +++ b/devito/operator/operator.py @@ -194,7 +194,7 @@ def _sanitize_exprs(cls, expressions, **kwargs): @classmethod def _build(cls, expressions, **kwargs): # Python- (i.e., compile-) and C-level (i.e., run-time) performance - profiler = create_profile('timers') + profiler = create_profile('timers', kwargs['language']) # Lower the input expressions into an IET irs, byproduct = cls._lower(expressions, profiler=profiler, **kwargs) @@ -1004,7 +1004,9 @@ def _emit_apply_profiling(self, args): elapsed = fround(self._profiler.py_timers['apply']) info(f"Operator `{self.name}` ran in {elapsed:.2f} s") - summary = self._profiler.summary(args, self._dtype, reduce_over=elapsed) + summary = self._profiler.summary( + args, self._dtype, self.parameters, reduce_over=elapsed + ) if not is_log_enabled_for('PERF'): # Do not waste time diff --git a/devito/operator/profiling.py b/devito/operator/profiling.py index ae2f50e171..360d506d17 100644 --- a/devito/operator/profiling.py +++ b/devito/operator/profiling.py @@ -17,6 +17,7 @@ from devito.parameters import configuration from devito.symbolics import subs_op_args from devito.tools import DefaultOrderedDict, flatten +from devito.petsc.logging import PetscSummary __all__ = ['create_profile'] @@ -42,7 +43,7 @@ class Profiler: _attempted_init = False - def __init__(self, name): + def __init__(self, name, language): self.name = name # Operation reductions observed in sections @@ -55,6 +56,9 @@ def __init__(self, name): # Python-level timers self.py_timers = OrderedDict() + # For language specific summaries + self.language = language + self._attempted_init = True def analyze(self, iet): @@ -179,7 +183,7 @@ def record_ops_variation(self, initial, final): def all_sections(self): return list(self._sections) + flatten(self._subsections.values()) - def summary(self, args, dtype, reduce_over=None): + def summary(self, args, dtype, params, reduce_over=None): """ Return a PerformanceSummary of the profiled sections. @@ -277,7 +281,7 @@ def _allgather_from_comm(self, comm, time, ops, points, traffic, sops, itershape return list(zip(times, opss, pointss, traffics, sops, itershapess)) # Override basic summary so that arguments other than runtime are computed. - def summary(self, args, dtype, reduce_over=None): + def summary(self, args, dtype, params, reduce_over=None): grid = args.grid comm = args.comm @@ -338,6 +342,11 @@ def summary(self, args, dtype, reduce_over=None): # data transfers) summary.add_glb_fdlike('fdlike-nosetup', points, reduce_over_nosetup) + # Add the language specific summary + summary.add_language_summary( + self.language, + language_summary_mapper[self.language](params) + ) return summary @@ -478,6 +487,16 @@ def add_glb_fdlike(self, key, points, time): self.globals[key] = PerfEntry(time, None, gpointss, None, None, None) + def add_language_summary(self, lang, summary): + """ + Register a language specific summary (e.g., PetscSummary) + and dynamically add a property to access it via perf_summary.. + """ + # TODO: Consider renaming `PerformanceSummary` to something more generic + # (e.g., `Summary`), or separating `PetscSummary` entirely from + # `PerformanceSummary`. + setattr(self, lang, summary) + @property def globals_all(self): v0 = self.globals['vanilla'] @@ -503,7 +522,7 @@ def timings(self): return OrderedDict([(k, v.time) for k, v in self.items()]) -def create_profile(name): +def create_profile(name, language): """Create a new Profiler.""" if configuration['log-level'] in ['DEBUG', 'PERF'] and \ configuration['profiling'] == 'basic': @@ -511,13 +530,13 @@ def create_profile(name): level = 'advanced' else: level = configuration['profiling'] - profiler = profiler_registry[level](name) + profiler = profiler_registry[level](name, language) if profiler._attempted_init: return profiler else: warning(f"Couldn't set up `{level}` profiler; reverting to 'advanced'") - profiler = profiler_registry['advanced'](name) + profiler = profiler_registry['advanced'](name, language) # We expect the `advanced` profiler to always initialize successfully assert profiler._attempted_init return profiler @@ -533,3 +552,8 @@ def create_profile(name): 'advisor': AdvisorProfiler } """Profiling levels.""" + + +language_summary_mapper = { + 'petsc': PetscSummary +} diff --git a/devito/petsc/iet/logging.py b/devito/petsc/iet/logging.py new file mode 100644 index 0000000000..6a1c74d767 --- /dev/null +++ b/devito/petsc/iet/logging.py @@ -0,0 +1,77 @@ +from functools import cached_property + +from devito.symbolics import Byref, FieldFromPointer +from devito.ir.iet import DummyExpr +from devito.logger import PERF + +from devito.petsc.iet.utils import petsc_call +from devito.petsc.logging import petsc_return_variable_dict, PetscInfo + + +class PetscLogger: + """ + Class for PETSc loggers that collect solver related statistics. + """ + def __init__(self, level, **kwargs): + self.sobjs = kwargs.get('solver_objs') + self.sreg = kwargs.get('sregistry') + self.section_mapper = kwargs.get('section_mapper', {}) + self.injectsolve = kwargs.get('injectsolve', None) + + self.function_list = [] + + if level <= PERF: + self.function_list.extend([ + 'kspgetiterationnumber', + 'snesgetiterationnumber' + ]) + + # TODO: To be extended with if level <= DEBUG: ... + + name = self.sreg.make_name(prefix='petscinfo') + pname = self.sreg.make_name(prefix='petscprofiler') + + self.statstruct = PetscInfo( + name, pname, self.logobjs, self.sobjs, + self.section_mapper, self.injectsolve, + self.function_list + ) + + @cached_property + def logobjs(self): + """ + Create PETSc objects specifically needed for logging solver statistics. + """ + return { + info.name: info.variable_type( + self.sreg.make_name(prefix=info.output_param) + ) + for func_name in self.function_list + for info in [petsc_return_variable_dict[func_name]] + } + + @cached_property + def calls(self): + """ + Generate the PETSc calls that will be injected into the C code to + extract solver statistics. + """ + struct = self.statstruct + calls = [] + for param in self.function_list: + param = petsc_return_variable_dict[param] + + inputs = [] + for i in param.input_params: + inputs.append(self.sobjs[i]) + + logobj = self.logobjs[param.name] + + calls.append( + petsc_call(param.name, inputs + [Byref(logobj)]) + ) + # TODO: Perform a PetscCIntCast here? + expr = DummyExpr(FieldFromPointer(logobj._C_symbol, struct), logobj._C_symbol) + calls.append(expr) + + return tuple(calls) diff --git a/devito/petsc/iet/passes.py b/devito/petsc/iet/passes.py index b4859dda16..8d7042bb6c 100644 --- a/devito/petsc/iet/passes.py +++ b/devito/petsc/iet/passes.py @@ -5,7 +5,7 @@ from devito.passes.iet.engine import iet_pass from devito.ir.iet import (Transformer, MapNodes, Iteration, BlankLine, DummyExpr, CallableBody, List, Call, Callable, - FindNodes) + FindNodes, Section) from devito.symbolics import Byref, Macro, FieldFromPointer from devito.types import Symbol, Scalar from devito.types.basic import DataSymbol @@ -22,8 +22,11 @@ CoupledObjectBuilder, BaseSetup, CoupledSetup, Solver, CoupledSolver, TimeDependent, NonTimeDependent) +from devito.petsc.iet.logging import PetscLogger from devito.petsc.iet.utils import petsc_call, petsc_call_mpi +import devito.logger as dl + @iet_pass def lower_petsc(iet, **kwargs): @@ -63,14 +66,17 @@ def lower_petsc(iet, **kwargs): subs = {} efuncs = {} + # Map PETScSolve to its Section (for logging) + section_mapper = MapNodes(Section, PetscMetaData, 'groupby').visit(iet) + for iters, (injectsolve,) in injectsolve_mapper.items(): - builder = Builder(injectsolve, objs, iters, comm, **kwargs) + builder = Builder(injectsolve, objs, iters, comm, section_mapper, **kwargs) setup.extend(builder.solversetup.calls) # Transform the spatial iteration loop with the calls to execute the solver - subs.update({builder.solve.spatial_body: builder.solve.calls}) + subs.update({builder.solve.spatial_body: builder.calls}) efuncs.update(builder.cbbuilder.efuncs) @@ -78,7 +84,7 @@ def lower_petsc(iet, **kwargs): iet = Transformer(subs).visit(iet) - body = core + tuple(setup) + (BlankLine,) + iet.body.body + body = core + tuple(setup) + iet.body.body body = iet.body._rebuild(body=body) iet = iet._rebuild(body=body) metadata = {**core_metadata(), 'efuncs': tuple(efuncs.values())} @@ -125,49 +131,64 @@ class Builder: returning subclasses of the objects initialised in __init__, depending on the properties of `injectsolve`. """ - def __init__(self, injectsolve, objs, iters, comm, **kwargs): + def __init__(self, injectsolve, objs, iters, comm, section_mapper, **kwargs): self.injectsolve = injectsolve self.objs = objs self.iters = iters self.comm = comm + self.section_mapper = section_mapper self.kwargs = kwargs self.coupled = isinstance(injectsolve.expr.rhs.fielddata, MultipleFieldData) - self.args = { + self.common_kwargs = { 'injectsolve': self.injectsolve, 'objs': self.objs, 'iters': self.iters, 'comm': self.comm, + 'section_mapper': self.section_mapper, **self.kwargs } - self.args['solver_objs'] = self.objbuilder.solver_objs - self.args['timedep'] = self.timedep - self.args['cbbuilder'] = self.cbbuilder + self.common_kwargs['solver_objs'] = self.objbuilder.solver_objs + self.common_kwargs['timedep'] = self.timedep + self.common_kwargs['cbbuilder'] = self.cbbuilder + self.common_kwargs['logger'] = self.logger @cached_property def objbuilder(self): return ( - CoupledObjectBuilder(**self.args) + CoupledObjectBuilder(**self.common_kwargs) if self.coupled else - BaseObjectBuilder(**self.args) + BaseObjectBuilder(**self.common_kwargs) ) @cached_property def timedep(self): time_mapper = self.injectsolve.expr.rhs.time_mapper timedep_class = TimeDependent if time_mapper else NonTimeDependent - return timedep_class(**self.args) + return timedep_class(**self.common_kwargs) @cached_property def cbbuilder(self): - return CCBBuilder(**self.args) if self.coupled else CBBuilder(**self.args) + return CCBBuilder(**self.common_kwargs) \ + if self.coupled else CBBuilder(**self.common_kwargs) @cached_property def solversetup(self): - return CoupledSetup(**self.args) if self.coupled else BaseSetup(**self.args) + return CoupledSetup(**self.common_kwargs) \ + if self.coupled else BaseSetup(**self.common_kwargs) @cached_property def solve(self): - return CoupledSolver(**self.args) if self.coupled else Solver(**self.args) + return CoupledSolver(**self.common_kwargs) \ + if self.coupled else Solver(**self.common_kwargs) + + @cached_property + def logger(self): + log_level = dl.logger.level + return PetscLogger(log_level, **self.common_kwargs) + + @cached_property + def calls(self): + return List(body=self.solve.calls+self.logger.calls) def populate_matrix_context(efuncs, objs): diff --git a/devito/petsc/iet/routines.py b/devito/petsc/iet/routines.py index 9249c7a557..d21af4be6b 100644 --- a/devito/petsc/iet/routines.py +++ b/devito/petsc/iet/routines.py @@ -7,22 +7,21 @@ retrieve_iteration_tree, filter_iterations, Iteration, PointerCast) from devito.symbolics import (Byref, FieldFromPointer, cast, VOID, - FieldFromComposite, IntDiv, Deref, Mod) + FieldFromComposite, IntDiv, Deref, Mod, String) from devito.symbolics.unevaluation import Mul from devito.types.basic import AbstractFunction from devito.types import Temp, Dimension from devito.tools import filter_ordered -from devito.petsc.types import PETScArray, PetscBundle from devito.petsc.iet.nodes import (PETScCallable, FormFunctionCallback, MatShellSetOp, PetscMetaData) from devito.petsc.iet.utils import (petsc_call, petsc_struct, zero_vector, dereference_funcs, residual_bundle) from devito.petsc.utils import solver_mapper -from devito.petsc.types import (DM, Mat, CallbackVec, Vec, KSP, PC, SNES, - PetscInt, StartPtr, PointerIS, PointerDM, VecScatter, - DMCast, JacobianStruct, - SubMatrixStruct, CallbackDM) +from devito.petsc.types import (PETScArray, PetscBundle, DM, Mat, CallbackVec, Vec, + KSP, PC, SNES, PetscInt, StartPtr, PointerIS, PointerDM, + VecScatter, DMCast, JacobianStruct, SubMatrixStruct, + CallbackDM) class CBBuilder: @@ -1068,6 +1067,10 @@ def _build(self): """ sreg = self.sregistry targets = self.fielddata.targets + + snes_name = sreg.make_name(prefix='snes') + options_prefix = self.injectsolve.expr.rhs.options_prefix + base_dict = { 'Jac': Mat(sreg.make_name(prefix='J')), 'xglobal': Vec(sreg.make_name(prefix='xglobal')), @@ -1076,10 +1079,12 @@ def _build(self): 'blocal': CallbackVec(sreg.make_name(prefix='blocal')), 'ksp': KSP(sreg.make_name(prefix='ksp')), 'pc': PC(sreg.make_name(prefix='pc')), - 'snes': SNES(sreg.make_name(prefix='snes')), + 'snes': SNES(snes_name), 'localsize': PetscInt(sreg.make_name(prefix='localsize')), 'dmda': DM(sreg.make_name(prefix='da'), dofs=len(targets)), 'callbackdm': CallbackDM(sreg.make_name(prefix='dm')), + 'snesprefix': String((options_prefix or '') + '_'), + 'options_prefix': options_prefix, } base_dict['comm'] = self.comm self._target_dependent(base_dict) @@ -1239,6 +1244,10 @@ def _setup(self): snes_create = petsc_call('SNESCreate', [sobjs['comm'], Byref(sobjs['snes'])]) + snes_options_prefix = petsc_call( + 'SNESSetOptionsPrefix', [sobjs['snes'], sobjs['snesprefix']] + ) if sobjs['options_prefix'] else None + snes_set_dm = petsc_call('SNESSetDM', [sobjs['snes'], dmda]) create_matrix = petsc_call('DMCreateMatrix', [dmda, Byref(sobjs['Jac'])]) @@ -1327,6 +1336,7 @@ def _setup(self): base_setup = dmda_calls + ( snes_create, + snes_options_prefix, snes_set_dm, create_matrix, snes_set_jac, @@ -1412,11 +1422,14 @@ def _setup(self): sobjs = self.solver_objs dmda = sobjs['dmda'] - solver_params = self.injectsolve.expr.rhs.solver_parameters snes_create = petsc_call('SNESCreate', [sobjs['comm'], Byref(sobjs['snes'])]) + snes_options_prefix = petsc_call( + 'SNESSetOptionsPrefix', [sobjs['snes'], sobjs['snesprefix']] + ) if sobjs['options_prefix'] else None + snes_set_dm = petsc_call('SNESSetDM', [sobjs['snes'], dmda]) create_matrix = petsc_call('DMCreateMatrix', [dmda, Byref(sobjs['Jac'])]) @@ -1530,6 +1543,7 @@ def _setup(self): coupled_setup = dmda_calls + ( snes_create, + snes_options_prefix, snes_set_dm, create_matrix, snes_set_jac, @@ -1618,7 +1632,7 @@ def _execute_solve(self): vec_reset_array, BlankLine, ) - return List(body=run_solver_calls) + return run_solver_calls @cached_property def spatial_body(self): @@ -1701,15 +1715,7 @@ def _execute_solve(self): snes_solve = (petsc_call('SNESSolve', [sobjs['snes'], objs['Null'], xglob]),) - return List( - body=( - (struct_assignment,) - + pre_solve - + snes_solve - + post_solve - + (BlankLine,) - ) - ) + return (struct_assignment,) + pre_solve + snes_solve + post_solve + (BlankLine,) class NonTimeDependent: diff --git a/devito/petsc/logging.py b/devito/petsc/logging.py new file mode 100644 index 0000000000..f552b69969 --- /dev/null +++ b/devito/petsc/logging.py @@ -0,0 +1,180 @@ +from collections import namedtuple, OrderedDict +from dataclasses import dataclass + +from devito.types import CompositeObject + +from devito.petsc.types import PetscInt +from devito.petsc.utils import petsc_type_mappings + + +class PetscEntry: + def __init__(self, **kwargs): + self.kwargs = kwargs + for k, v in self.kwargs.items(): + setattr(self, k, v) + self._properties = {k.lower(): v for k, v in kwargs.items()} + + def __getitem__(self, key): + return self._properties[key.lower()] + + def __repr__(self): + return f"PetscEntry({', '.join(f'{k}={v}' for k, v in self.kwargs.items())})" + + +class PetscSummary(dict): + """ + A summary of PETSc statistics collected for all solver runs + associated with a single operator during execution. + """ + PetscKey = namedtuple('PetscKey', 'name options_prefix') + + def __init__(self, params, *args, **kwargs): + super().__init__(*args, **kwargs) + + self.petscinfos = [i for i in params if isinstance(i, PetscInfo)] + + # Gather all unique PETSc function names across all PetscInfo objects + self._functions = list(dict.fromkeys( + petsc_return_variable_dict[key].name + for struct in self.petscinfos + for key in struct.function_list + )) + self._property_name_map = {} + # Dynamically create a property on this class for each PETSc function + self._add_properties() + + # Initialize the summary by adding PETSc information from each PetscInfo + # object (each corresponding to an individual PETScSolve) + for i in self.petscinfos: + self.add_info(i) + + def add_info(self, petscinfo): + """ + For a given PetscInfo object, create a key + and entry and add it to the PetscSummary. + """ + key = self.PetscKey(*petscinfo.summary_key) + entry = self.petsc_entry(petscinfo) + self[key] = entry + + def petsc_entry(self, petscinfo): + """ + Create a named tuple entry for the given PetscInfo object, + containing the values for each PETSc function call. + """ + funcs = self._functions + values = tuple(getattr(petscinfo, c) for c in funcs) + return PetscEntry(**{k: v for k, v in zip(funcs, values)}) + + def _add_properties(self): + """ + For each function name in `self._functions` (e.g., 'KSPGetIterationNumber'), + dynamically add a property to the class with the same name. + + Each property returns an OrderedDict that maps each PetscKey to the + result of looking up that function on the corresponding PetscEntry, + if the function exists on that entry. + """ + def make_property(function): + def getter(self): + return OrderedDict( + (k, getattr(v, function)) + for k, v in self.items() + # Only include entries that have the function + if hasattr(v, function) + ) + return property(getter) + + for f in self._functions: + # Inject the new property onto the class itself + setattr(self.__class__, f, make_property(f)) + self._property_name_map[f.lower()] = f + + def get_entry(self, name, options_prefix=None): + """ + Retrieve a single PetscEntry for a given name + and options_prefix. + """ + key = self.PetscKey(name, options_prefix) + if key not in self: + raise ValueError( + f"No PETSc information for:" + f" name='{name}'" + f" options_prefix='{options_prefix}'" + ) + return self[key] + + def __getitem__(self, key): + if isinstance(key, str): + # Allow case insensitive key access + original = self._property_name_map.get(key.lower()) + if original: + return getattr(self, original) + raise KeyError(f"No PETSc function named '{key}'") + elif isinstance(key, tuple) and len(key) == 2: + # Allow tuple keys (name, options_prefix) + key = self.PetscKey(*key) + return super().__getitem__(key) + + +class PetscInfo(CompositeObject): + + __rargs__ = ('name', 'pname', 'logobjs', 'sobjs', 'section_mapper', + 'injectsolve', 'function_list') + + def __init__(self, name, pname, logobjs, sobjs, section_mapper, + injectsolve, function_list): + + self.logobjs = logobjs + self.sobjs = sobjs + self.section_mapper = section_mapper + self.injectsolve = injectsolve + self.function_list = function_list + + mapper = {v: k for k, v in petsc_type_mappings.items()} + fields = [(str(i), mapper[str(i._C_ctype)]) for i in logobjs.values()] + super().__init__(name, pname, fields) + + @property + def section(self): + section = self.section_mapper.items() + return next((k[0].name for k, v in section if self.injectsolve in v), None) + + @property + def summary_key(self): + return (self.section, self.sobjs['options_prefix']) + + def __getattr__(self, attr): + if attr in self.logobjs.keys(): + return getattr(self.value._obj, self.logobjs[attr].name) + raise AttributeError(f"{attr} not found in PETSc return variables") + + +@dataclass +class PetscReturnVariable: + name: str + variable_type: None + input_params: list + output_param: str + + +# NOTE: +# In the future, this dictionary should be generated automatically from PETSc internals. +# For now, it serves as the reference for PETSc function metadata. +# If any of the PETSc function signatures change (e.g., names, input/output parameters), +# this dictionary must be updated accordingly. + +petsc_return_variable_dict = { + 'kspgetiterationnumber': PetscReturnVariable( + name='KSPGetIterationNumber', + variable_type=PetscInt, + input_params=['ksp'], + output_param='kspiter' + ), + 'snesgetiterationnumber': PetscReturnVariable( + name='SNESGetIterationNumber', + variable_type=PetscInt, + input_params=['snes'], + output_param='snesiter', + ) +} diff --git a/devito/petsc/solve.py b/devito/petsc/solve.py index 1f4423707e..55633d40fd 100644 --- a/devito/petsc/solve.py +++ b/devito/petsc/solve.py @@ -12,7 +12,7 @@ __all__ = ['PETScSolve'] -def PETScSolve(target_exprs, target=None, solver_parameters=None): +def PETScSolve(target_exprs, target=None, solver_parameters=None, options_prefix=None): """ Returns a symbolic expression representing a linear PETSc solver, enriched with all the necessary metadata for execution within an `Operator`. @@ -51,16 +51,21 @@ def PETScSolve(target_exprs, target=None, solver_parameters=None): This can be passed directly to a Devito Operator. """ if target is not None: - return InjectSolve(solver_parameters, {target: target_exprs}).build_expr() + return InjectSolve( + solver_parameters, {target: target_exprs}, options_prefix + ).build_expr() else: - return InjectMixedSolve(solver_parameters, target_exprs).build_expr() + return InjectMixedSolve( + solver_parameters, target_exprs, options_prefix + ).build_expr() class InjectSolve: - def __init__(self, solver_parameters=None, target_exprs=None): + def __init__(self, solver_parameters=None, target_exprs=None, options_prefix=None): self.solver_params = solver_parameters self.time_mapper = None self.target_exprs = target_exprs + self.options_prefix = options_prefix def build_expr(self): target, funcs, fielddata = self.linear_solve_args() @@ -71,7 +76,8 @@ def build_expr(self): self.solver_params, fielddata=fielddata, time_mapper=self.time_mapper, - localinfo=localinfo + localinfo=localinfo, + options_prefix=self.options_prefix ) return PetscEq(target, linear_solve) diff --git a/devito/petsc/types/object.py b/devito/petsc/types/object.py index 32892f2aa4..1484e1be81 100644 --- a/devito/petsc/types/object.py +++ b/devito/petsc/types/object.py @@ -1,9 +1,11 @@ from ctypes import POINTER, c_char + from devito.tools import CustomDtype, dtype_to_ctype, as_tuple, CustomIntType from devito.types import (LocalObject, LocalCompositeObject, ModuloDimension, TimeDimension, ArrayObject, CustomDimension) from devito.symbolics import Byref, cast from devito.types.basic import DataSymbol + from devito.petsc.iet.utils import petsc_call diff --git a/devito/petsc/types/types.py b/devito/petsc/types/types.py index 4f235bbbde..baab036f17 100644 --- a/devito/petsc/types/types.py +++ b/devito/petsc/types/types.py @@ -60,7 +60,7 @@ class LinearSolveExpr(MetaData): __rargs__ = ('expr',) __rkwargs__ = ('solver_parameters', 'fielddata', 'time_mapper', - 'localinfo') + 'localinfo', 'options_prefix') defaults = { 'ksp_type': 'gmres', @@ -72,7 +72,8 @@ class LinearSolveExpr(MetaData): } def __new__(cls, expr, solver_parameters=None, - fielddata=None, time_mapper=None, localinfo=None, **kwargs): + fielddata=None, time_mapper=None, localinfo=None, + options_prefix=None, **kwargs): if solver_parameters is None: solver_parameters = cls.defaults @@ -88,6 +89,7 @@ def __new__(cls, expr, solver_parameters=None, obj._fielddata = fielddata if fielddata else FieldData() obj._time_mapper = time_mapper obj._localinfo = localinfo + obj._options_prefix = options_prefix return obj def __repr__(self): @@ -125,6 +127,10 @@ def time_mapper(self): def localinfo(self): return self._localinfo + @property + def options_prefix(self): + return self._options_prefix + @property def grid(self): return self.fielddata.grid diff --git a/devito/symbolics/extended_sympy.py b/devito/symbolics/extended_sympy.py index a75e1091d3..4016a88466 100644 --- a/devito/symbolics/extended_sympy.py +++ b/devito/symbolics/extended_sympy.py @@ -581,7 +581,11 @@ class Keyword(ReservedWord): class String(ReservedWord): - pass + + def __str__(self): + return f'"{self.value}"' + + __repr__ = __str__ class Macro(ReservedWord): diff --git a/tests/test_petsc.py b/tests/test_petsc.py index 3f64a79c82..44668092ad 100644 --- a/tests/test_petsc.py +++ b/tests/test_petsc.py @@ -2,10 +2,12 @@ import numpy as np import os +from collections import OrderedDict from conftest import skipif from devito import (Grid, Function, TimeFunction, Eq, Operator, configuration, norm, switchconfig, SubDomain) +from devito.operator.profiling import PerformanceSummary from devito.ir.iet import (Call, ElementalFunction, FindNodes, retrieve_iteration_tree) from devito.types import Constant, LocalCompositeObject @@ -17,11 +19,11 @@ from devito.petsc.solve import PETScSolve, EssentialBC from devito.petsc.iet.nodes import Expression from devito.petsc.initialize import PetscInitialize +from devito.petsc.logging import PetscSummary -@skipif('petsc') @pytest.fixture(scope='session', autouse=True) -def test_petsc_initialization(): +def petsc_initialization(): # TODO: Temporary workaround until PETSc is automatically # initialized configuration['compiler'] = 'custom' @@ -1377,3 +1379,105 @@ def define(self, dimensions): # Expected norm computed "manually" from sequential run # What rtol and atol should be used? assert np.isclose(norm(u), unorm, rtol=1e-13, atol=1e-13) + + +class TestLogging: + + @skipif('petsc') + @pytest.mark.parametrize('log_level', ['PERF', 'DEBUG']) + def test_logging(self, log_level): + """Verify PetscSummary output when the log level is 'PERF' or 'DEBUG.""" + grid = Grid(shape=(11, 11), dtype=np.float64) + + functions = [Function(name=n, grid=grid, space_order=2) + for n in ['e', 'f']] + e, f = functions + f.data[:] = 5.0 + eq = Eq(e.laplace, f) + + petsc = PETScSolve(eq, target=e, options_prefix='poisson') + + with switchconfig(language='petsc', log_level=log_level): + op = Operator(petsc) + summary = op.apply() + + # One PerformanceSummary + assert len(summary) == 1 + + # Access the PetscSummary + petsc_summary = summary.petsc + + assert isinstance(summary, PerformanceSummary) + assert isinstance(petsc_summary, PetscSummary) + + # One section with a single solver + assert len(petsc_summary) == 1 + + entry0 = petsc_summary.get_entry('section0', 'poisson') + entry1 = petsc_summary[('section0', 'poisson')] + assert entry0 == entry1 + assert str(entry0) == \ + 'PetscEntry(KSPGetIterationNumber=16, SNESGetIterationNumber=1)' + + assert entry0.SNESGetIterationNumber == 1 + + snesiters0 = petsc_summary.SNESGetIterationNumber + snesiters1 = petsc_summary['SNESGetIterationNumber'] + # Check case insensitive key access + snesiters2 = petsc_summary['snesgetiterationnumber'] + snesiters3 = petsc_summary['SNESgetiterationNumber'] + + assert snesiters0 == snesiters1 == snesiters2 == snesiters3 + + assert isinstance(snesiters0, OrderedDict) + assert len(snesiters0) == 1 + key, value = next(iter(snesiters0.items())) + assert str(key) == "PetscKey(name='section0', options_prefix='poisson')" + assert value == 1 + + @skipif('petsc') + def test_logging_multiple_solves(self): + grid = Grid(shape=(11, 11), dtype=np.float64) + + functions = [Function(name=n, grid=grid, space_order=2) + for n in ['e', 'f', 'g', 'h']] + e, f, g, h = functions + + e.data[:] = 5.0 + f.data[:] = 6.0 + + eq1 = Eq(g.laplace, e) + eq2 = Eq(h, f + 5.0) + + solver1 = PETScSolve(eq1, target=g, options_prefix='poisson1') + solver2 = PETScSolve(eq2, target=h, options_prefix='poisson2') + + with switchconfig(language='petsc', log_level='DEBUG'): + op = Operator([solver1, solver2]) + summary = op.apply() + + petsc_summary = summary.petsc + # One PetscKey, PetscEntry for each solver + assert len(petsc_summary) == 2 + + entry1 = petsc_summary.get_entry('section0', 'poisson1') + entry2 = petsc_summary.get_entry('section1', 'poisson2') + + assert str(entry1) == \ + 'PetscEntry(KSPGetIterationNumber=16, SNESGetIterationNumber=1)' + assert str(entry2) == \ + 'PetscEntry(KSPGetIterationNumber=1, SNESGetIterationNumber=1)' + + assert len(petsc_summary.KSPGetIterationNumber) == 2 + assert len(petsc_summary.SNESGetIterationNumber) == 2 + + assert entry1.KSPGetIterationNumber == 16 + assert entry1.SNESGetIterationNumber == 1 + assert entry2.KSPGetIterationNumber == 1 + assert entry2.SNESGetIterationNumber == 1 + + # Test key access to PetscEntry + assert entry1['KSPGetIterationNumber'] == 16 + assert entry1['SNESGetIterationNumber'] == 1 + # Case insensitive key access + assert entry1['kspgetiterationnumber'] == 16