Since commit bb5d30ab2af5720775c63179afdec3ad9efd510d, we don't require any external programs like grep to parse the command line. We only use bash intrinsics. Therefore we can do it early (but after /proc is mounted). This allows verbose mode to enable set -x early on, so we can trace most things that the init script does. --- appliance/init | 39 +++++++++++++++++++++------------------ 1 file changed, 21 insertions(+), 18 deletions(-) diff --git a/appliance/init b/appliance/init index 04afbd6..c4cf964 100755 --- a/appliance/init +++ b/appliance/init @@ -33,9 +33,29 @@ done mkdir -p /sysroot +# Mount /proc. if [ ! -d /proc ]; then rm -f /proc; fi mkdir -p /proc mount -t proc /proc /proc + +# Parse the kernel command line early (must be after /proc is mounted). +cmdline=$(</proc/cmdline) + +if [[ $cmdline == *guestfs_verbose=1* ]]; then + guestfs_verbose=1 + set -x +fi +if [[ $cmdline == *guestfs_network=1* ]]; then + guestfs_network=1 +fi +if [[ $cmdline == *guestfs_rescue=1* ]]; then + guestfs_rescue=1 +fi +if [[ $cmdline == *guestfs_noreboot=1* ]]; then + guestfs_noreboot=1 +fi + +# Mount the other special filesystems. if [ ! -d /sys ]; then rm -f /sys; fi mkdir -p /sys mount -t sysfs /sys /sys @@ -75,8 +95,6 @@ $UDEVD --daemon #--debug udevadm trigger udevadm settle --timeout=600 -cmdline=$(</proc/cmdline) - if [[ $cmdline == *selinux=1* ]]; then mount -t selinuxfs none /sys/fs/selinux fi @@ -92,22 +110,6 @@ shopt -u nullglob # Update the system clock. hwclock -u -s -# Parse the kernel command line. -if [[ $cmdline == *guestfs_verbose=1* ]]; then - guestfs_verbose=1 - set -x -fi -if [[ $cmdline == *guestfs_network=1* ]]; then - guestfs_network=1 -fi -if [[ $cmdline == *guestfs_rescue=1* ]]; then - guestfs_rescue=1 -fi -if [[ $cmdline == *guestfs_noreboot=1* ]]; then - guestfs_noreboot=1 -fi -eval `grep -Eo 'guestfs_channel=[^[:space:]]+' /proc/cmdline` - # Set up the network. ip addr add 127.0.0.1/8 brd + dev lo scope host ip link set dev lo up @@ -156,6 +158,7 @@ fi if ! test "$guestfs_rescue" = 1; then # Run the daemon. cmd="guestfsd" + eval `grep -Eo 'guestfs_channel=[^[:space:]]+' /proc/cmdline` if test "x$guestfs_channel" != "x"; then cmd="$cmd --channel $guestfs_channel" fi -- 2.7.4

This command alone took 0.3 seconds which is about 10% of the current launch time. It appears to be unnecessary. This reverts commit 508f1ee87e816bf6b6fc8e629ccbb2d61a971169. --- appliance/init | 3 --- 1 file changed, 3 deletions(-) diff --git a/appliance/init b/appliance/init index d5f7404..7a28780 100755 --- a/appliance/init +++ b/appliance/init @@ -107,9 +107,6 @@ for f in /sys/block/sd*/device/timeout; do echo 300 > $f; done for f in /sys/block/{h,s,ub,v}d*/queue/scheduler; do echo noop > $f; done shopt -u nullglob -# Update the system clock. -hwclock -u -s - # Set up the network. ip addr add 127.0.0.1/8 brd + dev lo scope host ip link set dev lo up -- 2.7.4

