Feature/timing functions

polytope/datacube/backends/fdb.py

@@ -4,6 +4,7 @@
 from itertools import product
 
 from ...utility.geometry import nearest_pt
+from ...utility.profiling import timing_fn
 from .datacube import Datacube, TensorIndexTree
 
 
@@ -14,7 +15,7 @@ def __init__(self, gj, config=None, axis_options=None, compressed_axes_options=[
 
         super().__init__(axis_options, compressed_axes_options)
 
-        logging.info("Created an FDB datacube with options: " + str(axis_options))
+        logging.debug("Created an FDB datacube with options: " + str(axis_options))
 
         self.unwanted_path = {}
         self.axis_options = axis_options
@@ -30,7 +31,7 @@ def __init__(self, gj, config=None, axis_options=None, compressed_axes_options=[
             for axis_config in alternative_axes:
                 self.fdb_coordinates[axis_config.axis_name] = axis_config.values
 
-        logging.info("Axes returned from GribJump are: " + str(self.fdb_coordinates))
+        logging.debug("Axes returned from GribJump are: " + str(self.fdb_coordinates))
 
         self.fdb_coordinates["values"] = []
         for name, values in self.fdb_coordinates.items():
@@ -55,7 +56,7 @@ def __init__(self, gj, config=None, axis_options=None, compressed_axes_options=[
                 val = self._axes[name].type
                 self._check_and_add_axes(options, name, val)
 
-        logging.info("Polytope created axes for %s", self._axes.keys())
+        logging.debug("Polytope created axes for %s", self._axes.keys())
 
     def check_branching_axes(self, request):
         polytopes = request.polytopes()
@@ -77,10 +78,10 @@ def check_branching_axes(self, request):
         for axis_name in axes_to_remove:
             self._axes.pop(axis_name, None)
 
+    @timing_fn
     def get(self, requests: TensorIndexTree, context=None):
         if context is None:
             context = {}
-        requests.pprint()
         if len(requests.children) == 0:
             return requests
         fdb_requests = []

polytope/datacube/transformations/datacube_merger/datacube_merger.py

@@ -38,7 +38,7 @@ def merged_values(self, datacube):
                 val_to_add = val_to_add.astype("datetime64[s]")
                 merged_values.append(val_to_add)
         merged_values = np.array(merged_values)
-        logging.info(
+        logging.debug(
             f"Merged values {first_ax_vals} on axis {self.name} and \
                      values {second_ax_vals} on axis {second_ax_name} to values {merged_values}"
         )
@@ -64,7 +64,7 @@ def unmerge(self, merged_val):
             # TODO: maybe replacing like this is too specific to time/dates?
             first_val = str(first_val).replace("-", "")
             second_val = second_val.replace(":", "")
-            logging.info(
+            logging.debug(
                 f"Unmerged value {merged_val} to values {first_val} on axis {self.name} \
                         and {second_val} on axis {self._second_axis}"
             )

polytope/engine/hullslicer.py

@@ -12,6 +12,7 @@
 from ..utility.combinatorics import argmax, argmin, group, tensor_product, unique
 from ..utility.exceptions import UnsliceableShapeError
 from ..utility.geometry import lerp
+from ..utility.profiling import timing_fn
 from .engine import Engine
 
 
@@ -204,6 +205,7 @@ def remove_compressed_axis_in_union(self, polytopes):
                     if axis == self.compressed_axes[-1]:
                         self.compressed_axes.remove(axis)
 
+    @timing_fn
     def extract(self, datacube: Datacube, polytopes: List[ConvexPolytope]):
         # Determine list of axes to compress
         self.find_compressed_axes(datacube, polytopes)

polytope/polytope.py

@@ -4,6 +4,7 @@
 from .options import PolytopeOptions
 from .shapes import ConvexPolytope
 from .utility.exceptions import AxisOverdefinedError
+from .utility.profiling import timing_fn
 
 
 class Request:
@@ -56,6 +57,7 @@ def slice(self, polytopes: List[ConvexPolytope]):
         """Low-level API which takes a polytope geometry object and uses it to slice the datacube"""
         return self.engine.extract(self.datacube, polytopes)
 
+    @timing_fn
     def retrieve(self, request: Request, method="standard", context=None):
         """Higher-level API which takes a request and uses it to slice the datacube"""
         if context is None:

polytope/utility/profiling.py

@@ -1,3 +1,4 @@
+import logging
 import time
 
 
@@ -12,3 +13,15 @@ def __exit__(self, ty, val, tb):
         end = time.perf_counter()
         print("%s : %0.7f seconds" % (self.name, end - self.start))
         return False
+
+
+def timing_fn(func):
+    def wrapper(*arg, **kw):
+        t1 = time.perf_counter()
+        res = func(*arg, **kw)
+        time_taken = time.perf_counter() - t1
+        fn_name = func.__name__
+        logging.debug("Time taken for %s is %s seconds", fn_name, time_taken)
+        return res
+
+    return wrapper