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

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

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

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