perf(instances): the VM stats no longer wait a second per poll

Each stats answer carries a signed sample of the counters, bound to the VM,
its compute and UUID. The next poll sends it back and the rates are the
averages since then; a sample from another run of the VM (domain ID),
another host CPU count or device list, or older than 30 s falls back to
one second as before. Windows are measured on the monotonic clock.

Now that a poll is cheap, the Stats tab polls every 5 s like the host
graph, the first time as soon as it opens (pollWhileVisible takes the
delay of the first request).

A counter the host reports as unsupported (-1) or that went back gives no
value instead of 0 or a jump; a NIC without a target keeps its chart, a
pool volume disk is measured, and a disk or NIC attached after the page
loaded no longer stops the other charts. Disk rates are MB/s (they were
MiB/s labelled Mb/s), network Mbit/s; the CPU tooltip names the window.

instances/templates/instance.html

@@ -381,8 +381,13 @@
 <script src="{% static 'js/Chart.bundle.min.js' %}"></script>
 <script src="{% static 'js/poll.js' %}"></script>
 <script>
+    {% trans "average over" as average_over %}
     var stats_tab = document.querySelector('#graphics-tab');
     var stats_poll = null;
+    // the seconds each CPU point averages
+    var cpuWindows = [];
+    // the usage sample of the previous answer: the next one averages since then
+    var statsSample = null;
     // The charts are polled while the Stats tab is shown; they are made once.
     stats_tab.addEventListener('hidden.bs.tab', function (event) {
         stats_poll.stop();
@@ -436,7 +441,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;
                          }
                      }
                 }
@@ -530,7 +537,7 @@
                                 suggestedmax: 100,
                                 suggestedMin: 0,
                                 callback: function(value, index, values) {
-                                    return value + ' Mb/s';
+                                    return value + ' MB/s';
                                 }
                             },
                         }],
@@ -542,7 +549,7 @@
                                  if (label) {
                                     label += ': ';
                                  }
-                                 return label += tooltipItem.yLabel + ' Mb/s';
+                                 return label += tooltipItem.yLabel + ' MB/s';
                              }
                          }
                     }
@@ -608,14 +615,21 @@
             });
         {% endfor %}
 
-        stats_poll = pollWhileVisible(10000, function () {
-            return $.getJSON("{% url 'instances:stats' instance.id %}");
+        // the first point at once, then every 5 s like the host graph
+        stats_poll = pollWhileVisible(5000, function () {
+            return $.getJSON("{% url 'instances:stats' instance.id %}", statsSample ? {sample: statsSample} : {})
+                .fail(function () {
+                    statsSample = null;
+                });
         }, function graph_usage(data) {
+            statsSample = data.sample || null;
             cpuChart.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();
             }
             cpuChart.update();
 
@@ -629,32 +643,24 @@
             }
             memChart.update();
 
-            for (let j = 0; j < data.blkdata.length; j++) {
-                diskChart[data.blkdata[j].dev].data.labels.push(data.timeline);
-
-                diskChart[data.blkdata[j].dev].data.datasets[0].data.push(data.blkdata[j].data[0]);
-                diskChart[data.blkdata[j].dev].data.datasets[1].data.push(data.blkdata[j].data[1]);
-                if (diskChart[data.blkdata[j].dev].data.datasets[0].data.length > 10){
-                    diskChart[data.blkdata[j].dev].data.labels.shift();
-                    diskChart[data.blkdata[j].dev].data.datasets[0].data.shift();
-                    diskChart[data.blkdata[j].dev].data.datasets[1].data.shift();
+            // a disk or NIC added after the page loaded has no chart until a reload
+            function push(chart, values) {
+                if (!chart) {
+                    return;
                 }
-                diskChart[data.blkdata[j].dev].update();
-            }
-
-            for (let j = 0; j < data.netdata.length; j++) {
-                netChart[data.netdata[j].dev].data.labels.push(data.timeline);
-
-                netChart[data.netdata[j].dev].data.datasets[0].data.push(data.netdata[j].data[0]);
-                netChart[data.netdata[j].dev].data.datasets[1].data.push(data.netdata[j].data[1]);
-                if (netChart[data.netdata[j].dev].data.datasets[0].data.length > 10){
-                    netChart[data.netdata[j].dev].data.labels.shift();
-                    netChart[data.netdata[j].dev].data.datasets[0].data.shift();
-                    netChart[data.netdata[j].dev].data.datasets[1].data.shift();
+                chart.data.labels.push(data.timeline);
+                chart.data.datasets[0].data.push(values[0]);
+                chart.data.datasets[1].data.push(values[1]);
+                if (chart.data.datasets[0].data.length > 10){
+                    chart.data.labels.shift();
+                    chart.data.datasets[0].data.shift();
+                    chart.data.datasets[1].data.shift();
                 }
-                netChart[data.netdata[j].dev].update();
+                chart.update();
             }
-        });
+            data.blkdata.forEach(function (disk) { push(diskChart[disk.dev], disk.data); });
+            data.netdata.forEach(function (nic) { push(netChart[nic.dev], nic.data); });
+        }, 0);
     });
 </script>
 <script>

