Richard W.M. Jones
2016-Mar-22 19:05 UTC
[Libguestfs] [PATCH v3 0/11] tests/qemu: Add program for tracing and analyzing boot times.
Lots of changes since v2, too much to remember or summarize. Please ignore patch 11/11, it's just for my testing. Rich.
Richard W.M. Jones
2016-Mar-22 19:05 UTC
[Libguestfs] [PATCH v3 01/11] 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 f6fe9b9..f4f6333 100755
--- a/appliance/init
+++ b/appliance/init
@@ -93,6 +93,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.7.4
Richard W.M. Jones
2016-Mar-22 19:05 UTC
[Libguestfs] [PATCH v3 02/11] 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 f4f6333..5d43c71 100755
--- a/appliance/init
+++ b/appliance/init
@@ -75,21 +75,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
@@ -106,6 +91,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.7.4
Richard W.M. Jones
2016-Mar-22 19:05 UTC
[Libguestfs] [PATCH v3 03/11] 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 5d43c71..77ea47e 100755
--- a/appliance/init
+++ b/appliance/init
@@ -103,9 +103,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
Richard W.M. Jones
2016-Mar-22 19:05 UTC
[Libguestfs] [PATCH v3 04/11] 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 | 12 +-----------
1 file changed, 1 insertion(+), 11 deletions(-)
diff --git a/src/launch-direct.c b/src/launch-direct.c
index a81d4b3..e8450e1 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: */
+ /* Create the serial console. */
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.7.4
Richard W.M. Jones
2016-Mar-22 19:05 UTC
[Libguestfs] [PATCH v3 05/11] conn: Pretend to be a serial terminal, so sgabios doesn't hang.
This tedious workaround avoids a 0.26 second pause when using sgabios
(the Serial Graphics Adapter). It's basically a workaround for buggy
code in sgabios, but much easier than fixing the assembler.
---
src/conn-socket.c | 32 +++++++++++++++++++++++++++++++-
1 file changed, 31 insertions(+), 1 deletion(-)
diff --git a/src/conn-socket.c b/src/conn-socket.c
index 5b6b80e..13cb39b 100644
--- a/src/conn-socket.c
+++ b/src/conn-socket.c
@@ -33,6 +33,8 @@
#include <assert.h>
#include <libintl.h>
+#include "ignore-value.h"
+
#include "guestfs.h"
#include "guestfs-internal.h"
@@ -314,6 +316,9 @@ handle_log_message (guestfs_h *g,
{
CLEANUP_FREE char *buf = safe_malloc (g, BUFSIZ);
ssize_t n;
+ const char dsr_request[] = "\033[6n";
+ const char dsr_reply[] = "\033[24;80R";
+ const char dsr_reply_padding[] =
"\b\b\b\b\b\b\b\b\b\b\b\b\b\b\b\b";
/* Carried over from ancient proto.c code. The comment there was:
*
@@ -341,7 +346,32 @@ handle_log_message (guestfs_h *g,
return -1;
}
- /* It's an actual log message, send it upwards. */
+ /* It's an actual log message. */
+
+ /* SGABIOS tries to query the "serial console" for its size using
the
+ * ISO/IEC 6429 Device Status Report (ESC [ 6 n). If it doesn't
+ * read anything back, then it unfortunately hangs for 0.26 seconds.
+ * Therefore we detect this situation and send back a fake console
+ * size.
+ */
+ if (memmem (buf, n, dsr_request, sizeof dsr_request - 1) != NULL) {
+ /* Ignore any error from this write, as it's just an optimization.
+ * We can't even be sure that console_sock is a socket or that
+ * it's writable.
+ */
+ ignore_value (write (conn->console_sock, dsr_reply,
+ sizeof dsr_reply - 1));
+ /* Additionally, because of a bug in sgabios, it will still pause
+ * unless you write at least 14 bytes, so we have to pad the
+ * reply. We can't pad with NULs since sgabios's input routine
+ * ignores these, so we have to use some other safe padding
+ * characters. Backspace seems innocuous.
+ */
+ ignore_value (write (conn->console_sock, dsr_reply_padding,
+ sizeof dsr_reply_padding - 1));
+ }
+
+ /* Send it upwards. */
guestfs_int_log_message_callback (g, buf, n);
return 1;
--
2.7.4
Richard W.M. Jones
2016-Mar-22 19:05 UTC
[Libguestfs] [PATCH v3 06/11] launch: Factor out earlyprintk from the command line.
Just code motion.
In theory we could also add earlyprintk=ttyS0,115200 on x86, but I
cannot get it to work.
---
src/launch.c | 11 +++++++++--
1 file changed, 9 insertions(+), 2 deletions(-)
diff --git a/src/launch.c b/src/launch.c
index 074ac6f..886041a 100644
--- a/src/launch.c
+++ b/src/launch.c
@@ -303,6 +303,12 @@ guestfs_impl_config (guestfs_h *g,
#define SERIAL_CONSOLE "console=ttyS0"
#endif
+#if defined(__aarch64__)
+#define EARLYPRINTK " earlyprintk=pl011,0x9000000"
+#else
+#define EARLYPRINTK ""
+#endif
+
char *
guestfs_int_appliance_command_line (guestfs_h *g, const char *appliance_dev,
int flags)
@@ -331,9 +337,10 @@ guestfs_int_appliance_command_line (guestfs_h *g, const
char *appliance_dev,
#ifdef __i386__
" noapic" /* workaround for RHBZ#857026 */
#endif
- " " SERIAL_CONSOLE /* serial console */
+ " " SERIAL_CONSOLE /* serial console */
+ EARLYPRINTK /* get messages from early boot */
#ifdef __aarch64__
- " earlyprintk=pl011,0x9000000 ignore_loglevel"
+ " ignore_loglevel"
/* This option turns off the EFI RTC device. QEMU VMs don't
* currently provide EFI, and if the device is compiled in it
* will try to call the EFI function GetTime unconditionally
--
2.7.4
Richard W.M. Jones
2016-Mar-22 19:05 UTC
[Libguestfs] [PATCH v3 07/11] launch: direct: Don't run qemu -version.
Dr. David Gilbert pointed out to me that the first line of the
qemu -help output includes the qemu version, so we don't need
to run qemu -version at all.
This saves about 0.04s on the launch time when using the direct
backend.
---
src/launch-direct.c | 54 +++++++++++++++++++----------------------------------
1 file changed, 19 insertions(+), 35 deletions(-)
diff --git a/src/launch-direct.c b/src/launch-direct.c
index e8450e1..25b0349 100644
--- a/src/launch-direct.c
+++ b/src/launch-direct.c
@@ -54,7 +54,6 @@ struct backend_direct_data {
pid_t recoverypid; /* Recovery process PID. */
char *qemu_help; /* Output of qemu -help. */
- char *qemu_version; /* Output of qemu -version. */
char *qemu_devices; /* Output of qemu -device ? */
/* qemu version (0, 0 if unable to parse). */
@@ -931,22 +930,18 @@ print_qemu_command_line (guestfs_h *g, char **argv)
static void parse_qemu_version (guestfs_h *g, struct backend_direct_data
*data);
static void read_all (guestfs_h *g, void *retv, const char *buf, size_t len);
-/* Test qemu binary (or wrapper) runs, and do 'qemu -help' and
- * 'qemu -version' so we know what options this qemu supports and
- * the version.
+/* Test qemu binary (or wrapper) runs, and do 'qemu -help' so we know
+ * the version of qemu what options this qemu supports.
*/
static int
test_qemu (guestfs_h *g, struct backend_direct_data *data)
{
CLEANUP_CMD_CLOSE struct command *cmd1 = guestfs_int_new_command (g);
CLEANUP_CMD_CLOSE struct command *cmd2 = guestfs_int_new_command (g);
- CLEANUP_CMD_CLOSE struct command *cmd3 = guestfs_int_new_command (g);
int r;
free (data->qemu_help);
data->qemu_help = NULL;
- free (data->qemu_version);
- data->qemu_version = NULL;
free (data->qemu_devices);
data->qemu_devices = NULL;
@@ -960,34 +955,24 @@ test_qemu (guestfs_h *g, struct backend_direct_data *data)
if (r == -1 || !WIFEXITED (r) || WEXITSTATUS (r) != 0)
goto error;
+ parse_qemu_version (g, data);
+
guestfs_int_cmd_add_arg (cmd2, g->hv);
guestfs_int_cmd_add_arg (cmd2, "-display");
guestfs_int_cmd_add_arg (cmd2, "none");
- guestfs_int_cmd_add_arg (cmd2, "-version");
- guestfs_int_cmd_set_stdout_callback (cmd2, read_all,
&data->qemu_version,
- CMD_STDOUT_FLAG_WHOLE_BUFFER);
- r = guestfs_int_cmd_run (cmd2);
- if (r == -1 || !WIFEXITED (r) || WEXITSTATUS (r) != 0)
- goto error;
-
- parse_qemu_version (g, data);
-
- guestfs_int_cmd_add_arg (cmd3, g->hv);
- guestfs_int_cmd_add_arg (cmd3, "-display");
- guestfs_int_cmd_add_arg (cmd3, "none");
- guestfs_int_cmd_add_arg (cmd3, "-machine");
- guestfs_int_cmd_add_arg (cmd3,
+ guestfs_int_cmd_add_arg (cmd2, "-machine");
+ guestfs_int_cmd_add_arg (cmd2,
#ifdef MACHINE_TYPE
MACHINE_TYPE ","
#endif
"accel=kvm:tcg");
- guestfs_int_cmd_add_arg (cmd3, "-device");
- guestfs_int_cmd_add_arg (cmd3, "?");
- guestfs_int_cmd_clear_capture_errors (cmd3);
- guestfs_int_cmd_set_stderr_to_stdout (cmd3);
- guestfs_int_cmd_set_stdout_callback (cmd3, read_all,
&data->qemu_devices,
+ guestfs_int_cmd_add_arg (cmd2, "-device");
+ guestfs_int_cmd_add_arg (cmd2, "?");
+ guestfs_int_cmd_clear_capture_errors (cmd2);
+ guestfs_int_cmd_set_stderr_to_stdout (cmd2);
+ guestfs_int_cmd_set_stdout_callback (cmd2, read_all,
&data->qemu_devices,
CMD_STDOUT_FLAG_WHOLE_BUFFER);
- r = guestfs_int_cmd_run (cmd3);
+ r = guestfs_int_cmd_run (cmd2);
if (r == -1 || !WIFEXITED (r) || WEXITSTATUS (r) != 0)
goto error;
@@ -1001,8 +986,9 @@ test_qemu (guestfs_h *g, struct backend_direct_data *data)
return -1;
}
-/* Parse data->qemu_version (if not NULL) into the major and minor
- * version of qemu, but don't fail if parsing is not possible.
+/* Parse the first line of data->qemu_help (if not NULL) into the
+ * major and minor version of qemu, but don't fail if parsing is not
+ * possible.
*/
static void
parse_qemu_version (guestfs_h *g, struct backend_direct_data *data)
@@ -1013,13 +999,13 @@ parse_qemu_version (guestfs_h *g, struct
backend_direct_data *data)
data->qemu_version_major = 0;
data->qemu_version_minor = 0;
- if (!data->qemu_version)
+ if (!data->qemu_help)
return;
- if (!match2 (g, data->qemu_version, re_major_minor, &major_s,
&minor_s)) {
+ if (!match2 (g, data->qemu_help, re_major_minor, &major_s,
&minor_s)) {
parse_failed:
- debug (g, "%s: failed to parse qemu version string '%s'",
- __func__, data->qemu_version);
+ debug (g, "%s: failed to parse qemu version string from the first line
of the output of '%s -help'. When reporting this bug please include the
-help output.",
+ __func__, g->hv);
return;
}
@@ -1508,8 +1494,6 @@ shutdown_direct (guestfs_h *g, void *datav, int
check_for_errors)
free (data->qemu_help);
data->qemu_help = NULL;
- free (data->qemu_version);
- data->qemu_version = NULL;
free (data->qemu_devices);
data->qemu_devices = NULL;
--
2.7.4
Richard W.M. Jones
2016-Mar-22 19:05 UTC
[Libguestfs] [PATCH v3 08/11] tests/qemu: Add program for tracing and analyzing boot times.
---
.gitignore | 1 +
appliance/init | 5 +-
tests/qemu/Makefile.am | 24 +-
tests/qemu/boot-analysis.c | 1380 ++++++++++++++++++++++++++++++++++++++++++++
4 files changed, 1406 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 77ea47e..43de32f 100755
--- a/appliance/init
+++ b/appliance/init
@@ -89,6 +89,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
@@ -129,7 +132,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..55bbea4 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,24 @@ 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) \
+ $(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.c b/tests/qemu/boot-analysis.c
new file mode 100644
index 0000000..41f91bc
--- /dev/null
+++ b/tests/qemu/boot-analysis.c
@@ -0,0 +1,1380 @@
+/* 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 <pcre.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 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 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"
+ " --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 ();
+
+ 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 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");
+ }
+ }
+}
+
+static 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. */
+static 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;
+}
+
+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
+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;
+}
+
+/* "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;
+}
+
+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;
+}
+
+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)
+
+/* 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)
+
+ /* 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);
+
+ /* Each kernel initcall. */
+ 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;
+ }
+ }
+ }
+ }
+
+ /* 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"));
+
+ /* 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 (" %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 (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);
+}
--
2.7.4
Richard W.M. Jones
2016-Mar-22 19:05 UTC
[Libguestfs] [PATCH v3 09/11] 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 25b0349..d0af04d 100644
--- a/src/launch-direct.c
+++ b/src/launch-direct.c
@@ -284,8 +284,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)
@@ -326,8 +325,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
@@ -814,8 +812,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 886041a..5e9e122 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.7.4
Richard W.M. Jones
2016-Mar-22 19:05 UTC
[Libguestfs] [PATCH v3 10/11] launch: Add a virtio-rng device to the guest.
---
src/launch-direct.c | 11 +++++++++++
src/launch-libvirt.c | 14 ++++++++++++++
2 files changed, 25 insertions(+)
diff --git a/src/launch-direct.c b/src/launch-direct.c
index d0af04d..52badc2 100644
--- a/src/launch-direct.c
+++ b/src/launch-direct.c
@@ -451,6 +451,17 @@ launch_direct (guestfs_h *g, void *datav, const char *arg)
ADD_CMDLINE ("-initrd");
ADD_CMDLINE (initrd);
+ /* Add a random number generator (backend for virtio-rng). This
+ * isn't strictly necessary but means we won't need to hang around
+ * when needing entropy.
+ */
+ if (qemu_supports_device (g, data, "virtio-rng-pci")) {
+ ADD_CMDLINE ("-object");
+ ADD_CMDLINE ("rng-random,filename=/dev/urandom,id=rng0");
+ ADD_CMDLINE ("-device");
+ ADD_CMDLINE ("virtio-rng-pci,rng=rng0");
+ }
+
/* Add drives */
virtio_scsi = qemu_supports_virtio_scsi (g, data);
diff --git a/src/launch-libvirt.c b/src/launch-libvirt.c
index 9f2672d..c6cc740 100644
--- a/src/launch-libvirt.c
+++ b/src/launch-libvirt.c
@@ -1251,6 +1251,20 @@ construct_libvirt_xml_devices (guestfs_h *g,
}
#endif
+ /* Add a random number generator (backend for virtio-rng). */
+ start_element ("rng") {
+ attribute ("model", "virtio");
+ start_element ("backend") {
+ attribute ("model", "random");
+ /* It'd be nice to do this, but libvirt says:
+ * file '/dev/urandom' is not a supported random source
+ * Let libvirt pick /dev/random automatically instead.
+ * See also: https://bugzilla.redhat.com/show_bug.cgi?id=1074464
+ */
+ //string ("/dev/urandom");
+ } end_element ();
+ } end_element ();
+
/* virtio-scsi controller. */
start_element ("controller") {
attribute ("type", "scsi");
--
2.7.4
Richard W.M. Jones
2016-Mar-22 19:05 UTC
[Libguestfs] [PATCH v3 11/11] REDUCE PASSES IN BOOT ANALYSIS
---
tests/qemu/boot-analysis.c | 4 ++++
1 file changed, 4 insertions(+)
diff --git a/tests/qemu/boot-analysis.c b/tests/qemu/boot-analysis.c
index 41f91bc..0137913 100644
--- a/tests/qemu/boot-analysis.c
+++ b/tests/qemu/boot-analysis.c
@@ -79,8 +79,12 @@
#include "guestfs.h"
#include "guestfs-internal-frontend.h"
+/*
#define NR_WARMUP_PASSES 3
#define NR_TEST_PASSES 5
+*/
+#define NR_WARMUP_PASSES 1
+#define NR_TEST_PASSES 2
/* Per-pass data collected. */
struct pass_data {
--
2.7.4
Richard W.M. Jones
2016-Mar-22 19:07 UTC
Re: [Libguestfs] [PATCH v3 0/11] tests/qemu: Add program for tracing and analyzing boot times.
Attached is some typical output from the latest version.
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
--z4+8/lEcDcG5Ke9S
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: 2067 events collected in 1585008402 ns
pass 2: 2067 events collected in 1575015262 ns
Analyzing the results ...
libguestfs 1.33.15
Host:
Appliance:
qemu version 2.5
SeaBIOS (version rel-1.9.0-117-gdce99e0)
[ 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 1.579867s 5.0ms (100.0%)
0.000066s: supermin:build 0.010922s 0.0ms (0.7%)
0.010989s:
0.011017s: qemu:feature-detect 0.082707s 0.3ms (5.2%)
0.093724s:
0.095377s: qemu 1.484490s 4.7ms (94.0%) qemu:overhead 0.113866s 1.1ms (7.2%)
0.187017s: seabios 0.154841s 3.1ms (9.8%)
0.209244s:
0.209244s: bios:overhead 0.132614s 3.0ms (8.4%)
0.215632s: seabios:pci-probe 0.106848s 2.9ms (6.8%)
0.322480s:
0.341858s:
0.341858s: kernel 1.238009s 6.6ms (78.4%) kernel:overhead 0.820765s 6.4ms
(52.0%) kernel:entry 0.081296s 0.6ms (5.1%)
0.423154s:
0.473678s: kernel:alternatives 0.009459s 0.0ms (0.6%)
0.483137s:
0.485714s: kernel:ftrace 0.020747s 0.0ms (1.3%)
0.506461s:
0.509057s: initcall kernel.trace_init_flags_sys_exit 0.000001s 0.0ms (0.0%)
0.509058s:
0.509058s: initcall kernel.trace_init_flags_sys_enter 0.001139s 0.0ms
(0.1%)
0.510197s:
0.510198s: initcall kernel.set_real_mode_permissions 0.000570s 0.6ms (0.0%)
0.510768s:
0.511334s: initcall kernel.trace_init_perf_perm_irq_work_exit 0.000001s
0.0ms (0.0%)
0.511335s:
0.512470s: initcall kernel.init_hw_perf_events 0.002855s 0.6ms (0.2%)
0.515325s:
0.515326s: initcall kernel.register_trigger_all_cpu_backtrace 0.000575s
0.6ms (0.0%)
0.515901s:
0.516468s: initcall kernel.numachip_system_init 0.000569s 0.6ms (0.0%)
0.517037s:
0.517607s: initcall kernel.early_efi_map_fb 0.000001s 0.0ms (0.0%)
0.517608s:
0.518172s: initcall kernel.spawn_ksoftirqd 0.000567s 0.6ms (0.0%)
0.518739s:
0.518739s: initcall kernel.init_workqueues 0.000000s 0.0ms (0.0%)
0.518740s:
0.519875s: initcall kernel.migration_init 0.000001s 0.0ms (0.0%)
0.519876s:
0.519876s: initcall kernel.check_cpu_stall_init 0.001132s 0.0ms (0.1%)
0.521009s:
0.521009s: initcall kernel.rcu_spawn_gp_kthread 0.000000s 0.0ms (0.0%)
0.521010s:
0.522143s: initcall kernel.cpu_stop_init 0.000001s 0.0ms (0.0%)
0.522144s:
0.522144s: initcall kernel.relay_init 0.001140s 0.0ms (0.1%)
0.523285s:
0.523285s: initcall kernel.init_events 0.000000s 0.0ms (0.0%)
0.523286s:
0.524428s: initcall kernel.init_trace_printk 0.000001s 0.0ms (0.0%)
0.524429s:
0.524429s: initcall kernel.event_trace_enable_again 0.001135s 0.0ms (0.1%)
0.525564s:
0.525565s: initcall kernel.jump_label_init_module 0.000000s 0.0ms (0.0%)
0.525565s:
0.526686s: initcall kernel.dynamic_debug_init 0.000001s 0.0ms (0.0%)
0.526686s:
0.527820s: initcall kernel.rand_initialize 0.000001s 0.0ms (0.0%)
0.527821s:
0.531283s: initcall kernel.ipc_ns_init 0.000001s 0.0ms (0.0%)
0.531284s:
0.531284s: initcall kernel.init_mmap_min_addr 0.000000s 0.0ms (0.0%)
0.531284s:
0.532421s: initcall kernel.init_cpufreq_transition_notifier_list 0.000001s
0.0ms (0.0%)
0.532422s:
0.533553s: initcall kernel.net_ns_init 0.000001s 0.0ms (0.0%)
0.533554s:
0.533554s: initcall kernel.xen_pvh_gnttab_setup 0.001150s 0.0ms (0.1%)
0.534704s:
0.534705s: initcall kernel.e820_mark_nvs_memory 0.000576s 0.6ms (0.0%)
0.535281s:
0.535850s: initcall kernel.cpufreq_tsc 0.000000s 0.0ms (0.0%)
0.535851s:
0.536424s: initcall kernel.init_cpu_syscore 0.000001s 0.0ms (0.0%)
0.536425s:
0.536992s: initcall kernel.reboot_init 0.000572s 0.6ms (0.0%)
0.537564s:
0.537565s: initcall kernel.init_lapic_sysfs 0.000570s 0.6ms (0.0%)
0.538134s:
0.538703s: initcall kernel.uv_bau_init 0.000000s 0.0ms (0.0%)
0.538704s:
0.539273s: initcall kernel.cpu_hotplug_pm_sync_init 0.000568s 0.6ms (0.0%)
0.539841s:
0.539842s: initcall kernel.alloc_frozen_cpus 0.000569s 0.6ms (0.0%)
0.540410s:
0.540977s: initcall kernel.wq_sysfs_init 0.000000s 0.0ms (0.0%)
0.540978s:
0.541545s: initcall kernel.ksysfs_init 0.000575s 0.6ms (0.0%)
0.542120s:
0.542121s: initcall kernel.pm_init 0.000000s 0.0ms (0.0%)
0.542121s:
0.543252s: initcall kernel.pm_disk_init 0.000001s 0.0ms (0.0%)
0.543252s:
0.543253s: initcall kernel.swsusp_header_init 0.001134s 0.0ms (0.1%)
0.544387s:
0.544388s: initcall kernel.init_jiffies_clocksource 0.001134s 0.0ms (0.1%)
0.545522s:
0.545523s: initcall kernel.cgroup_wq_init 0.000569s 0.6ms (0.0%)
0.546091s:
0.546661s: initcall kernel.ftrace_mod_cmd_init 0.000000s 0.0ms (0.0%)
0.546662s:
0.547229s: initcall kernel.init_function_trace 0.000570s 0.6ms (0.0%)
0.547798s:
0.547799s: initcall kernel.init_wakeup_tracer 0.000567s 0.6ms (0.0%)
0.548365s:
0.548935s: initcall kernel.init_graph_trace 0.000000s 0.0ms (0.0%)
0.548935s:
0.549505s: initcall kernel.perf_workqueue_init 0.000570s 0.6ms (0.0%)
0.550075s:
0.550645s: initcall kernel.init_zero_pfn 0.000001s 0.0ms (0.0%)
0.550646s:
0.551214s: initcall kernel.memory_failure_init 0.000576s 0.6ms (0.0%)
0.551790s:
0.551791s: initcall kernel.cma_init_reserved_areas 0.000568s 0.6ms (0.0%)
0.552359s:
0.552926s: initcall kernel.fsnotify_init 0.000001s 0.0ms (0.0%)
0.552926s:
0.553494s: initcall kernel.filelock_init 0.000568s 0.6ms (0.0%)
0.554063s:
0.554063s: initcall kernel.init_script_binfmt 0.000569s 0.6ms (0.0%)
0.554632s:
0.555199s: initcall kernel.init_elf_binfmt 0.000001s 0.0ms (0.0%)
0.555199s:
0.555766s: initcall kernel.init_compat_elf_binfmt 0.000567s 0.6ms (0.0%)
0.556334s:
0.556334s: initcall kernel.configfs_init 0.000000s 0.0ms (0.0%)
0.556334s:
0.557470s: initcall kernel.debugfs_init 0.000003s 0.0ms (0.0%)
0.557473s:
0.557474s: initcall kernel.tracefs_init 0.001137s 0.0ms (0.1%)
0.558610s:
0.558611s: initcall kernel.securityfs_init 0.000000s 0.0ms (0.0%)
0.558611s:
0.559755s: initcall kernel.prandom_init 0.000001s 0.0ms (0.0%)
0.559756s:
0.559756s: initcall kernel.test_atomics 0.001135s 0.0ms (0.1%)
0.560891s:
0.560891s: initcall kernel.pinctrl_init 0.001136s 0.0ms (0.1%)
0.562027s:
0.562028s: initcall kernel.sfi_sysfs_init 0.000566s 0.6ms (0.0%)
0.562594s:
0.563162s: initcall kernel.iommu_init 0.000000s 0.0ms (0.0%)
0.563163s:
0.563728s: initcall kernel.early_resume_init 0.000590s 0.6ms (0.0%)
0.564318s:
0.564887s: initcall kernel.cpufreq_core_init 0.000001s 0.0ms (0.0%)
0.564887s:
0.565455s: initcall kernel.cpuidle_init 0.000568s 0.6ms (0.0%)
0.566024s:
0.566024s: initcall kernel.bsp_pm_check_init 0.000567s 0.6ms (0.0%)
0.566591s:
0.567157s: initcall kernel.sock_init 0.000001s 0.0ms (0.0%)
0.567158s:
0.567731s: initcall kernel.net_inuse_init 0.000567s 0.6ms (0.0%)
0.568297s:
0.568298s: initcall kernel.netpoll_init 0.000567s 0.6ms (0.0%)
0.568865s:
0.569430s: initcall kernel.netlink_proto_init 0.000593s 0.6ms (0.0%)
0.570023s:
0.570588s: initcall kernel.__gnttab_init 0.000001s 0.0ms (0.0%)
0.570589s:
0.571182s: initcall kernel.bdi_class_init 0.000567s 0.6ms (0.0%)
0.571749s:
0.571749s: initcall kernel.mm_sysfs_init 0.000000s 0.0ms (0.0%)
0.571749s:
0.572883s: initcall kernel.kobject_uevent_init 0.000001s 0.0ms (0.0%)
0.572883s:
0.572884s: initcall kernel.gpiolib_sysfs_init 0.001120s 0.0ms (0.1%)
0.574004s:
0.574005s: initcall kernel.pcibus_class_init 0.000000s 0.0ms (0.0%)
0.574005s:
0.575125s: initcall kernel.pci_driver_init 0.000001s 0.0ms (0.0%)
0.575125s:
0.575125s: initcall kernel.backlight_class_init 0.001134s 0.0ms (0.1%)
0.576259s:
0.576260s: initcall kernel.xenbus_init 0.000000s 0.0ms (0.0%)
0.576260s:
0.577392s: initcall kernel.tty_class_init 0.000001s 0.0ms (0.0%)
0.577392s:
0.577393s: initcall kernel.vtconsole_class_init 0.001135s 0.0ms (0.1%)
0.578528s:
0.578528s: initcall kernel.iommu_dev_init 0.000000s 0.0ms (0.0%)
0.578529s:
0.579094s: initcall kernel.mipi_dsi_bus_init 0.000568s 0.6ms (0.0%)
0.579662s:
0.580229s: initcall kernel.wakeup_sources_debugfs_init 0.000000s 0.0ms
(0.0%)
0.580229s:
0.580797s: initcall kernel.register_node_type 0.000566s 0.6ms (0.0%)
0.581364s:
0.581933s: initcall kernel.regmap_initcall 0.000001s 0.0ms (0.0%)
0.581933s:
0.582501s: initcall kernel.spi_init 0.000001s 0.0ms (0.0%)
0.582501s:
0.583069s: initcall kernel.i2c_init 0.000566s 0.6ms (0.0%)
0.583635s:
0.583636s: initcall kernel.init_menu 0.000576s 0.6ms (0.0%)
0.584211s:
0.584784s: initcall kernel.amd_postcore_init 0.000000s 0.0ms (0.0%)
0.584785s:
0.585952s: initcall kernel.boot_params_ksysfs_init 0.000001s 0.0ms (0.0%)
0.585953s:
0.585954s: initcall kernel.sbf_init 0.000566s 0.6ms (0.0%)
0.586519s:
0.587090s: initcall kernel.arch_kdebugfs_init 0.000000s 0.0ms (0.0%)
0.587091s:
0.588225s: initcall kernel.pt_init 0.000001s 0.0ms (0.0%)
0.588226s:
0.588226s: initcall kernel.bts_init 0.000566s 0.6ms (0.0%)
0.588792s:
0.589359s: initcall kernel.mtrr_if_init 0.000000s 0.0ms (0.0%)
0.589360s:
0.589360s: initcall kernel.ffh_cstate_init 0.001136s 0.0ms (0.1%)
0.590496s:
0.590497s: initcall kernel.activate_jump_labels 0.000000s 0.0ms (0.0%)
0.590497s:
0.591635s: initcall kernel.gigantic_pages_init 0.000001s 0.0ms (0.0%)
0.591635s:
0.592202s: initcall kernel.uv_rtc_setup_clock 0.000568s 0.6ms (0.0%)
0.592771s:
0.592771s: initcall kernel.kcmp_cookies_init 0.000566s 0.6ms (0.0%)
0.593337s:
0.593912s: initcall kernel.acpi_pci_init 0.000003s 0.0ms (0.0%)
0.593915s:
0.594482s: initcall kernel.dma_bus_init 0.000568s 0.6ms (0.0%)
0.595050s:
0.595051s: initcall kernel.dma_channel_table_init 0.000567s 0.6ms (0.0%)
0.595617s:
0.596187s: initcall kernel.setup_vcpu_hotplug_event 0.000000s 0.0ms (0.0%)
0.596187s:
0.596755s: initcall kernel.register_xen_pci_notifier 0.000569s 0.6ms (0.0%)
0.597323s:
0.597889s: initcall kernel.xen_pcpu_init 0.000001s 0.0ms (0.0%)
0.597890s:
0.598458s: initcall kernel.dmi_id_init 0.000000s 0.0ms (0.0%)
0.598459s:
0.599027s: initcall kernel.numachip_timer_init 0.000570s 0.6ms (0.0%)
0.599597s:
0.600170s: initcall kernel.pci_arch_init 0.000567s 0.6ms (0.0%)
0.600737s:
0.601303s: initcall kernel.init_vdso 0.000000s 0.0ms (0.0%)
0.601304s:
0.601877s: initcall kernel.sysenter_setup 0.000566s 0.6ms (0.0%)
0.602443s:
0.602444s: initcall kernel.topology_init 0.000000s 0.0ms (0.0%)
0.602444s:
0.603578s: initcall kernel.fixup_ht_bug 0.000001s 0.0ms (0.0%)
0.603579s:
0.603579s: initcall kernel.mtrr_init_finialize 0.001135s 0.0ms (0.1%)
0.604713s:
0.604714s: initcall kernel.uid_cache_init 0.000003s 0.0ms (0.0%)
0.604717s:
0.605824s: initcall kernel.param_sysfs_init 0.000001s 0.0ms (0.0%)
0.605824s:
0.606959s: initcall kernel.proc_schedstat_init 0.000000s 0.0ms (0.0%)
0.606960s:
0.607526s: initcall kernel.pm_sysrq_init 0.000572s 0.6ms (0.0%)
0.608098s:
0.608099s: initcall kernel.create_proc_profile 0.000566s 0.6ms (0.0%)
0.608665s:
0.609234s: initcall kernel.crash_save_vmcoreinfo_init 0.000000s 0.0ms
(0.0%)
0.609234s:
0.609799s: initcall kernel.crash_notes_memory_init 0.000568s 0.6ms (0.0%)
0.610367s:
0.610368s: initcall kernel.user_namespaces_init 0.000565s 0.6ms (0.0%)
0.610933s:
0.611500s: initcall kernel.default_bdi_init 0.000585s 0.6ms (0.0%)
0.612084s:
0.612085s: initcall kernel.percpu_enable_async 0.000569s 0.6ms (0.0%)
0.612654s:
0.613215s: initcall kernel.init_reserve_notifier 0.000001s 0.0ms (0.0%)
0.613216s:
0.613783s: initcall kernel.init_admin_reserve 0.000569s 0.6ms (0.0%)
0.614352s:
0.614353s: initcall kernel.init_user_reserve 0.000568s 0.6ms (0.0%)
0.614921s:
0.615489s: initcall kernel.mmu_notifier_init 0.000000s 0.0ms (0.0%)
0.615490s:
0.616047s: initcall kernel.ksm_init 0.000574s 0.6ms (0.0%)
0.616621s:
0.616621s: initcall kernel.hugepage_init 0.000571s 0.6ms (0.0%)
0.617192s:
0.617759s: initcall kernel.mem_cgroup_swap_init 0.000001s 0.0ms (0.0%)
0.617759s:
0.618335s: initcall kernel.mem_cgroup_init 0.000566s 0.6ms (0.0%)
0.618900s:
0.618901s: initcall kernel.crypto_wq_init 0.000569s 0.6ms (0.0%)
0.619470s:
0.620037s: initcall kernel.cryptomgr_init 0.000000s 0.0ms (0.0%)
0.620037s:
0.620037s: initcall kernel.cryptd_init 0.001135s 0.0ms (0.1%)
0.621172s:
0.621172s: initcall kernel.init_bio 0.000000s 0.0ms (0.0%)
0.621173s:
0.622307s: initcall kernel.blk_settings_init 0.000001s 0.0ms (0.0%)
0.622307s:
0.622307s: initcall kernel.blk_ioc_init 0.001144s 0.0ms (0.1%)
0.623451s:
0.623453s: initcall kernel.blk_softirq_init 0.000000s 0.0ms (0.0%)
0.623453s:
0.624020s: initcall kernel.blk_iopoll_setup 0.000571s 0.6ms (0.0%)
0.624591s:
0.624591s: initcall kernel.blk_mq_init 0.000567s 0.6ms (0.0%)
0.625158s:
0.625728s: initcall kernel.genhd_device_init 0.000000s 0.0ms (0.0%)
0.625728s:
0.626294s: initcall kernel.byt_gpio_init 0.000580s 0.6ms (0.0%)
0.626874s:
0.626875s: initcall kernel.chv_pinctrl_init 0.000567s 0.6ms (0.0%)
0.627441s:
0.628008s: initcall kernel.gpiolib_debugfs_init 0.000009s 0.0ms (0.0%)
0.628016s:
0.628583s: initcall kernel.pci_slot_init 0.000566s 0.6ms (0.0%)
0.629149s:
0.629150s: initcall kernel.fbmem_init 0.000569s 0.6ms (0.0%)
0.629719s:
0.630289s: initcall kernel.acpi_init 0.000559s 0.6ms (0.0%)
0.630847s:
0.630848s: initcall kernel.pnp_init 0.000568s 0.6ms (0.0%)
0.631416s:
0.631990s: initcall kernel.balloon_init 0.000001s 0.0ms (0.0%)
0.631991s:
0.632560s: initcall kernel.xen_setup_shutdown_event 0.000579s 0.6ms (0.0%)
0.633139s:
0.633140s: initcall kernel.xenbus_probe_backend_init 0.001138s 0.0ms (0.1%)
0.634277s:
0.634278s: initcall kernel.xenbus_probe_frontend_init 0.000000s 0.0ms
(0.0%)
0.634279s:
0.635423s: initcall kernel.xen_acpi_pad_init 0.000001s 0.0ms (0.0%)
0.635424s:
0.635424s: initcall kernel.balloon_init:1 0.001138s 0.0ms (0.1%)
0.636562s:
0.636562s: initcall kernel.misc_init 0.000000s 0.0ms (0.0%)
0.636563s:
0.637690s: initcall kernel.vga_arb_device_init 0.000001s 0.0ms (0.0%)
0.637691s:
0.638824s: initcall kernel.cn_init 0.000001s 0.0ms (0.0%)
0.638825s:
0.638837s: initcall kernel.libnvdimm_init 0.000566s 0.6ms (0.0%)
0.639403s:
0.639973s: initcall kernel.dma_buf_init 0.000000s 0.0ms (0.0%)
0.639973s:
0.640543s: initcall kernel.init_scsi 0.000567s 0.6ms (0.0%)
0.641110s:
0.641682s: initcall kernel.ata_init 0.000583s 0.6ms (0.0%)
0.642265s:
0.642265s: initcall kernel.phy_init 0.000564s 0.6ms (0.0%)
0.642829s:
0.643408s: initcall kernel.init_pcmcia_cs 0.000001s 0.0ms (0.0%)
0.643409s:
0.643975s: initcall kernel.usb_init 0.001135s 0.0ms (0.1%)
0.645110s:
0.645678s: initcall kernel.serio_init 0.000593s 0.6ms (0.0%)
0.646272s:
0.646273s: initcall kernel.input_init 0.000567s 0.6ms (0.0%)
0.646839s:
0.647407s: initcall kernel.rtc_init 0.000001s 0.0ms (0.0%)
0.647408s:
0.647408s: initcall kernel.power_supply_class_init 0.000568s 0.6ms (0.0%)
0.647976s:
0.648551s: initcall kernel.hwmon_init 0.000000s 0.0ms (0.0%)
0.648551s:
0.649119s: initcall kernel.md_init 0.000566s 0.6ms (0.0%)
0.649685s:
0.649686s: initcall kernel.leds_init 0.000568s 0.6ms (0.0%)
0.650254s:
0.650823s: initcall kernel.dmi_init 0.000001s 0.0ms (0.0%)
0.650824s:
0.650824s: initcall kernel.efisubsys_init 0.001137s 0.0ms (0.1%)
0.651961s:
0.651962s: initcall kernel.devfreq_init 0.000585s 0.6ms (0.0%)
0.652547s:
0.653115s: initcall kernel.ras_init 0.000001s 0.0ms (0.0%)
0.653116s:
0.653116s: initcall kernel.pci_subsys_init 0.078254s 5.1ms (5.0%)
0.731370s:
0.732497s: initcall kernel.proto_init 0.000001s 0.0ms (0.0%)
0.732498s:
0.732498s: initcall kernel.net_dev_init 0.001130s 0.0ms (0.1%)
0.733628s:
0.733629s: initcall kernel.neigh_init 0.000935s 0.9ms (0.1%)
0.734564s:
0.735131s: initcall kernel.fib_rules_init 0.000001s 0.0ms (0.0%)
0.735131s:
0.735703s: initcall kernel.init_cgroup_netprio 0.000572s 0.6ms (0.0%)
0.736275s:
0.736833s: initcall kernel.pktsched_init 0.000000s 0.0ms (0.0%)
0.736834s:
0.737396s: initcall kernel.tc_filter_init 0.000556s 0.6ms (0.0%)
0.737953s:
0.738611s: initcall kernel.tc_action_init 0.000001s 0.0ms (0.0%)
0.738612s:
0.739171s: initcall kernel.genl_init 0.000571s 0.6ms (0.0%)
0.739741s:
0.739742s: initcall kernel.ipv4_netfilter_init 0.000560s 0.6ms (0.0%)
0.740301s:
0.740868s: initcall kernel.cipso_v4_init 0.000001s 0.0ms (0.0%)
0.740868s:
0.741428s: initcall kernel.wireless_nlevent_init 0.000567s 0.6ms (0.0%)
0.741995s:
0.742554s: initcall kernel.netlbl_init 0.001137s 0.0ms (0.1%)
0.743691s:
0.744258s: initcall kernel.xen_mcfg_late 0.000563s 0.6ms (0.0%)
0.744821s:
0.744822s: initcall kernel.watchdog_init 0.000590s 0.6ms (0.0%)
0.745412s:
0.745968s: initcall kernel.xen_p2m_debugfs 0.000000s 0.0ms (0.0%)
0.745968s:
0.746529s: initcall kernel.nmi_warning_debugfs 0.000558s 0.6ms (0.0%)
0.747087s:
0.747087s: initcall kernel.hpet_late_init 0.000565s 0.6ms (0.0%)
0.747652s:
0.748211s: initcall kernel.init_amd_nbs 0.000000s 0.0ms (0.0%)
0.748212s:
0.748776s: initcall kernel.uv_ptc_init 0.000559s 0.6ms (0.0%)
0.749335s:
0.749335s: initcall kernel.clocksource_done_booting 0.001128s 0.0ms (0.1%)
0.750463s:
0.750464s: initcall kernel.ftrace_init_tracefs 0.001116s 0.0ms (0.1%)
0.751579s:
0.751580s: initcall kernel.tracer_init_tracefs 0.001397s 0.0ms (0.1%)
0.752977s:
0.752978s: initcall kernel.init_trace_printk_function_export 0.000003s
0.0ms (0.0%)
0.752982s:
0.754105s: initcall kernel.init_graph_tracefs 0.000001s 0.0ms (0.0%)
0.754105s:
0.754106s: initcall kernel.event_trace_init 0.004755s 0.0ms (0.3%)
0.758861s:
0.758862s: initcall kernel.init_kprobe_trace 0.000000s 0.0ms (0.0%)
0.758862s:
0.759990s: initcall kernel.init_uprobe_trace 0.000001s 0.0ms (0.0%)
0.759991s:
0.759991s: initcall kernel.bpf_init 0.001133s 0.0ms (0.1%)
0.761124s:
0.761125s: initcall kernel.init_pipe_fs 0.000000s 0.0ms (0.0%)
0.761125s:
0.761692s: initcall kernel.inotify_user_setup 0.000566s 0.6ms (0.0%)
0.762258s:
0.762259s: initcall kernel.eventpoll_init 0.000561s 0.6ms (0.0%)
0.762819s:
0.763389s: initcall kernel.anon_inode_init 0.000000s 0.0ms (0.0%)
0.763389s:
0.764513s: initcall kernel.proc_cmdline_init 0.000001s 0.0ms (0.0%)
0.764513s:
0.764514s: initcall kernel.proc_consoles_init 0.001123s 0.0ms (0.1%)
0.765637s:
0.765637s: initcall kernel.proc_cpuinfo_init 0.000000s 0.0ms (0.0%)
0.765637s:
0.766762s: initcall kernel.proc_devices_init 0.000001s 0.0ms (0.0%)
0.766763s:
0.767318s: initcall kernel.proc_interrupts_init 0.000568s 0.6ms (0.0%)
0.767886s:
0.767887s: initcall kernel.proc_loadavg_init 0.000561s 0.6ms (0.0%)
0.768447s:
0.769003s: initcall kernel.proc_meminfo_init 0.000001s 0.0ms (0.0%)
0.769004s:
0.769560s: initcall kernel.proc_stat_init 0.000567s 0.6ms (0.0%)
0.770127s:
0.770128s: initcall kernel.proc_uptime_init 0.000557s 0.6ms (0.0%)
0.770684s:
0.771252s: initcall kernel.proc_version_init 0.000001s 0.0ms (0.0%)
0.771253s:
0.771822s: initcall kernel.proc_softirqs_init 0.000567s 0.6ms (0.0%)
0.772388s:
0.772949s: initcall kernel.proc_kcore_init 0.000000s 0.0ms (0.0%)
0.772949s:
0.773523s: initcall kernel.vmcore_init 0.000001s 0.0ms (0.0%)
0.773524s:
0.774084s: initcall kernel.proc_kmsg_init 0.000567s 0.6ms (0.0%)
0.774651s:
0.775239s: initcall kernel.proc_page_init 0.000000s 0.0ms (0.0%)
0.775240s:
0.775807s: initcall kernel.init_ramfs_fs 0.000001s 0.0ms (0.0%)
0.775807s:
0.776366s: initcall kernel.blk_scsi_ioctl_init 0.000568s 0.6ms (0.0%)
0.776933s:
0.777492s: initcall kernel.dynamic_debug_init_debugfs 0.000000s 0.0ms
(0.0%)
0.777492s:
0.778058s: initcall kernel.fb_console_init 0.000559s 0.6ms (0.0%)
0.778617s:
0.778617s: initcall kernel.acpi_event_init 0.000567s 0.6ms (0.0%)
0.779184s:
0.779744s: initcall kernel.pnp_system_init 0.000000s 0.0ms (0.0%)
0.779744s:
0.780872s: initcall kernel.pnpacpi_init 0.000001s 0.0ms (0.0%)
0.780873s:
0.781426s: initcall kernel.chr_dev_init 0.001165s 0.1ms (0.1%)
0.782591s:
0.783148s: initcall kernel.firmware_class_init 0.000000s 0.0ms (0.0%)
0.783148s:
0.783715s: initcall kernel.init_pcmcia_bus 0.000563s 0.6ms (0.0%)
0.784278s:
0.784279s: initcall kernel.thermal_init 0.000569s 0.6ms (0.0%)
0.784848s:
0.785405s: initcall kernel.cpufreq_gov_performance_init 0.000000s 0.0ms
(0.0%)
0.785406s:
0.786533s: initcall kernel.cpufreq_gov_dbs_init 0.000001s 0.0ms (0.0%)
0.786534s:
0.786534s: initcall kernel.init_acpi_pm_clocksource 0.001122s 0.0ms (0.1%)
0.787656s:
0.787657s: initcall kernel.pcibios_assign_resources 0.001125s 0.0ms (0.1%)
0.788782s:
0.789907s: initcall kernel.sysctl_core_init 0.000001s 0.0ms (0.0%)
0.789907s:
0.789907s: initcall kernel.eth_offload_init 0.001121s 0.0ms (0.1%)
0.791029s:
0.791029s: initcall kernel.inet_init 0.003423s 0.1ms (0.2%)
0.794452s:
0.794453s: initcall kernel.ipv4_offload_init 0.000564s 0.6ms (0.0%)
0.795016s:
0.795583s: initcall kernel.af_unix_init 0.000001s 0.0ms (0.0%)
0.795584s:
0.796716s: initcall kernel.ipv6_offload_init 0.000001s 0.0ms (0.0%)
0.796716s:
0.797272s: initcall kernel.pci_apply_final_quirks 0.001705s 0.6ms (0.1%)
0.798977s:
0.799538s: initcall kernel.acpi_reserve_resources 0.000566s 0.6ms (0.0%)
0.800104s:
0.800659s: initcall kernel.populate_rootfs 0.001133s 0.0ms (0.1%)
0.801792s:
0.802359s: initcall kernel.pci_iommu_init 0.000001s 0.0ms (0.0%)
0.802360s:
0.802917s: initcall kernel.ir_dev_scope_init 0.000566s 0.6ms (0.0%)
0.803483s:
0.804040s: initcall kernel.ia32_binfmt_init 0.000000s 0.0ms (0.0%)
0.804040s:
0.804607s: initcall kernel.register_kernel_offset_dumper 0.000570s 0.6ms
(0.0%)
0.805177s:
0.805177s: initcall kernel.i8259A_init_ops 0.000568s 0.6ms (0.0%)
0.805745s:
0.806306s: initcall kernel.init_tsc_clocksource 0.000000s 0.0ms (0.0%)
0.806306s:
0.807431s: initcall kernel.add_rtc_cmos 0.000569s 0.6ms (0.0%)
0.808000s:
0.808564s: initcall kernel.i8237A_init_ops 0.000000s 0.0ms (0.0%)
0.808564s:
0.809131s: initcall kernel.amd_uncore_init 0.000558s 0.6ms (0.0%)
0.809689s:
0.809690s: initcall kernel.amd_iommu_pc_init 0.000566s 0.6ms (0.0%)
0.810256s:
0.810814s: initcall kernel.rapl_pmu_init 0.000000s 0.0ms (0.0%)
0.810815s:
0.811381s: initcall kernel.intel_cqm_init 0.000561s 0.6ms (0.0%)
0.811942s:
0.811943s: initcall kernel.cstate_pmu_init 0.000568s 0.6ms (0.0%)
0.812510s:
0.813069s: initcall kernel.intel_uncore_init 0.000000s 0.0ms (0.0%)
0.813069s:
0.814194s: initcall kernel.msr_init 0.000001s 0.0ms (0.0%)
0.814195s:
0.814195s: initcall kernel.thermal_throttle_init_device 0.001128s 0.0ms
(0.1%)
0.815324s:
0.815324s: initcall kernel.amd_ibs_init 0.000000s 0.0ms (0.0%)
0.815325s:
0.816453s: initcall kernel.msr_init:1 0.000001s 0.0ms (0.0%)
0.816453s:
0.816454s: initcall kernel.cpuid_init 0.001123s 0.0ms (0.1%)
0.817577s:
0.817578s: initcall kernel.ioapic_init_ops 0.000000s 0.0ms (0.0%)
0.817578s:
0.818707s: initcall kernel.register_e820_pmem 0.000001s 0.0ms (0.0%)
0.818707s:
0.818708s: initcall kernel.add_pcspkr 0.001126s 0.0ms (0.1%)
0.819834s:
0.819834s: initcall kernel.start_periodic_check_for_corruption 0.000000s
0.0ms (0.0%)
0.819834s:
0.820963s: initcall kernel.sysfb_init 0.000001s 0.0ms (0.0%)
0.820963s:
0.822090s: initcall kernel.audit_classes_init 0.000001s 0.0ms (0.0%)
0.822090s:
0.822091s: initcall kernel.pt_dump_init 0.000559s 0.6ms (0.0%)
0.822650s:
0.823224s: initcall kernel.aes_init 0.000000s 0.0ms (0.0%)
0.823224s:
0.823780s: initcall kernel.pmc_atom_init 0.000568s 0.6ms (0.0%)
0.824348s:
0.824348s: initcall kernel.sgi_uv_sysfs_init 0.000557s 0.6ms (0.0%)
0.824905s:
0.825474s: initcall kernel.proc_execdomains_init 0.000000s 0.0ms (0.0%)
0.825474s:
0.826597s: initcall kernel.ioresources_init 0.000001s 0.0ms (0.0%)
0.826597s:
0.826598s: initcall kernel.init_sched_debug_procfs 0.001127s 0.0ms (0.1%)
0.827725s:
0.827726s: initcall kernel.snapshot_device_init 0.000561s 0.6ms (0.0%)
0.828287s:
0.828854s: initcall kernel.irq_pm_init_ops 0.000000s 0.0ms (0.0%)
0.828855s:
0.829412s: initcall kernel.init_posix_timers 0.000569s 0.6ms (0.0%)
0.829981s:
0.829982s: initcall kernel.init_posix_cpu_timers 0.000561s 0.6ms (0.0%)
0.830542s:
0.831112s: initcall kernel.timekeeping_init_ops 0.000001s 0.0ms (0.0%)
0.831112s:
0.832238s: initcall kernel.init_clocksource_sysfs 0.000001s 0.0ms (0.0%)
0.832239s:
0.832781s: initcall kernel.init_timer_list_procfs 0.000565s 0.6ms (0.0%)
0.833346s:
0.833347s: initcall kernel.alarmtimer_init 0.000565s 0.6ms (0.0%)
0.833912s:
0.835059s: initcall kernel.clockevents_init_sysfs 0.000001s 0.0ms (0.0%)
0.835060s:
0.836201s: initcall kernel.init_tstats_procfs 0.000001s 0.0ms (0.0%)
0.836202s:
0.836202s: initcall kernel.futex_init 0.001141s 0.0ms (0.1%)
0.837343s:
0.837343s: initcall kernel.proc_dma_init 0.000569s 0.6ms (0.0%)
0.837912s:
0.838483s: initcall kernel.proc_modules_init 0.000000s 0.0ms (0.0%)
0.838483s:
0.839616s: initcall kernel.kallsyms_init 0.000001s 0.0ms (0.0%)
0.839616s:
0.839617s: initcall kernel.pid_namespaces_init 0.000565s 0.6ms (0.0%)
0.840182s:
0.840747s: initcall kernel.audit_init 0.001123s 0.0ms (0.1%)
0.841870s:
0.841871s: initcall kernel.audit_watch_init 0.001133s 0.0ms (0.1%)
0.843004s:
0.843005s: initcall kernel.audit_fsnotify_init 0.000000s 0.0ms (0.0%)
0.843005s:
0.844138s: initcall kernel.audit_tree_init 0.000001s 0.0ms (0.0%)
0.844138s:
0.844139s: initcall kernel.init_kprobes 0.001192s 0.1ms (0.1%)
0.845331s:
0.845331s: initcall kernel.utsname_sysctl_init 0.000000s 0.0ms (0.0%)
0.845332s:
0.846467s: initcall kernel.init_tracepoints 0.000001s 0.0ms (0.0%)
0.846467s:
0.847034s: initcall kernel.init_lstats_procfs 0.000553s 0.6ms (0.0%)
0.847587s:
0.847588s: initcall kernel.stack_trace_init 0.000567s 0.6ms (0.0%)
0.848155s:
0.848724s: initcall kernel.init_mmio_trace 0.000001s 0.0ms (0.0%)
0.848724s:
0.849303s: initcall kernel.init_blk_tracer 0.000584s 0.5ms (0.0%)
0.849887s:
0.849887s: initcall kernel.perf_event_sysfs_init 0.000569s 0.6ms (0.0%)
0.850456s:
0.851020s: initcall kernel.init_uprobes 0.000000s 0.0ms (0.0%)
0.851020s:
0.851590s: initcall kernel.system_trusted_keyring_init 0.000570s 0.6ms
(0.0%)
0.852160s:
0.852729s: initcall kernel.init_per_zone_wmark_min 0.000565s 0.6ms (0.0%)
0.853294s:
0.853860s: initcall kernel.kswapd_init 0.000001s 0.0ms (0.0%)
0.853860s:
0.854429s: initcall kernel.extfrag_debug_init 0.000000s 0.0ms (0.0%)
0.854429s:
0.855562s: initcall kernel.setup_vmstat 0.000001s 0.0ms (0.0%)
0.855563s:
0.856131s: initcall kernel.mm_compute_batch_init 0.000000s 0.0ms (0.0%)
0.856132s:
0.856707s: initcall kernel.slab_proc_init 0.000572s 0.6ms (0.0%)
0.857279s:
0.857845s: initcall kernel.workingset_init 0.000001s 0.0ms (0.0%)
0.857846s:
0.858413s: initcall kernel.proc_vmalloc_init 0.000000s 0.0ms (0.0%)
0.858413s:
0.858981s: initcall kernel.procswaps_init 0.000567s 0.6ms (0.0%)
0.859548s:
0.860115s: initcall kernel.init_frontswap 0.000001s 0.0ms (0.0%)
0.860115s:
0.860683s: initcall kernel.hugetlb_init 0.001123s 0.0ms (0.1%)
0.861807s:
0.862358s: initcall kernel.slab_sysfs_init 0.001566s 0.2ms (0.1%)
0.863924s:
0.863925s: initcall kernel.init_cleancache 0.000000s 0.0ms (0.0%)
0.863925s:
0.865059s: initcall kernel.init_zbud 0.000003s 0.0ms (0.0%)
0.865062s:
0.865063s: initcall kernel.zs_init 0.001125s 0.0ms (0.1%)
0.866188s:
0.866189s: initcall kernel.fcntl_init 0.000000s 0.0ms (0.0%)
0.866189s:
0.867350s: initcall kernel.proc_filesystems_init 0.000001s 0.0ms (0.0%)
0.867351s:
0.867351s: initcall kernel.start_dirtytime_writeback 0.001135s 0.0ms (0.1%)
0.868485s:
0.868486s: initcall kernel.dio_init 0.000000s 0.0ms (0.0%)
0.868486s:
0.869631s: initcall kernel.fsnotify_mark_init 0.000001s 0.0ms (0.0%)
0.869631s:
0.869632s: initcall kernel.dnotify_init 0.001132s 0.0ms (0.1%)
0.870764s:
0.870765s: initcall kernel.fanotify_user_setup 0.000000s 0.0ms (0.0%)
0.870765s:
0.871898s: initcall kernel.userfaultfd_init 0.000001s 0.0ms (0.0%)
0.871899s:
0.872472s: initcall kernel.aio_setup 0.000569s 0.6ms (0.0%)
0.873041s:
0.873042s: initcall kernel.proc_locks_init 0.000000s 0.0ms (0.0%)
0.873042s:
0.874177s: initcall kernel.init_sys32_ioctl 0.000001s 0.0ms (0.0%)
0.874178s:
0.874744s: initcall kernel.init_mbcache 0.000552s 0.6ms (0.0%)
0.875296s:
0.875296s: initcall kernel.dquot_init 0.001135s 0.0ms (0.1%)
0.876432s:
0.876432s: initcall kernel.init_v2_quota_format 0.001136s 0.0ms (0.1%)
0.877569s:
0.877569s: initcall kernel.quota_init 0.000000s 0.0ms (0.0%)
0.877570s:
0.878706s: initcall kernel.init_devpts_fs 0.000001s 0.0ms (0.0%)
0.878707s:
0.878707s: initcall kernel.ext4_init_fs 0.001183s 0.1ms (0.1%)
0.879891s:
0.879891s: initcall kernel.journal_init 0.000593s 0.6ms (0.0%)
0.880484s:
0.881051s: initcall kernel.init_hugetlbfs_fs 0.000001s 0.0ms (0.0%)
0.881052s:
0.881621s: initcall kernel.init_nls_cp437 0.000576s 0.6ms (0.0%)
0.882197s:
0.882198s: initcall kernel.init_nls_ascii 0.000566s 0.6ms (0.0%)
0.882764s:
0.883334s: initcall kernel.init_autofs4_fs 0.000001s 0.0ms (0.0%)
0.883334s:
0.883902s: initcall kernel.init_pstore_fs 0.000570s 0.6ms (0.0%)
0.884472s:
0.884473s: initcall kernel.efivarfs_init 0.000567s 0.6ms (0.0%)
0.885040s:
0.885609s: initcall kernel.ipc_init 0.000001s 0.0ms (0.0%)
0.885609s:
0.886176s: initcall kernel.ipc_sysctl_init 0.000001s 0.0ms (0.0%)
0.886176s:
0.886745s: initcall kernel.init_mqueue_fs 0.000565s 0.6ms (0.0%)
0.887310s:
0.887884s: initcall kernel.key_proc_init 0.000001s 0.0ms (0.0%)
0.887884s:
0.888451s: initcall kernel.big_key_init 0.000570s 0.6ms (0.0%)
0.889020s:
0.889020s: initcall kernel.selinux_nf_ip_init 0.000566s 0.6ms (0.0%)
0.889586s:
0.890156s: initcall kernel.init_sel_fs 0.000001s 0.0ms (0.0%)
0.890156s:
0.890724s: initcall kernel.selnl_init 0.000557s 0.6ms (0.0%)
0.891281s:
0.891282s: initcall kernel.sel_netif_init 0.000565s 0.6ms (0.0%)
0.891847s:
0.892417s: initcall kernel.sel_netnode_init 0.000000s 0.0ms (0.0%)
0.892418s:
0.892985s: initcall kernel.sel_netport_init 0.000569s 0.6ms (0.0%)
0.893554s:
0.893554s: initcall kernel.aurule_init 0.000567s 0.6ms (0.0%)
0.894122s:
0.894690s: initcall kernel.fips_init 0.000000s 0.0ms (0.0%)
0.894691s:
0.895259s: initcall kernel.crypto_algapi_init 0.000001s 0.0ms (0.0%)
0.895260s:
0.895829s: initcall kernel.chainiv_module_init 0.000567s 0.6ms (0.0%)
0.896396s:
0.896987s: initcall kernel.eseqiv_module_init 0.000001s 0.0ms (0.0%)
0.896988s:
0.897554s: initcall kernel.seqiv_module_init 0.000000s 0.0ms (0.0%)
0.897555s:
0.898126s: initcall kernel.hmac_module_init 0.000566s 0.6ms (0.0%)
0.898692s:
0.899265s: initcall kernel.crypto_null_mod_init 0.000001s 0.0ms (0.0%)
0.899265s:
0.899833s: initcall kernel.md5_mod_init 0.000567s 0.6ms (0.0%)
0.900400s:
0.900967s: initcall kernel.sha1_generic_mod_init 0.000001s 0.0ms (0.0%)
0.900968s:
0.901538s: initcall kernel.sha256_generic_mod_init 0.000565s 0.6ms (0.0%)
0.902102s:
0.902678s: initcall kernel.crypto_ecb_module_init 0.000568s 0.6ms (0.0%)
0.903246s:
0.903246s: initcall kernel.crypto_cbc_module_init 0.000575s 0.6ms (0.0%)
0.903821s:
0.904387s: initcall kernel.crypto_module_init 0.000000s 0.0ms (0.0%)
0.904388s:
0.904954s: initcall kernel.crypto_module_init:1 0.000566s 0.6ms (0.0%)
0.905520s:
0.905520s: initcall kernel.crypto_ctr_module_init 0.000566s 0.6ms (0.0%)
0.906086s:
0.906651s: initcall kernel.aes_init:1 0.000000s 0.0ms (0.0%)
0.906651s:
0.907218s: initcall kernel.crc32c_mod_init 0.000564s 0.6ms (0.0%)
0.907783s:
0.907783s: initcall kernel.crct10dif_mod_init 0.000566s 0.6ms (0.0%)
0.908349s:
0.908915s: initcall kernel.lzo_mod_init 0.000000s 0.0ms (0.0%)
0.908916s:
0.910020s: initcall kernel.drbg_init 0.001438s 0.1ms (0.1%)
0.911457s:
0.911458s: initcall kernel.jent_mod_init 0.000000s 0.0ms (0.0%)
0.911458s:
0.912593s: initcall kernel.af_alg_init 0.000001s 0.0ms (0.0%)
0.912594s:
0.913729s: initcall kernel.algif_hash_init 0.000001s 0.0ms (0.0%)
0.913730s:
0.913730s: initcall kernel.algif_skcipher_init 0.001160s 0.0ms (0.1%)
0.914890s:
0.914892s: initcall kernel.rng_init 0.000004s 0.0ms (0.0%)
0.914895s:
0.915464s: initcall kernel.algif_aead_init 0.000570s 0.6ms (0.0%)
0.916034s:
0.916035s: initcall kernel.asymmetric_key_init 0.001137s 0.0ms (0.1%)
0.917171s:
0.917172s: initcall kernel.x509_key_init 0.001141s 0.0ms (0.1%)
0.918313s:
0.918313s: initcall kernel.proc_genhd_init 0.000000s 0.0ms (0.0%)
0.918314s:
0.919449s: initcall kernel.bsg_init 0.000569s 0.6ms (0.0%)
0.920018s:
0.920586s: initcall kernel.throtl_init 0.000000s 0.0ms (0.0%)
0.920586s:
0.921151s: initcall kernel.noop_init 0.000571s 0.6ms (0.0%)
0.921722s:
0.921722s: initcall kernel.deadline_init 0.001136s 0.0ms (0.1%)
0.922858s:
0.922859s: initcall kernel.cfq_init 0.001137s 0.0ms (0.1%)
0.923995s:
0.923996s: initcall kernel.test_kstrtox_init 0.000572s 0.6ms (0.0%)
0.924568s:
0.925135s: initcall kernel.btree_module_init 0.000000s 0.0ms (0.0%)
0.925135s:
0.925714s: initcall kernel.crc_t10dif_mod_init 0.000584s 0.6ms (0.0%)
0.926298s:
0.926865s: initcall kernel.percpu_counter_startup 0.000001s 0.0ms (0.0%)
0.926866s:
0.927440s: initcall kernel.phy_core_init 0.000569s 0.6ms (0.0%)
0.928009s:
0.928583s: initcall kernel.crystalcove_gpio_driver_init 0.000001s 0.0ms
(0.0%)
0.928583s:
0.929152s: initcall kernel.pci_proc_init 0.000569s 0.6ms (0.0%)
0.929721s:
0.929722s: initcall kernel.pcie_portdrv_init 0.000567s 0.6ms (0.0%)
0.930288s:
0.930860s: initcall kernel.aer_service_init 0.000001s 0.0ms (0.0%)
0.930860s:
0.931427s: initcall kernel.pcie_pme_service_init 0.000574s 0.6ms (0.0%)
0.932001s:
0.932583s: initcall kernel.pci_hotplug_init 0.000571s 0.6ms (0.0%)
0.933153s:
0.933735s: initcall kernel.pcied_init 0.000569s 0.6ms (0.0%)
0.934304s:
0.934876s: initcall kernel.pci_stub_init 0.000001s 0.0ms (0.0%)
0.934877s:
0.936020s: initcall kernel.xenfb_init 0.000001s 0.0ms (0.0%)
0.936020s:
0.936021s: initcall kernel.vesafb_driver_init 0.000570s 0.6ms (0.0%)
0.936590s:
0.937164s: initcall kernel.efifb_driver_init 0.000000s 0.0ms (0.0%)
0.937164s:
0.938307s: initcall kernel.intel_idle_init 0.000001s 0.0ms (0.0%)
0.938308s:
0.939449s: initcall kernel.acpi_ac_init 0.000001s 0.0ms (0.0%)
0.939450s:
0.939450s: initcall kernel.acpi_button_driver_init 0.001136s 0.0ms (0.1%)
0.940586s:
0.940587s: initcall kernel.acpi_fan_driver_init 0.000000s 0.0ms (0.0%)
0.940587s:
0.941726s: initcall kernel.acpi_processor_driver_init 0.000001s 0.0ms
(0.0%)
0.941727s:
0.942862s: initcall kernel.acpi_thermal_init 0.000001s 0.0ms (0.0%)
0.942863s:
0.942863s: initcall kernel.acpi_battery_init 0.001139s 0.0ms (0.1%)
0.944002s:
0.944003s: initcall kernel.acpi_hed_driver_init 0.000000s 0.0ms (0.0%)
0.944003s:
0.945139s: initcall kernel.bgrt_init 0.000001s 0.0ms (0.0%)
0.945140s:
0.945140s: initcall kernel.erst_init 0.001134s 0.0ms (0.1%)
0.946274s:
0.946275s: initcall kernel.ghes_init 0.000000s 0.0ms (0.0%)
0.946275s:
0.947403s: initcall kernel.intel_crc_pmic_opregion_driver_init 0.000001s
0.0ms (0.0%)
0.947404s:
0.947968s: initcall kernel.xenbus_probe_initcall 0.000567s 0.6ms (0.0%)
0.948534s:
0.948535s: initcall kernel.xenbus_init:1 0.001123s 0.0ms (0.1%)
0.949657s:
0.949658s: initcall kernel.xenbus_backend_init 0.000567s 0.6ms (0.0%)
0.950225s:
0.950796s: initcall kernel.hypervisor_subsys_init 0.000571s 0.6ms (0.0%)
0.951367s:
0.951368s: initcall kernel.hyper_sysfs_init 0.000562s 0.6ms (0.0%)
0.951930s:
0.952497s: initcall kernel.platform_pci_module_init 0.000000s 0.0ms (0.0%)
0.952498s:
0.953626s: initcall kernel.pty_init 0.000001s 0.0ms (0.0%)
0.953627s:
0.954766s: initcall kernel.sysrq_init 0.000001s 0.0ms (0.0%)
0.954767s:
0.954767s: initcall kernel.xen_hvc_init 0.000594s 0.6ms (0.0%)
0.955361s:
0.955924s: initcall kernel.serial8250_init 0.024766s 0.1ms (1.6%)
0.980690s:
0.980691s: initcall kernel.serial_pci_driver_init 0.000000s 0.0ms (0.0%)
0.980691s:
0.981804s: initcall kernel.dw8250_platform_driver_init 0.000001s 0.0ms
(0.0%)
0.981805s:
0.982358s: initcall kernel.mid8250_pci_driver_init 0.000566s 0.6ms (0.0%)
0.982924s:
0.983489s: initcall kernel.init_kgdboc 0.000566s 0.6ms (0.0%)
0.984055s:
0.984056s: initcall kernel.raw_init 0.000554s 0.6ms (0.0%)
0.984610s:
0.985171s: initcall kernel.hpet_init 0.000000s 0.0ms (0.0%)
0.985171s:
0.985725s: initcall kernel.nvram_init 0.000562s 0.6ms (0.0%)
0.986288s:
0.986842s: initcall kernel.hwrng_modinit 0.000000s 0.0ms (0.0%)
0.986842s:
0.987419s: initcall kernel.agp_init 0.000558s 0.6ms (0.0%)
0.987977s:
0.988540s: initcall kernel.agp_amd64_mod_init 0.000554s 0.6ms (0.0%)
0.989095s:
0.989099s: initcall kernel.agp_intel_init 0.000562s 0.6ms (0.0%)
0.989661s:
0.990213s: initcall kernel.agp_sis_init 0.000000s 0.0ms (0.0%)
0.990214s:
0.990777s: initcall kernel.agp_via_init 0.000554s 0.6ms (0.0%)
0.991331s:
0.991332s: initcall kernel.cn_proc_init 0.000563s 0.6ms (0.0%)
0.991895s:
0.992452s: initcall kernel.topology_sysfs_init 0.000000s 0.0ms (0.0%)
0.992452s:
0.993580s: initcall kernel.cacheinfo_sysfs_init 0.000000s 0.0ms (0.0%)
0.993580s:
0.993581s: initcall kernel.devcoredump_init 0.001119s 0.0ms (0.1%)
0.994699s:
0.994700s: initcall kernel.init_kgdbts 0.000000s 0.0ms (0.0%)
0.994700s:
0.995818s: initcall kernel.intel_soc_pmic_i2c_driver_init 0.000000s 0.0ms
(0.0%)
0.995819s:
0.996389s: initcall kernel.e820_pmem_init 0.000571s 0.6ms (0.0%)
0.996959s:
0.996960s: initcall kernel.mac_hid_init 0.000000s 0.0ms (0.0%)
0.996960s:
0.998078s: initcall kernel.init_sd 0.000000s 0.0ms (0.0%)
0.998079s:
0.998079s: initcall kernel.init_sr 0.001119s 0.0ms (0.1%)
0.999198s:
0.999198s: initcall kernel.init_sg 0.000000s 0.0ms (0.0%)
0.999198s:
1.000320s: initcall kernel.ahci_pci_driver_init 0.000000s 0.0ms (0.0%)
1.000320s:
1.000320s: initcall kernel.piix_init 0.003355s 0.0ms (0.2%)
1.003675s:
1.004231s: initcall kernel.net_olddevs_init 0.000562s 0.6ms (0.0%)
1.004793s:
1.004793s: initcall kernel.fixed_mdio_bus_init 0.001134s 0.0ms (0.1%)
1.005927s:
1.005927s: initcall kernel.cdrom_init 0.000564s 0.6ms (0.0%)
1.006491s:
1.007056s: initcall kernel.nonstatic_sysfs_init 0.000000s 0.0ms (0.0%)
1.007056s:
1.008173s: initcall kernel.mon_init 0.000001s 0.0ms (0.0%)
1.008173s:
1.008173s: initcall kernel.ehci_hcd_init 0.001123s 0.0ms (0.1%)
1.009297s:
1.009297s: initcall kernel.ehci_pci_init 0.001118s 0.0ms (0.1%)
1.010415s:
1.010415s: initcall kernel.ohci_hcd_mod_init 0.001118s 0.0ms (0.1%)
1.011534s:
1.012086s: initcall kernel.ohci_pci_init 0.000566s 0.6ms (0.0%)
1.012652s:
1.012652s: initcall kernel.uhci_hcd_init 0.001128s 0.0ms (0.1%)
1.013781s:
1.014341s: initcall kernel.xhci_hcd_init 0.000574s 0.6ms (0.0%)
1.014916s:
1.014916s: initcall kernel.xhci_pci_init 0.000570s 0.6ms (0.0%)
1.015486s:
1.016049s: initcall kernel.usb_serial_init 0.001135s 0.0ms (0.1%)
1.017184s:
1.017751s: initcall kernel.kgdbdbgp_start_thread 0.000564s 0.6ms (0.0%)
1.018315s:
1.018316s: initcall kernel.ledtrig_usb_init 0.000567s 0.6ms (0.0%)
1.018883s:
1.019449s: initcall kernel.i8042_init 0.002239s 0.0ms (0.1%)
1.021688s:
1.021688s: initcall kernel.serport_init 0.000567s 0.6ms (0.0%)
1.022255s:
1.022828s: initcall kernel.input_leds_init 0.000000s 0.0ms (0.0%)
1.022829s:
1.023397s: initcall kernel.mousedev_init 0.000549s 0.5ms (0.0%)
1.023946s:
1.024514s: initcall kernel.evdev_init 0.000565s 0.6ms (0.0%)
1.025078s:
1.025078s: initcall kernel.atkbd_init 0.000000s 0.0ms (0.0%)
1.025079s:
1.026851s: initcall kernel.psmouse_init 0.000557s 0.6ms (0.0%)
1.027408s:
1.030231s: initcall kernel.xenkbd_init 0.000001s 0.0ms (0.0%)
1.030232s:
1.030797s: initcall kernel.cmos_init 0.001141s 0.0ms (0.1%)
1.031938s:
1.031939s: initcall kernel.dm_init 0.002274s 0.0ms (0.1%)
1.034213s:
1.034214s: initcall kernel.dm_bufio_init 0.000000s 0.0ms (0.0%)
1.034214s:
1.035343s: initcall kernel.dm_snapshot_init 0.000001s 0.0ms (0.0%)
1.035344s:
1.035344s: initcall kernel.dm_mirror_init 0.001130s 0.0ms (0.1%)
1.036474s:
1.036475s: initcall kernel.dm_dirty_log_init 0.000000s 0.0ms (0.0%)
1.036475s:
1.037600s: initcall kernel.dm_zero_init 0.000000s 0.0ms (0.0%)
1.037600s:
1.037601s: initcall kernel.cpufreq_gov_powersave_init 0.001123s 0.0ms
(0.1%)
1.038723s:
1.038724s: initcall kernel.cpufreq_gov_userspace_init 0.000571s 0.6ms
(0.0%)
1.039295s:
1.039860s: initcall kernel.cpufreq_gov_dbs_init:1 0.000558s 0.6ms (0.0%)
1.040418s:
1.040983s: initcall kernel.intel_pstate_init 0.000000s 0.0ms (0.0%)
1.040984s:
1.041544s: initcall kernel.dmi_sysfs_init 0.000561s 0.6ms (0.0%)
1.042106s:
1.042106s: initcall kernel.esrt_sysfs_init 0.000567s 0.6ms (0.0%)
1.042673s:
1.043237s: initcall kernel.hid_init 0.000559s 0.6ms (0.0%)
1.043796s:
1.044359s: initcall kernel.hid_generic_init 0.000000s 0.0ms (0.0%)
1.044360s:
1.044921s: initcall kernel.magicmouse_driver_init 0.000563s 0.6ms (0.0%)
1.045484s:
1.045485s: initcall kernel.ntrig_driver_init 0.000565s 0.6ms (0.0%)
1.046050s:
1.046613s: initcall kernel.hid_init:1 0.001700s 0.6ms (0.1%)
1.048313s:
1.048314s: initcall kernel.staging_init 0.000000s 0.0ms (0.0%)
1.048314s:
1.049448s: initcall kernel.smartconnect_driver_init 0.000001s 0.0ms (0.0%)
1.049448s:
1.049449s: initcall kernel.powercap_init 0.001127s 0.0ms (0.1%)
1.050575s:
1.050576s: initcall kernel.sock_diag_init 0.000000s 0.0ms (0.0%)
1.050576s:
1.051707s: initcall kernel.init_net_drop_monitor 0.000568s 0.6ms (0.0%)
1.052275s:
1.052835s: initcall kernel.blackhole_init 0.000000s 0.0ms (0.0%)
1.052836s:
1.053967s: initcall kernel.fq_codel_module_init 0.000022s 0.0ms (0.0%)
1.053988s:
1.053989s: initcall kernel.init_cgroup_cls 0.001135s 0.0ms (0.1%)
1.055124s:
1.055125s: initcall kernel.xt_init 0.000000s 0.0ms (0.0%)
1.055125s:
1.056248s: initcall kernel.tcpudp_mt_init 0.000000s 0.0ms (0.0%)
1.056249s:
1.056249s: initcall kernel.gre_offload_init 0.001119s 0.0ms (0.1%)
1.057368s:
1.057368s: initcall kernel.sysctl_ipv4_init 0.000000s 0.0ms (0.0%)
1.057369s:
1.058503s: initcall kernel.ip_tables_init 0.000001s 0.0ms (0.0%)
1.058504s:
1.059635s: initcall kernel.iptable_filter_init 0.000001s 0.0ms (0.0%)
1.059636s:
1.059638s: initcall kernel.reject_tg_init 0.001133s 0.0ms (0.1%)
1.060770s:
1.060771s: initcall kernel.cubictcp_register 0.000000s 0.0ms (0.0%)
1.060771s:
1.061903s: initcall kernel.tcp_memcontrol_init 0.000001s 0.0ms (0.0%)
1.061903s:
1.061904s: initcall kernel.xfrm_user_init 0.001133s 0.0ms (0.1%)
1.063037s:
1.063037s: initcall kernel.inet6_init 0.001121s 0.0ms (0.1%)
1.064158s:
1.064730s: initcall kernel.mip6_init 0.000574s 0.6ms (0.0%)
1.065304s:
1.065304s: initcall kernel.packet_init 0.001131s 0.0ms (0.1%)
1.066435s:
1.066436s: initcall kernel.dcbnl_init 0.000566s 0.6ms (0.0%)
1.067002s:
1.067565s: initcall kernel.mcheck_init_device 0.000000s 0.0ms (0.0%)
1.067565s:
1.068728s: initcall kernel.secure_boot_sysrq 0.000001s 0.0ms (0.0%)
1.068729s:
1.068729s: initcall kernel.tboot_late_init 0.000557s 0.6ms (0.0%)
1.069286s:
1.069852s: initcall kernel.mcheck_late_init 0.000000s 0.0ms (0.0%)
1.069852s:
1.070989s: initcall kernel.severities_debugfs_init 0.000001s 0.0ms (0.0%)
1.070990s:
1.071558s: initcall kernel.threshold_init_device 0.000565s 0.6ms (0.0%)
1.072123s:
1.072123s: initcall kernel.microcode_init 0.001142s 0.0ms (0.1%)
1.073265s:
1.074397s: initcall kernel.hpet_insert_resource 0.000001s 0.0ms (0.0%)
1.074398s:
1.074967s: initcall kernel.update_mp_table 0.000581s 0.5ms (0.0%)
1.075548s:
1.075548s: initcall kernel.lapic_insert_resource 0.000569s 0.6ms (0.0%)
1.076118s:
1.076682s: initcall kernel.print_ICs 0.000000s 0.0ms (0.0%)
1.076683s:
1.077258s: initcall kernel.pat_memtype_list_init 0.000565s 0.6ms (0.0%)
1.077822s:
1.077823s: initcall kernel.create_tlb_single_page_flush_ceiling 0.000572s
0.6ms (0.0%)
1.078395s:
1.078960s: initcall kernel.aesni_init 0.018268s 0.3ms (1.2%)
1.097228s:
1.097229s: initcall kernel.init_oops_id 0.000000s 0.0ms (0.0%)
1.097229s:
1.098364s: initcall kernel.sched_init_debug 0.000001s 0.0ms (0.0%)
1.098365s:
1.098365s: initcall kernel.pm_qos_power_init 0.001181s 0.1ms (0.1%)
1.099546s:
1.099547s: initcall kernel.pm_debugfs_init 0.000000s 0.0ms (0.0%)
1.099547s:
1.100680s: initcall kernel.printk_late_init 0.000001s 0.0ms (0.0%)
1.100681s:
1.100681s: initcall kernel.tk_debug_sleep_time_init 0.001136s 0.0ms (0.1%)
1.101818s:
1.101818s: initcall kernel.load_uefi_certs 0.000000s 0.0ms (0.0%)
1.101818s:
1.102950s: initcall kernel.debugfs_kprobe_init 0.000001s 0.0ms (0.0%)
1.102951s:
1.103533s: initcall kernel.taskstats_init 0.000568s 0.6ms (0.0%)
1.104101s:
1.104101s: initcall kernel.clear_boot_tracer 0.001132s 0.0ms (0.1%)
1.105233s:
1.105234s: initcall kernel.register_kprobe_prog_ops 0.000000s 0.0ms (0.0%)
1.105234s:
1.106368s: initcall kernel.kdb_ftrace_register 0.000001s 0.0ms (0.0%)
1.106368s:
1.106933s: initcall kernel.register_htab_map 0.000568s 0.6ms (0.0%)
1.107500s:
1.107501s: initcall kernel.register_perf_event_array_map 0.001133s 0.0ms
(0.1%)
1.108633s:
1.108634s: initcall kernel.register_prog_array_map 0.000000s 0.0ms (0.0%)
1.108634s:
1.109770s: initcall kernel.register_array_map 0.000001s 0.0ms (0.0%)
1.109771s:
1.110327s: initcall kernel.load_system_certificate_list 0.001825s 0.5ms
(0.1%)
1.112152s:
1.113289s: initcall kernel.fault_around_debugfs 0.000001s 0.0ms (0.0%)
1.113290s:
1.113290s: initcall kernel.max_swapfiles_check 0.001130s 0.0ms (0.1%)
1.114420s:
1.114421s: initcall kernel.init_zswap 0.000000s 0.0ms (0.0%)
1.114422s:
1.115554s: initcall kernel.check_early_ioremap_leak 0.000000s 0.0ms (0.0%)
1.115555s:
1.116688s: initcall kernel.init_root_keyring 0.000001s 0.0ms (0.0%)
1.116689s:
1.116689s: initcall kernel.prandom_reseed 0.001133s 0.0ms (0.1%)
1.117822s:
1.117823s: initcall kernel.pci_resource_alignment_sysfs_init 0.000000s
0.0ms (0.0%)
1.117823s:
1.118952s: initcall kernel.pci_sysfs_init 0.000001s 0.0ms (0.0%)
1.118953s:
1.120096s: initcall kernel.fb_logo_late_init 0.000001s 0.0ms (0.0%)
1.120097s:
1.120097s: initcall kernel.boot_wait_for_devices 0.001140s 0.0ms (0.1%)
1.121237s:
1.121238s: initcall kernel.dmar_free_unused_resources 0.000000s 0.0ms
(0.0%)
1.121238s:
1.122376s: initcall kernel.deferred_probe_initcall 0.000001s 0.0ms (0.0%)
1.122377s:
1.122377s: initcall kernel.late_resume_init 0.001131s 0.0ms (0.1%)
1.123508s:
1.123508s: initcall kernel.rtc_hctosys 0.001130s 0.0ms (0.1%)
1.124638s:
1.125757s: initcall kernel.firmware_memmap_init 0.000001s 0.0ms (0.0%)
1.125757s:
1.125757s: initcall kernel.efi_shutdown_init 0.001136s 0.0ms (0.1%)
1.126894s:
1.126895s: initcall kernel.clk_debug_init 0.000000s 0.0ms (0.0%)
1.126895s:
1.128034s: initcall kernel.pci_mmcfg_late_insert_resources 0.000001s 0.0ms
(0.0%)
1.128035s:
1.128607s: initcall kernel.register_sk_filter_ops 0.000568s 0.6ms (0.0%)
1.129174s:
1.129175s: initcall kernel.tcp_congestion_default 0.001160s 0.0ms (0.1%)
1.130335s:
1.130336s: initcall kernel.software_resume 0.001154s 0.0ms (0.1%)
1.131489s:
1.131490s: initcall kernel.clk_disable_unused 0.000000s 0.0ms (0.0%)
1.131491s:
1.132630s: initcall kernel.init_default_flow_dissectors 0.000001s 0.0ms
(0.0%)
1.132631s:
1.162623s:
1.162623s: supermin:mini-initrd 0.104940s 1.9ms (6.6%)
1.164947s: insmod crc32-pclmul.ko 0.001449s 0.0ms (0.1%)
1.166395s: initcall crc32_pclmul.crc32_pclmul_mod_init 0.000001s 0.0ms
(0.0%)
1.166396s:
1.166396s:
1.166396s: insmod crc32c-intel.ko 0.002223s 0.0ms (0.1%)
1.167486s: initcall crc32c_intel.crc32c_intel_mod_init 0.001132s 0.0ms
(0.1%)
1.168618s:
1.168619s:
1.168619s: insmod crct10dif-pclmul.ko 0.002234s 0.0ms (0.1%)
1.169728s: initcall crct10dif_pclmul.crct10dif_intel_mod_init 0.001124s
0.0ms (0.1%)
1.170852s:
1.170853s:
1.170853s: insmod crc32.ko 0.001964s 0.2ms (0.1%)
1.172256s: initcall crc32.crc32_mod_init 0.000560s 0.6ms (0.0%)
1.172816s:
1.172817s:
1.172817s: insmod virtio.ko 0.001893s 0.4ms (0.1%)
1.174151s: initcall virtio.virtio_init 0.000558s 0.6ms (0.0%)
1.174709s:
1.174710s:
1.174710s: insmod virtio_ring.ko 0.001671s 0.2ms (0.1%)
1.176381s:
1.176381s: insmod virtio_blk.ko 0.001124s 0.0ms (0.1%)
1.176381s: initcall virtio_blk.init 0.001123s 0.0ms (0.1%)
1.177505s:
1.177505s:
1.177505s: insmod virtio-rng.ko 0.001761s 0.0ms (0.1%)
1.179265s: initcall virtio_rng.virtio_rng_driver_init 0.000001s 0.0ms
(0.0%)
1.179266s:
1.179266s:
1.179266s: insmod virtio_console.ko 0.002286s 0.0ms (0.1%)
1.181551s: initcall virtio_console.init 0.000001s 0.0ms (0.0%)
1.181552s:
1.181552s:
1.181552s: insmod virtio_net.ko 0.002235s 0.0ms (0.1%)
1.182660s: initcall virtio_net.virtio_net_driver_init 0.001127s 0.0ms
(0.1%)
1.183787s:
1.183787s:
1.183787s: insmod virtio_scsi.ko 0.002216s 0.0ms (0.1%)
1.184886s: initcall virtio_scsi.init 0.001117s 0.0ms (0.1%)
1.186003s:
1.186003s:
1.186003s: insmod virtio_balloon.ko 0.002878s 0.0ms (0.2%)
1.187772s: initcall virtio_balloon.virtio_balloon_driver_init 0.000001s
0.0ms (0.0%)
1.187773s:
1.188881s:
1.188881s: insmod virtio_input.ko 0.001129s 0.0ms (0.1%)
1.188882s: initcall virtio_input.virtio_input_driver_init 0.001128s 0.0ms
(0.1%)
1.190010s:
1.190011s:
1.190011s: insmod virtio_mmio.ko 0.002251s 0.0ms (0.1%)
1.191145s: initcall virtio_mmio.virtio_mmio_init 0.001115s 0.0ms (0.1%)
1.192261s:
1.192261s:
1.192261s: insmod virtio_pci.ko 0.055208s 2.9ms (3.5%)
1.194090s: initcall virtio_pci.virtio_pci_driver_init 0.024959s 1.2ms
(1.6%)
1.219049s:
1.247469s:
1.247469s: insmod crc-ccitt.ko 0.001241s 0.1ms (0.1%)
1.248710s:
1.248710s: insmod crc-itu-t.ko 0.000001s 0.0ms (0.0%)
1.248711s:
1.248711s: insmod crc8.ko 0.001104s 0.0ms (0.1%)
1.249815s:
1.249815s: insmod libcrc32c.ko 0.001673s 0.0ms (0.1%)
1.251487s: initcall libcrc32c.libcrc32c_mod_init 0.000001s 0.0ms (0.0%)
1.251487s:
1.251488s:
1.267564s:
1.267564s: /init 0.274493s 11.2ms (17.4%) bash:overhead 0.012160s 0.9ms
(0.8%)
1.279723s:
1.436108s: initcall soundcore.init_soundcore 0.000002s 0.0ms (0.0%)
1.436109s:
1.438198s: initcall serio_raw.serio_raw_drv_init 0.000001s 0.0ms (0.0%)
1.438199s:
1.445275s: initcall joydev.joydev_init 0.000001s 0.0ms (0.0%)
1.445275s:
1.448343s: initcall pata_acpi.pacpi_pci_driver_init 0.002946s 0.4ms (0.2%)
1.449601s: initcall i2c_piix4.piix4_driver_init 0.004609s 2.2ms (0.3%)
1.451289s:
1.454211s:
1.462483s: initcall ghash_clmulni_intel.ghash_pclmulqdqni_mod_init
0.002943s 0.0ms (0.2%)
1.462602s: initcall snd.alsa_sound_init 0.001118s 1.1ms (0.1%)
1.463720s:
1.465426s:
1.471268s: initcall iosf_mbi.iosf_mbi_init 0.002571s 0.1ms (0.2%)
1.472288s: initcall ata_generic.ata_generic_pci_driver_init 0.000001s
0.0ms (0.0%)
1.472289s:
1.473838s:
1.481830s: initcall snd_timer.alsa_timer_init 0.002687s 0.7ms (0.2%)
1.484517s:
1.488991s: initcall intel_rapl.rapl_init 0.004131s 4.1ms (0.3%)
1.493123s:
1.505230s: initcall snd_pcm.alsa_pcm_init 0.000001s 0.0ms (0.0%)
1.505231s:
1.508350s: initcall snd_pcsp.pcsp_init 0.001130s 0.0ms (0.1%)
1.509479s:
1.542056s:
1.542056s: guestfsd 0.019108s 1.6ms (1.2%)
1.551271s: shutdown 0.028597s 0.1ms (1.8%)
1.561164s:
1.579867s:
--z4+8/lEcDcG5Ke9S--
Pino Toscano
2016-Mar-23 09:31 UTC
Re: [Libguestfs] [PATCH v3 02/11] appliance: Move /proc/cmdline checks earlier.
On Tuesday 22 March 2016 19:05:21 Richard W.M. Jones wrote:> --- > appliance/init | 30 +++++++++++++++--------------- > 1 file changed, 15 insertions(+), 15 deletions(-) > > diff --git a/appliance/init b/appliance/init > index f4f6333..5d43c71 100755 > --- a/appliance/init > +++ b/appliance/init > @@ -75,21 +75,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 > @@ -106,6 +91,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 upConsidering commit bb5d30ab2af5720775c63179afdec3ad9efd510d, these checks (excluding the guestfs_channel one) could be moved ever earlier than there, what do you think? I'd say between the mount of the filesystems and the static nodes setup. -- Pino Toscano
Pino Toscano
2016-Mar-23 09:32 UTC
Re: [Libguestfs] [PATCH v3 04/11] launch: direct: Remove dead code promising we were going to use virtio-console.
On Tuesday 22 March 2016 19:05:23 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. > ---LGTM. -- Pino Toscano
Pino Toscano
2016-Mar-23 09:39 UTC
Re: [Libguestfs] [PATCH v3 05/11] conn: Pretend to be a serial terminal, so sgabios doesn't hang.
On Tuesday 22 March 2016 19:05:24 Richard W.M. Jones wrote:> This tedious workaround avoids a 0.26 second pause when using sgabios > (the Serial Graphics Adapter). It's basically a workaround for buggy > code in sgabios, but much easier than fixing the assembler. > --- > src/conn-socket.c | 32 +++++++++++++++++++++++++++++++- > 1 file changed, 31 insertions(+), 1 deletion(-) > > diff --git a/src/conn-socket.c b/src/conn-socket.c > index 5b6b80e..13cb39b 100644 > --- a/src/conn-socket.c > +++ b/src/conn-socket.c > @@ -33,6 +33,8 @@ > #include <assert.h> > #include <libintl.h> > > +#include "ignore-value.h" > + > #include "guestfs.h" > #include "guestfs-internal.h" > > @@ -314,6 +316,9 @@ handle_log_message (guestfs_h *g, > { > CLEANUP_FREE char *buf = safe_malloc (g, BUFSIZ); > ssize_t n; > + const char dsr_request[] = "\033[6n"; > + const char dsr_reply[] = "\033[24;80R"; > + const char dsr_reply_padding[] = "\b\b\b\b\b\b\b\b\b\b\b\b\b\b\b\b"; > > /* Carried over from ancient proto.c code. The comment there was: > * > @@ -341,7 +346,32 @@ handle_log_message (guestfs_h *g, > return -1; > } > > - /* It's an actual log message, send it upwards. */ > + /* It's an actual log message. */ > + > + /* SGABIOS tries to query the "serial console" for its size using the > + * ISO/IEC 6429 Device Status Report (ESC [ 6 n). If it doesn't > + * read anything back, then it unfortunately hangs for 0.26 seconds. > + * Therefore we detect this situation and send back a fake console > + * size. > + */ > + if (memmem (buf, n, dsr_request, sizeof dsr_request - 1) != NULL) { > + /* Ignore any error from this write, as it's just an optimization. > + * We can't even be sure that console_sock is a socket or that > + * it's writable. > + */ > + ignore_value (write (conn->console_sock, dsr_reply, > + sizeof dsr_reply - 1)); > + /* Additionally, because of a bug in sgabios, it will still pause > + * unless you write at least 14 bytes, so we have to pad the > + * reply. We can't pad with NULs since sgabios's input routine > + * ignores these, so we have to use some other safe padding > + * characters. Backspace seems innocuous. > + */ > + ignore_value (write (conn->console_sock, dsr_reply_padding, > + sizeof dsr_reply_padding - 1)); > + } > + > + /* Send it upwards. */ > guestfs_int_log_message_callback (g, buf, n); > > return 1;If I read this correctly, the newly added memmem would be executed for every read data from the daemon socket: read_data -> handle_log_message -> memmem Wouldn't be better to limit it in accept_connection if possible? More than the overhead of memmem, I'm worried that this check might misdetect other kind of binary data coming from the daemon (e.g. download APIs) with the sgabios output. -- Pino Toscano
Pino Toscano
2016-Mar-23 09:40 UTC
Re: [Libguestfs] [PATCH v3 06/11] launch: Factor out earlyprintk from the command line.
On Tuesday 22 March 2016 19:05:25 Richard W.M. Jones wrote:> Just code motion. > > In theory we could also add earlyprintk=ttyS0,115200 on x86, but I > cannot get it to work. > ---LGTM. -- Pino Toscano
Pino Toscano
2016-Mar-23 09:51 UTC
Re: [Libguestfs] [PATCH v3 07/11] launch: direct: Don't run qemu -version.
On Tuesday 22 March 2016 19:05:26 Richard W.M. Jones wrote:> Dr. David Gilbert pointed out to me that the first line of the > qemu -help output includes the qemu version, so we don't need > to run qemu -version at all. > > This saves about 0.04s on the launch time when using the direct > backend. > ---LGTM. Thanks, -- Pino Toscano
Pino Toscano
2016-Mar-23 09:56 UTC
Re: [Libguestfs] [PATCH v3 09/11] launch: Remove guestfs_int_print_timestamped_message function.
On Tuesday 22 March 2016 19:05:28 Richard W.M. Jones wrote:> 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. > ---LGTM. -- Pino Toscano
Pino Toscano
2016-Mar-23 09:58 UTC
Re: [Libguestfs] [PATCH v3 10/11] launch: Add a virtio-rng device to the guest.
On Tuesday 22 March 2016 19:05:29 Richard W.M. Jones wrote:> --- > src/launch-direct.c | 11 +++++++++++ > src/launch-libvirt.c | 14 ++++++++++++++ > 2 files changed, 25 insertions(+)LGTM. -- Pino Toscano
Apparently Analagous Threads
- [PATCH v4 0/6] tests/qemu: Add program for tracing and analyzing boot times.
- [PATCH v2 0/7] tests/qemu: Add program for tracing and analyzing boot times.
- [PATCH] tests/qemu: Add program for tracing and analyzing boot times.
- 3.0.0-rc2: Xen: High amount of kernel "reserved" memory, about 33% in 256MB DOMU
- [PATCH RFC 0/4] Paravirtual spinlocks