Libguestfs - Nov 2009 - [PATCH 0/3] Timestamp messages during guestfs_launch

I found this useful when looking at where the time goes
during guestfs_launch, and in fact using this I've reduced
the launch time from around 12 seconds on my machine to
7 or 8 seconds.

Rich.

-- 
Richard Jones, Virtualization Group, Red Hat http://people.redhat.com/~rjones
New in Fedora 11: Fedora Windows cross-compiler. Compile Windows
programs, test, and build Windows installers. Over 70 libraries supprt'd
http://fedoraproject.org/wiki/MinGW http://www.annexia.org/fedora_mingw

With this patch, kernel boot messages get prefixed with a timestamp
counting from the boot, although in fact early messages (before kernel
command line parsing) don't get timestamped.

The output looks something like this:

[    0.003999] Calibrating delay loop (skipped) preset value.. 5866.95 BogoMIPS
(lpj=2933478)
[    0.007546] Security Framework initialized
[    0.009056] SELinux:  Disabled at boot.
[    0.012702] Dentry cache hash table entries: 65536 (order: 7, 524288 bytes)
[    0.016942] Inode-cache hash table entries: 32768 (order: 6, 262144 bytes)
[    0.020233] Mount-cache hash table entries: 256

Of course you only see this when the verbose flag is set.

Rich.

-- 
Richard Jones, Virtualization Group, Red Hat http://people.redhat.com/~rjones
virt-top is 'top' for virtual machines.  Tiny program with many
powerful monitoring features, net stats, disk stats, logging, etc.
http://et.redhat.com/~rjones/virt-top
-------------- next part --------------
>From 8ddbb6c236b416f59f03a673a965e429bfda958f Mon Sep 17 00:00:00 2001
From: Richard Jones <rjones at redhat.com>
Date: Mon, 9 Nov 2009 14:15:43 +0000
Subject: [PATCH 1/3] appliance: Prefix kernel messages with timestamp.

---
 src/guestfs.c |    1 +
 1 files changed, 1 insertions(+), 0 deletions(-)

diff --git a/src/guestfs.c b/src/guestfs.c
index f7df27e..896d8a7 100644
--- a/src/guestfs.c
+++ b/src/guestfs.c
@@ -1157,6 +1157,7 @@ guestfs__launch (guestfs_h *g)
     "udevtimeout=300 " /* good for very slow systems (RHBZ#480319) */
\
     "noapic "          /* workaround for RHBZ#502058 - ok if not SMP
*/ \
     "acpi=off "        /* we don't need ACPI, turn it off */		\
+    "printk.time=1 "   /* display timestamp before kernel messages */
\
     "cgroup_disable=memory " /* saves us about 5 MB of RAM */
 
     /* Linux kernel command line. */
-- 
1.6.5.rc2

-- 
Richard Jones, Virtualization Group, Red Hat http://people.redhat.com/~rjones
virt-p2v converts physical machines to virtual machines.  Boot with a
live CD or over the network (PXE) and turn machines into Xen guests.
http://et.redhat.com/~rjones/virt-p2v
-------------- next part --------------
>From e3104fb2cab4efdd980d39ab378e88d3238cbb2b Mon Sep 17 00:00:00 2001
From: Richard Jones <rjones at redhat.com>
Date: Mon, 9 Nov 2009 14:16:21 +0000
Subject: [PATCH 2/3] Record time of guest launch.

The guest handle field start_t was previously used (when we
had the wait_ready call), but had fallen into disuse.  Note
that it could never be accessed through the API.

Rename this field as launch_t, convert it to a timeval, and
use it to measure the time since guestfs_launch was called
so that we can start profiling guest launch.
---
 src/guestfs.c |   13 +++++++------
 1 files changed, 7 insertions(+), 6 deletions(-)

diff --git a/src/guestfs.c b/src/guestfs.c
index 896d8a7..cb103d4 100644
--- a/src/guestfs.c
+++ b/src/guestfs.c
@@ -107,7 +107,8 @@ struct guestfs_h
   int sock;			/* Daemon communications socket. */
   pid_t pid;			/* Qemu PID. */
   pid_t recoverypid;		/* Recovery process PID. */
-  time_t start_t;		/* The time when we started qemu. */
+
+  struct timeval launch_t;      /* The time that we called guestfs_launch. */
 
   char *tmpdir;			/* Temporary directory containing socket. */
 
@@ -876,6 +877,9 @@ guestfs__launch (guestfs_h *g)
   char unixsock[256];
   struct sockaddr_un addr;
 
+  /* Start the clock ... */
+  gettimeofday (&g->launch_t, NULL);
+
 #ifdef P_tmpdir
   tmpdir = P_tmpdir;
 #else
@@ -1264,9 +1268,6 @@ guestfs__launch (guestfs_h *g)
     g->recoverypid = r;
   }
 
