Richard W.M. Jones
2016-Mar-20 12:30 UTC
[Libguestfs] [PATCH v2 0/7] tests/qemu: Add program for tracing and analyzing boot times.
v1 was here: https://www.redhat.com/archives/libguestfs/2016-March/thread.html#00157 Not running the 'hwclock' command reduces boot times considerably. However I'm not sure if it is safe. See the question I posted on qemu-devel: http://thread.gmane.org/gmane.comp.emulators.qemu/402194 At the moment, about 50% of the time is consumed by SeaBIOS. Of this, about ⅓rd is SGABIOS (it contains a useless ¼s sleep waiting for a keypress ... ffs!), and the other ⅔rds is something else in SeaBIOS. Simply removing SGABIOS improves boot times to below 2s, but at a cost that we cannot see any messages from SeaBIOS so further measurement and therefore improvement becomes impossible. I'm going to try to fix SeaBIOS/SGABIOS first. See also: http://thread.gmane.org/gmane.comp.emulators.qemu/402196 Rich.
Richard W.M. Jones
2016-Mar-20 12:30 UTC
[Libguestfs] [PATCH v2 1/7] appliance: Print location of udevd.
This is useful for debugging (but we can't print it unconditionally
since we cannot run grep etc yet). It also allows us to identify
when udevd is invoked so we can time it for boot analysis.
---
appliance/init | 8 +++++---
1 file changed, 5 insertions(+), 3 deletions(-)
diff --git a/appliance/init b/appliance/init
index f6fe9b9..657943c 100755
--- a/appliance/init
+++ b/appliance/init
@@ -65,10 +65,12 @@ systemd-tmpfiles --prefix=/dev --create --boot
for f in /sbin/udevd /lib/udev/udevd \
/lib/systemd/systemd-udevd /usr/lib/systemd/systemd-udevd \
/usr/lib/udev/udevd; do
- if [ -x "$f" ]; then UDEVD="$f"; fi
+ if [ -x "$f" ]; then UDEVD="$f"; fi
done
-if [ -z "$UDEVD" ]; then
- echo "udev not found! Things will probably not work ..."
+if [ -n "$UDEVD" ]; then
+ echo "UDEVD=$UDEVD"
+else
+ echo "WARNING: udev not found! Things will probably not work
..."
fi
$UDEVD --daemon #--debug
--
2.5.0
Richard W.M. Jones
2016-Mar-20 12:30 UTC
[Libguestfs] [PATCH v2 2/7] appliance: When using verbose mode, 'set -x' in the appliance init script.
---
appliance/init | 1 +
1 file changed, 1 insertion(+)
diff --git a/appliance/init b/appliance/init
index 657943c..d1ea9a6 100755
--- a/appliance/init
+++ b/appliance/init
@@ -95,6 +95,7 @@ hwclock -u -s
# Parse the kernel command line.
if grep -sq guestfs_verbose=1 /proc/cmdline; then
guestfs_verbose=1
+ set -x
fi
if grep -sq guestfs_network=1 /proc/cmdline; then
guestfs_network=1
--
2.5.0
Richard W.M. Jones
2016-Mar-20 12:31 UTC
[Libguestfs] [PATCH v2 3/7] appliance: Move /proc/cmdline checks earlier.
---
appliance/init | 30 +++++++++++++++---------------
1 file changed, 15 insertions(+), 15 deletions(-)
diff --git a/appliance/init b/appliance/init
index d1ea9a6..de028b3 100755
--- a/appliance/init
+++ b/appliance/init
@@ -77,21 +77,6 @@ $UDEVD --daemon #--debug
udevadm trigger
udevadm settle --timeout=600
-if grep -sq selinux=1 /proc/cmdline; then
- mount -t selinuxfs none /sys/fs/selinux
-fi
-
-# Disk optimizations.
-# Increase the SCSI timeout so we can read remote images.
-shopt -s nullglob
-for f in /sys/block/sd*/device/timeout; do echo 300 > $f; done
-# https://access.redhat.com/site/solutions/5427
-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
-
# Parse the kernel command line.
if grep -sq guestfs_verbose=1 /proc/cmdline; then
guestfs_verbose=1
@@ -108,6 +93,21 @@ if grep -sq guestfs_noreboot=1 /proc/cmdline; then
fi
eval `grep -Eo 'guestfs_channel=[^[:space:]]+' /proc/cmdline`
+if grep -sq selinux=1 /proc/cmdline; then
+ mount -t selinuxfs none /sys/fs/selinux
+fi
+
+# Disk optimizations.
+# Increase the SCSI timeout so we can read remote images.
+shopt -s nullglob
+for f in /sys/block/sd*/device/timeout; do echo 300 > $f; done
+# https://access.redhat.com/site/solutions/5427
+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.5.0
Richard W.M. Jones
2016-Mar-20 12:31 UTC
[Libguestfs] [PATCH v2 4/7] appliance: Don't run hwclock command.
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 de028b3..586f208 100755
--- a/appliance/init
+++ b/appliance/init
@@ -105,9 +105,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.5.0
Richard W.M. Jones
2016-Mar-20 12:31 UTC
[Libguestfs] [PATCH v2 5/7] launch: direct: Remove dead code promising we were going to use virtio-console.
We're never going to use virtio-console since, although it is faster,
it's not available during early boot, and that is more important for
debugging.
---
src/launch-direct.c | 10 ----------
1 file changed, 10 deletions(-)
diff --git a/src/launch-direct.c b/src/launch-direct.c
index a81d4b3..f1fe92b 100644
--- a/src/launch-direct.c
+++ b/src/launch-direct.c
@@ -574,19 +574,9 @@ launch_direct (guestfs_h *g, void *datav, const char *arg)
ADD_CMDLINE ("-device");
ADD_CMDLINE (VIRTIO_SERIAL);
-#if 0
- /* Use virtio-console (a variant form of virtio-serial) for the
- * guest's serial console.
- */
- ADD_CMDLINE ("-chardev");
- ADD_CMDLINE ("stdio,id=console");
- ADD_CMDLINE ("-device");
- ADD_CMDLINE
("virtconsole,chardev=console,name=org.libguestfs.console.0");
-#else
/* When the above works ... until then: */
ADD_CMDLINE ("-serial");
ADD_CMDLINE ("stdio");
-#endif
if (qemu_supports_device (g, data, "Serial Graphics Adapter")) {
/* Use sgabios instead of vgabios. This means we'll see BIOS
--
2.5.0
Richard W.M. Jones
2016-Mar-20 12:31 UTC
[Libguestfs] [PATCH v2 6/7] tests/qemu: Add program for tracing and analyzing boot times.
---
.gitignore | 1 +
appliance/init | 5 +-
tests/qemu/Makefile.am | 22 +-
tests/qemu/boot-analysis.c | 1195 ++++++++++++++++++++++++++++++++++++++++++++
4 files changed, 1219 insertions(+), 4 deletions(-)
create mode 100644 tests/qemu/boot-analysis.c
diff --git a/.gitignore b/.gitignore
index 1493011..9306a19 100644
--- a/.gitignore
+++ b/.gitignore
@@ -510,6 +510,7 @@ Makefile.in
/tests/mountable/test-internal-parse-mountable
/tests/parallel/test-parallel
/tests/protocol/test-error-messages
+/tests/qemu/boot-analysis
/tests/qemu/qemu-boot
/tests/qemu/qemu-speed-test
/tests/regressions/rhbz501893
diff --git a/appliance/init b/appliance/init
index 586f208..8225110 100755
--- a/appliance/init
+++ b/appliance/init
@@ -91,6 +91,9 @@ fi
if grep -sq guestfs_noreboot=1 /proc/cmdline; then
guestfs_noreboot=1
fi
+if grep -sq guestfs_boot_analysis=1 /proc/cmdline; then
+ guestfs_boot_analysis=1
+fi
eval `grep -Eo 'guestfs_channel=[^[:space:]]+' /proc/cmdline`
if grep -sq selinux=1 /proc/cmdline; then
@@ -131,7 +134,7 @@ lvm vgchange -aay --sysinit
ldmtool create all
# These are useful when debugging.
-if test "$guestfs_verbose" = 1; then
+if test "$guestfs_verbose" = 1 && test
"$guestfs_boot_analysis" != 1; then
uname -a
ls -lR /dev
cat /proc/mounts
diff --git a/tests/qemu/Makefile.am b/tests/qemu/Makefile.am
index 6c72b18..57ceeae 100644
--- a/tests/qemu/Makefile.am
+++ b/tests/qemu/Makefile.am
@@ -34,10 +34,10 @@ EXTRA_DIST = \
qemu-boot.c \
qemu-speed-test.c
-# qemu-boot & qemu-speed-test are built but not run by default as they
-# are mainly qemu & kernel diagnostic tools.
+# qemu-boot, qemu-speed-test and boot-analysis are built but not run
+# by default as they are mainly qemu & kernel diagnostic tools.
-check_PROGRAMS = qemu-boot qemu-speed-test
+check_PROGRAMS = qemu-boot qemu-speed-test boot-analysis
qemu_boot_SOURCES = \
../../df/estimate-max-threads.c \
@@ -76,6 +76,22 @@ qemu_speed_test_LDADD = \
$(LTLIBINTL) \
$(top_builddir)/gnulib/lib/libgnu.la
+boot_analysis_SOURCES = \
+ boot-analysis.c
+boot_analysis_CPPFLAGS = \
+ -I$(top_srcdir)/gnulib/lib -I$(top_builddir)/gnulib/lib \
+ -I$(top_srcdir)/src -I$(top_builddir)/src
+boot_analysis_CFLAGS = \
+ $(WARN_CFLAGS) $(WERROR_CFLAGS)
+boot_analysis_LDADD = \
+ $(top_builddir)/src/libutils.la \
+ $(top_builddir)/src/libguestfs.la \
+ $(LIBXML2_LIBS) \
+ $(LIBVIRT_LIBS) \
+ $(LTLIBINTL) \
+ $(top_builddir)/gnulib/lib/libgnu.la \
+ -lm
+
# Don't run these tests in parallel, since they are designed to check
# the integrity of qemu.
.NOTPARALLEL:
diff --git a/tests/qemu/boot-analysis.c b/tests/qemu/boot-analysis.c
new file mode 100644
index 0000000..9c7dd72
--- /dev/null
+++ b/tests/qemu/boot-analysis.c
@@ -0,0 +1,1195 @@
+/* libguestfs
+ * Copyright (C) 2016 Red Hat Inc.
+ *
+ * This program is free software; you can redistribute it and/or modify
+ * it under the terms of the GNU General Public License as published by
+ * the Free Software Foundation; either version 2 of the License, or
+ * (at your option) any later version.
+ *
+ * This program is distributed in the hope that it will be useful,
+ * but WITHOUT ANY WARRANTY; without even the implied warranty of
+ * MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the
+ * GNU General Public License for more details.
+ *
+ * You should have received a copy of the GNU General Public License along
+ * with this program; if not, write to the Free Software Foundation, Inc.,
+ * 51 Franklin Street, Fifth Floor, Boston, MA 02110-1301 USA.
+ */
+
+/* Trace and analyze the appliance boot process to find out which
+ * steps are taking the most time. It is not part of the standard
+ * tests.
+ *
+ * This needs to be run on a quiet machine, so that other processes
+ * disturb the timing as little as possible. The program is
+ * completely safe to run at any time. It doesn't read or write any
+ * external files, and it doesn't require root.
+ *
+ * You can run it from the build directory like this:
+ *
+ * make
+ * make -C tests/qemu boot-analysis
+ * ./run tests/qemu/boot-analysis
+ *
+ * The way it works is roughly like this:
+ *
+ * We create a libguestfs handle and register callback handlers so we
+ * can see appliance messages, trace events and so on.
+ *
+ * We then launch the handle and shut it down as quickly as possible.
+ *
+ * While the handle is running, events (seen by the callback handlers)
+ * are written verbatim into an in-memory buffer, with timestamps.
+ *
+ * Afterwards we analyze the result using regular expressions to try
+ * to identify a "timeline" for the handle (eg. at what time did the
+ * BIOS hand control to the kernel).
+ *
+ * The whole process is repeated across a few runs, and the final
+ * timeline (including statistical analysis of the variation between
+ * runs) gets printed.
+ *
+ * The program is very sensitive to the specific messages printed by
+ * BIOS/kernel/supermin/userspace, so it won't work on non-x86, and it
+ * will require periodic adjustment of the regular expressions in
+ * order to keep things up to date.
+ */
+
+#include <config.h>
+
+#include <stdio.h>
+#include <stdlib.h>
+#include <stdint.h>
+#include <inttypes.h>
+#include <string.h>
+#include <unistd.h>
+#include <getopt.h>
+#include <limits.h>
+#include <time.h>
+#include <errno.h>
+#include <error.h>
+#include <ctype.h>
+#include <assert.h>
+#include <math.h>
+
+#include "ignore-value.h"
+
+#include "guestfs.h"
+#include "guestfs-internal-frontend.h"
+
+#define NR_WARMUP_PASSES 3
+#define NR_TEST_PASSES 5
+
+/* Per-pass data collected. */
+struct pass_data {
+ size_t pass;
+ struct timespec start_t;
+ struct timespec end_t;
+ int64_t elapsed_ns;
+
+ /* Array of timestamped events. */
+ size_t nr_events;
+ struct event *events;
+
+ /* Was the previous appliance log message incomplete? If so, this
+ * contains the index of that incomplete message in the events
+ * array.
+ */
+ ssize_t incomplete_log_message;
+
+ /* Have we seen the launch event yet? We don't record events until
+ * this one has been received. This makes it easy to base the
+ * timeline at event 0.
+ */
+ int seen_launch;
+};
+
+struct event {
+ struct timespec t;
+ uint64_t source;
+ char *message;
+};
+
+static struct pass_data pass_data[NR_TEST_PASSES];
+
+/* The final timeline consisting of various activities starting and
+ * ending. We're interested in when the activities start, and how
+ * long they take (mean, variance, standard deviation of length).
+ */
+struct activity {
+ char *name; /* Name of this activity. */
+ int flags;
+#define LONG_ACTIVITY 1 /* Expected to take a long time. */
+
+ /* For each pass, record the actual start & end events of this
+ * activity.
+ */
+ size_t start_event[NR_TEST_PASSES];
+ size_t end_event[NR_TEST_PASSES];
+
+ double t; /* Start (ns offset). */
+ double end_t; /* t + mean - 1 */
+
+ /* Length of this activity. */
+ double mean; /* Mean time elapsed (ns). */
+ double variance; /* Variance. */
+ double sd; /* Standard deviation. */
+ double percent; /* Percent of total elapsed time. */
+
+ int warning; /* Appears in red. */
+};
+
+static size_t nr_activities;
+static struct activity *activities;
+
+static int verbose = 0;
+
+static void run_test (void);
+static void get_time (struct timespec *ts);
+static int64_t timespec_diff (const struct timespec *x, const struct timespec
*y);
+static struct event *add_event (struct pass_data *, uint64_t source);
+static guestfs_h *create_handle (void);
+static void set_up_event_handlers (guestfs_h *g, size_t pass);
+static void add_drive (guestfs_h *g);
+static void check_pass_data (void);
+static void dump_pass_data (void);
+static void construct_timeline (void);
+static void dump_timeline (void);
+static void print_info (void);
+static void print_analysis (void);
+static void free_pass_data (void);
+static void free_final_timeline (void);
+static void ansi_green (void);
+static void ansi_red (void);
+static void ansi_blue (void);
+static void ansi_magenta (void);
+static void ansi_restore (void);
+
+static void
+usage (int exitcode)
+{
+ fprintf (stderr,
+ "boot-analysis: Trace and analyze the appliance boot
process.\n"
+ "Usage:\n"
+ " boot-analysis [--options]\n"
+ "Options:\n"
+ " --help Display this usage text and exit.\n"
+ " -v|--verbose Verbose output, useful for
debugging.\n");
+ exit (exitcode);
+}
+
+int
+main (int argc, char *argv[])
+{
+ enum { HELP_OPTION = CHAR_MAX + 1 };
+ static const char *options = "v";
+ static const struct option long_options[] = {
+ { "help", 0, 0, HELP_OPTION },
+ { "verbose", 0, 0, 'v' },
+ { 0, 0, 0, 0 }
+ };
+ int c, option_index;
+
+ for (;;) {
+ c = getopt_long (argc, argv, options, long_options, &option_index);
+ if (c == -1) break;
+
+ switch (c) {
+ case 0:
+ /* Options which are long only. */
+ fprintf (stderr, "%s: unknown long option: %s (%d)\n",
+ guestfs_int_program_name, long_options[option_index].name,
option_index);
+ exit (EXIT_FAILURE);
+
+ case 'v':
+ verbose = 1;
+ break;
+
+ case HELP_OPTION:
+ usage (EXIT_SUCCESS);
+
+ default:
+ usage (EXIT_FAILURE);
+ }
+ }
+
+ if (STRNEQ (host_cpu, "x86_64"))
+ fprintf (stderr, "WARNING: host_cpu != x86_64: This program may not
work or give bogus results.\n");
+
+ run_test ();
+}
+
+static void
+run_test (void)
+{
+ guestfs_h *g;
+ size_t i;
+
+ printf ("Warming up the libguestfs cache ...\n");
+ for (i = 0; i < NR_WARMUP_PASSES; ++i) {
+ g = create_handle ();
+ add_drive (g);
+ if (guestfs_launch (g) == -1)
+ exit (EXIT_FAILURE);
+ guestfs_close (g);
+ }
+
+ printf ("Running the tests in %d passes ...\n", NR_TEST_PASSES);
+ for (i = 0; i < NR_TEST_PASSES; ++i) {
+ g = create_handle ();
+ set_up_event_handlers (g, i);
+ add_drive (g);
+ if (guestfs_launch (g) == -1)
+ exit (EXIT_FAILURE);
+ guestfs_close (g);
+
+ printf (" pass %zu: %zu events collected in %" PRIi64 "
ns\n",
+ i+1, pass_data[i].nr_events, pass_data[i].elapsed_ns);
+ }
+
+ if (verbose)
+ dump_pass_data ();
+
+ printf ("Analyzing the results ...\n");
+ check_pass_data ();
+ construct_timeline ();
+
+ if (verbose)
+ dump_timeline ();
+
+ printf ("\n");
+ print_info ();
+ printf ("\n");
+ print_analysis ();
+
+ free_pass_data ();
+ free_final_timeline ();
+}
+
+static void
+get_time (struct timespec *ts)
+{
+ if (clock_gettime (CLOCK_REALTIME, ts) == -1)
+ error (EXIT_FAILURE, errno, "clock_gettime: CLOCK_REALTIME");
+}
+
+/* Computes Y - X, returning nanoseconds. */
+static int64_t
+timespec_diff (const struct timespec *x, const struct timespec *y)
+{
+ int64_t nsec;
+
+ nsec = (y->tv_sec - x->tv_sec) * UINT64_C(1000000000);
+ nsec += y->tv_nsec - x->tv_nsec;
+ return nsec;
+}
+
+static struct event *
+add_event (struct pass_data *data, uint64_t source)
+{
+ struct event *ret;
+
+ data->nr_events++;
+ data->events = realloc (data->events,
+ sizeof (struct event) * data->nr_events);
+ if (data->events == NULL)
+ error (EXIT_FAILURE, errno, "realloc");
+ ret = &data->events[data->nr_events-1];
+ get_time (&ret->t);
+ ret->source = source;
+ ret->message = NULL;
+ return ret;
+}
+
+/* Common function to create the handle and set various defaults. */
+static guestfs_h *
+create_handle (void)
+{
+ guestfs_h *g;
+
+ g = guestfs_create ();
+ if (!g) error (EXIT_FAILURE, errno, "guestfs_create");
+
+ /* We always run these tests using LIBGUESTFS_BACKEND=direct. It
+ * may be in future we need to test libvirt as well, in case
+ * performance issues are suspected there, but so far libvirt has
+ * not been a bottleneck.
+ */
+ if (guestfs_set_backend (g, "direct") == -1)
+ exit (EXIT_FAILURE);
+
+ /* This changes some details in appliance/init. */
+ if (guestfs_set_append (g, "guestfs_boot_analysis=1") == -1)
+ exit (EXIT_FAILURE);
+
+ return g;
+}
+
+/* Common function to add the /dev/null drive. */
+static void
+add_drive (guestfs_h *g)
+{
+ if (guestfs_add_drive (g, "/dev/null") == -1)
+ exit (EXIT_FAILURE);
+}
+
+/* Called when the handle is closed. Perform any cleanups required in
+ * the pass_data here.
+ */
+static void
+close_callback (guestfs_h *g, void *datavp, uint64_t source,
+ int eh, int flags,
+ const char *buf, size_t buf_len,
+ const uint64_t *array, size_t array_len)
+{
+ struct pass_data *data = datavp;
+ struct event *event;
+
+ if (!data->seen_launch)
+ return;
+
+ event = add_event (data, source);
+ event->message = strdup ("close callback");
+ if (event->message == NULL)
+ error (EXIT_FAILURE, errno, "strdup");
+
+ get_time (&data->end_t);
+ data->elapsed_ns = timespec_diff (&data->start_t,
&data->end_t);
+}
+
+/* Called when the qemu subprocess exits.
+ * XXX This is never called - why?
+ */
+static void
+subprocess_quit_callback (guestfs_h *g, void *datavp, uint64_t source,
+ int eh, int flags,
+ const char *buf, size_t buf_len,
+ const uint64_t *array, size_t array_len)
+{
+ struct pass_data *data = datavp;
+ struct event *event;
+
+ if (!data->seen_launch)
+ return;
+
+ event = add_event (data, source);
+ event->message = strdup ("subprocess quit callback");
+ if (event->message == NULL)
+ error (EXIT_FAILURE, errno, "strdup");
+}
+
+/* Called when the launch operation is complete (the library and the
+ * guestfs daemon and talking to each other).
+ */
+static void
+launch_done_callback (guestfs_h *g, void *datavp, uint64_t source,
+ int eh, int flags,
+ const char *buf, size_t buf_len,
+ const uint64_t *array, size_t array_len)
+{
+ struct pass_data *data = datavp;
+ struct event *event;
+
+ if (!data->seen_launch)
+ return;
+
+ event = add_event (data, source);
+ event->message = strdup ("launch done callback");
+ if (event->message == NULL)
+ error (EXIT_FAILURE, errno, "strdup");
+}
+
+/* Trim \r (multiple) from the end of a string. */
+static void
+trim_r (char *message)
+{
+ size_t len = strlen (message);
+
+ while (len > 0 && message[len-1] == '\r') {
+ message[len-1] = '\0';
+ len--;
+ }
+}
+
+/* Called when we get (possibly part of) a log message (or more than
+ * one log message) from the appliance (which may include qemu, the
+ * BIOS, kernel, etc).
+ */
+static void
+appliance_callback (guestfs_h *g, void *datavp, uint64_t source,
+ int eh, int flags,
+ const char *buf, size_t buf_len,
+ const uint64_t *array, size_t array_len)
+{
+ struct pass_data *data = datavp;
+ struct event *event;
+ size_t i, len, slen;
+
+ if (!data->seen_launch)
+ return;
+
+ /* If the previous log message was incomplete then we may need to
+ * append part of the current log message to a previous one.
+ */
+ if (data->incomplete_log_message >= 0) {
+ len = buf_len;
+ for (i = 0; i < buf_len; ++i) {
+ if (buf[i] == '\n') {
+ len = i;
+ break;
+ }
+ }
+
+ event = &data->events[data->incomplete_log_message];
+ slen = strlen (event->message);
+ event->message = realloc (event->message, slen + len + 1);
+ if (event->message == NULL)
+ error (EXIT_FAILURE, errno, "realloc");
+ memcpy (event->message + slen, buf, len);
+ event->message[slen + len] = '\0';
+ trim_r (event->message);
+
+ /* Skip what we just added to the previous incomplete message. */
+ buf += len;
+ buf_len -= len;
+
+ if (buf_len == 0) /* still not complete, more to come! */
+ return;
+
+ /* Skip the \n in the buffer. */
+ buf++;
+ buf_len--;
+ data->incomplete_log_message = -1;
+ }
+
+ /* Add the event, or perhaps multiple events if the message
+ * contains \n characters.
+ */
+ while (buf_len > 0) {
+ len = buf_len;
+ for (i = 0; i < buf_len; ++i) {
+ if (buf[i] == '\n') {
+ len = i;
+ break;
+ }
+ }
+
+ event = add_event (data, source);
+ event->message = strndup (buf, len);
+ if (event->message == NULL)
+ error (EXIT_FAILURE, errno, "strndup");
+ trim_r (event->message);
+
+ /* Skip what we just added to the event. */
+ buf += len;
+ buf_len -= len;
+
+ if (buf_len == 0) {
+ /* Event is incomplete (doesn't end with \n). We'll finish it
+ * in the next callback.
+ */
+ data->incomplete_log_message = event - data->events;
+ return;
+ }
+
+ /* Skip the \n in the buffer. */
+ buf++;
+ buf_len--;
+ }
+}
+
+/* Called when we get a debug message from the library side. These
+ * are always delivered as complete messages.
+ */
+static void
+library_callback (guestfs_h *g, void *datavp, uint64_t source,
+ int eh, int flags,
+ const char *buf, size_t buf_len,
+ const uint64_t *array, size_t array_len)
+{
+ struct pass_data *data = datavp;
+ struct event *event;
+
+ if (!data->seen_launch)
+ return;
+
+ event = add_event (data, source);
+ event->message = strndup (buf, buf_len);
+ if (event->message == NULL)
+ error (EXIT_FAILURE, errno, "strndup");
+}
+
+/* Called when we get a call trace message (a libguestfs API function
+ * has been called or is returning). These are always delivered as
+ * complete messages.
+ */
+static void
+trace_callback (guestfs_h *g, void *datavp, uint64_t source,
+ int eh, int flags,
+ const char *buf, size_t buf_len,
+ const uint64_t *array, size_t array_len)
+{
+ struct pass_data *data = datavp;
+ struct event *event;
+ char *message;
+
+ message = strndup (buf, buf_len);
+ if (message == NULL)
+ error (EXIT_FAILURE, errno, "strndup");
+
+ if (STREQ (message, "launch"))
+ data->seen_launch = 1;
+
+ if (!data->seen_launch) {
+ free (message);
+ return;
+ }
+
+ event = add_event (data, source);
+ event->message = message;
+}
+
+/* Common function to set up event callbacks and record data in memory
+ * for a particular pass (0 <= pass < NR_TEST_PASSES).
+ */
+static void
+set_up_event_handlers (guestfs_h *g, size_t pass)
+{
+ struct pass_data *data;
+
+ assert (/* 0 <= pass && */ pass < NR_TEST_PASSES);
+
+ data = &pass_data[pass];
+ data->pass = pass;
+ data->nr_events = 0;
+ data->events = NULL;
+ get_time (&data->start_t);
+ data->incomplete_log_message = -1;
+ data->seen_launch = 0;
+
+ guestfs_set_event_callback (g, close_callback,
+ GUESTFS_EVENT_CLOSE, 0, data);
+ guestfs_set_event_callback (g, subprocess_quit_callback,
+ GUESTFS_EVENT_SUBPROCESS_QUIT, 0, data);
+ guestfs_set_event_callback (g, launch_done_callback,
+ GUESTFS_EVENT_LAUNCH_DONE, 0, data);
+ guestfs_set_event_callback (g, appliance_callback,
+ GUESTFS_EVENT_APPLIANCE, 0, data);
+ guestfs_set_event_callback (g, library_callback,
+ GUESTFS_EVENT_LIBRARY, 0, data);
+ guestfs_set_event_callback (g, trace_callback,
+ GUESTFS_EVENT_TRACE, 0, data);
+
+ guestfs_set_verbose (g, 1);
+ guestfs_set_trace (g, 1);
+}
+
+/* Sanity check the collected events. */
+static void
+check_pass_data (void)
+{
+ size_t i, j, len;
+ int64_t ns;
+ const char *message;
+
+ for (i = 0; i < NR_TEST_PASSES; ++i) {
+ assert (pass_data[i].pass == i);
+ assert (pass_data[i].elapsed_ns > 1000);
+ assert (pass_data[i].nr_events > 0);
+ assert (pass_data[i].events != NULL);
+
+ for (j = 0; j < pass_data[i].nr_events; ++j) {
+ assert (pass_data[i].events[j].t.tv_sec > 0);
+ if (j > 0) {
+ ns = timespec_diff (&pass_data[i].events[j-1].t,
+ &pass_data[i].events[j].t);
+ assert (ns >= 0);
+ }
+ assert (pass_data[i].events[j].source != 0);
+ message = pass_data[i].events[j].message;
+ assert (message != NULL);
+ assert (strchr (message, '\n') == NULL);
+ len = strlen (message);
+ assert (len == 0 || message[len-1] != '\r');
+ }
+ }
+}
+
+static void
+print_escaped_string (const char *message)
+{
+ while (*message) {
+ if (isprint (*message))
+ putchar (*message);
+ else
+ printf ("\\x%02x", (unsigned int) *message);
+ message++;
+ }
+}
+
+/* Dump the events to stdout, if verbose is set. */
+static void
+dump_pass_data (void)
+{
+ size_t i, j;
+
+ for (i = 0; i < NR_TEST_PASSES; ++i) {
+ printf ("pass %zu\n", pass_data[i].pass);
+ printf (" number of events collected %zu\n",
pass_data[i].nr_events);
+ printf (" elapsed time %" PRIi64 " ns\n",
pass_data[i].elapsed_ns);
+ for (j = 0; j < pass_data[i].nr_events; ++j) {
+ int64_t ns;
+ CLEANUP_FREE char *event_str = NULL;
+
+ ns = timespec_diff (&pass_data[i].start_t,
&pass_data[i].events[j].t);
+ event_str = guestfs_event_to_string (pass_data[i].events[j].source);
+ printf (" #%zu: +%" PRIi64 " [%s] \"", j, ns,
event_str);
+ print_escaped_string (pass_data[i].events[j].message);
+ printf ("\"\n");
+ }
+ }
+}
+
+/* Add an activity to the global list. */
+static struct activity *
+add_activity (const char *name, int flags)
+{
+ struct activity *ret;
+
+ nr_activities++;
+ activities = realloc (activities, sizeof (struct activity) * nr_activities);
+ if (activities == NULL)
+ error (EXIT_FAILURE, errno, "realloc");
+ ret = &activities[nr_activities-1];
+ ret->name = strdup (name);
+ if (ret->name == NULL)
+ error (EXIT_FAILURE, errno, "strdup");
+ ret->flags = flags;
+ return ret;
+}
+
+static struct activity *
+find_activity (const char *name)
+{
+ size_t i;
+
+ for (i = 0; i < nr_activities; ++i)
+ if (STREQ (activities[i].name, name))
+ return &activities[i];
+ error (EXIT_FAILURE, 0,
+ "internal error: could not find activity '%s'",
name);
+ /*NOTREACHED*/
+ abort ();
+}
+
+static int
+compare_activities (const void *av, const void *bv)
+{
+ const struct activity *a = av;
+ const struct activity *b = bv;
+
+ return a->t - b->t;
+}
+
+/* Analyze significant events from the events array, to form a
+ * timeline of activities.
+ */
+static void
+construct_timeline (void)
+{
+ size_t i, j, k;
+ struct pass_data *data;
+ struct activity *activity;
+ int64_t delta_ns;
+
+ for (i = 0; i < NR_TEST_PASSES; ++i) {
+ data = &pass_data[i];
+
+ /* Find an activity, by matching an event with the condition
+ * `begin_cond' through to the second event `end_cond'. Create an
+ * activity object in the timeline from the result.
+ */
+#define FIND(name, flags, begin_cond, end_cond) \
+ do { \
+ activity = NULL; \
+ for (j = 0; j < data->nr_events; ++j) { \
+ if (begin_cond) { \
+ for (k = j+1; k < data->nr_events; ++k) { \
+ if (end_cond) { \
+ if (i == 0) \
+ activity = add_activity (name, flags); \
+ else \
+ activity = find_activity (name); \
+ break; \
+ } \
+ } \
+ break; \
+ } \
+ } \
+ if (activity) { \
+ activity->start_event[i] = j; \
+ activity->end_event[i] = k; \
+ } \
+ else \
+ error (EXIT_FAILURE, 0, "could not find activity '%s' in
pass '%zu'", \
+ name, i); \
+ } while (0)
+
+#if 0
+ /* Same as FIND() macro, but if no matching events are found,
+ * ignore it.
+ */
+#define FIND_OPTIONAL(name, flags, begin_cond, end_cond) \
+ do { \
+ activity = NULL; \
+ for (j = 0; j < data->nr_events; ++j) { \
+ if (begin_cond) { \
+ for (k = j+1; k < data->nr_events; ++k) { \
+ if (end_cond) { \
+ if (i == 0) \
+ activity = add_activity (name, flags); \
+ else \
+ activity = find_activity (name); \
+ break; \
+ } \
+ } \
+ break; \
+ } \
+ } \
+ if (activity) { \
+ activity->start_event[i] = j; \
+ activity->end_event[i] = k; \
+ } \
+ } while (0)
+#endif
+
+#define FIND_MULTIPLE(debug_name, flags, next_cond, end_cond) \
+ do { \
+ activity = NULL; \
+ for (j = 0; j < data->nr_events; ++j) { \
+ if (next_cond) { \
+ if (activity) \
+ activity->end_event[i] = j; \
+ if (i == 0) \
+ activity = add_activity (data->events[j].message, flags); \
+ else \
+ activity = find_activity (data->events[j].message); \
+ activity->start_event[i] = j; \
+ } \
+ else if (end_cond) \
+ break; \
+ } \
+ if (j < data->nr_events && activity)
\
+ activity->end_event[i] = j; \
+ else \
+ error (EXIT_FAILURE, 0, "could not find activity '%s' in
pass '%zu'", \
+ debug_name, i); \
+ } while (0)
+
+ /* Add one activity which is going to cover the whole process
+ * from launch to close. The launch event is always event 0.
+ * NB: This activity must be called "run" (see below).
+ */
+ FIND ("run", LONG_ACTIVITY,
+ j == 0, data->events[k].source == GUESTFS_EVENT_CLOSE);
+
+ /* Find where we invoke supermin --build. This should be a null
+ * operation, but it still takes time to run the external command.
+ */
+ FIND ("supermin:build", 0,
+ data->events[j].source == GUESTFS_EVENT_LIBRARY &&
+ strstr (data->events[j].message,
+ "begin building supermin appliance"),
+ data->events[k].source == GUESTFS_EVENT_LIBRARY &&
+ strstr (data->events[k].message,
+ "finished building supermin appliance"));
+
+ /* Find where we invoke qemu to test features. */
+ FIND ("qemu:feature-detect", 0,
+ data->events[j].source == GUESTFS_EVENT_LIBRARY &&
+ strstr (data->events[j].message,
+ "begin testing qemu features"),
+ data->events[k].source == GUESTFS_EVENT_LIBRARY &&
+ strstr (data->events[k].message,
+ "finished testing qemu features"));
+
+ /* Find where we run qemu. */
+ FIND ("qemu", LONG_ACTIVITY,
+ data->events[j].source == GUESTFS_EVENT_APPLIANCE &&
+ strstr (data->events[j].message, "-nodefconfig"),
+ data->events[k].source == GUESTFS_EVENT_CLOSE);
+
+#define SGABIOS_STRING "\033[1;256r\033[256;256H\033[6n"
+
+ /* From starting qemu up to entering the BIOS is the qemu overhead. */
+ FIND ("qemu:overhead", 0,
+ data->events[j].source == GUESTFS_EVENT_APPLIANCE &&
+ strstr (data->events[j].message, "-nodefconfig"),
+ data->events[k].source == GUESTFS_EVENT_APPLIANCE &&
+ strstr (data->events[k].message, SGABIOS_STRING));
+
+ /* From entering the BIOS to starting the kernel is the BIOS overhead. */
+ FIND ("bios:overhead", 0,
+ data->events[j].source == GUESTFS_EVENT_APPLIANCE &&
+ strstr (data->events[j].message, SGABIOS_STRING),
+ data->events[k].source == GUESTFS_EVENT_APPLIANCE &&
+ strstr (data->events[k].message, "Linux version"));
+
+ /* SGABIOS (option ROM). */
+ FIND ("sgabios", 0,
+ data->events[j].source == GUESTFS_EVENT_APPLIANCE &&
+ strstr (data->events[j].message, SGABIOS_STRING),
+ data->events[k].source == GUESTFS_EVENT_APPLIANCE &&
+ strstr (data->events[k].message, "SeaBIOS (version"));
+
+ /* SeaBIOS. */
+ FIND ("seabios", 0,
+ data->events[j].source == GUESTFS_EVENT_APPLIANCE &&
+ strstr (data->events[j].message, "SeaBIOS (version"),
+ data->events[k].source == GUESTFS_EVENT_APPLIANCE &&
+ strstr (data->events[k].message, "Linux version"));
+
+ /* Find where we run the guest kernel. */
+ FIND ("kernel", LONG_ACTIVITY,
+ data->events[j].source == GUESTFS_EVENT_APPLIANCE &&
+ strstr (data->events[j].message, "Linux version"),
+ data->events[k].source == GUESTFS_EVENT_CLOSE);
+
+ /* Kernel startup. */
+ FIND ("kernel:overhead", 0,
+ data->events[j].source == GUESTFS_EVENT_APPLIANCE &&
+ strstr (data->events[j].message, "Linux version"),
+ data->events[k].source == GUESTFS_EVENT_APPLIANCE &&
+ strstr (data->events[k].message, "supermin:") &&
+ strstr (data->events[k].message, "starting up"));
+
+ /* XXX More detailed look at kernel boot stages here. */
+
+ /* Find where we run supermin mini-initrd. */
+ FIND ("supermin:mini-initrd", 0,
+ data->events[j].source == GUESTFS_EVENT_APPLIANCE &&
+ strstr (data->events[j].message, "supermin:") &&
+ strstr (data->events[j].message, "starting up"),
+ data->events[k].source == GUESTFS_EVENT_APPLIANCE &&
+ strstr (data->events[k].message, "supermin: chroot"));
+
+ /* Loading kernel modules from supermin initrd. */
+ FIND_MULTIPLE
+ ("supermin insmod", 0,
+ data->events[j].source == GUESTFS_EVENT_APPLIANCE &&
+ strstr (data->events[j].message, "supermin: internal
insmod"),
+ data->events[j].source == GUESTFS_EVENT_APPLIANCE &&
+ strstr (data->events[j].message, "supermin: picked"));
+
+ /* Find where we run the /init script. */
+ FIND ("/init", 0,
+ data->events[j].source == GUESTFS_EVENT_APPLIANCE &&
+ strstr (data->events[j].message, "supermin: chroot"),
+ data->events[k].source == GUESTFS_EVENT_APPLIANCE &&
+ strstr (data->events[k].message, "guestfsd --verbose"));
+
+ /* Everything from the chroot to the first echo in the /init
+ * script counts as bash overhead.
+ */
+ FIND ("bash:overhead", 0,
+ data->events[j].source == GUESTFS_EVENT_APPLIANCE &&
+ strstr (data->events[j].message, "supermin: chroot"),
+ data->events[k].source == GUESTFS_EVENT_APPLIANCE &&
+ strstr (data->events[k].message, "Starting /init
script"));
+
+ /* Find where we run guestfsd. */
+ FIND ("guestfsd", 0,
+ data->events[j].source == GUESTFS_EVENT_APPLIANCE &&
+ strstr (data->events[j].message, "guestfsd --verbose"),
+ data->events[k].source == GUESTFS_EVENT_APPLIANCE &&
+ strstr (data->events[k].message, "fsync /dev/sda"));
+
+ /* Shutdown process. */
+ FIND ("shutdown", 0,
+ data->events[j].source == GUESTFS_EVENT_TRACE &&
+ STREQ (data->events[j].message, "close"),
+ data->events[k].source == GUESTFS_EVENT_CLOSE);
+ }
+
+ /* Now we can go through the activities, computing the start and
+ * elapsed time.
+ */
+ for (j = 0; j < nr_activities; ++j) {
+ activity = &activities[j];
+
+ activity->t = 0;
+ activity->mean = 0;
+ for (i = 0; i < NR_TEST_PASSES; ++i) {
+ delta_ns + timespec_diff (&pass_data[i].events[0].t,
+
&pass_data[i].events[activity->start_event[i]].t);
+ activity->t += delta_ns;
+
+ delta_ns + timespec_diff
(&pass_data[i].events[activity->start_event[i]].t,
+ &pass_data[i].events[activity->end_event[i]].t);
+ activity->mean += delta_ns;
+ }
+
+ /* Divide through to get real start time and mean of each activity. */
+ activity->t /= NR_TEST_PASSES;
+ activity->mean /= NR_TEST_PASSES;
+
+ /* Calculate the end time of this activity. It's convenient when
+ * drawing the timeline for one activity to finish just before the
+ * next activity starts, rather than having them end and start at
+ * the same time, hence ``- 1'' here.
+ */
+ activity->end_t = activity->t + activity->mean - 1;
+
+ /* The above only calculated mean. Now we are able to
+ * calculate from the mean the variance and the standard
+ * deviation.
+ */
+ activity->variance = 0;
+ for (i = 0; i < NR_TEST_PASSES; ++i) {
+ delta_ns + timespec_diff
(&pass_data[i].events[activity->start_event[i]].t,
+ &pass_data[i].events[activity->end_event[i]].t);
+ activity->variance += pow (delta_ns - activity->mean, 2);
+ }
+ activity->variance /= NR_TEST_PASSES;
+
+ activity->sd = sqrt (activity->variance);
+ }
+
+ /* Get the total mean elapsed time from the special "run" activity.
*/
+ activity = find_activity ("run");
+ for (j = 0; j < nr_activities; ++j) {
+ activities[j].percent = 100.0 * activities[j].mean / activity->mean;
+
+ activities[j].warning + !(activities[j].flags & LONG_ACTIVITY)
&& activities[j].percent >= 5.0;
+ }
+
+ /* Sort the activities by start time. */
+ qsort (activities, nr_activities, sizeof (struct activity),
+ compare_activities);
+}
+
+/* Dump the timeline to stdout, if verbose is set. */
+static void
+dump_timeline (void)
+{
+ size_t i;
+
+ for (i = 0; i < nr_activities; ++i) {
+ printf ("activity %zu:\n", i);
+ printf (" name = %s\n", activities[i].name);
+ printf (" start - end = %.1f - %.1f\n",
+ activities[i].t, activities[i].end_t);
+ printf (" mean elapsed = %.1f\n", activities[i].mean);
+ printf (" variance = %.1f\n", activities[i].variance);
+ printf (" s.d = %.1f\n", activities[i].sd);
+ printf (" percent = %.1f\n", activities[i].percent);
+ }
+}
+
+/* Print some information that will allow us to determine the test
+ * system when reviewing the results in future.
+ */
+static void
+print_info (void)
+{
+ size_t i;
+
+ printf ("%s %s\n", PACKAGE_NAME, PACKAGE_VERSION_FULL);
+
+ printf ("Host:\n");
+ ignore_value (system ("uname -a"));
+ ignore_value (system ("grep '^model name' /proc/cpuinfo | head
-1"));
+
+ /* We can dig some information about qemu and the appliance out of
+ * the events.
+ */
+ printf ("Appliance:\n");
+ assert (NR_TEST_PASSES > 0);
+ for (i = 0; i < pass_data[0].nr_events; ++i) {
+ const char *message = pass_data[0].events[i].message;
+ if (strstr (message, "qemu version") ||
+ (strstr (message, "SeaBIOS") && strstr (message,
"version")) ||
+ strstr (message, "Linux version") ||
+ (strstr (message, "supermin") && strstr (message,
"starting up"))) {
+ print_escaped_string (message);
+ putchar ('\n');
+ }
+ }
+}
+
+static void
+print_analysis (void)
+{
+ double t = -1; /* Current time. */
+ /* Which columns contain activities that we are displaying now?
+ * -1 == unused column, else index of an activity
+ */
+ CLEANUP_FREE ssize_t *columns = NULL;
+ const size_t nr_columns = nr_activities;
+ size_t last_free_column = 0;
+
+ size_t i, j;
+ double last_t, smallest_next_t;
+ const double MAX_T = 1e20;
+
+ columns = malloc (nr_columns * sizeof (ssize_t));
+ if (columns == NULL) error (EXIT_FAILURE, errno, "malloc");
+ for (j = 0; j < nr_columns; ++j)
+ columns[j] = -1;
+
+ for (;;) {
+ /* Find the next significant time to display, which is a time when
+ * some activity started or ended.
+ */
+ smallest_next_t = MAX_T;
+ for (i = 0; i < nr_activities; ++i) {
+ if (t < activities[i].t && activities[i].t <
smallest_next_t)
+ smallest_next_t = activities[i].t;
+ else if (t < activities[i].end_t && activities[i].end_t <
smallest_next_t)
+ smallest_next_t = activities[i].end_t;
+ }
+ if (smallest_next_t == MAX_T)
+ break; /* Finished. */
+
+ last_t = t;
+ t = smallest_next_t;
+
+ /* Draw a spacer line, but only if last_t -> t is a large jump. */
+ if (t - last_t >= 1000000 /* ns */) {
+ printf (" ");
+ ansi_magenta ();
+ for (j = 0; j < last_free_column; ++j) {
+ if (columns[j] >= 0 &&
+ activities[columns[j]].end_t != last_t /* !▼ */)
+ printf ("│ ");
+ else
+ printf (" ");
+ }
+ ansi_restore ();
+ printf ("\n");
+ }
+
+ /* If there are any activities that ended before this time, drop
+ * them from the columns list.
+ */
+ for (i = 0; i < nr_activities; ++i) {
+ if (activities[i].end_t < t) {
+ for (j = 0; j < nr_columns; ++j)
+ if (columns[j] == (ssize_t) i) {
+ columns[j] = -1;
+ break;
+ }
+ }
+ }
+
+ /* May need to adjust last_free_column after previous operation. */
+ while (last_free_column > 0 && columns[last_free_column-1] ==
-1)
+ last_free_column--;
+
+ /* If there are any activities starting at this time, add them to
+ * the right hand end of the columns list.
+ */
+ for (i = 0; i < nr_activities; ++i) {
+ if (activities[i].t == t)
+ columns[last_free_column++] = i;
+ }
+
+ /* Draw the line. */
+ ansi_blue ();
+ printf ("%1.6fs: ", t / 1000000000);
+
+ ansi_magenta ();
+ for (j = 0; j < last_free_column; ++j) {
+ if (columns[j] >= 0) {
+ if (activities[columns[j]].t == t)
+ printf ("▲ ");
+ else if (activities[columns[j]].end_t == t)
+ printf ("▼ ");
+ else
+ printf ("│ ");
+ }
+ else
+ printf (" ");
+ }
+ ansi_restore ();
+
+ for (j = 0; j < last_free_column; ++j) {
+ if (columns[j] >= 0 && activities[columns[j]].t == t) /* ▲ */
{
+ if (activities[columns[j]].warning) ansi_red (); else ansi_green ();
+ print_escaped_string (activities[columns[j]].name);
+ ansi_restore ();
+ printf (" mean:%1.6fs ±%.1fms ",
+ activities[columns[j]].mean / 1000000000,
+ activities[columns[j]].sd / 1000000);
+ if (activities[columns[j]].warning) ansi_red (); else ansi_green ();
+ printf ("(%.1f%%) ", activities[columns[j]].percent);
+ ansi_restore ();
+ }
+ }
+
+ printf ("\n");
+ }
+}
+
+/* Free the non-static part of the pass_data structures. */
+static void
+free_pass_data (void)
+{
+ size_t i, j;
+
+ for (i = 0; i < NR_TEST_PASSES; ++i) {
+ for (j = 0; j < pass_data[i].nr_events; ++j)
+ free (pass_data[i].events[j].message);
+ free (pass_data[i].events);
+ }
+}
+
+static void
+free_final_timeline (void)
+{
+ size_t i;
+
+ for (i = 0; i < nr_activities; ++i)
+ free (activities[i].name);
+ free (activities);
+}
+
+/* Colours. */
+static void
+ansi_green (void)
+{
+ if (isatty (1))
+ fputs ("\033[0;32m", stdout);
+}
+
+static void
+ansi_red (void)
+{
+ if (isatty (1))
+ fputs ("\033[1;31m", stdout);
+}
+
+static void
+ansi_blue (void)
+{
+ if (isatty (1))
+ fputs ("\033[1;34m", stdout);
+}
+
+static void
+ansi_magenta (void)
+{
+ if (isatty (1))
+ fputs ("\033[1;35m", stdout);
+}
+
+static void
+ansi_restore (void)
+{
+ if (isatty (1))
+ fputs ("\033[0m", stdout);
+}
--
2.5.0
Richard W.M. Jones
2016-Mar-20 12:31 UTC
[Libguestfs] [PATCH v2 7/7] launch: Remove guestfs_int_print_timestamped_message function.
This function was kind of like debug(), except that it didn't check
the g->verbose flag and it only worked in the library (it would crash
if used after fork).
It also wasn't very useful. The sort of boot analysis done by
tests/qemu/boot-analysis.c means that timestamping (some) messages is
even less interesting than before.
Remove it and replace calls with debug() instead.
---
src/appliance.c | 9 +++------
src/guestfs-internal.h | 1 -
src/launch-direct.c | 9 +++------
src/launch-libvirt.c | 21 +++++++--------------
src/launch-uml.c | 3 +--
src/launch-unix.c | 6 ++----
src/launch.c | 25 -------------------------
7 files changed, 16 insertions(+), 58 deletions(-)
diff --git a/src/appliance.c b/src/appliance.c
index de088e9..864761f 100644
--- a/src/appliance.c
+++ b/src/appliance.c
@@ -233,18 +233,15 @@ build_supermin_appliance (guestfs_h *g,
}
(void) utimes (cachedir, NULL);
- if (g->verbose)
- guestfs_int_print_timestamped_message (g, "begin building supermin
appliance");
+ debug (g, "begin building supermin appliance");
/* Build the appliance if it needs to be built. */
- if (g->verbose)
- guestfs_int_print_timestamped_message (g, "run supermin");
+ debug (g, "run supermin");
if (run_supermin_build (g, lockfile, appliancedir, supermin_path) == -1)
return -1;
- if (g->verbose)
- guestfs_int_print_timestamped_message (g, "finished building supermin
appliance");
+ debug (g, "finished building supermin appliance");
/* Return the appliance filenames. */
*kernel = safe_asprintf (g, "%s/kernel", appliancedir);
diff --git a/src/guestfs-internal.h b/src/guestfs-internal.h
index 3707c1b..61f384c 100644
--- a/src/guestfs-internal.h
+++ b/src/guestfs-internal.h
@@ -778,7 +778,6 @@ extern int guestfs_int_get_uefi (guestfs_h *g, char **code,
char **vars);
/* launch.c */
extern int64_t guestfs_int_timeval_diff (const struct timeval *x, const struct
timeval *y);
-extern void guestfs_int_print_timestamped_message (guestfs_h *g, const char
*fs, ...) __attribute__((format (printf,2,3)));
extern void guestfs_int_launch_send_progress (guestfs_h *g, int perdozen);
extern char *guestfs_int_appliance_command_line (guestfs_h *g, const char
*appliance_dev, int flags);
#define APPLIANCE_COMMAND_LINE_IS_TCG 1
diff --git a/src/launch-direct.c b/src/launch-direct.c
index f1fe92b..3ed840d 100644
--- a/src/launch-direct.c
+++ b/src/launch-direct.c
@@ -285,8 +285,7 @@ launch_direct (guestfs_h *g, void *datav, const char *arg)
guestfs_int_launch_send_progress (g, 3);
- if (g->verbose)
- guestfs_int_print_timestamped_message (g, "begin testing qemu
features");
+ debug (g, "begin testing qemu features");
/* Get qemu help text and version. */
if (qemu_supports (g, data, NULL) == -1)
@@ -327,8 +326,7 @@ launch_direct (guestfs_h *g, void *datav, const char *arg)
}
}
- if (g->verbose)
- guestfs_int_print_timestamped_message (g, "finished testing qemu
features");
+ debug (g, "finished testing qemu features");
/* Construct the qemu command line. We have to do this before
* forking, because after fork we are not allowed to use
@@ -815,8 +813,7 @@ launch_direct (guestfs_h *g, void *datav, const char *arg)
goto cleanup1;
}
- if (g->verbose)
- guestfs_int_print_timestamped_message (g, "appliance is up");
+ debug (g, "appliance is up");
/* This is possible in some really strange situations, such as
* guestfsd starts up OK but then qemu immediately exits. Check for
diff --git a/src/launch-libvirt.c b/src/launch-libvirt.c
index cdc83f4..9f2672d 100644
--- a/src/launch-libvirt.c
+++ b/src/launch-libvirt.c
@@ -286,8 +286,7 @@ launch_libvirt (guestfs_h *g, void *datav, const char
*libvirt_uri)
}
debug (g, "guest random name = %s", data->name);
- if (g->verbose)
- guestfs_int_print_timestamped_message (g, "connect to libvirt");
+ debug (g, "connect to libvirt");
/* Decode the URI string. */
if (!libvirt_uri) { /* "libvirt" */
@@ -326,8 +325,7 @@ launch_libvirt (guestfs_h *g, void *datav, const char
*libvirt_uri)
data->qemu_version = 0;
}
- if (g->verbose)
- guestfs_int_print_timestamped_message (g, "get libvirt
capabilities");
+ debug (g, "get libvirt capabilities");
capabilities_xml = virConnectGetCapabilities (conn);
if (!capabilities_xml) {
@@ -339,8 +337,7 @@ launch_libvirt (guestfs_h *g, void *datav, const char
*libvirt_uri)
* struct, and can also fail if we detect that the hypervisor cannot
* run qemu guests (RHBZ#886915).
*/
- if (g->verbose)
- guestfs_int_print_timestamped_message (g, "parsing capabilities
XML");
+ debug (g, "parsing capabilities XML");
if (parse_capabilities (g, capabilities_xml, data) == -1)
goto cleanup;
@@ -373,8 +370,7 @@ launch_libvirt (guestfs_h *g, void *datav, const char
*libvirt_uri)
/* Locate and/or build the appliance. */
TRACE0 (launch_build_libvirt_appliance_start);
- if (g->verbose)
- guestfs_int_print_timestamped_message (g, "build appliance");
+ debug (g, "build appliance");
if (guestfs_int_build_appliance (g, ¶ms.kernel, ¶ms.initrd,
&appliance) == -1)
@@ -503,8 +499,7 @@ launch_libvirt (guestfs_h *g, void *datav, const char
*libvirt_uri)
}
/* Construct the libvirt XML. */
- if (g->verbose)
- guestfs_int_print_timestamped_message (g, "create libvirt XML");
+ debug (g, "create libvirt XML");
params.appliance_index = g->nr_drives;
strcpy (params.appliance_dev, "/dev/sd");
@@ -522,8 +517,7 @@ launch_libvirt (guestfs_h *g, void *datav, const char
*libvirt_uri)
}
/* Launch the libvirt guest. */
- if (g->verbose)
- guestfs_int_print_timestamped_message (g, "launch libvirt
guest");
+ debug (g, "launch libvirt guest");
dom = virDomainCreateXML (conn, (char *) xml, VIR_DOMAIN_START_AUTODESTROY);
if (!dom) {
@@ -591,8 +585,7 @@ launch_libvirt (guestfs_h *g, void *datav, const char
*libvirt_uri)
goto cleanup;
}
- if (g->verbose)
- guestfs_int_print_timestamped_message (g, "appliance is up");
+ debug (g, "appliance is up");
/* This is possible in some really strange situations, such as
* guestfsd starts up OK but then qemu immediately exits. Check for
diff --git a/src/launch-uml.c b/src/launch-uml.c
index 1c2fd02..318081c 100644
--- a/src/launch-uml.c
+++ b/src/launch-uml.c
@@ -446,8 +446,7 @@ launch_uml (guestfs_h *g, void *datav, const char *arg)
goto cleanup1;
}
- if (g->verbose)
- guestfs_int_print_timestamped_message (g, "appliance is up");
+ debug (g, "appliance is up");
/* This is possible in some really strange situations, such as
* guestfsd starts up OK but then vmlinux immediately exits. Check
diff --git a/src/launch-unix.c b/src/launch-unix.c
index 973e14b..212de69 100644
--- a/src/launch-unix.c
+++ b/src/launch-unix.c
@@ -53,8 +53,7 @@ launch_unix (guestfs_h *g, void *datav, const char *sockpath)
return -1;
}
- if (g->verbose)
- guestfs_int_print_timestamped_message (g, "connecting to %s",
sockpath);
+ debug (g, "connecting to %s", sockpath);
daemon_sock = socket (AF_UNIX, SOCK_STREAM|SOCK_CLOEXEC, 0);
if (daemon_sock == -1) {
@@ -90,8 +89,7 @@ launch_unix (guestfs_h *g, void *datav, const char *sockpath)
goto cleanup;
}
- if (g->verbose)
- guestfs_int_print_timestamped_message (g, "connected");
+ debug (g, "connected");
if (g->state != READY) {
error (g, _("contacted guestfsd, but state != READY"));
diff --git a/src/launch.c b/src/launch.c
index 074ac6f..f553bd3 100644
--- a/src/launch.c
+++ b/src/launch.c
@@ -119,31 +119,6 @@ guestfs_int_launch_send_progress (guestfs_h *g, int
perdozen)
}
}
-/* Note that since this calls 'debug' it should only be called
- * from the parent process.
- */
-void
-guestfs_int_print_timestamped_message (guestfs_h *g, const char *fs, ...)
-{
- va_list args;
- char *msg;
- int err;
- struct timeval tv;
-
- va_start (args, fs);
- err = vasprintf (&msg, fs, args);
- va_end (args);
-
- if (err < 0) return;
-
- gettimeofday (&tv, NULL);
-
- debug (g, "[%05" PRIi64 "ms] %s",
- guestfs_int_timeval_diff (&g->launch_t, &tv), msg);
-
- free (msg);
-}
-
/* Compute Y - X and return the result in milliseconds.
* Approximately the same as this code:
* http://www.mpp.mpg.de/~huber/util/timevaldiff.c
--
2.5.0
Richard W.M. Jones
2016-Mar-20 12:40 UTC
Re: [Libguestfs] [PATCH v2 0/7] tests/qemu: Add program for tracing and analyzing boot times.
Typical analysis from this program attached.
(The real output from the program has pretty colours ...)
Rich.
--
Richard Jones, Virtualization Group, Red Hat http://people.redhat.com/~rjones
Read my programming and virtualization blog: http://rwmj.wordpress.com
virt-df lists disk usage of guests without needing to install any
software inside the virtual machine. Supports Linux and Windows.
http://people.redhat.com/~rjones/virt-df/
--7ZAtKRhVyVSsbBD2
Content-Type: text/plain; charset=utf-8
Content-Disposition: attachment; filename="analysis.txt"
Content-Transfer-Encoding: 8bit
Linux moo.home.annexia.org 4.4.4-301.fc23.x86_64 #1 SMP Fri Mar 4 17:42:42 UTC
2016 x86_64 x86_64 x86_64 GNU/Linux
model name : Intel(R) Core(TM) i7-5600U CPU @ 2.60GHz
Warming up the libguestfs cache ...
Running the tests in 2 passes ...
pass 1: 461 events collected in 2282816890 ns
pass 2: 461 events collected in 2266873397 ns
pass 0
number of events collected 461
elapsed time 2282816890 ns
#0: +147443 [trace] "launch"
#1: +151110 [trace] "version"
#2: +159516 [trace] "version = <struct guestfs_version = major: 1,
minor: 33, release: 15, extra: , >"
#3: +161830 [trace] "get_backend"
#4: +163814 [trace] "get_backend = "direct""
#5: +164982 [library] "launch: program=boot-analysis"
#6: +165903 [library] "launch: version=1.33.15"
#7: +166831 [library] "launch: backend registered: unix"
#8: +167616 [library] "launch: backend registered: uml"
#9: +168287 [library] "launch: backend registered: libvirt"
#10: +168899 [library] "launch: backend registered: direct"
#11: +169474 [library] "launch: backend=direct"
#12: +170141 [library] "launch:
tmpdir=/home/rjones/d/libguestfs/tmp/libguestfsDOucPz"
#13: +202457 [library] "launch: umask=0002"
#14: +203374 [library] "launch: euid=1000"
#15: +220156 [trace] "get_backend_setting "force_tcg""
#16: +224124 [trace] "get_backend_setting = NULL (error)"
#17: +230759 [trace] "get_cachedir"
#18: +232760 [trace] "get_cachedir =
"/home/rjones/d/libguestfs/tmp""
#19: +246029 [library] "begin building supermin appliance"
#20: +246607 [library] "run supermin"
#21: +249927 [library] "command: run: /usr/bin/supermin"
#22: +250539 [library] "command: run: \ --build"
#23: +251007 [library] "command: run: \ --verbose"
#24: +251471 [library] "command: run: \ --if-newer"
#25: +252083 [library] "command: run: \ --lock
/home/rjones/d/libguestfs/tmp/.guestfs-1000/lock"
#26: +252789 [library] "command: run: \ --copy-kernel"
#27: +253367 [library] "command: run: \ -f ext2"
#28: +253964 [library] "command: run: \ --host-cpu x86_64"
#29: +254460 [library] "command: run: \
/home/rjones/d/libguestfs/appliance/supermin.d"
#30: +255101 [library] "command: run: \ -o
/home/rjones/d/libguestfs/tmp/.guestfs-1000/appliance.d"
#31: +8276383 [appliance] "supermin: version: 5.1.15"
#32: +8277112 [appliance] "supermin: rpm: detected RPM version
4.13"
#33: +8277641 [appliance] "supermin: package handler: fedora/rpm"
#34: +8277846 [appliance] "supermin: acquiring lock on
/home/rjones/d/libguestfs/tmp/.guestfs-1000/lock"
#35: +8279912 [appliance] "supermin: if-newer: output does not need
rebuilding"
#36: +10738829 [library] "finished building supermin appliance"
#37: +10759858 [library] "begin testing qemu features"
#38: +10762666 [library] "command: run: /usr/bin/qemu-kvm"
#39: +10763144 [library] "command: run: \ -display none"
#40: +10763467 [library] "command: run: \ -help"
#41: +109881029 [library] "command: run: /usr/bin/qemu-kvm"
#42: +109882585 [library] "command: run: \ -display none"
#43: +109883183 [library] "command: run: \ -version"
#44: +204787129 [library] "qemu version 2.5"
#45: +204791498 [library] "command: run: /usr/bin/qemu-kvm"
#46: +204792374 [library] "command: run: \ -display none"
#47: +204792999 [library] "command: run: \ -machine accel=kvm:tcg"
#48: +204793611 [library] "command: run: \ -device ?"
#49: +301752570 [trace] "get_sockdir"
#50: +301757996 [trace] "get_sockdir = "/run/user/1000""
#51: +302140236 [library] "finished testing qemu features"
#52: +302151821 [trace] "get_backend_setting "gdb""
#53: +302156417 [trace] "get_backend_setting = NULL (error)"
#54: +304046282 [appliance] "[00302ms] /usr/bin/qemu-kvm \"
#55: +304048563 [appliance] " -global virtio-blk-pci.scsi=off
\"
#56: +304050283 [appliance] " -nodefconfig \"
#57: +304051966 [appliance] " -enable-fips \"
#58: +304053570 [appliance] " -nodefaults \"
#59: +304055288 [appliance] " -display none \"
#60: +304056989 [appliance] " -machine accel=kvm:tcg \"
#61: +304058405 [appliance] " -cpu host \"
#62: +304059751 [appliance] " -m 500 \"
#63: +304061194 [appliance] " -no-reboot \"
#64: +304062616 [appliance] " -rtc driftfix=slew \"
#65: +304064126 [appliance] " -no-hpet \"
#66: +304065683 [appliance] " -global
kvm-pit.lost_tick_policy=discard \"
#67: +304067208 [appliance] " -kernel
/home/rjones/d/libguestfs/tmp/.guestfs-1000/appliance.d/kernel \"
#68: +304068865 [appliance] " -initrd
/home/rjones/d/libguestfs/tmp/.guestfs-1000/appliance.d/initrd \"
#69: +304070394 [appliance] " -device virtio-scsi-pci,id=scsi
\"
#70: +304071970 [appliance] " -drive
file=/home/rjones/d/libguestfs/tmp/libguestfsDOucPz/devnull1,cache=writeback,id=hd0,if=none
\"
#71: +304073902 [appliance] " -device scsi-hd,drive=hd0 \"
#72: +304075535 [appliance] " -drive
file=/home/rjones/d/libguestfs/tmp/.guestfs-1000/appliance.d/root,snapshot=on,id=appliance,cache=unsafe,if=none
\"
#73: +304077200 [appliance] " -device scsi-hd,drive=appliance
\"
#74: +304078741 [appliance] " -device virtio-serial-pci \"
#75: +304080228 [appliance] " -serial stdio \"
#76: +304081626 [appliance] " -device sga \"
#77: +304083208 [appliance] " -chardev
socket,path=/run/user/1000/libguestfs0hEfxo/guestfsd.sock,id=channel0 \"
#78: +304084864 [appliance] " -device
virtserialport,chardev=channel0,name=org.libguestfs.channel.0 \"
#79: +304086528 [appliance] " -append 'panic=1 console=ttyS0
udevtimeout=6000 udev.event-timeout=6000 no_timer_check acpi=off printk.time=1
cgroup_disable=memory root=/dev/sdb selinux=0 guestfs_verbose=1
TERM=xterm-256color guestfs_boot_analysis=1'"
#80: +402033642 [appliance] "WARNING: Image format was not specified
for '/home/rjones/d/libguestfs/tmp/libguestfsDOucPz/devnull1' and
probing guessed raw."
#81: +402036909 [appliance] " Automatically detecting the
format is dangerous for raw images, write operations on block 0 will be
restricted."
#82: +402037921 [appliance] " Specify the 'raw' format
explicitly to remove the restrictions."
#83: +468615858 [appliance] "\x1b[1;256r\x1b[256;256H\x1b[6n"
#84: +737817509 [appliance] "Google, Inc."
#85: +737820124 [appliance] "Serial Graphics Adapter 06/19/15"
#86: +737822013 [appliance] "SGABIOS $Id: sgabios.S 8 2010-04-22
00:03:40Z nlaredo $ (mockbuild@) Fri Jun 19 00:52:18 UTC 2015"
#87: +737823798 [appliance] "Term: 80x24"
#88: +737825462 [appliance] "4 0"
#89: +737827075 [appliance] "\x1b[2J\x0dSeaBIOS (version
1.8.2-20150714_191134-)"
#90: +847527635 [appliance] "\x0dBooting from ROM..."
#91: +1498583245 [appliance] "\x0dProbing EDD (edd=off to disable)...
ok"
#92: +1498588180 [appliance] "\x1b[2J[ 0.000000] Initializing cgroup
subsys cpuset"
#93: +1578297560 [appliance] "[ 0.000000] Initializing cgroup subsys
cpu"
#94: +1578299341 [appliance] "[ 0.000000] Initializing cgroup subsys
cpuacct"
#95: +1578300235 [appliance] "[ 0.000000] Linux version
4.4.4-301.fc23.x86_64 (mockbuild@bkernel02.phx2.fedoraproject.org) (gcc version
5.3.1 20151207 (Red Hat 5.3.1-2) (GCC) ) #1 SMP Fri Mar 4 17:42:42 UTC
2016"
#96: +1579437002 [appliance] "[ 0.000000] Command line: panic=1
console=ttyS0 udevtimeout=6000 udev.event-timeout=6000 no_timer_check acpi=off
printk.time=1 cgroup_disable=memory root=/dev/sdb selinux=0 guestfs_verbose=1
TERM=xterm-256color guestfs_boot_analysis=1"
#97: +1580589541 [appliance] "[ 0.000000] x86/fpu: xstate_offset[2]:
576, xstate_sizes[2]: 256"
#98: +1581723903 [appliance] "[ 0.000000] x86/fpu: Supporting XSAVE
feature 0x01: 'x87 floating point registers'"
#99: +1581725406 [appliance] "[ 0.000000] x86/fpu: Supporting XSAVE
feature 0x02: 'SSE registers'"
#100: +1582860145 [appliance] "[ 0.000000] x86/fpu: Supporting XSAVE
feature 0x04: 'AVX registers'"
#101: +1582861673 [appliance] "[ 0.000000] x86/fpu: Enabled xstate
features 0x7, context size is 832 bytes, using 'standard' format."
#102: +1583995644 [appliance] "[ 0.000000] x86/fpu: Using
'eager' FPU context switches."
#103: +1583997147 [appliance] "[ 0.000000] e820: BIOS-provided
physical RAM map:"
#104: +1583998041 [appliance] "[ 0.000000] BIOS-e820: [mem
0x0000000000000000-0x000000000009f7ff] usable"
#105: +1585148018 [appliance] "[ 0.000000] BIOS-e820: [mem
0x000000000009f800-0x000000000009ffff] reserved"
#106: +1585150003 [appliance] "[ 0.000000] BIOS-e820: [mem
0x00000000000f0000-0x00000000000fffff] reserved"
#107: +1585151262 [appliance] "[ 0.000000] BIOS-e820: [mem
0x0000000000100000-0x000000001f3dffff] usable"
#108: +1586287942 [appliance] "[ 0.000000] BIOS-e820: [mem
0x000000001f3e0000-0x000000001f3fffff] reserved"
#109: +1586289402 [appliance] "[ 0.000000] BIOS-e820: [mem
0x00000000feffc000-0x00000000feffffff] reserved"
#110: +1587425993 [appliance] "[ 0.000000] BIOS-e820: [mem
0x00000000fffc0000-0x00000000ffffffff] reserved"
#111: +1587427505 [appliance] "[ 0.000000] NX (Execute Disable)
protection: active"
#112: +1587428376 [appliance] "[ 0.000000] SMBIOS 2.8 present."
#113: +1588572045 [appliance] "[ 0.000000] Hypervisor detected:
KVM"
#114: +1588573562 [appliance] "[ 0.000000] e820: last_pfn = 0x1f3e0
max_arch_pfn = 0x400000000"
#115: +1588574564 [appliance] "[ 0.000000] x86/PAT: Configuration
[0-7]: WB WC UC- UC WB WC UC- WT "
#116: +1589708009 [appliance] "[ 0.000000] found SMP MP-table at
[mem 0x000f64d0-0x000f64df] mapped at [ffff8800000f64d0]"
#117: +1589709512 [appliance] "[ 0.000000] Using GB pages for direct
mapping"
#118: +1589710419 [appliance] "[ 0.000000] RAMDISK: [mem
0x1f38a000-0x1f3dffff]"
#119: +1590843717 [appliance] "[ 0.000000] No NUMA configuration
found"
#120: +1590845202 [appliance] "[ 0.000000] Faking a node at [mem
0x0000000000000000-0x000000001f3dffff]"
#121: +1590846149 [appliance] "[ 0.000000] NODE_DATA(0) allocated
[mem 0x1f378000-0x1f389fff]"
#122: +1591982264 [appliance] "[ 0.000000] kvm-clock: Using msrs
4b564d01 and 4b564d00"
#123: +1591983698 [appliance] "[ 0.000000] kvm-clock: cpu 0, msr
0:1f368001, primary cpu clock"
#124: +1591984626 [appliance] "[ 0.000000] kvm-clock: using sched
offset of 1128250597 cycles"
#125: +1593132165 [appliance] "[ 0.000000] clocksource: kvm-clock:
mask: 0xffffffffffffffff max_cycles: 0x1cd42e4dffb, max_idle_ns: 881590591483
ns"
#126: +1593133666 [appliance] "[ 0.000000] Zone ranges:"
#127: +1593134573 [appliance] "[ 0.000000] DMA [mem
0x0000000000001000-0x0000000000ffffff]"
#128: +1594269741 [appliance] "[ 0.000000] DMA32 [mem
0x0000000001000000-0x000000001f3dffff]"
#129: +1594271152 [appliance] "[ 0.000000] Normal empty"
#130: +1594272092 [appliance] "[ 0.000000] Movable zone start for
each node"
#131: +1594272912 [appliance] "[ 0.000000] Early memory node
ranges"
#132: +1595408325 [appliance] "[ 0.000000] node 0: [mem
0x0000000000001000-0x000000000009efff]"
#133: +1595409782 [appliance] "[ 0.000000] node 0: [mem
0x0000000000100000-0x000000001f3dffff]"
#134: +1595410612 [appliance] "[ 0.000000] Initmem setup node 0 [mem
0x0000000000001000-0x000000001f3dffff]"
#135: +1596545387 [appliance] "[ 0.000000] SFI: Simple Firmware
Interface v0.81 http://simplefirmware.org"
#136: +1596546756 [appliance] "[ 0.000000] Intel MultiProcessor
Specification v1.4"
#137: +1597694902 [appliance] "[ 0.000000] MPTABLE: OEM ID:
BOCHSCPU"
#138: +1597696375 [appliance] "[ 0.000000] MPTABLE: Product ID: 0.1
"
#139: +1597697225 [appliance] "[ 0.000000] MPTABLE: APIC at:
0xFEE00000"
#140: +1597697986 [appliance] "[ 0.000000] Processor #0
(Bootup-CPU)"
#141: +1597698779 [appliance] "[ 0.000000] IOAPIC[0]: apic_id 0,
version 17, address 0xfec00000, GSI 0-23"
#142: +1598836161 [appliance] "[ 0.000000] Processors: 1"
#143: +1598837499 [appliance] "[ 0.000000] smpboot: Allowing 1 CPUs,
0 hotplug CPUs"
#144: +1598838367 [appliance] "[ 0.000000] PM: Registered nosave
memory: [mem 0x00000000-0x00000fff]"
#145: +1599971258 [appliance] "[ 0.000000] PM: Registered nosave
memory: [mem 0x0009f000-0x0009ffff]"
#146: +1599972658 [appliance] "[ 0.000000] PM: Registered nosave
memory: [mem 0x000a0000-0x000effff]"
#147: +1599973462 [appliance] "[ 0.000000] PM: Registered nosave
memory: [mem 0x000f0000-0x000fffff]"
#148: +1601108016 [appliance] "[ 0.000000] e820: [mem
0x1f400000-0xfeffbfff] available for PCI devices"
#149: +1601109374 [appliance] "[ 0.000000] Booting paravirtualized
kernel on KVM"
#150: +1602226775 [appliance] "[ 0.000000] clocksource:
refined-jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns:
1910969940391419 ns"
#151: +1602228326 [appliance] "[ 0.000000] setup_percpu:
NR_CPUS:1024 nr_cpumask_bits:1 nr_cpu_ids:1 nr_node_ids:1"
#152: +1603364627 [appliance] "[ 0.000000] PERCPU: Embedded 34
pages/cpu @ffff88001f000000 s98712 r8192 d32360 u2097152"
#153: +1603365993 [appliance] "[ 0.000000] KVM setup async PF for
cpu 0"
#154: +1603366924 [appliance] "[ 0.000000] kvm-stealtime: cpu 0, msr
1f00d900"
#155: +1604502833 [appliance] "[ 0.000000] Built 1 zonelists in Node
order, mobility grouping on. Total pages: 125849"
#156: +1604504205 [appliance] "[ 0.000000] Policy zone: DMA32"
#157: +1604505090 [appliance] "[ 0.000000] Kernel command line:
panic=1 console=ttyS0 udevtimeout=6000 udev.event-timeout=6000 no_timer_check
acpi=off printk.time=1 cgroup_disable=memory root=/dev/sdb selinux=0
guestfs_verbose=1 TERM=xterm-256color guestfs_boot_analysis=1"
#158: +1605639283 [appliance] "[ 0.000000] PID hash table entries:
2048 (order: 2, 16384 bytes)"
#159: +1606775674 [appliance] "[ 0.000000] Memory: 485620K/511480K
available (7827K kernel code, 1307K rwdata, 3444K rodata, 1528K init, 1544K bss,
25860K reserved, 0K cma-reserved)"
#160: +1607910593 [appliance] "[ 0.000000] SLUB: HWalign=64,
Order=0-3, MinObjects=0, CPUs=1, Nodes=1"
#161: +1607911967 [appliance] "[ 0.000000] Hierarchical RCU
implementation."
#162: +1607912837 [appliance] "[ 0.000000] \x09Build-time adjustment
of leaf fanout to 64."
#163: +1609048767 [appliance] "[ 0.000000] \x09RCU restricting CPUs
from NR_CPUS=1024 to nr_cpu_ids=1."
#164: +1609050038 [appliance] "[ 0.000000] RCU: Adjusting geometry
for rcu_fanout_leaf=64, nr_cpu_ids=1"
#165: +1609050748 [appliance] "[ 0.000000] NR_IRQS:65792 nr_irqs:256
16"
#166: +1610184515 [appliance] "[ 0.000000] \x09Offload RCU callbacks
from all CPUs"
#167: +1610185688 [appliance] "[ 0.000000] \x09Offload RCU callbacks
from CPUs: 0."
#168: +1610186341 [appliance] "[ 0.000000] Console: colour *CGA
80x25"
#169: +1610186953 [appliance] "[ 0.000000] console [ttyS0]
enabled"
#170: +1611295424 [appliance] "[ 0.000000] tsc: Detected 2593.994
MHz processor"
#171: +1611296569 [appliance] "[ 0.041879] Calibrating delay loop
(skipped) preset value.. 5187.98 BogoMIPS (lpj=2593994)"
#172: +1611297270 [appliance] "[ 0.042446] pid_max: default: 32768
minimum: 301"
#173: +1612411168 [appliance] "[ 0.042785] Security Framework
initialized"
#174: +1612411881 [appliance] "[ 0.043064] Yama: becoming
mindful."
#175: +1612412502 [appliance] "[ 0.043310] SELinux: Disabled at
boot."
#176: +1613549975 [appliance] "[ 0.043660] Dentry cache hash table
entries: 65536 (order: 7, 524288 bytes)"
#177: +1613551223 [appliance] "[ 0.044209] Inode-cache hash table
entries: 32768 (order: 6, 262144 bytes)"
#178: +1613551900 [appliance] "[ 0.044717] Mount-cache hash table
entries: 1024 (order: 1, 8192 bytes)"
#179: +1614691667 [appliance] "[ 0.045187] Mountpoint-cache hash
table entries: 1024 (order: 1, 8192 bytes)"
#180: +1614692714 [appliance] "[ 0.045791] Initializing cgroup
subsys io"
#181: +1615818691 [appliance] "[ 0.046090] Initializing cgroup
subsys memory"
#182: +1615819663 [appliance] "[ 0.046542] Disabling memory control
group subsystem"
#183: +1615820334 [appliance] "[ 0.046882] Initializing cgroup
subsys devices"
#184: +1616951514 [appliance] "[ 0.047200] Initializing cgroup
subsys freezer"
#185: +1616952672 [appliance] "[ 0.047508] Initializing cgroup
subsys net_cls"
#186: +1616953297 [appliance] "[ 0.047813] Initializing cgroup
subsys perf_event"
#187: +1616953925 [appliance] "[ 0.048127] Initializing cgroup
subsys net_prio"
#188: +1618070496 [appliance] "[ 0.048454] Initializing cgroup
subsys hugetlb"
#189: +1618071474 [appliance] "[ 0.048771] Initializing cgroup
subsys pids"
#190: +1619897918 [appliance] "[ 0.050009] mce: CPU supports 10 MCE
banks"
#191: +1619899131 [appliance] "[ 0.050329] Last level iTLB entries:
4KB 0, 2MB 0, 4MB 0"
#192: +1619899847 [appliance] "[ 0.050701] Last level dTLB entries:
4KB 0, 2MB 0, 4MB 0, 1GB 0"
#193: +1629517447 [appliance] "[ 0.059636] Freeing SMP alternatives
memory: 28K (ffffffff81ec6000 - ffffffff81ecd000)"
#194: +1632098688 [appliance] "[ 0.062221] ftrace: allocating 29522
entries in 116 pages"
#195: +1653005102 [appliance] "[ 0.083103] x2apic enabled"
#196: +1653006772 [appliance] "[ 0.083481] Switched APIC routing to
physical x2apic."
#197: +1654452726 [appliance] "[ 0.084544] ..TIMER: vector=0x30
apic1=0 pin1=2 apic2=-1 pin2=-1"
#198: +1654453949 [appliance] "[ 0.084976] smpboot: CPU0: Intel(R)
Core(TM) i7-5600U CPU @ 2.60GHz (family: 0x6, model: 0x3d, stepping: 0x4)"
#199: +1654454686 [appliance] "[ 0.085665] Performance Events:
16-deep LBR, Broadwell events, Intel PMU driver."
#200: +1655600907 [appliance] "[ 0.086233] ... version:
2"
#201: +1655601951 [appliance] "[ 0.086495] ... bit width:
48"
#202: +1655602559 [appliance] "[ 0.086760] ... generic registers:
4"
#203: +1656739318 [appliance] "[ 0.087051] ... value mask:
0000ffffffffffff"
#204: +1656740352 [appliance] "[ 0.087395] ... max period:
000000007fffffff"
#205: +1656741030 [appliance] "[ 0.087735] ... fixed-purpose events:
3"
#206: +1657857199 [appliance] "[ 0.088012] ... event mask:
000000070000000f"
#207: +1657858360 [appliance] "[ 0.088804] x86: Booted up 1 node, 1
CPUs"
#208: +1657859005 [appliance] "[ 0.089082] smpboot: Total of 1
processors activated (5187.98 BogoMIPS)"
#209: +1658968912 [appliance] "[ 0.089737] devtmpfs:
initialized"
#210: +1661143181 [appliance] "[ 0.091227] clocksource: jiffies:
mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 1911260446275000 ns"
#211: +1661144425 [appliance] "[ 0.091939] atomic64_test: passed for
x86-64 platform with CX8 and with SSE"
#212: +1662267067 [appliance] "[ 0.092406] pinctrl core: initialized
pinctrl subsystem"
#213: +1662268242 [appliance] "[ 0.092803] RTC time: 12:39:27, date:
03/20/16"
#214: +1662268884 [appliance] "[ 0.093180] NET: Registered protocol
family 16"
#215: +1663470095 [appliance] "[ 0.093601] cpuidle: using governor
menu"
#216: +1663471301 [appliance] "[ 0.094036] PCI: Using configuration
type 1 for base access"
#217: +1665163081 [appliance] "[ 0.095252] ACPI: Interpreter
disabled."
#218: +1665164225 [appliance] "[ 0.095577] vgaarb: loaded"
#219: +1665164858 [appliance] "[ 0.095821] SCSI subsystem
initialized"
#220: +1665165491 [appliance] "[ 0.096105] usbcore: registered new
interface driver usbfs"
#221: +1666292082 [appliance] "[ 0.096488] usbcore: registered new
interface driver hub"
#222: +1666293201 [appliance] "[ 0.096843] usbcore: registered new
device driver usb"
#223: +1666293788 [appliance] "[ 0.097223] PCI: Probing PCI
hardware"
#224: +1666294623 [appliance] "[ 0.097494] PCI host bridge to bus
0000:00"
#225: +1667427793 [appliance] "[ 0.097774] pci_bus 0000:00: root bus
resource [io 0x0000-0xffff]"
#226: +1667428825 [appliance] "[ 0.098183] pci_bus 0000:00: root bus
resource [mem 0x00000000-0xffffffffff]"
#227: +1667429389 [appliance] "[ 0.098649] pci_bus 0000:00: No busn
resource found for root bus, will use [bus 00-ff]"
#228: +1672874977 [appliance] "[ 0.102946] pci 0000:00:01.1: legacy
IDE quirk: reg 0x10: [io 0x01f0-0x01f7]"
#229: +1672876700 [appliance] "[ 0.103444] pci 0000:00:01.1: legacy
IDE quirk: reg 0x14: [io 0x03f6]"
#230: +1672877345 [appliance] "[ 0.103897] pci 0000:00:01.1: legacy
IDE quirk: reg 0x18: [io 0x0170-0x0177]"
#231: +1673996446 [appliance] "[ 0.104380] pci 0000:00:01.1: legacy
IDE quirk: reg 0x1c: [io 0x0376]"
#232: +1673998919 [appliance] "[ 0.105138] pci 0000:00:01.3: quirk:
[io 0x0600-0x063f] claimed by PIIX4 ACPI"
#233: +1675117175 [appliance] "[ 0.105628] pci 0000:00:01.3: quirk:
[io 0x0700-0x070f] claimed by PIIX4 SMB"
#234: +1689577809 [appliance] "[ 0.119624] pci 0000:00:01.0:
PIIX/ICH IRQ router [8086:7000]"
#235: +1689579265 [appliance] "[ 0.120193] NetLabel:
Initializing"
#236: +1689579867 [appliance] "[ 0.120425] NetLabel: domain hash
size = 128"
#237: +1689580286 [appliance] "[ 0.120719] NetLabel: protocols =
UNLABELED CIPSOv4"
#238: +1690691686 [appliance] "[ 0.121077] NetLabel: unlabeled
traffic allowed by default"
#239: +1693098593 [appliance] "[ 0.121543] clocksource: Switched to
clocksource kvm-clock"
#240: +1697406909 [appliance] "[ 0.127480] pnp: PnP ACPI:
disabled"
#241: +1697408565 [appliance] "[ 0.128509] NET: Registered protocol
family 2"
#242: +1698538885 [appliance] "[ 0.128969] TCP established hash
table entries: 4096 (order: 3, 32768 bytes)"
#243: +1698539725 [appliance] "[ 0.129444] TCP bind hash table
entries: 4096 (order: 4, 65536 bytes)"
#244: +1699672141 [appliance] "[ 0.129898] TCP: Hash tables
configured (established 4096 bind 4096)"
#245: +1699673095 [appliance] "[ 0.130482] UDP hash table entries:
256 (order: 1, 8192 bytes)"
#246: +1699673529 [appliance] "[ 0.130885] UDP-Lite hash table
entries: 256 (order: 1, 8192 bytes)"
#247: +1700803965 [appliance] "[ 0.131335] NET: Registered protocol
family 1"
#248: +1700804777 [appliance] "[ 0.131633] pci 0000:00:00.0:
Limiting direct PCI/PCI transfers"
#249: +1700805227 [appliance] "[ 0.132041] pci 0000:00:01.0: PIIX3:
Enabling Passive Release"
#250: +1701932232 [appliance] "[ 0.132433] pci 0000:00:01.0:
Activating ISA DMA hang workarounds"
#251: +1701933316 [appliance] "[ 0.132906] Unpacking
initramfs..."
#252: +1703265782 [appliance] "[ 0.133374] Freeing initrd memory:
344K (ffff88001f38a000 - ffff88001f3e0000)"
#253: +1703266861 [appliance] "[ 0.133960] platform rtc_cmos:
registered platform RTC device (no PNP device found)"
#254: +1704648489 [appliance] "[ 0.134732] futex hash table entries:
256 (order: 2, 16384 bytes)"
#255: +1704649641 [appliance] "[ 0.135168] audit: initializing
netlink subsys (disabled)"
#256: +1704650164 [appliance] "[ 0.135528] audit: type=2000
audit(1458477567.955:1): initialized"
#257: +1705772643 [appliance] "[ 0.136123] Initialise system trusted
keyring"
#258: +1705773567 [appliance] "[ 0.136470] HugeTLB registered 1 GB
page size, pre-allocated 0 pages"
#259: +1705774079 [appliance] "[ 0.136893] HugeTLB registered 2 MB
page size, pre-allocated 0 pages"
#260: +1708096268 [appliance] "[ 0.138196] zbud: loaded"
#261: +1708097257 [appliance] "[ 0.138567] VFS: Disk quotas
dquot_6.6.0"
#262: +1708097778 [appliance] "[ 0.138848] VFS: Dquot-cache hash
table entries: 512 (order 0, 4096 bytes)"
#263: +1709446211 [appliance] "[ 0.139571] Key type big_key
registered"
#264: +1711289017 [appliance] "[ 0.141364] NET: Registered protocol
family 38"
#265: +1711289999 [appliance] "[ 0.141709] Key type asymmetric
registered"
#266: +1711290489 [appliance] "[ 0.141981] Asymmetric key parser
'x509' registered"
#267: +1711290871 [appliance] "[ 0.142338] Block layer SCSI generic
(bsg) driver version 0.4 loaded (major 250)"
#268: +1712419415 [appliance] "[ 0.142885] io scheduler noop
registered"
#269: +1712420298 [appliance] "[ 0.143146] io scheduler deadline
registered"
#270: +1712420708 [appliance] "[ 0.143449] io scheduler cfq
registered (default)"
#271: +1713541204 [appliance] "[ 0.143853] pci_hotplug: PCI Hot Plug
PCI Core version: 0.5"
#272: +1713542138 [appliance] "[ 0.144236] pciehp: PCI Express Hot
Plug Controller Driver version: 0.4"
#273: +1714628531 [appliance] "[ 0.144782] Serial: 8250/16550
driver, 32 ports, IRQ sharing enabled"
#274: +1737387483 [appliance] "[ 0.167535] serial8250: ttyS0 at I/O
0x3f8 (irq = 4, base_baud = 115200) is a 16550A"
#275: +1738628968 [appliance] "[ 0.168780] Non-volatile memory
driver v1.3"
#276: +1738629686 [appliance] "[ 0.169085] Linux agpgart interface
v0.103"
#277: +1739962259 [appliance] "[ 0.170096] scsi host0:
ata_piix"
#278: +1739962826 [appliance] "[ 0.170375] scsi host1:
ata_piix"
#279: +1739963237 [appliance] "[ 0.170627] ata1: PATA max MWDMA2 cmd
0x1f0 ctl 0x3f6 bmdma 0xc060 irq 14"
#280: +1739963693 [appliance] "[ 0.171086] ata2: PATA max MWDMA2 cmd
0x170 ctl 0x376 bmdma 0xc068 irq 15"
#281: +1741066353 [appliance] "[ 0.171733] libphy: Fixed MDIO Bus:
probed"
#282: +1741066821 [appliance] "[ 0.172049] ehci_hcd: USB 2.0
'Enhanced' Host Controller (EHCI) Driver"
#283: +1742209296 [appliance] "[ 0.172489] ehci-pci: EHCI PCI
platform driver"
#284: +1742210765 [appliance] "[ 0.172800] ohci_hcd: USB 1.1
'Open' Host Controller (OHCI) Driver"
#285: +1742211439 [appliance] "[ 0.173226] ohci-pci: OHCI PCI
platform driver"
#286: +1743321291 [appliance] "[ 0.173537] uhci_hcd: USB Universal
Host Controller Interface driver"
#287: +1743322081 [appliance] "[ 0.174017] usbcore: registered new
interface driver usbserial"
#288: +1743322477 [appliance] "[ 0.174415] usbcore: registered new
interface driver usbserial_generic"
#289: +1744454836 [appliance] "[ 0.174868] usbserial: USB Serial
support registered for generic"
#290: +1744455829 [appliance] "[ 0.175273] i8042: PNP: No PS/2
controller found. Probing ports directly."
#291: +1745585579 [appliance] "[ 0.176217] serio: i8042 KBD port at
0x60,0x64 irq 1"
#292: +1745586473 [appliance] "[ 0.176546] serio: i8042 AUX port at
0x60,0x64 irq 12"
#293: +1746703324 [appliance] "[ 0.177121] mousedev: PS/2 mouse
device common for all mice"
#294: +1746704288 [appliance] "[ 0.177640] input: AT Translated Set
2 keyboard as /devices/platform/i8042/serio0/input/input0"
#295: +1747824370 [appliance] "[ 0.178608] input: VirtualPS/2 VMware
VMMouse as /devices/platform/i8042/serio1/input/input3"
#296: +1748944259 [appliance] "[ 0.179306] input: VirtualPS/2 VMware
VMMouse as /devices/platform/i8042/serio1/input/input2"
#297: +1748945151 [appliance] "[ 0.180037] rtc_cmos rtc_cmos: rtc
core: registered rtc_cmos as rtc0"
#298: +1750052288 [appliance] "[ 0.180532] rtc_cmos rtc_cmos: alarms
up to one day, 114 bytes nvram"
#299: +1750053284 [appliance] "[ 0.181005] device-mapper: uevent:
version 1.0.3"
#300: +1751178878 [appliance] "[ 0.181417] device-mapper: ioctl:
4.34.0-ioctl (2015-10-28) initialised: dm-devel@redhat.com"
#301: +1751179833 [appliance] "[ 0.182046] hidraw: raw HID events
driver (C) Jiri Kosina"
#302: +1752325114 [appliance] "[ 0.182434] usbcore: registered new
interface driver usbhid"
#303: +1752326687 [appliance] "[ 0.182807] usbhid: USB HID core
driver"
#304: +1752327439 [appliance] "[ 0.183090] drop_monitor:
Initializing network drop monitor service"
#305: +1753453323 [appliance] "[ 0.183577] ip_tables: (C) 2000-2006
Netfilter Core Team"
#306: +1753454256 [appliance] "[ 0.183975] Initializing XFRM netlink
socket"
#307: +1753454692 [appliance] "[ 0.184376] NET: Registered protocol
family 10"
#308: +1754717315 [appliance] "[ 0.184807] mip6: Mobile IPv6"
#309: +1754718316 [appliance] "[ 0.185034] NET: Registered protocol
family 17"
#310: +1754718746 [appliance] "[ 0.185444] microcode: CPU0
sig=0x306d4, pf=0x1, revision=0x1"
#311: +1754719212 [appliance] "[ 0.185838] microcode: Microcode
Update Driver: v2.01 <tigran@aivazian.fsnet.co.uk>, Peter Oruba"
#312: +1755847009 [appliance] "[ 0.186436] AVX2 version of
gcm_enc/dec engaged."
#313: +1755847753 [appliance] "[ 0.186739] AES CTR mode by8
optimization enabled"
#314: +1773249630 [appliance] "[ 0.203347] registered taskstats
version 1"
#315: +1773250815 [appliance] "[ 0.203698] Loading compiled-in X.509
certificates"
#316: +1774482151 [appliance] "[ 0.204584] Loaded X.509 cert
'Fedora kernel signing key:
ff671496ff3f386a8ef2031bac2201b2edb4da2a'"
#317: +1774483051 [appliance] "[ 0.205212] zswap: loaded using pool
lzo/zbud"
#318: +1774483581 [appliance] "[ 0.205637] Magic number:
8:887:683"
#319: +1775598297 [appliance] "[ 0.205967] rtc_cmos rtc_cmos:
setting system clock to 2016-03-20 12:39:27 UTC (1458477567)"
#320: +1898461040 [appliance] "[ 0.328531] Freeing unused kernel
memory: 1528K (ffffffff81d48000 - ffffffff81ec6000)"
#321: +1898462356 [appliance] "[ 0.329079] Write protecting the
kernel read-only data: 12288k"
#322: +1898463099 [appliance] "[ 0.329570] Freeing unused kernel
memory: 352K (ffff8800017a8000 - ffff880001800000)"
#323: +1901110890 [appliance] "[ 0.331207] Freeing unused kernel
memory: 652K (ffff880001b5d000 - ffff880001c00000)"
#324: +1901111838 [appliance] "supermin: mounting /proc"
#325: +1901112236 [appliance] "supermin: ext2 mini initrd starting up:
5.1.15 dietlibc"
#326: +1901130485 [appliance] "supermin: cmdline: panic=1 console=ttyS0
udevtimeout=6000 udev.event-timeout=6000 no_timer_check acpi=off printk.time=1
cgroup_disable=memory root=/dev/sdb selinux=0 guestfs_verbose=1
TERM=xterm-256color guestfs_boot_analysis=1"
#327: +1902275395 [appliance] "supermin: uptime: 0.26 0.14"
#328: +1903378005 [appliance] "supermin: mounting /sys"
#329: +1903379037 [appliance] "supermin: internal insmod
crc32-pclmul.ko"
#330: +1904726374 [appliance] "supermin: internal insmod
crc32c-intel.ko"
#331: +1904727226 [appliance] "supermin: internal insmod
crct10dif-pclmul.ko"
#332: +1905827944 [appliance] "supermin: internal insmod crc32.ko"
#333: +1906988159 [appliance] "supermin: internal insmod
virtio.ko"
#334: +1908702651 [appliance] "supermin: internal insmod
virtio_ring.ko"
#335: +1908703455 [appliance] "supermin: internal insmod
virtio_blk.ko"
#336: +1909856826 [appliance] "supermin: internal insmod
virtio-rng.ko"
#337: +1910953800 [appliance] "supermin: internal insmod
virtio_console.ko"
#338: +1912990126 [appliance] "supermin: internal insmod
virtio_net.ko"
#339: +1914243041 [appliance] "supermin: internal insmod
virtio_scsi.ko"
#340: +1914243801 [appliance] "supermin: internal insmod
virtio_balloon.ko"
#341: +1915341054 [appliance] "supermin: internal insmod
virtio_input.ko"
#342: +1916441706 [appliance] "supermin: internal insmod
virtio_mmio.ko"
#343: +1917538134 [appliance] "supermin: internal insmod
virtio_pci.ko"
#344: +1919545587 [appliance] "[ 0.349669] virtio-pci 0000:00:02.0:
PCI->APIC IRQ transform: INT A -> IRQ 10"
#345: +1919546869 [appliance] "[ 0.350184] virtio-pci 0000:00:02.0:
virtio_pci: leaving for legacy driver"
#346: +1921092009 [appliance] "[ 0.351188] scsi host2: Virtio SCSI
HBA"
#347: +1921092886 [appliance] "[ 0.351623] virtio-pci 0000:00:03.0:
PCI->APIC IRQ transform: INT A -> IRQ 11"
#348: +1921093192 [appliance] "[ 0.352120] virtio-pci 0000:00:03.0:
virtio_pci: leaving for legacy driver"
#349: +1925134272 [appliance] "[ 0.355232] scsi 2:0:0:0:
Direct-Access QEMU QEMU HARDDISK 2.5+ PQ: 0 ANSI: 5"
#350: +1925135515 [appliance] "[ 0.355993] scsi 2:0:1:0:
Direct-Access QEMU QEMU HARDDISK 2.5+ PQ: 0 ANSI: 5"
#351: +1940829827 [appliance] "[ 0.370948] sd 2:0:0:0: Attached scsi
generic sg0 type 0"
#352: +1940831113 [appliance] "[ 0.371443] sd 2:0:1:0: Attached scsi
generic sg1 type 0"
#353: +1940831419 [appliance] "[ 0.371937] sd 2:0:0:0: [sda] 8
512-byte logical blocks: (4.10 kB/4.00 KiB)"
#354: +1941930911 [appliance] "[ 0.372451] sd 2:0:1:0: [sdb] 8388608
512-byte logical blocks: (4.29 GB/4.00 GiB)"
#355: +1941931311 [appliance] "[ 0.373111] sd 2:0:0:0: [sda] Write
Protect is off"
#356: +1943035999 [appliance] "[ 0.373474] sd 2:0:1:0: [sdb] Write
Protect is off"
#357: +1943036376 [appliance] "[ 0.373838] sd 2:0:0:0: [sda] Write
cache: enabled, read cache: enabled, doesn't support DPO or FUA"
#358: +1944140306 [appliance] "[ 0.374472] sd 2:0:1:0: [sdb] Write
cache: enabled, read cache: enabled, doesn't support DPO or FUA"
#359: +1945499684 [appliance] "[ 0.375498] Dev sda: unable to read
RDB block 8"
#360: +1945500501 [appliance] "[ 0.375950] sda: unable to read
partition table"
#361: +1945500827 [appliance] "[ 0.376275] sda: partition table
beyond EOD, enabling native capacity"
#362: +1947105724 [appliance] "[ 0.377163] sd 2:0:1:0: [sdb]
Attached SCSI disk"
#363: +1947106648 [appliance] "[ 0.377549] Dev sda: unable to read
RDB block 8"
#364: +1947106891 [appliance] "[ 0.377858] sda: unable to read
partition table"
#365: +1947107080 [appliance] "[ 0.378161] sda: partition table
beyond EOD, truncated"
#366: +1948211773 [appliance] "[ 0.378787] sd 2:0:0:0: [sda]
Attached SCSI disk"
#367: +1948212192 [appliance] "supermin: internal insmod
crc-ccitt.ko"
#368: +1949926809 [appliance] "supermin: internal insmod
crc-itu-t.ko"
#369: +1949927509 [appliance] "supermin: internal insmod crc8.ko"
#370: +1951675280 [appliance] "supermin: internal insmod
libcrc32c.ko"
#371: +1951676420 [appliance] "supermin: picked /sys/block/sdb/dev as
root device"
#372: +1952783002 [appliance] "supermin: creating /dev/root as block
special 8:16"
#373: +1952783853 [appliance] "supermin: mounting new root on
/root"
#374: +1953939205 [appliance] "[ 0.384085] EXT4-fs (sdb): mounting
ext2 file system using the ext4 subsystem"
#375: +1956529358 [appliance] "[ 0.386671] EXT4-fs (sdb): mounted
filesystem without journal. Opts: "
#376: +1956530329 [appliance] "supermin: chroot"
#377: +1965185616 [appliance] "Starting /init script ..."
#378: +2070362644 [appliance] "[ 0.500469] random: systemd-tmpfile
urandom read with 80 bits of entropy available"
#379: +2071744483 [appliance]
"[/usr/lib/tmpfiles.d/journal-nocow.conf:26] Failed to replace specifiers:
/var/log/journal/%m"
#380: +2073121930 [appliance] "[/usr/lib/tmpfiles.d/systemd.conf:26]
Failed to replace specifiers: /run/log/journal/%m"
#381: +2073122583 [appliance] "[/usr/lib/tmpfiles.d/systemd.conf:28]
Failed to replace specifiers: /run/log/journal/%m"
#382: +2073124850 [appliance] "[/usr/lib/tmpfiles.d/systemd.conf:29]
Failed to replace specifiers: /run/log/journal/%m"
#383: +2074260427 [appliance] "[/usr/lib/tmpfiles.d/systemd.conf:32]
Failed to replace specifiers: /var/log/journal/%m"
#384: +2074261044 [appliance] "[/usr/lib/tmpfiles.d/systemd.conf:33]
Failed to replace specifiers: /var/log/journal/%m/system.journal"
#385: +2075597550 [appliance] "[/usr/lib/tmpfiles.d/systemd.conf:37]
Failed to replace specifiers: /var/log/journal/%m"
#386: +2075598068 [appliance] "[/usr/lib/tmpfiles.d/systemd.conf:38]
Failed to replace specifiers: /var/log/journal/%m"
#387: +2075598298 [appliance] "[/usr/lib/tmpfiles.d/systemd.conf:39]
Failed to replace specifiers: /var/log/journal/%m/system.journal"
#388: +2076681425 [appliance]
"UDEVD=/usr/lib/systemd/systemd-udevd"
#389: +2080189956 [appliance] "starting version 229"
#390: +2147808021 [appliance] "[ 0.577887] piix4_smbus 0000:00:01.3:
PCI->APIC IRQ transform: INT A -> IRQ 9"
#391: +2147809300 [appliance] "[ 0.578383] piix4_smbus 0000:00:01.3:
SMBus Host Controller at 0x700, revision 0"
#392: +2182141938 [appliance] "[ 0.612232] intel_rapl: no valid rapl
domains found in package 0"
#393: +2207026507 [appliance] "[ 0.637126] input: PC Speaker as
/devices/platform/pcspkr/input/input4"
#394: +2215064188 [appliance] "[ 0.645194] random: nonblocking pool
is initialized"
#395: +2222206065 [appliance] "+ grep -sq guestfs_network=1
/proc/cmdline"
#396: +2222207598 [appliance] "+ grep -sq guestfs_rescue=1
/proc/cmdline"
#397: +2223845143 [appliance] "+ grep -sq guestfs_noreboot=1
/proc/cmdline"
#398: +2223846028 [appliance] "+ grep -sq guestfs_boot_analysis=1
/proc/cmdline"
#399: +2225312012 [appliance] "+ guestfs_boot_analysis=1"
#400: +2226468203 [appliance] "++ grep -Eo
'guestfs_channel=[^[:space:]]+' /proc/cmdline"
#401: +2226469028 [appliance] "+ eval"
#402: +2227631960 [appliance] "+ grep -sq selinux=1 /proc/cmdline"
#403: +2227632978 [appliance] "+ shopt -s nullglob"
#404: +2227633277 [appliance] "+ for f in
'/sys/block/sd*/device/timeout'"
#405: +2228763365 [appliance] "+ echo 300"
#406: +2228764136 [appliance] "+ for f in
'/sys/block/sd*/device/timeout'"
#407: +2228764332 [appliance] "+ echo 300"
#408: +2228764484 [appliance] "+ for f in
'/sys/block/{h,s,ub,v}d*/queue/scheduler'"
#409: +2228764627 [appliance] "+ echo noop"
#410: +2228764776 [appliance] "+ for f in
'/sys/block/{h,s,ub,v}d*/queue/scheduler'"
#411: +2229862714 [appliance] "+ echo noop"
#412: +2229864052 [appliance] "+ shopt -u nullglob"
#413: +2229864252 [appliance] "+ ip addr add 127.0.0.1/8 brd + dev lo
scope host"
#414: +2232073306 [appliance] "+ ip link set dev lo up"
#415: +2232076200 [appliance] "+ test '' = 1"
#416: +2232076664 [appliance] "+ mdadm -As --auto=yes --run"
#417: +2236022535 [appliance] "mdadm: No arrays found in config file or
automatically"
#418: +2236024820 [appliance] "+ modprobe dm_mod"
#419: +2237430363 [appliance] "+ lvmetad"
#420: +2240145280 [appliance] "+ lvm vgchange -aay --sysinit"
#421: +2243949022 [appliance] " Configuration setting
"global/notify_dbus" unknown."
#422: +2243949990 [appliance] " lvmetad is not active yet, using
direct activation during sysinit"
#423: +2246643479 [appliance] "+ ldmtool create all"
#424: +2250354120 [appliance] "["
#425: +2250355138 [appliance] "]"
#426: +2250355312 [appliance] "+ test 1 = 1"
#427: +2250355470 [appliance] "+ test 1 '!=' 1"
#428: +2250355698 [appliance] "+ test '' = 1"
#429: +2251491263 [appliance] "+ cmd=guestfsd"
#430: +2251492238 [appliance] "+ test x '!=' x"
#431: +2251492464 [appliance] "+ test 1 = 1"
#432: +2251492692 [appliance] "+ cmd='guestfsd --verbose'"
#433: +2251492940 [appliance] "+ test '' = 1"
#434: +2251493145 [appliance] "+ echo guestfsd --verbose"
#435: +2251493352 [appliance] "guestfsd --verbose"
#436: +2251493562 [appliance] "+ guestfsd --verbose"
#437: +2260135598 [appliance] "trying to open virtio-serial channel
'/dev/virtio-ports/org.libguestfs.channel.0'"
#438: +2260137117 [appliance] "udevadm --debug settle"
#439: +2262363111 [appliance] "calling: settle"
#440: +2262370721 [launch_done] "launch done callback"
#441: +2262372472 [library] "recv_from_daemon: received
GUESTFS_LAUNCH_FLAG"
#442: +2262373500 [library] "appliance is up"
#443: +2262390731 [trace] "launch = 0"
#444: +2262391594 [trace] "close"
#445: +2262392583 [library] "closing guestfs handle 0x55eb2eb8c7a0
(state 2)"
#446: +2262394907 [trace] "internal_autosync"
#447: +2264992750 [appliance] "guestfsd: main_loop: new request, len
0x28"
#448: +2264993776 [appliance] "umount-all: /proc/mounts:
fsname=/dev/root dir=/ type=ext2
opts=rw,noatime,block_validity,barrier,user_xattr,acl freq=0 passno=0"
#449: +2264994271 [appliance] "umount-all: /proc/mounts: fsname=/proc
dir=/proc type=proc opts=rw,relatime freq=0 passno=0"
#450: +2266161113 [appliance] "umount-all: /proc/mounts: fsname=/sys
dir=/sys type=sysfs opts=rw,relatime freq=0 passno=0"
#451: +2266161500 [appliance] "umount-all: /proc/mounts: fsname=tmpfs
dir=/run type=tmpfs opts=rw,nosuid,relatime,size=97708k,mode=755 freq=0
passno=0"
#452: +2266161815 [appliance] "umount-all: /proc/mounts: fsname=/dev
dir=/dev type=devtmpfs opts=rw,relatime,size=242824k,nr_inodes=60706,mode=755
freq=0 passno=0"
#453: +2269956659 [appliance] "fsync /dev/sda"
#454: +2276086959 [trace] "internal_autosync = 0"
#455: +2276088930 [library] "sending SIGTERM to process 21607"
#456: +2282816237 [close] "close callback"
#457: +2282822347 [library] "command: run: rm"
#458: +2282823277 [library] "command: run: \ -rf
/home/rjones/d/libguestfs/tmp/libguestfsDOucPz"
#459: +2283992941 [library] "command: run: rm"
#460: +2283993663 [library] "command: run: \ -rf
/run/user/1000/libguestfs0hEfxo"
pass 1
number of events collected 461
elapsed time 2266873397 ns
#0: +139401 [trace] "launch"
#1: +141774 [trace] "version"
#2: +146241 [trace] "version = <struct guestfs_version = major: 1,
minor: 33, release: 15, extra: , >"
#3: +148391 [trace] "get_backend"
#4: +150880 [trace] "get_backend = "direct""
#5: +152228 [library] "launch: program=boot-analysis"
#6: +153435 [library] "launch: version=1.33.15"
#7: +154232 [library] "launch: backend registered: unix"
#8: +154899 [library] "launch: backend registered: uml"
#9: +155697 [library] "launch: backend registered: libvirt"
#10: +156482 [library] "launch: backend registered: direct"
#11: +157173 [library] "launch: backend=direct"
#12: +157990 [library] "launch:
tmpdir=/home/rjones/d/libguestfs/tmp/libguestfsnmgtRi"
#13: +189043 [library] "launch: umask=0002"
#14: +190505 [library] "launch: euid=1000"
#15: +202732 [trace] "get_backend_setting "force_tcg""
#16: +207479 [trace] "get_backend_setting = NULL (error)"
#17: +216104 [trace] "get_cachedir"
#18: +218906 [trace] "get_cachedir =
"/home/rjones/d/libguestfs/tmp""
#19: +234673 [library] "begin building supermin appliance"
#20: +235610 [library] "run supermin"
#21: +239688 [library] "command: run: /usr/bin/supermin"
#22: +240625 [library] "command: run: \ --build"
#23: +241421 [library] "command: run: \ --verbose"
#24: +242122 [library] "command: run: \ --if-newer"
#25: +243248 [library] "command: run: \ --lock
/home/rjones/d/libguestfs/tmp/.guestfs-1000/lock"
#26: +244072 [library] "command: run: \ --copy-kernel"
#27: +244889 [library] "command: run: \ -f ext2"
#28: +245609 [library] "command: run: \ --host-cpu x86_64"
#29: +246354 [library] "command: run: \
/home/rjones/d/libguestfs/appliance/supermin.d"
#30: +247211 [library] "command: run: \ -o
/home/rjones/d/libguestfs/tmp/.guestfs-1000/appliance.d"
#31: +8214105 [appliance] "supermin: version: 5.1.15"
#32: +8215068 [appliance] "supermin: rpm: detected RPM version
4.13"
#33: +8215670 [appliance] "supermin: package handler: fedora/rpm"
#34: +8215907 [appliance] "supermin: acquiring lock on
/home/rjones/d/libguestfs/tmp/.guestfs-1000/lock"
#35: +8217975 [appliance] "supermin: if-newer: output does not need
rebuilding"
#36: +10620441 [library] "finished building supermin appliance"
#37: +10638767 [library] "begin testing qemu features"
#38: +10643999 [library] "command: run: /usr/bin/qemu-kvm"
#39: +10644845 [library] "command: run: \ -display none"
#40: +10646602 [library] "command: run: \ -help"
#41: +106273872 [library] "command: run: /usr/bin/qemu-kvm"
#42: +106274897 [library] "command: run: \ -display none"
#43: +106275478 [library] "command: run: \ -version"
#44: +203774409 [library] "qemu version 2.5"
#45: +203777225 [library] "command: run: /usr/bin/qemu-kvm"
#46: +203778092 [library] "command: run: \ -display none"
#47: +203778683 [library] "command: run: \ -machine accel=kvm:tcg"
#48: +203779187 [library] "command: run: \ -device ?"
#49: +301367769 [trace] "get_sockdir"
#50: +301372861 [trace] "get_sockdir = "/run/user/1000""
#51: +301737015 [library] "finished testing qemu features"
#52: +301747584 [trace] "get_backend_setting "gdb""
#53: +301751916 [trace] "get_backend_setting = NULL (error)"
#54: +303384552 [appliance] "[00302ms] /usr/bin/qemu-kvm \"
#55: +303385945 [appliance] " -global virtio-blk-pci.scsi=off
\"
#56: +303386283 [appliance] " -nodefconfig \"
#57: +303386773 [appliance] " -enable-fips \"
#58: +303387008 [appliance] " -nodefaults \"
#59: +303387257 [appliance] " -display none \"
#60: +303387509 [appliance] " -machine accel=kvm:tcg \"
#61: +303387766 [appliance] " -cpu host \"
#62: +303388004 [appliance] " -m 500 \"
#63: +303388334 [appliance] " -no-reboot \"
#64: +303388622 [appliance] " -rtc driftfix=slew \"
#65: +303388862 [appliance] " -no-hpet \"
#66: +303389154 [appliance] " -global
kvm-pit.lost_tick_policy=discard \"
#67: +303389481 [appliance] " -kernel
/home/rjones/d/libguestfs/tmp/.guestfs-1000/appliance.d/kernel \"
#68: +303389873 [appliance] " -initrd
/home/rjones/d/libguestfs/tmp/.guestfs-1000/appliance.d/initrd \"
#69: +303390133 [appliance] " -device virtio-scsi-pci,id=scsi
\"
#70: +303390454 [appliance] " -drive
file=/home/rjones/d/libguestfs/tmp/libguestfsnmgtRi/devnull1,cache=writeback,id=hd0,if=none
\"
#71: +303390740 [appliance] " -device scsi-hd,drive=hd0 \"
#72: +303391054 [appliance] " -drive
file=/home/rjones/d/libguestfs/tmp/.guestfs-1000/appliance.d/root,snapshot=on,id=appliance,cache=unsafe,if=none
\"
#73: +303391438 [appliance] " -device scsi-hd,drive=appliance
\"
#74: +303391705 [appliance] " -device virtio-serial-pci \"
#75: +303391969 [appliance] " -serial stdio \"
#76: +303392174 [appliance] " -device sga \"
#77: +303392418 [appliance] " -chardev
socket,path=/run/user/1000/libguestfsRJNA2d/guestfsd.sock,id=channel0 \"
#78: +303392702 [appliance] " -device
virtserialport,chardev=channel0,name=org.libguestfs.channel.0 \"
#79: +303393740 [appliance] " -append 'panic=1 console=ttyS0
udevtimeout=6000 udev.event-timeout=6000 no_timer_check acpi=off printk.time=1
cgroup_disable=memory root=/dev/sdb selinux=0 guestfs_verbose=1
TERM=xterm-256color guestfs_boot_analysis=1'"
#80: +398564258 [appliance] "WARNING: Image format was not specified
for '/home/rjones/d/libguestfs/tmp/libguestfsnmgtRi/devnull1' and
probing guessed raw."
#81: +398565421 [appliance] " Automatically detecting the
format is dangerous for raw images, write operations on block 0 will be
restricted."
#82: +398565971 [appliance] " Specify the 'raw' format
explicitly to remove the restrictions."
#83: +464682224 [appliance] "\x1b[1;256r\x1b[256;256H\x1b[6n"
#84: +731815532 [appliance] "Google, Inc."
#85: +731816776 [appliance] "Serial Graphics Adapter 06/19/15"
#86: +731817499 [appliance] "SGABIOS $Id: sgabios.S 8 2010-04-22
00:03:40Z nlaredo $ (mockbuild@) Fri Jun 19 00:52:18 UTC 2015"
#87: +731818127 [appliance] "Term: 80x24"
#88: +731818568 [appliance] "4 0"
#89: +731818972 [appliance] "\x1b[2J\x0dSeaBIOS (version
1.8.2-20150714_191134-)"
#90: +841089745 [appliance] "\x0dBooting from ROM..."
#91: +1484308192 [appliance] "\x0dProbing EDD (edd=off to disable)...
ok"
#92: +1484310651 [appliance] "\x1b[2J[ 0.000000] Initializing cgroup
subsys cpuset"
#93: +1564645056 [appliance] "[ 0.000000] Initializing cgroup subsys
cpu"
#94: +1564646172 [appliance] "[ 0.000000] Initializing cgroup subsys
cpuacct"
#95: +1564646527 [appliance] "[ 0.000000] Linux version
4.4.4-301.fc23.x86_64 (mockbuild@bkernel02.phx2.fedoraproject.org) (gcc version
5.3.1 20151207 (Red Hat 5.3.1-2) (GCC) ) #1 SMP Fri Mar 4 17:42:42 UTC
2016"
#96: +1565793658 [appliance] "[ 0.000000] Command line: panic=1
console=ttyS0 udevtimeout=6000 udev.event-timeout=6000 no_timer_check acpi=off
printk.time=1 cgroup_disable=memory root=/dev/sdb selinux=0 guestfs_verbose=1
TERM=xterm-256color guestfs_boot_analysis=1"
#97: +1568053603 [appliance] "[ 0.000000] x86/fpu: xstate_offset[2]:
576, xstate_sizes[2]: 256"
#98: +1568055220 [appliance] "[ 0.000000] x86/fpu: Supporting XSAVE
feature 0x01: 'x87 floating point registers'"
#99: +1568055920 [appliance] "[ 0.000000] x86/fpu: Supporting XSAVE
feature 0x02: 'SSE registers'"
#100: +1569195939 [appliance] "[ 0.000000] x86/fpu: Supporting XSAVE
feature 0x04: 'AVX registers'"
#101: +1569196790 [appliance] "[ 0.000000] x86/fpu: Enabled xstate
features 0x7, context size is 832 bytes, using 'standard' format."
#102: +1570339729 [appliance] "[ 0.000000] x86/fpu: Using
'eager' FPU context switches."
#103: +1570341239 [appliance] "[ 0.000000] e820: BIOS-provided
physical RAM map:"
#104: +1570341837 [appliance] "[ 0.000000] BIOS-e820: [mem
0x0000000000000000-0x000000000009f7ff] usable"
#105: +1571481410 [appliance] "[ 0.000000] BIOS-e820: [mem
0x000000000009f800-0x000000000009ffff] reserved"
#106: +1571482335 [appliance] "[ 0.000000] BIOS-e820: [mem
0x00000000000f0000-0x00000000000fffff] reserved"
#107: +1572615889 [appliance] "[ 0.000000] BIOS-e820: [mem
0x0000000000100000-0x000000001f3dffff] usable"
#108: +1572617005 [appliance] "[ 0.000000] BIOS-e820: [mem
0x000000001f3e0000-0x000000001f3fffff] reserved"
#109: +1572617396 [appliance] "[ 0.000000] BIOS-e820: [mem
0x00000000feffc000-0x00000000feffffff] reserved"
#110: +1573751015 [appliance] "[ 0.000000] BIOS-e820: [mem
0x00000000fffc0000-0x00000000ffffffff] reserved"
#111: +1573751871 [appliance] "[ 0.000000] NX (Execute Disable)
protection: active"
#112: +1574885825 [appliance] "[ 0.000000] SMBIOS 2.8 present."
#113: +1574886641 [appliance] "[ 0.000000] Hypervisor detected:
KVM"
#114: +1574887030 [appliance] "[ 0.000000] e820: last_pfn = 0x1f3e0
max_arch_pfn = 0x400000000"
#115: +1574887450 [appliance] "[ 0.000000] x86/PAT: Configuration
[0-7]: WB WC UC- UC WB WC UC- WT "
#116: +1576020760 [appliance] "[ 0.000000] found SMP MP-table at
[mem 0x000f64d0-0x000f64df] mapped at [ffff8800000f64d0]"
#117: +1576021669 [appliance] "[ 0.000000] Using GB pages for direct
mapping"
#118: +1576022098 [appliance] "[ 0.000000] RAMDISK: [mem
0x1f38a000-0x1f3dffff]"
#119: +1577157517 [appliance] "[ 0.000000] No NUMA configuration
found"
#120: +1577158451 [appliance] "[ 0.000000] Faking a node at [mem
0x0000000000000000-0x000000001f3dffff]"
#121: +1577158901 [appliance] "[ 0.000000] NODE_DATA(0) allocated
[mem 0x1f378000-0x1f389fff]"
#122: +1578293304 [appliance] "[ 0.000000] kvm-clock: Using msrs
4b564d01 and 4b564d00"
#123: +1578294164 [appliance] "[ 0.000000] kvm-clock: cpu 0, msr
0:1f368001, primary cpu clock"
#124: +1578294585 [appliance] "[ 0.000000] kvm-clock: using sched
offset of 1117368092 cycles"
#125: +1579428855 [appliance] "[ 0.000000] clocksource: kvm-clock:
mask: 0xffffffffffffffff max_cycles: 0x1cd42e4dffb, max_idle_ns: 881590591483
ns"
#126: +1579429744 [appliance] "[ 0.000000] Zone ranges:"
#127: +1580571321 [appliance] "[ 0.000000] DMA [mem
0x0000000000001000-0x0000000000ffffff]"
#128: +1580572191 [appliance] "[ 0.000000] DMA32 [mem
0x0000000001000000-0x000000001f3dffff]"
#129: +1580581295 [appliance] "[ 0.000000] Normal empty"
#130: +1580581767 [appliance] "[ 0.000000] Movable zone start for
each node"
#131: +1581715560 [appliance] "[ 0.000000] Early memory node
ranges"
#132: +1581716373 [appliance] "[ 0.000000] node 0: [mem
0x0000000000001000-0x000000000009efff]"
#133: +1581716796 [appliance] "[ 0.000000] node 0: [mem
0x0000000000100000-0x000000001f3dffff]"
#134: +1582850598 [appliance] "[ 0.000000] Initmem setup node 0 [mem
0x0000000000001000-0x000000001f3dffff]"
#135: +1582851451 [appliance] "[ 0.000000] SFI: Simple Firmware
Interface v0.81 http://simplefirmware.org"
#136: +1582851826 [appliance] "[ 0.000000] Intel MultiProcessor
Specification v1.4"
#137: +1583980321 [appliance] "[ 0.000000] MPTABLE: OEM ID:
BOCHSCPU"
#138: +1583981475 [appliance] "[ 0.000000] MPTABLE: Product ID: 0.1
"
#139: +1583982103 [appliance] "[ 0.000000] MPTABLE: APIC at:
0xFEE00000"
#140: +1585119263 [appliance] "[ 0.000000] Processor #0
(Bootup-CPU)"
#141: +1585120164 [appliance] "[ 0.000000] IOAPIC[0]: apic_id 0,
version 17, address 0xfec00000, GSI 0-23"
#142: +1585120618 [appliance] "[ 0.000000] Processors: 1"
#143: +1585120984 [appliance] "[ 0.000000] smpboot: Allowing 1 CPUs,
0 hotplug CPUs"
#144: +1586254702 [appliance] "[ 0.000000] PM: Registered nosave
memory: [mem 0x00000000-0x00000fff]"
#145: +1586255585 [appliance] "[ 0.000000] PM: Registered nosave
memory: [mem 0x0009f000-0x0009ffff]"
#146: +1586255975 [appliance] "[ 0.000000] PM: Registered nosave
memory: [mem 0x000a0000-0x000effff]"
#147: +1587392642 [appliance] "[ 0.000000] PM: Registered nosave
memory: [mem 0x000f0000-0x000fffff]"
#148: +1587393460 [appliance] "[ 0.000000] e820: [mem
0x1f400000-0xfeffbfff] available for PCI devices"
#149: +1588586224 [appliance] "[ 0.000000] Booting paravirtualized
kernel on KVM"
#150: +1588587092 [appliance] "[ 0.000000] clocksource:
refined-jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns:
1910969940391419 ns"
#151: +1588587939 [appliance] "[ 0.000000] setup_percpu:
NR_CPUS:1024 nr_cpumask_bits:1 nr_cpu_ids:1 nr_node_ids:1"
#152: +1589725448 [appliance] "[ 0.000000] PERCPU: Embedded 34
pages/cpu @ffff88001f000000 s98712 r8192 d32360 u2097152"
#153: +1589726163 [appliance] "[ 0.000000] KVM setup async PF for
cpu 0"
#154: +1590859380 [appliance] "[ 0.000000] kvm-stealtime: cpu 0, msr
1f00d900"
#155: +1590860261 [appliance] "[ 0.000000] Built 1 zonelists in Node
order, mobility grouping on. Total pages: 125849"
#156: +1590860656 [appliance] "[ 0.000000] Policy zone: DMA32"
#157: +1590860968 [appliance] "[ 0.000000] Kernel command line:
panic=1 console=ttyS0 udevtimeout=6000 udev.event-timeout=6000 no_timer_check
acpi=off printk.time=1 cgroup_disable=memory root=/dev/sdb selinux=0
guestfs_verbose=1 TERM=xterm-256color guestfs_boot_analysis=1"
#158: +1593141591 [appliance] "[ 0.000000] PID hash table entries:
2048 (order: 2, 16384 bytes)"
#159: +1593144920 [appliance] "[ 0.000000] Memory: 485620K/511480K
available (7827K kernel code, 1307K rwdata, 3444K rodata, 1528K init, 1544K bss,
25860K reserved, 0K cma-reserved)"
#160: +1594279677 [appliance] "[ 0.000000] SLUB: HWalign=64,
Order=0-3, MinObjects=0, CPUs=1, Nodes=1"
#161: +1594280495 [appliance] "[ 0.000000] Hierarchical RCU
implementation."
#162: +1594280857 [appliance] "[ 0.000000] \x09Build-time adjustment
of leaf fanout to 64."
#163: +1595416032 [appliance] "[ 0.000000] \x09RCU restricting CPUs
from NR_CPUS=1024 to nr_cpu_ids=1."
#164: +1595416908 [appliance] "[ 0.000000] RCU: Adjusting geometry
for rcu_fanout_leaf=64, nr_cpu_ids=1"
#165: +1596557474 [appliance] "[ 0.000000] NR_IRQS:65792 nr_irqs:256
16"
#166: +1596558281 [appliance] "[ 0.000000] \x09Offload RCU callbacks
from all CPUs"
#167: +1596558679 [appliance] "[ 0.000000] \x09Offload RCU callbacks
from CPUs: 0."
#168: +1596558965 [appliance] "[ 0.000000] Console: colour *CGA
80x25"
#169: +1597686741 [appliance] "[ 0.000000] console [ttyS0]
enabled"
#170: +1597687552 [appliance] "[ 0.000000] tsc: Detected 2593.994
MHz processor"
#171: +1597687893 [appliance] "[ 0.042322] Calibrating delay loop
(skipped) preset value.. 5187.98 BogoMIPS (lpj=2593994)"
#172: +1598818246 [appliance] "[ 0.042899] pid_max: default: 32768
minimum: 301"
#173: +1598819117 [appliance] "[ 0.043247] Security Framework
initialized"
#174: +1598819473 [appliance] "[ 0.043530] Yama: becoming
mindful."
#175: +1598819751 [appliance] "[ 0.043776] SELinux: Disabled at
boot."
#176: +1599948692 [appliance] "[ 0.044126] Dentry cache hash table
entries: 65536 (order: 7, 524288 bytes)"
#177: +1599949504 [appliance] "[ 0.044667] Inode-cache hash table
entries: 32768 (order: 6, 262144 bytes)"
#178: +1601083942 [appliance] "[ 0.045182] Mount-cache hash table
entries: 1024 (order: 1, 8192 bytes)"
#179: +1601103870 [appliance] "[ 0.045644] Mountpoint-cache hash
table entries: 1024 (order: 1, 8192 bytes)"
#180: +1602354592 [appliance] "[ 0.046257] Initializing cgroup
subsys io"
#181: +1602355839 [appliance] "[ 0.046550] Initializing cgroup
subsys memory"
#182: +1602356484 [appliance] "[ 0.047015] Disabling memory control
group subsystem"
#183: +1602357037 [appliance] "[ 0.047366] Initializing cgroup
subsys devices"
#184: +1603482878 [appliance] "[ 0.047676] Initializing cgroup
subsys freezer"
#185: +1603483979 [appliance] "[ 0.048004] Initializing cgroup
subsys net_cls"
#186: +1603484632 [appliance] "[ 0.048325] Initializing cgroup
subsys perf_event"
#187: +1604608898 [appliance] "[ 0.048661] Initializing cgroup
subsys net_prio"
#188: +1604610070 [appliance] "[ 0.049011] Initializing cgroup
subsys hugetlb"
#189: +1604610703 [appliance] "[ 0.049318] Initializing cgroup
subsys pids"
#190: +1606681477 [appliance] "[ 0.050568] mce: CPU supports 10 MCE
banks"
#191: +1606682705 [appliance] "[ 0.050894] Last level iTLB entries:
4KB 0, 2MB 0, 4MB 0"
#192: +1606683312 [appliance] "[ 0.051266] Last level dTLB entries:
4KB 0, 2MB 0, 4MB 0, 1GB 0"
#193: +1615740666 [appliance] "[ 0.059647] Freeing SMP alternatives
memory: 28K (ffffffff81ec6000 - ffffffff81ecd000)"
#194: +1618329957 [appliance] "[ 0.062278] ftrace: allocating 29522
entries in 116 pages"
#195: +1639245067 [appliance] "[ 0.083108] x2apic enabled"
#196: +1639246590 [appliance] "[ 0.083504] Switched APIC routing to
physical x2apic."
#197: +1640618314 [appliance] "[ 0.084557] ..TIMER: vector=0x30
apic1=0 pin1=2 apic2=-1 pin2=-1"
#198: +1640619617 [appliance] "[ 0.085010] smpboot: CPU0: Intel(R)
Core(TM) i7-5600U CPU @ 2.60GHz (family: 0x6, model: 0x3d, stepping: 0x4)"
#199: +1641752086 [appliance] "[ 0.085737] Performance Events:
16-deep LBR, Broadwell events, Intel PMU driver."
#200: +1641753183 [appliance] "[ 0.086259] ... version:
2"
#201: +1641753868 [appliance] "[ 0.086520] ... bit width:
48"
#202: +1642887320 [appliance] "[ 0.086807] ... generic registers:
4"
#203: +1642888446 [appliance] "[ 0.087084] ... value mask:
0000ffffffffffff"
#204: +1642889053 [appliance] "[ 0.087426] ... max period:
000000007fffffff"
#205: +1642889644 [appliance] "[ 0.087785] ... fixed-purpose events:
3"
#206: +1643997597 [appliance] "[ 0.088067] ... event mask:
000000070000000f"
#207: +1643998680 [appliance] "[ 0.088876] x86: Booted up 1 node, 1
CPUs"
#208: +1645113532 [appliance] "[ 0.089164] smpboot: Total of 1
processors activated (5187.98 BogoMIPS)"
#209: +1645114628 [appliance] "[ 0.089820] devtmpfs:
initialized"
#210: +1647435717 [appliance] "[ 0.091309] clocksource: jiffies:
mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 1911260446275000 ns"
#211: +1647437208 [appliance] "[ 0.092033] atomic64_test: passed for
x86-64 platform with CX8 and with SSE"
#212: +1648570136 [appliance] "[ 0.092509] pinctrl core: initialized
pinctrl subsystem"
#213: +1648571251 [appliance] "[ 0.092902] RTC time: 12:39:30, date:
03/20/16"
#214: +1648571931 [appliance] "[ 0.093283] NET: Registered protocol
family 16"
#215: +1649813088 [appliance] "[ 0.093715] cpuidle: using governor
menu"
#216: +1649814266 [appliance] "[ 0.094161] PCI: Using configuration
type 1 for base access"
#217: +1651492027 [appliance] "[ 0.095384] ACPI: Interpreter
disabled."
#218: +1651493402 [appliance] "[ 0.095723] vgaarb: loaded"
#219: +1651494004 [appliance] "[ 0.095970] SCSI subsystem
initialized"
#220: +1651494578 [appliance] "[ 0.096272] usbcore: registered new
interface driver usbfs"
#221: +1652625942 [appliance] "[ 0.096667] usbcore: registered new
interface driver hub"
#222: +1652627060 [appliance] "[ 0.097019] usbcore: registered new
device driver usb"
#223: +1652627626 [appliance] "[ 0.097406] PCI: Probing PCI
hardware"
#224: +1653790879 [appliance] "[ 0.097685] PCI host bridge to bus
0000:00"
#225: +1653792047 [appliance] "[ 0.097983] pci_bus 0000:00: root bus
resource [io 0x0000-0xffff]"
#226: +1653792749 [appliance] "[ 0.098385] pci_bus 0000:00: root bus
resource [mem 0x00000000-0xffffffffff]"
#227: +1654897966 [appliance] "[ 0.098866] pci_bus 0000:00: No busn
resource found for root bus, will use [bus 00-ff]"
#228: +1659252834 [appliance] "[ 0.103113] pci 0000:00:01.1: legacy
IDE quirk: reg 0x10: [io 0x01f0-0x01f7]"
#229: +1659254425 [appliance] "[ 0.103612] pci 0000:00:01.1: legacy
IDE quirk: reg 0x14: [io 0x03f6]"
#230: +1659255065 [appliance] "[ 0.104041] pci 0000:00:01.1: legacy
IDE quirk: reg 0x18: [io 0x0170-0x0177]"
#231: +1660375095 [appliance] "[ 0.104521] pci 0000:00:01.1: legacy
IDE quirk: reg 0x1c: [io 0x0376]"
#232: +1660376209 [appliance] "[ 0.105277] pci 0000:00:01.3: quirk:
[io 0x0600-0x063f] claimed by PIIX4 ACPI"
#233: +1661501079 [appliance] "[ 0.105773] pci 0000:00:01.3: quirk:
[io 0x0700-0x070f] claimed by PIIX4 SMB"
#234: +1676525754 [appliance] "[ 0.120383] pci 0000:00:01.0:
PIIX/ICH IRQ router [8086:7000]"
#235: +1676527343 [appliance] "[ 0.120922] NetLabel:
Initializing"
#236: +1676528014 [appliance] "[ 0.121139] NetLabel: domain hash
size = 128"
#237: +1676528606 [appliance] "[ 0.121413] NetLabel: protocols =
UNLABELED CIPSOv4"
#238: +1679736296 [appliance] "[ 0.121761] NetLabel: unlabeled
traffic allowed by default"
#239: +1679737535 [appliance] "[ 0.124087] clocksource: Switched to
clocksource kvm-clock"
#240: +1684459475 [appliance] "[ 0.128332] pnp: PnP ACPI:
disabled"
#241: +1686180166 [appliance] "[ 0.130045] NET: Registered protocol
family 2"
#242: +1686181360 [appliance] "[ 0.130556] TCP established hash
table entries: 4096 (order: 3, 32768 bytes)"
#243: +1686182040 [appliance] "[ 0.131006] TCP bind hash table
entries: 4096 (order: 4, 65536 bytes)"
#244: +1687323987 [appliance] "[ 0.131434] TCP: Hash tables
configured (established 4096 bind 4096)"
#245: +1687325288 [appliance] "[ 0.131998] UDP hash table entries:
256 (order: 1, 8192 bytes)"
#246: +1688458606 [appliance] "[ 0.132380] UDP-Lite hash table
entries: 256 (order: 1, 8192 bytes)"
#247: +1688459672 [appliance] "[ 0.132813] NET: Registered protocol
family 1"
#248: +1688460315 [appliance] "[ 0.133098] pci 0000:00:00.0:
Limiting direct PCI/PCI transfers"
#249: +1688460842 [appliance] "[ 0.133488] pci 0000:00:01.0: PIIX3:
Enabling Passive Release"
#250: +1689589876 [appliance] "[ 0.133873] pci 0000:00:01.0:
Activating ISA DMA hang workarounds"
#251: +1689590922 [appliance] "[ 0.134323] Unpacking
initramfs..."
#252: +1690869934 [appliance] "[ 0.134757] Freeing initrd memory:
344K (ffff88001f38a000 - ffff88001f3e0000)"
#253: +1690871151 [appliance] "[ 0.135306] platform rtc_cmos:
registered platform RTC device (no PNP device found)"
#254: +1692150258 [appliance] "[ 0.136028] futex hash table entries:
256 (order: 2, 16384 bytes)"
#255: +1692151431 [appliance] "[ 0.136456] audit: initializing
netlink subsys (disabled)"
#256: +1692152068 [appliance] "[ 0.136797] audit: type=2000
audit(1458477570.228:1): initialized"
#257: +1693488247 [appliance] "[ 0.137368] Initialise system trusted
keyring"
#258: +1693489376 [appliance] "[ 0.137721] HugeTLB registered 1 GB
page size, pre-allocated 0 pages"
#259: +1693490036 [appliance] "[ 0.138114] HugeTLB registered 2 MB
page size, pre-allocated 0 pages"
#260: +1695492419 [appliance] "[ 0.139386] zbud: loaded"
#261: +1695493520 [appliance] "[ 0.139736] VFS: Disk quotas
dquot_6.6.0"
#262: +1695494120 [appliance] "[ 0.140037] VFS: Dquot-cache hash
table entries: 512 (order 0, 4096 bytes)"
#263: +1696830315 [appliance] "[ 0.140745] Key type big_key
registered"
#264: +1698648419 [appliance] "[ 0.142517] NET: Registered protocol
family 38"
#265: +1698649574 [appliance] "[ 0.142837] Key type asymmetric
registered"
#266: +1698650142 [appliance] "[ 0.143101] Asymmetric key parser
'x509' registered"
#267: +1698650630 [appliance] "[ 0.143441] Block layer SCSI generic
(bsg) driver version 0.4 loaded (major 250)"
#268: +1699757284 [appliance] "[ 0.143960] io scheduler noop
registered"
#269: +1699758351 [appliance] "[ 0.144218] io scheduler deadline
registered"
#270: +1699758834 [appliance] "[ 0.144509] io scheduler cfq
registered (default)"
#271: +1700871756 [appliance] "[ 0.144951] pci_hotplug: PCI Hot Plug
PCI Core version: 0.5"
#272: +1700872825 [appliance] "[ 0.145504] pciehp: PCI Express Hot
Plug Controller Driver version: 0.4"
#273: +1701981381 [appliance] "[ 0.146338] Serial: 8250/16550
driver, 32 ports, IRQ sharing enabled"
#274: +1725263660 [appliance] "[ 0.169120] serial8250: ttyS0 at I/O
0x3f8 (irq = 4, base_baud = 115200) is a 16550A"
#275: +1726732608 [appliance] "[ 0.170625] Non-volatile memory
driver v1.3"
#276: +1726733819 [appliance] "[ 0.170934] Linux agpgart interface
v0.103"
#277: +1728052309 [appliance] "[ 0.171928] scsi host0:
ata_piix"
#278: +1728053464 [appliance] "[ 0.172211] scsi host1:
ata_piix"
#279: +1728054048 [appliance] "[ 0.172434] ata1: PATA max MWDMA2 cmd
0x1f0 ctl 0x3f6 bmdma 0xc060 irq 14"
#280: +1728054608 [appliance] "[ 0.172853] ata2: PATA max MWDMA2 cmd
0x170 ctl 0x376 bmdma 0xc068 irq 15"
#281: +1729168429 [appliance] "[ 0.173476] libphy: Fixed MDIO Bus:
probed"
#282: +1729169175 [appliance] "[ 0.173786] ehci_hcd: USB 2.0
'Enhanced' Host Controller (EHCI) Driver"
#283: +1729169683 [appliance] "[ 0.174200] ehci-pci: EHCI PCI
platform driver"
#284: +1730303942 [appliance] "[ 0.174488] ohci_hcd: USB 1.1
'Open' Host Controller (OHCI) Driver"
#285: +1730304877 [appliance] "[ 0.174872] ohci-pci: OHCI PCI
platform driver"
#286: +1730305483 [appliance] "[ 0.175153] uhci_hcd: USB Universal
Host Controller Interface driver"
#287: +1731440277 [appliance] "[ 0.175595] usbcore: registered new
interface driver usbserial"
#288: +1731441370 [appliance] "[ 0.175952] usbcore: registered new
interface driver usbserial_generic"
#289: +1731441947 [appliance] "[ 0.176356] usbserial: USB Serial
support registered for generic"
#290: +1732558403 [appliance] "[ 0.176769] i8042: PNP: No PS/2
controller found. Probing ports directly."
#291: +1733773238 [appliance] "[ 0.177666] serio: i8042 KBD port at
0x60,0x64 irq 1"
#292: +1733775278 [appliance] "[ 0.178004] serio: i8042 AUX port at
0x60,0x64 irq 12"
#293: +1733776291 [appliance] "[ 0.178538] mousedev: PS/2 mouse
device common for all mice"
#294: +1734866211 [appliance] "[ 0.179046] input: AT Translated Set
2 keyboard as /devices/platform/i8042/serio0/input/input0"
#295: +1736122554 [appliance] "[ 0.180003] input: VirtualPS/2 VMware
VMMouse as /devices/platform/i8042/serio1/input/input3"
#296: +1736123737 [appliance] "[ 0.180678] input: VirtualPS/2 VMware
VMMouse as /devices/platform/i8042/serio1/input/input2"
#297: +1737241349 [appliance] "[ 0.181383] rtc_cmos rtc_cmos: rtc
core: registered rtc_cmos as rtc0"
#298: +1737242386 [appliance] "[ 0.181855] rtc_cmos rtc_cmos: alarms
up to one day, 114 bytes nvram"
#299: +1738435495 [appliance] "[ 0.182323] device-mapper: uevent:
version 1.0.3"
#300: +1738436644 [appliance] "[ 0.182715] device-mapper: ioctl:
4.34.0-ioctl (2015-10-28) initialised: dm-devel@redhat.com"
#301: +1738437290 [appliance] "[ 0.183308] hidraw: raw HID events
driver (C) Jiri Kosina"
#302: +1739584034 [appliance] "[ 0.183692] usbcore: registered new
interface driver usbhid"
#303: +1739585080 [appliance] "[ 0.184033] usbhid: USB HID core
driver"
#304: +1739585620 [appliance] "[ 0.184303] drop_monitor:
Initializing network drop monitor service"
#305: +1740715371 [appliance] "[ 0.184760] ip_tables: (C) 2000-2006
Netfilter Core Team"
#306: +1740716398 [appliance] "[ 0.185124] Initializing XFRM netlink
socket"
#307: +1740716930 [appliance] "[ 0.185483] NET: Registered protocol
family 10"
#308: +1741838627 [appliance] "[ 0.185897] mip6: Mobile IPv6"
#309: +1741839672 [appliance] "[ 0.186093] NET: Registered protocol
family 17"
#310: +1741840263 [appliance] "[ 0.186484] microcode: CPU0
sig=0x306d4, pf=0x1, revision=0x1"
#311: +1741840890 [appliance] "[ 0.186862] microcode: Microcode
Update Driver: v2.01 <tigran@aivazian.fsnet.co.uk>, Peter Oruba"
#312: +1742977245 [appliance] "[ 0.187424] AVX2 version of
gcm_enc/dec engaged."
#313: +1742978146 [appliance] "[ 0.187711] AES CTR mode by8
optimization enabled"
#314: +1761190772 [appliance] "[ 0.205062] registered taskstats
version 1"
#315: +1761192139 [appliance] "[ 0.205385] Loading compiled-in X.509
certificates"
#316: +1762375083 [appliance] "[ 0.206244] Loaded X.509 cert
'Fedora kernel signing key:
ff671496ff3f386a8ef2031bac2201b2edb4da2a'"
#317: +1762376206 [appliance] "[ 0.206852] zswap: loaded using pool
lzo/zbud"
#318: +1762376854 [appliance] "[ 0.207256] Magic number:
8:887:683"
#319: +1763466629 [appliance] "[ 0.207568] rtc_cmos rtc_cmos:
setting system clock to 2016-03-20 12:39:30 UTC (1458477570)"
#320: +1886127448 [appliance] "[ 0.330021] Freeing unused kernel
memory: 1528K (ffffffff81d48000 - ffffffff81ec6000)"
#321: +1886129424 [appliance] "[ 0.330562] Write protecting the
kernel read-only data: 12288k"
#322: +1886132750 [appliance] "[ 0.331080] Freeing unused kernel
memory: 352K (ffff8800017a8000 - ffff880001800000)"
#323: +1888843733 [appliance] "[ 0.332742] Freeing unused kernel
memory: 652K (ffff880001b5d000 - ffff880001c00000)"
#324: +1888844654 [appliance] "supermin: mounting /proc"
#325: +1888845046 [appliance] "supermin: ext2 mini initrd starting up:
5.1.15 dietlibc"
#326: +1890013809 [appliance] "supermin: cmdline: panic=1 console=ttyS0
udevtimeout=6000 udev.event-timeout=6000 no_timer_check acpi=off printk.time=1
cgroup_disable=memory root=/dev/sdb selinux=0 guestfs_verbose=1
TERM=xterm-256color guestfs_boot_analysis=1"
#327: +1890014781 [appliance] "supermin: uptime: 0.27 0.14"
#328: +1891127695 [appliance] "supermin: mounting /sys"
#329: +1891128224 [appliance] "supermin: internal insmod
crc32-pclmul.ko"
#330: +1892467473 [appliance] "supermin: internal insmod
crc32c-intel.ko"
#331: +1892468289 [appliance] "supermin: internal insmod
crct10dif-pclmul.ko"
#332: +1893570041 [appliance] "supermin: internal insmod crc32.ko"
#333: +1894659309 [appliance] "supermin: internal insmod
virtio.ko"
#334: +1896422680 [appliance] "supermin: internal insmod
virtio_ring.ko"
#335: +1896423390 [appliance] "supermin: internal insmod
virtio_blk.ko"
#336: +1897501521 [appliance] "supermin: internal insmod
virtio-rng.ko"
#337: +1898629654 [appliance] "supermin: internal insmod
virtio_console.ko"
#338: +1900657612 [appliance] "supermin: internal insmod
virtio_net.ko"
#339: +1901920188 [appliance] "supermin: internal insmod
virtio_scsi.ko"
#340: +1903044166 [appliance] "supermin: internal insmod
virtio_balloon.ko"
#341: +1903045442 [appliance] "supermin: internal insmod
virtio_input.ko"
#342: +1904128275 [appliance] "supermin: internal insmod
virtio_mmio.ko"
#343: +1905209093 [appliance] "supermin: internal insmod
virtio_pci.ko"
#344: +1906282571 [appliance] "[ 0.351153] virtio-pci 0000:00:02.0:
PCI->APIC IRQ transform: INT A -> IRQ 10"
#345: +1907391885 [appliance] "[ 0.351667] virtio-pci 0000:00:02.0:
virtio_pci: leaving for legacy driver"
#346: +1908770046 [appliance] "[ 0.352690] scsi host2: Virtio SCSI
HBA"
#347: +1908771021 [appliance] "[ 0.353102] virtio-pci 0000:00:03.0:
PCI->APIC IRQ transform: INT A -> IRQ 11"
#348: +1908771444 [appliance] "[ 0.353598] virtio-pci 0000:00:03.0:
virtio_pci: leaving for legacy driver"
#349: +1912827625 [appliance] "[ 0.356731] scsi 2:0:0:0:
Direct-Access QEMU QEMU HARDDISK 2.5+ PQ: 0 ANSI: 5"
#350: +1912829131 [appliance] "[ 0.357470] scsi 2:0:1:0:
Direct-Access QEMU QEMU HARDDISK 2.5+ PQ: 0 ANSI: 5"
#351: +1931634509 [appliance] "[ 0.375493] sd 2:0:0:0: Attached scsi
generic sg0 type 0"
#352: +1931635875 [appliance] "[ 0.376027] sd 2:0:1:0: Attached scsi
generic sg1 type 0"
#353: +1931636107 [appliance] "[ 0.376556] sd 2:0:0:0: [sda] 8
512-byte logical blocks: (4.10 kB/4.00 KiB)"
#354: +1932757666 [appliance] "[ 0.377143] sd 2:0:1:0: [sdb] 8388608
512-byte logical blocks: (4.29 GB/4.00 GiB)"
#355: +1934002572 [appliance] "[ 0.377865] sd 2:0:0:0: [sda] Write
Protect is off"
#356: +1934003696 [appliance] "[ 0.378248] sd 2:0:1:0: [sdb] Write
Protect is off"
#357: +1934003952 [appliance] "[ 0.378657] sd 2:0:0:0: [sda] Write
cache: enabled, read cache: enabled, doesn't support DPO or FUA"
#358: +1935128289 [appliance] "[ 0.379302] sd 2:0:1:0: [sdb] Write
cache: enabled, read cache: enabled, doesn't support DPO or FUA"
#359: +1936911379 [appliance] "[ 0.380705] Dev sda: unable to read
RDB block 8"
#360: +1936912327 [appliance] "[ 0.381140] sda: unable to read
partition table"
#361: +1936912566 [appliance] "[ 0.381490] sda: partition table
beyond EOD, enabling native capacity"
#362: +1938500321 [appliance] "[ 0.382389] sd 2:0:1:0: [sdb]
Attached SCSI disk"
#363: +1938501116 [appliance] "[ 0.382900] Dev sda: unable to read
RDB block 8"
#364: +1938501336 [appliance] "[ 0.383215] sda: unable to read
partition table"
#365: +1938501487 [appliance] "[ 0.383532] sda: partition table
beyond EOD, truncated"
#366: +1939611728 [appliance] "[ 0.384237] sd 2:0:0:0: [sda]
Attached SCSI disk"
#367: +1939612220 [appliance] "supermin: internal insmod
crc-ccitt.ko"
#368: +1940714392 [appliance] "supermin: internal insmod
crc-itu-t.ko"
#369: +1941821487 [appliance] "supermin: internal insmod crc8.ko"
#370: +1943365168 [appliance] "supermin: internal insmod
libcrc32c.ko"
#371: +1943365983 [appliance] "supermin: picked /sys/block/sdb/dev as
root device"
#372: +1944460610 [appliance] "supermin: creating /dev/root as block
special 8:16"
#373: +1944461337 [appliance] "supermin: mounting new root on
/root"
#374: +1944461511 [appliance] "[ 0.389441] EXT4-fs (sdb): mounting
ext2 file system using the ext4 subsystem"
#375: +1948265619 [appliance] "[ 0.392188] EXT4-fs (sdb): mounted
filesystem without journal. Opts: "
#376: +1948266732 [appliance] "supermin: chroot"
#377: +1956567229 [appliance] "Starting /init script ..."
#378: +2064643002 [appliance] "[ 0.508528] random: systemd-tmpfile
urandom read with 79 bits of entropy available"
#379: +2065944843 [appliance]
"[/usr/lib/tmpfiles.d/journal-nocow.conf:26] Failed to replace specifiers:
/var/log/journal/%m"
#380: +2067292216 [appliance] "[/usr/lib/tmpfiles.d/systemd.conf:26]
Failed to replace specifiers: /run/log/journal/%m"
#381: +2067293412 [appliance] "[/usr/lib/tmpfiles.d/systemd.conf:28]
Failed to replace specifiers: /run/log/journal/%m"
#382: +2067293710 [appliance] "[/usr/lib/tmpfiles.d/systemd.conf:29]
Failed to replace specifiers: /run/log/journal/%m"
#383: +2068440681 [appliance] "[/usr/lib/tmpfiles.d/systemd.conf:32]
Failed to replace specifiers: /var/log/journal/%m"
#384: +2068441058 [appliance] "[/usr/lib/tmpfiles.d/systemd.conf:33]
Failed to replace specifiers: /var/log/journal/%m/system.journal"
#385: +2069945670 [appliance] "[/usr/lib/tmpfiles.d/systemd.conf:37]
Failed to replace specifiers: /var/log/journal/%m"
#386: +2069946507 [appliance] "[/usr/lib/tmpfiles.d/systemd.conf:38]
Failed to replace specifiers: /var/log/journal/%m"
#387: +2069946791 [appliance] "[/usr/lib/tmpfiles.d/systemd.conf:39]
Failed to replace specifiers: /var/log/journal/%m/system.journal"
#388: +2072200550 [appliance]
"UDEVD=/usr/lib/systemd/systemd-udevd"
#389: +2074745745 [appliance] "starting version 229"
#390: +2166190858 [appliance] "[ 0.610068] piix4_smbus 0000:00:01.3:
PCI->APIC IRQ transform: INT A -> IRQ 9"
#391: +2166192150 [appliance] "[ 0.610752] piix4_smbus 0000:00:01.3:
SMBus Host Controller at 0x700, revision 0"
#392: +2190375042 [appliance] "[ 0.634255] input: PC Speaker as
/devices/platform/pcspkr/input/input4"
#393: +2197211627 [appliance] "[ 0.641119] random: nonblocking pool
is initialized"
#394: +2201263496 [appliance] "[ 0.645144] intel_rapl: no valid rapl
domains found in package 0"
#395: +2210122223 [appliance] "+ grep -sq guestfs_network=1
/proc/cmdline"
#396: +2210123413 [appliance] "+ grep -sq guestfs_rescue=1
/proc/cmdline"
#397: +2211676758 [appliance] "+ grep -sq guestfs_noreboot=1
/proc/cmdline"
#398: +2211677608 [appliance] "+ grep -sq guestfs_boot_analysis=1
/proc/cmdline"
#399: +2214179490 [appliance] "+ guestfs_boot_analysis=1"
#400: +2214180419 [appliance] "++ grep -Eo
'guestfs_channel=[^[:space:]]+' /proc/cmdline"
#401: +2215360930 [appliance] "+ eval"
#402: +2215361784 [appliance] "+ grep -sq selinux=1 /proc/cmdline"
#403: +2215362026 [appliance] "+ shopt -s nullglob"
#404: +2215362185 [appliance] "+ for f in
'/sys/block/sd*/device/timeout'"
#405: +2216488450 [appliance] "+ echo 300"
#406: +2216488833 [appliance] "+ for f in
'/sys/block/sd*/device/timeout'"
#407: +2216488970 [appliance] "+ echo 300"
#408: +2216489123 [appliance] "+ for f in
'/sys/block/{h,s,ub,v}d*/queue/scheduler'"
#409: +2216489257 [appliance] "+ echo noop"
#410: +2217672460 [appliance] "+ for f in
'/sys/block/{h,s,ub,v}d*/queue/scheduler'"
#411: +2217674626 [appliance] "+ echo noop"
#412: +2217674953 [appliance] "+ shopt -u nullglob"
#413: +2217675279 [appliance] "+ ip addr add 127.0.0.1/8 brd + dev lo
scope host"
#414: +2220033292 [appliance] "+ ip link set dev lo up"
#415: +2220034517 [appliance] "+ test '' = 1"
#416: +2220034797 [appliance] "+ mdadm -As --auto=yes --run"
#417: +2223956603 [appliance] "mdadm: No arrays found in config file or
automatically"
#418: +2223957984 [appliance] "+ modprobe dm_mod"
#419: +2225298741 [appliance] "+ lvmetad"
#420: +2227762913 [appliance] "+ lvm vgchange -aay --sysinit"
#421: +2231333146 [appliance] " Configuration setting
"global/notify_dbus" unknown."
#422: +2231334173 [appliance] " lvmetad is not active yet, using
direct activation during sysinit"
#423: +2234022854 [appliance] "+ ldmtool create all"
#424: +2238833631 [appliance] "["
#425: +2238834839 [appliance] "]"
#426: +2238834990 [appliance] "+ test 1 = 1"
#427: +2238835145 [appliance] "+ test 1 '!=' 1"
#428: +2238835324 [appliance] "+ test '' = 1"
#429: +2240017320 [appliance] "+ cmd=guestfsd"
#430: +2240018150 [appliance] "+ test x '!=' x"
#431: +2240018398 [appliance] "+ test 1 = 1"
#432: +2240018533 [appliance] "+ cmd='guestfsd --verbose'"
#433: +2240018686 [appliance] "+ test '' = 1"
#434: +2240018827 [appliance] "+ echo guestfsd --verbose"
#435: +2240018953 [appliance] "guestfsd --verbose"
#436: +2240019070 [appliance] "+ guestfsd --verbose"
#437: +2248600573 [appliance] "trying to open virtio-serial channel
'/dev/virtio-ports/org.libguestfs.channel.0'"
#438: +2248601967 [appliance] "udevadm --debug settle"
#439: +2250839221 [appliance] "calling: settle"
#440: +2250847987 [launch_done] "launch done callback"
#441: +2250850513 [library] "recv_from_daemon: received
GUESTFS_LAUNCH_FLAG"
#442: +2250852032 [library] "appliance is up"
#443: +2250877067 [trace] "launch = 0"
#444: +2250878155 [trace] "close"
#445: +2250879672 [library] "closing guestfs handle 0x55eb2eb8c7a0
(state 2)"
#446: +2250883093 [trace] "internal_autosync"
#447: +2253681120 [appliance] "guestfsd: main_loop: new request, len
0x28"
#448: +2253681925 [appliance] "umount-all: /proc/mounts:
fsname=/dev/root dir=/ type=ext2
opts=rw,noatime,block_validity,barrier,user_xattr,acl freq=0 passno=0"
#449: +2253682315 [appliance] "umount-all: /proc/mounts: fsname=/proc
dir=/proc type=proc opts=rw,relatime freq=0 passno=0"
#450: +2254851718 [appliance] "umount-all: /proc/mounts: fsname=/sys
dir=/sys type=sysfs opts=rw,relatime freq=0 passno=0"
#451: +2254852079 [appliance] "umount-all: /proc/mounts: fsname=tmpfs
dir=/run type=tmpfs opts=rw,nosuid,relatime,size=97708k,mode=755 freq=0
passno=0"
#452: +2255974417 [appliance] "umount-all: /proc/mounts: fsname=/dev
dir=/dev type=devtmpfs opts=rw,relatime,size=242824k,nr_inodes=60706,mode=755
freq=0 passno=0"
#453: +2258852466 [appliance] "fsync /dev/sda"
#454: +2259948899 [trace] "internal_autosync = 0"
#455: +2259950967 [library] "sending SIGTERM to process 21627"
#456: +2266872725 [close] "close callback"
#457: +2266880057 [library] "command: run: rm"
#458: +2266881759 [library] "command: run: \ -rf
/home/rjones/d/libguestfs/tmp/libguestfsnmgtRi"
#459: +2268445016 [library] "command: run: rm"
#460: +2268446292 [library] "command: run: \ -rf
/run/user/1000/libguestfsRJNA2d"
Analyzing the results ...
activity 0:
name = run
start - end = 0.0 - 2274701058.0
mean elapsed = 2274701059.0
variance = 63484801030225.0
s.d = 7967735.0
percent = 100.0
activity 1:
name = supermin:build
start - end = 96929.0 - 10536212.0
mean elapsed = 10439284.0
variance = 2863962256.0
s.d = 53516.0
percent = 0.5
activity 2:
name = qemu:feature-detect
start - end = 10555890.5 - 301795202.5
mean elapsed = 291239313.0
variance = 19899334225.0
s.d = 141065.0
percent = 12.8
activity 3:
name = qemu
start - end = 303574861.0 - 2274701058.0
mean elapsed = 1971126198.0
variance = 58365871739536.0
s.d = 7639756.0
percent = 86.7
activity 4:
name = qemu:overhead
start - end = 303574861.0 - 466505618.0
mean elapsed = 162930758.0
variance = 2672626623489.0
s.d = 1634817.0
percent = 7.2
activity 5:
name = bios:overhead
start - end = 466505619.0 - 1571329958.0
mean elapsed = 1104824340.0
variance = 23619959641369.0
s.d = 4860037.0
percent = 48.6
activity 6:
name = sgabios
start - end = 466505619.0 - 734679600.5
mean elapsed = 268173982.5
variance = 1075855407990.2
s.d = 1037234.5
percent = 11.8
activity 7:
name = seabios
start - end = 734679601.5 - 1571329958.0
mean elapsed = 836650357.5
variance = 14613818954006.2
s.d = 3822802.5
percent = 36.8
activity 8:
name = kernel
start - end = 1571329959.0 - 2274701058.0
mean elapsed = 703371100.0
variance = 1310800589604.0
s.d = 1144902.0
percent = 30.9
activity 9:
name = kernel:overhead
start - end = 1571329959.0 - 1894835218.0
mean elapsed = 323505260.0
variance = 480608041081.0
s.d = 693259.0
percent = 14.2
activity 10:
name = supermin:mini-initrd
start - end = 1894835219.0 - 1952255107.5
mean elapsed = 57419889.5
variance = 4007189227412.2
s.d = 2001796.5
percent = 2.5
activity 11:
name = supermin: internal insmod crc32-pclmul.ko
start - end = 1897110208.5 - 1898453500.5
mean elapsed = 1343293.0
variance = 16353936.0
s.d = 4044.0
percent = 0.1
activity 12:
name = supermin: internal insmod crc32c-intel.ko
start - end = 1898453501.5 - 1898454334.5
mean elapsed = 834.0
variance = 324.0
s.d = 18.0
percent = 0.0
activity 13:
name = supermin: internal insmod crct10dif-pclmul.ko
start - end = 1898454335.5 - 1899555569.5
mean elapsed = 1101235.0
variance = 267289.0
s.d = 517.0
percent = 0.0
activity 14:
name = supermin: internal insmod crc32.ko
start - end = 1899555570.5 - 1900680311.0
mean elapsed = 1124741.5
variance = 1258369202.2
s.d = 35473.5
percent = 0.0
activity 15:
name = supermin: internal insmod virtio.ko
start - end = 1900680312.0 - 1902419242.5
mean elapsed = 1738931.5
variance = 597289160.2
s.d = 24439.5
percent = 0.1
activity 16:
name = supermin: internal insmod virtio_ring.ko
start - end = 1902419243.5 - 1902419999.5
mean elapsed = 757.0
variance = 2209.0
s.d = 47.0
percent = 0.0
activity 17:
name = supermin: internal insmod virtio_blk.ko
start - end = 1902420000.5 - 1903535750.5
mean elapsed = 1115751.0
variance = 1415264400.0
s.d = 37620.0
percent = 0.0
activity 18:
name = supermin: internal insmod virtio-rng.ko
start - end = 1903535751.5 - 1904648304.0
mean elapsed = 1112553.5
variance = 242720820.2
s.d = 15579.5
percent = 0.0
activity 19:
name = supermin: internal insmod virtio_console.ko
start - end = 1904648305.0 - 1906680446.0
mean elapsed = 2032142.0
variance = 17505856.0
s.d = 4184.0
percent = 0.1
activity 20:
name = supermin: internal insmod virtio_net.ko
start - end = 1906680447.0 - 1907938191.5
mean elapsed = 1257745.5
variance = 23333730.2
s.d = 4830.5
percent = 0.1
activity 21:
name = supermin: internal insmod virtio_scsi.ko
start - end = 1907938192.5 - 1908500560.5
mean elapsed = 562369.0
variance = 315404668881.0
s.d = 561609.0
percent = 0.0
activity 22:
name = supermin: internal insmod virtio_balloon.ko
start - end = 1908500561.5 - 1909049825.0
mean elapsed = 549264.5
variance = 300291396132.2
s.d = 547988.5
percent = 0.0
activity 23:
name = supermin: internal insmod virtio_input.ko
start - end = 1909049826.0 - 1910141567.5
mean elapsed = 1091742.5
variance = 79379190.2
s.d = 8909.5
percent = 0.0
activity 24:
name = supermin: internal insmod virtio_mmio.ko
start - end = 1910141568.5 - 1911230190.5
mean elapsed = 1088623.0
variance = 60918025.0
s.d = 7805.0
percent = 0.0
activity 25:
name = supermin: internal insmod virtio_pci.ko
start - end = 1911230191.5 - 1943768783.0
mean elapsed = 32538592.5
variance = 3476488901690.2
s.d = 1864534.5
percent = 1.4
activity 26:
name = supermin: internal insmod crc-ccitt.ko
start - end = 1943768784.0 - 1945177177.5
mean elapsed = 1408394.5
variance = 93772219506.2
s.d = 306222.5
percent = 0.1
activity 27:
name = supermin: internal insmod crc-itu-t.ko
start - end = 1945177178.5 - 1945731075.0
mean elapsed = 553897.5
variance = 306027474006.2
s.d = 553197.5
percent = 0.0
activity 28:
name = supermin: internal insmod crc8.ko
start - end = 1945731076.0 - 1947376801.0
mean elapsed = 1645726.0
variance = 10413182025.0
s.d = 102045.0
percent = 0.1
activity 29:
name = supermin: internal insmod libcrc32c.ko
start - end = 1947376802.0 - 1947377778.5
mean elapsed = 977.5
variance = 26406.2
s.d = 162.5
percent = 0.0
activity 30:
name = /init
start - end = 1952255108.5 - 2245612189.5
mean elapsed = 293357082.0
variance = 2576927088961.0
s.d = 1605281.0
percent = 12.9
activity 31:
name = bash:overhead
start - end = 1952255108.5 - 1960732999.5
mean elapsed = 8477892.0
variance = 31468986025.0
s.d = 177395.0
percent = 0.4
activity 32:
name = guestfsd
start - end = 2245612190.5 - 2264261139.5
mean elapsed = 18648950.0
variance = 34218710289.0
s.d = 184983.0
percent = 0.8
activity 33:
name = shutdown
start - end = 2256491452.5 - 2274701058.0
mean elapsed = 18209606.5
variance = 4906386696332.2
s.d = 2215036.5
percent = 0.8
libguestfs 1.33.15
Host:
Appliance:
qemu version 2.5
\x1b[2J\x0dSeaBIOS (version 1.8.2-20150714_191134-)
[ 0.000000] Linux version 4.4.4-301.fc23.x86_64
(mockbuild@bkernel02.phx2.fedoraproject.org) (gcc version 5.3.1 20151207 (Red
Hat 5.3.1-2) (GCC) ) #1 SMP Fri Mar 4 17:42:42 UTC 2016
supermin: ext2 mini initrd starting up: 5.1.15 dietlibc
0.000000s: run mean:2.274701s 8.0ms (100.0%)
0.000097s: supermin:build mean:0.010439s 0.1ms (0.5%)
0.010536s:
0.010556s: qemu:feature-detect mean:0.291239s 0.1ms (12.8%)
0.301795s:
0.303575s: qemu mean:1.971126s 7.6ms (86.7%) qemu:overhead mean:0.162931s
1.6ms (7.2%)
0.466506s:
0.466506s: bios:overhead mean:1.104824s 4.9ms (48.6%) sgabios mean:0.268174s
1.0ms (11.8%)
0.734680s:
0.734680s: seabios mean:0.836650s 3.8ms (36.8%)
1.571330s:
1.571330s: kernel mean:0.703371s 1.1ms (30.9%) kernel:overhead
mean:0.323505s 0.7ms (14.2%)
1.894835s:
1.894835s: supermin:mini-initrd mean:0.057420s 2.0ms (2.5%)
1.897110s: supermin: internal insmod crc32-pclmul.ko mean:0.001343s 0.0ms
(0.1%)
1.898454s:
1.898454s: supermin: internal insmod crc32c-intel.ko mean:0.000001s 0.0ms
(0.0%)
1.898454s:
1.898454s: supermin: internal insmod crct10dif-pclmul.ko mean:0.001101s
0.0ms (0.0%)
1.899556s:
1.899556s: supermin: internal insmod crc32.ko mean:0.001125s 0.0ms (0.0%)
1.900680s:
1.900680s: supermin: internal insmod virtio.ko mean:0.001739s 0.0ms (0.1%)
1.902419s:
1.902419s: supermin: internal insmod virtio_ring.ko mean:0.000001s 0.0ms
(0.0%)
1.902420s:
1.902420s: supermin: internal insmod virtio_blk.ko mean:0.001116s 0.0ms
(0.0%)
1.903536s:
1.903536s: supermin: internal insmod virtio-rng.ko mean:0.001113s 0.0ms
(0.0%)
1.904648s:
1.904648s: supermin: internal insmod virtio_console.ko mean:0.002032s 0.0ms
(0.1%)
1.906680s:
1.906680s: supermin: internal insmod virtio_net.ko mean:0.001258s 0.0ms
(0.1%)
1.907938s:
1.907938s: supermin: internal insmod virtio_scsi.ko mean:0.000562s 0.6ms
(0.0%)
1.908501s:
1.908501s: supermin: internal insmod virtio_balloon.ko mean:0.000549s 0.5ms
(0.0%)
1.909050s:
1.909050s: supermin: internal insmod virtio_input.ko mean:0.001092s 0.0ms
(0.0%)
1.910142s:
1.910142s: supermin: internal insmod virtio_mmio.ko mean:0.001089s 0.0ms
(0.0%)
1.911230s:
1.911230s: supermin: internal insmod virtio_pci.ko mean:0.032539s 1.9ms
(1.4%)
1.943769s:
1.943769s: supermin: internal insmod crc-ccitt.ko mean:0.001408s 0.3ms
(0.1%)
1.945177s:
1.945177s: supermin: internal insmod crc-itu-t.ko mean:0.000554s 0.6ms
(0.0%)
1.945731s:
1.945731s: supermin: internal insmod crc8.ko mean:0.001646s 0.1ms (0.1%)
1.947377s:
1.947377s: supermin: internal insmod libcrc32c.ko mean:0.000001s 0.0ms
(0.0%)
1.947378s:
1.952255s:
1.952255s: /init mean:0.293357s 1.6ms (12.9%) bash:overhead mean:0.008478s
0.2ms (0.4%)
1.960733s:
2.245612s:
2.245612s: guestfsd mean:0.018649s 0.2ms (0.8%)
2.256491s: shutdown mean:0.018210s 2.2ms (0.8%)
2.264261s:
2.274701s:
--7ZAtKRhVyVSsbBD2--
Török Edwin
2016-Mar-20 15:28 UTC
Re: [Libguestfs] [PATCH v2 0/7] tests/qemu: Add program for tracing and analyzing boot times.
On 03/20/2016 14:30, Richard W.M. Jones wrote:> v1 was here: > > https://www.redhat.com/archives/libguestfs/2016-March/thread.html#00157Thanks, this is much better than looking at 'ts -i' output. BTW I have use 'git am' to apply them to latest git HEAD and try it. Is this the preferred way, or is there a git branch/repo somewhere that I missed which would already have these applied?> > Not running the 'hwclock' command reduces boot times considerably. > However I'm not sure if it is safe. See the question I posted on > qemu-devel: > > http://thread.gmane.org/gmane.comp.emulators.qemu/402194 > > At the moment, about 50% of the time is consumed by SeaBIOS. Of this, > about ⅓rd is SGABIOS (it contains a useless ¼s sleep waiting for a > keypress ... ffs!)Ah, I didn't have sgabios installed, and it complained it couldn't find an event (qemu:overhead?). Installed it and I got similar results to yours, the largest overhead is BIOS: https://gist.github.com/anonymous/37cfb3d4eb3d3a1c86b2 Thought to try booting a Xen PV domain for comparison, but AFAICT libguestfs doesn't support LIBGUESTFS_BACKEND=libvirt:xen:///>, and the other ⅔rds is something else in SeaBIOS. > Simply removing SGABIOS improves boot times to below 2s, but at a cost > that we cannot see any messages from SeaBIOS so further measurement > and therefore improvement becomes impossible. I'm going to try to fix > SeaBIOS/SGABIOS first. See also: > > http://thread.gmane.org/gmane.comp.emulators.qemu/402196Nice, this would benefit booting regular VMs too, not just libguestfs appliances, right? Best regards, -- Edwin Török | Co-founder and Lead Developer Skylable open-source object storage: reliable, fast, secure http://www.skylable.com
Richard W.M. Jones
2016-Mar-20 16:05 UTC
Re: [Libguestfs] [PATCH v2 0/7] tests/qemu: Add program for tracing and analyzing boot times.
On Sun, Mar 20, 2016 at 05:28:05PM +0200, Török Edwin wrote:> On 03/20/2016 14:30, Richard W.M. Jones wrote: > > v1 was here: > > > > https://www.redhat.com/archives/libguestfs/2016-March/thread.html#00157 > > Thanks, this is much better than looking at 'ts -i' output. > > BTW I have use 'git am' to apply them to latest git HEAD and try it. > Is this the preferred way, or is there a git branch/repo somewhere that I missed which would already have these applied?I've just pushed what I'm working on to my fork of the repo (https://github.com/rwmjones/libguestfs/commits/master).> Ah, I didn't have sgabios installed, and it complained it couldn't > find an event (qemu:overhead?).Right - it's very sensitive to the exact debug output.> Installed it and I got similar results to yours, the largest > overhead is BIOS: > https://gist.github.com/anonymous/37cfb3d4eb3d3a1c86b2Your qemu overhead is lower. That could be because of: https://bugzilla.redhat.com/show_bug.cgi?id=1319483 Interestingly your total time is at least double mine. Either your hardware is slower or there's something else going on.> Thought to try booting a Xen PV domain for comparison, but AFAICT > libguestfs doesn't support LIBGUESTFS_BACKEND=libvirt:xen:///No, this isn't really going to work. It's a bunch of work to support completely different hypervisors like Xen, even with libvirt helping.> >, and the other ⅔rds is something else in SeaBIOS. > > Simply removing SGABIOS improves boot times to below 2s, but at a cost > > that we cannot see any messages from SeaBIOS so further measurement > > and therefore improvement becomes impossible. I'm going to try to fix > > SeaBIOS/SGABIOS first. See also: > > > > http://thread.gmane.org/gmane.comp.emulators.qemu/402196SGABIOS turns out to be caused by something different from what I thought. See my attempt (not yet working) to fix this: https://github.com/rwmjones/libguestfs/commit/8ffab2d708e9480741b373c0702d12ed86dd572a I haven't looked at SeaBIOS yet. That's the biggest issue.> Nice, this would benefit booting regular VMs too, not just > libguestfs appliances, right?Yes, this work benefits everyone. Rich. -- Richard Jones, Virtualization Group, Red Hat http://people.redhat.com/~rjones Read my programming and virtualization blog: http://rwmj.wordpress.com libguestfs lets you edit virtual machines. Supports shell scripting, bindings from many languages. http://libguestfs.org
Kashyap Chamarthy
2016-Mar-21 13:14 UTC
Re: [Libguestfs] [PATCH v2 0/7] tests/qemu: Add program for tracing and analyzing boot times.
I gave this series a spin, along a custom QEMU, and `supermin` from Git,
for my `libguestfs-test-tool` itself fails with:
"Could not open option rom 'linuxboot_dma.bin': No such file or
directory"
How I went about:
(1) Build QEMU with
https://lists.gnu.org/archive/html/qemu-devel/2016-01/msg05891.html
-- Add optionrom compatible with fw_cfg DMA version
Build QEMU with the above patch:
$ w3m https://patchwork.ozlabs.org/patch/575578/mbox \
> add-optionrom-compatible-with-fw_cfg-DMA-version.patch
$ git am -3 \
~/add-optionrom-compatible-with-fw_cfg-DMA-version.patch
# sudo dnf builddep qemu -y
$ ~/src/qemu/configure --target-list=x86_64-softmmu
$ make -j4
(2) Build 'supermin' from Git
(3) Build 'libguestfs' from Rich's fork
https://github.com/rwmjones/libguestfs/commits/master/
Configure libguestfs (from Rich's fork) with `supermin` built from
Git in step (2):
$ SUPERMIN=~/src/supermin/src/supermin ./configure
$ ./bootstrap && ./autogen.sh && make
Compile libguestfs:
$ ./autogen.sh
$ make -j22
(4) Use the QEMU built in step (1), build and run the 'boot-analysis'
program from libguestfs test suite:
$ export
LIBGUESTFS_HV=$HOME/build/qemu-build/x86_64-softmmu/qemu-system-x86_64
$ make -C tests/qemu boot-analysis
$ ./run tests/qemu/boot-analysis -v
One and a half minute passes, nothing is printed on the screen. . .
Okay, let's try 'libguestfs-test-tool' (untruncated output
attached), it
fails with:
-------------------------------------
[...]
Could not open option rom 'linuxboot_dma.bin': No such file or directory
\x1b[1;256r\x1b[256;256H\x1b[6n
Google, Inc.
Serial Graphics Adapter 11/03/11
SGABIOS $Id$ (pbonzini@yakj.usersys.redhat.com) Thu Nov 3 13:33:51 UTC 2011
Term: 80x24
4 0
\x1b[2J
SeaBIOS (version rel-1.9.1-0-gb3ef39f-prebuilt.qemu-project.org)
Booting from Hard Disk...
Boot failed: not a bootable disk
-------------------------------------
Rich: What am I missing here?
--
/kashyap
Richard W.M. Jones
2016-Mar-21 13:16 UTC
Re: [Libguestfs] [PATCH v2 0/7] tests/qemu: Add program for tracing and analyzing boot times.
On Mon, Mar 21, 2016 at 02:14:19PM +0100, Kashyap Chamarthy wrote:> I gave this series a spin, along a custom QEMU, and `supermin` from Git, > for my `libguestfs-test-tool` itself fails with: > > "Could not open option rom 'linuxboot_dma.bin': No such file or > directory"The qemu build is broken in some way. To fix it you have to do: cp pc-bios/optionrom/linuxboot_dma.bin pc-bios/optionrom/ 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
Pino Toscano
2016-Mar-22 14:51 UTC
Re: [Libguestfs] [PATCH v2 1/7] appliance: Print location of udevd.
On Sunday 20 March 2016 12:30:58 Richard W.M. Jones wrote:> This is useful for debugging (but we can't print it unconditionally > since we cannot run grep etc yet). It also allows us to identify > when udevd is invoked so we can time it for boot analysis. > ---I just sent a patch to make use of bash functionalities for string matching in /proc/cmdline. This way, the verbosity level could be checked earlier than this point (earlier than what patch #3 in this series does), and used here. -- Pino Toscano
Pino Toscano
2016-Mar-22 14:55 UTC
Re: [Libguestfs] [PATCH v2 5/7] launch: direct: Remove dead code promising we were going to use virtio-console.
On Sunday 20 March 2016 12:31:02 Richard W.M. Jones wrote:> We're never going to use virtio-console since, although it is faster, > it's not available during early boot, and that is more important for > debugging. > --- > src/launch-direct.c | 10 ---------- > 1 file changed, 10 deletions(-) > > diff --git a/src/launch-direct.c b/src/launch-direct.c > index a81d4b3..f1fe92b 100644 > --- a/src/launch-direct.c > +++ b/src/launch-direct.c > @@ -574,19 +574,9 @@ launch_direct (guestfs_h *g, void *datav, const char *arg) > ADD_CMDLINE ("-device"); > ADD_CMDLINE (VIRTIO_SERIAL); > > -#if 0 > - /* Use virtio-console (a variant form of virtio-serial) for the > - * guest's serial console. > - */ > - ADD_CMDLINE ("-chardev"); > - ADD_CMDLINE ("stdio,id=console"); > - ADD_CMDLINE ("-device"); > - ADD_CMDLINE ("virtconsole,chardev=console,name=org.libguestfs.console.0"); > -#else > /* When the above works ... until then: */This line ^ should be removed too, as it does not make much sense without the comments removed by this patch. With this fix, LGTM. Thanks, -- Pino Toscano
Reasonably Related Threads
- Re: [PATCH v2 1/7] appliance: Print location of udevd.
- [PATCH] appliance: run systemd-tmpfiles also for /var/run
- [PATCH 5/5] appliance: run systemd-tmpfiles also for /run
- [PATCH 4/4] appliance: run systemd-tmpfiles also for /run
- [PATCH] appliance: use bash features for string matching in files