instances/test_stats_sample.py

@@ -0,0 +1,194 @@
+"""The VM stats: each answer carries a signed usage sample bound to the VM on
+its compute; the next poll sends it back so that the rates are averages since
+then, without waiting."""
+
+import json
+import re
+import shutil
+import subprocess
+import unittest
+from unittest.mock import patch
+
+import libvirt
+from computes.models import Compute
+from django.contrib.auth import get_user_model
+from django.core import signing
+from django.test import TestCase
+from django.urls import reverse
+from instances.models import Instance
+from vrtManager.instance import USAGE_MAX_WINDOW
+
+SAMPLE = {"key": [7, 4, ["vda"], [["52:54:00:00:00:01", "vnet0"]]], "counters": [1, [[2, 3]], [[4, 5]], 100.0]}
+
+
+class StatsViewTestCase(TestCase):
+    def setUp(self):
+        self.compute = Compute.objects.create(name="stats", hostname="192.0.2.1", login="u", password="p", type=1)
+        self.other_compute = Compute.objects.create(name="stats2", hostname="192.0.2.2", login="u", password="p", type=1)
+        uuid = "5d1b8a3e-0000-4000-8000-000000000001"
+        self.vm = Instance.objects.create(compute=self.compute, name="stats-vm", uuid=uuid)
+        self.other = Instance.objects.create(compute=self.compute, name="stats-vm2", uuid=uuid.replace("1", "2"))
+        self.client.force_login(get_user_model().objects.create_superuser("sv-admin", "sv@example.com", "pw"))
+        patcher = patch("instances.models.wvmInstance")
+        self.addCleanup(patcher.stop)
+        self.proxy = patcher.start().return_value
+        self.proxy.mem_usage.return_value = {"used": 1, "total": 2}
+        self.proxy.usage.return_value = {
+            "cpu": 12.345,
+            "disks": [{"dev": "vda", "rd": 2_000_000, "wr": None}],
+            "nics": [{"dev": 0, "rx": 8_000_000, "tx": 0}],
+            "window": 9.96,
+            "sample": SAMPLE,
+        }
+
+    def stats(self, vm=None, **params):
+        response = self.client.get(reverse("instances:stats", args=[(vm or self.vm).id]), params)
+        self.assertEqual(response.status_code, 200)
+        return json.loads(response.content)
+
+    def previous(self):
+        return self.proxy.usage.call_args.args[0]
+
+    def test_rates_in_mb_and_mbit_per_second_and_the_sample_round_trip(self):
+        data = self.stats()
+        self.assertIsNone(self.previous())
+        self.assertEqual((data["cpudata"], data["window"]), (12.3, 10.0))
+        self.assertEqual(data["blkdata"], [{"dev": "vda", "data": [2.0, None]}])
+        self.assertEqual(data["netdata"], [{"dev": 0, "data": [8.0, 0.0]}])
+        self.stats(sample=data["sample"])
+        self.assertEqual(self.previous(), SAMPLE)
+
+    def test_an_altered_old_or_foreign_sample_is_not_used(self):
+        token = self.stats()["sample"]
+        foreign = self.stats(self.other)["sample"]
+        altered = token[:-2] + ("xx" if not token.endswith("xx") else "yy")
+        for name, sample in (("altered", altered), ("garbage", "x"), ("other VM", foreign)):
+            with self.subTest(name):
+                self.stats(sample=sample)
+                self.assertIsNone(self.previous())
+        with patch("django.core.signing.time.time", return_value=signing.time.time() + USAGE_MAX_WINDOW + 1):
+            self.stats(sample=token)
+        self.assertIsNone(self.previous())
+
+    def test_a_sample_from_before_a_migration_is_not_used(self):
+        token = self.stats()["sample"]
+        Instance.objects.filter(pk=self.vm.pk).update(compute=self.other_compute)
+        self.stats(sample=token)
+        self.assertIsNone(self.previous())
+
+    def test_a_vm_that_is_not_running_gives_no_sample(self):
+        self.proxy.usage.return_value = {"cpu": 0, "disks": [], "nics": []}
+        data = self.stats()
+        self.assertEqual(data["cpudata"], 0)
+        self.assertNotIn("sample", data)
+        self.assertNotIn("window", data)
+
+
+# a VM with a disk and a NIC, on libvirt's test driver
+DOMAIN = """<domain type='test'><name>stats-script-vm</name><uuid>3c0e2b7a-91d4-4f5e-8a6b-0d2f4e6a8c10</uuid>
+<memory unit='MiB'>128</memory><vcpu>1</vcpu><os><type arch='i686'>hvm</type></os>
+<devices><disk type='file' device='disk'><source file='/default-pool/stats-script.img'/><target dev='vda' bus='virtio'/></disk>
+<interface type='network'><mac address='52:54:00:00:00:31'/><source network='default'/><model type='virtio'/></interface></devices>
+</domain>"""
+
+
+class TestDriverVM:
+    def setUp(self):
+        self.conn = libvirt.open("test:///default")
+        self.addCleanup(self.conn.close)
+        # the test host lives on while a libvirt object still refers to it
+        pool = self.conn.storagePoolLookupByName("default-pool")
+        if "stats-script.img" not in pool.listVolumes():
+            pool.createXML("<volume><name>stats-script.img</name><capacity>1048576</capacity></volume>", 0)
+        self.domain = self.conn.defineXML(DOMAIN)
+        compute = Compute.objects.create(name="ss", hostname="localhost", login="", password="", type=4)
+        self.vm = Instance.objects.create(compute=compute, name=self.domain.name(), uuid=self.domain.UUIDString())
+        self.client.force_login(get_user_model().objects.create_superuser("ss-admin", "ss@example.com", "pw"))
+        for target, value in (
+            ("vrtManager.connection.connection_manager.get_connection", self.conn),
+            ("vrtManager.connection.wvmConnect.get_machine_types", ["pc"]),
+            ("vrtManager.connection.wvmConnect.get_nwfilters", []),
+        ):
+            patcher = patch(target, return_value=value)
+            patcher.start()
+            self.addCleanup(patcher.stop)
+
+
+class SampleRoundTripTestCase(TestDriverVM, TestCase):
+    def test_a_real_sample_is_used_by_the_next_poll(self):
+        self.domain.create()
+        self.addCleanup(self.domain.destroy)
+        url = reverse("instances:stats", args=[self.vm.id])
+        with patch("vrtManager.instance.time.sleep") as sleep:
+            first = json.loads(self.client.get(url).content)
+            sleep.assert_called_once_with(1)
+            sleep.reset_mock()
+            second = json.loads(self.client.get(url, {"sample": first["sample"]}).content)
+        sleep.assert_not_called()
+        self.assertEqual([disk["dev"] for disk in second["blkdata"]], ["vda"])
+        self.assertIn("sample", second)
+
+
+@unittest.skipUnless(shutil.which("node"), "node is not installed")
+class StatsScriptTestCase(TestDriverVM, TestCase):
+    """The VM page's script sends each answer's sample with the next poll and
+    drops it after a failed one."""
+
+    def page(self):
+        response = self.client.get(reverse("instances:instance", args=[self.vm.id]))
+        self.assertEqual(response.status_code, 200)
+        return response.content.decode()
+
+    def test_the_next_poll_sends_the_previous_sample(self):
+        script = next(s for s in re.findall(r"<script>(.*?)</script>", self.page(), re.S) if "statsSample" in s)
+        js = """
+        const vm = require("vm");
+        const charts = [], requests = [], handlers = {};
+        let poll, fail = false;
+        const canvas = {get: () => ({getContext: () => ({})})};
+        const $ = () => canvas;
+        $.getJSON = (url, params) => {
+            requests.push(params);
+            return {fail: (callback) => { if (fail) callback(); return {}; }};
+        };
+        const page = {
+            $,
+            document: {querySelector: () => ({addEventListener: (name, handler) => { handlers[name] = handler; }})},
+            // 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);
+            },
+            pollWhileVisible: (interval, request, onData, first) => { poll = {interval, first, request, onData}; return {}; },
+        };
+        vm.runInNewContext(SCRIPT, vm.createContext(page));
+        handlers["shown.bs.tab"]();
+        const answer = (cpu, sample) => ({cpudata: cpu, window: 9.9, sample: sample, timeline: "t",
+                                          memdata: {used: 0, total: 1024},
+                                          // vdb was attached after the page loaded
+                                          blkdata: [{dev: "vdb", data: [9, 9]}, {dev: "vda", data: [1.5, null]}],
+                                          netdata: [{dev: 0, data: [2, 3]}]});
+        poll.request();
+        poll.onData(answer(3, "token-1"));
+        poll.request();
+        fail = true;
+        poll.request();
+        fail = false;
+        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, every: [poll.interval, poll.first], cpu: charts[0].data.datasets[0].data,
+                                    disk: charts[2].data.datasets[1].data, net: charts[3].data.datasets[0].data}));
+        """.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)
+        # the first poll at once, then every 5 s
+        self.assertEqual(result["every"], [5000, 0])
+        # the sample goes with the next poll; a failed poll drops it
+        self.assertEqual(result["requests"], [{}, {"sample": "token-1"}, {"sample": "token-1"}, {}])
+        # a disk without a chart is skipped, the other charts still update
+        self.assertEqual((result["cpu"], result["disk"], result["net"]), ([3], [None], [2]))
+        self.assertTrue(result["label"].endswith(": 3 % (average over 9.9 s)"), result["label"])

