Libguestfs - Mar 2016 - [PATCH] tests/qemu: Add program for tracing and analyzing boot times.

---
 .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

[Sorry the cover letter is after the patch, but I couldn't work out
how to attach something to a cover letter in git send-email.]

This commit adds a program that measures the appliance boot process,
trying to determine which bits take longest.  It produces output
similar to that attached.

This patch is not quite finished yet, but I think it demonstrates a
few points already, those points being that SeaBIOS is really slow and
qemu has a lot of overhead.

Rich.

-- 
Richard Jones, Virtualization Group, Red Hat http://people.redhat.com/~rjones
Read my programming and virtualization blog: http://rwmj.wordpress.com
virt-top is 'top' for virtual machines.  Tiny program with many
powerful monitoring features, net stats, disk stats, logging, etc.
http://people.redhat.com/~rjones/virt-top