Rewrite calibration of loops; change dump output

* Replace "calibrate" with "calibrate loops"
* Rename some worker methods
* add tests on the number of values
* Worker cannot compute values if calibration needed
* Calibration now uses the number of warmups
* dump now writes one value per line

TODO.rst

@@ -10,8 +10,6 @@ BUGS
 TODO
 ====
 
-* ERROR when running bench.py --worker --loops=0 on PyPy? calibration
-  needs multiple processes
 * check: warn if min/max is 25% smaller/larger than mean, instead of 50%?
 * show: add --name option to always display benchmark names
 * Implement a system-wide lock to prevent running two benchmarks at the same

doc/changelog.rst

@@ -4,10 +4,15 @@ Changelog
 Version 1.2
 -----------
 
-* Fix calibration on PyPy: recalibrate until the number of loops becomes
-  stable.
+* Fix calibration on PyPy: spawn multiple worker processes until the number of
+  loops becomes stable.
+* Calibration now uses the number of warmups, instead of 1.
 * Command line interface (CLI): the ``--benchmark``, ``--include-benchmark``
   and ``--exclude-benchmark`` options can now be specified multiple times.
+* ``dump`` command now writes one value per line
+* A worker process cannot calibrate the loops number and compute values
+  anymore. The calibration of the loops number requires multiple processes
+  on PyPy.
 
 Version 1.1 (2017-03-27)
 ------------------------

doc/cli.rst

@@ -245,31 +245,53 @@ Options:
 Example::
 
     $ python3 -m perf dump telco.json
-    Run 1/50: warmup (1): 24.9 ms; values (3): 24.6 ms, 24.6 ms, 24.6 ms
-    Run 2/50: warmup (1): 25.0 ms; values (3): 24.8 ms, 24.8 ms, 24.6 ms
-    Run 3/50: warmup (1): 24.6 ms; values (3): 24.6 ms, 24.5 ms, 24.3 ms
+    Run 1: calibrate the number of loops
+    - calibrate 1: 23.1 ms (loops: 1, raw: 23.1 ms)
+    - calibrate 2: 22.5 ms (loops: 2, raw: 45.0 ms)
+    - calibrate 3: 22.5 ms (loops: 4, raw: 89.9 ms)
+    - calibrate 4: 22.4 ms (loops: 8, raw: 179 ms)
+    Run 2:
+    - warmup 1: 22.5 ms
+    - value 1: 22.8 ms
+    - value 2: 22.5 ms
+    - value 3: 22.6 ms
     (...)
-    Run 50/50: warmup (1): 24.8 ms; values (3): 24.6 ms, 24.8 ms, 24.8 ms
+    Run 41:
+    - warmup 1: 22.5 ms
+    - value 1: 22.6 ms
+    - value 2: 22.4 ms
+    - value 3: 22.4 ms
 
 Example in verbose mode::
 
     $ python3 -m perf dump telco.json -v
     Metadata:
-      cpu_count: 2
+      cpu_affinity: 2-3
+      cpu_config: 2-3=driver:intel_pstate, intel_pstate:turbo, governor:performance, isolated; idle:intel_idle
+      cpu_count: 4
       cpu_model_name: Intel(R) Core(TM) i7-3520M CPU @ 2.90GHz
       hostname: selma
-      loops: 4
+      loops: 8
       name: telco
+      perf_version: 0.8.2
       ...
 
