compiler: Enhance logging of arguments and apply specialization test

Author: EdCaunt

devito/operator/operator.py

@@ -989,34 +989,45 @@ def apply(self, **kwargs):
         # Get items expected to be specialized
         specialize = as_tuple(kwargs.pop('specialize', []))
 
-        if not specialize:
-            # Compile the operator before building the arguments list
-            # to avoid out of memory with greedy compilers
-            cfunction = self.cfunction
-
-        # Build the arguments list to invoke the kernel function
-        with self._profiler.timer_on('arguments-preprocess'):
-            args = self.arguments(**kwargs)
-        with switch_log_level(comm=args.comm):
-            self._emit_args_profiling('arguments-preprocess')
-
         # In the case of specialization, arguments must be processed before
         # the operator can be compiled
         if specialize:
             # FIXME: Cannot cope with things like sizes/strides yet since it only
             # looks at the parameters
-            specialized_args = {p: sympify(args.pop(p.name))
-                                for p in self.parameters if p.name in specialize}
 
-            op = Specializer(specialized_args).visit(self)
+            # Build the arguments list for specialization
+            with self._profiler.timer_on('specialized-arguments-preprocess'):
+                args = self.arguments(**kwargs)
+            with switch_log_level(comm=args.comm):
+                self._emit_args_profiling('specialized-arguments-preprocess')
 
-            specialized_kwargs = {k: v for k, v in kwargs.items()
-                                  if k not in specialize}
+            # Uses parameters here since Specializer needs {symbol: sympy value} mapper
+            specialized_values = {p: sympify(args[p.name])
+                                  for p in self.parameters if p.name in specialize}
+
+            op = Specializer(specialized_values).visit(self)
 
             # TODO: Does this cause problems for profilers?
             # FIXME: Need some way to inspect this Operator for testing
             # FIXME: Perhaps this should use some separate method
-            return op.apply(**specialized_kwargs)
+            unspecialized_kwargs = {k: v for k, v in kwargs.items()
+                                    if k not in specialize}
+
+            return op.apply(**unspecialized_kwargs)
+
+        # Compile the operator before building the arguments list
+        # to avoid out of memory with greedy compilers
+        cfunction = self.cfunction
+
+        # Build the arguments list to invoke the kernel function
+        with self._profiler.timer_on('arguments-preprocess'):
+            args = self.arguments(**kwargs)
+        with switch_log_level(comm=args.comm):
+            self._emit_args_profiling('arguments-preprocess')
+
+        args_string = ", ".join([f"{p.name}={args[p.name]}"
+                                 for p in self.parameters if p.is_Symbol])
+        debug(f"Invoking `{self.name}` with scalar arguments: {args_string}")
 
         # Invoke kernel function with args
         arg_values = [args[p.name] for p in self.parameters]

devito/operator/profiling.py

@@ -425,8 +425,8 @@ def add(self, name, rank, time,
         if not ops or any(not np.isfinite(i) for i in [ops, points, traffic]):
             self[k] = PerfEntry(time, 0.0, 0.0, 0.0, 0, [])
         else:
-            gflops = float(ops)/10**9
-            gpoints = float(points)/10**9
+            gflops = float(ops)/10e9
+            gpoints = float(points)/10e9
             gflopss = gflops/time
             gpointss = gpoints/time
             oi = float(ops/traffic)

tests/test_specialization.py

@@ -1,10 +1,12 @@
+import logging
+
 import sympy
 import pytest
 
 import numpy as np
 
 from devito import (Grid, Function, TimeFunction, Eq, Operator, SubDomain, Dimension,
-                    ConditionalDimension)
+                    ConditionalDimension, switchconfig)
 from devito.ir.iet.visitors import Specializer
 
 # Test that specializer replaces symbols as expected
@@ -202,24 +204,36 @@ def test_apply_basic(self):
 
         assert np.all(check == f.data)
 
+    # TODO: Need a test to check that block sizes can be specialized
+    # TODO: Need to test that tile sizes can be specialized
+
 
 class TestApply:
     """Tests for specialization of operators at apply time"""
 
-    def test_basic(self):
+    @pytest.mark.parametrize('override', [False, True])
+    def test_basic(self, caplog, override):
         grid = Grid(shape=(11, 11))
         f = Function(name='f', grid=grid, dtype=np.int32)
         op = Operator(Eq(f, f+1))
 
-        # TODO: Need to verify that specialized operator is actually the one
-        # being run. How can I achieve this?
-        op.apply(specialize=('x_m', 'x_M'))
+        specialize = ('x_m', 'x_M')
+
+        kwargs = {}
+        if override:
+            kwargs['x_m'] = 3
+
+        with switchconfig(log_level='DEBUG'), caplog.at_level(logging.DEBUG):
+            op.apply(specialize=specialize, **kwargs)
+
+            # Ensure that the specialized operator was run
+            assert all(s not in caplog.text for s in specialize)
+            assert "specialized arguments preprocess" in caplog.text
 
         check = np.array(f.data[:])
         f.data[:] = 0
-        op.apply()
+        op.apply(**kwargs)
 
         assert np.all(check == f.data)
 
-# Need to test combining specialization and overrides (a range of them)
 # Need to test specialization with MPI (both at)