[Libguestfs] [PATCH v2 6/7] tests/qemu: Add program for tracing and analyzing boot times.

--- .gitignore | 1 + appliance/init | 5 +- tests/qemu/Makefile.am | 22 +- tests/qemu/boot-analysis.c | 1195 ++++++++++++++++++++++++++++++++++++++++++++ 4 files changed, 1219 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 586f208..8225110 100755 --- a/appliance/init +++ b/appliance/init @@ -91,6 +91,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 @@ -131,7 +134,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..57ceeae 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,22 @@ 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) +boot_analysis_LDADD = \ + $(top_builddir)/src/libutils.la \ + $(top_builddir)/src/libguestfs.la \ + $(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..9c7dd72 --- /dev/null +++ b/tests/qemu/boot-analysis.c @@ -0,0 +1,1195 @@ +/* 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 "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 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" + " -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 }, + { "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. */ + 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. */ + if (guestfs_set_append (g, "guestfs_boot_analysis=1") == -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 (g, "/dev/null") == -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 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"); + } + } +} + +/* Add an activity to the global list. */ +static struct activity * +add_activity (const char *name, int flags) +{ + struct activity *ret; + + 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; + 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 +compare_activities (const void *av, const void *bv) +{ + const struct activity *a = av; + const struct activity *b = bv; + + return a->t - b->t; +} + +/* 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) + +#if 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) +#endif + +#define FIND_MULTIPLE(debug_name, flags, next_cond, end_cond) \ + do { \ + activity = NULL; \ + for (j = 0; j < data->nr_events; ++j) { \ + if (next_cond) { \ + if (activity) \ + activity->end_event[i] = j; \ + if (i == 0) \ + activity = add_activity (data->events[j].message, flags); \ + else \ + activity = find_activity (data->events[j].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 ("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, "Linux version")); + + /* SGABIOS (option ROM). */ + FIND ("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, "Linux version")); + + /* Find where we run the guest kernel. */ + FIND ("kernel", LONG_ACTIVITY, + data->events[j].source == GUESTFS_EVENT_APPLIANCE && + strstr (data->events[j].message, "Linux version"), + data->events[k].source == GUESTFS_EVENT_CLOSE); + + /* Kernel startup. */ + FIND ("kernel:overhead", 0, + data->events[j].source == GUESTFS_EVENT_APPLIANCE && + strstr (data->events[j].message, "Linux version"), + data->events[k].source == GUESTFS_EVENT_APPLIANCE && + strstr (data->events[k].message, "supermin:") && + strstr (data->events[k].message, "starting up")); + + /* XXX More detailed look at kernel boot stages here. */ + + /* 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")); + + /* 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 (" mean:%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 (isatty (1)) + fputs ("\033[0;32m", stdout); +} + +static void +ansi_red (void) +{ + if (isatty (1)) + fputs ("\033[1;31m", stdout); +} + +static void +ansi_blue (void) +{ + if (isatty (1)) + fputs ("\033[1;34m", stdout); +} + +static void +ansi_magenta (void) +{ + if (isatty (1)) + fputs ("\033[1;35m", stdout); +} + +static void +ansi_restore (void) +{ + if (isatty (1)) + fputs ("\033[0m", stdout); +} -- 2.5.0