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

v4:

 - Lots more analysis of the /init script and other parts.

 - Display a list of the longest to shortest activities.

 - Rebase on top of current head.

Rich.

---
 appliance/init | 1 +
 1 file changed, 1 insertion(+)

diff --git a/appliance/init b/appliance/init
index 8d662fa..04afbd6 100755
--- a/appliance/init
+++ b/appliance/init
@@ -95,6 +95,7 @@ hwclock -u -s
 # Parse the kernel command line.
 if [[ $cmdline == *guestfs_verbose=1* ]]; then
     guestfs_verbose=1
+    set -x
 fi
 if [[ $cmdline == *guestfs_network=1* ]]; then
     guestfs_network=1
-- 
2.7.4

Since commit bb5d30ab2af5720775c63179afdec3ad9efd510d, we don't
require any external programs like grep to parse the command line.  We
only use bash intrinsics.

Therefore we can do it early (but after /proc is mounted).

This allows verbose mode to enable set -x early on, so we can trace
most things that the init script does.
---
 appliance/init | 39 +++++++++++++++++++++------------------
 1 file changed, 21 insertions(+), 18 deletions(-)

diff --git a/appliance/init b/appliance/init
index 04afbd6..c4cf964 100755
--- a/appliance/init
+++ b/appliance/init
@@ -33,9 +33,29 @@ done
 
 mkdir -p /sysroot
 
+# Mount /proc.
 if [ ! -d /proc ]; then rm -f /proc; fi
 mkdir -p /proc
 mount -t proc /proc /proc
+
+# Parse the kernel command line early (must be after /proc is mounted).
+cmdline=$(</proc/cmdline)
+
+if [[ $cmdline == *guestfs_verbose=1* ]]; then
+    guestfs_verbose=1
+    set -x
+fi
+if [[ $cmdline == *guestfs_network=1* ]]; then
+    guestfs_network=1
+fi
+if [[ $cmdline == *guestfs_rescue=1* ]]; then
+    guestfs_rescue=1
+fi
+if [[ $cmdline == *guestfs_noreboot=1* ]]; then
+    guestfs_noreboot=1
+fi
+
+# Mount the other special filesystems.
 if [ ! -d /sys ]; then rm -f /sys; fi
 mkdir -p /sys
 mount -t sysfs /sys /sys
@@ -75,8 +95,6 @@ $UDEVD --daemon #--debug
 udevadm trigger
 udevadm settle --timeout=600
 
-cmdline=$(</proc/cmdline)
-
 if [[ $cmdline == *selinux=1* ]]; then
   mount -t selinuxfs none /sys/fs/selinux
 fi
@@ -92,22 +110,6 @@ shopt -u nullglob
 # Update the system clock.
 hwclock -u -s
 
-# Parse the kernel command line.
-if [[ $cmdline == *guestfs_verbose=1* ]]; then
-    guestfs_verbose=1
-    set -x
-fi
-if [[ $cmdline == *guestfs_network=1* ]]; then
-    guestfs_network=1
-fi
-if [[ $cmdline == *guestfs_rescue=1* ]]; then
-    guestfs_rescue=1
-fi
-if [[ $cmdline == *guestfs_noreboot=1* ]]; then
-    guestfs_noreboot=1
-fi
-eval `grep -Eo 'guestfs_channel=[^[:space:]]+' /proc/cmdline`
-
 # Set up the network.
 ip addr add 127.0.0.1/8 brd + dev lo scope host
 ip link set dev lo up
@@ -156,6 +158,7 @@ fi
 if ! test "$guestfs_rescue" = 1; then
   # Run the daemon.
   cmd="guestfsd"
+  eval `grep -Eo 'guestfs_channel=[^[:space:]]+' /proc/cmdline`
   if test "x$guestfs_channel" != "x"; then
     cmd="$cmd --channel $guestfs_channel"
   fi
-- 
2.7.4

Move this earlier.
---
 appliance/init | 8 ++++----
 1 file changed, 4 insertions(+), 4 deletions(-)

diff --git a/appliance/init b/appliance/init
index c4cf964..d5f7404 100755
--- a/appliance/init
+++ b/appliance/init
@@ -72,6 +72,10 @@ ln -s /proc/mounts /etc/mtab
 # devtmpfs is required since udev 176
 mount -t devtmpfs /dev /dev
 
+if [[ $cmdline == *selinux=1* ]]; then
+  mount -t selinuxfs none /sys/fs/selinux
+fi
+
 # Static nodes must happen before udev is started.
 
 # Set up kmod static-nodes (RHBZ#1011907).
@@ -95,10 +99,6 @@ $UDEVD --daemon #--debug
 udevadm trigger
 udevadm settle --timeout=600
 
-if [[ $cmdline == *selinux=1* ]]; then
-  mount -t selinuxfs none /sys/fs/selinux
-fi
-
 # Disk optimizations.
 # Increase the SCSI timeout so we can read remote images.
 shopt -s nullglob
-- 
2.7.4

This command alone took 0.3 seconds which is about 10% of the current
launch time.  It appears to be unnecessary.

This reverts commit 508f1ee87e816bf6b6fc8e629ccbb2d61a971169.
---
 appliance/init | 3 ---
 1 file changed, 3 deletions(-)

diff --git a/appliance/init b/appliance/init
index d5f7404..7a28780 100755
--- a/appliance/init
+++ b/appliance/init
@@ -107,9 +107,6 @@ for f in /sys/block/sd*/device/timeout; do echo 300 > $f;
done
 for f in /sys/block/{h,s,ub,v}d*/queue/scheduler; do echo noop > $f; done
 shopt -u nullglob
 
-# Update the system clock.
-hwclock -u -s
-
 # Set up the network.
 ip addr add 127.0.0.1/8 brd + dev lo scope host
 ip link set dev lo up
-- 
2.7.4

This tedious workaround avoids a 0.26 second pause when using sgabios
(the Serial Graphics Adapter).  It's basically a workaround for buggy
code in sgabios, but much easier than fixing the assembler.
---
 src/conn-socket.c | 34 +++++++++++++++++++++++++++++++++-
 1 file changed, 33 insertions(+), 1 deletion(-)

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

