From 8a875828ffe3acbd3d32898f2365c69cafc4f3f0 Mon Sep 17 00:00:00 2001 From: Andreas Kloeckner Date: Fri, 23 Mar 2018 14:58:37 -0500 Subject: [PATCH 1/2] Reduce log chattiness --- boxtree/area_query.py | 56 ++++++++++++++++++++++++++--------- boxtree/traversal.py | 20 +++++++++---- boxtree/tree_build.py | 26 +++++++++------- boxtree/tree_build_kernels.py | 12 ++++++-- 4 files changed, 82 insertions(+), 32 deletions(-) diff --git a/boxtree/area_query.py b/boxtree/area_query.py index a824cfc..ed08fc6 100644 --- a/boxtree/area_query.py +++ b/boxtree/area_query.py @@ -34,6 +34,8 @@ from mako.template import Template from boxtree.tools import AXIS_NAMES, DeviceDataRecord from pytools import memoize_method +from time import time + import logging logger = logging.getLogger(__name__) @@ -635,7 +637,7 @@ class AreaQueryBuilder(object): from pyopencl.tools import dtype_to_ctype from boxtree import box_flags_enum - logger.info("start building area query kernel") + logger.debug("start building area query kernel") from boxtree.traversal import TRAVERSAL_PREAMBLE_TEMPLATE from boxtree.tree_build import TreeBuilder @@ -689,7 +691,7 @@ class AreaQueryBuilder(object): count_sharing={}, complex_kernel=True) - logger.info("done building area query kernel") + logger.debug("done building area query kernel") return area_query_kernel # }}} @@ -741,7 +743,8 @@ class AreaQueryBuilder(object): tree.coord_dtype, tree.box_id_dtype, ball_id_dtype, peer_lists.peer_list_starts.dtype, max_levels) - logger.info("area query: run area query") + logger.debug("area query: run area query") + aq_start_time = time() result, evt = area_query_kernel( queue, len(ball_radii), @@ -754,7 +757,13 @@ class AreaQueryBuilder(object): tuple(bc.data for bc in ball_centers)), wait_for=wait_for) - logger.info("area query: done") + 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) return AreaQueryResult( tree=tree, @@ -823,13 +832,14 @@ class LeavesToBallsLookupBuilder(object): if ball_radii.dtype != tree.coord_dtype: raise TypeError("ball_radii dtype must match tree.coord_dtype") - logger.info("leaves-to-balls lookup: run area query") + logger.debug("leaves-to-balls lookup: run area query") + ltb_start_time = time() area_query, evt = self.area_query_builder( queue, tree, ball_centers, ball_radii, peer_lists, wait_for) wait_for = [evt] - logger.info("leaves-to-balls lookup: expand starts") + logger.debug("leaves-to-balls lookup: expand starts") nkeys = tree.nboxes nballs_p_1 = len(area_query.leaves_near_ball_starts) @@ -851,7 +861,7 @@ class LeavesToBallsLookupBuilder(object): nballs_p_1) wait_for = [evt] - logger.info("leaves-to-balls lookup: key-value sort") + logger.debug("leaves-to-balls lookup: key-value sort") balls_near_box_starts, balls_near_box_lists, evt \ = self.key_value_sorter( @@ -863,7 +873,13 @@ class LeavesToBallsLookupBuilder(object): nkeys, starts_dtype=tree.box_id_dtype, wait_for=wait_for) - logger.info("leaves-to-balls lookup: built") + 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) return LeavesToBallsLookup( tree=tree, @@ -968,7 +984,8 @@ class SpaceInvaderQueryBuilder(object): tree.dimensions, tree.coord_dtype, tree.box_id_dtype, peer_lists.peer_list_starts.dtype, max_levels) - logger.info("space invader query: run space invader query") + logger.debug("space invader query: run space invader query") + si_start_time = time() outer_space_invader_dists = cl.array.zeros(queue, tree.nboxes, np.float32) if not wait_for: @@ -994,7 +1011,12 @@ class SpaceInvaderQueryBuilder(object): tree.coord_dtype) evt, = outer_space_invader_dists.events - logger.info("space invader query: done") + 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) return outer_space_invader_dists, evt @@ -1037,7 +1059,7 @@ class PeerListFinder(object): from pyopencl.tools import dtype_to_ctype from boxtree import box_flags_enum - logger.info("start building peer list finder kernel") + logger.debug("start building peer list finder kernel") from boxtree.traversal import ( TRAVERSAL_PREAMBLE_TEMPLATE, HELPER_FUNCTION_TEMPLATE) @@ -1084,7 +1106,7 @@ class PeerListFinder(object): count_sharing={}, complex_kernel=True) - logger.info("done building peer list finder kernel") + logger.debug("done building peer list finder kernel") return peer_list_finder_kernel # }}} @@ -1109,7 +1131,8 @@ 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.info("peer list finder: find peer lists") + logger.debug("peer list finder: find peer lists") + pl_start_time = time() result, evt = peer_list_finder_kernel( queue, tree.nboxes, @@ -1118,7 +1141,12 @@ class PeerListFinder(object): tree.box_child_ids.data, tree.box_flags.data, wait_for=wait_for) - logger.info("peer list finder: done") + 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) return PeerListLookup( tree=tree, diff --git a/boxtree/traversal.py b/boxtree/traversal.py index 6caadc3..3c42d50 100644 --- a/boxtree/traversal.py +++ b/boxtree/traversal.py @@ -30,6 +30,7 @@ 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__) @@ -1551,7 +1552,8 @@ class _KernelInfo(Record): class FMMTraversalBuilder: def __init__(self, context, well_sep_is_n_away=1, from_sep_smaller_crit=None): """ - :arg well_sep_is_n_away: Either An integer 1 or greater. (Only 2 is tested) + :arg well_sep_is_n_away: Either An integer 1 or greater. + (Only 1 and 2 are tested.) The spacing between boxes that is considered "well-separated" for :attr:`from_sep_siblings` (List 2). :arg from_sep_smaller_crit: The criterion used to determine separation @@ -1614,7 +1616,8 @@ class FMMTraversalBuilder: # }}} - logger.info("traversal build kernels: start build") + logger.debug("traversal build kernels: start build") + kernel_build_start = time() debug = False @@ -1771,7 +1774,13 @@ class FMMTraversalBuilder: # }}} - logger.info("traversal build kernels: done") + 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) @@ -1823,7 +1832,8 @@ class FMMTraversalBuilder: logger.debug(s) - logger.info("start building traversal") + traversal_build_start_time = time() + logger.debug("start building traversal") # {{{ source boxes, their parents, and target boxes @@ -2117,7 +2127,7 @@ class FMMTraversalBuilder: evt, = wait_for - logger.info("traversal built") + logger.info("traversal built after %g seconds", time()-traversal_build_start_time) return FMMTraversalInfo( tree=tree, diff --git a/boxtree/tree_build.py b/boxtree/tree_build.py index fcbf1dc..dbf9f52 100644 --- a/boxtree/tree_build.py +++ b/boxtree/tree_build.py @@ -216,7 +216,7 @@ class TreeBuilder(object): sources_are_targets, srcntgts_extent_norm, kind=kind) - logger.info("tree build: start") + logger.debug("tree build: start") # {{{ combine sources and targets into one array, if necessary @@ -515,7 +515,7 @@ class TreeBuilder(object): level_leaf_counts = np.array([1]) from time import time - start_time = time() + tree_build_start_time = time() if total_refine_weight > max_leaf_refine_weight: level = 1 else: @@ -853,7 +853,7 @@ class TreeBuilder(object): # }}} - logger.info("LEVEL %d -> %d boxes" % (level, nboxes_new)) + logger.debug("LEVEL %d -> %d boxes" % (level, nboxes_new)) assert ( level_start_box_nrs[-1] != nboxes_new or @@ -1114,15 +1114,16 @@ class TreeBuilder(object): # }}} - end_time = time() - elapsed = end_time-start_time + nboxes = level_start_box_nrs[-1] + + level_loop_elapsed = time()-tree_build_start_time npasses = level+1 - logger.info("elapsed time: %g s (%g s/particle/pass)" % ( - elapsed, elapsed/(npasses*nsrcntgts))) + 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)) del npasses - nboxes = level_start_box_nrs[-1] - # }}} # {{{ extract number of non-child srcntgts from box morton counts @@ -1189,7 +1190,7 @@ class TreeBuilder(object): size=nboxes, wait_for=wait_for) wait_for = [evt] nboxes_post_prune = int(nboxes_post_prune_dev.get()) - logger.info("{} boxes after pruning " + logger.debug("{} boxes after pruning " "({} empty leaves and/or unused boxes removed)" .format(nboxes_post_prune, nboxes - nboxes_post_prune)) should_prune = True @@ -1569,7 +1570,10 @@ class TreeBuilder(object): if targets_have_extent: extra_tree_attrs.update(target_radii=target_radii) - logger.info("tree build complete") + 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) 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 5c9bfcb..f86b0ba 100644 --- a/boxtree/tree_build_kernels.py +++ b/boxtree/tree_build_kernels.py @@ -32,6 +32,7 @@ from pyopencl.scan import ScanTemplate from mako.template import Template from pytools import Record, memoize from boxtree.tools import get_type_moniker +from time import time import logging logger = logging.getLogger(__name__) @@ -1292,7 +1293,8 @@ def get_tree_build_kernel_info(context, dimensions, coord_dtype, level_restrict = (kind == "adaptive-level-restricted") adaptive = not (kind == "non-adaptive") - logger.info("start building tree build kernels") + logger.debug("start building tree build kernels") + kernel_build_start_time = time() # {{{ preparation @@ -1711,7 +1713,13 @@ def get_tree_build_kernel_info(context, dimensions, coord_dtype, # }}} - logger.info("tree build kernels built") + 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, -- GitLab From d62b0b2b51641faa9ad7e66b0651cfcdd04fc892 Mon Sep 17 00:00:00 2001 From: Andreas Kloeckner Date: Fri, 23 Mar 2018 15:55:33 -0500 Subject: [PATCH 2/2] Placate flake8 --- boxtree/traversal.py | 3 ++- 1 file changed, 2 insertions(+), 1 deletion(-) diff --git a/boxtree/traversal.py b/boxtree/traversal.py index 3c42d50..597f2cc 100644 --- a/boxtree/traversal.py +++ b/boxtree/traversal.py @@ -2127,7 +2127,8 @@ class FMMTraversalBuilder: evt, = wait_for - logger.info("traversal built after %g seconds", time()-traversal_build_start_time) + logger.info("traversal built after %g seconds", + time()-traversal_build_start_time) return FMMTraversalInfo( tree=tree, -- GitLab