instances/views.py

@@ -22,6 +22,7 @@ from django.conf import settings
 from django.contrib import messages
 from django.contrib.auth.decorators import permission_required
 from django.contrib.auth.models import User
+from django.core import signing
 from django.core.exceptions import PermissionDenied, ValidationError
 from django.http import Http404, HttpResponse, JsonResponse
 from django.db.models import prefetch_related_objects
@@ -41,7 +42,7 @@ from logs.views import addlogmsg
 from webvirtcloud.middleware import error_text
 from vrtManager import util
 from vrtManager.create import wvmCreate
-from vrtManager.instance import wvmInstances
+from vrtManager.instance import USAGE_MAX_WINDOW, wvmInstances
 from vrtManager.interface import wvmInterface
 from vrtManager.storage import wvmStorage
 from vrtManager.util import randomPasswd
@@ -54,6 +55,8 @@ from .models import Flavor
 
 # the VM page waits this long (seconds) for the compute's drbdadm status
 DRBD_STATUS_TIMEOUT = 10
+# the stats tab sends the sample of each answer back with its next poll
+STATS_SAMPLE_SIGNER = signing.TimestampSigner(salt="instances.stats-sample")
 
 
 def index(request):
@@ -269,41 +272,42 @@ def drbd_status(request, pk):
     return result
 
 