-    Run 1: warmup (1): 24.7 ms; values (3): 24.5 ms, 24.5 ms, 24.5 ms
-      cpu_freq: 1=3588 MHz
-      date: 2016-07-17T22:50:27
-      load_avg_1min: 0.12
-    Run 2: warmup (1): 25.0 ms; values (3): 24.8 ms, 24.6 ms, 24.8 ms
-      cpu_freq: 1=3586 MHz
-      date: 2016-07-17T22:50:27
-      load_avg_1min: 0.12
+    Run 1: calibrate the number of loops
+    - calibrate 1: 23.1 ms (loops: 1, raw: 23.1 ms)
+    - calibrate 2: 22.5 ms (loops: 2, raw: 45.0 ms)
+    - calibrate 3: 22.5 ms (loops: 4, raw: 89.9 ms)
+    - calibrate 4: 22.4 ms (loops: 8, raw: 179 ms)
+    Run 2:
+    - warmup 1: 22.5 ms
+    - value 1: 22.8 ms
+    - value 2: 22.5 ms
+    - value 3: 22.6 ms
+    - Metadata:
+      cpu_freq: 2=3596 MHz, 3=2998 MHz
+      cpu_temp: coretemp:Physical id 0=67 C, coretemp:Core 0=51 C, coretemp:Core 1=67 C
+      date: 2016-10-21 03:14:20.496710
+      duration: 723 ms
+      load_avg_1min: 0.29
     ...
 
 

doc/runner.rst

@@ -157,14 +157,14 @@ explicitly::
 
     --worker
     --worker-task=TASK_ID
-    --calibrate
-    --recalibrate
+    --calibrate-loops
+    --recalibrate-loops
     --debug-single-value
 
 * ``--worker``: a worker process, run the benchmark in the running processs
 * ``--worker-task``: Identifier of the worker task, only execute the benchmark
   function number ``TASK_ID``.
-* ``--calibrate``: only calibrate the benchmark, don't compute values
-* ``--recalibrate``: only compute warmup values to validate the number of
+* ``--calibrate-loops``: only calibrate the benchmark, don't compute values
+* ``--recalibrate-loops``: only compute warmup values to validate the number of
   loops. Option used with JIT compilers to validate the number of loops.
 * ``--debug-single-value``: Debug mode, only produce a single value

perf/_cli.py