---
 .gitignore                          |    1 +
 appliance/init                      |    5 +-
 tests/qemu/Makefile.am              |   26 +-
 tests/qemu/boot-analysis-timeline.c |  468 ++++++++++++++++
 tests/qemu/boot-analysis.c          | 1030 +++++++++++++++++++++++++++++++++++
 tests/qemu/boot-analysis.h          |   94 ++++
 6 files changed, 1620 insertions(+), 4 deletions(-)
 create mode 100644 tests/qemu/boot-analysis-timeline.c
 create mode 100644 tests/qemu/boot-analysis.c
 create mode 100644 tests/qemu/boot-analysis.h

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 7a28780..28054ab 100755
--- a/appliance/init
+++ b/appliance/init
@@ -54,6 +54,9 @@ fi
 if [[ $cmdline == *guestfs_noreboot=1* ]]; then
     guestfs_noreboot=1
 fi
+if [[ $cmdline == *guestfs_boot_analysis=1* ]]; then
+    guestfs_boot_analysis=1
+fi
 
 # Mount the other special filesystems.
 if [ ! -d /sys ]; then rm -f /sys; fi
@@ -133,7 +136,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 fe45d88..bea1c85 100644
--- a/tests/qemu/Makefile.am
+++ b/tests/qemu/Makefile.am
@@ -33,10 +33,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 \
@@ -73,6 +73,26 @@ qemu_speed_test_LDADD = \
 	$(LTLIBINTL) \
 	$(top_builddir)/gnulib/lib/libgnu.la
 
+boot_analysis_SOURCES = \
+	boot-analysis.c \
+	boot-analysis.h \
+	boot-analysis-timeline.c
+boot_analysis_CPPFLAGS = \
+	-I$(top_srcdir)/gnulib/lib -I$(top_builddir)/gnulib/lib \
+	-I$(top_srcdir)/src -I$(top_builddir)/src
+boot_analysis_CFLAGS = \
+	$(WARN_CFLAGS) $(WERROR_CFLAGS) \
+	$(PCRE_CFLAGS)
+boot_analysis_LDADD = \
+	$(top_builddir)/src/libutils.la \
+	$(top_builddir)/src/libguestfs.la \
+	$(PCRE_LIBS) \
+	$(LIBXML2_LIBS) \
+	$(LIBVIRT_LIBS) \
+	$(LTLIBINTL) \
+	$(top_builddir)/gnulib/lib/libgnu.la \
+	-lm
+
 # Don't run these tests in parallel, since they are designed to check
 # the integrity of qemu.
 .NOTPARALLEL:
