perf(computes): the host CPU graph no longer waits a second per poll

Each poll of a host's overview graph held a worker for one second between
two CPU samples. The answer now carries its sample, signed with the time
and the compute; the next poll sends it back and the usage is taken since
then, so a point is the average since the previous one (normally 5 s, at
most 15 s). Without a sample, or with one that is altered, older or from
another host, or when the host restarted, it is measured over one second
as before.

A sample is one reading; the busy share was mixed from separate readings,
counted guest time twice (it is part of user) and added half a percent.
A host that cannot be read leaves a gap in both graphs instead of a zero
CPU point and a broken memory axis.

README.md

@@ -534,6 +534,7 @@ A rollback leaves the clone on a detached HEAD at the restored commit; the updat
 - A VM that vanishes from its compute keeps its owners for `INSTANCE_OWNERSHIP_RETENTION_DAYS` (30) in case the same UUID comes back; superusers list and remove these records on the "Removed VMs" admin page.
 - The log rotates (10 MB × 5) in `data/webvirtcloud.log`.
 - A disk can be grown while its VM runs or is paused, not only when it is shut off.
+- A host's CPU graph shows the average since its previous point (normally 5 s) instead of a 1 s sample taken while a worker waits.
 - A running VM without a guest agent shows the IPv4 address the host learned by ARP (the lookup always failed before).
 - After a live migration the VM's NVRAM file is deleted on the source, when it is in libvirt's `/var/lib/libvirt/qemu/nvram` and the destination does not share that directory (a VM created there later with the same name would start with those UEFI variables).
 - gstfsd finds the guest's operating system the way libguestfs inspects it, so a root on LVM works, and it always answers (an error when it finds no or several operating systems). Update `/usr/local/bin/gstfsd` on every compute (see [Adding a Compute Node](#adding-a-compute-node), step 3).

computes/templates/overview.html

@@ -120,6 +120,9 @@
 <script src="{% static "js/poll.js" %}"></script>
 <script>
 
+    {% trans "average over" as average_over %}
+    // the seconds each CPU point averages
+    var cpuWindows = [];
     var cpu_ctx = document.getElementById("cpuChart").getContext("2d");
     var cpuChart = new Chart(cpu_ctx, {
         type: 'line',
@@ -165,7 +168,9 @@
                          if (label) {
                             label += ': ';
                          }
-                         return label += tooltipItem.yLabel + ' %';
+                         label += tooltipItem.yLabel + ' %';
+                         var span = cpuWindows[tooltipItem.index];
+                         return span ? label + ' ({{ average_over|escapejs }} ' + span + ' s)' : label;
                      }
                  }
             }