-  /* Start the clock ... */
-  time (&g->start_t);
-
   if (!g->direct) {
     /* Close the other ends of the pipe. */
     close (wfd[0]);
@@ -1414,7 +1415,7 @@ guestfs__launch (guestfs_h *g)
   g->fd[1] = -1;
   g->pid = 0;
   g->recoverypid = 0;
-  g->start_t = 0;
+  memset (&g->launch_t, 0, sizeof g->launch_t);
 
  cleanup0:
   if (g->sock >= 0) {
@@ -1840,7 +1841,7 @@ child_cleanup (guestfs_h *g)
   g->sock = -1;
   g->pid = 0;
   g->recoverypid = 0;
-  g->start_t = 0;
+  memset (&g->launch_t, 0, sizeof g->launch_t);
   g->state = CONFIG;
   if (g->subprocess_quit_cb)
     g->subprocess_quit_cb (g, g->subprocess_quit_cb_data);
-- 
1.6.5.rc2

The timestamped messages look like this:

[00000ms] begin building supermin appliance
[02295ms] finished building supermin appliance
[02295ms] begin testing qemu features
[02313ms] finished testing qemu features

Note that the time to build the supermin appliance has somehow grown
from a fraction of a second to 2 seconds!  That's a separate issue
that needs to be investigated.

Rich.

-- 
Richard Jones, Virtualization Group, Red Hat http://people.redhat.com/~rjones
virt-p2v converts physical machines to virtual machines.  Boot with a
live CD or over the network (PXE) and turn machines into Xen guests.
http://et.redhat.com/~rjones/virt-p2v
-------------- next part --------------
>From 8f59622b344b07558de018f512f58170838b6fed Mon Sep 17 00:00:00 2001
From: Richard Jones <rjones at redhat.com>
Date: Mon, 9 Nov 2009 14:42:55 +0000
Subject: [PATCH 3/3] Print timestamped messages during appliance launch.

In verbose mode, print timestamped messages during guestfs_launch
so we can see how long each step takes.
---
 src/guestfs.c |   54 ++++++++++++++++++++++++++++++++++++++++++++++++++++++
 1 files changed, 54 insertions(+), 0 deletions(-)

diff --git a/src/guestfs.c b/src/guestfs.c
index cb103d4..2eb5546 100644
--- a/src/guestfs.c
+++ b/src/guestfs.c
@@ -24,6 +24,8 @@
 #include <stdlib.h>
 #include <stdarg.h>
 #include <stddef.h>
+#include <stdint.h>
+#include <inttypes.h>
 #include <unistd.h>
 #include <string.h>
 #include <fcntl.h>
@@ -850,6 +852,7 @@ dir_contains_files (const char *dir, ...)
   return 1;
 }
 
+static void print_timestamped_message (guestfs_h *g, const char *fs, ...);
 static int build_supermin_appliance (guestfs_h *g, const char *path, char
**kernel, char **initrd);
 static int test_qemu (guestfs_h *g);
 static int qemu_supports (guestfs_h *g, const char *option);
@@ -999,6 +1002,9 @@ guestfs__launch (guestfs_h *g)
     goto cleanup0;
   }
 
+  if (g->verbose)
+    print_timestamped_message (g, "begin testing qemu features");
+
   /* Get qemu help text and version. */
   if (test_qemu (g) == -1)
     goto cleanup0;
@@ -1059,6 +1065,9 @@ guestfs__launch (guestfs_h *g)
     }
   }
 
+  if (g->verbose)
+    print_timestamped_message (g, "finished testing qemu features");
+
   r = fork ();
   if (r == -1) {
     perrorf (g, "fork");
@@ -1390,6 +1399,9 @@ guestfs__launch (guestfs_h *g)
     goto cleanup1;
   }
 
+  if (g->verbose)
+    print_timestamped_message (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
    * it because the caller is probably expecting to be able to send
@@ -1468,6 +1480,9 @@ build_supermin_appliance (guestfs_h *g, const char *path,
   char cmd[4096];
   int r, len;
 
+  if (g->verbose)
+    print_timestamped_message (g, "begin building supermin
appliance");
+
   len = strlen (g->tmpdir);
   *kernel = safe_malloc (g, len + 8);
   snprintf (*kernel, len+8, "%s/kernel", g->tmpdir);
@@ -1489,9 +1504,48 @@ build_supermin_appliance (guestfs_h *g, const char *path,
     return -1;
   }
 
+  if (g->verbose)
+    print_timestamped_message (g, "finished building supermin
appliance");
+
   return 0;
 }
 
+/* Compute Y - X and return the result in milliseconds.
+ * Approximately the same as this code:
+ * http://www.mpp.mpg.de/~huber/util/timevaldiff.c
+ */
+static int64_t
+timeval_diff (const struct timeval *x, const struct timeval *y)
+{
+  int64_t msec;
+
+  msec = (y->tv_sec - x->tv_sec) * 1000;
+  msec += (y->tv_usec - x->tv_usec) / 1000;
+  return msec;
+}
+
+static void
+print_timestamped_message (guestfs_h *g, const char *fs, ...)
+{
+  va_list args;
+  char *msg;
+  int err;
+  struct timeval tv, diff;
+
+  va_start (args, fs);
+  err = vasprintf (&msg, fs, args);
+  va_end (args);
+
+  if (err < 0) return;
+
+  gettimeofday (&tv, NULL);
+  
+  fprintf (stderr, "[%05" PRIi64 "ms] %s\n",
+           timeval_diff (&g->launch_t, &tv), msg);
+
+  free (msg);
+}
+
 static int read_all (guestfs_h *g, FILE *fp, char **ret);
 
 /* Test qemu binary (or wrapper) runs, and do 'qemu -help' and
-- 
1.6.5.rc2