--- .gitignore | 1 + appliance/init | 5 +- tests/qemu/Makefile.am | 26 +- tests/qemu/boot-analysis-timeline.c | 468 ++++++++++++++++ tests/qemu/boot-analysis.c | 1030 +++++++++++++++++++++++++++++++++++ tests/qemu/boot-analysis.h | 94 ++++ 6 files changed, 1620 insertions(+), 4 deletions(-) create mode 100644 tests/qemu/boot-analysis-timeline.c create mode 100644 tests/qemu/boot-analysis.c create mode 100644 tests/qemu/boot-analysis.h diff --git a/.gitignore b/.gitignore index 1493011..9306a19 100644 --- a/.gitignore +++ b/.gitignore @@ -510,6 +510,7 @@ Makefile.in /tests/mountable/test-internal-parse-mountable /tests/parallel/test-parallel /tests/protocol/test-error-messages +/tests/qemu/boot-analysis /tests/qemu/qemu-boot /tests/qemu/qemu-speed-test /tests/regressions/rhbz501893 diff --git a/appliance/init b/appliance/init index 7a28780..28054ab 100755 --- a/appliance/init +++ b/appliance/init @@ -54,6 +54,9 @@ fi if [[ $cmdline == *guestfs_noreboot=1* ]]; then guestfs_noreboot=1 fi +if [[ $cmdline == *guestfs_boot_analysis=1* ]]; then + guestfs_boot_analysis=1 +fi # Mount the other special filesystems. if [ ! -d /sys ]; then rm -f /sys; fi @@ -133,7 +136,7 @@ lvm vgchange -aay --sysinit ldmtool create all # These are useful when debugging. -if test "$guestfs_verbose" = 1; then +if test "$guestfs_verbose" = 1 && test "$guestfs_boot_analysis" != 1; then uname -a ls -lR /dev cat /proc/mounts diff --git a/tests/qemu/Makefile.am b/tests/qemu/Makefile.am index fe45d88..bea1c85 100644 --- a/tests/qemu/Makefile.am +++ b/tests/qemu/Makefile.am @@ -33,10 +33,10 @@ EXTRA_DIST = \ qemu-boot.c \ qemu-speed-test.c -# qemu-boot & qemu-speed-test are built but not run by default as they -# are mainly qemu & kernel diagnostic tools. +# qemu-boot, qemu-speed-test and boot-analysis are built but not run +# by default as they are mainly qemu & kernel diagnostic tools. -check_PROGRAMS = qemu-boot qemu-speed-test +check_PROGRAMS = qemu-boot qemu-speed-test boot-analysis qemu_boot_SOURCES = \ ../../df/estimate-max-threads.c \ @@ -73,6 +73,26 @@ qemu_speed_test_LDADD = \ $(LTLIBINTL) \ $(top_builddir)/gnulib/lib/libgnu.la +boot_analysis_SOURCES = \ + boot-analysis.c \ + boot-analysis.h \ + boot-analysis-timeline.c +boot_analysis_CPPFLAGS = \ + -I$(top_srcdir)/gnulib/lib -I$(top_builddir)/gnulib/lib \ + -I$(top_srcdir)/src -I$(top_builddir)/src +boot_analysis_CFLAGS = \ + $(WARN_CFLAGS) $(WERROR_CFLAGS) \ + $(PCRE_CFLAGS) +boot_analysis_LDADD = \ + $(top_builddir)/src/libutils.la \ + $(top_builddir)/src/libguestfs.la \ + $(PCRE_LIBS) \ + $(LIBXML2_LIBS) \ + $(LIBVIRT_LIBS) \ + $(LTLIBINTL) \ + $(top_builddir)/gnulib/lib/libgnu.la \ + -lm + # Don't run these tests in parallel, since they are designed to check # the integrity of qemu. .NOTPARALLEL: diff --git a/tests/qemu/boot-analysis-timeline.c b/tests/qemu/boot-analysis-timeline.c new file mode 100644 index 0000000..8753805 --- /dev/null +++ b/tests/qemu/boot-analysis-timeline.c @@ -0,0 +1,468 @@ +/* libguestfs + * Copyright (C) 2016 Red Hat Inc. + * + * This program is free software; you can redistribute it and/or modify + * it under the terms of the GNU General Public License as published by + * the Free Software Foundation; either version 2 of the License, or + * (at your option) any later version. + * + * This program is distributed in the hope that it will be useful, + * but WITHOUT ANY WARRANTY; without even the implied warranty of + * MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the + * GNU General Public License for more details. + * + * You should have received a copy of the GNU General Public License along + * with this program; if not, write to the Free Software Foundation, Inc., + * 51 Franklin Street, Fifth Floor, Boston, MA 02110-1301 USA. + */ + +#include <config.h> + +#include <stdio.h> +#include <stdlib.h> +#include <stdint.h> +#include <inttypes.h> +#include <string.h> +#include <unistd.h> +#include <error.h> +#include <errno.h> +#include <assert.h> + +#include <pcre.h> + +#include "ignore-value.h" + +#include "guestfs.h" +#include "guestfs-internal-frontend.h" + +#include "boot-analysis.h" + +COMPILE_REGEXP(re_initcall_calling_module, + "calling ([_A-Za-z0-9]+)\\+.*\\[([_A-Za-z0-9]+)]", 0) +COMPILE_REGEXP(re_initcall_calling, + "calling ([_A-Za-z0-9]+)\\+", 0) + +static void construct_initcall_timeline (void); + +/* "supermin: internal insmod xx.ko" -> "insmod xx.ko" */ +static char * +translate_supermin_insmod_message (const char *message) +{ + char *ret; + + assert (STRPREFIX (message, "supermin: internal ")); + + ret = strdup (message + strlen ("supermin: internal ")); + if (ret == NULL) + error (EXIT_FAILURE, errno, "strdup"); + return ret; +} + +/* Analyze significant events from the events array, to form a + * timeline of activities. + */ +void +construct_timeline (void) +{ + size_t i, j, k; + struct pass_data *data; + struct activity *activity; + + for (i = 0; i < NR_TEST_PASSES; ++i) { + data = &pass_data[i]; + + /* Find an activity, by matching an event with the condition + * `begin_cond' through to the second event `end_cond'. Create an + * activity object in the timeline from the result. + */ +#define FIND(name, flags, begin_cond, end_cond) \ + do { \ + activity = NULL; \ + for (j = 0; j < data->nr_events; ++j) { \ + if (begin_cond) { \ + for (k = j+1; k < data->nr_events; ++k) { \ + if (end_cond) { \ + if (i == 0) \ + activity = add_activity (name, flags); \ + else \ + activity = find_activity (name); \ + break; \ + } \ + } \ + break; \ + } \ + } \ + if (activity) { \ + activity->start_event[i] = j; \ + activity->end_event[i] = k; \ + } \ + else \ + error (EXIT_FAILURE, 0, "could not find activity '%s' in pass '%zu'", \ + name, i); \ + } while (0) + + /* Same as FIND() macro, but if no matching events are found, + * ignore it. + */ +#define FIND_OPTIONAL(name, flags, begin_cond, end_cond) \ + do { \ + activity = NULL; \ + for (j = 0; j < data->nr_events; ++j) { \ + if (begin_cond) { \ + for (k = j+1; k < data->nr_events; ++k) { \ + if (end_cond) { \ + if (i == 0) \ + activity = add_activity (name, flags); \ + else \ + activity = find_activity (name); \ + break; \ + } \ + } \ + break; \ + } \ + } \ + if (activity) { \ + activity->start_event[i] = j; \ + activity->end_event[i] = k; \ + } \ + } while (0) + + /* Find multiple entries, where we check for: + * next_cond + * next_cond + * next_cond + * end_cond + */ +#define FIND_MULTIPLE(debug_name, flags, next_cond, end_cond, translate_message) \ + do { \ + activity = NULL; \ + for (j = 0; j < data->nr_events; ++j) { \ + if (next_cond) { \ + CLEANUP_FREE char *message = translate_message (data->events[j].message); \ + if (activity) \ + activity->end_event[i] = j; \ + if (i == 0) \ + activity = add_activity (message, flags); \ + else \ + activity = find_activity (message); \ + activity->start_event[i] = j; \ + } \ + else if (end_cond) \ + break; \ + } \ + if (j < data->nr_events && activity) \ + activity->end_event[i] = j; \ + else \ + error (EXIT_FAILURE, 0, "could not find activity '%s' in pass '%zu'", \ + debug_name, i); \ + } while (0) + + /* Add one activity which is going to cover the whole process + * from launch to close. The launch event is always event 0. + * NB: This activity must be called "run" (see below). + */ + FIND ("run", LONG_ACTIVITY, + j == 0, data->events[k].source == GUESTFS_EVENT_CLOSE); + + /* Find where we invoke supermin --build. This should be a null + * operation, but it still takes time to run the external command. + */ + FIND ("supermin:build", 0, + data->events[j].source == GUESTFS_EVENT_LIBRARY && + strstr (data->events[j].message, + "begin building supermin appliance"), + data->events[k].source == GUESTFS_EVENT_LIBRARY && + strstr (data->events[k].message, + "finished building supermin appliance")); + + /* Find where we invoke qemu to test features. */ + FIND ("qemu:feature-detect", 0, + data->events[j].source == GUESTFS_EVENT_LIBRARY && + strstr (data->events[j].message, + "begin testing qemu features"), + data->events[k].source == GUESTFS_EVENT_LIBRARY && + strstr (data->events[k].message, + "finished testing qemu features")); + + /* Find where we run qemu. */ + FIND ("qemu", LONG_ACTIVITY, + data->events[j].source == GUESTFS_EVENT_APPLIANCE && + strstr (data->events[j].message, "-nodefconfig"), + data->events[k].source == GUESTFS_EVENT_CLOSE); + +#define SGABIOS_STRING "\033[1;256r\033[256;256H\033[6n" + + /* From starting qemu up to entering the BIOS is the qemu overhead. */ + FIND ("qemu:overhead", 0, + data->events[j].source == GUESTFS_EVENT_APPLIANCE && + strstr (data->events[j].message, "-nodefconfig"), + data->events[k].source == GUESTFS_EVENT_APPLIANCE && + strstr (data->events[k].message, SGABIOS_STRING)); + + /* From entering the BIOS to starting the kernel is the BIOS overhead. */ + FIND_OPTIONAL ("bios:overhead", 0, + data->events[j].source == GUESTFS_EVENT_APPLIANCE && + strstr (data->events[j].message, SGABIOS_STRING), + data->events[k].source == GUESTFS_EVENT_APPLIANCE && + strstr (data->events[k].message, "Probing EDD")); + + /* SGABIOS (option ROM). */ + FIND_OPTIONAL ("sgabios", 0, + data->events[j].source == GUESTFS_EVENT_APPLIANCE && + strstr (data->events[j].message, SGABIOS_STRING), + data->events[k].source == GUESTFS_EVENT_APPLIANCE && + strstr (data->events[k].message, "SeaBIOS (version")); + + /* SeaBIOS. */ + FIND ("seabios", 0, + data->events[j].source == GUESTFS_EVENT_APPLIANCE && + strstr (data->events[j].message, "SeaBIOS (version"), + data->events[k].source == GUESTFS_EVENT_APPLIANCE && + strstr (data->events[k].message, "Probing EDD")); + + /* SeaBIOS - only available when using debug messages. */ + FIND_OPTIONAL ("seabios:pci-probe", 0, + data->events[j].source == GUESTFS_EVENT_APPLIANCE && + strstr (data->events[j].message, "Searching bootorder for: /pci@"), + data->events[k].source == GUESTFS_EVENT_APPLIANCE && + strstr (data->events[k].message, "Scan for option roms")); + + /* Find where we run the guest kernel. */ + FIND ("kernel", LONG_ACTIVITY, + data->events[j].source == GUESTFS_EVENT_APPLIANCE && + strstr (data->events[j].message, "Probing EDD"), + data->events[k].source == GUESTFS_EVENT_CLOSE); + + /* Kernel startup to userspace. */ + FIND ("kernel:overhead", 0, + data->events[j].source == GUESTFS_EVENT_APPLIANCE && + strstr (data->events[j].message, "Probing EDD"), + data->events[k].source == GUESTFS_EVENT_APPLIANCE && + strstr (data->events[k].message, "supermin:") && + strstr (data->events[k].message, "starting up")); + + /* The time taken to get into start_kernel function. */ + FIND ("kernel:entry", 0, + data->events[j].source == GUESTFS_EVENT_APPLIANCE && + strstr (data->events[j].message, "Probing EDD"), + data->events[k].source == GUESTFS_EVENT_APPLIANCE && + strstr (data->events[k].message, "Linux version")); + + /* Alternatives patching instructions (XXX not very accurate we + * really need some debug messages inserted into the code). + */ + FIND ("kernel:alternatives", 0, + data->events[j].source == GUESTFS_EVENT_APPLIANCE && + strstr (data->events[j].message, "Last level dTLB entries"), + data->events[k].source == GUESTFS_EVENT_APPLIANCE && + strstr (data->events[k].message, "Freeing SMP alternatives")); + + /* ftrace patching instructions. */ + FIND ("kernel:ftrace", 0, + data->events[j].source == GUESTFS_EVENT_APPLIANCE && + strstr (data->events[j].message, "ftrace: allocating"), + 1); + + /* Find where we run supermin mini-initrd. */ + FIND ("supermin:mini-initrd", 0, + data->events[j].source == GUESTFS_EVENT_APPLIANCE && + strstr (data->events[j].message, "supermin:") && + strstr (data->events[j].message, "starting up"), + data->events[k].source == GUESTFS_EVENT_APPLIANCE && + strstr (data->events[k].message, "supermin: chroot")); + + /* Loading kernel modules from supermin initrd. */ + FIND_MULTIPLE + ("supermin insmod", 0, + data->events[j].source == GUESTFS_EVENT_APPLIANCE && + strstr (data->events[j].message, "supermin: internal insmod"), + data->events[j].source == GUESTFS_EVENT_APPLIANCE && + strstr (data->events[j].message, "supermin: picked"), + translate_supermin_insmod_message); + + /* Find where we run the /init script. */ + FIND ("/init", 0, + data->events[j].source == GUESTFS_EVENT_APPLIANCE && + strstr (data->events[j].message, "supermin: chroot"), + data->events[k].source == GUESTFS_EVENT_APPLIANCE && + strstr (data->events[k].message, "guestfsd --verbose")); + + /* Everything from the chroot to the first echo in the /init + * script counts as bash overhead. + */ + FIND ("bash:overhead", 0, + data->events[j].source == GUESTFS_EVENT_APPLIANCE && + strstr (data->events[j].message, "supermin: chroot"), + data->events[k].source == GUESTFS_EVENT_APPLIANCE && + strstr (data->events[k].message, "Starting /init script")); + + /* /init: Mount special filesystems. */ + FIND ("/init:mount-special", 0, + data->events[j].source == GUESTFS_EVENT_APPLIANCE && + strstr (data->events[j].message, "*guestfs_boot_analysis=1*"), + data->events[k].source == GUESTFS_EVENT_APPLIANCE && + strstr (data->events[k].message, "kmod static-nodes")); + + /* /init: Run kmod static-nodes */ + FIND ("/init:kmod-static-nodes", 0, + data->events[j].source == GUESTFS_EVENT_APPLIANCE && + strstr (data->events[j].message, "kmod static-nodes"), + data->events[k].source == GUESTFS_EVENT_APPLIANCE && + strstr (data->events[k].message, "systemd-tmpfiles")); + + /* /init: systemd-tmpfiles. */ + FIND ("/init:systemd-tmpfiles", 0, + data->events[j].source == GUESTFS_EVENT_APPLIANCE && + strstr (data->events[j].message, "systemd-tmpfiles"), + data->events[k].source == GUESTFS_EVENT_APPLIANCE && + strstr (data->events[k].message, "udev")); + + /* /init: start udevd. */ + FIND ("/init:udev-overhead", 0, + data->events[j].source == GUESTFS_EVENT_APPLIANCE && + strstr (data->events[j].message, "udevd --daemon"), + data->events[k].source == GUESTFS_EVENT_APPLIANCE && + strstr (data->events[k].message, "nullglob")); + + /* /init: set up network. */ + FIND ("/init:network-overhead", 0, + data->events[j].source == GUESTFS_EVENT_APPLIANCE && + strstr (data->events[j].message, "+ ip addr"), + data->events[k].source == GUESTFS_EVENT_APPLIANCE && + strstr (data->events[k].message, "+ test")); + + /* /init: probe MD arrays. */ + FIND ("/init:md-probe", 0, + data->events[j].source == GUESTFS_EVENT_APPLIANCE && + strstr (data->events[j].message, "+ mdadm"), + data->events[k].source == GUESTFS_EVENT_APPLIANCE && + strstr (data->events[k].message, "+ modprobe dm_mod")); + + /* /init: probe DM/LVM. */ + FIND ("/init:lvm-probe", 0, + data->events[j].source == GUESTFS_EVENT_APPLIANCE && + strstr (data->events[j].message, "+ modprobe dm_mod"), + data->events[k].source == GUESTFS_EVENT_APPLIANCE && + strstr (data->events[k].message, "+ ldmtool")); + + /* /init: probe Windows dynamic disks. */ + FIND ("/init:windows-dynamic-disks-probe", 0, + data->events[j].source == GUESTFS_EVENT_APPLIANCE && + strstr (data->events[j].message, "+ ldmtool"), + data->events[k].source == GUESTFS_EVENT_APPLIANCE && + strstr (data->events[k].message, "+ test")); + + /* Find where we run guestfsd. */ + FIND ("guestfsd", 0, + data->events[j].source == GUESTFS_EVENT_APPLIANCE && + strstr (data->events[j].message, "guestfsd --verbose"), + data->events[k].source == GUESTFS_EVENT_APPLIANCE && + strstr (data->events[k].message, "fsync /dev/sda")); + + /* Shutdown process. */ + FIND ("shutdown", 0, + data->events[j].source == GUESTFS_EVENT_TRACE && + STREQ (data->events[j].message, "close"), + data->events[k].source == GUESTFS_EVENT_CLOSE); + } + + construct_initcall_timeline (); +} + +/* Handling of initcall is so peculiar that we hide it in a separate + * function from the rest. + */ +static void +construct_initcall_timeline (void) +{ + size_t i, j, k; + struct pass_data *data; + struct activity *activity; + + for (i = 0; i < NR_TEST_PASSES; ++i) { + data = &pass_data[i]; + + /* Each kernel initcall is bracketed by: + * + * calling ehci_hcd_init+0x0/0xc1 @ 1" + * initcall ehci_hcd_init+0x0/0xc1 returned 0 after 420 usecs" + * + * For initcall functions in modules: + * + * calling virtio_mmio_init+0x0/0x1000 [virtio_mmio] @ 1" + * initcall virtio_mmio_init+0x0/0x1000 [virtio_mmio] returned 0 after 14 usecs" + * + * Initcall functions can be nested, and do not have unique names. + */ + for (j = 0; j < data->nr_events; ++j) { + int vec[30], r; + const char *message = data->events[j].message; + + if (data->events[j].source == GUESTFS_EVENT_APPLIANCE && + ((r = pcre_exec (re_initcall_calling_module, NULL, + message, strlen (message), + 0, 0, vec, sizeof vec / sizeof vec[0])) >= 1 || + (r = pcre_exec (re_initcall_calling, NULL, + message, strlen (message), + 0, 0, vec, sizeof vec / sizeof vec[0])) >= 1)) { + + CLEANUP_FREE char *fn_name = NULL, *module_name = NULL; + if (r >= 2) /* because pcre_exec returns 1 + number of captures */ + fn_name = strndup (message + vec[2], vec[3]-vec[2]); + if (r >= 3) + module_name = strndup (message + vec[4], vec[5]-vec[4]); + + CLEANUP_FREE char *fullname; + if (asprintf (&fullname, "%s.%s", + module_name ? module_name : "kernel", fn_name) == -1) + error (EXIT_FAILURE, errno, "asprintf"); + + CLEANUP_FREE char *initcall_match; + if (asprintf (&initcall_match, "initcall %s", fn_name) == -1) + error (EXIT_FAILURE, errno, "asprintf"); + + /* Get a unique name for this activity. Unfortunately + * kernel initcall function names are not unique! + */ + CLEANUP_FREE char *activity_name; + if (asprintf (&activity_name, "initcall %s", fullname) == -1) + error (EXIT_FAILURE, errno, "asprintf"); + + if (i == 0) { + int n = 1; + while (activity_exists (activity_name)) { + free (activity_name); + if (asprintf (&activity_name, "initcall %s:%d", fullname, n) == -1) + error (EXIT_FAILURE, errno, "asprintf"); + n++; + } + } + else { + int n = 1; + while (!activity_exists_with_no_data (activity_name, i)) { + free (activity_name); + if (asprintf (&activity_name, "initcall %s:%d", fullname, n) == -1) + error (EXIT_FAILURE, errno, "asprintf"); + n++; + } + } + + /* Find the matching end event. It might be some time later, + * since it appears initcalls can be nested. + */ + for (k = j+1; k < data->nr_events; ++k) { + if (data->events[k].source == GUESTFS_EVENT_APPLIANCE && + strstr (data->events[k].message, initcall_match)) { + if (i == 0) + activity = add_activity (activity_name, 0); + else + activity = find_activity (activity_name); + activity->start_event[i] = j; + activity->end_event[i] = k; + break; + } + } + } + } + } +} diff --git a/tests/qemu/boot-analysis.c b/tests/qemu/boot-analysis.c new file mode 100644 index 0000000..71b265a --- /dev/null +++ b/tests/qemu/boot-analysis.c @@ -0,0 +1,1030 @@ +/* libguestfs + * Copyright (C) 2016 Red Hat Inc. + * + * This program is free software; you can redistribute it and/or modify + * it under the terms of the GNU General Public License as published by + * the Free Software Foundation; either version 2 of the License, or + * (at your option) any later version. + * + * This program is distributed in the hope that it will be useful, + * but WITHOUT ANY WARRANTY; without even the implied warranty of + * MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the + * GNU General Public License for more details. + * + * You should have received a copy of the GNU General Public License along + * with this program; if not, write to the Free Software Foundation, Inc., + * 51 Franklin Street, Fifth Floor, Boston, MA 02110-1301 USA. + */ + +/* Trace and analyze the appliance boot process to find out which + * steps are taking the most time. It is not part of the standard + * tests. + * + * This needs to be run on a quiet machine, so that other processes + * disturb the timing as little as possible. The program is + * completely safe to run at any time. It doesn't read or write any + * external files, and it doesn't require root. + * + * You can run it from the build directory like this: + * + * make + * make -C tests/qemu boot-analysis + * ./run tests/qemu/boot-analysis + * + * The way it works is roughly like this: + * + * We create a libguestfs handle and register callback handlers so we + * can see appliance messages, trace events and so on. + * + * We then launch the handle and shut it down as quickly as possible. + * + * While the handle is running, events (seen by the callback handlers) + * are written verbatim into an in-memory buffer, with timestamps. + * + * Afterwards we analyze the result using regular expressions to try + * to identify a "timeline" for the handle (eg. at what time did the + * BIOS hand control to the kernel). This analysis is done in + * 'boot-analysis-timeline.c'. + * + * The whole process is repeated across a few runs, and the final + * timeline (including statistical analysis of the variation between + * runs) gets printed. + * + * The program is very sensitive to the specific messages printed by + * BIOS/kernel/supermin/userspace, so it won't work on non-x86, and it + * will require periodic adjustment of the regular expressions in + * order to keep things up to date. + */ + +#include <config.h> + +#include <stdio.h> +#include <stdlib.h> +#include <stdint.h> +#include <inttypes.h> +#include <string.h> +#include <unistd.h> +#include <getopt.h> +#include <limits.h> +#include <time.h> +#include <errno.h> +#include <error.h> +#include <ctype.h> +#include <assert.h> +#include <math.h> + +#include "ignore-value.h" + +#include "guestfs.h" +#include "guestfs-internal-frontend.h" + +#include "boot-analysis.h" + +/* Activities taking longer than this % of the total time, except + * those flagged as LONG_ACTIVITY, are highlighted in red. + */ +#define WARNING_THRESHOLD 1.0 + +struct pass_data pass_data[NR_TEST_PASSES]; +size_t nr_activities; +struct activity *activities; + +static int force_colour = 0; +static int verbose = 0; + +static void run_test (void); +static void get_time (struct timespec *ts); +static int64_t timespec_diff (const struct timespec *x, const struct timespec *y); +static struct event *add_event (struct pass_data *, uint64_t source); +static guestfs_h *create_handle (void); +static void set_up_event_handlers (guestfs_h *g, size_t pass); +static void add_drive (guestfs_h *g); +static void check_pass_data (void); +static void dump_pass_data (void); +static void analyze_timeline (void); +static void dump_timeline (void); +static void print_info (void); +static void print_analysis (void); +static void print_longest_to_shortest (void); +static void free_pass_data (void); +static void free_final_timeline (void); +static void ansi_green (void); +static void ansi_red (void); +static void ansi_blue (void); +static void ansi_magenta (void); +static void ansi_restore (void); + +static void +usage (int exitcode) +{ + fprintf (stderr, + "boot-analysis: Trace and analyze the appliance boot process.\n" + "Usage:\n" + " boot-analysis [--options]\n" + "Options:\n" + " --help Display this usage text and exit.\n" + " --colour Output colours, even if not a terminal.\n" + " -v|--verbose Verbose output, useful for debugging.\n"); + exit (exitcode); +} + +int +main (int argc, char *argv[]) +{ + enum { HELP_OPTION = CHAR_MAX + 1 }; + static const char *options = "v"; + static const struct option long_options[] = { + { "help", 0, 0, HELP_OPTION }, + { "color", 0, 0, 0 }, + { "colour", 0, 0, 0 }, + { "verbose", 0, 0, 'v' }, + { 0, 0, 0, 0 } + }; + int c, option_index; + + for (;;) { + c = getopt_long (argc, argv, options, long_options, &option_index); + if (c == -1) break; + + switch (c) { + case 0: /* Options which are long only. */ + if (STREQ (long_options[option_index].name, "color") || + STREQ (long_options[option_index].name, "colour")) { + force_colour = 1; + break; + } + fprintf (stderr, "%s: unknown long option: %s (%d)\n", + guestfs_int_program_name, long_options[option_index].name, option_index); + exit (EXIT_FAILURE); + + case 'v': + verbose = 1; + break; + + case HELP_OPTION: + usage (EXIT_SUCCESS); + + default: + usage (EXIT_FAILURE); + } + } + + if (STRNEQ (host_cpu, "x86_64")) + fprintf (stderr, "WARNING: host_cpu != x86_64: This program may not work or give bogus results.\n"); + + run_test (); +} + +static void +run_test (void) +{ + guestfs_h *g; + size_t i; + + printf ("Warming up the libguestfs cache ...\n"); + for (i = 0; i < NR_WARMUP_PASSES; ++i) { + g = create_handle (); + add_drive (g); + if (guestfs_launch (g) == -1) + exit (EXIT_FAILURE); + guestfs_close (g); + } + + printf ("Running the tests in %d passes ...\n", NR_TEST_PASSES); + for (i = 0; i < NR_TEST_PASSES; ++i) { + g = create_handle (); + set_up_event_handlers (g, i); + add_drive (g); + if (guestfs_launch (g) == -1) + exit (EXIT_FAILURE); + guestfs_close (g); + + printf (" pass %zu: %zu events collected in %" PRIi64 " ns\n", + i+1, pass_data[i].nr_events, pass_data[i].elapsed_ns); + } + + if (verbose) + dump_pass_data (); + + printf ("Analyzing the results ...\n"); + check_pass_data (); + construct_timeline (); + analyze_timeline (); + + if (verbose) + dump_timeline (); + + printf ("\n"); + print_info (); + printf ("\n"); + print_analysis (); + printf ("\n"); + printf ("Longest activities:\n"); + printf ("\n"); + print_longest_to_shortest (); + + free_pass_data (); + free_final_timeline (); +} + +static void +get_time (struct timespec *ts) +{ + if (clock_gettime (CLOCK_REALTIME, ts) == -1) + error (EXIT_FAILURE, errno, "clock_gettime: CLOCK_REALTIME"); +} + +/* Computes Y - X, returning nanoseconds. */ +static int64_t +timespec_diff (const struct timespec *x, const struct timespec *y) +{ + int64_t nsec; + + nsec = (y->tv_sec - x->tv_sec) * UINT64_C(1000000000); + nsec += y->tv_nsec - x->tv_nsec; + return nsec; +} + +static struct event * +add_event (struct pass_data *data, uint64_t source) +{ + struct event *ret; + + data->nr_events++; + data->events = realloc (data->events, + sizeof (struct event) * data->nr_events); + if (data->events == NULL) + error (EXIT_FAILURE, errno, "realloc"); + ret = &data->events[data->nr_events-1]; + get_time (&ret->t); + ret->source = source; + ret->message = NULL; + return ret; +} + +/* Common function to create the handle and set various defaults. */ +static guestfs_h * +create_handle (void) +{ + guestfs_h *g; + + g = guestfs_create (); + if (!g) error (EXIT_FAILURE, errno, "guestfs_create"); + + /* We always run these tests using LIBGUESTFS_BACKEND=direct. It + * may be in future we need to test libvirt as well, in case + * performance issues are suspected there, but so far libvirt has + * not been a bottleneck. + */ + if (guestfs_set_backend (g, "direct") == -1) + exit (EXIT_FAILURE); + + /* This changes some details in appliance/init and enables a + * detailed trace of calls to initcall functions in the kernel. + */ + if (guestfs_set_append (g, + "guestfs_boot_analysis=1 " + "ignore_loglevel initcall_debug") == -1) + exit (EXIT_FAILURE); + + return g; +} + +/* Common function to add the /dev/null drive. */ +static void +add_drive (guestfs_h *g) +{ + if (guestfs_add_drive_opts (g, "/dev/null", + GUESTFS_ADD_DRIVE_OPTS_FORMAT, "raw", + GUESTFS_ADD_DRIVE_OPTS_READONLY, 1, + -1) == -1) + exit (EXIT_FAILURE); +} + +/* Called when the handle is closed. Perform any cleanups required in + * the pass_data here. + */ +static void +close_callback (guestfs_h *g, void *datavp, uint64_t source, + int eh, int flags, + const char *buf, size_t buf_len, + const uint64_t *array, size_t array_len) +{ + struct pass_data *data = datavp; + struct event *event; + + if (!data->seen_launch) + return; + + event = add_event (data, source); + event->message = strdup ("close callback"); + if (event->message == NULL) + error (EXIT_FAILURE, errno, "strdup"); + + get_time (&data->end_t); + data->elapsed_ns = timespec_diff (&data->start_t, &data->end_t); +} + +/* Called when the qemu subprocess exits. + * XXX This is never called - why? + */ +static void +subprocess_quit_callback (guestfs_h *g, void *datavp, uint64_t source, + int eh, int flags, + const char *buf, size_t buf_len, + const uint64_t *array, size_t array_len) +{ + struct pass_data *data = datavp; + struct event *event; + + if (!data->seen_launch) + return; + + event = add_event (data, source); + event->message = strdup ("subprocess quit callback"); + if (event->message == NULL) + error (EXIT_FAILURE, errno, "strdup"); +} + +/* Called when the launch operation is complete (the library and the + * guestfs daemon and talking to each other). + */ +static void +launch_done_callback (guestfs_h *g, void *datavp, uint64_t source, + int eh, int flags, + const char *buf, size_t buf_len, + const uint64_t *array, size_t array_len) +{ + struct pass_data *data = datavp; + struct event *event; + + if (!data->seen_launch) + return; + + event = add_event (data, source); + event->message = strdup ("launch done callback"); + if (event->message == NULL) + error (EXIT_FAILURE, errno, "strdup"); +} + +/* Trim \r (multiple) from the end of a string. */ +static void +trim_r (char *message) +{ + size_t len = strlen (message); + + while (len > 0 && message[len-1] == '\r') { + message[len-1] = '\0'; + len--; + } +} + +/* Called when we get (possibly part of) a log message (or more than + * one log message) from the appliance (which may include qemu, the + * BIOS, kernel, etc). + */ +static void +appliance_callback (guestfs_h *g, void *datavp, uint64_t source, + int eh, int flags, + const char *buf, size_t buf_len, + const uint64_t *array, size_t array_len) +{ + struct pass_data *data = datavp; + struct event *event; + size_t i, len, slen; + + if (!data->seen_launch) + return; + + /* If the previous log message was incomplete, but time has moved on + * a lot, record a new log message anyway, so it gets a new + * timestamp. + */ + if (data->incomplete_log_message >= 0) { + struct timespec ts; + get_time (&ts); + if (timespec_diff (&data->events[data->incomplete_log_message].t, + &ts) >= 10000000 /* 10ms */) + data->incomplete_log_message = -1; + } + + /* If the previous log message was incomplete then we may need to + * append part of the current log message to a previous one. + */ + if (data->incomplete_log_message >= 0) { + len = buf_len; + for (i = 0; i < buf_len; ++i) { + if (buf[i] == '\n') { + len = i; + break; + } + } + + event = &data->events[data->incomplete_log_message]; + slen = strlen (event->message); + event->message = realloc (event->message, slen + len + 1); + if (event->message == NULL) + error (EXIT_FAILURE, errno, "realloc"); + memcpy (event->message + slen, buf, len); + event->message[slen + len] = '\0'; + trim_r (event->message); + + /* Skip what we just added to the previous incomplete message. */ + buf += len; + buf_len -= len; + + if (buf_len == 0) /* still not complete, more to come! */ + return; + + /* Skip the \n in the buffer. */ + buf++; + buf_len--; + data->incomplete_log_message = -1; + } + + /* Add the event, or perhaps multiple events if the message + * contains \n characters. + */ + while (buf_len > 0) { + len = buf_len; + for (i = 0; i < buf_len; ++i) { + if (buf[i] == '\n') { + len = i; + break; + } + } + + event = add_event (data, source); + event->message = strndup (buf, len); + if (event->message == NULL) + error (EXIT_FAILURE, errno, "strndup"); + trim_r (event->message); + + /* Skip what we just added to the event. */ + buf += len; + buf_len -= len; + + if (buf_len == 0) { + /* Event is incomplete (doesn't end with \n). We'll finish it + * in the next callback. + */ + data->incomplete_log_message = event - data->events; + return; + } + + /* Skip the \n in the buffer. */ + buf++; + buf_len--; + } +} + +/* Called when we get a debug message from the library side. These + * are always delivered as complete messages. + */ +static void +library_callback (guestfs_h *g, void *datavp, uint64_t source, + int eh, int flags, + const char *buf, size_t buf_len, + const uint64_t *array, size_t array_len) +{ + struct pass_data *data = datavp; + struct event *event; + + if (!data->seen_launch) + return; + + event = add_event (data, source); + event->message = strndup (buf, buf_len); + if (event->message == NULL) + error (EXIT_FAILURE, errno, "strndup"); +} + +/* Called when we get a call trace message (a libguestfs API function + * has been called or is returning). These are always delivered as + * complete messages. + */ +static void +trace_callback (guestfs_h *g, void *datavp, uint64_t source, + int eh, int flags, + const char *buf, size_t buf_len, + const uint64_t *array, size_t array_len) +{ + struct pass_data *data = datavp; + struct event *event; + char *message; + + message = strndup (buf, buf_len); + if (message == NULL) + error (EXIT_FAILURE, errno, "strndup"); + + if (STREQ (message, "launch")) + data->seen_launch = 1; + + if (!data->seen_launch) { + free (message); + return; + } + + event = add_event (data, source); + event->message = message; +} + +/* Common function to set up event callbacks and record data in memory + * for a particular pass (0 <= pass < NR_TEST_PASSES). + */ +static void +set_up_event_handlers (guestfs_h *g, size_t pass) +{ + struct pass_data *data; + + assert (/* 0 <= pass && */ pass < NR_TEST_PASSES); + + data = &pass_data[pass]; + data->pass = pass; + data->nr_events = 0; + data->events = NULL; + get_time (&data->start_t); + data->incomplete_log_message = -1; + data->seen_launch = 0; + + guestfs_set_event_callback (g, close_callback, + GUESTFS_EVENT_CLOSE, 0, data); + guestfs_set_event_callback (g, subprocess_quit_callback, + GUESTFS_EVENT_SUBPROCESS_QUIT, 0, data); + guestfs_set_event_callback (g, launch_done_callback, + GUESTFS_EVENT_LAUNCH_DONE, 0, data); + guestfs_set_event_callback (g, appliance_callback, + GUESTFS_EVENT_APPLIANCE, 0, data); + guestfs_set_event_callback (g, library_callback, + GUESTFS_EVENT_LIBRARY, 0, data); + guestfs_set_event_callback (g, trace_callback, + GUESTFS_EVENT_TRACE, 0, data); + + guestfs_set_verbose (g, 1); + guestfs_set_trace (g, 1); +} + +/* Sanity check the collected events. */ +static void +check_pass_data (void) +{ + size_t i, j, len; + int64_t ns; + const char *message; + + for (i = 0; i < NR_TEST_PASSES; ++i) { + assert (pass_data[i].pass == i); + assert (pass_data[i].elapsed_ns > 1000); + assert (pass_data[i].nr_events > 0); + assert (pass_data[i].events != NULL); + + for (j = 0; j < pass_data[i].nr_events; ++j) { + assert (pass_data[i].events[j].t.tv_sec > 0); + if (j > 0) { + ns = timespec_diff (&pass_data[i].events[j-1].t, + &pass_data[i].events[j].t); + assert (ns >= 0); + } + assert (pass_data[i].events[j].source != 0); + message = pass_data[i].events[j].message; + assert (message != NULL); + assert (strchr (message, '\n') == NULL); + len = strlen (message); + assert (len == 0 || message[len-1] != '\r'); + } + } +} + +static void +print_escaped_string (const char *message) +{ + while (*message) { + if (isprint (*message)) + putchar (*message); + else + printf ("\\x%02x", (unsigned int) *message); + message++; + } +} + +/* Dump the events to stdout, if verbose is set. */ +static void +dump_pass_data (void) +{ + size_t i, j; + + for (i = 0; i < NR_TEST_PASSES; ++i) { + printf ("pass %zu\n", pass_data[i].pass); + printf (" number of events collected %zu\n", pass_data[i].nr_events); + printf (" elapsed time %" PRIi64 " ns\n", pass_data[i].elapsed_ns); + for (j = 0; j < pass_data[i].nr_events; ++j) { + int64_t ns; + CLEANUP_FREE char *event_str = NULL; + + ns = timespec_diff (&pass_data[i].start_t, &pass_data[i].events[j].t); + event_str = guestfs_event_to_string (pass_data[i].events[j].source); + printf (" #%zu: +%" PRIi64 " [%s] \"", j, ns, event_str); + print_escaped_string (pass_data[i].events[j].message); + printf ("\"\n"); + } + } +} + +int +activity_exists (const char *name) +{ + size_t i; + + for (i = 0; i < nr_activities; ++i) + if (STREQ (activities[i].name, name)) + return 1; + return 0; +} + +/* Add an activity to the global list. */ +struct activity * +add_activity (const char *name, int flags) +{ + struct activity *ret; + size_t i; + + /* You shouldn't have two activities with the same name. */ + assert (!activity_exists (name)); + + nr_activities++; + activities = realloc (activities, sizeof (struct activity) * nr_activities); + if (activities == NULL) + error (EXIT_FAILURE, errno, "realloc"); + ret = &activities[nr_activities-1]; + ret->name = strdup (name); + if (ret->name == NULL) + error (EXIT_FAILURE, errno, "strdup"); + ret->flags = flags; + + for (i = 0; i < NR_TEST_PASSES; ++i) + ret->start_event[i] = ret->end_event[i] = 0; + + return ret; +} + +struct activity * +find_activity (const char *name) +{ + size_t i; + + for (i = 0; i < nr_activities; ++i) + if (STREQ (activities[i].name, name)) + return &activities[i]; + error (EXIT_FAILURE, 0, + "internal error: could not find activity '%s'", name); + /*NOTREACHED*/ + abort (); +} + +int +activity_exists_with_no_data (const char *name, size_t pass) +{ + size_t i; + + for (i = 0; i < nr_activities; ++i) + if (STREQ (activities[i].name, name) && + activities[i].start_event[pass] == 0 && + activities[i].end_event[pass] == 0) + return 1; + return 0; +} + +static int +compare_activities_by_t (const void *av, const void *bv) +{ + const struct activity *a = av; + const struct activity *b = bv; + + return a->t - b->t; +} + +/* Go through the activities, computing the start and elapsed time. */ +static void +analyze_timeline (void) +{ + struct activity *activity; + size_t i, j; + int64_t delta_ns; + + for (j = 0; j < nr_activities; ++j) { + activity = &activities[j]; + + activity->t = 0; + activity->mean = 0; + for (i = 0; i < NR_TEST_PASSES; ++i) { + delta_ns = + timespec_diff (&pass_data[i].events[0].t, + &pass_data[i].events[activity->start_event[i]].t); + activity->t += delta_ns; + + delta_ns = + timespec_diff (&pass_data[i].events[activity->start_event[i]].t, + &pass_data[i].events[activity->end_event[i]].t); + activity->mean += delta_ns; + } + + /* Divide through to get real start time and mean of each activity. */ + activity->t /= NR_TEST_PASSES; + activity->mean /= NR_TEST_PASSES; + + /* Calculate the end time of this activity. It's convenient when + * drawing the timeline for one activity to finish just before the + * next activity starts, rather than having them end and start at + * the same time, hence ``- 1'' here. + */ + activity->end_t = activity->t + activity->mean - 1; + + /* The above only calculated mean. Now we are able to + * calculate from the mean the variance and the standard + * deviation. + */ + activity->variance = 0; + for (i = 0; i < NR_TEST_PASSES; ++i) { + delta_ns = + timespec_diff (&pass_data[i].events[activity->start_event[i]].t, + &pass_data[i].events[activity->end_event[i]].t); + activity->variance += pow (delta_ns - activity->mean, 2); + } + activity->variance /= NR_TEST_PASSES; + + activity->sd = sqrt (activity->variance); + } + + /* Get the total mean elapsed time from the special "run" activity. */ + activity = find_activity ("run"); + for (j = 0; j < nr_activities; ++j) { + activities[j].percent = 100.0 * activities[j].mean / activity->mean; + + activities[j].warning = + !(activities[j].flags & LONG_ACTIVITY) && + activities[j].percent >= WARNING_THRESHOLD; + } + + /* Sort the activities by start time. */ + qsort (activities, nr_activities, sizeof (struct activity), + compare_activities_by_t); +} + +/* Dump the timeline to stdout, if verbose is set. */ +static void +dump_timeline (void) +{ + size_t i; + + for (i = 0; i < nr_activities; ++i) { + printf ("activity %zu:\n", i); + printf (" name = %s\n", activities[i].name); + printf (" start - end = %.1f - %.1f\n", + activities[i].t, activities[i].end_t); + printf (" mean elapsed = %.1f\n", activities[i].mean); + printf (" variance = %.1f\n", activities[i].variance); + printf (" s.d = %.1f\n", activities[i].sd); + printf (" percent = %.1f\n", activities[i].percent); + } +} + +/* Print some information that will allow us to determine the test + * system when reviewing the results in future. + */ +static void +print_info (void) +{ + size_t i; + + printf ("%s %s\n", PACKAGE_NAME, PACKAGE_VERSION_FULL); + + printf ("Host:\n"); + ignore_value (system ("uname -a")); + ignore_value (system ("grep '^model name' /proc/cpuinfo | head -1")); + + /* We can dig some information about qemu and the appliance out of + * the events. + */ + printf ("Appliance:\n"); + assert (NR_TEST_PASSES > 0); + for (i = 0; i < pass_data[0].nr_events; ++i) { + const char *message = pass_data[0].events[i].message; + if (strstr (message, "qemu version") || + (strstr (message, "SeaBIOS") && strstr (message, "version")) || + strstr (message, "Linux version") || + (strstr (message, "supermin") && strstr (message, "starting up"))) { + print_escaped_string (message); + putchar ('\n'); + } + } +} + +static void +print_activity (struct activity *activity) +{ + if (activity->warning) ansi_red (); else ansi_green (); + print_escaped_string (activity->name); + ansi_restore (); + printf (" %1.6fs ±%.1fms ", + activity->mean / 1000000000, activity->sd / 1000000); + if (activity->warning) ansi_red (); else ansi_green (); + printf ("(%.1f%%) ", activity->percent); + ansi_restore (); +} + +static void +print_analysis (void) +{ + double t = -1; /* Current time. */ + /* Which columns contain activities that we are displaying now? + * -1 == unused column, else index of an activity + */ + CLEANUP_FREE ssize_t *columns = NULL; + const size_t nr_columns = nr_activities; + size_t last_free_column = 0; + + size_t i, j; + double last_t, smallest_next_t; + const double MAX_T = 1e20; + + columns = malloc (nr_columns * sizeof (ssize_t)); + if (columns == NULL) error (EXIT_FAILURE, errno, "malloc"); + for (j = 0; j < nr_columns; ++j) + columns[j] = -1; + + for (;;) { + /* Find the next significant time to display, which is a time when + * some activity started or ended. + */ + smallest_next_t = MAX_T; + for (i = 0; i < nr_activities; ++i) { + if (t < activities[i].t && activities[i].t < smallest_next_t) + smallest_next_t = activities[i].t; + else if (t < activities[i].end_t && activities[i].end_t < smallest_next_t) + smallest_next_t = activities[i].end_t; + } + if (smallest_next_t == MAX_T) + break; /* Finished. */ + + last_t = t; + t = smallest_next_t; + + /* Draw a spacer line, but only if last_t -> t is a large jump. */ + if (t - last_t >= 1000000 /* ns */) { + printf (" "); + ansi_magenta (); + for (j = 0; j < last_free_column; ++j) { + if (columns[j] >= 0 && + activities[columns[j]].end_t != last_t /* !▼ */) + printf ("│ "); + else + printf (" "); + } + ansi_restore (); + printf ("\n"); + } + + /* If there are any activities that ended before this time, drop + * them from the columns list. + */ + for (i = 0; i < nr_activities; ++i) { + if (activities[i].end_t < t) { + for (j = 0; j < nr_columns; ++j) + if (columns[j] == (ssize_t) i) { + columns[j] = -1; + break; + } + } + } + + /* May need to adjust last_free_column after previous operation. */ + while (last_free_column > 0 && columns[last_free_column-1] == -1) + last_free_column--; + + /* If there are any activities starting at this time, add them to + * the right hand end of the columns list. + */ + for (i = 0; i < nr_activities; ++i) { + if (activities[i].t == t) + columns[last_free_column++] = i; + } + + /* Draw the line. */ + ansi_blue (); + printf ("%1.6fs: ", t / 1000000000); + + ansi_magenta (); + for (j = 0; j < last_free_column; ++j) { + if (columns[j] >= 0) { + if (activities[columns[j]].t == t) + printf ("▲ "); + else if (activities[columns[j]].end_t == t) + printf ("▼ "); + else + printf ("│ "); + } + else + printf (" "); + } + ansi_restore (); + + for (j = 0; j < last_free_column; ++j) { + if (columns[j] >= 0 && activities[columns[j]].t == t) /* ▲ */ + print_activity (&activities[columns[j]]); + } + + printf ("\n"); + } +} + +static int +compare_activities_pointers_by_mean (const void *av, const void *bv) +{ + const struct activity * const *a = av; + const struct activity * const *b = bv; + + return (*b)->mean - (*a)->mean; +} + +static void +print_longest_to_shortest (void) +{ + size_t i; + CLEANUP_FREE struct activity **longest; + + /* Sort the activities longest first. In order not to affect the + * global activities array, sort an array of pointers to the + * activities instead. + */ + longest = malloc (sizeof (struct activity *) * nr_activities); + for (i = 0; i < nr_activities; ++i) + longest[i] = &activities[i]; + + qsort (longest, nr_activities, sizeof (struct activity *), + compare_activities_pointers_by_mean); + + /* Display the activities, longest first. */ + for (i = 0; i < nr_activities; ++i) { + print_activity (longest[i]); + printf ("\n"); + } +} + +/* Free the non-static part of the pass_data structures. */ +static void +free_pass_data (void) +{ + size_t i, j; + + for (i = 0; i < NR_TEST_PASSES; ++i) { + for (j = 0; j < pass_data[i].nr_events; ++j) + free (pass_data[i].events[j].message); + free (pass_data[i].events); + } +} + +static void +free_final_timeline (void) +{ + size_t i; + + for (i = 0; i < nr_activities; ++i) + free (activities[i].name); + free (activities); +} + +/* Colours. */ +static void +ansi_green (void) +{ + if (force_colour || isatty (1)) + fputs ("\033[0;32m", stdout); +} + +static void +ansi_red (void) +{ + if (force_colour || isatty (1)) + fputs ("\033[1;31m", stdout); +} + +static void +ansi_blue (void) +{ + if (force_colour || isatty (1)) + fputs ("\033[1;34m", stdout); +} + +static void +ansi_magenta (void) +{ + if (force_colour || isatty (1)) + fputs ("\033[1;35m", stdout); +} + +static void +ansi_restore (void) +{ + if (force_colour || isatty (1)) + fputs ("\033[0m", stdout); +} diff --git a/tests/qemu/boot-analysis.h b/tests/qemu/boot-analysis.h new file mode 100644 index 0000000..86d403e --- /dev/null +++ b/tests/qemu/boot-analysis.h @@ -0,0 +1,94 @@ +/* libguestfs + * Copyright (C) 2016 Red Hat Inc. + * + * This program is free software; you can redistribute it and/or modify + * it under the terms of the GNU General Public License as published by + * the Free Software Foundation; either version 2 of the License, or + * (at your option) any later version. + * + * This program is distributed in the hope that it will be useful, + * but WITHOUT ANY WARRANTY; without even the implied warranty of + * MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the + * GNU General Public License for more details. + * + * You should have received a copy of the GNU General Public License along + * with this program; if not, write to the Free Software Foundation, Inc., + * 51 Franklin Street, Fifth Floor, Boston, MA 02110-1301 USA. + */ + +#ifndef GUESTFS_BOOT_ANALYSIS_H_ +#define GUESTFS_BOOT_ANALYSIS_H_ + +#define NR_WARMUP_PASSES 3 +#define NR_TEST_PASSES 5 + +/* Per-pass data collected. */ +struct pass_data { + size_t pass; + struct timespec start_t; + struct timespec end_t; + int64_t elapsed_ns; + + /* Array of timestamped events. */ + size_t nr_events; + struct event *events; + + /* Was the previous appliance log message incomplete? If so, this + * contains the index of that incomplete message in the events + * array. + */ + ssize_t incomplete_log_message; + + /* Have we seen the launch event yet? We don't record events until + * this one has been received. This makes it easy to base the + * timeline at event 0. + */ + int seen_launch; +}; + +struct event { + struct timespec t; + uint64_t source; + char *message; +}; + +extern struct pass_data pass_data[NR_TEST_PASSES]; + +/* The final timeline consisting of various activities starting and + * ending. We're interested in when the activities start, and how + * long they take (mean, variance, standard deviation of length). + */ +struct activity { + char *name; /* Name of this activity. */ + int flags; +#define LONG_ACTIVITY 1 /* Expected to take a long time. */ + + /* For each pass, record the actual start & end events of this + * activity. + */ + size_t start_event[NR_TEST_PASSES]; + size_t end_event[NR_TEST_PASSES]; + + double t; /* Start (ns offset). */ + double end_t; /* t + mean - 1 */ + + /* Length of this activity. */ + double mean; /* Mean time elapsed (ns). */ + double variance; /* Variance. */ + double sd; /* Standard deviation. */ + double percent; /* Percent of total elapsed time. */ + + int warning; /* Appears in red. */ +}; + +extern size_t nr_activities; +extern struct activity *activities; + +extern int activity_exists (const char *name); +extern struct activity *add_activity (const char *name, int flags); +extern struct activity *find_activity (const char *name); +extern int activity_exists_with_no_data (const char *name, size_t pass); + +extern void construct_timeline (void); + +#endif /* GUESTFS_BOOT_ANALYSIS_H_ */ -- 2.7.4