diff --git a/tests/qemu/boot-analysis-timeline.c
b/tests/qemu/boot-analysis-timeline.c
new file mode 100644
index 0000000..8753805
--- /dev/null
+++ b/tests/qemu/boot-analysis-timeline.c
@@ -0,0 +1,468 @@
+/* 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.
+ */
+
+#include <config.h>
+
+#include <stdio.h>
+#include <stdlib.h>
+#include <stdint.h>
+#include <inttypes.h>
+#include <string.h>
+#include <unistd.h>
+#include <error.h>
+#include <errno.h>
+#include <assert.h>
+
+#include <pcre.h>
+
+#include "ignore-value.h"
+
+#include "guestfs.h"
+#include "guestfs-internal-frontend.h"
+
+#include "boot-analysis.h"
+
+COMPILE_REGEXP(re_initcall_calling_module,
+               "calling  ([_A-Za-z0-9]+)\\+.*\\[([_A-Za-z0-9]+)]", 0)
+COMPILE_REGEXP(re_initcall_calling,
+               "calling  ([_A-Za-z0-9]+)\\+", 0)
+
+static void construct_initcall_timeline (void);
+
+/* "supermin: internal insmod xx.ko" -> "insmod xx.ko"
*/
+static char *
+translate_supermin_insmod_message (const char *message)
+{
+  char *ret;
+
+  assert (STRPREFIX (message, "supermin: internal "));
+
+  ret = strdup (message + strlen ("supermin: internal "));
+  if (ret == NULL)
+    error (EXIT_FAILURE, errno, "strdup");
+  return ret;
+}
+
+/* Analyze significant events from the events array, to form a
+ * timeline of activities.
+ */
+void
+construct_timeline (void)
+{
+  size_t i, j, k;
+  struct pass_data *data;
+  struct activity *activity;
+
+  for (i = 0; i < NR_TEST_PASSES; ++i) {
+    data = &pass_data[i];
+
+    /* Find an activity, by matching an event with the condition
+     * `begin_cond' through to the second event `end_cond'.  Create an
+     * activity object in the timeline from the result.
+     */
+#define FIND(name, flags, begin_cond, end_cond)                         \
+    do {                                                                \
+      activity = NULL;                                                  \
+      for (j = 0; j < data->nr_events; ++j) {                           \
+        if (begin_cond) {                                               \
+          for (k = j+1; k < data->nr_events; ++k) {                     \
+            if (end_cond) {                                             \
+              if (i == 0)                                               \
+                activity = add_activity (name, flags);                  \
+              else                                                      \
+                activity = find_activity (name);                        \
+              break;                                                    \
+            }                                                           \
+          }                                                             \
+          break;                                                        \
+        }                                                               \
+      }                                                                 \
+      if (activity) {                                                   \
+        activity->start_event[i] = j;                                   \
+        activity->end_event[i] = k;                                     \
+      }                                                                 \
+      else                                                              \
+        error (EXIT_FAILURE, 0, "could not find activity '%s' in
pass '%zu'", \
+               name, i);                                                \
+    } while (0)
+
+    /* Same as FIND() macro, but if no matching events are found,
+     * ignore it.
+     */
+#define FIND_OPTIONAL(name, flags, begin_cond, end_cond)                \
+    do {                                                                \
+      activity = NULL;                                                  \
+      for (j = 0; j < data->nr_events; ++j) {                           \
+        if (begin_cond) {                                               \
+          for (k = j+1; k < data->nr_events; ++k) {                     \
+            if (end_cond) {                                             \
+              if (i == 0)                                               \
+                activity = add_activity (name, flags);                  \
+              else                                                      \
+                activity = find_activity (name);                        \
+              break;                                                    \
+            }                                                           \
+          }                                                             \
+          break;                                                        \
+        }                                                               \
+      }                                                                 \
+      if (activity) {                                                   \
+        activity->start_event[i] = j;                                   \
+        activity->end_event[i] = k;                                     \
+      }                                                                 \
+    } while (0)
+
+    /* Find multiple entries, where we check for:
+     *   next_cond
+     *   next_cond
+     *   next_cond
+     *   end_cond
+     */
+#define FIND_MULTIPLE(debug_name, flags, next_cond, end_cond,
translate_message) \
+    do {                                                                \
+      activity = NULL;                                                  \
+      for (j = 0; j < data->nr_events; ++j) {                           \
+        if (next_cond) {                                                \
+          CLEANUP_FREE char *message = translate_message
(data->events[j].message); \
+          if (activity)                                                 \
+            activity->end_event[i] = j;                                 \
+          if (i == 0)                                                   \
+            activity = add_activity (message, flags);                   \
+          else                                                          \
+            activity = find_activity (message);                         \
+          activity->start_event[i] = j;                                 \
+        }                                                               \
+        else if (end_cond)                                              \
+          break;                                                        \
+      }                                                                 \
+      if (j < data->nr_events && activity)                       
\
+        activity->end_event[i] = j;                                     \
+      else                                                              \
+        error (EXIT_FAILURE, 0, "could not find activity '%s' in
pass '%zu'", \
+               debug_name, i);                                          \
+    } while (0)
+
+    /* Add one activity which is going to cover the whole process
+     * from launch to close.  The launch event is always event 0.
+     * NB: This activity must be called "run" (see below).
+     */
+    FIND ("run", LONG_ACTIVITY,
+          j == 0, data->events[k].source == GUESTFS_EVENT_CLOSE);
+
+    /* Find where we invoke supermin --build.  This should be a null
+     * operation, but it still takes time to run the external command.
+     */
+    FIND ("supermin:build", 0,
+          data->events[j].source == GUESTFS_EVENT_LIBRARY &&
+          strstr (data->events[j].message,
+                  "begin building supermin appliance"),
+          data->events[k].source == GUESTFS_EVENT_LIBRARY &&
+          strstr (data->events[k].message,
+                  "finished building supermin appliance"));
+
+    /* Find where we invoke qemu to test features. */
+    FIND ("qemu:feature-detect", 0,
+          data->events[j].source == GUESTFS_EVENT_LIBRARY &&
+          strstr (data->events[j].message,
+                  "begin testing qemu features"),
+          data->events[k].source == GUESTFS_EVENT_LIBRARY &&
+          strstr (data->events[k].message,
+                  "finished testing qemu features"));
+
+    /* Find where we run qemu. */
+    FIND ("qemu", LONG_ACTIVITY,
+          data->events[j].source == GUESTFS_EVENT_APPLIANCE &&
+          strstr (data->events[j].message, "-nodefconfig"),
+          data->events[k].source == GUESTFS_EVENT_CLOSE);
+
+#define SGABIOS_STRING "\033[1;256r\033[256;256H\033[6n"
+
+    /* From starting qemu up to entering the BIOS is the qemu overhead. */
+    FIND ("qemu:overhead", 0,
+          data->events[j].source == GUESTFS_EVENT_APPLIANCE &&
+          strstr (data->events[j].message, "-nodefconfig"),
+          data->events[k].source == GUESTFS_EVENT_APPLIANCE &&
+          strstr (data->events[k].message, SGABIOS_STRING));
+
+    /* From entering the BIOS to starting the kernel is the BIOS overhead. */
+    FIND_OPTIONAL ("bios:overhead", 0,
+          data->events[j].source == GUESTFS_EVENT_APPLIANCE &&
+          strstr (data->events[j].message, SGABIOS_STRING),
+          data->events[k].source == GUESTFS_EVENT_APPLIANCE &&
+          strstr (data->events[k].message, "Probing EDD"));
+
+    /* SGABIOS (option ROM). */
+    FIND_OPTIONAL ("sgabios", 0,
+          data->events[j].source == GUESTFS_EVENT_APPLIANCE &&
+          strstr (data->events[j].message, SGABIOS_STRING),
+          data->events[k].source == GUESTFS_EVENT_APPLIANCE &&
+          strstr (data->events[k].message, "SeaBIOS (version"));
+
+    /* SeaBIOS. */
+    FIND ("seabios", 0,
+          data->events[j].source == GUESTFS_EVENT_APPLIANCE &&
+          strstr (data->events[j].message, "SeaBIOS (version"),
+          data->events[k].source == GUESTFS_EVENT_APPLIANCE &&
+          strstr (data->events[k].message, "Probing EDD"));
+
+    /* SeaBIOS - only available when using debug messages. */
+    FIND_OPTIONAL ("seabios:pci-probe", 0,
+          data->events[j].source == GUESTFS_EVENT_APPLIANCE &&
+          strstr (data->events[j].message, "Searching bootorder for:
/pci@"),
+          data->events[k].source == GUESTFS_EVENT_APPLIANCE &&
+          strstr (data->events[k].message, "Scan for option
roms"));
+
+    /* Find where we run the guest kernel. */
+    FIND ("kernel", LONG_ACTIVITY,
+          data->events[j].source == GUESTFS_EVENT_APPLIANCE &&
+          strstr (data->events[j].message, "Probing EDD"),
+          data->events[k].source == GUESTFS_EVENT_CLOSE);
+
+    /* Kernel startup to userspace. */
+    FIND ("kernel:overhead", 0,
+          data->events[j].source == GUESTFS_EVENT_APPLIANCE &&
+          strstr (data->events[j].message, "Probing EDD"),
+          data->events[k].source == GUESTFS_EVENT_APPLIANCE &&
+          strstr (data->events[k].message, "supermin:") &&
+          strstr (data->events[k].message, "starting up"));
+
+    /* The time taken to get into start_kernel function. */
+    FIND ("kernel:entry", 0,
+          data->events[j].source == GUESTFS_EVENT_APPLIANCE &&
+          strstr (data->events[j].message, "Probing EDD"),
+          data->events[k].source == GUESTFS_EVENT_APPLIANCE &&
+          strstr (data->events[k].message, "Linux version"));
+
+    /* Alternatives patching instructions (XXX not very accurate we
+     * really need some debug messages inserted into the code).
+     */
+    FIND ("kernel:alternatives", 0,
+          data->events[j].source == GUESTFS_EVENT_APPLIANCE &&
+          strstr (data->events[j].message, "Last level dTLB
entries"),
+          data->events[k].source == GUESTFS_EVENT_APPLIANCE &&
+          strstr (data->events[k].message, "Freeing SMP
alternatives"));
+
+    /* ftrace patching instructions. */
+    FIND ("kernel:ftrace", 0,
+          data->events[j].source == GUESTFS_EVENT_APPLIANCE &&
+          strstr (data->events[j].message, "ftrace: allocating"),
+          1);
+
+    /* Find where we run supermin mini-initrd. */
+    FIND ("supermin:mini-initrd", 0,
+          data->events[j].source == GUESTFS_EVENT_APPLIANCE &&
+          strstr (data->events[j].message, "supermin:") &&
+          strstr (data->events[j].message, "starting up"),
+          data->events[k].source == GUESTFS_EVENT_APPLIANCE &&
+          strstr (data->events[k].message, "supermin: chroot"));
+
+    /* Loading kernel modules from supermin initrd. */
+    FIND_MULTIPLE
+      ("supermin insmod", 0,
+       data->events[j].source == GUESTFS_EVENT_APPLIANCE &&
+       strstr (data->events[j].message, "supermin: internal
insmod"),
+       data->events[j].source == GUESTFS_EVENT_APPLIANCE &&
+       strstr (data->events[j].message, "supermin: picked"),
+       translate_supermin_insmod_message);
+
+    /* Find where we run the /init script. */
+    FIND ("/init", 0,
+          data->events[j].source == GUESTFS_EVENT_APPLIANCE &&
+          strstr (data->events[j].message, "supermin: chroot"),
+          data->events[k].source == GUESTFS_EVENT_APPLIANCE &&
+          strstr (data->events[k].message, "guestfsd --verbose"));
+
+    /* Everything from the chroot to the first echo in the /init
+     * script counts as bash overhead.
+     */
+    FIND ("bash:overhead", 0,
+          data->events[j].source == GUESTFS_EVENT_APPLIANCE &&
+          strstr (data->events[j].message, "supermin: chroot"),
+          data->events[k].source == GUESTFS_EVENT_APPLIANCE &&
+          strstr (data->events[k].message, "Starting /init
script"));
+
+    /* /init: Mount special filesystems. */
+    FIND ("/init:mount-special", 0,
+          data->events[j].source == GUESTFS_EVENT_APPLIANCE &&
+          strstr (data->events[j].message,
"*guestfs_boot_analysis=1*"),
+          data->events[k].source == GUESTFS_EVENT_APPLIANCE &&
+          strstr (data->events[k].message, "kmod static-nodes"));
+
+    /* /init: Run kmod static-nodes */
+    FIND ("/init:kmod-static-nodes", 0,
+          data->events[j].source == GUESTFS_EVENT_APPLIANCE &&
+          strstr (data->events[j].message, "kmod static-nodes"),
+          data->events[k].source == GUESTFS_EVENT_APPLIANCE &&
+          strstr (data->events[k].message, "systemd-tmpfiles"));
+
+    /* /init: systemd-tmpfiles. */
+    FIND ("/init:systemd-tmpfiles", 0,
+          data->events[j].source == GUESTFS_EVENT_APPLIANCE &&
+          strstr (data->events[j].message, "systemd-tmpfiles"),
+          data->events[k].source == GUESTFS_EVENT_APPLIANCE &&
+          strstr (data->events[k].message, "udev"));
+
+    /* /init: start udevd. */
+    FIND ("/init:udev-overhead", 0,
+          data->events[j].source == GUESTFS_EVENT_APPLIANCE &&
+          strstr (data->events[j].message, "udevd --daemon"),
+          data->events[k].source == GUESTFS_EVENT_APPLIANCE &&
+          strstr (data->events[k].message, "nullglob"));
+
+    /* /init: set up network. */
+    FIND ("/init:network-overhead", 0,
+          data->events[j].source == GUESTFS_EVENT_APPLIANCE &&
+          strstr (data->events[j].message, "+ ip addr"),
+          data->events[k].source == GUESTFS_EVENT_APPLIANCE &&
+          strstr (data->events[k].message, "+ test"));
+
+    /* /init: probe MD arrays. */
+    FIND ("/init:md-probe", 0,
+          data->events[j].source == GUESTFS_EVENT_APPLIANCE &&
+          strstr (data->events[j].message, "+ mdadm"),
+          data->events[k].source == GUESTFS_EVENT_APPLIANCE &&
+          strstr (data->events[k].message, "+ modprobe dm_mod"));
+
+    /* /init: probe DM/LVM. */
+    FIND ("/init:lvm-probe", 0,
+          data->events[j].source == GUESTFS_EVENT_APPLIANCE &&
+          strstr (data->events[j].message, "+ modprobe dm_mod"),
+          data->events[k].source == GUESTFS_EVENT_APPLIANCE &&
+          strstr (data->events[k].message, "+ ldmtool"));
+
+    /* /init: probe Windows dynamic disks. */
+    FIND ("/init:windows-dynamic-disks-probe", 0,
+          data->events[j].source == GUESTFS_EVENT_APPLIANCE &&
+          strstr (data->events[j].message, "+ ldmtool"),
+          data->events[k].source == GUESTFS_EVENT_APPLIANCE &&
+          strstr (data->events[k].message, "+ test"));
+
+    /* 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);
+  }
+
+  construct_initcall_timeline ();
+}
+
+/* Handling of initcall is so peculiar that we hide it in a separate
+ * function from the rest.
+ */
+static void
+construct_initcall_timeline (void)
+{
+  size_t i, j, k;
+  struct pass_data *data;
+  struct activity *activity;
+
+  for (i = 0; i < NR_TEST_PASSES; ++i) {
+    data = &pass_data[i];
+
+    /* Each kernel initcall is bracketed by:
+     *
+     * calling  ehci_hcd_init+0x0/0xc1 @ 1"
+     * initcall ehci_hcd_init+0x0/0xc1 returned 0 after 420 usecs"
+     *
+     * For initcall functions in modules:
+     *
+     * calling  virtio_mmio_init+0x0/0x1000 [virtio_mmio] @ 1"
+     * initcall virtio_mmio_init+0x0/0x1000 [virtio_mmio] returned 0 after 14
usecs"
+     *
+     * Initcall functions can be nested, and do not have unique names.
+     */
+    for (j = 0; j < data->nr_events; ++j) {
+      int vec[30], r;
+      const char *message = data->events[j].message;
+
+      if (data->events[j].source == GUESTFS_EVENT_APPLIANCE &&
+          ((r = pcre_exec (re_initcall_calling_module, NULL,
+                           message, strlen (message),
+                           0, 0, vec, sizeof vec / sizeof vec[0])) >= 1 ||
+           (r = pcre_exec (re_initcall_calling, NULL,
+                           message, strlen (message),
+                           0, 0, vec, sizeof vec / sizeof vec[0])) >= 1)) {
+
+        CLEANUP_FREE char *fn_name = NULL, *module_name = NULL;
+        if (r >= 2) /* because pcre_exec returns 1 + number of captures */
+          fn_name = strndup (message + vec[2], vec[3]-vec[2]);
+        if (r >= 3)
+          module_name = strndup (message + vec[4], vec[5]-vec[4]);
+
+        CLEANUP_FREE char *fullname;
+        if (asprintf (&fullname, "%s.%s",
+                      module_name ? module_name : "kernel", fn_name)
== -1)
+          error (EXIT_FAILURE, errno, "asprintf");
+
+        CLEANUP_FREE char *initcall_match;
+        if (asprintf (&initcall_match, "initcall %s", fn_name) ==
-1)
+          error (EXIT_FAILURE, errno, "asprintf");
+
+        /* Get a unique name for this activity.  Unfortunately
+         * kernel initcall function names are not unique!
+         */
+        CLEANUP_FREE char *activity_name;
+        if (asprintf (&activity_name, "initcall %s", fullname) ==
-1)
+          error (EXIT_FAILURE, errno, "asprintf");
+
+        if (i == 0) {
+          int n = 1;
+          while (activity_exists (activity_name)) {
+            free (activity_name);
+            if (asprintf (&activity_name, "initcall %s:%d",
fullname, n) == -1)
+              error (EXIT_FAILURE, errno, "asprintf");
+            n++;
+          }
+        }
+        else {
+          int n = 1;
+          while (!activity_exists_with_no_data (activity_name, i)) {
+            free (activity_name);
+            if (asprintf (&activity_name, "initcall %s:%d",
fullname, n) == -1)
+              error (EXIT_FAILURE, errno, "asprintf");
+            n++;
+          }
+        }
+
+        /* Find the matching end event.  It might be some time later,
+         * since it appears initcalls can be nested.
+         */
+        for (k = j+1; k < data->nr_events; ++k) {
+          if (data->events[k].source == GUESTFS_EVENT_APPLIANCE &&
+              strstr (data->events[k].message, initcall_match)) {
+            if (i == 0)
+              activity = add_activity (activity_name, 0);
+            else
+              activity = find_activity (activity_name);
+            activity->start_event[i] = j;
+            activity->end_event[i] = k;
+            break;
+          }
+        }
+      }
+    }
+  }
+}
diff --git a/tests/qemu/boot-analysis.c b/tests/qemu/boot-analysis.c
new file mode 100644
index 0000000..71b265a
--- /dev/null
+++ b/tests/qemu/boot-analysis.c
@@ -0,0 +1,1030 @@
+/* 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).  This analysis is done in
+ * 'boot-analysis-timeline.c'.
+ *
+ * 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"
+
+#include "boot-analysis.h"
+
+/* Activities taking longer than this % of the total time, except
+ * those flagged as LONG_ACTIVITY, are highlighted in red.
+ */
+#define WARNING_THRESHOLD 1.0
+
+struct pass_data pass_data[NR_TEST_PASSES];
+size_t nr_activities;
+struct activity *activities;
+
+static int force_colour = 0;
+static int verbose = 0;
+
+static void run_test (void);
+static void get_time (struct timespec *ts);
+static int64_t timespec_diff (const struct timespec *x, const struct timespec
*y);
+static struct event *add_event (struct pass_data *, uint64_t source);
+static guestfs_h *create_handle (void);
+static void set_up_event_handlers (guestfs_h *g, size_t pass);
+static void add_drive (guestfs_h *g);
+static void check_pass_data (void);
+static void dump_pass_data (void);
+static void analyze_timeline (void);
+static void dump_timeline (void);
+static void print_info (void);
+static void print_analysis (void);
+static void print_longest_to_shortest (void);
+static void free_pass_data (void);
+static void free_final_timeline (void);
+static void ansi_green (void);
+static void ansi_red (void);
+static void ansi_blue (void);
+static void ansi_magenta (void);
+static void ansi_restore (void);
+
+static void
+usage (int exitcode)
+{
+  fprintf (stderr,
+           "boot-analysis: Trace and analyze the appliance boot
process.\n"
+           "Usage:\n"
+           "  boot-analysis [--options]\n"
+           "Options:\n"
+           "  --help        Display this usage text and exit.\n"
+           "  --colour      Output colours, even if not a
terminal.\n"
+           "  -v|--verbose  Verbose output, useful for
debugging.\n");
+  exit (exitcode);
+}
+
+int
+main (int argc, char *argv[])
+{
+  enum { HELP_OPTION = CHAR_MAX + 1 };
+  static const char *options = "v";
+  static const struct option long_options[] = {
+    { "help", 0, 0, HELP_OPTION },
+    { "color", 0, 0, 0 },
+    { "colour", 0, 0, 0 },
+    { "verbose", 0, 0, 'v' },
+    { 0, 0, 0, 0 }
+  };
+  int c, option_index;
+
+  for (;;) {
+    c = getopt_long (argc, argv, options, long_options, &option_index);
+    if (c == -1) break;
+
+    switch (c) {
+    case 0:                     /* Options which are long only. */
+      if (STREQ (long_options[option_index].name, "color") ||
+          STREQ (long_options[option_index].name, "colour")) {
+        force_colour = 1;
+        break;
+      }
+      fprintf (stderr, "%s: unknown long option: %s (%d)\n",
+               guestfs_int_program_name, long_options[option_index].name,
option_index);
+      exit (EXIT_FAILURE);
+
+    case 'v':
+      verbose = 1;
+      break;
+
+    case HELP_OPTION:
+      usage (EXIT_SUCCESS);
+
+    default:
+      usage (EXIT_FAILURE);
+    }
+  }
+
+  if (STRNEQ (host_cpu, "x86_64"))
+    fprintf (stderr, "WARNING: host_cpu != x86_64: This program may not
work or give bogus results.\n");
+
+  run_test ();
+}
+
+static void
+run_test (void)
+{
+  guestfs_h *g;
+  size_t i;
+
+  printf ("Warming up the libguestfs cache ...\n");
+  for (i = 0; i < NR_WARMUP_PASSES; ++i) {
+    g = create_handle ();
+    add_drive (g);
+    if (guestfs_launch (g) == -1)
+      exit (EXIT_FAILURE);
+    guestfs_close (g);
+  }
+
+  printf ("Running the tests in %d passes ...\n", NR_TEST_PASSES);
+  for (i = 0; i < NR_TEST_PASSES; ++i) {
+    g = create_handle ();
+    set_up_event_handlers (g, i);
+    add_drive (g);
+    if (guestfs_launch (g) == -1)
+      exit (EXIT_FAILURE);
+    guestfs_close (g);
+
+    printf ("    pass %zu: %zu events collected in %" PRIi64 "
ns\n",
+            i+1, pass_data[i].nr_events, pass_data[i].elapsed_ns);
+  }
+
+  if (verbose)
+    dump_pass_data ();
+
+  printf ("Analyzing the results ...\n");
+  check_pass_data ();
+  construct_timeline ();
+  analyze_timeline ();
+
+  if (verbose)
+    dump_timeline ();
+
+  printf ("\n");
+  print_info ();
+  printf ("\n");
+  print_analysis ();
+  printf ("\n");
+  printf ("Longest activities:\n");
+  printf ("\n");
+  print_longest_to_shortest ();
+
+  free_pass_data ();
+  free_final_timeline ();
+}
+
+static void
+get_time (struct timespec *ts)
+{
+  if (clock_gettime (CLOCK_REALTIME, ts) == -1)
+    error (EXIT_FAILURE, errno, "clock_gettime: CLOCK_REALTIME");
+}
+
+/* Computes Y - X, returning nanoseconds. */
+static int64_t
+timespec_diff (const struct timespec *x, const struct timespec *y)
+{
+  int64_t nsec;
+
+  nsec = (y->tv_sec - x->tv_sec) * UINT64_C(1000000000);
+  nsec += y->tv_nsec - x->tv_nsec;
+  return nsec;
+}
+
+static struct event *
+add_event (struct pass_data *data, uint64_t source)
+{
+  struct event *ret;
+
+  data->nr_events++;
+  data->events = realloc (data->events,
+                          sizeof (struct event) * data->nr_events);
+  if (data->events == NULL)
+    error (EXIT_FAILURE, errno, "realloc");
+  ret = &data->events[data->nr_events-1];
+  get_time (&ret->t);
+  ret->source = source;
+  ret->message = NULL;
+  return ret;
+}
+
+/* Common function to create the handle and set various defaults. */
+static guestfs_h *
+create_handle (void)
+{
+  guestfs_h *g;
+
+  g = guestfs_create ();
+  if (!g) error (EXIT_FAILURE, errno, "guestfs_create");
+
+  /* We always run these tests using LIBGUESTFS_BACKEND=direct.  It
+   * may be in future we need to test libvirt as well, in case
+   * performance issues are suspected there, but so far libvirt has
+   * not been a bottleneck.
+   */
+  if (guestfs_set_backend (g, "direct") == -1)
+    exit (EXIT_FAILURE);
+
+  /* This changes some details in appliance/init and enables a
+   * detailed trace of calls to initcall functions in the kernel.
+   */
+  if (guestfs_set_append (g,
+                          "guestfs_boot_analysis=1 "
+                          "ignore_loglevel initcall_debug") == -1)
+    exit (EXIT_FAILURE);
+
+  return g;
+}
+
+/* Common function to add the /dev/null drive. */
+static void
+add_drive (guestfs_h *g)
+{
+  if (guestfs_add_drive_opts (g, "/dev/null",
+                              GUESTFS_ADD_DRIVE_OPTS_FORMAT, "raw",
+                              GUESTFS_ADD_DRIVE_OPTS_READONLY, 1,
+                              -1) == -1)
+    exit (EXIT_FAILURE);
+}
+
+/* Called when the handle is closed.  Perform any cleanups required in
+ * the pass_data here.
+ */
+static void
+close_callback (guestfs_h *g, void *datavp, uint64_t source,
+                int eh, int flags,
+                const char *buf, size_t buf_len,
+                const uint64_t *array, size_t array_len)
+{
+  struct pass_data *data = datavp;
+  struct event *event;
+
+  if (!data->seen_launch)
+    return;
+
+  event = add_event (data, source);
+  event->message = strdup ("close callback");
+  if (event->message == NULL)
+    error (EXIT_FAILURE, errno, "strdup");
+
+  get_time (&data->end_t);
+  data->elapsed_ns = timespec_diff (&data->start_t,
&data->end_t);
+}
+
+/* Called when the qemu subprocess exits.
+ * XXX This is never called - why?
+ */
+static void
+subprocess_quit_callback (guestfs_h *g, void *datavp, uint64_t source,
+                          int eh, int flags,
+                          const char *buf, size_t buf_len,
+                          const uint64_t *array, size_t array_len)
+{
+  struct pass_data *data = datavp;
+  struct event *event;
+
+  if (!data->seen_launch)
+    return;
+
+  event = add_event (data, source);
+  event->message = strdup ("subprocess quit callback");
+  if (event->message == NULL)
+    error (EXIT_FAILURE, errno, "strdup");
+}
+
+/* Called when the launch operation is complete (the library and the
+ * guestfs daemon and talking to each other).
+ */
+static void
+launch_done_callback (guestfs_h *g, void *datavp, uint64_t source,
+                      int eh, int flags,
+                      const char *buf, size_t buf_len,
+                      const uint64_t *array, size_t array_len)
+{
+  struct pass_data *data = datavp;
+  struct event *event;
+
+  if (!data->seen_launch)
+    return;
+
+  event = add_event (data, source);
+  event->message = strdup ("launch done callback");
+  if (event->message == NULL)
+    error (EXIT_FAILURE, errno, "strdup");
+}
+
+/* Trim \r (multiple) from the end of a string. */
+static void
+trim_r (char *message)
+{
+  size_t len = strlen (message);
+
+  while (len > 0 && message[len-1] == '\r') {
+    message[len-1] = '\0';
+    len--;
+  }
+}
+
+/* Called when we get (possibly part of) a log message (or more than
+ * one log message) from the appliance (which may include qemu, the
+ * BIOS, kernel, etc).
+ */
+static void
+appliance_callback (guestfs_h *g, void *datavp, uint64_t source,
+                    int eh, int flags,
+                    const char *buf, size_t buf_len,
+                    const uint64_t *array, size_t array_len)
+{
+  struct pass_data *data = datavp;
+  struct event *event;
+  size_t i, len, slen;
+
+  if (!data->seen_launch)
+    return;
+
+  /* If the previous log message was incomplete, but time has moved on
+   * a lot, record a new log message anyway, so it gets a new
+   * timestamp.
+   */
+  if (data->incomplete_log_message >= 0) {
+    struct timespec ts;
+    get_time (&ts);
+    if (timespec_diff (&data->events[data->incomplete_log_message].t,
+                       &ts) >= 10000000 /* 10ms */)
+      data->incomplete_log_message = -1;
+  }
+
+  /* If the previous log message was incomplete then we may need to
+   * append part of the current log message to a previous one.
+   */
+  if (data->incomplete_log_message >= 0) {
+    len = buf_len;
+    for (i = 0; i < buf_len; ++i) {
+      if (buf[i] == '\n') {
+        len = i;
+        break;
+      }
+    }
+
+    event = &data->events[data->incomplete_log_message];
+    slen = strlen (event->message);
+    event->message = realloc (event->message, slen + len + 1);
+    if (event->message == NULL)
+      error (EXIT_FAILURE, errno, "realloc");
+    memcpy (event->message + slen, buf, len);
+    event->message[slen + len] = '\0';
+    trim_r (event->message);
+
+    /* Skip what we just added to the previous incomplete message. */
+    buf += len;
+    buf_len -= len;
+
+    if (buf_len == 0)          /* still not complete, more to come! */
+      return;
+
+    /* Skip the \n in the buffer. */
+    buf++;
+    buf_len--;
+    data->incomplete_log_message = -1;
+  }
+
+  /* Add the event, or perhaps multiple events if the message
+   * contains \n characters.
+   */
+  while (buf_len > 0) {
+    len = buf_len;
+    for (i = 0; i < buf_len; ++i) {
+      if (buf[i] == '\n') {
+        len = i;
+        break;
+      }
+    }
+
+    event = add_event (data, source);
+    event->message = strndup (buf, len);
+    if (event->message == NULL)
+      error (EXIT_FAILURE, errno, "strndup");
+    trim_r (event->message);
+
+    /* Skip what we just added to the event. */
+    buf += len;
+    buf_len -= len;
+
+    if (buf_len == 0) {
+      /* Event is incomplete (doesn't end with \n).  We'll finish it
+       * in the next callback.
+       */
+      data->incomplete_log_message = event - data->events;
+      return;
+    }
+
+    /* Skip the \n in the buffer. */
+    buf++;
+    buf_len--;
+  }
+}
+
+/* Called when we get a debug message from the library side.  These
+ * are always delivered as complete messages.
+ */
+static void
+library_callback (guestfs_h *g, void *datavp, uint64_t source,
+                  int eh, int flags,
+                  const char *buf, size_t buf_len,
+                  const uint64_t *array, size_t array_len)
+{
+  struct pass_data *data = datavp;
+  struct event *event;
+
+  if (!data->seen_launch)
+    return;
+
+  event = add_event (data, source);
+  event->message = strndup (buf, buf_len);
+  if (event->message == NULL)
+    error (EXIT_FAILURE, errno, "strndup");
+}
+
+/* Called when we get a call trace message (a libguestfs API function
+ * has been called or is returning).  These are always delivered as
+ * complete messages.
+ */
+static void
+trace_callback (guestfs_h *g, void *datavp, uint64_t source,
+                int eh, int flags,
+                const char *buf, size_t buf_len,
+                const uint64_t *array, size_t array_len)
+{
+  struct pass_data *data = datavp;
+  struct event *event;
+  char *message;
+
+  message = strndup (buf, buf_len);
+  if (message == NULL)
+    error (EXIT_FAILURE, errno, "strndup");
+
+  if (STREQ (message, "launch"))
+    data->seen_launch = 1;
+
+  if (!data->seen_launch) {
+    free (message);
+    return;
+  }
+
+  event = add_event (data, source);
+  event->message = message;
+}
+
+/* Common function to set up event callbacks and record data in memory
+ * for a particular pass (0 <= pass < NR_TEST_PASSES).
+ */
+static void
+set_up_event_handlers (guestfs_h *g, size_t pass)
+{
+  struct pass_data *data;
+
+  assert (/* 0 <= pass && */ pass < NR_TEST_PASSES);
+
+  data = &pass_data[pass];
+  data->pass = pass;
+  data->nr_events = 0;
+  data->events = NULL;
+  get_time (&data->start_t);
+  data->incomplete_log_message = -1;
+  data->seen_launch = 0;
+
+  guestfs_set_event_callback (g, close_callback,
+                              GUESTFS_EVENT_CLOSE, 0, data);
+  guestfs_set_event_callback (g, subprocess_quit_callback,
+                              GUESTFS_EVENT_SUBPROCESS_QUIT, 0, data);
+  guestfs_set_event_callback (g, launch_done_callback,
+                              GUESTFS_EVENT_LAUNCH_DONE, 0, data);
+  guestfs_set_event_callback (g, appliance_callback,
+                              GUESTFS_EVENT_APPLIANCE, 0, data);
+  guestfs_set_event_callback (g, library_callback,
+                              GUESTFS_EVENT_LIBRARY, 0, data);
+  guestfs_set_event_callback (g, trace_callback,
+                              GUESTFS_EVENT_TRACE, 0, data);
+
+  guestfs_set_verbose (g, 1);
+  guestfs_set_trace (g, 1);
+}
+
+/* Sanity check the collected events. */
+static void
+check_pass_data (void)
+{
+  size_t i, j, len;
+  int64_t ns;
+  const char *message;
+
+  for (i = 0; i < NR_TEST_PASSES; ++i) {
+    assert (pass_data[i].pass == i);
+    assert (pass_data[i].elapsed_ns > 1000);
+    assert (pass_data[i].nr_events > 0);
+    assert (pass_data[i].events != NULL);
+
+    for (j = 0; j < pass_data[i].nr_events; ++j) {
+      assert (pass_data[i].events[j].t.tv_sec > 0);
+      if (j > 0) {
+        ns = timespec_diff (&pass_data[i].events[j-1].t,
+                            &pass_data[i].events[j].t);
+        assert (ns >= 0);
+      }
+      assert (pass_data[i].events[j].source != 0);
+      message = pass_data[i].events[j].message;
+      assert (message != NULL);
+      assert (strchr (message, '\n') == NULL);
+      len = strlen (message);
+      assert (len == 0 || message[len-1] != '\r');
+    }
+  }
+}
+
+static void
+print_escaped_string (const char *message)
+{
+  while (*message) {
+    if (isprint (*message))
+      putchar (*message);
+    else
+      printf ("\\x%02x", (unsigned int) *message);
+    message++;
+  }
+}
+
+/* Dump the events to stdout, if verbose is set. */
+static void
+dump_pass_data (void)
+{
+  size_t i, j;
+
+  for (i = 0; i < NR_TEST_PASSES; ++i) {
+    printf ("pass %zu\n", pass_data[i].pass);
+    printf ("    number of events collected %zu\n",
pass_data[i].nr_events);
+    printf ("    elapsed time %" PRIi64 " ns\n",
pass_data[i].elapsed_ns);
+    for (j = 0; j < pass_data[i].nr_events; ++j) {
+      int64_t ns;
+      CLEANUP_FREE char *event_str = NULL;
+
+      ns = timespec_diff (&pass_data[i].start_t,
&pass_data[i].events[j].t);
+      event_str = guestfs_event_to_string (pass_data[i].events[j].source);
+      printf ("    #%zu: +%" PRIi64 " [%s] \"", j, ns,
event_str);
+      print_escaped_string (pass_data[i].events[j].message);
+      printf ("\"\n");
+    }
+  }
+}
+
+int
+activity_exists (const char *name)
+{
+  size_t i;
+
+  for (i = 0; i < nr_activities; ++i)
+    if (STREQ (activities[i].name, name))
+      return 1;
+  return 0;
+}
+
+/* Add an activity to the global list. */
+struct activity *
+add_activity (const char *name, int flags)
+{
+  struct activity *ret;
+  size_t i;
+
+  /* You shouldn't have two activities with the same name. */
+  assert (!activity_exists (name));
+
+  nr_activities++;
+  activities = realloc (activities, sizeof (struct activity) * nr_activities);
+  if (activities == NULL)
+    error (EXIT_FAILURE, errno, "realloc");
+  ret = &activities[nr_activities-1];
+  ret->name = strdup (name);
+  if (ret->name == NULL)
+    error (EXIT_FAILURE, errno, "strdup");
+  ret->flags = flags;
+
+  for (i = 0; i < NR_TEST_PASSES; ++i)
+    ret->start_event[i] = ret->end_event[i] = 0;
+
+  return ret;
+}
+
+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 ();
+}
+
+int
+activity_exists_with_no_data (const char *name, size_t pass)
+{
+  size_t i;
+
+  for (i = 0; i < nr_activities; ++i)
+    if (STREQ (activities[i].name, name) &&
+        activities[i].start_event[pass] == 0 &&
+        activities[i].end_event[pass] == 0)
+      return 1;
+  return 0;
+}
+
+static int
+compare_activities_by_t (const void *av, const void *bv)
+{
+  const struct activity *a = av;
+  const struct activity *b = bv;
+
+  return a->t - b->t;
+}
+
+/* Go through the activities, computing the start and elapsed time. */
+static void
+analyze_timeline (void)
+{
+  struct activity *activity;
+  size_t i, j;
+  int64_t delta_ns;
+
+  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 >= WARNING_THRESHOLD;
+  }
+
+  /* Sort the activities by start time. */
+  qsort (activities, nr_activities, sizeof (struct activity),
+         compare_activities_by_t);
+}
+
+/* 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_activity (struct activity *activity)
+{
+  if (activity->warning) ansi_red (); else ansi_green ();
+  print_escaped_string (activity->name);
+  ansi_restore ();
+  printf (" %1.6fs ±%.1fms ",
+          activity->mean / 1000000000, activity->sd / 1000000);
+  if (activity->warning) ansi_red (); else ansi_green ();
+  printf ("(%.1f%%) ", activity->percent);
+  ansi_restore ();
+}
+
+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) /* ▲ */
+        print_activity (&activities[columns[j]]);
+    }
+
+    printf ("\n");
+  }
+}
+
+static int
+compare_activities_pointers_by_mean (const void *av, const void *bv)
+{
+  const struct activity * const *a = av;
+  const struct activity * const *b = bv;
+
+  return (*b)->mean - (*a)->mean;
+}
+
+static void
+print_longest_to_shortest (void)
+{
+  size_t i;
+  CLEANUP_FREE struct activity **longest;
+
+  /* Sort the activities longest first.  In order not to affect the
+   * global activities array, sort an array of pointers to the
+   * activities instead.
+   */
+  longest = malloc (sizeof (struct activity *) * nr_activities);
+  for (i = 0; i < nr_activities; ++i)
+    longest[i] = &activities[i];
+
+  qsort (longest, nr_activities, sizeof (struct activity *),
+         compare_activities_pointers_by_mean);
+
+  /* Display the activities, longest first. */
+  for (i = 0; i < nr_activities; ++i) {
+    print_activity (longest[i]);
+    printf ("\n");
+  }
+}
+
+/* Free the non-static part of the pass_data structures. */
+static void
+free_pass_data (void)
+{
+  size_t i, j;
+
+  for (i = 0; i < NR_TEST_PASSES; ++i) {
+    for (j = 0; j < pass_data[i].nr_events; ++j)
+      free (pass_data[i].events[j].message);
+    free (pass_data[i].events);
+  }
+}
+
+static void
+free_final_timeline (void)
+{
+  size_t i;
+
+  for (i = 0; i < nr_activities; ++i)
+    free (activities[i].name);
+  free (activities);
+}
+
+/* Colours. */
+static void
+ansi_green (void)
+{
+  if (force_colour || isatty (1))
+    fputs ("\033[0;32m", stdout);
+}
+
+static void
+ansi_red (void)
+{
+  if (force_colour || isatty (1))
+    fputs ("\033[1;31m", stdout);
+}
+
+static void
+ansi_blue (void)
+{
+  if (force_colour || isatty (1))
+    fputs ("\033[1;34m", stdout);
+}
+
+static void
+ansi_magenta (void)
+{
+  if (force_colour || isatty (1))
+    fputs ("\033[1;35m", stdout);
+}
+
+static void
+ansi_restore (void)
+{
+  if (force_colour || isatty (1))
+    fputs ("\033[0m", stdout);
+}
diff --git a/tests/qemu/boot-analysis.h b/tests/qemu/boot-analysis.h
new file mode 100644
index 0000000..86d403e
--- /dev/null
+++ b/tests/qemu/boot-analysis.h
@@ -0,0 +1,94 @@
+/* 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.
+ */
+
+#ifndef GUESTFS_BOOT_ANALYSIS_H_
+#define GUESTFS_BOOT_ANALYSIS_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;
+};
+
+extern 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. */
+};
+
+extern size_t nr_activities;
+extern struct activity *activities;
+
+extern int activity_exists (const char *name);
+extern struct activity *add_activity (const char *name, int flags);
+extern struct activity *find_activity (const char *name);
+extern int activity_exists_with_no_data (const char *name, size_t pass);
+
+extern void construct_timeline (void);
+
+#endif /* GUESTFS_BOOT_ANALYSIS_H_ */
-- 
2.7.4

I accidentally (really) pushed these to the upstream branch instead of
my forked repo.  But they seem in good shape.

Rich.

-- 
Richard Jones, Virtualization Group, Red Hat http://people.redhat.com/~rjones
Read my programming and virtualization blog: http://rwmj.wordpress.com
virt-p2v converts physical machines to virtual machines.  Boot with a
live CD or over the network (PXE) and turn machines into KVM guests.
http://libguestfs.org/virt-v2v