Report disposable performance in JSON

For: QubesOS/qubes-issues#1512

Author: ben-grande

run-tests

@@ -6,7 +6,8 @@ case $0 in (/*) cd "${0%/*}/";; (*/*) cd "./${0%/*}";; esac
 install_rpm_deps () {
     local applications
     applications=(lvm2 python3-docutils python3-pyyaml python3-jinja2
-        python3-lxml btrfs-progs vim-common python3-coverage python3-inotify cryptsetup)
+        python3-lxml btrfs-progs vim-common python3-coverage python3-inotify
+        python3-deepmerge cryptsetup)
 
     if test -f /etc/qubes-release; then
         sudo qubes-dom0-update "${applications[@]}" || :
@@ -20,7 +21,7 @@ install_apt_deps(){
     local applications
     applications=(lvm2 python3-docutils python3-yaml python3-jinja2
         python3-lxml btrfs-progs python3-coverage python3-inotify
-        python3-libvirt cryptsetup)
+        python3-libvirt python3-deepmerge cryptsetup)
     sudo apt --no-install-recommends -- install "${applications[@]}" ||
     : # we don’t actually care if this succeeds
 }

tests/dispvm_perf.py

@@ -30,9 +30,12 @@
 import asyncio
 import concurrent.futures
 import dataclasses
+import json
 import os
+import statistics
 import subprocess
 import time
+from deepmerge import always_merger
 
 
 import qubesadmin
@@ -74,8 +77,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
@@ -396,19 +399,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 +423,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 +448,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_time": 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 = always_merger.merge(old_data, data_final)
+        with open(results_file, "w", encoding="ascii") as file:
+            json.dump(data_final, file)
 
     def run_test(self, test: TestConfig):
         with open(POLICY_FILE, "w", encoding="ascii") as policy: