--- appliance/init | 30 +++++++++++++++--------------- 1 file changed, 15 insertions(+), 15 deletions(-) diff --git a/appliance/init b/appliance/init index f4f6333..5d43c71 100755 --- a/appliance/init +++ b/appliance/init @@ -75,21 +75,6 @@ $UDEVD --daemon #--debug udevadm trigger udevadm settle --timeout=600 -if grep -sq selinux=1 /proc/cmdline; then - mount -t selinuxfs none /sys/fs/selinux -fi - -# Disk optimizations. -# Increase the SCSI timeout so we can read remote images. -shopt -s nullglob -for f in /sys/block/sd*/device/timeout; do echo 300 > $f; done -# https://access.redhat.com/site/solutions/5427 -for f in /sys/block/{h,s,ub,v}d*/queue/scheduler; do echo noop > $f; done -shopt -u nullglob - -# Update the system clock. -hwclock -u -s - # Parse the kernel command line. if grep -sq guestfs_verbose=1 /proc/cmdline; then guestfs_verbose=1 @@ -106,6 +91,21 @@ if grep -sq guestfs_noreboot=1 /proc/cmdline; then fi eval `grep -Eo 'guestfs_channel=[^[:space:]]+' /proc/cmdline` +if grep -sq selinux=1 /proc/cmdline; then + mount -t selinuxfs none /sys/fs/selinux +fi + +# Disk optimizations. +# Increase the SCSI timeout so we can read remote images. +shopt -s nullglob +for f in /sys/block/sd*/device/timeout; do echo 300 > $f; done +# https://access.redhat.com/site/solutions/5427 +for f in /sys/block/{h,s,ub,v}d*/queue/scheduler; do echo noop > $f; done +shopt -u nullglob + +# Update the system clock. +hwclock -u -s + # Set up the network. ip addr add 127.0.0.1/8 brd + dev lo scope host ip link set dev lo up -- 2.7.4

We're never going to use virtio-console since, although it is faster, it's not available during early boot, and that is more important for debugging. --- src/launch-direct.c | 12 +----------- 1 file changed, 1 insertion(+), 11 deletions(-) diff --git a/src/launch-direct.c b/src/launch-direct.c index a81d4b3..e8450e1 100644 --- a/src/launch-direct.c +++ b/src/launch-direct.c @@ -574,19 +574,9 @@ launch_direct (guestfs_h *g, void *datav, const char *arg) ADD_CMDLINE ("-device"); ADD_CMDLINE (VIRTIO_SERIAL); -#if 0 - /* Use virtio-console (a variant form of virtio-serial) for the - * guest's serial console. - */ - ADD_CMDLINE ("-chardev"); - ADD_CMDLINE ("stdio,id=console"); - ADD_CMDLINE ("-device"); - ADD_CMDLINE ("virtconsole,chardev=console,name=org.libguestfs.console.0"); -#else - /* When the above works ... until then: */ + /* Create the serial console. */ ADD_CMDLINE ("-serial"); ADD_CMDLINE ("stdio"); -#endif if (qemu_supports_device (g, data, "Serial Graphics Adapter")) { /* Use sgabios instead of vgabios. This means we'll see BIOS -- 2.7.4

This tedious workaround avoids a 0.26 second pause when using sgabios (the Serial Graphics Adapter). It's basically a workaround for buggy code in sgabios, but much easier than fixing the assembler. --- src/conn-socket.c | 32 +++++++++++++++++++++++++++++++- 1 file changed, 31 insertions(+), 1 deletion(-) diff --git a/src/conn-socket.c b/src/conn-socket.c index 5b6b80e..13cb39b 100644 --- a/src/conn-socket.c +++ b/src/conn-socket.c @@ -33,6 +33,8 @@ #include <assert.h> #include <libintl.h> +#include "ignore-value.h" + #include "guestfs.h" #include "guestfs-internal.h" @@ -314,6 +316,9 @@ handle_log_message (guestfs_h *g, { CLEANUP_FREE char *buf = safe_malloc (g, BUFSIZ); ssize_t n; + const char dsr_request[] = "\033[6n"; + const char dsr_reply[] = "\033[24;80R"; + const char dsr_reply_padding[] = "\b\b\b\b\b\b\b\b\b\b\b\b\b\b\b\b"; /* Carried over from ancient proto.c code. The comment there was: * @@ -341,7 +346,32 @@ handle_log_message (guestfs_h *g, return -1; } - /* It's an actual log message, send it upwards. */ + /* It's an actual log message. */ + + /* SGABIOS tries to query the "serial console" for its size using the + * ISO/IEC 6429 Device Status Report (ESC [ 6 n). If it doesn't + * read anything back, then it unfortunately hangs for 0.26 seconds. + * Therefore we detect this situation and send back a fake console + * size. + */ + if (memmem (buf, n, dsr_request, sizeof dsr_request - 1) != NULL) { + /* Ignore any error from this write, as it's just an optimization. + * We can't even be sure that console_sock is a socket or that + * it's writable. + */ + ignore_value (write (conn->console_sock, dsr_reply, + sizeof dsr_reply - 1)); + /* Additionally, because of a bug in sgabios, it will still pause + * unless you write at least 14 bytes, so we have to pad the + * reply. We can't pad with NULs since sgabios's input routine + * ignores these, so we have to use some other safe padding + * characters. Backspace seems innocuous. + */ + ignore_value (write (conn->console_sock, dsr_reply_padding, + sizeof dsr_reply_padding - 1)); + } + + /* Send it upwards. */ guestfs_int_log_message_callback (g, buf, n); return 1; -- 2.7.4

