add the boot time performance test

The boot time test will fail if the boot time is under 0.15s.

Boot time is measured with the following approach:
1. Statically compile a C program that reads the current time, writes it
   to a timestamp log file, and exists.
2. Set up a microvm with a rootfs that has this program as `/sbin/init`
3. The the boot time test, record a timestamp before the API command
   that starts the microVM.
4. Later, extract the timestamp log from the microMVs rootfs.
5. Get the elapsed time as the difference between the two timestamps.

Note: The boot time threshold is now 0.35s, since we boot in 0.3s. This
      should be 0.15s (investigation ongoing).

Signed-off-by: Radu Weiss <[email protected]>

tests/performance/test_boottime.py

@@ -0,0 +1,121 @@
+"""
+Tests that ensure the boot time to init process is within spec.
+
+# TODO
+
+- Get the minimum acceptable boot time from the `spec.firecracker` s3 bucket.
+  Also set the current boot time if we're running as part of a continuous
+  integration merge operation.
+"""
+
+import os
+import re
+from subprocess import run
+import time
+
+import pytest
+
+
+@pytest.mark.timeout(240)
+def test_microvm_boottime(test_microvm_with_boottime):
+    """
+    Asserts that we meet the minimum boot time. Microvms with the boottimer
+    capability should use a kernel config customized for quick booting within
+    Firecracker.
+    """
+
+    MIN_BOOT_TIME = 0.35
+    """ The minimum acceptable boot time. """
+    # TODO: This needs to be 0.15, is currently ~0.3 (investigation ongoing).
+    # TODO: Get the minimum acceptable boot time from the `spec.firecracker` s3
+    #       bucket. Also set the current boot time if we're running as part of
+    #       continuous integration merge operation.
+
+    BOOTTIME_INIT_PROGRAM = 'test_boottime_init.c'
+    """
+    This program saves an accurate timestamp to disk and exists. It will be
+    compiled statically and copied into the guest root file system as the init
+    program.
+    """
+
+    TIMESTAMP_LOG_FILE = 'timestamp.log'
+    """ The timestamp log file within the microvm root file system. """
+
+    TIMESTAMP_LOG_REGEX = r'^\[(\d+\.\d+)\]\ init\ executed'
+    """ Regex for extracting timestamp data from a the boot time log. """
+
+    test_microvm = test_microvm_with_boottime
+    test_microvm.basic_config()
+
+    response = test_microvm.api_session.put(
+        test_microvm.blk_cfg_url + '/timer_rootfs',
+        json={
+            'drive_id': 'timer_rootfs',
+            'path_on_host': test_microvm.slot.make_fsfile(name='timer_rootfs'),
+            'is_root_device': True,
+            'permissions': 'rw',
+            'state': 'Attached'
+        }
+    )
+    """ Create a new empty root file system and attach it. """
+    assert(test_microvm.api_session.is_good_response(response.status_code))
+
+    init_binary = test_microvm.slot.path + 'init'
+    run(
+        'gcc -static -O3 {boottime_init_program} -o {binary_path}'.format(
+            binary_path=init_binary,
+            boottime_init_program=(
+                os.path.dirname(os.path.abspath(__file__)) + '/' +
+                BOOTTIME_INIT_PROGRAM
+            )
+        ),
+        shell=True,
+        check=True
+    )
+    """ Compile the timer program as a binary named `init`. """
+
+    test_microvm.slot.fsfiles['timer_rootfs'].copy_to(init_binary, 'sbin/')
+    """ Copy the init program to the root file system. """
+
+    response = test_microvm.api_session.put(
+        test_microvm.actions_url + '/1',
+        json={'action_id': '1', 'action_type': 'InstanceStart'}
+    )
+    """ Issues a power-on command to the microvm. """
+
+    boot_start_time_realtime = time.clock_gettime(time.CLOCK_REALTIME)
+
+    assert(test_microvm.api_session.is_good_response(response.status_code))
+
+    """ Starts the boot timer. """
+
+    time.sleep(1)
+    response = test_microvm.api_session.get(
+        test_microvm.actions_url + '/1'
+    )
+    assert(test_microvm.api_session.is_good_response(response.status_code))
+
+    try:
+        test_microvm.slot.fsfiles['timer_rootfs'].copy_from(
+            TIMESTAMP_LOG_FILE,
+            test_microvm.slot.path
+        )
+        """ Retrieves the guest OS boot timestamp. """
+    except:
+        print("Could not get timestamp log (after 1 second).")
+        raise
+    """
+    If the microvm doesn't boot and print a timestamp within 1 second, it's
+    all in vain anyway ...
+    """
+
+    with open(test_microvm.slot.path + TIMESTAMP_LOG_FILE) as timestamp_log:
+        timestamps = re.findall(TIMESTAMP_LOG_REGEX, timestamp_log.read())
+        boot_end_time_realtime = float(timestamps[0])
+
+    boot_time_realtime = boot_end_time_realtime - boot_start_time_realtime
+
+    print("Boot time: " + str(round(boot_time_realtime * 1000)) + "ms")
+    # Print this to the test session output until we have s3 upload.
+
+    assert(boot_time_realtime < MIN_BOOT_TIME)

tests/performance/test_boottime_init.c

@@ -0,0 +1,38 @@
+/* This program is meant to be compiled statically, and run as the init process
+ * in a Guest OS as part of a boottime timing. The boottime test will records
+ * a timestamp before issuing the microvm power-on command, and this program
+ * records another timestamp as the 1st user-space instruction, then writes it
+ * to a log for the boottime test to retrieve.
+ */
+
+#include <sys/io.h>
+#include <stdio.h>
+#include <time.h>
+#include <unistd.h>
+
+#define TIMESTAMP_LOG_FILE "/timestamp.log"
+// Should match the one in `test_boottime.py`
+
+#define TIMESTAMP_LOG_LINE "[%ld.%ld] init executed.\n"
+// Will be parsed by the TIMESTAMP_LOG_REGEX regex in `test_boottime.py`
+
+int main(int argc, char **argv) {
+    struct timespec moment_realtime;
+    clock_gettime(CLOCK_REALTIME, &moment_realtime);
+    // Records this moment in time.
+
+    FILE *timestamp_log;
+    timestamp_log = fopen(TIMESTAMP_LOG_FILE, "w");
+    fprintf(
+        timestamp_log,
+        TIMESTAMP_LOG_LINE,
+        moment_realtime.tv_sec,
+        moment_realtime.tv_nsec
+    );
+    fclose(timestamp_log);
+    sync();
+    // Saves timestamp to file, which can then be read by the host test.
+
+    return 0;
+    // Used in a Linux init process, this triggers system shutdown.
+}