@@ -220,20 +225,30 @@
         }
     });
     if (Boolean({{ status }}) === true) {
+        // the CPU sample of the previous answer: usage is taken since then
+        var cpuSample = null;
         pollWhileVisible(5000, function () {
-            return $.getJSON('{% url 'compute_graph' compute_id %}');
+            return $.getJSON('{% url 'compute_graph' compute_id %}', cpuSample ? {cpu_sample: cpuSample} : {});
         }, function graph_usage(data) {
+            cpuSample = data.cpu_sample || null;
             cpuChart.data.labels.push(data.timeline);
             memChart.data.labels.push(data.timeline);
 
             cpuChart.data.datasets[0].data.push(data.cpudata);
+            cpuWindows.push(data.window);
             if (cpuChart.data.datasets[0].data.length > 10){
                 cpuChart.data.labels.shift();
                 cpuChart.data.datasets[0].data.shift();
+                cpuWindows.shift();
+            }
+            // a host that could not be read gives no memory value: a gap, same axis
+            if (data.memdata.total) {
+                memChart.options.scales.yAxes[0].ticks.max = parseInt(data.memdata.total / 1048576);
+                memChart.options.scales.yAxes[0].ticks.stepSize = parseInt(data.memdata.total / (1048576 * 5));
+                memChart.data.datasets[0].data.push(parseInt(data.memdata.usage / 1048576));
+            } else {
+                memChart.data.datasets[0].data.push(null);
             }
-            memChart.options.scales.yAxes[0].ticks.max = parseInt(data.memdata.total / 1048576);
-            memChart.options.scales.yAxes[0].ticks.stepSize = parseInt(data.memdata.total / (1048576 * 5));
-            memChart.data.datasets[0].data.push(parseInt(data.memdata.usage / 1048576));
 
             if (memChart.data.datasets[0].data.length > 10){
                 memChart.data.labels.shift();

computes/test_cpu_graph.py

@@ -0,0 +1,171 @@
+"""The host CPU graph: usage is taken between the sample of the graph's
+previous answer and now, without waiting, when that sample is recent and
+unaltered; otherwise over one second as before."""
+
+import json
+import re
+import shutil
+import subprocess
+import unittest
+from unittest import TestCase as UnitTestCase
+from unittest.mock import MagicMock, PropertyMock, patch
+
+from django.contrib.auth import get_user_model
+from django.core import signing
+from django.test import TestCase
+from django.urls import reverse
+from libvirt import libvirtError
+
+from computes.models import Compute
+from computes.views import CPU_SAMPLE_MAX_AGE, CPU_SAMPLE_SIGNER
+from vrtManager.hostdetails import cpu_percent, wvmHostDetails
+
+
+def host(*readings):
+    """A wvmHostDetails whose getCPUStats returns readings, (idle, busy) each."""
+    h = wvmHostDetails.__new__(wvmHostDetails)
+    h.wvm = MagicMock()
+    h.wvm.getCPUStats.side_effect = [
+        {"kernel": busy // 2, "user": busy - busy // 2, "idle": idle, "iowait": 0, "guest": busy // 3, "utilization": 99}
+        for idle, busy in readings
+    ]
+    return h
+
+
+class CpuPercentTestCase(UnitTestCase):
+    def test_busy_share_between_two_samples(self):
+        self.assertEqual(cpu_percent((100, 200), (130, 300)), 70.0)
+        self.assertEqual(cpu_percent((0, 0), (1, 3)), 66.7)
+
+    def test_samples_that_do_not_follow_on(self):
+        for before, after in (((100, 200), (100, 200)), ((100, 200), (50, 100)), ((100, 200), (200, 250))):
+            with self.subTest(before=before, after=after):
+                self.assertIsNone(cpu_percent(before, after))
+
+
+@patch("vrtManager.hostdetails.time")
+class CpuUsageTestCase(UnitTestCase):
+    def test_since_a_previous_sample_without_waiting(self, clock):
+        clock.time.return_value = 105.0
+        h = host((130, 70))
+        usage = h.get_cpu_usage(previous=(100, 100, 100.0))
+        clock.sleep.assert_not_called()
+        # total = kernel + user + idle + iowait; guest (inside user) and utilization are left out
+        self.assertEqual(usage, {"usage": 70.0, "sample": (130, 200, 105.0), "window": 5.0})
+
+    def test_over_one_second_without_a_sample(self, clock):
+        clock.time.side_effect = [10.0, 11.0]
+        h = host((100, 100), (110, 190))
+        self.assertEqual(h.get_cpu_usage(), {"usage": 90.0, "sample": (110, 300, 11.0), "window": 1.0})
+        clock.sleep.assert_called_once_with(1)
+
+    def test_over_one_second_after_the_host_restarted(self, clock):
+        clock.time.side_effect = [10.0, 11.0]
+        h = host((5, 5), (6, 9))
+        usage = h.get_cpu_usage(previous=(1000, 5000, 5.0))
+        clock.sleep.assert_called_once_with(1)
+        self.assertEqual((usage["usage"], usage["window"]), (80.0, 1.0))
+
+    def test_since_the_host_started(self, clock):
+        self.assertEqual(host((25, 75)).get_cpu_usage(diff=False), {"usage": 75.0})
+        clock.sleep.assert_not_called()
+
+
+class GraphTestCase(TestCase):
+    def setUp(self):
+        self.compute = Compute.objects.create(name="graph", hostname="192.0.2.1", login="u", password="p", type=1)
+        self.other = Compute.objects.create(name="other", hostname="192.0.2.2", login="u", password="p", type=1)
+        admin = get_user_model().objects.create_superuser("graph-admin", "graph@example.com", "pw")
+        self.client.force_login(admin)
+        for target in ("computes.views.wvmConnect", "computes.views.wvmHostDetails"):
+            patcher = patch(target)
+            self.addCleanup(patcher.stop)
+            self.conn = patcher.start().return_value  # the graph reads through wvmHostDetails
+        self.conn.get_memory_usage.return_value = {"total": 4, "usage": 1, "percent": 25}
+        self.conn.get_cpu_usage.return_value = {"usage": 12.5, "sample": (10, 20, 100.0), "window": 5.04}
+
+    def graph(self, compute=None, **params):
+        response = self.client.get(reverse("compute_graph", args=[(compute or self.compute).id]), params)
+        self.assertEqual(response.status_code, 200)
+        return json.loads(response.content)
+
+    def previous(self):
+        return self.conn.get_cpu_usage.call_args.kwargs["previous"]
+
+    def test_the_answer_carries_the_sample_for_the_next_poll(self):
+        data = self.graph()
+        self.assertIsNone(self.previous())
+        self.assertEqual((data["cpudata"], data["window"], data["memdata"]["percent"]), (12.5, 5.0, 25))
+        self.graph(cpu_sample=data["cpu_sample"])
+        self.assertEqual(self.previous(), (10, 20, 100.0))
+
+    def test_an_altered_old_or_foreign_sample_is_not_used(self):
+        token = self.graph()["cpu_sample"]
+        foreign = self.graph(self.other)["cpu_sample"]
+        altered = CPU_SAMPLE_SIGNER.sign_object({"compute": self.compute.id, "idle": 0, "total": 1, "time": 0})[:-2] + "xx"
+        for name, sample in (("altered", altered), ("garbage", "x"), ("other compute", foreign)):
+            with self.subTest(name):
+                self.graph(cpu_sample=sample)
+                self.assertIsNone(self.previous())
+        with patch("django.core.signing.time.time", return_value=signing.time.time() + CPU_SAMPLE_MAX_AGE + 1):
+            self.graph(cpu_sample=token)
+        self.assertIsNone(self.previous())
+
+    def test_an_unreachable_host_gives_no_cpu_value_and_no_sample(self):
+        self.conn.get_cpu_usage.side_effect = libvirtError("unreachable")
+        data = self.graph()
+        self.assertEqual((data["cpudata"], data["memdata"]["total"]), (None, None))
+        self.assertNotIn("cpu_sample", data)
+
+
+@unittest.skipUnless(shutil.which("node"), "node is not installed")
+class GraphScriptTestCase(TestCase):
+    """The overview page's script sends each answer's sample with the next poll."""
+
+    def test_the_next_poll_sends_the_previous_sample(self):
+        self.client.force_login(get_user_model().objects.create_superuser("gs-admin", "gs@example.com", "pw"))
+        compute = Compute.objects.create(name="gs", hostname="192.0.2.1", login="u", password="p", type=1)
+        with patch("computes.views.wvmHostDetails") as details, patch.object(
+            Compute, "status", new_callable=PropertyMock, return_value=True
+        ):
+            details.return_value.get_node_info.return_value = ("h", "x86_64", 1024, 2, "cpu", "qemu+tcp://h/system")
+            details.return_value.get_memory_usage.return_value = {"total": 1024, "usage": 512, "percent": 50}
+            page = self.client.get(reverse("overview", args=[compute.id])).content.decode()
+        script = next(s for s in re.findall(r"<script>(.*?)</script>", page, re.S) if "pollWhileVisible(" in s)
+        js = """
+        const vm = require("vm");
+        const charts = [], requests = [];
+        let poll;
+        const page = {
+            document: {getElementById: () => ({getContext: () => ({})})},
+            // Chart.js adds the lists a config leaves out
+            Chart: function (ctx, config) {
+                this.data = Object.assign({labels: []}, config.data);
+                this.data.datasets.forEach((set) => { set.data = set.data || []; });
+                this.options = config.options;
+                this.update = () => {};
+                charts.push(this);
+            },
+            $: {getJSON: (url, params) => { requests.push(params); return {}; }},
+            pollWhileVisible: (interval, request, onData) => { poll = {request, onData}; },
+        };
+        vm.runInNewContext(SCRIPT, vm.createContext(page));
+        const answer = (cpu, sample) => ({cpudata: cpu, window: 5.1, cpu_sample: sample, timeline: "t",
+                                          memdata: {total: 1048576, usage: 0}});
+        poll.request();
+        poll.onData(answer(3, "token-1"));
+        poll.request();
+        poll.onData({cpudata: null, memdata: {total: null, usage: null}, timeline: "t"});
+        poll.request();
+        const label = charts[0].options.tooltips.callbacks.label({datasetIndex: 0, index: 0, yLabel: 3}, charts[0].data);
+        console.log(JSON.stringify({requests, label, cpu: charts[0].data.datasets[0].data,
+                                    mem: charts[1].data.datasets[0].data, memMax: charts[1].options.scales.yAxes[0].ticks.max}));
+        """.replace("SCRIPT", json.dumps(script))
+        out = subprocess.run(["node", "-e", js], capture_output=True, text=True, timeout=30)
+        self.assertEqual(out.returncode, 0, out.stderr)
+        result = json.loads(out.stdout)
+        self.assertEqual(result["requests"], [{}, {"cpu_sample": "token-1"}, {}])
+        self.assertEqual(result["cpu"], [3, None])
+        # a host that could not be read leaves a gap and keeps the memory axis
+        self.assertEqual((result["mem"], result["memMax"]), ([0, None], 1))
+        self.assertTrue(result["label"].endswith(": 3 % (average over 5.1 s)"), result["label"])

computes/views.py

@@ -1,6 +1,7 @@
 import json
 
 from admin.decorators import superuser_only
+from django.core import signing
 from django.http import HttpResponse
 from django.shortcuts import get_object_or_404, redirect, render
 from django.urls import reverse
@@ -20,6 +21,11 @@ from computes.models import Compute
 
 from . import utils
 
+# The host CPU graph sends back the CPU sample of its previous answer; usage
+# is taken since then when it is this recent, otherwise over one second.
+CPU_SAMPLE_MAX_AGE = 15
+CPU_SAMPLE_SIGNER = signing.TimestampSigner(salt="computes.cpu-sample")
+
 
 @superuser_only
 def computes(request):
@@ -130,7 +136,7 @@ def compute_graph(request, compute_id):
     :return:
     """
     comp_mgr = ComputeManager(compute_id)
-    data = comp_mgr.compute_graph()
+    data = comp_mgr.compute_graph(request.GET.get("cpu_sample"))
 
     return HttpResponse(data, content_type="application/json")
 
@@ -219,7 +225,21 @@ class ComputeManager:
 
         return json.dumps(data)
 
-    def compute_graph(self):
+    def _cpu_sample(self, token):
+        """The (idle, total, time) sample in a token of this compute's graph,
+        or None when there is none, it is altered or too old."""
+        if not token:
+            return None
+        try:
+            data = CPU_SAMPLE_SIGNER.unsign_object(token, max_age=CPU_SAMPLE_MAX_AGE)
+        except signing.BadSignature:
+            return None
+        if data.get("compute") != self.compute.id:
+            return None
+        return data["idle"], data["total"], data["time"]
+
+    def compute_graph(self, cpu_sample=None):
+        result = {"cpudata": None, "memdata": {"total": None, "usage": None}, "timeline": timezone.now().strftime("%H:%M:%S")}
         try:
             conn = wvmHostDetails(
                 self.compute.hostname,
@@ -227,19 +247,19 @@ class ComputeManager:
                 self.compute.password,
                 self.compute.type,
             )
-            current_time = timezone.now().strftime("%H:%M:%S")
-            cpu_usage = conn.get_cpu_usage()
-            mem_usage = conn.get_memory_usage()
+            cpu = conn.get_cpu_usage(previous=self._cpu_sample(cpu_sample))
+            idle, total, taken = cpu["sample"]
+            result = {
+                "cpudata": cpu["usage"],
+                "memdata": conn.get_memory_usage(),
+                "timeline": timezone.now().strftime("%H:%M:%S"),
+                "window": round(cpu["window"], 1),
+                "cpu_sample": CPU_SAMPLE_SIGNER.sign_object(
+                    {"compute": self.compute.id, "idle": idle, "total": total, "time": taken}
+                ),
+            }
             conn.close()
         except libvirtError:
-            cpu_usage = {"usage": 0}
-            mem_usage = {"usage": 0}
-            current_time = 0
+            pass
 
-        return json.dumps(
-            {
-                "cpudata": cpu_usage["usage"],
-                "memdata": mem_usage,
-                "timeline": current_time,
-            }
-        )
+        return json.dumps(result)

vrtManager/hostdetails.py

@@ -1,9 +1,26 @@
 import time
 
+from libvirt import VIR_NODE_CPU_STATS_ALL_CPUS
+
 from vrtManager.connection import wvmConnect
 from vrtManager.util import get_xml_path
 
 
+# the times of virNodeGetCPUStats that add up to the elapsed CPU time; guest is
+# already part of user and utilization is a percentage
+CPU_TIMES = ("kernel", "user", "idle", "iowait")
+
+
+def cpu_percent(before, after):
+    """Busy share in percent between two (idle, total) samples, or None when
+    the second does not follow the first."""
+    idle = after[0] - before[0]
+    total = after[1] - before[1]
+    if total <= 0 or not 0 <= idle <= total:
+        return None
+    return round(100 * (total - idle) / total, 1)
+
+
 def cpu_version(doc):
     for info in doc.xpath("/sysinfo/processor/entry"):
         elem = info.xpath("@name")[0]
@@ -27,32 +44,34 @@ class wvmHostDetails(wvmConnect):
         else:
             return {"total": None, "usage": None, "percent": None}
 
-    def get_cpu_usage(self, diff=True):
-        """
-        Function return cpu usage on node.
-        """
-        prev_idle = 0
-        prev_total = 0
-        cpu = self.wvm.getCPUStats(-1, 0)
-        if not isinstance(cpu, dict):
-            return {"usage": None}
+    def _cpu_times(self):
+        """(idle, total) nanoseconds of all host CPUs, from one reading."""
+        stats = self.wvm.getCPUStats(VIR_NODE_CPU_STATS_ALL_CPUS, 0)
+        return stats["idle"], sum(stats.get(name, 0) for name in CPU_TIMES)
 
-        for num in range(2):
-            idle = self.wvm.getCPUStats(-1, 0)["idle"]
-            total = sum(self.wvm.getCPUStats(-1, 0).values())
-            diff_idle = idle - prev_idle
-            diff_total = total - prev_total
-            diff_usage = (1000 * (diff_total - diff_idle) / diff_total + 5) / 10
-            if not diff:
-                return {"usage": diff_usage}
-            prev_total = total
-            prev_idle = idle
-            if num == 0:
-                time.sleep(1)
-            else:
-                diff_usage = max(diff_usage, 0)
-
-        return {"usage": diff_usage}
+    def get_cpu_usage(self, diff=True, previous=None):
+        """
+        Busy share of all host CPUs in percent. diff=False: since the host
+        started. Otherwise since previous, an (idle, total, time) sample this
+        method returned, or over one second when there is none or it does not
+        lead to this one (the host restarted). Also returns the closing sample
+        and the seconds the usage covers.
+        """
+        times = self._cpu_times()
+        if not diff:
+            return {"usage": cpu_percent((0, 0), times)}
+        now = time.time()
+        usage = None
+        if previous is not None:
+            usage = cpu_percent(previous[:2], times)
+            start = previous[2]
+        if usage is None:
+            before, start = times, now
+            time.sleep(1)
+            times = self._cpu_times()
+            now = time.time()
+            usage = cpu_percent(before, times)
+        return {"usage": usage, "sample": (*times, now), "window": now - start}
 
     def get_node_info(self):
         """