Print timestamped messages during appliance launch.

[libguestfs.git] / src / guestfs.c

diff --git a/src/guestfs.c b/src/guestfs.c
index f7df27e..41872d3 100644 (file)
--- 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>
@@ -107,7 +109,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. */
 
@@ -173,10 +176,10 @@ guestfs_create (void)
   g->recovery_proc = 1;
 
   str = getenv ("LIBGUESTFS_DEBUG");
-  g->verbose = str != NULL && strcmp (str, "1") == 0;
+  g->verbose = str != NULL && STREQ (str, "1");
 
   str = getenv ("LIBGUESTFS_TRACE");
-  g->trace = str != NULL && strcmp (str, "1") == 0;
+  g->trace = str != NULL && STREQ (str, "1");
 
   str = getenv ("LIBGUESTFS_PATH");
   g->path = str != NULL ? strdup (str) : strdup (GUESTFS_DEFAULT_PATH);
@@ -722,13 +725,13 @@ guestfs__config (guestfs_h *g,
   /* A bit fascist, but the user will probably break the extra
    * parameters that we add if they try to set any of these.
    */
-  if (strcmp (qemu_param, "-kernel") == 0 ||
-      strcmp (qemu_param, "-initrd") == 0 ||
-      strcmp (qemu_param, "-nographic") == 0 ||
-      strcmp (qemu_param, "-serial") == 0 ||
-      strcmp (qemu_param, "-full-screen") == 0 ||
-      strcmp (qemu_param, "-std-vga") == 0 ||
-      strcmp (qemu_param, "-vnc") == 0) {
+  if (STREQ (qemu_param, "-kernel") ||
+      STREQ (qemu_param, "-initrd") ||
+      STREQ (qemu_param, "-nographic") ||
+      STREQ (qemu_param, "-serial") ||
+      STREQ (qemu_param, "-full-screen") ||
+      STREQ (qemu_param, "-std-vga") ||
+      STREQ (qemu_param, "-vnc")) {
     error (g, _("guestfs_config: parameter '%s' isn't allowed"), qemu_param);
     return -1;
   }
@@ -849,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);
@@ -876,6 +880,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
@@ -995,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;
@@ -1055,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");
@@ -1157,6 +1170,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. */
@@ -1263,9 +1277,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]);
@@ -1388,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
@@ -1413,7 +1427,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) {
@@ -1466,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);
@@ -1487,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
@@ -1839,7 +1895,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);