Track live migration state unconditionally in logfiles to see how long a domU was suspended.
Depends on libxc.sr.superpage.patch

--- a/tools/libs/toollog/include/xentoollog.h
+++ b/tools/libs/toollog/include/xentoollog.h
@@ -133,6 +133,7 @@ const char *xtl_level_to_string(xentooll
 });
 
 
+#define XL_NO_SUSEINFO "XL_NO_SUSEINFO"
 #endif /* XENTOOLLOG_H */
 
 /*
--- a/tools/libxc/xc_domain.c
+++ b/tools/libxc/xc_domain.c
@@ -69,20 +69,28 @@ int xc_domain_cacheflush(xc_interface *x
 int xc_domain_pause(xc_interface *xch,
                     uint32_t domid)
 {
+    int ret;
     DECLARE_DOMCTL;
     domctl.cmd = XEN_DOMCTL_pausedomain;
     domctl.domain = domid;
-    return do_domctl(xch, &domctl);
+    ret = do_domctl(xch, &domctl);
+    if (getenv(XL_NO_SUSEINFO) == NULL)
+        SUSEINFO("domid %u: %s returned %d", domid, __func__, ret);
+    return ret;
 }
 
 
 int xc_domain_unpause(xc_interface *xch,
                       uint32_t domid)
 {
+    int ret;
     DECLARE_DOMCTL;
     domctl.cmd = XEN_DOMCTL_unpausedomain;
     domctl.domain = domid;
-    return do_domctl(xch, &domctl);
+    ret = do_domctl(xch, &domctl);
+    if (getenv(XL_NO_SUSEINFO) == NULL)
+        SUSEINFO("domid %u: %s returned %d", domid, __func__, ret);
+    return ret;
 }
 
 
--- a/tools/libxc/xc_private.h
+++ b/tools/libxc/xc_private.h
@@ -42,6 +42,15 @@
 
 #include <xen-tools/libs.h>
 
+/*
+ * Using loglevel ERROR to make sure the intended informational messages appear
+ * in libvirts libxl-driver.log
+ */
+#define SUSEINFO(_m, _a...)  do { int ERROR_errno = errno; \
+        xc_report(xch, xch->error_handler, XTL_ERROR, XC_ERROR_NONE, "SUSEINFO: " _m , ## _a ); \
+        errno = ERROR_errno; \
+        } while (0)
+
 #if defined(HAVE_VALGRIND_MEMCHECK_H) && !defined(NDEBUG) && !defined(__MINIOS__)
 /* Compile in Valgrind client requests? */
 #include <valgrind/memcheck.h>
