Report disposable performance in JSON

For: QubesOS/qubes-issues#1512

Author: ben-grande

tests/dispvm_perf.py

@@ -30,14 +30,23 @@
 import asyncio
 import concurrent.futures
 import dataclasses
+import json
 import os
+import statistics
 import subprocess
 import time
-
+from deepmerge import Merger
 
 import qubesadmin
 
 
+merger = Merger(
+    [(list, ["override"]), (dict, ["merge"]), (set, ["override"])],
+    ["override"],
+    ["override"],
+)
+
+
 @dataclasses.dataclass
 class TestConfig:
     """
@@ -50,6 +59,7 @@ class TestConfig:
     :param int preload_max: number of disposables to preload
     :param bool non_dispvm: target a non disposable qube
     :param bool admin_api: use the Admin API directly
+    :param bool extra_id: base test that extra ID varies from
 
     Notes
     -----
@@ -74,8 +84,8 @@ class TestConfig:
           it is simpler to achieve.
         - Concurrent calls are multiple requests that are done without regards
           to the previous request completion.
-        - Concurrency average time is skewed as there are multiples
-          simultaneous calls.
+        - Concurrency mean time is skewed as there are multiples simultaneous
+          calls.
     Normal VS Preloaded:
         - Improving normal qube startup will shorten preload usage time, but
           the reverse is not true. Normal disposables are a control group for
@@ -91,6 +101,7 @@ class TestConfig:
     preload_max: int = 0
     non_dispvm: bool = False
     admin_api: bool = False
+    extra_id: str = ""
 
 
 POLICY_FILE = "/run/qubes/policy.d/10-test-dispvm-perf.policy"
@@ -179,11 +190,13 @@ class TestConfig:
         "dispvm-preload-more-api",
         preload_max=MAX_PRELOAD + 1,
         admin_api=True,
+        extra_id="dispvm-preload-api",
     ),
     TestConfig(
         "dispvm-preload-less-api",
         preload_max=MAX_PRELOAD - 1,
         admin_api=True,
+        extra_id="dispvm-preload-api",
     ),
     TestConfig("dispvm-preload-api", preload_max=MAX_PRELOAD, admin_api=True),
     TestConfig(
@@ -396,19 +409,22 @@ def run_latency_api_calls(self, test):
             qube = self.dvm
 
         results = {}
+        results["api_results"] = {}
+        results["api_results"]["iteration"] = {}
+        results["api_results"]["stage"] = {}
         start_time = get_time()
         if test.concurrent:
             all_results = asyncio.run(self.api_thread(test, service, qube))
             for i in range(1, self.iterations + 1):
-                results[i] = all_results[i - 1]
+                results["api_results"]["iteration"][i] = all_results[i - 1]
         else:
             for i in range(1, self.iterations + 1):
-                results[i] = self.call_api(
+                results["api_results"]["iteration"][i] = self.call_api(
                     test=test, service=service, qube=qube
                 )
         end_time = get_time()
 
-        sample_keys = list(results[1].keys())
+        sample_keys = list(results["api_results"]["iteration"][1].keys())
         value_keys = [k for k in sample_keys if k != "total"]
         headers = (
             ["iter"]
@@ -417,7 +433,7 @@ def run_latency_api_calls(self, test):
             + [f"{k}%" for k in value_keys]
         )
         rows = []
-        for key, values in results.items():
+        for key, values in results["api_results"]["iteration"].items():
             total = values.get("total", 0)
             row_values = [str(key)]
             for k in value_keys:
@@ -442,56 +458,63 @@ def run_latency_api_calls(self, test):
                 " ".join(val.rjust(col_widths[i]) for i, val in enumerate(row))
             )
 
+        values_by_stage = {key: {} for key in sample_keys}
+        for subdict in results["api_results"]["iteration"].values():
+            for key, value in subdict.items():
+                values_by_stage[key].setdefault("values", []).append(value)
+        for key, value in values_by_stage.items():
+            values = value["values"]
+            mean = round(statistics.mean(values), ROUND_PRECISION)
+            median = round(statistics.median(values), ROUND_PRECISION)
+            values_by_stage[key]["mean"] = mean
+            values_by_stage[key]["median"] = median
+        results["api_results"]["stage"].update(values_by_stage)
+
         total_time = round(end_time - start_time, ROUND_PRECISION)
         return total_time, results
 
     def report_result(self, test, result):
-        items = " ".join(
-            "{}={}".format(key, value) for key, value in vars(test).items()
-        )
+        try:
+            template = self.vm1.template.name
+        except AttributeError:
+            template = self.vm1.name
+        data = vars(test)
+        data["template"] = str(template)
         if test.admin_api:
             total_time = result[0]
-            average = round(total_time / self.iterations, ROUND_PRECISION)
-            pretty_average = f"{average:.{ROUND_PRECISION}f}"
-            compiled_result = []
-            for key, value in result[1].items():
-                individual_result = (
-                    f"{key}=("
-                    + ",".join(
-                        f"{k}={v:.{ROUND_PRECISION}f}" for k, v in value.items()
-                    )
-                    + ")"
-                )
-                compiled_result.append(individual_result)
-            items += f" iterations={self.iterations} average={pretty_average} "
-            items += " ".join(compiled_result)
+            data.update(result[1].items())
         else:
             total_time = result
-            average = total_time / self.iterations
-            pretty_average = f"{average:.{ROUND_PRECISION}f}"
-            items += f" iterations={self.iterations} average={pretty_average}"
+        mean = round(total_time / self.iterations, ROUND_PRECISION)
+        data.update(
+            {
+                "iterations": self.iterations,
+                "mean": mean,
+                "total": total_time,
+            }
+        )
+        pretty_mean = f"{mean:.{ROUND_PRECISION}f}"
         pretty_total_time = f"{total_time:.{ROUND_PRECISION}f}"
-        final_result = pretty_total_time + " " + items
         pretty_items = "iterations=" + str(self.iterations)
-        pretty_items += " average=" + pretty_average
+        pretty_items += " mean=" + pretty_mean
         print(f"Run time ({pretty_items}): {pretty_total_time}s")
         results_file = os.environ.get("QUBES_TEST_PERF_FILE")
         if not results_file:
             return
         try:
-            if self.vm2 and self.vm1.template != self.vm2.template:
-                name_prefix = (
-                    f"{self.vm1.template!s}_" f"{self.vm2.template!s}_"
-                )
-            else:
-                name_prefix = f"{self.vm1.template!s}_"
+            name_prefix = f"{template!s}_"
         except AttributeError:
-            if self.vm2:
-                name_prefix = f"{self.vm1!s}_{self.vm2!s}_"
-            else:
-                name_prefix = f"{self.vm1!s}_"
-        with open(results_file, "a", encoding="ascii") as file:
-            file.write(name_prefix + test.name + " " + str(final_result) + "\n")
+            name_prefix = f"{template!s}_"
+        data_final = {}
+        data_final[name_prefix + test.name] = data
+        try:
+            with open(results_file, "r", encoding="ascii") as file:
+                old_data = json.load(file)
+        except (FileNotFoundError, json.JSONDecodeError):
+            old_data = {}
+        data_final = merger.merge(old_data, data_final)
+        with open(results_file, "w", encoding="ascii") as file:
+            json.dump(data_final, file, indent=2)
 
     def run_test(self, test: TestConfig):
         with open(POLICY_FILE, "w", encoding="ascii") as policy: