From 78b3ee6d581165395573b30489da156f8547f9aa Mon Sep 17 00:00:00 2001
From: Andreas Kloeckner <inform@tiker.net>
Date: Fri, 20 Apr 2018 15:48:12 -0500
Subject: [PATCH 1/3] Switch to new pytools logging infrastructure

---
 boxtree/area_query.py           | 46 +++++++--------------------------
 boxtree/fmm.py                  | 25 +++---------------
 boxtree/pyfmmlib_integration.py | 13 +++++++++-
 boxtree/traversal.py            | 20 +++-----------
 boxtree/tree_build.py           | 18 +++++--------
 boxtree/tree_build_kernels.py   | 14 ++--------
 setup.py                        |  2 +-
 7 files changed, 38 insertions(+), 100 deletions(-)

diff --git a/boxtree/area_query.py b/boxtree/area_query.py
index ed08fc6..5790ce1 100644
--- a/boxtree/area_query.py
+++ b/boxtree/area_query.py
@@ -32,9 +32,7 @@ import pyopencl.cltypes  # noqa
 import pyopencl.array  # noqa
 from mako.template import Template
 from boxtree.tools import AXIS_NAMES, DeviceDataRecord
-from pytools import memoize_method
-
-from time import time
+from pytools import memoize_method, ProcessLogger
 
 import logging
 logger = logging.getLogger(__name__)
@@ -743,8 +741,7 @@ class AreaQueryBuilder(object):
             tree.coord_dtype, tree.box_id_dtype, ball_id_dtype,
             peer_lists.peer_list_starts.dtype, max_levels)
 
-        logger.debug("area query: run area query")
-        aq_start_time = time()
+        aq_plog = ProcessLogger(logger, "area query")
 
         result, evt = area_query_kernel(
                 queue, len(ball_radii),
@@ -757,13 +754,7 @@ class AreaQueryBuilder(object):
                   tuple(bc.data for bc in ball_centers)),
                 wait_for=wait_for)
 
-        aq_elapsed = time() - aq_start_time
-        if aq_elapsed > 0.1:
-            done_logger = logger.info
-        else:
-            done_logger = logger.debug
-
-        done_logger("area query: done after %g seconds", aq_elapsed)
+        aq_plog.done()
 
         return AreaQueryResult(
                 tree=tree,
@@ -832,8 +823,7 @@ class LeavesToBallsLookupBuilder(object):
         if ball_radii.dtype != tree.coord_dtype:
             raise TypeError("ball_radii dtype must match tree.coord_dtype")
 
-        logger.debug("leaves-to-balls lookup: run area query")
-        ltb_start_time = time()
+        ltb_plog = ProcessLogger("leaves-to-balls lookup: run area query")
 
         area_query, evt = self.area_query_builder(
                 queue, tree, ball_centers, ball_radii, peer_lists, wait_for)
@@ -873,13 +863,7 @@ class LeavesToBallsLookupBuilder(object):
                         nkeys, starts_dtype=tree.box_id_dtype,
                         wait_for=wait_for)
 
-        ltb_elapsed = time() - ltb_start_time
-        if ltb_elapsed > 0.1:
-            done_logger = logger.info
-        else:
-            done_logger = logger.debug
-        done_logger("leaves-to-balls lookup: built after %g seconds",
-                ltb_elapsed)
+        ltb_plog.done()
 
         return LeavesToBallsLookup(
                 tree=tree,
@@ -984,8 +968,7 @@ class SpaceInvaderQueryBuilder(object):
             tree.dimensions, tree.coord_dtype, tree.box_id_dtype,
             peer_lists.peer_list_starts.dtype, max_levels)
 
-        logger.debug("space invader query: run space invader query")
-        si_start_time = time()
+        si_plog = ProcessLogger(logger, "space invader query")
 
         outer_space_invader_dists = cl.array.zeros(queue, tree.nboxes, np.float32)
         if not wait_for:
