[PATCH 0 of 7] various changes for xm migrate logging

[PATCH 0 of 7] various changes for xm migrate logging

[Olaf Hering]

Changes:
tools/xc: fix logic error in stdiostream_progress
tools/xc: handle tty output differently in stdiostream_progress
tools/xc: turn XCFLAGS_* into shifts
tools/xc: restore logging in xc_save
tools/xc: log pid in xc_save/xc_restore output
xl: correct help text of xl migrate
libxl: pass debug flag down to libxl_domain_suspend

 docs/man/xl.pod.1               |    4 ++++
 tools/libxc/xc_domain_restore.c |    6 ++++--
 tools/libxc/xc_domain_save.c    |    4 +++-
 tools/libxc/xenguest.h          |   11 ++++++-----
 tools/libxc/xtl_logger_stdio.c  |   24 +++++++++++++++++++++---
 tools/libxl/xl_cmdimpl.c        |   21 ++++++++++++++-------
 tools/libxl/xl_cmdtable.c       |    5 +++--
 tools/xcutils/xc_restore.c      |    9 +++++++--
 tools/xcutils/xc_save.c         |   15 ++++++++++-----
 9 files changed, 72 insertions(+), 27 deletions(-)

[PATCH 1 of 7] tools/xc: fix logic error in stdiostream_progress

[Olaf Hering]

# HG changeset patch
# User Olaf Hering <olaf@aepfle.de>
# Date 1360769518 -3600
# Node ID d13841ebeb080e3dea9b865d79e194e81d6aa2db
# Parent  63594ce1708ffb1269cd124c3a864485eeba1736
tools/xc: fix logic error in stdiostream_progress

Setting XTL_STDIOSTREAM_HIDE_PROGRESS should disable progress reporting.

Signed-off-by: Olaf Hering <olaf@aepfle.de>