--- a/tools/libxc/xc_resume.c
+++ b/tools/libxc/xc_resume.c
@@ -284,7 +284,10 @@ out:
  */
 int xc_domain_resume(xc_interface *xch, uint32_t domid, int fast)
 {
-    return (fast
+    int ret = (fast
             ? xc_domain_resume_cooperative(xch, domid)
             : xc_domain_resume_any(xch, domid));
+    if (getenv(XL_NO_SUSEINFO) == NULL)
+        SUSEINFO("domid %u: %s%s returned %d", domid, __func__, fast ? " fast" : "", ret);
+    return ret;
 }
--- a/tools/libxc/xc_sr_common.c
+++ b/tools/libxc/xc_sr_common.c
@@ -196,6 +196,65 @@ bool _xc_sr_bitmap_resize(struct xc_sr_b
     return true;
 }
 
+/* Write a two-character hex representation of 'byte' to digits[].
+   Pre-condition: sizeof(digits) >= 2 */
+static void byte_to_hex(char *digits, const uint8_t byte)
+{
+    uint8_t nybbel = byte >> 4;
+
+    if ( nybbel > 9 )
+        digits[0] = 'a' + nybbel-10;
+    else
+        digits[0] = '0' + nybbel;
+
+    nybbel = byte & 0x0f;
+    if ( nybbel > 9 )
+        digits[1] = 'a' + nybbel-10;
+    else
+        digits[1] = '0' + nybbel;
+}
+
+/* Convert an array of 16 unsigned bytes to a DCE/OSF formatted UUID
+   string.
+
+   Pre-condition: sizeof(dest) >= 37 */
+void sr_uuid_to_string(char *dest, const uint8_t *uuid)
+{
+    int i = 0;
+    char *p = dest;
+
+    for (; i < 4; i++ )
+    {
+        byte_to_hex(p, uuid[i]);
+        p += 2;
+    }
+    *p++ = '-';
+    for (; i < 6; i++ )
+    {
+        byte_to_hex(p, uuid[i]);
+        p += 2;
+    }
+    *p++ = '-';
+    for (; i < 8; i++ )
+    {
+        byte_to_hex(p, uuid[i]);
+        p += 2;
+    }
+    *p++ = '-';
+    for (; i < 10; i++ )
+    {
+        byte_to_hex(p, uuid[i]);
+        p += 2;
+    }
+    *p++ = '-';
+    for (; i < 16; i++ )
+    {
+        byte_to_hex(p, uuid[i]);
+        p += 2;
+    }
+    *p = '\0';
+}
+
 /*
  * Local variables:
  * mode: C
--- a/tools/libxc/xc_sr_common.h
+++ b/tools/libxc/xc_sr_common.h
@@ -195,6 +195,7 @@ struct xc_sr_context
     int fd;
 
     xc_dominfo_t dominfo;
+    char uuid[16*2+4+1];
 
     union /* Common save or restore data. */
     {
@@ -427,6 +428,8 @@ static inline int pfn_set_populated(stru
     return 0;
 }
 
+extern void sr_uuid_to_string(char *dest, const uint8_t *uuid);
+
 struct xc_sr_record
 {
     uint32_t type;
--- a/tools/libxc/xc_sr_restore.c
+++ b/tools/libxc/xc_sr_restore.c
@@ -608,6 +608,7 @@ static int restore(struct xc_sr_context
     struct xc_sr_record rec;
     int rc, saved_rc = 0, saved_errno = 0;
 
+    SUSEINFO("domid %u: %s %s start", ctx->domid, ctx->uuid, __func__);
     IPRINTF("Restoring domain");
 
     rc = setup(ctx);
@@ -684,6 +685,7 @@ static int restore(struct xc_sr_context
     PERROR("Restore failed");
 
  done:
+    SUSEINFO("domid %u: %s done", ctx->domid, __func__);
     cleanup(ctx);
 
     if ( saved_rc )
@@ -748,6 +750,7 @@ int xc_domain_restore(xc_interface *xch,
     }
 
     ctx.domid = dom;
+    sr_uuid_to_string(ctx.uuid, ctx.dominfo.handle);
 
     if ( read_headers(&ctx) )
         return -1;
--- a/tools/libxc/xc_sr_save.c
+++ b/tools/libxc/xc_sr_save.c
@@ -852,6 +852,7 @@ static int save(struct xc_sr_context *ct
     xc_interface *xch = ctx->xch;
     int rc, saved_rc = 0, saved_errno = 0;
 
+    SUSEINFO("domid %u: %s %s start, %lu pages allocated", ctx->domid, ctx->uuid, __func__, ctx->dominfo.nr_pages);
     IPRINTF("Saving domain %d, type %s",
             ctx->domid, dhdr_type_to_str(guest_type));
 
@@ -964,6 +965,7 @@ static int save(struct xc_sr_context *ct
     PERROR("Save failed");
 
  done:
+    SUSEINFO("domid %u: %s done", ctx->domid, __func__);
     cleanup(ctx);
 
     if ( saved_rc )
@@ -1019,6 +1021,10 @@ static int suse_precopy_policy(struct pr
         goto out;
     }
     /* Keep going */
+    if ( stats.dirty_count >= 0 )
+        SUSEINFO("domid %u: dirty pages %ld after iteration %u/%u",
+                suse_flags.ctx->domid,
+                suse_flags.dirty_count, stats.iteration, suse_flags.max_iters);
     return XGS_POLICY_CONTINUE_PRECOPY;
 
 out:
@@ -1032,6 +1038,8 @@ out:
         return XGS_POLICY_ABORT;
     }
 suspend:
+    SUSEINFO("domid %u: suspending, %ld remaining dirty pages prior final transit",
+            suse_flags.ctx->domid, suse_flags.dirty_count);
     return XGS_POLICY_STOP_AND_COPY;
 }
 
@@ -1095,6 +1103,7 @@ int xc_domain_save_suse(xc_interface *xc
     }
 
     ctx.domid = dom;
+    sr_uuid_to_string(ctx.uuid, ctx.dominfo.handle);
 
     if ( ctx.dominfo.hvm )
     {
--- a/tools/xl/xl.c
+++ b/tools/xl/xl.c
@@ -388,6 +388,8 @@ int main(int argc, char **argv)
         (progress_use_cr ? XTL_STDIOSTREAM_PROGRESS_USE_CR : 0));
     if (!logger) exit(EXIT_FAILURE);
 
+    /* Provide context to libxl and libxc: no SUSEINFO() from xl */
+    setenv(XL_NO_SUSEINFO, "1", 0);
     xl_ctx_alloc();
 
     atexit(xl_ctx_free);
