feat: multiple iterations of functions

README.md

@@ -2,7 +2,7 @@
 
 ![Microbench: Benchmarking and reproducibility metadata capture for Python](https://raw.githubusercontent.com/alubbock/microbench/master/microbench.png)
 
-Microbench is a small Python package for benchmarking Python functions, and 
+Microbench is a small Python package for benchmarking Python functions, and
 optionally capturing extra runtime/environment information. It is most useful in
 clustered/distributed environments, where the same function runs under different
 environments, and is designed to be extensible with new
@@ -20,7 +20,7 @@ examine results. However, some mixins (extensions) have specific requirements:
 * The [line_profiler](https://github.com/rkern/line_profiler)
   package needs to be installed for line-by-line code benchmarking.
 * `MBInstalledPackages` requires `setuptools`, which is not a part of the
-  standard library, but is usually available. 
+  standard library, but is usually available.
 * The CPU cores, total RAM, and telemetry extensions require
   [psutil](https://pypi.org/project/psutil/).
 * The NVIDIA GPU plugin requires the
@@ -56,7 +56,7 @@ Here's a minimal, complete example:
 
 ```python
 from microbench import MicroBench
-    
+
 basic_bench = MicroBench()
 ```
 
@@ -78,17 +78,20 @@ import pandas as pd
 results = pd.read_json(basic_bench.outfile.getvalue(), lines=True)
 ```
 
-The above example captures the fields `start_time`, `finish_time` and
-`function_name`. Microbench can capture many other types of metadata
-from the environment, resource usage, and hardware,
-which are covered below.
+The above example captures the fields `start_time`, `finish_time`,
+`run_durations` and `function_name`. Microbench can capture many
+other types of metadata from the environment, resource usage, and
+hardware, which are covered below.
 
 ### Extended examples
 
-Here's a more complete example using mixins (the `MB` prefixed class 
+Here's a more complete example using mixins (the `MB` prefixed class
 names) to extend functionality. Note that keyword arguments can be supplied
 to the constructor (in this case `some_info=123`) to specify additional
-information to capture. This example also specifies the `outfile` option,
+information to capture. We also specify `iterations=3`, which means that the
+called function with be executed 3 times (the returned result will always
+be from the final run) with timings captured for each run.
+This example also specifies the `outfile` option,
 which appends metadata to a file on disk.
 
 ```python
@@ -99,8 +102,8 @@ class MyBench(MicroBench, MBFunctionCall, MBPythonVersion, MBHostInfo):
     outfile = '/home/user/my-benchmarks'
     capture_versions = (numpy, pandas)  # Or use MBGlobalPackages/MBInstalledPackages
     env_vars = ('SLURM_ARRAY_TASK_ID', )
-    
-benchmark = MyBench(some_info=123)
+
+benchmark = MyBench(some_info=123, iterations=3)
 ```
 
 The `env_vars` option from the example above specifies a list of environment
@@ -132,9 +135,9 @@ from microbench import *
 
 class Bench3(MicroBench, MBInstalledPackages):
     pass
-    
+
 bench3 = Bench3()
-``` 
+```
 
  Mixin                 | Fields captured
 -----------------------|----------------
@@ -159,7 +162,7 @@ separate line in the file. The output from the minimal example above for a
 single run will look similar to the following:
 
 ```json
-{"start_time": "2018-08-06T10:28:24.806493", "finish_time": "2018-08-06T10:28:24.867456", "function_name": "my_function"}
+{"start_time": "2018-08-06T10:28:24.806493+00:00", "finish_time": "2018-08-06T10:28:24.867456+00:00", "run_durations": [0.60857599999999999], "function_name": "my_function"}
 ```
 
 The simplest way to examine results in detail is to load them into a
@@ -174,10 +177,10 @@ Pandas has powerful data manipulation capabilities. For example, to calculate
 the average runtime by Python version:
 
 ```python
-# Calculate runtime for each run
+# Calculate overall runtime
 results['runtime'] = results['finish_time'] - results['start_time']
 
-# Average runtime by Python version
+# Average overall runtime by Python version
 results.groupby('python_version')['runtime'].mean()
 ```
 
@@ -330,7 +333,7 @@ class Bench(MicroBench):
 
     def capture_machine_platform(self, bm_data):
         bm_data['platform'] = platform.machine()
-        
+
 benchmark = Bench()
 ```
 
@@ -443,6 +446,12 @@ although the latter is a one-off per invocation and typically less than one seco
 Telemetry capture intervals should be kept relatively infrequent (e.g., every minute
 or two, rather than every second) to avoid significant runtime impacts.
 
+### Timezones
+
+Microbench captures `start_time` and `finish_time` in the UTC timezone by default.
+This can be overriden by passing a `timezone=tz` argument when creating a benchmark
+class, where `tz` is a timezone object (e.g. created using the `pytz` library).
+
 ## Feedback
 
 Please note this is a recently created, experimental package. Please let me know

microbench/__init__.py

@@ -1,4 +1,4 @@
-from datetime import datetime
+from datetime import datetime, timezone, timedelta
 import json
 import platform
 import socket
@@ -45,6 +45,10 @@ class JSONEncoder(json.JSONEncoder):
     def default(self, o):
         if isinstance(o, datetime):
             return o.isoformat()
+        if isinstance(o, timedelta):
+            return o.total_seconds()
+        if isinstance(o, timezone):
+            return str(o)
         if numpy:
             if isinstance(o, numpy.integer):
                 return int(o)
@@ -65,6 +69,7 @@ class JSONEncodeWarning(Warning):
 
 class MicroBench(object):
     def __init__(self, outfile=None, json_encoder=JSONEncoder,
+                 tz=timezone.utc, iterations=1,
                  *args, **kwargs):
         self._capture_before = []
         if args:
@@ -75,8 +80,13 @@ def __init__(self, outfile=None, json_encoder=JSONEncoder,
         elif not hasattr(self, 'outfile'):
             self.outfile = io.StringIO()
         self._json_encoder = json_encoder
+        self.tz = tz
+        self.iterations = iterations
+
+    def pre_start_triggers(self, bm_data):
+        # Store timezone
+        bm_data['timestamp_tz'] = str(self.tz)
 
-    def pre_run_triggers(self, bm_data):
         # Capture environment variables
         if hasattr(self, 'env_vars'):
             if not isinstance(self.env_vars, Iterable):
@@ -107,22 +117,27 @@ def pre_run_triggers(self, bm_data):
             interval = getattr(self, 'telemetry_interval', 60)
             bm_data['telemetry'] = []
             self._telemetry_thread = TelemetryThread(
-                self.telemetry, interval, bm_data['telemetry'])
+                self.telemetry, interval, bm_data['telemetry'], self.tz)
             self._telemetry_thread.start()
 
-        # Special case, as we want this to run immediately before run
-        bm_data['start_time'] = datetime.now()
+        bm_data['run_durations'] = []
+        bm_data['start_time'] = datetime.now(self.tz)
 
-    def post_run_triggers(self, bm_data):
-        # Special case, as we want this to run immediately after run
-        bm_data['finish_time'] = datetime.now()
+    def post_finish_triggers(self, bm_data):
+        bm_data['finish_time'] = datetime.now(self.tz)
 
         # Terminate telemetry thread and gather results
         if hasattr(self, '_telemetry_thread'):
             self._telemetry_thread.terminate()
             timeout = getattr(self, 'telemetry_timeout', 30)
             self._telemetry_thread.join(timeout)
 
+    def pre_run_triggers(self, bm_data):
+        bm_data['_run_start'] = datetime.now(self.tz)
+
+    def post_run_triggers(self, bm_data):
+        bm_data['run_durations'].append(datetime.now(self.tz) - bm_data['_run_start'])
+
     def capture_function_name(self, bm_data):
         bm_data['function_name'] = bm_data['_func'].__name__
 
@@ -168,14 +183,18 @@ def inner(*args, **kwargs):
                                       '"line_profiler" package')
                 self._line_profiler = line_profiler.LineProfiler(func)
 
-            self.pre_run_triggers(bm_data)
+            self.pre_start_triggers(bm_data)
 
-            if isinstance(self, MBLineProfiler):
-                res = self._line_profiler.runcall(func, *args, **kwargs)
-            else:
-                res = func(*args, **kwargs)
+            for _ in range(self.iterations):
+                self.pre_run_triggers(bm_data)
 
-            self.post_run_triggers(bm_data)
+                if isinstance(self, MBLineProfiler):
+                    res = self._line_profiler.runcall(func, *args, **kwargs)
+                else:
+                    res = func(*args, **kwargs)
+                self.post_run_triggers(bm_data)
+
+            self.post_finish_triggers(bm_data)
 
             if isinstance(self, MBReturnValue):
                 try:
@@ -218,7 +237,6 @@ def capture_function_args_and_kwargs(self, bm_data):
                 bm_data['kwargs'][k] = _UNENCODABLE_PLACEHOLDER_VALUE
 
 
-
 class MBReturnValue(object):
     """ Capture the decorated function's return value """
     pass
@@ -439,14 +457,15 @@ def output_result(self, bm_data):
 
 
 class TelemetryThread(threading.Thread):
-    def __init__(self, telem_fn, interval, slot, *args, **kwargs):
+    def __init__(self, telem_fn, interval, slot, timezone, *args, **kwargs):
         super(TelemetryThread, self).__init__(*args, **kwargs)
         self._terminate = threading.Event()
         signal.signal(signal.SIGINT, self.terminate)
         signal.signal(signal.SIGTERM, self.terminate)
         self._interval = interval
         self._telemetry = slot
         self._telem_fn = telem_fn
+        self._tz = timezone
         if not psutil:
             raise ImportError('Telemetry requires the "psutil" package')
         self.process = psutil.Process()
@@ -455,7 +474,7 @@ def terminate(self, signum=None, frame=None):
         self._terminate.set()
 
     def _get_telemetry(self):
-        telem = {'timestamp': datetime.now()}
+        telem = {'timestamp': datetime.now(self._tz)}
         telem.update(self._telem_fn(self.process))
         self._telemetry.append(telem)
 

microbench/tests/test_base.py

@@ -28,13 +28,39 @@ def my_function():
     for _ in range(3):
         assert my_function() == 499999500000
 
-    results = pandas.read_json(benchmark.outfile.getvalue(), lines=True, )
+    results = pandas.read_json(benchmark.outfile.getvalue(), lines=True)
     assert (results['function_name'] == 'my_function').all()
     assert results['package_versions'][0]['pandas'] == pandas.__version__
     runtimes = results['finish_time'] - results['start_time']
     assert (runtimes > datetime.timedelta(0)).all()
 
 
+def test_multi_iterations():
+    class MyBench(MicroBench):
+        pass
+
+    timezone = datetime.timezone(datetime.timedelta(hours=10))
+    iterations = 3
+    benchmark = MyBench(iterations=iterations, timezone=timezone)
+
+    @benchmark
+    def my_function():
+        pass
+
+    # call the function
+    my_function()
+
+    results = pandas.read_json(benchmark.outfile.getvalue(), lines=True)
+    assert (results['function_name'] == 'my_function').all()
+    runtimes = results['finish_time'] - results['start_time']
+    assert (runtimes >= datetime.timedelta(0)).all()
+    assert results['timezone'][0] == str(timezone)
+
+    assert len(results['run_durations'][0]) == iterations
+    assert all(dur >= 0 for dur in results['run_durations'][0])
+    assert sum(results['run_durations'][0]) <= runtimes[0].total_seconds()
+
+
 def test_capture_global_packages():
     @globals_bench
     def noop():