diff --git a/boxtree/area_query.py b/boxtree/area_query.py index ed08fc6e9d0c316acf547d53173297a7a810fc84..84e3733fe6ad6cb717a2803d186f50d6284bd133 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(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) @@ -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(logger, "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 dc38cda0a75ffc740a66f0a1f960a9f9c749eb49..b2dd2764eb6ae49d41e7335c65ff025dc7f23ce6 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 693c13aba11ecbec037b047c9a7acd3e3c7b01a9..ddf7e2000b16a9195eab5f6c38ec438899c2367d 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 597f2ccf84f35234c647c8749c358f2324374217..d7cda23601b0b3d2aaf7d801c4c8d3c2e114911e 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 84a7fbc01891fa4d0ceb600a09bea642f91fafeb..15e8dd472cfdefe1019c2a994bed1fa6dad445a5 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__) @@ -520,8 +521,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: @@ -539,7 +540,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 @@ -1122,12 +1123,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 # }}} @@ -1576,10 +1573,8 @@ 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, %d particles, " - "elapsed time: %g s", - nlevels, len(box_parent_ids), nsrcntgts, tree_build_elapsed) + tree_build_proc.done("%d levels, %d boxes, %d particles", + nlevels, len(box_parent_ids), nsrcntgts) 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 f86b0baa6b4a6316ead3a6ce0859b8eb2029259f..a8548349d3ab6e0e1ff7e5aad3b8bc66304e3be2 100644 --- a/boxtree/tree_build_kernels.py +++ b/boxtree/tree_build_kernels.py @@ -30,9 +30,8 @@ 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 import logging logger = logging.getLogger(__name__) @@ -1282,6 +1281,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 +1293,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 +1710,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 7f3f3fa2336e3a90daf48c1c66240be75af0a2c3..32cca6a23d46884c398fe0f31c363f7e8f4e7c76 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",