From 07954ad0663456014c56ed4db0c1ab3f71846678 Mon Sep 17 00:00:00 2001

From: "Richard W.M. Jones" <rjones@redhat.com>

Date: Fri, 18 Mar 2016 18:00:51 +0000

Subject: [PATCH] tests/qemu: Add program for tracing and analyzing boot times.

(cherry picked from commit 0ba59db611fc2620bf47b50c6d0a71242a0800d7)

---

 .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 6436eeb..9c45df7 100644

--- a/.gitignore

+++ b/.gitignore

@@ -509,6 +509,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 4407bbb..4a04bce 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 }