@@ -51,18 +51,26 @@ def format_run(bench, run_index, run, common_metadata=None, raw=False,
     inner_loops = run._get_inner_loops()
 
     if run._is_calibration():
-        lines.append("Run %s: calibrate" % (run_index,))
-        for loops, value in run.warmups:
+        lines.append("Run %s: calibrate the number of loops" % (run_index,))
+        if raw:
+            name = 'raw calibrate'
+        else:
+            name = 'calibrate'
+        for index, warmup in enumerate(run.warmups, 1):
+            loops, value = warmup
             raw_value = value * (loops * inner_loops)
             if raw:
-                lines.append("- %s: %s"
-                             % (format_number(loops, 'loop'),
-                                format_timedelta(raw_value)))
+                text = format_timedelta(raw_value)
+                text = ("%s (loops: %s)"
+                        % (format_timedelta(raw_value),
+                           format_number(loops)))
             else:
-                lines.append("- %s: %s (raw: %s)"
-                             % (format_number(loops, 'loop'),
-                                format_timedelta(value),
-                                format_timedelta(raw_value)))
+                text = ("%s (loops: %s, raw: %s)"
+                        % (format_timedelta(value),
+                           format_number(loops),
+                           format_timedelta(raw_value)))
+            lines.append("- %s %s: %s"
+                         % (name, index, text))
         return lines
 
     show_warmup = (verbose >= 0)
@@ -81,6 +89,8 @@ def format_values(values):
                 values_str[index] += ' (%+.0f%%)' % (delta * 100 / mean)
         return values_str
 
+    lines.append("Run %s:" % (run_index,))
+
     values = run.values
     if raw:
         warmups = [bench.format_value(value * (loops * inner_loops))
@@ -93,30 +103,30 @@ def format_values(values):
             warmups = format_values(warmups)
     values = format_values(values)
 
-    if raw:
-        name = 'raw values'
-    else:
-        name = 'values'
-    text = '%s (%s): %s' % (name, len(values), ', '.join(values))
     if warmups and show_warmup:
         if raw:
-            name = 'raw warmups'
+            name = 'raw warmup'
         else:
-            name = 'warmups'
-        text = ('%s (%s): %s; %s'
-                % (name, len(warmups), ', '.join(warmups), text))
+            name = 'warmup'
+        for index, warmup in enumerate(warmups, 1):
+            lines.append('- %s %s: %s' % (name, index, warmup))
 
-    text = "Run %s: %s" % (run_index, text)
-    lines.append(text)
+    if raw:
+        name = 'raw value'
+    else:
+        name = 'value'
+    for index, value in enumerate(values, 1):
+        lines.append('- %s %s: %s' % (name, index, value))
 
     if verbose > 0:
-        prefix = '  '
         metadata = run.get_metadata()
-        for name, value in sorted(metadata.items()):
-            if common_metadata and name in common_metadata:
-                continue
-            value = _format_metadata(name, value)
-            lines.append('%s%s: %s' % (prefix, name, value))
+        if metadata:
+            lines.append('- Metadata:')
+            for name, value in sorted(metadata.items()):
+                if common_metadata and name in common_metadata:
+                    continue
+                value = _format_metadata(name, value)
+                lines.append('  %s: %s' % (name, value))
 
     return lines
 

perf/_runner.py

@@ -177,10 +177,10 @@ def __init__(self, values=None, warmups=None, processes=None,
         parser.add_argument('--worker-task', type=positive_or_nul, metavar='TASK_ID',
                             help='Identifier of the worker task: '
                                  'only execute the benchmark function TASK_ID')
-        parser.add_argument('--calibrate', action="store_true",
-                            help="only calibrate the benchmark, "
+        parser.add_argument('--calibrate-loops', action="store_true",
+                            help="only calibrate the number of loops, "
                                  "don't compute values")
-        parser.add_argument('--recalibrate', action="store_true",
+        parser.add_argument('--recalibrate-loops', action="store_true",
                             help="only compute warmup values to validate "
                                  "the number of loops")
         parser.add_argument('-d', '--dump', action="store_true",
@@ -258,25 +258,36 @@ def _process_args(self):
             args.loops = 1
             args.min_time = 1e-9
 
-        if args.calibrate:
+        if args.calibrate_loops:
             if not args.worker:
                 print("ERROR: Calibration can only be done "
                       "in a worker process")
                 sys.exit(1)
+            if args.loops:
+                print("ERROR: --loops=N is incompatible with "
+                      "--calibration-loops")
+                sys.exit(1)
 
             args.loops = 0
             # calibration values will be stored as warmup values
-            args.warmups = 0
             args.values = 0
-        elif args.recalibrate:
+        elif args.recalibrate_loops:
             if not args.worker:
                 print("ERROR: Recalibration can only be done "
                       "in a worker process")
                 sys.exit(1)
+            if not args.loops:
+                print("ERROR: --recalibration-loops requires --loops=N")
+                sys.exit(1)
 
-            if not args.warmups:
-                args.warmups = 1
             args.values = 0
+        elif args.values < 1:
+            print("ERROR: need at least one value")
+            sys.exit(1)
+
+        if args.worker and not args.loops and args.values:
+            print("ERROR: --worker requires --loops=N or --calibrate-loops")
+            sys.exit(1)
 
         filename = args.output
         if filename and os.path.exists(filename):
@@ -439,7 +450,8 @@ def task_func(task, loops):
             return time_func(loops, *args)
 
         task = WorkerProcessTask(self, name, task_func, metadata)
-        task.calibrate_warmups = (self.args.calibrate or self.args.recalibrate)
+        task.calibrate_warmups = (self.args.calibrate_loops
+                                  or self.args.recalibrate_loops)
         task.inner_loops = inner_loops
         return self._main(task)
 
@@ -475,7 +487,8 @@ def task_func(task, loops):
             return dt
 
         task = WorkerProcessTask(self, name, task_func, metadata)
-        task.calibrate_warmups = (self.args.calibrate or self.args.recalibrate)
+        task.calibrate_warmups = (self.args.calibrate_loops
+                                  or self.args.recalibrate_loops)
         task.inner_loops = inner_loops
         return self._main(task)
 
@@ -493,7 +506,7 @@ def timeit(self, name, stmt, setup="pass", inner_loops=None,
                             func_metadata=metadata,
                             globals=globals)
 
-    def _worker_cmd(self, python, calibrate, wpipe):
+    def _worker_cmd(self, python, calibrate_loops, wpipe):
         args = self.args
 
         cmd = [python]
@@ -504,11 +517,11 @@ def _worker_cmd(self, python, calibrate, wpipe):
                     '--warmups', str(args.warmups),
                     '--loops', str(args.loops),
                     '--min-time', str(args.min_time)))
-        if calibrate:
-            if calibrate > 1:
-                cmd.append('--recalibrate')
+        if calibrate_loops:
+            if calibrate_loops > 1:
+                cmd.append('--recalibrate-loops')
             else:
-                cmd.append('--calibrate')
+                cmd.append('--calibrate-loops')
         if args.verbose:
             cmd.append('-' + 'v' * args.verbose)
         if args.affinity:
@@ -523,7 +536,7 @@ def _worker_cmd(self, python, calibrate, wpipe):
 
         return cmd
 
-    def _spawn_worker(self, python=None, calibrate=0):
+    def _spawn_worker(self, python=None, calibrate_loops=0):
         if not python:
             python = self.args.python
 
@@ -534,7 +547,7 @@ def _spawn_worker(self, python=None, calibrate=0):
         with rpipe:
             with wpipe:
                 warg = wpipe.to_subprocess()
-                cmd = self._worker_cmd(python, calibrate, warg)
+                cmd = self._worker_cmd(python, calibrate_loops, warg)
 
                 kw = {}
                 if MS_WINDOWS:
@@ -606,9 +619,9 @@ def _spawn_workers(self, python=None, newline=True):
         nprocess = args.processes
         old_loops = self.args.loops
         if not args.loops:
-            calibrate = 1
+            calibrate_loops = 1
         else:
-            calibrate = 0
+            calibrate_loops = 0
         has_jit = perf.python_has_jit()
 
         if verbose and self._worker_task > 0:
@@ -617,7 +630,7 @@ def _spawn_workers(self, python=None, newline=True):
         nprocess_value = 0
         nprocess_warmup = 0
         while nprocess_value < nprocess:
-            suite = self._spawn_worker(python, calibrate)
+            suite = self._spawn_worker(python, calibrate_loops)
             if suite is None:
                 raise RuntimeError("perf worker process didn't produce JSON result")
 
@@ -641,36 +654,36 @@ def _spawn_workers(self, python=None, newline=True):
                 print(".", end='')
             sys.stdout.flush()
 
-            if calibrate:
-                if calibrate > 1:
+            if calibrate_loops:
+                if calibrate_loops > 1:
                     # Recalibration (JIT compiler only): get the number of
                     # loops from the last warmup value
                     old_loops = args.loops
                     args.loops = run.warmups[-1][0]
 
                     if args.loops != old_loops:
                         # recalibrate
-                        calibrate += 1
+                        calibrate_loops += 1
                     else:
                         # calibration now seems stable
-                        calibrate = 0
+                        calibrate_loops = 0
                 else:
-                    # Use the first worker to calibrate the benchmark. Use a
-                    # worker process rather than the main process because
+                    # Use the first worker to calibrate the number of loops.
+                    # Use a worker process rather than the main process because
                     # a worker process is more isolated and so should be more
                     # reliable.
                     args.loops = run._get_loops()
 
                     if has_jit:
                         # recalibrate
-                        calibrate += 1
+                        calibrate_loops += 1
                     else:
-                        calibrate = 0
+                        calibrate_loops = 0
 
-                if calibrate > MAX_CALIBRATION:
+                if calibrate_loops > MAX_CALIBRATION:
                     print("ERROR: calibration failed, the number of loops "
                           "is not stable after %s calibrations"
-                          % (calibrate - 1))
+                          % (calibrate_loops - 1))
                     sys.exit(1)
 
                 if verbose: