FEAT: added timings to debug log

Author: gdementen

larray_editor/arrayadapter.py

@@ -50,7 +50,8 @@
 from larray.util.misc import Product
 
 from larray_editor.utils import (get_sample, scale_to_01range,
-                                 is_number_value_vectorized, logger)
+                                 is_number_value_vectorized, logger,
+                                 timed)
 from larray_editor.commands import CellValueChange
 
 
@@ -397,6 +398,7 @@ def close(self):
     # TODO: factorize with LArrayArrayAdapter (so that we get the attributes
     #       handling of LArrayArrayAdapter for all types and the larray adapter
     #       can benefit from the generic code here
+    @timed(logger)
     def get_data_values_and_attributes(self, h_start, v_start, h_stop, v_stop):
         """h_stop and v_stop should *not* be included"""
         # TODO: implement region caching
@@ -551,6 +553,7 @@ def get_sample(self):
         # return self.get_values(0, 0, min(width, 20), min(height, 20))
         return self.get_data_values_and_attributes(0, 0, min(width, 20), min(height, 20))['values']
 
+    @timed(logger)
     def update_finite_min_max_values(self, finite_values: np.ndarray,
                                      h_start: int, v_start: int,
                                      h_stop: int, v_stop: int):
@@ -652,6 +655,7 @@ def can_sort_hlabel(self, row_idx, col_idx) -> bool:
     def sort_hlabel(self, row_idx, col_idx, ascending):
         pass
 
+    @timed(logger)
     def get_vlabels(self, start, stop) -> dict:
         chunk_values = self.get_vlabels_values(start, stop)
         if isinstance(chunk_values, list) and len(chunk_values) == 0:
@@ -667,6 +671,7 @@ def get_vlabels_values(self, start, stop):
         # that would be slower than what we have now.
         return [[i] for i in range(start, stop)]
 
+    @timed(logger)
     def get_hlabels(self, start, stop):
         values = self.get_hlabels_values(start, stop)
         return {'values': values, 'decoration': self.get_hlabels_decorations(start, stop, values)}
@@ -899,6 +904,7 @@ def __init__(self, data, attributes=None):
         self.vmin = {}
         self.vmax = {}
 
+    @timed(logger)
     def update_finite_min_max_values(self, finite_values: np.ndarray, 
                                      h_start: int, v_start: int,
                                      h_stop: int, v_stop: int):

larray_editor/utils.py

@@ -7,6 +7,7 @@
 import sys
 import math
 import logging
+import time
 import traceback
 from contextlib import contextmanager
 from pathlib import Path
@@ -806,3 +807,91 @@ def get_func_name(frame):
         # defined, not the instance class which is usually much more useful
         func_name = f"{frame.f_locals['self'].__class__.__name__}.{func_name}"
     return func_name
+
+
+def time2str(seconds, precision="auto"):
+    """Format a duration in seconds as a string using given precision.
+
+    Parameters
+    ----------
+    seconds : float
+        Duration (in seconds) to format.
+    precision : str, optional
+        Precision of the output. Defaults to "auto" (the largest unit minus 2).
+        See examples below.
+
+    Returns
+    -------
+    str
+# FIXME: round values instead of truncating them
+    Examples
+    --------
+    >>> time2str(3727.2785, precision="ns")
+    '1 hour 2 minutes 7 seconds 278 ms 500 µs'
+    >>> # auto: the largest unit is hour, the unit two steps below is seconds => precision = seconds
+    >>> time2str(3727.2785)
+    '1 hour 2 minutes 7 seconds'
+    >>> time2str(3605.2785)
+    '1 hour 5 seconds'
+    >>> time2str(3727.2785, precision="hour")
+    '1 hour'
+    >>> time2str(3723.1234567890123456789, precision="ns")
+    '1 hour 2 minutes 3 seconds 123 ms 456 µs 789 ns'
+    >>> time2str(3723.1234567890123456789)
+    '1 hour 2 minutes 3 seconds'
+    """
+    # for Python 3.7+, we could use a dict (and rely on dict ordering)
+    divisors = [
+        ('ns', 1000),
+        ('µs', 1000),
+        ('ms', 1000),
+        ('second', 60),
+        ('minute', 60),
+        ('hour', 24),
+        ('day', 365),
+    ]
+    precision_map = {
+        'day': 6,
+        'hour': 5,
+        'minute': 4,
+        'second': 3,
+        'ms': 2,
+        'µs': 1,
+        'ns': 0,
+    }
+
+    values = []
+    str_parts = []
+    ns = int(seconds * 10 ** 9)
+    value = ns
+    for cur_precision, (unit, divisor_for_next) in enumerate(divisors):
+        next_value, cur_value = divmod(value, divisor_for_next)
+        values.append(cur_value)
+        if next_value == 0:
+            break
+        value = next_value
+    max_prec = len(values) - 1
+    int_precision = max_prec - 2 if precision == 'auto' else precision_map[precision]
+    for cur_precision, (cur_value, (unit, divisor_for_next)) in enumerate(zip(values, divisors)):
+        if cur_value > 0 and cur_precision >= int_precision:
+            str_parts.append(f"{cur_value:d} {unit}{'s' if cur_value > 1 and cur_precision > 2 else ''}")
+    return ' '.join(str_parts[::-1])
+
+
+def timed(logger):
+    def decorator(func):
+        def new_func(*args, **kwargs):
+            # testing for this outside new_func to make the decorator return
+            # the original func if the logger is not enabled does not work
+            # because the logger is not configured yet when the code to be
+            # profiled is defined (and the decorator is called)
+            if logger.isEnabledFor(logging.DEBUG):
+                start = time.perf_counter()
+                res = func(*args, **kwargs)
+                time_taken = time.perf_counter() - start
+                logger.debug(f"{func.__name__} done in {time2str(time_taken)}")
+                return res
+            else:
+                return func(*args, **kwargs)
+        return new_func
+    return decorator