@@ -1011,12 +994,7 @@ class SpaceInvaderQueryBuilder(object):
                     tree.coord_dtype)
             evt, = outer_space_invader_dists.events
 
-        si_elapsed = time() - si_start_time
-        if si_elapsed > 0.1:
-            done_logger = logger.info
-        else:
-            done_logger = logger.debug
-        done_logger("space invader query: done after %g seconds", si_elapsed)
+        si_plog.done()
 
         return outer_space_invader_dists, evt
 
@@ -1131,8 +1109,7 @@ class PeerListFinder(object):
         peer_list_finder_kernel = self.get_peer_list_finder_kernel(
             tree.dimensions, tree.coord_dtype, tree.box_id_dtype, max_levels)
 
-        logger.debug("peer list finder: find peer lists")
-        pl_start_time = time()
+        pl_plog = ProcessLogger("find peer lists")
 
         result, evt = peer_list_finder_kernel(
                 queue, tree.nboxes,
@@ -1141,12 +1118,7 @@ class PeerListFinder(object):
                 tree.box_child_ids.data, tree.box_flags.data,
                 wait_for=wait_for)
 
-        pl_elapsed = time() - pl_start_time
-        if pl_elapsed > 0.1:
-            done_logger = logger.info
-        else:
-            done_logger = logger.debug
-        done_logger("peer list finder: done after %g seconds", pl_elapsed)
+        pl_plog.done()
 
         return PeerListLookup(
                 tree=tree,
diff --git a/boxtree/fmm.py b/boxtree/fmm.py
index dc38cda..b2dd276 100644
--- a/boxtree/fmm.py
+++ b/boxtree/fmm.py
@@ -25,6 +25,8 @@ THE SOFTWARE.
 import logging
 logger = logging.getLogger(__name__)
 
+from pytools import ProcessLogger
+
 
 def drive_fmm(traversal, expansion_wrangler, src_weights):
     """Top-level driver routine for a fast multipole calculation.
@@ -50,15 +52,12 @@ def drive_fmm(traversal, expansion_wrangler, src_weights):
     # Interface guidelines: Attributes of the tree are assumed to be known
     # to the expansion wrangler and should not be passed.
 
-    logger.info("start fmm")
-
-    logger.debug("reorder source weights")
+    fmm_proc = ProcessLogger(logger, "qbx fmm")
 
     src_weights = wrangler.reorder_sources(src_weights)
 
     # {{{ "Step 2.1:" Construct local multipoles
 
-    logger.debug("construct local multipoles")
     mpole_exps = wrangler.form_multipoles(
             traversal.level_start_source_box_nrs,
             traversal.source_boxes,
@@ -68,7 +67,6 @@ def drive_fmm(traversal, expansion_wrangler, src_weights):
 
     # {{{ "Step 2.2:" Propagate multipoles upward
 
-    logger.debug("propagate multipoles upward")
     wrangler.coarsen_multipoles(
             traversal.level_start_source_parent_box_nrs,
             traversal.source_parent_boxes,
@@ -80,7 +78,6 @@ def drive_fmm(traversal, expansion_wrangler, src_weights):
 
     # {{{ "Stage 3:" Direct evaluation from neighbor source boxes ("list 1")
 
-    logger.debug("direct evaluation from neighbor source boxes ('list 1')")
     potentials = wrangler.eval_direct(
             traversal.target_boxes,
             traversal.neighbor_source_boxes_starts,
@@ -93,7 +90,6 @@ def drive_fmm(traversal, expansion_wrangler, src_weights):
 
     # {{{ "Stage 4:" translate separated siblings' ("list 2") mpoles to local
 
-    logger.debug("translate separated siblings' ('list 2') mpoles to local")
     local_exps = wrangler.multipole_to_local(
             traversal.level_start_target_or_target_parent_box_nrs,
             traversal.target_or_target_parent_boxes,
@@ -107,8 +103,6 @@ def drive_fmm(traversal, expansion_wrangler, src_weights):
 
     # {{{ "Stage 5:" evaluate sep. smaller mpoles ("list 3") at particles
 
-    logger.debug("evaluate sep. smaller mpoles at particles ('list 3 far')")
-
     # (the point of aiming this stage at particles is specifically to keep its
     # contribution *out* of the downward-propagating local expansions)
 
@@ -133,8 +127,6 @@ def drive_fmm(traversal, expansion_wrangler, src_weights):
 
     # {{{ "Stage 6:" form locals for separated bigger source boxes ("list 4")
 
-    logger.debug("form locals for separated bigger source boxes ('list 4 far')")
-
     local_exps = local_exps + wrangler.form_locals(
             traversal.level_start_target_or_target_parent_box_nrs,
             traversal.target_or_target_parent_boxes,
@@ -143,9 +135,6 @@ def drive_fmm(traversal, expansion_wrangler, src_weights):
             src_weights)
 
     if traversal.from_sep_close_bigger_starts is not None:
-        logger.debug("evaluate separated close bigger interactions directly "
-                "('list 4 close')")
-
         potentials = potentials + wrangler.eval_direct(
                 traversal.target_or_target_parent_boxes,
                 traversal.from_sep_close_bigger_starts,
@@ -156,8 +145,6 @@ def drive_fmm(traversal, expansion_wrangler, src_weights):
 
     # {{{ "Stage 7:" propagate local_exps downward
 
-    logger.debug("propagate local_exps downward")
-
     wrangler.refine_locals(
             traversal.level_start_target_or_target_parent_box_nrs,
             traversal.target_or_target_parent_boxes,
@@ -167,8 +154,6 @@ def drive_fmm(traversal, expansion_wrangler, src_weights):
 
     # {{{ "Stage 8:" evaluate locals
 
-    logger.debug("evaluate locals")
-
     potentials = potentials + wrangler.eval_locals(
             traversal.level_start_target_box_nrs,
             traversal.target_boxes,
@@ -176,13 +161,11 @@ def drive_fmm(traversal, expansion_wrangler, src_weights):
 
     # }}}
 
-    logger.debug("reorder potentials")
     result = wrangler.reorder_potentials(potentials)
 
-    logger.debug("finalize potentials")
     result = wrangler.finalize_potentials(result)
 
-    logger.info("fmm complete")
+    fmm_proc.done()
 
     return result
 
diff --git a/boxtree/pyfmmlib_integration.py b/boxtree/pyfmmlib_integration.py
index 693c13a..ddf7e20 100644
--- a/boxtree/pyfmmlib_integration.py
+++ b/boxtree/pyfmmlib_integration.py
@@ -26,7 +26,7 @@ THE SOFTWARE.
 
 
 import numpy as np
-from pytools import memoize_method
+from pytools import memoize_method, log_process
 
 import logging
 logger = logging.getLogger(__name__)
@@ -393,9 +393,11 @@ class FMMLibExpansionWrangler(object):
 
     # }}}
 
+    @log_process(logger)
     def reorder_sources(self, source_array):
         return source_array[..., self.tree.user_source_ids]
 
+    @log_process(logger)
     def reorder_potentials(self, potentials):
         return potentials[self.tree.sorted_target_ids]
 
@@ -417,6 +419,7 @@ class FMMLibExpansionWrangler(object):
                         "dipvec": self.dipole_vec[:, pslice],
                         }
 
+    @log_process(logger)
     def form_multipoles(self, level_start_source_box_nrs, source_boxes, src_weights):
         formmp = self.get_routine("%ddformmp" + self.dp_suffix)
 
@@ -455,6 +458,7 @@ class FMMLibExpansionWrangler(object):
 
         return mpoles
 
+    @log_process(logger)
     def coarsen_multipoles(self, level_start_source_parent_box_nrs,
             source_parent_boxes, mpoles):
         tree = self.tree
@@ -507,6 +511,7 @@ class FMMLibExpansionWrangler(object):
                         target_mpoles_view[
                                 ibox - target_level_start_ibox] += new_mp[..., 0].T
 
+    @log_process(logger)
     def eval_direct(self, target_boxes, neighbor_sources_starts,
             neighbor_sources_lists, src_weights):
         output = self.output_zeros()
@@ -547,6 +552,7 @@ class FMMLibExpansionWrangler(object):
 
         return output
 
+    @log_process(logger)
     def multipole_to_local(self,
             level_start_target_or_target_parent_box_nrs,
             target_or_target_parent_boxes,
@@ -631,6 +637,7 @@ class FMMLibExpansionWrangler(object):
 
         return local_exps
 
+    @log_process(logger)
     def eval_multipoles(self,
             target_boxes_by_source_level, sep_smaller_nonsiblings_by_level,
             mpole_exps):
@@ -672,6 +679,7 @@ class FMMLibExpansionWrangler(object):
 
         return output
 
+    @log_process(logger)
     def form_locals(self,
             level_start_target_or_target_parent_box_nrs,
             target_or_target_parent_boxes, starts, lists, src_weights):
@@ -722,6 +730,7 @@ class FMMLibExpansionWrangler(object):
 
         return local_exps
 
+    @log_process(logger)
     def refine_locals(self, level_start_target_or_target_parent_box_nrs,
             target_or_target_parent_boxes, local_exps):
 
@@ -767,6 +776,7 @@ class FMMLibExpansionWrangler(object):
 
         return local_exps
 
+    @log_process(logger)
     def eval_locals(self, level_start_target_box_nrs, target_boxes, local_exps):
         output = self.output_zeros()
         taeval = self.get_expn_eval_routine("ta")
@@ -801,6 +811,7 @@ class FMMLibExpansionWrangler(object):
 
         return output
 
+    @log_process(logger)
     def finalize_potentials(self, potential):
         if self.eqn_letter == "l" and self.dim == 2:
             scale_factor = -1/(2*np.pi)
diff --git a/boxtree/traversal.py b/boxtree/traversal.py
index 597f2cc..d7cda23 100644
--- a/boxtree/traversal.py
+++ b/boxtree/traversal.py
@@ -30,11 +30,11 @@ import pyopencl.cltypes  # noqa
 from pyopencl.elementwise import ElementwiseTemplate
 from mako.template import Template
 from boxtree.tools import AXIS_NAMES, DeviceDataRecord
-from time import time
 
 import logging
 logger = logging.getLogger(__name__)
 
+from pytools import ProcessLogger, log_process
 
 # {{{ preamble
 
@@ -1571,6 +1571,7 @@ class FMMTraversalBuilder:
     # {{{ kernel builder
 
     @memoize_method
+    @log_process(logger)
     def get_kernel_info(self, dimensions, particle_id_dtype, box_id_dtype,
             coord_dtype, box_level_dtype, max_levels,
             sources_are_targets, sources_have_extent, targets_have_extent,
@@ -1616,9 +1617,6 @@ class FMMTraversalBuilder:
 
         # }}}
 
-        logger.debug("traversal build kernels: start build")
-        kernel_build_start = time()
-
         debug = False
 
         from pyopencl.tools import dtype_to_ctype
@@ -1774,14 +1772,6 @@ class FMMTraversalBuilder:
 
         # }}}
 
-        kernel_build_elapsed = time() - kernel_build_start
-        if kernel_build_start > 0.1:
-            build_logger = logger.info
-        else:
-            build_logger = logger.debug
-        build_logger("traversal build kernels: done after %g seconds",
-                kernel_build_elapsed)
-
         return _KernelInfo(**result)
 
     # }}}
@@ -1832,8 +1822,7 @@ class FMMTraversalBuilder:
 
             logger.debug(s)
 
-        traversal_build_start_time = time()
-        logger.debug("start building traversal")
+        traversal_plog = ProcessLogger(logger, "build traversal")
 
         # {{{ source boxes, their parents, and target boxes
 
@@ -2127,8 +2116,7 @@ class FMMTraversalBuilder:
 
         evt, = wait_for
 
-        logger.info("traversal built after %g seconds",
-                time()-traversal_build_start_time)
+        traversal_plog.done()
 
         return FMMTraversalInfo(
                 tree=tree,
diff --git a/boxtree/tree_build.py b/boxtree/tree_build.py
index dbf9f52..b594045 100644
--- a/boxtree/tree_build.py
+++ b/boxtree/tree_build.py
@@ -31,6 +31,7 @@ import pyopencl as cl
 import pyopencl.array  # noqa
 from functools import partial
 from boxtree.tree import Tree
+from pytools import ProcessLogger, DebugProcessLogger
 
 import logging
 logger = logging.getLogger(__name__)
@@ -514,8 +515,8 @@ class TreeBuilder(object):
         # leaf.
         level_leaf_counts = np.array([1])
 
-        from time import time
-        tree_build_start_time = time()
+        tree_build_proc = ProcessLogger(logger, "tree build")
+
         if total_refine_weight > max_leaf_refine_weight:
             level = 1
         else:
@@ -533,7 +534,7 @@ class TreeBuilder(object):
         # single box, by how 'level' is set above. Read this as 'while True' with
         # an edge case.
 
-        logger.debug("entering level loop with %s srcntgts" % nsrcntgts)
+        level_loop_proc = DebugProcessLogger(logger, "tree build level loop")
 
         # When doing level restriction, the level loop may need to be entered
         # one more time after creating all the levels (see fixme note below
@@ -1116,12 +1117,8 @@ class TreeBuilder(object):
 
         nboxes = level_start_box_nrs[-1]
 
-        level_loop_elapsed = time()-tree_build_start_time
         npasses = level+1
-        logger.debug("tree build level loop complete: %d levels, %d boxes, "
-                "elapsed time: %g s (%g s/particle/pass)",
-                level, nboxes, level_loop_elapsed,
-                level_loop_elapsed/(npasses*nsrcntgts))
+        level_loop_proc.done("%d levels, %d boxes", level, nboxes)
         del npasses
 
         # }}}
@@ -1570,10 +1567,7 @@ class TreeBuilder(object):
         if targets_have_extent:
             extra_tree_attrs.update(target_radii=target_radii)
 
-        tree_build_elapsed = time() - tree_build_start_time
-        logger.info("tree build complete: %d levels, %d boxes, "
-                "elapsed time: %g s",
-                nlevels, len(box_parent_ids), tree_build_elapsed)
+        tree_build_proc.done("%d levels, %d boxes", nlevels, len(box_parent_ids))
 
         return Tree(
                 # If you change this, also change the documentation
diff --git a/boxtree/tree_build_kernels.py b/boxtree/tree_build_kernels.py
index f86b0ba..45c78f8 100644
--- a/boxtree/tree_build_kernels.py
+++ b/boxtree/tree_build_kernels.py
@@ -30,7 +30,7 @@ import pyopencl as cl
 from pyopencl.elementwise import ElementwiseTemplate
 from pyopencl.scan import ScanTemplate
 from mako.template import Template
-from pytools import Record, memoize
+from pytools import Record, memoize, log_process
 from boxtree.tools import get_type_moniker
 from time import time
 
@@ -1282,6 +1282,7 @@ BOX_INFO_KERNEL_TPL = ElementwiseTemplate(
 # {{{ kernel creation top-level
 
 
+@log_process(logger)
 def get_tree_build_kernel_info(context, dimensions, coord_dtype,
         particle_id_dtype, box_id_dtype,
         sources_are_targets, srcntgts_extent_norm,
@@ -1293,9 +1294,6 @@ def get_tree_build_kernel_info(context, dimensions, coord_dtype,
     level_restrict = (kind == "adaptive-level-restricted")
     adaptive = not (kind == "non-adaptive")
 
-    logger.debug("start building tree build kernels")
-    kernel_build_start_time = time()
-
     # {{{ preparation
 
     if np.iinfo(box_id_dtype).min == 0:
@@ -1713,14 +1711,6 @@ def get_tree_build_kernel_info(context, dimensions, coord_dtype,
 
     # }}}
 
-    kernel_build_elapsed = time() - kernel_build_start_time
-    if kernel_build_elapsed > 0.1:
-        build_logger = logger.info
-    else:
-        build_logger = logger.debug
-
-    build_logger("tree build kernels built after %g seconds", kernel_build_elapsed)
-
     return _KernelInfo(
             particle_id_dtype=particle_id_dtype,
             box_id_dtype=box_id_dtype,
diff --git a/setup.py b/setup.py
index 7f3f3fa..32cca6a 100644
--- a/setup.py
+++ b/setup.py
@@ -41,7 +41,7 @@ def main():
 
           packages=["boxtree"],
           install_requires=[
-              "pytools>=2013.1",
+              "pytools>=2018.4",
               "pyopencl>=2013.1",
               "Mako>=0.7.3",
               "pytest>=2.3",
-- 
GitLab


From 029cb6dbc7b52abe6bee5a0729efb324441e6a85 Mon Sep 17 00:00:00 2001
From: Andreas Kloeckner <inform@tiker.net>
Date: Fri, 20 Apr 2018 16:12:59 -0500
Subject: [PATCH 2/3] Fix some missing ProcessLogger arguments

---
 boxtree/area_query.py | 4 ++--
 1 file changed, 2 insertions(+), 2 deletions(-)

diff --git a/boxtree/area_query.py b/boxtree/area_query.py
index 5790ce1..84e3733 100644
--- a/boxtree/area_query.py
+++ b/boxtree/area_query.py
@@ -823,7 +823,7 @@ class LeavesToBallsLookupBuilder(object):
         if ball_radii.dtype != tree.coord_dtype:
             raise TypeError("ball_radii dtype must match tree.coord_dtype")
 
-        ltb_plog = ProcessLogger("leaves-to-balls lookup: run area query")
+        ltb_plog = ProcessLogger(logger, "leaves-to-balls lookup: run area query")
 
         area_query, evt = self.area_query_builder(
                 queue, tree, ball_centers, ball_radii, peer_lists, wait_for)
@@ -1109,7 +1109,7 @@ class PeerListFinder(object):
         peer_list_finder_kernel = self.get_peer_list_finder_kernel(
             tree.dimensions, tree.coord_dtype, tree.box_id_dtype, max_levels)
 
-        pl_plog = ProcessLogger("find peer lists")
+        pl_plog = ProcessLogger(logger, "find peer lists")
 
         result, evt = peer_list_finder_kernel(
                 queue, tree.nboxes,
-- 
GitLab


From 3f7808f369ab3e96aa55fe222941aee506888d71 Mon Sep 17 00:00:00 2001
From: Andreas Kloeckner <inform@tiker.net>
Date: Fri, 20 Apr 2018 19:01:32 -0500
Subject: [PATCH 3/3] Remove unused import

---
 boxtree/tree_build_kernels.py | 1 -
 1 file changed, 1 deletion(-)

diff --git a/boxtree/tree_build_kernels.py b/boxtree/tree_build_kernels.py
index 45c78f8..a854834 100644
--- a/boxtree/tree_build_kernels.py
+++ b/boxtree/tree_build_kernels.py
@@ -32,7 +32,6 @@ from pyopencl.scan import ScanTemplate
 from mako.template import Template
 from pytools import Record, memoize, log_process
 from boxtree.tools import get_type_moniker
-from time import time
 
 import logging
 logger = logging.getLogger(__name__)
-- 
GitLab