+def _stats_sample(instance, token):
+    """The usage sample in a token of this VM's stats on its current compute,
+    or None when there is none, it is altered or too old."""
+    if not token:
+        return None
+    try:
+        data = STATS_SAMPLE_SIGNER.unsign_object(token, max_age=USAGE_MAX_WINDOW)
+    except signing.BadSignature:
+        return None
+    if data.get("vm") != [instance.id, instance.compute_id, instance.uuid]:
+        return None
+    return data["sample"]
+
+
 def stats(request, pk):
     instance = get_instance(request.user, pk)
-    json_blk = []
-    json_net = []
-
-    # TODO: stats are inaccurate
-    cpu_usage, blk_usage, net_usage = instance.proxy.usage()
+    usage = instance.proxy.usage(_stats_sample(instance, request.GET.get("sample")))
     mem_usage = instance.proxy.mem_usage()
 
-    current_time = time.strftime("%H:%M:%S")
-    for blk in blk_usage:
-        json_blk.append(
-            {
-                "dev": blk["dev"],
-                "data": [int(blk["rd"]) / 1048576, int(blk["wr"]) / 1048576],
-            }
-        )
+    def mega(value):
+        return None if value is None else value / 10**6
 
-    for net in net_usage:
-        json_net.append(
-            {
-                "dev": net["dev"],
-                "data": [int(net["rx"]) / 1048576, int(net["tx"]) / 1048576],
-            }
+    result = {
+        "cpudata": None if usage["cpu"] is None else round(usage["cpu"], 1),
+        "memdata": mem_usage,
+        # MB/s and Mbit/s
+        "blkdata": [{"dev": disk["dev"], "data": [mega(disk["rd"]), mega(disk["wr"])]} for disk in usage["disks"]],
+        "netdata": [{"dev": nic["dev"], "data": [mega(nic["rx"]), mega(nic["tx"])]} for nic in usage["nics"]],
+        "timeline": time.strftime("%H:%M:%S"),
+    }
+    if "sample" in usage:
+        result["window"] = None if usage["window"] is None else round(usage["window"], 1)
+        result["sample"] = STATS_SAMPLE_SIGNER.sign_object(
+            {"vm": [instance.id, instance.compute_id, instance.uuid], "sample": usage["sample"]}, compress=True
         )
-
-    return JsonResponse(
-        {
-            "cpudata": int(cpu_usage["cpu"]),
-            "memdata": mem_usage,
-            "blkdata": json_blk,
-            "netdata": json_net,
-            "timeline": current_time,
-        }
-    )
+    return JsonResponse(result)
 
 
 def osinfo(request, pk):