Introduce Timer context manager (#995)

Originally tried to make it do logging, too, but I couldn't figure
out how to get it to log in the correct scope.
Separating timing from logging substantially simplifies the logic
at a modest cost in LoC at point of use.

fipy/solvers/petsc/linearLUSolver.py

@@ -6,6 +6,7 @@
 from petsc4py import PETSc
 
 from fipy.solvers.petsc.petscSolver import PETScSolver
+from fipy.tools.timer import Timer
 
 __all__ = ["LinearLUSolver"]
 
@@ -41,20 +42,25 @@ def _solve_(self, L, x, b):
         ksp.setOperators(L)
         ksp.setFromOptions()
 
-        for iteration in range(self.iterations):
-            errorVector = L * x - b
-            tol = errorVector.norm()
+        self._log.debug("BEGIN solve")
 
-            if iteration == 0:
-                tol0 = tol
+        with Timer() as t:
+            for iteration in range(self.iterations):
+                errorVector = L * x - b
+                tol = errorVector.norm()
 
-            if tol <= self.tolerance * tol0:
-                break
+                if iteration == 0:
+                    tol0 = tol
 
-            xError = x.copy()
+                if tol <= self.tolerance * tol0:
+                    break
 
-            ksp.solve(errorVector, xError)
-            x -= xError
+                xError = x.copy()
+
+                ksp.solve(errorVector, xError)
+                x -= xError
+
+        self._log.debug("END solve - {} ns".format(t.elapsed))
 
         self._log.debug('solver: %s', ksp.type)
         self._log.debug('precon: %s', ksp.getPC().type)

fipy/solvers/petsc/petscKrylovSolver.py

@@ -3,6 +3,7 @@
 from petsc4py import PETSc
 
 from fipy.solvers.petsc.petscSolver import PETScSolver
+from fipy.tools.timer import Timer
 
 __all__ = ["PETScKrylovSolver"]
 
@@ -53,13 +54,26 @@ def _solve_(self, L, x, b):
         ksp = PETSc.KSP()
         ksp.create(L.comm)
         ksp.setType(self.solver)
-        if self.preconditioner is not None:
-            ksp.getPC().setType(self.preconditioner)
+
+        self._log.debug("BEGIN precondition")
+
+        with Timer() as t:
+            if self.preconditioner is not None:
+                ksp.getPC().setType(self.preconditioner)
+
+        self._log.debug("END precondition - {} ns".format(t.elapsed))
+
         ksp.setTolerances(rtol=self.tolerance, max_it=self.iterations)
         L.assemble()
         ksp.setOperators(L)
         ksp.setFromOptions()
-        ksp.solve(b, x)
+
+        self._log.debug("BEGIN solve")
+
+        with Timer() as t:
+            ksp.solve(b, x)
+
+        self._log.debug("END solve - {} ns".format(t.elapsed))
 
         self._log.debug('solver: %s', ksp.type)
         self._log.debug('precon: %s', ksp.getPC().type)

fipy/solvers/pyamgx/pyAMGXSolver.py

@@ -7,6 +7,7 @@
 from fipy.solvers.solver import Solver
 from fipy.matrices.scipyMatrix import _ScipyMeshMatrix
 from fipy.tools import numerix
+from fipy.tools.timer import Timer
 
 __all__ = ["PyAMGXSolver"]
 from future.utils import text_to_native_str
@@ -71,14 +72,30 @@ def _storeMatrix(self, var, matrix, RHSvector):
 
     def _solve_(self, L, x, b):
         # transfer data from CPU to GPU
-        self.x_gpu.upload(x)
-        self.b_gpu.upload(b)
+        self._log.debug("BEGIN cpu2gpu")
+
+        with Timer() as t:
+            self.x_gpu.upload(x)
+            self.b_gpu.upload(b)
+
+        self._log.debug("END cpu2gpu - {elapsed} ns".format(elapsed=t.elapsed))
 
         # solve system on GPU
-        self.solver.solve(self.b_gpu, self.x_gpu)
+        self._log.debug("BEGIN solve")
+
+        with Timer() as t:
+            self.solver.solve(self.b_gpu, self.x_gpu)
+
+        self._log.debug("END solve - {} ns".format(t.elapsed))
 
         # download values from GPU to CPU
-        self.x_gpu.download(x)
+        self._log.debug("BEGIN gpu2cpu")
+
+        with Timer() as t:
+            self.x_gpu.download(x)
+
+        self._log.debug("END gpu2cpu - {} ns".format(t.elapsed))
+
         return x
 
     def _solve(self):

fipy/solvers/pysparse/linearLUSolver.py

@@ -8,6 +8,7 @@
 
 from fipy.solvers.pysparse.pysparseSolver import PysparseSolver
 from fipy.tools import numerix
+from fipy.tools.timer import Timer
 
 __all__ = ["LinearLUSolver"]
 from future.utils import text_to_native_str
@@ -54,19 +55,24 @@ def _solve_(self, L, x, b):
         L = L * (1 / maxdiag)
         b = b * (1 / maxdiag)
 
-        LU = superlu.factorize(L.matrix.to_csr())
+        self._log.debug("BEGIN solve")
 
-        error0 = numerix.sqrt(numerix.sum((L * x - b)**2))
+        with Timer() as t:
+            LU = superlu.factorize(L.matrix.to_csr())
 
-        for iteration in range(self.iterations):
-            errorVector = L * x - b
+            error0 = numerix.sqrt(numerix.sum((L * x - b)**2))
 
-            if numerix.sqrt(numerix.sum(errorVector**2))  <= self.tolerance * error0:
-                break
+            for iteration in range(self.iterations):
+                errorVector = L * x - b
 
-            xError = numerix.zeros(len(b), 'd')
-            LU.solve(errorVector, xError)
-            x[:] = x - xError
+                if numerix.sqrt(numerix.sum(errorVector**2))  <= self.tolerance * error0:
+                    break
+
+                xError = numerix.zeros(len(b), 'd')
+                LU.solve(errorVector, xError)
+                x[:] = x - xError
+
+        self._log.debug("END solve - {} ns".format(t.elapsed))
 
         self._log.debug('iterations: %d / %d', iteration+1, self.iterations)
         self._log.debug('residual: %s', numerix.sqrt(numerix.sum(errorVector**2)))

fipy/solvers/pysparse/pysparseSolver.py

@@ -2,6 +2,7 @@
 __docformat__ = 'restructuredtext'
 
 from fipy.solvers.pysparseMatrixSolver import _PysparseMatrixSolver
+from fipy.tools.timer import Timer
 
 __all__ = ["PysparseSolver"]
 from future.utils import text_to_native_str
@@ -37,13 +38,23 @@ def _solve_(self, L, x, b):
 
         A = L.matrix
 
-        if self.preconditioner is None:
-            P = None
-        else:
-            P, A = self.preconditioner._applyToMatrix(A)
+        self._log.debug("BEGIN precondition")
 
-        info, iter, relres = self.solveFnc(A, b, x, self.tolerance,
-                                           self.iterations, P)
+        with Timer() as t:
+            if self.preconditioner is None:
+                P = None
+            else:
+                P, A = self.preconditioner._applyToMatrix(A)
+
+        self._log.debug("END precondition - {} ns".format(t.elapsed))
+
+        self._log.debug("BEGIN solve")
+
+        with Timer() as t:
+            info, iter, relres = self.solveFnc(A, b, x, self.tolerance,
+                                               self.iterations, P)
+
+        self._log.debug("END solve - {} ns".format(t.elapsed))
 
         self._raiseWarning(info, iter, relres)
 

fipy/solvers/scipy/linearLUSolver.py

@@ -7,6 +7,7 @@
 
 from fipy.solvers.scipy.scipySolver import _ScipySolver
 from fipy.tools import numerix
+from fipy.tools.timer import Timer
 
 __all__ = ["LinearLUSolver"]
 from future.utils import text_to_native_str
@@ -23,24 +24,34 @@ def _solve_(self, L, x, b):
         diag = L.takeDiagonal()
         maxdiag = max(numerix.absolute(diag))
 
-        L = L * (1 / maxdiag)
-        b = b * (1 / maxdiag)
+        self._log.debug("BEGIN precondition")
 
-        LU = splu(L.matrix.asformat("csc"), diag_pivot_thresh=1.,
-                                            relax=1,
-                                            panel_size=10,
-                                            permc_spec=3)
+        with Timer() as t:
+            L = L * (1 / maxdiag)
+            b = b * (1 / maxdiag)
 
-        error0 = numerix.sqrt(numerix.sum((L * x - b)**2))
+        self._log.debug("END precondition - {} ns".format(t.elapsed))
 
-        for iteration in range(min(self.iterations, 10)):
-            errorVector = L * x - b
+        self._log.debug("BEGIN solve")
 
-            if numerix.sqrt(numerix.sum(errorVector**2))  <= self.tolerance * error0:
-                break
+        with Timer() as t:
+            LU = splu(L.matrix.asformat("csc"), diag_pivot_thresh=1.,
+                                                relax=1,
+                                                panel_size=10,
+                                                permc_spec=3)
 
-            xError = LU.solve(errorVector)
-            x[:] = x - xError
+            error0 = numerix.sqrt(numerix.sum((L * x - b)**2))
+
+            for iteration in range(min(self.iterations, 10)):
+                errorVector = L * x - b
+
+                if numerix.sqrt(numerix.sum(errorVector**2))  <= self.tolerance * error0:
+                    break
+
+                xError = LU.solve(errorVector)
+                x[:] = x - xError
+
+        self._log.debug("END solve - {} ns".format(t.elapsed))
 
         self._log.debug('iterations: %d / %d', iteration+1, self.iterations)
         self._log.debug('residual: %s', numerix.sqrt(numerix.sum(errorVector**2)))

fipy/solvers/scipy/scipyKrylovSolver.py

@@ -4,6 +4,7 @@
 __all__ = []
 
 from fipy.solvers.scipy.scipySolver import _ScipySolver
+from fipy.tools.timer import Timer
 
 class _ScipyKrylovSolver(_ScipySolver):
     """
@@ -14,16 +15,27 @@ class _ScipyKrylovSolver(_ScipySolver):
 
     def _solve_(self, L, x, b):
         A = L.matrix
-        if self.preconditioner is None:
-            M = None
-        else:
-            M = self.preconditioner._applyToMatrix(A)
-
-        x, info = self.solveFnc(A, b, x,
-                                tol=self.tolerance,
-                                maxiter=self.iterations,
-                                M=M,
-                                atol='legacy')
+
+        self._log.debug("BEGIN precondition")
+
+        with Timer() as t:
+            if self.preconditioner is None:
+                M = None
+            else:
+                M = self.preconditioner._applyToMatrix(A)
+
+        self._log.debug("END precondition - {} ns".format(t.elapsed))
+
+        self._log.debug("BEGIN solve")
+
+        with Timer() as t:
+            x, info = self.solveFnc(A, b, x,
+                                    tol=self.tolerance,
+                                    maxiter=self.iterations,
+                                    M=M,
+                                    atol='legacy')
+
+        self._log.debug("END solve - {} ns".format(t.elapsed))
 
         if info < 0:
             self._log.debug('failure: %s', self._warningList[info].__class__.__name__)

fipy/solvers/trilinos/linearLUSolver.py

@@ -7,6 +7,7 @@
 from PyTrilinos import Amesos
 
 from fipy.solvers.trilinos.trilinosSolver import TrilinosSolver
+from fipy.tools.timer import Timer
 
 __all__ = ["LinearLUSolver"]
 from future.utils import text_to_native_str
@@ -45,31 +46,36 @@ def __init__(self, tolerance=1e-10, iterations=10, precon=None, maxIterations=10
 
     def _solve_(self, L, x, b):
 
-        for iteration in range(self.iterations):
-             # errorVector = L*x - b
-             errorVector = Epetra.Vector(L.RangeMap())
-             L.Multiply(False, x, errorVector)
-             # If A is an Epetra.Vector with map M
-             # and B is an Epetra.Vector with map M
-             # and C = A - B
-             # then C is an Epetra.Vector with *no map* !!!?!?!
-             errorVector -= b
+        self._log.debug("BEGIN solve")
 
-             tol = errorVector.Norm1()
+        with Timer() as t:
+            for iteration in range(self.iterations):
+                 # errorVector = L*x - b
+                 errorVector = Epetra.Vector(L.RangeMap())
+                 L.Multiply(False, x, errorVector)
+                 # If A is an Epetra.Vector with map M
+                 # and B is an Epetra.Vector with map M
+                 # and C = A - B
+                 # then C is an Epetra.Vector with *no map* !!!?!?!
+                 errorVector -= b
 
-             if iteration == 0:
-                 tol0 = tol
+                 tol = errorVector.Norm1()
 
-             if (tol / tol0) <= self.tolerance:
-                 break
+                 if iteration == 0:
+                     tol0 = tol
 
-             xError = Epetra.Vector(L.RowMap())
+                 if (tol / tol0) <= self.tolerance:
+                     break
 
-             Problem = Epetra.LinearProblem(L, xError, errorVector)
-             Solver = self.Factory.Create(text_to_native_str("Klu"), Problem)
-             Solver.Solve()
+                 xError = Epetra.Vector(L.RowMap())
 
-             x[:] = x - xError
+                 Problem = Epetra.LinearProblem(L, xError, errorVector)
+                 Solver = self.Factory.Create(text_to_native_str("Klu"), Problem)
+                 Solver.Solve()
+
+                 x[:] = x - xError
+
+        self._log.debug("END solve - {} ns".format(t.elapsed))
 
         self._log.debug('iterations: %d / %d', iteration+1, self.iterations)
         self._log.debug('residual: %s', errorVector.Norm2())