diff -r 63594ce1708f -r d13841ebeb08 tools/libxc/xtl_logger_stdio.c
--- a/tools/libxc/xtl_logger_stdio.c
+++ b/tools/libxc/xtl_logger_stdio.c
@@ -89,7 +89,7 @@ static void stdiostream_progress(struct 
     int newpel, extra_erase;
     xentoollog_level this_level;
 
-    if (!(lg->flags & XTL_STDIOSTREAM_HIDE_PROGRESS))
+    if (lg->flags & XTL_STDIOSTREAM_HIDE_PROGRESS)
         return;
 
     if (percent < lg->progress_last_percent) {

Re: [PATCH 1 of 7] tools/xc: fix logic error in stdiostream_progress

[Ian Jackson]

Olaf Hering writes ("[Xen-devel] [PATCH 1 of 7] tools/xc: fix logic error in stdiostream_progress"):
> tools/xc: fix logic error in stdiostream_progress

Applied, thanks.

Ian.

[PATCH 2 of 7] tools/xc: handle tty output differently in stdiostream_progress

[Olaf Hering]

# HG changeset patch
# User Olaf Hering <olaf@aepfle.de>
# Date 1360769525 -3600
# Node ID 1518e1b1341a56e8ea52c7fbaa56a7c062e559a5
# Parent  d13841ebeb080e3dea9b865d79e194e81d6aa2db
tools/xc: handle tty output differently in stdiostream_progress

If the output goes to a tty, rewind the cursor and print everything in a
single line as it was done up to now. If the output goes to a file or
pipe print a newline after each progress output. This will fix logging
of progress messages from xc_save to xend.log.

To support XTL_STDIOSTREAM_SHOW_PID or XTL_STDIOSTREAM_SHOW_DATE print
the output via vmessage if the output is not a tty.

Signed-off-by: Olaf Hering <olaf@aepfle.de>

diff -r d13841ebeb08 -r 1518e1b1341a tools/libxc/xtl_logger_stdio.c
--- a/tools/libxc/xtl_logger_stdio.c
+++ b/tools/libxc/xtl_logger_stdio.c
@@ -81,6 +81,17 @@ static void stdiostream_vmessage(xentool
     fflush(lg->f);
 }
 
+static void stdiostream_message(struct xentoollog_logger *logger_in,
+                                xentoollog_level level,
+                                const char *context,
+                                const char *format, ...)
+{
+    va_list al;
+    va_start(al,format);
+    stdiostream_vmessage(logger_in, level, -1, context, format, al);
+    va_end(al);
+}
+
 static void stdiostream_progress(struct xentoollog_logger *logger_in,
                                  const char *context,
                                  const char *doing_what, int percent,
@@ -105,11 +116,18 @@ static void stdiostream_progress(struct 
     if (this_level < lg->min_level)
         return;
 
+    lg->progress_last_percent = percent;
+
+    if (isatty(fileno(lg->f)) <= 0) {
+        stdiostream_message(logger_in, this_level, context,
+                            "%s: %lu/%lu  %3d%%",
+                            doing_what, done, total, percent);
+        return;
+    }
+
     if (lg->progress_erase_len)
         putc('\r', lg->f);
 
-    lg->progress_last_percent = percent;
-
     newpel = fprintf(lg->f, "%s%s" "%s: %lu/%lu  %3d%%%s",
                      context?context:"", context?": ":"",
                      doing_what, done, total, percent,

Re: [PATCH 2 of 7] tools/xc: handle tty output differently in stdiostream_progress

[Ian Jackson]

Olaf Hering writes ("[Xen-devel] [PATCH 2 of 7] tools/xc: handle tty output differently in stdiostream_progress"):
> tools/xc: handle tty output differently in stdiostream_progress
> 
> If the output goes to a tty, rewind the cursor and print everything in a
> single line as it was done up to now. If the output goes to a file or
> pipe print a newline after each progress output. This will fix logging
> of progress messages from xc_save to xend.log.
> 
> To support XTL_STDIOSTREAM_SHOW_PID or XTL_STDIOSTREAM_SHOW_DATE print
> the output via vmessage if the output is not a tty.

Can we lift the call to isatty out of the loop by calling it at
setup ?

Calling it continually is undesirable not really for performance
reasons but because it always trashes errno and because it will make
strace output more noisy.

Thanks,
Ian.

Re: [PATCH 2 of 7] tools/xc: handle tty output differently in stdiostream_progress

[Olaf Hering]

On Fri, Feb 22, Ian Jackson wrote:

> Olaf Hering writes ("[Xen-devel] [PATCH 2 of 7] tools/xc: handle tty output differently in stdiostream_progress"):
> > tools/xc: handle tty output differently in stdiostream_progress
> > 
> > If the output goes to a tty, rewind the cursor and print everything in a
> > single line as it was done up to now. If the output goes to a file or
> > pipe print a newline after each progress output. This will fix logging
> > of progress messages from xc_save to xend.log.
> > 
> > To support XTL_STDIOSTREAM_SHOW_PID or XTL_STDIOSTREAM_SHOW_DATE print
> > the output via vmessage if the output is not a tty.
> 
> Can we lift the call to isatty out of the loop by calling it at
> setup ?
> 
> Calling it continually is undesirable not really for performance
> reasons but because it always trashes errno and because it will make
> strace output more noisy.

Ok, I will prepare a patch. I think that series is already applied.

Olaf

Re: [PATCH 2 of 7] tools/xc: handle tty output differently in stdiostream_progress

[Ian Jackson]

Ian Jackson writes ("Re: [Xen-devel] [PATCH 2 of 7] tools/xc: handle tty output> Can we lift the call to isatty out of the loop by calling it at
> setup ?
> 
> Calling it continually is undesirable not really for performance
> reasons but because it always trashes errno and because it will make
> strace output more noisy.

Never mind, I see Ian Campbell has applied this already.

Ian.

[PATCH 3 of 7] tools/xc: turn XCFLAGS_* into shifts

[Olaf Hering]

# HG changeset patch
# User Olaf Hering <olaf@aepfle.de>
# Date 1360769530 -3600
# Node ID 8958163de4026b150a2fbb8fd7fa496941e22d0d
# Parent  1518e1b1341a56e8ea52c7fbaa56a7c062e559a5
tools/xc: turn XCFLAGS_* into shifts

to make it clear that these are bits and to make it easier to use in
xend code.

Signed-off-by: Olaf Hering <olaf@aepfle.de>

diff -r 1518e1b1341a -r 8958163de402 tools/libxc/xenguest.h
--- a/tools/libxc/xenguest.h
+++ b/tools/libxc/xenguest.h
@@ -23,11 +23,12 @@
 #ifndef XENGUEST_H
 #define XENGUEST_H
 
-#define XCFLAGS_LIVE      1
-#define XCFLAGS_DEBUG     2
-#define XCFLAGS_HVM       4
-#define XCFLAGS_STDVGA    8
-#define XCFLAGS_CHECKPOINT_COMPRESS    16
+#define XCFLAGS_LIVE      (1 << 0)
+#define XCFLAGS_DEBUG     (1 << 1)
+#define XCFLAGS_HVM       (1 << 2)
+#define XCFLAGS_STDVGA    (1 << 3)
+#define XCFLAGS_CHECKPOINT_COMPRESS    (1 << 4)
+
 #define X86_64_B_SIZE   64 
 #define X86_32_B_SIZE   32

[PATCH 4 of 7] tools/xc: restore logging in xc_save

[Olaf Hering]

# HG changeset patch
# User Olaf Hering <olaf@aepfle.de>
# Date 1360769534 -3600
# Node ID 0e6a41e1ee36237ba130959dc3d2a3bd44104eb0
# Parent  8958163de4026b150a2fbb8fd7fa496941e22d0d
tools/xc: restore logging in xc_save

Prior to xen-4.1 the helper xc_save would print some progress during
migration. With the new xc_interface_open API no more messages were
printed because no logger was configured.

Restore previous behaviour by providing a logger. The progress in
xc_domain_save will be disabled because it generates alot of output and
fills up xend.log quickly.

Signed-off-by: Olaf Hering <olaf@aepfle.de>

diff -r 8958163de402 -r 0e6a41e1ee36 tools/xcutils/xc_save.c
--- a/tools/xcutils/xc_save.c
+++ b/tools/xcutils/xc_save.c
@@ -166,17 +166,15 @@ static int switch_qemu_logdirty(int domi
 int
 main(int argc, char **argv)
 {
-    unsigned int maxit, max_f;
+    unsigned int maxit, max_f, lflags;
     int io_fd, ret, port;
     struct save_callbacks callbacks;
+    xentoollog_level lvl;
+    xentoollog_logger *l;
 
     if (argc != 6)
         errx(1, "usage: %s iofd domid maxit maxf flags", argv[0]);
 
-    si.xch = xc_interface_open(0,0,0);
-    if (!si.xch)
-        errx(1, "failed to open control interface");
-
     io_fd = atoi(argv[1]);
     si.domid = atoi(argv[2]);
     maxit = atoi(argv[3]);
@@ -185,6 +183,13 @@ main(int argc, char **argv)
 
     si.suspend_evtchn = -1;
 
+    lvl = si.flags & XCFLAGS_DEBUG ? XTL_DEBUG: XTL_DETAIL;
+    lflags = XTL_STDIOSTREAM_HIDE_PROGRESS;
+    l = (xentoollog_logger *)xtl_createlogger_stdiostream(stderr, lvl, lflags);
+    si.xch = xc_interface_open(l, 0, 0);
+    if (!si.xch)
+        errx(1, "failed to open control interface");
+
     si.xce = xc_evtchn_open(NULL, 0);
     if (si.xce == NULL)
         warnx("failed to open event channel handle");

[PATCH 5 of 7] tools/xc: log pid in xc_save/xc_restore output

[Olaf Hering]

# HG changeset patch
# User Olaf Hering <olaf@aepfle.de>
# Date 1360770273 -3600
# Node ID 101ba725b5a58323c34a1944d7d24f600aaf48d5
# Parent  0e6a41e1ee36237ba130959dc3d2a3bd44104eb0
tools/xc: log pid in xc_save/xc_restore output

If several migrations log their output to xend.log its not clear which
line belongs to a which guest. Print entry/exit of xc_save and
xc_restore and also request to print pid with each log call.

Signed-off-by: Olaf Hering <olaf@aepfle.de>

diff -r 0e6a41e1ee36 -r 101ba725b5a5 tools/libxc/xc_domain_restore.c
--- a/tools/libxc/xc_domain_restore.c
+++ b/tools/libxc/xc_domain_restore.c
@@ -1456,6 +1456,8 @@ int xc_domain_restore(xc_interface *xch,
     struct restore_ctx *ctx = &_ctx;
     struct domain_info_context *dinfo = &ctx->dinfo;
 
+    DPRINTF("%s: starting restore of new domid %u", __func__, dom);
+
     pagebuf_init(&pagebuf);
     memset(&tailbuf, 0, sizeof(tailbuf));
     tailbuf.ishvm = hvm;
@@ -1485,7 +1487,7 @@ int xc_domain_restore(xc_interface *xch,
         PERROR("read: p2m_size");
         goto out;
     }
-    DPRINTF("xc_domain_restore start: p2m_size = %lx\n", dinfo->p2m_size);
+    DPRINTF("%s: p2m_size = %lx\n", __func__, dinfo->p2m_size);
 
     if ( !get_platform_info(xch, dom,
                             &ctx->max_mfn, &ctx->hvirt_start, &ctx->pt_levels, &dinfo->guest_width) )
@@ -2300,7 +2302,7 @@ int xc_domain_restore(xc_interface *xch,
 
     fcntl(io_fd, F_SETFL, orig_io_fd_flags);
 
-    DPRINTF("Restore exit with rc=%d\n", rc);
+    DPRINTF("Restore exit of domid %u with rc=%d\n", dom, rc);
 
     return rc;
 }
diff -r 0e6a41e1ee36 -r 101ba725b5a5 tools/libxc/xc_domain_save.c
--- a/tools/libxc/xc_domain_save.c
+++ b/tools/libxc/xc_domain_save.c
@@ -888,6 +888,8 @@ int xc_domain_save(xc_interface *xch, in
 
     int completed = 0;
 
+    DPRINTF("%s: starting save of domid %u", __func__, dom);
+
     if ( hvm && !callbacks->switch_qemu_logdirty )
     {
         ERROR("No switch_qemu_logdirty callback provided.");
@@ -2121,7 +2123,7 @@ int xc_domain_save(xc_interface *xch, in
     free(pfn_err);
     free(to_fix);
 
-    DPRINTF("Save exit rc=%d\n",rc);
+    DPRINTF("Save exit of domid %u with rc=%d\n", dom, rc);
 
     return !!rc;
 }
diff -r 0e6a41e1ee36 -r 101ba725b5a5 tools/xcutils/xc_restore.c
--- a/tools/xcutils/xc_restore.c
+++ b/tools/xcutils/xc_restore.c
@@ -19,17 +19,22 @@ int
 main(int argc, char **argv)
 {
     unsigned int domid, store_evtchn, console_evtchn;
-    unsigned int hvm, pae, apic;
+    unsigned int hvm, pae, apic, lflags;
     xc_interface *xch;
     int io_fd, ret;
     int superpages;
     unsigned long store_mfn, console_mfn;
+    xentoollog_level lvl;
+    xentoollog_logger *l;
 
     if ( (argc != 8) && (argc != 9) )
         errx(1, "usage: %s iofd domid store_evtchn "
              "console_evtchn hvm pae apic [superpages]", argv[0]);
 
-    xch = xc_interface_open(0,0,0);
+    lvl = XTL_DETAIL;
+    lflags = XTL_STDIOSTREAM_SHOW_PID | XTL_STDIOSTREAM_HIDE_PROGRESS;
+    l = (xentoollog_logger *)xtl_createlogger_stdiostream(stderr, lvl, lflags);
+    xch = xc_interface_open(l, 0, 0);
     if ( !xch )
         errx(1, "failed to open control interface");
 
diff -r 0e6a41e1ee36 -r 101ba725b5a5 tools/xcutils/xc_save.c
--- a/tools/xcutils/xc_save.c
+++ b/tools/xcutils/xc_save.c
@@ -184,7 +184,7 @@ main(int argc, char **argv)
     si.suspend_evtchn = -1;
 
     lvl = si.flags & XCFLAGS_DEBUG ? XTL_DEBUG: XTL_DETAIL;
-    lflags = XTL_STDIOSTREAM_HIDE_PROGRESS;
+    lflags = XTL_STDIOSTREAM_SHOW_PID | XTL_STDIOSTREAM_HIDE_PROGRESS;
     l = (xentoollog_logger *)xtl_createlogger_stdiostream(stderr, lvl, lflags);
     si.xch = xc_interface_open(l, 0, 0);
     if (!si.xch)

[PATCH 6 of 7] xl: correct help text of xl migrate

[Olaf Hering]

# HG changeset patch
# User Olaf Hering <olaf@aepfle.de>
# Date 1360770321 -3600
# Node ID de60f1266f051fd54155ca1b149dd8c9bf64f2dc
# Parent  101ba725b5a58323c34a1944d7d24f600aaf48d5
xl: correct help text of xl migrate

Signed-off-by: Olaf Hering <olaf@aepfle.de>

diff -r 101ba725b5a5 -r de60f1266f05 tools/libxl/xl_cmdtable.c
--- a/tools/libxl/xl_cmdtable.c
+++ b/tools/libxl/xl_cmdtable.c
@@ -145,7 +145,7 @@ struct cmd_spec cmd_table[] = {
     },
     { "migrate",
       &main_migrate, 0, 1,
-      "Save a domain state to restore later",
+      "Migrate a domain to another host",
       "[options] <Domain> <host>",
       "-h              Print this help.\n"
       "-C <config>     Send <config> instead of config file from creation.\n"

[PATCH 7 of 7] libxl: pass debug flag down to libxl_domain_suspend

[Olaf Hering]

# HG changeset patch
# User Olaf Hering <olaf@aepfle.de>
# Date 1360770325 -3600
# Node ID 3bcbdd2cc6079a93ed7f4c335b86bfa34c3ae4e1
# Parent  de60f1266f051fd54155ca1b149dd8c9bf64f2dc
libxl: pass debug flag down to libxl_domain_suspend

libxl_domain_suspend is already prepared to handle LIBXL_SUSPEND_DEBUG,
and xl migrate handles the -d switch as well. Pass this flag down to
libxl_domain_suspend, so that finally xc_domain_save can dump huge
amount of debug data to stdout.
Update xl.1 and help text output.

v4:
 - change -d to --debug

v3:
 - require 3 -d options to really enable it

v2:
 - fix xl.1 option, really use -d instead of -e

Signed-off-by: Olaf Hering <olaf@aepfle.de>

diff -r de60f1266f05 -r 3bcbdd2cc607 docs/man/xl.pod.1
--- a/docs/man/xl.pod.1
+++ b/docs/man/xl.pod.1
@@ -387,6 +387,10 @@ domain. See the corresponding option of 
 
 Send <config> instead of config file from creation.
 
+=item B<--debug>
+
+Print huge (!) amount of debug during the migration process.
+
 =back
 
 =item B<remus> [I<OPTIONS>] I<domain-id> I<host>
diff -r de60f1266f05 -r 3bcbdd2cc607 tools/libxl/xl_cmdimpl.c
--- a/tools/libxl/xl_cmdimpl.c
+++ b/tools/libxl/xl_cmdimpl.c
@@ -3331,7 +3331,7 @@ static void migrate_do_preamble(int send
 
 }
 
-static void migrate_domain(uint32_t domid, const char *rune,
+static void migrate_domain(uint32_t domid, const char *rune, int debug,
                            const char *override_config_file)
 {
     pid_t child = -1;
@@ -3340,7 +3340,7 @@ static void migrate_domain(uint32_t domi
     char *away_domname;
     char rc_buf;
     uint8_t *config_data;
-    int config_len;
+    int config_len, flags = LIBXL_SUSPEND_LIVE;
 
     save_domain_core_begin(domid, override_config_file,
                            &config_data, &config_len);
@@ -3358,7 +3358,9 @@ static void migrate_domain(uint32_t domi
 
     xtl_stdiostream_adjust_flags(logger, XTL_STDIOSTREAM_HIDE_PROGRESS, 0);
 
-    rc = libxl_domain_suspend(ctx, domid, send_fd, LIBXL_SUSPEND_LIVE, NULL);
+    if (debug)
+        flags |= LIBXL_SUSPEND_DEBUG;
+    rc = libxl_domain_suspend(ctx, domid, send_fd, flags, NULL);
     if (rc) {
         fprintf(stderr, "migration sender: libxl_domain_suspend failed"
                 " (rc=%d)\n", rc);
@@ -3751,8 +3753,13 @@ int main_migrate(int argc, char **argv)
     char *rune = NULL;
     char *host;
     int opt, daemonize = 1, monitor = 1, debug = 0;
-
-    SWITCH_FOREACH_OPT(opt, "FC:s:ed", NULL, "migrate", 2) {
+    static struct option opts[] = {
+        {"debug", 0, 0, 0x100},
+        COMMON_LONG_OPTS,
+        {0, 0, 0, 0}
+    };
+
+    SWITCH_FOREACH_OPT(opt, "FC:s:e", opts, "migrate", 2) {
     case 'C':
         config_filename = optarg;
         break;
@@ -3766,7 +3773,7 @@ int main_migrate(int argc, char **argv)
         daemonize = 0;
         monitor = 0;
         break;
-    case 'd':
+    case 0x100:
         debug = 1;
         break;
     }
@@ -3784,7 +3791,7 @@ int main_migrate(int argc, char **argv)
             return 1;
     }
 
-    migrate_domain(domid, rune, config_filename);
+    migrate_domain(domid, rune, debug, config_filename);
     return 0;
 }
 
diff -r de60f1266f05 -r 3bcbdd2cc607 tools/libxl/xl_cmdtable.c
--- a/tools/libxl/xl_cmdtable.c
+++ b/tools/libxl/xl_cmdtable.c
@@ -153,7 +153,8 @@ struct cmd_spec cmd_table[] = {
       "                to sh. If empty, run <host> instead of ssh <host> xl\n"
       "                migrate-receive [-d -e]\n"
       "-e              Do not wait in the background (on <host>) for the death\n"
-      "                of the domain."
+      "                of the domain.\n"
+      "--debug         Print huge (!) amount of debug during the migration process."
     },
     { "dump-core",
       &main_dump_core, 0, 1,

Re: [PATCH 0 of 7] various changes for xm migrate logging

[Ian Campbell]

On Wed, 2013-02-13 at 15:52 +0000, Olaf Hering wrote:
> Changes:
> tools/xc: fix logic error in stdiostream_progress
> tools/xc: handle tty output differently in stdiostream_progress
> tools/xc: turn XCFLAGS_* into shifts
> tools/xc: restore logging in xc_save
> tools/xc: log pid in xc_save/xc_restore output
> xl: correct help text of xl migrate
> libxl: pass debug flag down to libxl_domain_suspend

All acked = applied, thanks.