Performance measurement framework

.devcontainer/devcontainer.json

@@ -15,6 +15,8 @@
 		"ms-azuretools.vscode-docker",
 		"ms-vscode.cpptools-extension-pack",
 		"eamodio.gitlens",
+		"ms-python.python",
+		"MS-vsliveshare.vsliveshare",
 	],
 
 	// allow access to the toradex board

.vscode/tasks.json

@@ -31,7 +31,7 @@
       {
         "label": "Build and Run Toradex",
         "type": "shell",
-        "command": "cd ${BFBUILD} && make -j7 imx8x && make usbboot_imx8x | tee ${BFBUILD}/full_output.log",
+        "command": "cd ${BFBUILD} && make -j7 imx8x && make usbboot_imx8x",
         "group": {
           "kind": "build",
           "isDefault": true
@@ -40,7 +40,7 @@
       {
         "label": "Toradex Console",
         "type": "shell",
-        "command": "if ! picocom -b 115200 -f n /dev/ttyUSB0; then echo; echo !!!Make sure you installed the toradex udev rules to allow user access!!!; fi",
+        "command": "if ! picocom -b 115200 -f n /dev/ttyUSB0 | tee ${BFBUILD}/full_output.log; then echo; echo !!!Make sure you installed the toradex udev rules to allow user access!!!; fi",
         "group": {
           "kind": "build",
           "isDefault": true

include/aos/performance.h

@@ -0,0 +1,27 @@
+#ifndef LIBBARRELFISH_PERFORMANCE_H
+#define LIBBARRELFISH_PERFORMANCE_H
+
+#include <unistd.h>
+
+#define PERFORMANCE_MEASUREMENT_COUNT_MAX 10
+
+// uncomment to enable performance measurements
+// #define PERFORMANCE_ENABLED
+
+struct measurement {
+    char *tag;
+    systime_t timestamp;
+};
+
+struct performance_context {
+    size_t count;
+    char *name;
+    struct measurement measurements[PERFORMANCE_MEASUREMENT_COUNT_MAX];
+};
+
+void perf_init(struct performance_context *c, char *name);
+void perf_add_measurement(struct performance_context *c, char *tag, systime_t timestamp);
+void perf_add_now(struct performance_context *c, char *tag);
+void perf_print(struct performance_context *c);
+
+#endif // LIBBARRELFISH_PERFORMANCE_H

lib/aos/Hakefile

@@ -25,6 +25,7 @@
                              "slot_alloc/twolevel_slot_alloc.c",
                              "aos_rpc.c",
                              "aos_urpc.c",
+                             "performance.c",
                              "capabilities.c",
                              "coreset.c",
                              "coreboot.c",

lib/aos/aos_urpc.c

@@ -18,6 +18,7 @@
 #include <aos/aos_rpc.h>
 #include <spawn/rpc_server.h>
 #include <aos/deferred.h>
+#include <aos/performance.h>
 
 extern coreid_t my_core_id;
 extern rpc_handler_t rpc_handlers[RPC_MTYPE_COUNT];
@@ -167,7 +168,7 @@ errval_t aos_urpc_get_bootinfo(struct aos_urpc * rpc, struct bootinfo_serialized
     return SYS_ERR_OK;
 }
 
-
+struct performance_context p;
 int urpc_server(void *arg) {
     struct aos_urpc_server *urpc = arg;
     struct waitset *default_ws = get_default_waitset();
@@ -180,7 +181,8 @@ int urpc_server(void *arg) {
         // wait until an rpc call arrives
         while(urpc->meta->call_in_progress == false) {
             // sleep for a bit while there is nothing to do
-            barrelfish_usleep(100);
+            // barrelfish_usleep(100);
+            thread_yield();
         }
 
         // memory barrier
@@ -188,10 +190,29 @@ int urpc_server(void *arg) {
             "dmb sy\n"
         );
 
+#ifdef PERFORMANCE_ENABLED
+        bool type_nop = urpc->meta->a0 == RPC_MTYPE_NOP;
+        if(type_nop) {
+            perf_init(&p, "aos_urpc_server");
+            perf_add_now(&p, "start");
+        }
+#endif
+
         // handle the URPC on the same thread that handles regular RPCs, to avoid concurrency for the handlers
         waitset_chan_trigger_closure(default_ws, &chan, MKCLOSURE(urpc_server_handler, urpc));
 
+#ifdef PERFORMANCE_ENABLED
+        perf_add_now(&p, "triggered_closure");
+#endif
+        
         // wait until the rpc is handled
         thread_sem_wait(&urpc->sem);
+
+#ifdef PERFORMANCE_ENABLED
+        if(type_nop) {
+            perf_add_now(&p, "done");
+            perf_print(&p);
+        }
+#endif
     }
 }

lib/aos/performance.c

@@ -0,0 +1,33 @@
+#include <aos/debug.h>
+#include <aos/performance.h>
+#include <aos/systime.h>
+#include <string.h>
+
+void perf_init(struct performance_context *c, char *name) {
+    c->count = 0;
+    c->name = name;
+    memset(c->measurements, 0, sizeof(c->measurements));
+}
+
+inline void perf_add_measurement(struct performance_context *c, char *tag, systime_t timestamp)
+{
+    c->measurements[c->count].tag = tag;
+    c->measurements[c->count].timestamp = timestamp;
+    c->count++;
+    __asm volatile (
+        "dmb sy\n"
+    );
+}
+
+inline void perf_add_now(struct performance_context *c, char *tag)
+{
+    systime_t now = systime_now();
+    perf_add_measurement(c, tag, now);
+}
+
+void perf_print(struct performance_context *c)
+{
+    for (size_t i = 0; i < c->count; i++) {
+        debug_printf("MEASUREMENT %s:%s %lu\n", c->name, c->measurements[i].tag, c->measurements[i].timestamp);
+    }
+}

performance/.gitignore

@@ -0,0 +1 @@
+venv

performance/performance_evaluation.py

@@ -0,0 +1,109 @@
+#/bin/env python3
+from distutils.log import error
+from statistics import mean, median
+import sys
+from matplotlib import pyplot as p
+from mailbox import linesep
+import os
+import re
+
+from numpy import std
+
+MEASUREMENT_TAG = "MEASUREMENT"
+# searches for a measurement with #1 name, #2 tag, #3 time
+MEASUREMENT_REGEX = r"^.* " + MEASUREMENT_TAG + r" ([a-zA-Z_:-]*) ([0-9]*)$"
+
+# TODO change this for the actual measurement
+# data_basedir = os.environ.get("BFBUILD_QEMU")
+data_basedir = os.environ.get("BFBUILD")
+data_file = os.path.join(data_basedir, "full_output.log")
+out_dir = os.path.join(os.path.dirname(sys.argv[0]), "plots")
+
+def extract_measurement(line):
+    match = re.match(MEASUREMENT_REGEX, line)
+    if not match:
+        print(f"[ERROR] Malformed measurement: '{line}'")
+        exit(1)
+    return {
+        "tag": match.group(1),
+        "timestamp": int(match.group(2)),
+    }
+
+def extract_measurements(lines):
+    filtered = filter(lambda l: MEASUREMENT_TAG in l, lines)
+    return list(map(extract_measurement, filtered))
+
+def read_data(file):
+    with open(file) as f:
+        return f.readlines()
+        
+def build_dataseries(measurements, start_tag, end_tag):
+    datapoints = []
+
+    started_at = None
+    for m in measurements:
+        if started_at is None:
+            if m["tag"] == start_tag:
+                started_at = m["timestamp"]
+        else:
+            if m["tag"] == end_tag:
+                datapoints.append(m["timestamp"] - started_at)
+                started_at = None
+            elif m["tag"] == start_tag:
+                print("[ERROR] Invalid sequence, ignoring last start tag")
+                started_at = m["timestamp"]
+    
+    return datapoints
+
+
+def main():
+    raw_log = read_data(data_file)
+
+    measurements = extract_measurements(raw_log)
+    measurements.sort(key=lambda m: m["timestamp"])
+
+    dataset = {}
+
+    dataset["performance"] = build_dataseries(measurements, "aos_performance:start", "aos_performance:done")
+
+    dataset["client_to_server"] = build_dataseries(measurements, "aos_urpc_nop:start", "aos_urpc_server:start")
+    dataset["server_schedule_task"] = build_dataseries(measurements, "aos_urpc_server:start", "aos_urpc_server:triggered_closure")
+    dataset["server_completed_task"] = build_dataseries(measurements, "aos_urpc_server:triggered_closure", "aos_urpc_server:done")
+    dataset["server_to_client"] = build_dataseries(measurements, "aos_urpc_server:done", "aos_urpc_nop:done")
+
+    # calculate stats for each data series
+    metrics = {}
+    for key in dataset:
+        # d_mean = mean(dataset[key])
+        d_std = std(dataset[key])
+        d_median = median(dataset[key])
+        metrics[key] = (d_median, d_std)
+
+    # create output directory
+    os.makedirs(out_dir, exist_ok=True)
+
+    # create plots for data series
+    for key in dataset:
+        d = dataset[key]
+        d.sort()
+        p.clf()
+        p.title(key)
+        p.xlabel("datapoint index")
+        p.ylabel("duration (cycles)")
+        p.scatter(range(len(d)), d)
+        p.savefig(os.path.join(out_dir, f"{key}.jpg"))
+    
+    p.clf()
+    fig, ax = p.subplots(figsize=(12,5))
+    p.title("Metrics")
+    p.ylabel("median duration (cycles)")
+    p.bar(
+        metrics.keys(), 
+        [x[0] for x in metrics.values()], 
+        yerr=[x[1] for x in metrics.values()],
+    )
+    ax.set_ylim(0)
+    p.savefig(os.path.join(out_dir, "metrics.jpg"))
+
+if __name__ == "__main__":
+    main()

performance/requirements.txt

@@ -0,0 +1 @@
+matplotlib

usr/init/main.c

@@ -30,7 +30,8 @@
 #include <aos/kernel_cap_invocations.h>
 
 #include <barrelfish_kpi/startup_arm.h>
-
+#include <aos/performance.h>
+#include <aos/deferred.h>
 
 struct bootinfo *bi;
 
@@ -247,6 +248,28 @@ app_main(int argc, char *argv[]) {
 
     ram_alloc_set(ram_alloc_remote_core);
 
+#ifdef PERFORMANCE_ENABLED
+    barrelfish_usleep(2000000);
+
+    struct performance_context p;
+    // measure performance measurement performance
+    for(size_t i = 0; i < 1000; ++i) {
+        perf_init(&p, "aos_performance");
+        perf_add_now(&p, "start");
+        perf_add_now(&p, "done");
+        perf_print(&p);
+    }
+
+    // measure URPC performance
+    for(size_t i = 0; i < 1000; ++i) {
+        perf_init(&p, "aos_urpc_nop");
+        perf_add_now(&p, "start");
+        do_aos_urpc(&urpc_to_bsp, RPC_MTYPE_NOP, NULL_CAP, 0, 0, 0, NULL, NULL, NULL, NULL);
+        perf_add_now(&p, "done");
+        perf_print(&p);
+    }
+#endif
+
     // Allocate all pages of the thread stack now.
     // We can't have page faults while the thread is running,
     // because URPC calls may only be done from the main thread.