Just code motion. In theory we could also add earlyprintk=ttyS0,115200 on x86, but I cannot get it to work. --- src/launch.c | 11 +++++++++-- 1 file changed, 9 insertions(+), 2 deletions(-) diff --git a/src/launch.c b/src/launch.c index 074ac6f..886041a 100644 --- a/src/launch.c +++ b/src/launch.c @@ -303,6 +303,12 @@ guestfs_impl_config (guestfs_h *g, #define SERIAL_CONSOLE "console=ttyS0" #endif +#if defined(__aarch64__) +#define EARLYPRINTK " earlyprintk=pl011,0x9000000" +#else +#define EARLYPRINTK "" +#endif + char * guestfs_int_appliance_command_line (guestfs_h *g, const char *appliance_dev, int flags) @@ -331,9 +337,10 @@ guestfs_int_appliance_command_line (guestfs_h *g, const char *appliance_dev, #ifdef __i386__ " noapic" /* workaround for RHBZ#857026 */ #endif - " " SERIAL_CONSOLE /* serial console */ + " " SERIAL_CONSOLE /* serial console */ + EARLYPRINTK /* get messages from early boot */ #ifdef __aarch64__ - " earlyprintk=pl011,0x9000000 ignore_loglevel" + " ignore_loglevel" /* This option turns off the EFI RTC device. QEMU VMs don't * currently provide EFI, and if the device is compiled in it * will try to call the EFI function GetTime unconditionally -- 2.7.4

Dr. David Gilbert pointed out to me that the first line of the qemu -help output includes the qemu version, so we don't need to run qemu -version at all. This saves about 0.04s on the launch time when using the direct backend. --- src/launch-direct.c | 54 +++++++++++++++++++---------------------------------- 1 file changed, 19 insertions(+), 35 deletions(-) diff --git a/src/launch-direct.c b/src/launch-direct.c index e8450e1..25b0349 100644 --- a/src/launch-direct.c +++ b/src/launch-direct.c @@ -54,7 +54,6 @@ struct backend_direct_data { pid_t recoverypid; /* Recovery process PID. */ char *qemu_help; /* Output of qemu -help. */ - char *qemu_version; /* Output of qemu -version. */ char *qemu_devices; /* Output of qemu -device ? */ /* qemu version (0, 0 if unable to parse). */ @@ -931,22 +930,18 @@ print_qemu_command_line (guestfs_h *g, char **argv) static void parse_qemu_version (guestfs_h *g, struct backend_direct_data *data); static void read_all (guestfs_h *g, void *retv, const char *buf, size_t len); -/* Test qemu binary (or wrapper) runs, and do 'qemu -help' and - * 'qemu -version' so we know what options this qemu supports and - * the version. +/* Test qemu binary (or wrapper) runs, and do 'qemu -help' so we know + * the version of qemu what options this qemu supports. */ static int test_qemu (guestfs_h *g, struct backend_direct_data *data) { CLEANUP_CMD_CLOSE struct command *cmd1 = guestfs_int_new_command (g); CLEANUP_CMD_CLOSE struct command *cmd2 = guestfs_int_new_command (g); - CLEANUP_CMD_CLOSE struct command *cmd3 = guestfs_int_new_command (g); int r; free (data->qemu_help); data->qemu_help = NULL; - free (data->qemu_version); - data->qemu_version = NULL; free (data->qemu_devices); data->qemu_devices = NULL; @@ -960,34 +955,24 @@ test_qemu (guestfs_h *g, struct backend_direct_data *data) if (r == -1 || !WIFEXITED (r) || WEXITSTATUS (r) != 0) goto error; + parse_qemu_version (g, data); + guestfs_int_cmd_add_arg (cmd2, g->hv); guestfs_int_cmd_add_arg (cmd2, "-display"); guestfs_int_cmd_add_arg (cmd2, "none"); - guestfs_int_cmd_add_arg (cmd2, "-version"); - guestfs_int_cmd_set_stdout_callback (cmd2, read_all, &data->qemu_version, - CMD_STDOUT_FLAG_WHOLE_BUFFER); - r = guestfs_int_cmd_run (cmd2); - if (r == -1 || !WIFEXITED (r) || WEXITSTATUS (r) != 0) - goto error; - - parse_qemu_version (g, data); - - guestfs_int_cmd_add_arg (cmd3, g->hv); - guestfs_int_cmd_add_arg (cmd3, "-display"); - guestfs_int_cmd_add_arg (cmd3, "none"); - guestfs_int_cmd_add_arg (cmd3, "-machine"); - guestfs_int_cmd_add_arg (cmd3, + guestfs_int_cmd_add_arg (cmd2, "-machine"); + guestfs_int_cmd_add_arg (cmd2, #ifdef MACHINE_TYPE MACHINE_TYPE "," #endif "accel=kvm:tcg"); - guestfs_int_cmd_add_arg (cmd3, "-device"); - guestfs_int_cmd_add_arg (cmd3, "?"); - guestfs_int_cmd_clear_capture_errors (cmd3); - guestfs_int_cmd_set_stderr_to_stdout (cmd3); - guestfs_int_cmd_set_stdout_callback (cmd3, read_all, &data->qemu_devices, + guestfs_int_cmd_add_arg (cmd2, "-device"); + guestfs_int_cmd_add_arg (cmd2, "?"); + guestfs_int_cmd_clear_capture_errors (cmd2); + guestfs_int_cmd_set_stderr_to_stdout (cmd2); + guestfs_int_cmd_set_stdout_callback (cmd2, read_all, &data->qemu_devices, CMD_STDOUT_FLAG_WHOLE_BUFFER); - r = guestfs_int_cmd_run (cmd3); + r = guestfs_int_cmd_run (cmd2); if (r == -1 || !WIFEXITED (r) || WEXITSTATUS (r) != 0) goto error; @@ -1001,8 +986,9 @@ test_qemu (guestfs_h *g, struct backend_direct_data *data) return -1; } -/* Parse data->qemu_version (if not NULL) into the major and minor - * version of qemu, but don't fail if parsing is not possible. +/* Parse the first line of data->qemu_help (if not NULL) into the + * major and minor version of qemu, but don't fail if parsing is not + * possible. */ static void parse_qemu_version (guestfs_h *g, struct backend_direct_data *data) @@ -1013,13 +999,13 @@ parse_qemu_version (guestfs_h *g, struct backend_direct_data *data) data->qemu_version_major = 0; data->qemu_version_minor = 0; - if (!data->qemu_version) + if (!data->qemu_help) return; - if (!match2 (g, data->qemu_version, re_major_minor, &major_s, &minor_s)) { + if (!match2 (g, data->qemu_help, re_major_minor, &major_s, &minor_s)) { parse_failed: - debug (g, "%s: failed to parse qemu version string '%s'", - __func__, data->qemu_version); + debug (g, "%s: failed to parse qemu version string from the first line of the output of '%s -help'. When reporting this bug please include the -help output.", + __func__, g->hv); return; } @@ -1508,8 +1494,6 @@ shutdown_direct (guestfs_h *g, void *datav, int check_for_errors) free (data->qemu_help); data->qemu_help = NULL; - free (data->qemu_version); - data->qemu_version = NULL; free (data->qemu_devices); data->qemu_devices = NULL; -- 2.7.4

--- .gitignore | 1 + appliance/init | 5 +- tests/qemu/Makefile.am | 24 +- tests/qemu/boot-analysis.c | 1380 ++++++++++++++++++++++++++++++++++++++++++++ 4 files changed, 1406 insertions(+), 4 deletions(-) create mode 100644 tests/qemu/boot-analysis.c diff --git a/.gitignore b/.gitignore index 1493011..9306a19 100644 --- a/.gitignore +++ b/.gitignore @@ -510,6 +510,7 @@ Makefile.in /tests/mountable/test-internal-parse-mountable /tests/parallel/test-parallel /tests/protocol/test-error-messages +/tests/qemu/boot-analysis /tests/qemu/qemu-boot /tests/qemu/qemu-speed-test /tests/regressions/rhbz501893 diff --git a/appliance/init b/appliance/init index 77ea47e..43de32f 100755 --- a/appliance/init +++ b/appliance/init @@ -89,6 +89,9 @@ fi if grep -sq guestfs_noreboot=1 /proc/cmdline; then guestfs_noreboot=1 fi +if grep -sq guestfs_boot_analysis=1 /proc/cmdline; then + guestfs_boot_analysis=1 +fi eval `grep -Eo 'guestfs_channel=[^[:space:]]+' /proc/cmdline` if grep -sq selinux=1 /proc/cmdline; then @@ -129,7 +132,7 @@ lvm vgchange -aay --sysinit ldmtool create all # These are useful when debugging. -if test "$guestfs_verbose" = 1; then +if test "$guestfs_verbose" = 1 && test "$guestfs_boot_analysis" != 1; then uname -a ls -lR /dev cat /proc/mounts diff --git a/tests/qemu/Makefile.am b/tests/qemu/Makefile.am index 6c72b18..55bbea4 100644 --- a/tests/qemu/Makefile.am +++ b/tests/qemu/Makefile.am @@ -34,10 +34,10 @@ EXTRA_DIST = \ qemu-boot.c \ qemu-speed-test.c -# qemu-boot & qemu-speed-test are built but not run by default as they -# are mainly qemu & kernel diagnostic tools. +# qemu-boot, qemu-speed-test and boot-analysis are built but not run +# by default as they are mainly qemu & kernel diagnostic tools. -check_PROGRAMS = qemu-boot qemu-speed-test +check_PROGRAMS = qemu-boot qemu-speed-test boot-analysis qemu_boot_SOURCES = \ ../../df/estimate-max-threads.c \ @@ -76,6 +76,24 @@ qemu_speed_test_LDADD = \ $(LTLIBINTL) \ $(top_builddir)/gnulib/lib/libgnu.la +boot_analysis_SOURCES = \ + boot-analysis.c +boot_analysis_CPPFLAGS = \ + -I$(top_srcdir)/gnulib/lib -I$(top_builddir)/gnulib/lib \ + -I$(top_srcdir)/src -I$(top_builddir)/src +boot_analysis_CFLAGS = \ + $(WARN_CFLAGS) $(WERROR_CFLAGS) \ + $(PCRE_CFLAGS) +boot_analysis_LDADD = \ + $(top_builddir)/src/libutils.la \ + $(top_builddir)/src/libguestfs.la \ + $(PCRE_LIBS) \ + $(LIBXML2_LIBS) \ + $(LIBVIRT_LIBS) \ + $(LTLIBINTL) \ + $(top_builddir)/gnulib/lib/libgnu.la \ + -lm + # Don't run these tests in parallel, since they are designed to check # the integrity of qemu. .NOTPARALLEL: diff --git a/tests/qemu/boot-analysis.c b/tests/qemu/boot-analysis.c new file mode 100644 index 0000000..41f91bc --- /dev/null +++ b/tests/qemu/boot-analysis.c @@ -0,0 +1,1380 @@ +/* libguestfs + * Copyright (C) 2016 Red Hat Inc. + * + * This program is free software; you can redistribute it and/or modify + * it under the terms of the GNU General Public License as published by + * the Free Software Foundation; either version 2 of the License, or + * (at your option) any later version. + * + * This program is distributed in the hope that it will be useful, + * but WITHOUT ANY WARRANTY; without even the implied warranty of + * MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the + * GNU General Public License for more details. + * + * You should have received a copy of the GNU General Public License along + * with this program; if not, write to the Free Software Foundation, Inc., + * 51 Franklin Street, Fifth Floor, Boston, MA 02110-1301 USA. + */ + +/* Trace and analyze the appliance boot process to find out which + * steps are taking the most time. It is not part of the standard + * tests. + * + * This needs to be run on a quiet machine, so that other processes + * disturb the timing as little as possible. The program is + * completely safe to run at any time. It doesn't read or write any + * external files, and it doesn't require root. + * + * You can run it from the build directory like this: + * + * make + * make -C tests/qemu boot-analysis + * ./run tests/qemu/boot-analysis + * + * The way it works is roughly like this: + * + * We create a libguestfs handle and register callback handlers so we + * can see appliance messages, trace events and so on. + * + * We then launch the handle and shut it down as quickly as possible. + * + * While the handle is running, events (seen by the callback handlers) + * are written verbatim into an in-memory buffer, with timestamps. + * + * Afterwards we analyze the result using regular expressions to try + * to identify a "timeline" for the handle (eg. at what time did the + * BIOS hand control to the kernel). + * + * The whole process is repeated across a few runs, and the final + * timeline (including statistical analysis of the variation between + * runs) gets printed. + * + * The program is very sensitive to the specific messages printed by + * BIOS/kernel/supermin/userspace, so it won't work on non-x86, and it + * will require periodic adjustment of the regular expressions in + * order to keep things up to date. + */ + +#include <config.h> + +#include <stdio.h> +#include <stdlib.h> +#include <stdint.h> +#include <inttypes.h> +#include <string.h> +#include <unistd.h> +#include <getopt.h> +#include <limits.h> +#include <time.h> +#include <errno.h> +#include <error.h> +#include <ctype.h> +#include <assert.h> +#include <math.h> + +#include <pcre.h> + +#include "ignore-value.h" + +#include "guestfs.h" +#include "guestfs-internal-frontend.h" + +#define NR_WARMUP_PASSES 3 +#define NR_TEST_PASSES 5 + +/* Per-pass data collected. */ +struct pass_data { + size_t pass; + struct timespec start_t; + struct timespec end_t; + int64_t elapsed_ns; + + /* Array of timestamped events. */ + size_t nr_events; + struct event *events; + + /* Was the previous appliance log message incomplete? If so, this + * contains the index of that incomplete message in the events + * array. + */ + ssize_t incomplete_log_message; + + /* Have we seen the launch event yet? We don't record events until + * this one has been received. This makes it easy to base the + * timeline at event 0. + */ + int seen_launch; +}; + +struct event { + struct timespec t; + uint64_t source; + char *message; +}; + +static struct pass_data pass_data[NR_TEST_PASSES]; + +/* The final timeline consisting of various activities starting and + * ending. We're interested in when the activities start, and how + * long they take (mean, variance, standard deviation of length). + */ +struct activity { + char *name; /* Name of this activity. */ + int flags; +#define LONG_ACTIVITY 1 /* Expected to take a long time. */ + + /* For each pass, record the actual start & end events of this + * activity. + */ + size_t start_event[NR_TEST_PASSES]; + size_t end_event[NR_TEST_PASSES]; + + double t; /* Start (ns offset). */ + double end_t; /* t + mean - 1 */ + + /* Length of this activity. */ + double mean; /* Mean time elapsed (ns). */ + double variance; /* Variance. */ + double sd; /* Standard deviation. */ + double percent; /* Percent of total elapsed time. */ + + int warning; /* Appears in red. */ +}; + +static size_t nr_activities; +static struct activity *activities; + +static int force_colour = 0; +static int verbose = 0; + +static void run_test (void); +static void get_time (struct timespec *ts); +static int64_t timespec_diff (const struct timespec *x, const struct timespec *y); +static struct event *add_event (struct pass_data *, uint64_t source); +static guestfs_h *create_handle (void); +static void set_up_event_handlers (guestfs_h *g, size_t pass); +static void add_drive (guestfs_h *g); +static void check_pass_data (void); +static void dump_pass_data (void); +static void construct_timeline (void); +static void dump_timeline (void); +static void print_info (void); +static void print_analysis (void); +static void free_pass_data (void); +static void free_final_timeline (void); +static void ansi_green (void); +static void ansi_red (void); +static void ansi_blue (void); +static void ansi_magenta (void); +static void ansi_restore (void); + +static void +usage (int exitcode) +{ + fprintf (stderr, + "boot-analysis: Trace and analyze the appliance boot process.\n" + "Usage:\n" + " boot-analysis [--options]\n" + "Options:\n" + " --help Display this usage text and exit.\n" + " --colour Output colours, even if not a terminal.\n" + " -v|--verbose Verbose output, useful for debugging.\n"); + exit (exitcode); +} + +int +main (int argc, char *argv[]) +{ + enum { HELP_OPTION = CHAR_MAX + 1 }; + static const char *options = "v"; + static const struct option long_options[] = { + { "help", 0, 0, HELP_OPTION }, + { "color", 0, 0, 0 }, + { "colour", 0, 0, 0 }, + { "verbose", 0, 0, 'v' }, + { 0, 0, 0, 0 } + }; + int c, option_index; + + for (;;) { + c = getopt_long (argc, argv, options, long_options, &option_index); + if (c == -1) break; + + switch (c) { + case 0: /* Options which are long only. */ + if (STREQ (long_options[option_index].name, "color") || + STREQ (long_options[option_index].name, "colour")) { + force_colour = 1; + break; + } + fprintf (stderr, "%s: unknown long option: %s (%d)\n", + guestfs_int_program_name, long_options[option_index].name, option_index); + exit (EXIT_FAILURE); + + case 'v': + verbose = 1; + break; + + case HELP_OPTION: + usage (EXIT_SUCCESS); + + default: + usage (EXIT_FAILURE); + } + } + + if (STRNEQ (host_cpu, "x86_64")) + fprintf (stderr, "WARNING: host_cpu != x86_64: This program may not work or give bogus results.\n"); + + run_test (); +} + +static void +run_test (void) +{ + guestfs_h *g; + size_t i; + + printf ("Warming up the libguestfs cache ...\n"); + for (i = 0; i < NR_WARMUP_PASSES; ++i) { + g = create_handle (); + add_drive (g); + if (guestfs_launch (g) == -1) + exit (EXIT_FAILURE); + guestfs_close (g); + } + + printf ("Running the tests in %d passes ...\n", NR_TEST_PASSES); + for (i = 0; i < NR_TEST_PASSES; ++i) { + g = create_handle (); + set_up_event_handlers (g, i); + add_drive (g); + if (guestfs_launch (g) == -1) + exit (EXIT_FAILURE); + guestfs_close (g); + + printf (" pass %zu: %zu events collected in %" PRIi64 " ns\n", + i+1, pass_data[i].nr_events, pass_data[i].elapsed_ns); + } + + if (verbose) + dump_pass_data (); + + printf ("Analyzing the results ...\n"); + check_pass_data (); + construct_timeline (); + + if (verbose) + dump_timeline (); + + printf ("\n"); + print_info (); + printf ("\n"); + print_analysis (); + + free_pass_data (); + free_final_timeline (); +} + +static void +get_time (struct timespec *ts) +{ + if (clock_gettime (CLOCK_REALTIME, ts) == -1) + error (EXIT_FAILURE, errno, "clock_gettime: CLOCK_REALTIME"); +} + +/* Computes Y - X, returning nanoseconds. */ +static int64_t +timespec_diff (const struct timespec *x, const struct timespec *y) +{ + int64_t nsec; + + nsec = (y->tv_sec - x->tv_sec) * UINT64_C(1000000000); + nsec += y->tv_nsec - x->tv_nsec; + return nsec; +} + +static struct event * +add_event (struct pass_data *data, uint64_t source) +{ + struct event *ret; + + data->nr_events++; + data->events = realloc (data->events, + sizeof (struct event) * data->nr_events); + if (data->events == NULL) + error (EXIT_FAILURE, errno, "realloc"); + ret = &data->events[data->nr_events-1]; + get_time (&ret->t); + ret->source = source; + ret->message = NULL; + return ret; +} + +/* Common function to create the handle and set various defaults. */ +static guestfs_h * +create_handle (void) +{ + guestfs_h *g; + + g = guestfs_create (); + if (!g) error (EXIT_FAILURE, errno, "guestfs_create"); + + /* We always run these tests using LIBGUESTFS_BACKEND=direct. It + * may be in future we need to test libvirt as well, in case + * performance issues are suspected there, but so far libvirt has + * not been a bottleneck. + */ + if (guestfs_set_backend (g, "direct") == -1) + exit (EXIT_FAILURE); + + /* This changes some details in appliance/init and enables a + * detailed trace of calls to initcall functions in the kernel. + */ + if (guestfs_set_append (g, + "guestfs_boot_analysis=1 " + "ignore_loglevel initcall_debug") == -1) + exit (EXIT_FAILURE); + + return g; +} + +/* Common function to add the /dev/null drive. */ +static void +add_drive (guestfs_h *g) +{ + if (guestfs_add_drive_opts (g, "/dev/null", + GUESTFS_ADD_DRIVE_OPTS_FORMAT, "raw", + GUESTFS_ADD_DRIVE_OPTS_READONLY, 1, + -1) == -1) + exit (EXIT_FAILURE); +} + +/* Called when the handle is closed. Perform any cleanups required in + * the pass_data here. + */ +static void +close_callback (guestfs_h *g, void *datavp, uint64_t source, + int eh, int flags, + const char *buf, size_t buf_len, + const uint64_t *array, size_t array_len) +{ + struct pass_data *data = datavp; + struct event *event; + + if (!data->seen_launch) + return; + + event = add_event (data, source); + event->message = strdup ("close callback"); + if (event->message == NULL) + error (EXIT_FAILURE, errno, "strdup"); + + get_time (&data->end_t); + data->elapsed_ns = timespec_diff (&data->start_t, &data->end_t); +} + +/* Called when the qemu subprocess exits. + * XXX This is never called - why? + */ +static void +subprocess_quit_callback (guestfs_h *g, void *datavp, uint64_t source, + int eh, int flags, + const char *buf, size_t buf_len, + const uint64_t *array, size_t array_len) +{ + struct pass_data *data = datavp; + struct event *event; + + if (!data->seen_launch) + return; + + event = add_event (data, source); + event->message = strdup ("subprocess quit callback"); + if (event->message == NULL) + error (EXIT_FAILURE, errno, "strdup"); +} + +/* Called when the launch operation is complete (the library and the + * guestfs daemon and talking to each other). + */ +static void +launch_done_callback (guestfs_h *g, void *datavp, uint64_t source, + int eh, int flags, + const char *buf, size_t buf_len, + const uint64_t *array, size_t array_len) +{ + struct pass_data *data = datavp; + struct event *event; + + if (!data->seen_launch) + return; + + event = add_event (data, source); + event->message = strdup ("launch done callback"); + if (event->message == NULL) + error (EXIT_FAILURE, errno, "strdup"); +} + +/* Trim \r (multiple) from the end of a string. */ +static void +trim_r (char *message) +{ + size_t len = strlen (message); + + while (len > 0 && message[len-1] == '\r') { + message[len-1] = '\0'; + len--; + } +} + +/* Called when we get (possibly part of) a log message (or more than + * one log message) from the appliance (which may include qemu, the + * BIOS, kernel, etc). + */ +static void +appliance_callback (guestfs_h *g, void *datavp, uint64_t source, + int eh, int flags, + const char *buf, size_t buf_len, + const uint64_t *array, size_t array_len) +{ + struct pass_data *data = datavp; + struct event *event; + size_t i, len, slen; + + if (!data->seen_launch) + return; + + /* If the previous log message was incomplete, but time has moved on + * a lot, record a new log message anyway, so it gets a new + * timestamp. + */ + if (data->incomplete_log_message >= 0) { + struct timespec ts; + get_time (&ts); + if (timespec_diff (&data->events[data->incomplete_log_message].t, + &ts) >= 10000000 /* 10ms */) + data->incomplete_log_message = -1; + } + + /* If the previous log message was incomplete then we may need to + * append part of the current log message to a previous one. + */ + if (data->incomplete_log_message >= 0) { + len = buf_len; + for (i = 0; i < buf_len; ++i) { + if (buf[i] == '\n') { + len = i; + break; + } + } + + event = &data->events[data->incomplete_log_message]; + slen = strlen (event->message); + event->message = realloc (event->message, slen + len + 1); + if (event->message == NULL) + error (EXIT_FAILURE, errno, "realloc"); + memcpy (event->message + slen, buf, len); + event->message[slen + len] = '\0'; + trim_r (event->message); + + /* Skip what we just added to the previous incomplete message. */ + buf += len; + buf_len -= len; + + if (buf_len == 0) /* still not complete, more to come! */ + return; + + /* Skip the \n in the buffer. */ + buf++; + buf_len--; + data->incomplete_log_message = -1; + } + + /* Add the event, or perhaps multiple events if the message + * contains \n characters. + */ + while (buf_len > 0) { + len = buf_len; + for (i = 0; i < buf_len; ++i) { + if (buf[i] == '\n') { + len = i; + break; + } + } + + event = add_event (data, source); + event->message = strndup (buf, len); + if (event->message == NULL) + error (EXIT_FAILURE, errno, "strndup"); + trim_r (event->message); + + /* Skip what we just added to the event. */ + buf += len; + buf_len -= len; + + if (buf_len == 0) { + /* Event is incomplete (doesn't end with \n). We'll finish it + * in the next callback. + */ + data->incomplete_log_message = event - data->events; + return; + } + + /* Skip the \n in the buffer. */ + buf++; + buf_len--; + } +} + +/* Called when we get a debug message from the library side. These + * are always delivered as complete messages. + */ +static void +library_callback (guestfs_h *g, void *datavp, uint64_t source, + int eh, int flags, + const char *buf, size_t buf_len, + const uint64_t *array, size_t array_len) +{ + struct pass_data *data = datavp; + struct event *event; + + if (!data->seen_launch) + return; + + event = add_event (data, source); + event->message = strndup (buf, buf_len); + if (event->message == NULL) + error (EXIT_FAILURE, errno, "strndup"); +} + +/* Called when we get a call trace message (a libguestfs API function + * has been called or is returning). These are always delivered as + * complete messages. + */ +static void +trace_callback (guestfs_h *g, void *datavp, uint64_t source, + int eh, int flags, + const char *buf, size_t buf_len, + const uint64_t *array, size_t array_len) +{ + struct pass_data *data = datavp; + struct event *event; + char *message; + + message = strndup (buf, buf_len); + if (message == NULL) + error (EXIT_FAILURE, errno, "strndup"); + + if (STREQ (message, "launch")) + data->seen_launch = 1; + + if (!data->seen_launch) { + free (message); + return; + } + + event = add_event (data, source); + event->message = message; +} + +/* Common function to set up event callbacks and record data in memory + * for a particular pass (0 <= pass < NR_TEST_PASSES). + */ +static void +set_up_event_handlers (guestfs_h *g, size_t pass) +{ + struct pass_data *data; + + assert (/* 0 <= pass && */ pass < NR_TEST_PASSES); + + data = &pass_data[pass]; + data->pass = pass; + data->nr_events = 0; + data->events = NULL; + get_time (&data->start_t); + data->incomplete_log_message = -1; + data->seen_launch = 0; + + guestfs_set_event_callback (g, close_callback, + GUESTFS_EVENT_CLOSE, 0, data); + guestfs_set_event_callback (g, subprocess_quit_callback, + GUESTFS_EVENT_SUBPROCESS_QUIT, 0, data); + guestfs_set_event_callback (g, launch_done_callback, + GUESTFS_EVENT_LAUNCH_DONE, 0, data); + guestfs_set_event_callback (g, appliance_callback, + GUESTFS_EVENT_APPLIANCE, 0, data); + guestfs_set_event_callback (g, library_callback, + GUESTFS_EVENT_LIBRARY, 0, data); + guestfs_set_event_callback (g, trace_callback, + GUESTFS_EVENT_TRACE, 0, data); + + guestfs_set_verbose (g, 1); + guestfs_set_trace (g, 1); +} + +/* Sanity check the collected events. */ +static void +check_pass_data (void) +{ + size_t i, j, len; + int64_t ns; + const char *message; + + for (i = 0; i < NR_TEST_PASSES; ++i) { + assert (pass_data[i].pass == i); + assert (pass_data[i].elapsed_ns > 1000); + assert (pass_data[i].nr_events > 0); + assert (pass_data[i].events != NULL); + + for (j = 0; j < pass_data[i].nr_events; ++j) { + assert (pass_data[i].events[j].t.tv_sec > 0); + if (j > 0) { + ns = timespec_diff (&pass_data[i].events[j-1].t, + &pass_data[i].events[j].t); + assert (ns >= 0); + } + assert (pass_data[i].events[j].source != 0); + message = pass_data[i].events[j].message; + assert (message != NULL); + assert (strchr (message, '\n') == NULL); + len = strlen (message); + assert (len == 0 || message[len-1] != '\r'); + } + } +} + +static void +print_escaped_string (const char *message) +{ + while (*message) { + if (isprint (*message)) + putchar (*message); + else + printf ("\\x%02x", (unsigned int) *message); + message++; + } +} + +/* Dump the events to stdout, if verbose is set. */ +static void +dump_pass_data (void) +{ + size_t i, j; + + for (i = 0; i < NR_TEST_PASSES; ++i) { + printf ("pass %zu\n", pass_data[i].pass); + printf (" number of events collected %zu\n", pass_data[i].nr_events); + printf (" elapsed time %" PRIi64 " ns\n", pass_data[i].elapsed_ns); + for (j = 0; j < pass_data[i].nr_events; ++j) { + int64_t ns; + CLEANUP_FREE char *event_str = NULL; + + ns = timespec_diff (&pass_data[i].start_t, &pass_data[i].events[j].t); + event_str = guestfs_event_to_string (pass_data[i].events[j].source); + printf (" #%zu: +%" PRIi64 " [%s] \"", j, ns, event_str); + print_escaped_string (pass_data[i].events[j].message); + printf ("\"\n"); + } + } +} + +static int +activity_exists (const char *name) +{ + size_t i; + + for (i = 0; i < nr_activities; ++i) + if (STREQ (activities[i].name, name)) + return 1; + return 0; +} + +/* Add an activity to the global list. */ +static struct activity * +add_activity (const char *name, int flags) +{ + struct activity *ret; + size_t i; + + /* You shouldn't have two activities with the same name. */ + assert (!activity_exists (name)); + + nr_activities++; + activities = realloc (activities, sizeof (struct activity) * nr_activities); + if (activities == NULL) + error (EXIT_FAILURE, errno, "realloc"); + ret = &activities[nr_activities-1]; + ret->name = strdup (name); + if (ret->name == NULL) + error (EXIT_FAILURE, errno, "strdup"); + ret->flags = flags; + + for (i = 0; i < NR_TEST_PASSES; ++i) + ret->start_event[i] = ret->end_event[i] = 0; + + return ret; +} + +static struct activity * +find_activity (const char *name) +{ + size_t i; + + for (i = 0; i < nr_activities; ++i) + if (STREQ (activities[i].name, name)) + return &activities[i]; + error (EXIT_FAILURE, 0, + "internal error: could not find activity '%s'", name); + /*NOTREACHED*/ + abort (); +} + +static int +activity_exists_with_no_data (const char *name, size_t pass) +{ + size_t i; + + for (i = 0; i < nr_activities; ++i) + if (STREQ (activities[i].name, name) && + activities[i].start_event[pass] == 0 && + activities[i].end_event[pass] == 0) + return 1; + return 0; +} + +/* "supermin: internal insmod xx.ko" -> "insmod xx.ko" */ +static char * +translate_supermin_insmod_message (const char *message) +{ + char *ret; + + assert (STRPREFIX (message, "supermin: internal ")); + + ret = strdup (message + strlen ("supermin: internal ")); + if (ret == NULL) + error (EXIT_FAILURE, errno, "strdup"); + return ret; +} + +static int +compare_activities (const void *av, const void *bv) +{ + const struct activity *a = av; + const struct activity *b = bv; + + return a->t - b->t; +} + +COMPILE_REGEXP(re_initcall_calling_module, + "calling ([_A-Za-z0-9]+)\\+.*\\[([_A-Za-z0-9]+)]", 0) +COMPILE_REGEXP(re_initcall_calling, + "calling ([_A-Za-z0-9]+)\\+", 0) + +/* Analyze significant events from the events array, to form a + * timeline of activities. + */ +static void +construct_timeline (void) +{ + size_t i, j, k; + struct pass_data *data; + struct activity *activity; + int64_t delta_ns; + + for (i = 0; i < NR_TEST_PASSES; ++i) { + data = &pass_data[i]; + + /* Find an activity, by matching an event with the condition + * `begin_cond' through to the second event `end_cond'. Create an + * activity object in the timeline from the result. + */ +#define FIND(name, flags, begin_cond, end_cond) \ + do { \ + activity = NULL; \ + for (j = 0; j < data->nr_events; ++j) { \ + if (begin_cond) { \ + for (k = j+1; k < data->nr_events; ++k) { \ + if (end_cond) { \ + if (i == 0) \ + activity = add_activity (name, flags); \ + else \ + activity = find_activity (name); \ + break; \ + } \ + } \ + break; \ + } \ + } \ + if (activity) { \ + activity->start_event[i] = j; \ + activity->end_event[i] = k; \ + } \ + else \ + error (EXIT_FAILURE, 0, "could not find activity '%s' in pass '%zu'", \ + name, i); \ + } while (0) + + /* Same as FIND() macro, but if no matching events are found, + * ignore it. + */ +#define FIND_OPTIONAL(name, flags, begin_cond, end_cond) \ + do { \ + activity = NULL; \ + for (j = 0; j < data->nr_events; ++j) { \ + if (begin_cond) { \ + for (k = j+1; k < data->nr_events; ++k) { \ + if (end_cond) { \ + if (i == 0) \ + activity = add_activity (name, flags); \ + else \ + activity = find_activity (name); \ + break; \ + } \ + } \ + break; \ + } \ + } \ + if (activity) { \ + activity->start_event[i] = j; \ + activity->end_event[i] = k; \ + } \ + } while (0) + + /* Find multiple entries, where we check for: + * next_cond + * next_cond + * next_cond + * end_cond + */ +#define FIND_MULTIPLE(debug_name, flags, next_cond, end_cond, translate_message) \ + do { \ + activity = NULL; \ + for (j = 0; j < data->nr_events; ++j) { \ + if (next_cond) { \ + CLEANUP_FREE char *message = translate_message (data->events[j].message); \ + if (activity) \ + activity->end_event[i] = j; \ + if (i == 0) \ + activity = add_activity (message, flags); \ + else \ + activity = find_activity (message); \ + activity->start_event[i] = j; \ + } \ + else if (end_cond) \ + break; \ + } \ + if (j < data->nr_events && activity) \ + activity->end_event[i] = j; \ + else \ + error (EXIT_FAILURE, 0, "could not find activity '%s' in pass '%zu'", \ + debug_name, i); \ + } while (0) + + /* Add one activity which is going to cover the whole process + * from launch to close. The launch event is always event 0. + * NB: This activity must be called "run" (see below). + */ + FIND ("run", LONG_ACTIVITY, + j == 0, data->events[k].source == GUESTFS_EVENT_CLOSE); + + /* Find where we invoke supermin --build. This should be a null + * operation, but it still takes time to run the external command. + */ + FIND ("supermin:build", 0, + data->events[j].source == GUESTFS_EVENT_LIBRARY && + strstr (data->events[j].message, + "begin building supermin appliance"), + data->events[k].source == GUESTFS_EVENT_LIBRARY && + strstr (data->events[k].message, + "finished building supermin appliance")); + + /* Find where we invoke qemu to test features. */ + FIND ("qemu:feature-detect", 0, + data->events[j].source == GUESTFS_EVENT_LIBRARY && + strstr (data->events[j].message, + "begin testing qemu features"), + data->events[k].source == GUESTFS_EVENT_LIBRARY && + strstr (data->events[k].message, + "finished testing qemu features")); + + /* Find where we run qemu. */ + FIND ("qemu", LONG_ACTIVITY, + data->events[j].source == GUESTFS_EVENT_APPLIANCE && + strstr (data->events[j].message, "-nodefconfig"), + data->events[k].source == GUESTFS_EVENT_CLOSE); + +#define SGABIOS_STRING "\033[1;256r\033[256;256H\033[6n" + + /* From starting qemu up to entering the BIOS is the qemu overhead. */ + FIND ("qemu:overhead", 0, + data->events[j].source == GUESTFS_EVENT_APPLIANCE && + strstr (data->events[j].message, "-nodefconfig"), + data->events[k].source == GUESTFS_EVENT_APPLIANCE && + strstr (data->events[k].message, SGABIOS_STRING)); + + /* From entering the BIOS to starting the kernel is the BIOS overhead. */ + FIND_OPTIONAL ("bios:overhead", 0, + data->events[j].source == GUESTFS_EVENT_APPLIANCE && + strstr (data->events[j].message, SGABIOS_STRING), + data->events[k].source == GUESTFS_EVENT_APPLIANCE && + strstr (data->events[k].message, "Probing EDD")); + + /* SGABIOS (option ROM). */ + FIND_OPTIONAL ("sgabios", 0, + data->events[j].source == GUESTFS_EVENT_APPLIANCE && + strstr (data->events[j].message, SGABIOS_STRING), + data->events[k].source == GUESTFS_EVENT_APPLIANCE && + strstr (data->events[k].message, "SeaBIOS (version")); + + /* SeaBIOS. */ + FIND ("seabios", 0, + data->events[j].source == GUESTFS_EVENT_APPLIANCE && + strstr (data->events[j].message, "SeaBIOS (version"), + data->events[k].source == GUESTFS_EVENT_APPLIANCE && + strstr (data->events[k].message, "Probing EDD")); + + /* SeaBIOS - only available when using debug messages. */ + FIND_OPTIONAL ("seabios:pci-probe", 0, + data->events[j].source == GUESTFS_EVENT_APPLIANCE && + strstr (data->events[j].message, "Searching bootorder for: /pci@"), + data->events[k].source == GUESTFS_EVENT_APPLIANCE && + strstr (data->events[k].message, "Scan for option roms")); + + /* Find where we run the guest kernel. */ + FIND ("kernel", LONG_ACTIVITY, + data->events[j].source == GUESTFS_EVENT_APPLIANCE && + strstr (data->events[j].message, "Probing EDD"), + data->events[k].source == GUESTFS_EVENT_CLOSE); + + /* Kernel startup to userspace. */ + FIND ("kernel:overhead", 0, + data->events[j].source == GUESTFS_EVENT_APPLIANCE && + strstr (data->events[j].message, "Probing EDD"), + data->events[k].source == GUESTFS_EVENT_APPLIANCE && + strstr (data->events[k].message, "supermin:") && + strstr (data->events[k].message, "starting up")); + + /* The time taken to get into start_kernel function. */ + FIND ("kernel:entry", 0, + data->events[j].source == GUESTFS_EVENT_APPLIANCE && + strstr (data->events[j].message, "Probing EDD"), + data->events[k].source == GUESTFS_EVENT_APPLIANCE && + strstr (data->events[k].message, "Linux version")); + + /* Alternatives patching instructions (XXX not very accurate we + * really need some debug messages inserted into the code). + */ + FIND ("kernel:alternatives", 0, + data->events[j].source == GUESTFS_EVENT_APPLIANCE && + strstr (data->events[j].message, "Last level dTLB entries"), + data->events[k].source == GUESTFS_EVENT_APPLIANCE && + strstr (data->events[k].message, "Freeing SMP alternatives")); + + /* ftrace patching instructions. */ + FIND ("kernel:ftrace", 0, + data->events[j].source == GUESTFS_EVENT_APPLIANCE && + strstr (data->events[j].message, "ftrace: allocating"), + 1); + + /* Each kernel initcall. */ + for (j = 0; j < data->nr_events; ++j) { + int vec[30], r; + const char *message = data->events[j].message; + + if (data->events[j].source == GUESTFS_EVENT_APPLIANCE && + ((r = pcre_exec (re_initcall_calling_module, NULL, + message, strlen (message), + 0, 0, vec, sizeof vec / sizeof vec[0])) >= 1 || + (r = pcre_exec (re_initcall_calling, NULL, + message, strlen (message), + 0, 0, vec, sizeof vec / sizeof vec[0])) >= 1)) { + + CLEANUP_FREE char *fn_name = NULL, *module_name = NULL; + if (r >= 2) /* because pcre_exec returns 1 + number of captures */ + fn_name = strndup (message + vec[2], vec[3]-vec[2]); + if (r >= 3) + module_name = strndup (message + vec[4], vec[5]-vec[4]); + + CLEANUP_FREE char *fullname; + if (asprintf (&fullname, "%s.%s", + module_name ? module_name : "kernel", fn_name) == -1) + error (EXIT_FAILURE, errno, "asprintf"); + + CLEANUP_FREE char *initcall_match; + if (asprintf (&initcall_match, "initcall %s", fn_name) == -1) + error (EXIT_FAILURE, errno, "asprintf"); + + /* Get a unique name for this activity. Unfortunately + * kernel initcall function names are not unique! + */ + CLEANUP_FREE char *activity_name; + if (asprintf (&activity_name, "initcall %s", fullname) == -1) + error (EXIT_FAILURE, errno, "asprintf"); + + if (i == 0) { + int n = 1; + while (activity_exists (activity_name)) { + free (activity_name); + if (asprintf (&activity_name, "initcall %s:%d", fullname, n) == -1) + error (EXIT_FAILURE, errno, "asprintf"); + n++; + } + } + else { + int n = 1; + while (!activity_exists_with_no_data (activity_name, i)) { + free (activity_name); + if (asprintf (&activity_name, "initcall %s:%d", fullname, n) == -1) + error (EXIT_FAILURE, errno, "asprintf"); + n++; + } + } + + /* Find the matching end event. It might be some time later, + * since it appears initcalls can be nested. + */ + for (k = j+1; k < data->nr_events; ++k) { + if (data->events[k].source == GUESTFS_EVENT_APPLIANCE && + strstr (data->events[k].message, initcall_match)) { + if (i == 0) + activity = add_activity (activity_name, 0); + else + activity = find_activity (activity_name); + activity->start_event[i] = j; + activity->end_event[i] = k; + break; + } + } + } + } + + /* Find where we run supermin mini-initrd. */ + FIND ("supermin:mini-initrd", 0, + data->events[j].source == GUESTFS_EVENT_APPLIANCE && + strstr (data->events[j].message, "supermin:") && + strstr (data->events[j].message, "starting up"), + data->events[k].source == GUESTFS_EVENT_APPLIANCE && + strstr (data->events[k].message, "supermin: chroot")); + + /* Loading kernel modules from supermin initrd. */ + FIND_MULTIPLE + ("supermin insmod", 0, + data->events[j].source == GUESTFS_EVENT_APPLIANCE && + strstr (data->events[j].message, "supermin: internal insmod"), + data->events[j].source == GUESTFS_EVENT_APPLIANCE && + strstr (data->events[j].message, "supermin: picked"), + translate_supermin_insmod_message); + + /* Find where we run the /init script. */ + FIND ("/init", 0, + data->events[j].source == GUESTFS_EVENT_APPLIANCE && + strstr (data->events[j].message, "supermin: chroot"), + data->events[k].source == GUESTFS_EVENT_APPLIANCE && + strstr (data->events[k].message, "guestfsd --verbose")); + + /* Everything from the chroot to the first echo in the /init + * script counts as bash overhead. + */ + FIND ("bash:overhead", 0, + data->events[j].source == GUESTFS_EVENT_APPLIANCE && + strstr (data->events[j].message, "supermin: chroot"), + data->events[k].source == GUESTFS_EVENT_APPLIANCE && + strstr (data->events[k].message, "Starting /init script")); + + /* Find where we run guestfsd. */ + FIND ("guestfsd", 0, + data->events[j].source == GUESTFS_EVENT_APPLIANCE && + strstr (data->events[j].message, "guestfsd --verbose"), + data->events[k].source == GUESTFS_EVENT_APPLIANCE && + strstr (data->events[k].message, "fsync /dev/sda")); + + /* Shutdown process. */ + FIND ("shutdown", 0, + data->events[j].source == GUESTFS_EVENT_TRACE && + STREQ (data->events[j].message, "close"), + data->events[k].source == GUESTFS_EVENT_CLOSE); + } + + /* Now we can go through the activities, computing the start and + * elapsed time. + */ + for (j = 0; j < nr_activities; ++j) { + activity = &activities[j]; + + activity->t = 0; + activity->mean = 0; + for (i = 0; i < NR_TEST_PASSES; ++i) { + delta_ns = + timespec_diff (&pass_data[i].events[0].t, + &pass_data[i].events[activity->start_event[i]].t); + activity->t += delta_ns; + + delta_ns = + timespec_diff (&pass_data[i].events[activity->start_event[i]].t, + &pass_data[i].events[activity->end_event[i]].t); + activity->mean += delta_ns; + } + + /* Divide through to get real start time and mean of each activity. */ + activity->t /= NR_TEST_PASSES; + activity->mean /= NR_TEST_PASSES; + + /* Calculate the end time of this activity. It's convenient when + * drawing the timeline for one activity to finish just before the + * next activity starts, rather than having them end and start at + * the same time, hence ``- 1'' here. + */ + activity->end_t = activity->t + activity->mean - 1; + + /* The above only calculated mean. Now we are able to + * calculate from the mean the variance and the standard + * deviation. + */ + activity->variance = 0; + for (i = 0; i < NR_TEST_PASSES; ++i) { + delta_ns = + timespec_diff (&pass_data[i].events[activity->start_event[i]].t, + &pass_data[i].events[activity->end_event[i]].t); + activity->variance += pow (delta_ns - activity->mean, 2); + } + activity->variance /= NR_TEST_PASSES; + + activity->sd = sqrt (activity->variance); + } + + /* Get the total mean elapsed time from the special "run" activity. */ + activity = find_activity ("run"); + for (j = 0; j < nr_activities; ++j) { + activities[j].percent = 100.0 * activities[j].mean / activity->mean; + + activities[j].warning = + !(activities[j].flags & LONG_ACTIVITY) && activities[j].percent >= 5.0; + } + + /* Sort the activities by start time. */ + qsort (activities, nr_activities, sizeof (struct activity), + compare_activities); +} + +/* Dump the timeline to stdout, if verbose is set. */ +static void +dump_timeline (void) +{ + size_t i; + + for (i = 0; i < nr_activities; ++i) { + printf ("activity %zu:\n", i); + printf (" name = %s\n", activities[i].name); + printf (" start - end = %.1f - %.1f\n", + activities[i].t, activities[i].end_t); + printf (" mean elapsed = %.1f\n", activities[i].mean); + printf (" variance = %.1f\n", activities[i].variance); + printf (" s.d = %.1f\n", activities[i].sd); + printf (" percent = %.1f\n", activities[i].percent); + } +} + +/* Print some information that will allow us to determine the test + * system when reviewing the results in future. + */ +static void +print_info (void) +{ + size_t i; + + printf ("%s %s\n", PACKAGE_NAME, PACKAGE_VERSION_FULL); + + printf ("Host:\n"); + ignore_value (system ("uname -a")); + ignore_value (system ("grep '^model name' /proc/cpuinfo | head -1")); + + /* We can dig some information about qemu and the appliance out of + * the events. + */ + printf ("Appliance:\n"); + assert (NR_TEST_PASSES > 0); + for (i = 0; i < pass_data[0].nr_events; ++i) { + const char *message = pass_data[0].events[i].message; + if (strstr (message, "qemu version") || + (strstr (message, "SeaBIOS") && strstr (message, "version")) || + strstr (message, "Linux version") || + (strstr (message, "supermin") && strstr (message, "starting up"))) { + print_escaped_string (message); + putchar ('\n'); + } + } +} + +static void +print_analysis (void) +{ + double t = -1; /* Current time. */ + /* Which columns contain activities that we are displaying now? + * -1 == unused column, else index of an activity + */ + CLEANUP_FREE ssize_t *columns = NULL; + const size_t nr_columns = nr_activities; + size_t last_free_column = 0; + + size_t i, j; + double last_t, smallest_next_t; + const double MAX_T = 1e20; + + columns = malloc (nr_columns * sizeof (ssize_t)); + if (columns == NULL) error (EXIT_FAILURE, errno, "malloc"); + for (j = 0; j < nr_columns; ++j) + columns[j] = -1; + + for (;;) { + /* Find the next significant time to display, which is a time when + * some activity started or ended. + */ + smallest_next_t = MAX_T; + for (i = 0; i < nr_activities; ++i) { + if (t < activities[i].t && activities[i].t < smallest_next_t) + smallest_next_t = activities[i].t; + else if (t < activities[i].end_t && activities[i].end_t < smallest_next_t) + smallest_next_t = activities[i].end_t; + } + if (smallest_next_t == MAX_T) + break; /* Finished. */ + + last_t = t; + t = smallest_next_t; + + /* Draw a spacer line, but only if last_t -> t is a large jump. */ + if (t - last_t >= 1000000 /* ns */) { + printf (" "); + ansi_magenta (); + for (j = 0; j < last_free_column; ++j) { + if (columns[j] >= 0 && + activities[columns[j]].end_t != last_t /* !▼ */) + printf ("│ "); + else + printf (" "); + } + ansi_restore (); + printf ("\n"); + } + + /* If there are any activities that ended before this time, drop + * them from the columns list. + */ + for (i = 0; i < nr_activities; ++i) { + if (activities[i].end_t < t) { + for (j = 0; j < nr_columns; ++j) + if (columns[j] == (ssize_t) i) { + columns[j] = -1; + break; + } + } + } + + /* May need to adjust last_free_column after previous operation. */ + while (last_free_column > 0 && columns[last_free_column-1] == -1) + last_free_column--; + + /* If there are any activities starting at this time, add them to + * the right hand end of the columns list. + */ + for (i = 0; i < nr_activities; ++i) { + if (activities[i].t == t) + columns[last_free_column++] = i; + } + + /* Draw the line. */ + ansi_blue (); + printf ("%1.6fs: ", t / 1000000000); + + ansi_magenta (); + for (j = 0; j < last_free_column; ++j) { + if (columns[j] >= 0) { + if (activities[columns[j]].t == t) + printf ("▲ "); + else if (activities[columns[j]].end_t == t) + printf ("▼ "); + else + printf ("│ "); + } + else + printf (" "); + } + ansi_restore (); + + for (j = 0; j < last_free_column; ++j) { + if (columns[j] >= 0 && activities[columns[j]].t == t) /* ▲ */ { + if (activities[columns[j]].warning) ansi_red (); else ansi_green (); + print_escaped_string (activities[columns[j]].name); + ansi_restore (); + printf (" %1.6fs ±%.1fms ", + activities[columns[j]].mean / 1000000000, + activities[columns[j]].sd / 1000000); + if (activities[columns[j]].warning) ansi_red (); else ansi_green (); + printf ("(%.1f%%) ", activities[columns[j]].percent); + ansi_restore (); + } + } + + printf ("\n"); + } +} + +/* Free the non-static part of the pass_data structures. */ +static void +free_pass_data (void) +{ + size_t i, j; + + for (i = 0; i < NR_TEST_PASSES; ++i) { + for (j = 0; j < pass_data[i].nr_events; ++j) + free (pass_data[i].events[j].message); + free (pass_data[i].events); + } +} + +static void +free_final_timeline (void) +{ + size_t i; + + for (i = 0; i < nr_activities; ++i) + free (activities[i].name); + free (activities); +} + +/* Colours. */ +static void +ansi_green (void) +{ + if (force_colour || isatty (1)) + fputs ("\033[0;32m", stdout); +} + +static void +ansi_red (void) +{ + if (force_colour || isatty (1)) + fputs ("\033[1;31m", stdout); +} + +static void +ansi_blue (void) +{ + if (force_colour || isatty (1)) + fputs ("\033[1;34m", stdout); +} + +static void +ansi_magenta (void) +{ + if (force_colour || isatty (1)) + fputs ("\033[1;35m", stdout); +} + +static void +ansi_restore (void) +{ + if (force_colour || isatty (1)) + fputs ("\033[0m", stdout); +} -- 2.7.4