---
.gitignore | 1 +
tests/qemu/Makefile.am | 22 +-
tests/qemu/boot-analysis.c | 1098 ++++++++++++++++++++++++++++++++++++++++++++
3 files changed, 1118 insertions(+), 3 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/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..4bc9e28
--- /dev/null
+++ b/tests/qemu/boot-analysis.c
@@ -0,0 +1,1098 @@
+/* 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
+#define DEBUG 0
+
+/* 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). */
+
+ /* Length of this activity. */
+ double mean; /* Mean time elapsed (ns). */
+ double variance; /* Variance. */
+ double sd; /* Standard deviation. */
+ double percent; /* Percent of total elapsed time. */
+
+ double end_t; /* t + mean - 1 */
+};
+
+static size_t nr_activities;
+static struct activity *activities;
+
+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");
+ exit (exitcode);
+}
+
+int
+main (int argc, char *argv[])
+{
+ enum { HELP_OPTION = CHAR_MAX + 1 };
+ static const char *options = "";
+ static const struct option long_options[] = {
+ { "help", 0, 0, HELP_OPTION },
+ { 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 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 (DEBUG)
+ dump_pass_data ();
+
+ printf ("Analyzing the results ...\n");
+ check_pass_data ();
+ construct_timeline ();
+
+ if (DEBUG)
+ 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);
+
+ 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");
+}
+
+/* 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';
+
+ /* 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");
+
+ /* 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;
+ 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 (strlen (message) > 0);
+ assert (strchr (message, '\n') == NULL);
+ }
+ }
+}
+
+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 DEBUG 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];
+
+#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)
+
+#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);
+
+ /* 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, "SeaBIOS (version"));
+
+ /* From entering the BIOS to starting the kernel is the BIOS overhead. */
+ FIND ("seabios:overhead", 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);
+
+ /* 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"));
+
+ /* XXX More detail from /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;
+
+ /* Sort the activities by start time. */
+ qsort (activities, nr_activities, sizeof (struct activity),
+ compare_activities);
+}
+
+/* Dump the timeline to stdout, if DEBUG 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 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. */
+
+ t = smallest_next_t;
+
+ /* 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) /* ↑ */ {
+ int warning =
+ !(activities[columns[j]].flags & LONG_ACTIVITY) &&
+ activities[columns[j]].percent >= 5.0;
+
+ if (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 (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
