xen/libxc-sr-track-migration-time.patch

From: Olaf Hering <olaf@aepfle.de>
Date: Thu, 4 Feb 2021 20:33:53 +0100
Subject: libxc sr track migration time

Track live migration state unconditionally in logfiles to see how long a domU was suspended.

Signed-off-by: Olaf Hering <olaf@aepfle.de>
---
 tools/include/xentoollog.h       |  1 +
 tools/libs/ctrl/xc_domain.c      | 12 +++++--
 tools/libs/ctrl/xc_private.h     |  9 +++++
 tools/libs/guest/xg_resume.c     |  5 ++-
 tools/libs/guest/xg_sr_common.c  | 59 ++++++++++++++++++++++++++++++++
 tools/libs/guest/xg_sr_common.h  |  3 ++
 tools/libs/guest/xg_sr_restore.c |  3 ++
 tools/libs/guest/xg_sr_save.c    |  6 +++-
 tools/xl/xl.c                    |  2 ++
 9 files changed, 96 insertions(+), 4 deletions(-)

--- a/tools/include/xentoollog.h
+++ b/tools/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/libs/ctrl/xc_domain.c
+++ b/tools/libs/ctrl/xc_domain.c
@@ -66,20 +66,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/libs/ctrl/xc_private.h
+++ b/tools/libs/ctrl/xc_private.h
@@ -42,6 +42,15 @@
 
 #include <xen-tools/common-macros.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/libs/guest/xg_resume.c
+++ b/tools/libs/guest/xg_resume.c
@@ -259,7 +259,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/libs/guest/xg_sr_common.c
+++ b/tools/libs/guest/xg_sr_common.c
@@ -163,6 +163,65 @@ static void __attribute__((unused)) buil
     BUILD_BUG_ON(sizeof(struct xc_sr_rec_hvm_params)        != 8);
 }
 
+/* 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';
+}
+
 /*
  * Expand the tracking structures as needed.
  * To avoid realloc()ing too excessively, the size increased to the nearest
--- a/tools/libs/guest/xg_sr_common.h
+++ b/tools/libs/guest/xg_sr_common.h
@@ -294,6 +294,7 @@ struct xc_sr_context
     xc_stream_type_t stream_type;
 
     xc_domaininfo_t dominfo;
+    char uuid[16*2+4+1];
 
     union /* Common save or restore data. */
     {
@@ -505,6 +506,8 @@ extern struct xc_sr_save_ops save_ops_x8
 extern struct xc_sr_restore_ops restore_ops_x86_pv;
 extern struct xc_sr_restore_ops restore_ops_x86_hvm;
 
+extern void sr_uuid_to_string(char *dest, const uint8_t *uuid);
+
 struct xc_sr_record
 {
     uint32_t type;
--- a/tools/libs/guest/xg_sr_restore.c
+++ b/tools/libs/guest/xg_sr_restore.c
@@ -871,6 +871,8 @@ static int restore(struct xc_sr_context
     struct xc_sr_rhdr rhdr;
     int rc, saved_rc = 0, saved_errno = 0;
 
+    SUSEINFO("domid %u: %s %s start", ctx->domid, ctx->uuid, __func__);
+    DPRINTF("domid %u: max_pages %lx tot_pages %lx p2m_size %lx", ctx->domid, ctx->restore.max_pages, ctx->restore.tot_pages, ctx->restore.p2m_size);
     IPRINTF("Restoring domain");
 
     rc = setup(ctx);
@@ -946,6 +948,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 )
@@ -1011,6 +1014,7 @@ int xc_domain_restore(xc_interface *xch,
             io_fd, dom, hvm, stream_type);
 
     ctx.domid = dom;
+    sr_uuid_to_string(ctx.uuid, ctx.dominfo.handle);
 
     if ( read_headers(&ctx) )
         return -1;
--- a/tools/libs/guest/xg_sr_save.c
+++ b/tools/libs/guest/xg_sr_save.c
@@ -353,7 +353,7 @@ static void show_transfer_rate(struct xc
     MiB_sec = (ctx->save.pages_sent * PAGE_SIZE * 1000U) / ms / (1024U*1024U);
 
     errno = 0;
-    IPRINTF("%s: %zu bytes + %zu pages in %ld.%09ld sec, %zu MiB/sec", __func__,
+    SUSEINFO("domid %u: %zu bytes + %zu pages in %ld.%09ld sec, %zu MiB/sec", ctx->domid,
             ctx->save.overhead_sent, ctx->save.pages_sent,
             diff.tv_sec, diff.tv_nsec, MiB_sec);
 }
@@ -875,13 +875,16 @@ static int save(struct xc_sr_context *ct
 {
     xc_interface *xch = ctx->xch;
     int rc, saved_rc = 0, saved_errno = 0;
+    unsigned long tot_pages = ctx->dominfo.tot_pages;
 
+    SUSEINFO("domid %u: %s %s start, %lu pages allocated", ctx->domid, ctx->uuid, __func__, tot_pages);
     IPRINTF("Saving domain %d, type %s",
             ctx->domid, dhdr_type_to_str(guest_type));
 
     rc = setup(ctx);
     if ( rc )
         goto err;
+    SUSEINFO("domid %u: p2m_size %lx", ctx->domid, ctx->save.p2m_size);
 
     xc_report_progress_single(xch, "Start of stream");
 
@@ -995,6 +998,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 )
@@ -1054,6 +1058,7 @@ int xc_domain_save(xc_interface *xch, in
             io_fd, dom, flags, hvm);
 
     ctx.domid = dom;
+    sr_uuid_to_string(ctx.uuid, ctx.dominfo.handle);
 
     if ( hvm )
     {
--- a/tools/xl/xl.c
+++ b/tools/xl/xl.c
@@ -424,6 +424,8 @@ int main(int argc, char **argv)
     logger = xtl_createlogger_stdiostream(stderr, minmsglevel, xtl_flags);
     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);