[PATCH v2 0/4] libxl: events: debugging output

[PATCH v2 0/4] libxl: events: debugging output

[Ian Jackson]

I was using these to help with debugging the libxl event code.

Changes since v1: Made many of these less spammy.

 1/4 libxl: events: debugging output for timeouts
 2/4 libxl: events: improve debugging output for xs watches
 3/4 libxl: events: debugging output for fds
 4/4 libxl: events: debugging output relating to ao's

[PATCH 1/4] libxl: events: debugging output for timeouts

[Ian Jackson]

Signed-off-by: Ian Jackson <ian.jackson@eu.citrix.com>

Changes since v1:
 * New output only occurs if you compile with -DDEBUG=1
---
 tools/libxl/libxl_event.c |   43 +++++++++++++++++++++++++++++++++++++++++++
 1 files changed, 43 insertions(+), 0 deletions(-)

diff --git a/tools/libxl/libxl_event.c b/tools/libxl/libxl_event.c
index 7fbd5c3..c095f14 100644
--- a/tools/libxl/libxl_event.c
+++ b/tools/libxl/libxl_event.c
@@ -19,6 +19,18 @@
 
 #include "libxl_internal.h"
 
+
+//#define DEBUG 1
+
+#ifdef DEBUG
+# define LIBXL__DBG_LOG(ctx, args, ...) \
+    LIBXL__LOG((ctx), XTL_DEBUG, args, __VA_ARGS__)
+#else
+# define LIBXL__DBG_LOG(ctx, args, ...) ((void)0)
+#endif
+#define DBG(args, ...) LIBXL__DBG_LOG(CTX, args, __VA_ARGS__)
+
+
 /*
  * The counter osevent_in_hook is used to ensure that the application
  * honours the reentrancy restriction documented in libxl_event.h.
@@ -169,6 +181,16 @@ static void time_deregister(libxl__gc *gc, libxl__ev_time *ev)
     }
 }
 
+static void time_done_debug(libxl__gc *gc, const char *func,
+                            libxl__ev_time *ev, int rc)
+{
+#ifdef DEBUG
+    libxl__log(CTX, XTL_DEBUG, -1,__FILE__,0,func,
+               "ev_time=%p done rc=%d .func=%p infinite=%d abs=%lu.%06lu",
+               ev, rc, ev->func, ev->infinite,
+               (unsigned long)ev->abs.tv_sec, (unsigned long)ev->abs.tv_usec);
+#endif
+}
 
 int libxl__ev_time_register_abs(libxl__gc *gc, libxl__ev_time *ev,
                                 libxl__ev_time_callback *func,
@@ -178,6 +200,9 @@ int libxl__ev_time_register_abs(libxl__gc *gc, libxl__ev_time *ev,
 
     CTX_LOCK;
 
+    DBG("ev_time=%p register abs=%lu.%06lu",
+        ev, (unsigned long)abs.tv_sec, (unsigned long)abs.tv_usec);
+
     rc = time_register_finite(gc, ev, abs);
     if (rc) goto out;
 
@@ -185,6 +210,7 @@ int libxl__ev_time_register_abs(libxl__gc *gc, libxl__ev_time *ev,
 
     rc = 0;
  out:
+    time_done_debug(gc,__func__,ev,rc);
     CTX_UNLOCK;
     return rc;
 }
@@ -199,6 +225,8 @@ int libxl__ev_time_register_rel(libxl__gc *gc, libxl__ev_time *ev,
 
     CTX_LOCK;
 
+    DBG("ev_time=%p register ms=%d", ev, milliseconds);
+
     if (milliseconds < 0) {
         ev->infinite = 1;
     } else {
@@ -213,6 +241,7 @@ int libxl__ev_time_register_rel(libxl__gc *gc, libxl__ev_time *ev,
     rc = 0;
 
  out:
+    time_done_debug(gc,__func__,ev,rc);
     CTX_UNLOCK;
     return rc;
 }
@@ -224,6 +253,9 @@ int libxl__ev_time_modify_abs(libxl__gc *gc, libxl__ev_time *ev,
 
     CTX_LOCK;
 
+    DBG("ev_time=%p modify abs==%lu.%06lu",
+        ev, (unsigned long)abs.tv_sec, (unsigned long)abs.tv_usec);
+
     assert(libxl__ev_time_isregistered(ev));
 
     if (ev->infinite) {
@@ -240,6 +272,7 @@ int libxl__ev_time_modify_abs(libxl__gc *gc, libxl__ev_time *ev,
 
     rc = 0;
  out:
+    time_done_debug(gc,__func__,ev,rc);
     CTX_UNLOCK;
     return rc;
 }
@@ -252,6 +285,8 @@ int libxl__ev_time_modify_rel(libxl__gc *gc, libxl__ev_time *ev,
 
     CTX_LOCK;
 
+    DBG("ev_time=%p modify ms=%d", ev, milliseconds);
+
     assert(libxl__ev_time_isregistered(ev));
 
     if (milliseconds < 0) {
@@ -269,6 +304,7 @@ int libxl__ev_time_modify_rel(libxl__gc *gc, libxl__ev_time *ev,
 
     rc = 0;
  out:
+    time_done_debug(gc,__func__,ev,rc);
     CTX_UNLOCK;
     return rc;
 }
@@ -277,6 +313,8 @@ void libxl__ev_time_deregister(libxl__gc *gc, libxl__ev_time *ev)
 {
     CTX_LOCK;
 
+    DBG("ev_time=%p deregister", ev);
+
     if (!libxl__ev_time_isregistered(ev))
         goto out;
 
@@ -284,6 +322,7 @@ void libxl__ev_time_deregister(libxl__gc *gc, libxl__ev_time *ev)
     ev->func = 0;
 
  out:
+    time_done_debug(gc,__func__,ev,0);
     CTX_UNLOCK;
     return;
 }
@@ -856,6 +895,10 @@ static void afterpoll_internal(libxl__egc *egc, libxl__poller *poller,
 
         time_deregister(gc, etime);
 
+        DBG("ev_time=%p occurs abs=%lu.%06lu",
+            etime, (unsigned long)etime->abs.tv_sec,
+            (unsigned long)etime->abs.tv_usec);
+
         etime->func(egc, etime, &etime->abs);
     }
 }
-- 
1.7.2.5

[PATCH 2/4] libxl: events: improve debugging output for xs watches

[Ian Jackson]

* Add debugging output for register/deregister.
* Make the debugging printfs consistent about the order in which they
  print the information.
* Where we touch the code, change LIBXL__LOG to LOG.

Signed-off-by: Ian Jackson <ian.jackson@eu.citrix.com>
---
 tools/libxl/libxl_event.c |   29 ++++++++++++++++++-----------
 1 files changed, 18 insertions(+), 11 deletions(-)

diff --git a/tools/libxl/libxl_event.c b/tools/libxl/libxl_event.c
index c095f14..8d6fec8 100644
--- a/tools/libxl/libxl_event.c
+++ b/tools/libxl/libxl_event.c
@@ -420,9 +420,8 @@ static void watchfd_callback(libxl__egc *egc, libxl__ev_fd *ev,
         }
 
         if (w->counterval != counterval) {
-            LIBXL__LOG(CTX, LIBXL__LOG_DEBUG,
-                       "watch epath=%s token=%s: counter != %"PRIx32,
-                       epath, token, w->counterval);
+            LOG(DEBUG, "watch w=%p epath=%s token=%s: counter != %"PRIx32,
+                w, epath, token, w->counterval);
             goto ignore;
         }
 
@@ -440,16 +439,14 @@ static void watchfd_callback(libxl__egc *egc, libxl__ev_fd *ev,
          * See also docs/misc/xenstore.txt.
          */
         if (!xs_path_is_subpath(w->path, epath)) {
-            LIBXL__LOG(CTX, LIBXL__LOG_DEBUG,
-                       "watch epath=%s token=%s: not child of wpath=%s",
-                       epath, token, w->path);
+            LOG(DEBUG, "watch w=%p wpath=%s token=%s: unexpected epath=%s",
+                w, w->path, token, epath);
             goto ignore;
         }
 
         /* At last, we have checked everything! */
-        LIBXL__LOG(CTX, LIBXL__LOG_DEBUG,
-                   "watch event: epath=%s token=%s wpath=%s w=%p",
-                   epath, token, w->path, w);
+        LOG(DEBUG, "watch w=%p wpath=%s token=%s: event epath=%s",
+            w, w->path, token, epath);
         w->callback(egc, w, w->path, epath);
 
     ignore:
@@ -502,7 +499,11 @@ int libxl__ev_xswatch_register(libxl__gc *gc, libxl__ev_xswatch *w,
     int slotnum = use - CTX->watch_slots;
     w->counterval = CTX->watch_counter++;
 
-    if (!xs_watch(CTX->xsh, path, watch_token(gc, slotnum, w->counterval))) {
+    const char *token = watch_token(gc, slotnum, w->counterval);
+    LOG(DEBUG, "watch w=%p wpath=%s token=%s: register slotnum=%d",
+        w, path, token, slotnum);
+
+    if (!xs_watch(CTX->xsh, path, token)) {
         LIBXL__LOG_ERRNOVAL(CTX, LIBXL__LOG_ERROR, errno,
                             "create watch for path %s", path);
         rc = ERROR_FAIL;
@@ -534,7 +535,11 @@ void libxl__ev_xswatch_deregister(libxl__gc *gc, libxl__ev_xswatch *w)
     CTX_LOCK;
 
     if (w->slotnum >= 0) {
-        char *token = watch_token(gc, w->slotnum, w->counterval);
+        const char *token = watch_token(gc, w->slotnum, w->counterval);
+
+        LOG(DEBUG, "watch w=%p wpath=%s token=%s: deregister slotnum=%d",
+            w, w->path, token, w->slotnum);
+
         if (!xs_unwatch(CTX->xsh, w->path, token))
             /* Oh well, we will just get watch events forever more
              * and ignore them.  But we should complain to the log. */
@@ -544,6 +549,8 @@ void libxl__ev_xswatch_deregister(libxl__gc *gc, libxl__ev_xswatch *w)
         libxl__ev_watch_slot *slot = &CTX->watch_slots[w->slotnum];
         LIBXL_SLIST_INSERT_HEAD(&CTX->watch_freeslots, slot, empty);
         w->slotnum = -1;
+    } else {
+        LOG(DEBUG, "watch w=%p: deregister unregistered", w);
     }
 
     free(w->path);
-- 
1.7.2.5

[PATCH 3/4] libxl: events: debugging output for fds

[Ian Jackson]

Signed-off-by: Ian Jackson <ian.jackson@eu.citrix.com>

Changes since v1:
 * New output only occurs if you compile with -DDEBUG=1
---
 tools/libxl/libxl_event.c |   15 +++++++++++++--
 1 files changed, 13 insertions(+), 2 deletions(-)

diff --git a/tools/libxl/libxl_event.c b/tools/libxl/libxl_event.c
index 8d6fec8..ed8ed5c 100644
--- a/tools/libxl/libxl_event.c
+++ b/tools/libxl/libxl_event.c
@@ -70,6 +70,8 @@ int libxl__ev_fd_register(libxl__gc *gc, libxl__ev_fd *ev,
 
     CTX_LOCK;
 
+    DBG("ev_fd=%p register fd=%d events=%x", ev, fd, events);
+
     rc = OSEVENT_HOOK(fd_register, fd, &ev->for_app_reg, events, ev);
     if (rc) goto out;
 
@@ -93,6 +95,8 @@ int libxl__ev_fd_modify(libxl__gc *gc, libxl__ev_fd *ev, short events)
     CTX_LOCK;
     assert(libxl__ev_fd_isregistered(ev));
 
+    DBG("ev_fd=%p modify fd=%d events=%x", ev, ev->fd, events);
+
     rc = OSEVENT_HOOK(fd_modify, ev->fd, &ev->for_app_reg, events);
     if (rc) goto out;
 
@@ -108,8 +112,12 @@ void libxl__ev_fd_deregister(libxl__gc *gc, libxl__ev_fd *ev)
 {
     CTX_LOCK;
 
-    if (!libxl__ev_fd_isregistered(ev))
+    if (!libxl__ev_fd_isregistered(ev)) {
+        DBG("ev_fd=%p deregister unregistered",ev);
         goto out;
+    }
+
+    DBG("ev_fd=%p deregister fd=%d", ev, ev->fd);
 
     OSEVENT_HOOK_VOID(fd_deregister, ev->fd, ev->for_app_reg);
     LIBXL_LIST_REMOVE(ev, entry);
@@ -873,8 +881,11 @@ static void afterpoll_internal(libxl__egc *egc, libxl__poller *poller,
             continue;
 
         int revents = afterpoll_check_fd(poller,fds,nfds, efd->fd,efd->events);
-        if (revents)
+        if (revents) {
+            DBG("ev_fd=%p occurs fd=%d events=%x revents=%x",
+                efd, efd->fd, efd->events, revents);
             efd->func(egc, efd, efd->fd, efd->events, revents);
+        }
     }
 
     if (afterpoll_check_fd(poller,fds,nfds, poller->wakeup_pipe[0],POLLIN)) {
-- 
1.7.2.5

[PATCH 4/4] libxl: events: debugging output relating to ao's

[Ian Jackson]

(In libxl__ao_complete_check_progress_reports, introduce libxl_ctx *ctx.)

Signed-off-by: Ian Jackson <ian.jackson@eu.citrix.com>

Changes since v1:
 * New output in event loop only occurs if you compile with -DDEBUG=1;
   other new output remains.
 * Remove a mid-function use of AO_GC.  Instead, introduce a ctx
   variable and use that instead.
---
 tools/libxl/libxl_event.c    |   39 +++++++++++++++++++++++++++++++++++----
 tools/libxl/libxl_internal.h |   12 ++++++++----
 2 files changed, 43 insertions(+), 8 deletions(-)

diff --git a/tools/libxl/libxl_event.c b/tools/libxl/libxl_event.c
index ed8ed5c..565d2c2 100644
--- a/tools/libxl/libxl_event.c
+++ b/tools/libxl/libxl_event.c
@@ -1020,11 +1020,14 @@ static void egc_run_callbacks(libxl__egc *egc)
 
     LIBXL_TAILQ_FOREACH_SAFE(ev, &egc->occurred_for_callback, link, ev_tmp) {
         LIBXL_TAILQ_REMOVE(&egc->occurred_for_callback, ev, link);
+        LOG(DEBUG,"event %p callback type=%s",
+            ev, libxl_event_type_to_string(ev->type));
         CTX->event_hooks->event_occurs(CTX->event_hooks_user, ev);
     }
 
     LIBXL_TAILQ_FOREACH_SAFE(aop, &egc->aops_for_callback, entry, aop_tmp) {
         LIBXL_TAILQ_REMOVE(&egc->aops_for_callback, aop, entry);
+        LOG(DEBUG,"ao %p: progress report: callback aop=%p", aop->ao, aop);
         aop->how->callback(CTX, aop->ev, aop->how->for_callback);
 
         CTX_LOCK;
@@ -1037,6 +1040,7 @@ static void egc_run_callbacks(libxl__egc *egc)
     LIBXL_TAILQ_FOREACH_SAFE(ao, &egc->aos_for_callback,
                              entry_for_callback, ao_tmp) {
         LIBXL_TAILQ_REMOVE(&egc->aos_for_callback, ao, entry_for_callback);
+        LOG(DEBUG,"ao %p: completion callback", ao);
         ao->how.callback(CTX, ao->rc, ao->how.u.for_callback);
         CTX_LOCK;
         ao->notified = 1;
@@ -1396,7 +1400,9 @@ int libxl_event_wait(libxl_ctx *ctx, libxl_event **event_r,
 
 void libxl__ao__destroy(libxl_ctx *ctx, libxl__ao *ao)
 {
+    AO_GC;
     if (!ao) return;
+    LOG(DEBUG,"ao %p: destroy",ao);
     if (ao->poller) libxl__poller_put(ctx, ao->poller);
     ao->magic = LIBXL__AO_MAGIC_DESTROYED;
     libxl__free_all(&ao->gc);
@@ -1406,6 +1412,7 @@ void libxl__ao__destroy(libxl_ctx *ctx, libxl__ao *ao)
 void libxl__ao_abort(libxl__ao *ao)
 {
     AO_GC;
+    LOG(DEBUG,"ao %p: abort",ao);
     assert(ao->magic == LIBXL__AO_MAGIC);
     assert(ao->in_initiator);
     assert(!ao->complete);
@@ -1422,6 +1429,8 @@ libxl__gc *libxl__ao_inprogress_gc(libxl__ao *ao)
 
 void libxl__ao_complete(libxl__egc *egc, libxl__ao *ao, int rc)
 {
+    AO_GC;
+    LOG(DEBUG,"ao %p: complete, rc=%d",ao,rc);
     assert(ao->magic == LIBXL__AO_MAGIC);
     assert(!ao->complete);
     ao->complete = 1;
@@ -1439,7 +1448,7 @@ void libxl__ao_complete_check_progress_reports(libxl__egc *egc, libxl__ao *ao)
      * will, after making the callback, take out the lock again,
      * decrement progress_reports_outstanding, and call us again.
      */
-
+    libxl_ctx *ctx = libxl__gc_owner(&egc->gc);
     assert(ao->progress_reports_outstanding >= 0);
 
     if (!ao->complete || ao->progress_reports_outstanding)
@@ -1451,6 +1460,7 @@ void libxl__ao_complete_check_progress_reports(libxl__egc *egc, libxl__ao *ao)
             /* don't bother with this if we're not in the event loop */
             libxl__poller_wakeup(egc, ao->poller);
     } else if (ao->how.callback) {
+        LIBXL__LOG(ctx, XTL_DEBUG, "ao %p: complete for callback",ao);
         LIBXL_TAILQ_INSERT_TAIL(&egc->aos_for_callback, ao, entry_for_callback);
     } else {
         libxl_event *ev;
@@ -1463,11 +1473,12 @@ void libxl__ao_complete_check_progress_reports(libxl__egc *egc, libxl__ao *ao)
         ao->notified = 1;
     }
     if (!ao->in_initiator && ao->notified)
-        libxl__ao__destroy(libxl__gc_owner(&egc->gc), ao);
+        libxl__ao__destroy(ctx, ao);
 }
 
 libxl__ao *libxl__ao_create(libxl_ctx *ctx, uint32_t domid,
-                            const libxl_asyncop_how *how)
+                            const libxl_asyncop_how *how,
+                            const char *file, int line, const char *func)
 {
     libxl__ao *ao;
 
@@ -1487,6 +1498,10 @@ libxl__ao *libxl__ao_create(libxl_ctx *ctx, uint32_t domid,
         ao->poller = libxl__poller_get(ctx);
         if (!ao->poller) goto out;
     }
+    libxl__log(ctx,XTL_DEBUG,-1,file,line,func,
+               "ao %p: create: how=%p callback=%p poller=%p",
+               ao, how, ao->how.callback, ao->poller);
+
     return ao;
 
  out:
@@ -1495,7 +1510,8 @@ libxl__ao *libxl__ao_create(libxl_ctx *ctx, uint32_t domid,
 }
 
 
-int libxl__ao_inprogress(libxl__ao *ao)
+int libxl__ao_inprogress(libxl__ao *ao,
+                         const char *file, int line, const char *func)
 {
     AO_GC;
     int rc;
@@ -1505,6 +1521,14 @@ int libxl__ao_inprogress(libxl__ao *ao)
     assert(ao->in_initiator);
     ao->constructing = 0;
 
+    libxl__log(CTX,XTL_DEBUG,-1,file,line,func,
+               "ao %p: inprogress: poller=%p, flags=%s%s%s%s",
+               ao, ao->poller,
+               ao->constructing ? "o" : "",
+               ao->in_initiator ? "i" : "",
+               ao->complete ? "c" : "",
+               ao->notified ? "n" : "");
+
     if (ao->poller) {
         /* Caller wants it done synchronously. */
         /* We use a fresh gc, so that we can free things
@@ -1521,6 +1545,8 @@ int libxl__ao_inprogress(libxl__ao *ao)
                 break;
             }
 
+            DBG("ao %p: not ready, waiting",ao);
+
             rc = eventloop_iteration(&egc,ao->poller);
             if (rc) {
                 /* Oh dear, this is quite unfortunate. */
@@ -1571,8 +1597,10 @@ void libxl__ao_progress_gethow(libxl_asyncprogress_how *in_state,
 void libxl__ao_progress_report(libxl__egc *egc, libxl__ao *ao,
         const libxl_asyncprogress_how *how, libxl_event *ev)
 {
+    AO_GC;
     ev->for_user = how->for_event;
     if (how->callback == dummy_asyncprogress_callback_ignore) {
+        LOG(DEBUG,"ao %p: progress report: ignored",ao);
         /* ignore */
     } else if (how->callback) {
         libxl__aop_occurred *aop = libxl__zalloc(&egc->gc, sizeof(*aop));
@@ -1581,7 +1609,10 @@ void libxl__ao_progress_report(libxl__egc *egc, libxl__ao *ao,
         aop->ev = ev;
         aop->how = how;
         LIBXL_TAILQ_INSERT_TAIL(&egc->aops_for_callback, aop, entry);
+        LOG(DEBUG,"ao %p: progress report: callback queued aop=%p",ao,aop);
     } else {
+        LOG(DEBUG,"ao %p: progress report: event queued ev=%p type=%s",
+            ao, ev, libxl_event_type_to_string(ev->type));
         libxl__event_occurred(egc, ev);
     }
 }
diff --git a/tools/libxl/libxl_internal.h b/tools/libxl/libxl_internal.h
index 49d01a8..0e084c1 100644
--- a/tools/libxl/libxl_internal.h
+++ b/tools/libxl/libxl_internal.h
@@ -1555,14 +1555,16 @@ _hidden void libxl__egc_cleanup(libxl__egc *egc);
 
 #define AO_CREATE(ctx, domid, ao_how)                           \
     libxl__ctx_lock(ctx);                                       \
-    libxl__ao *ao = libxl__ao_create(ctx, domid, ao_how);       \
+    libxl__ao *ao = libxl__ao_create(ctx, domid, ao_how,        \
+                               __FILE__, __LINE__, __func__);   \
     if (!ao) { libxl__ctx_unlock(ctx); return ERROR_NOMEM; }    \
     libxl__egc egc[1]; LIBXL_INIT_EGC(egc[0],ctx);              \
     AO_GC;
 
 #define AO_INPROGRESS ({                                        \
         libxl_ctx *ao__ctx = libxl__gc_owner(&ao->gc);          \
-        int ao__rc = libxl__ao_inprogress(ao);                  \
+        int ao__rc = libxl__ao_inprogress(ao,                   \
+                               __FILE__, __LINE__, __func__);   \
         libxl__ctx_unlock(ao__ctx); /* gc is now invalid */     \
         EGC_FREE;                                               \
         (ao__rc);                                               \
@@ -1588,8 +1590,10 @@ _hidden void libxl__egc_cleanup(libxl__egc *egc);
 /* All of these MUST be called with the ctx locked.
  * libxl__ao_inprogress MUST be called with the ctx locked exactly once. */
 _hidden libxl__ao *libxl__ao_create(libxl_ctx*, uint32_t domid,
-                                    const libxl_asyncop_how*);
-_hidden int libxl__ao_inprogress(libxl__ao *ao); /* temporarily unlocks */
+                                    const libxl_asyncop_how*,
+       const char *file, int line, const char *func);
+_hidden int libxl__ao_inprogress(libxl__ao *ao,
+       const char *file, int line, const char *func); /* temporarily unlocks */
 _hidden void libxl__ao_abort(libxl__ao *ao);
 _hidden void libxl__ao_complete(libxl__egc *egc, libxl__ao *ao, int rc);
 _hidden libxl__gc *libxl__ao_inprogress_gc(libxl__ao *ao);
-- 
1.7.2.5

Re: [PATCH v2 0/4] libxl: events: debugging output

[Ian Campbell]

On Fri, 2012-05-18 at 19:20 +0100, Ian Jackson wrote:
> I was using these to help with debugging the libxl event code.
> 
> Changes since v1: Made many of these less spammy.

I booted a pv guest with "xl -vvv cr -c" with pygrub and direct kernel
and it wasn't too spammy anymore. I've applied them all.

Thanks,
Ian.

> 
>  1/4 libxl: events: debugging output for timeouts
>  2/4 libxl: events: improve debugging output for xs watches
>  3/4 libxl: events: debugging output for fds
>  4/4 libxl: events: debugging output relating to ao's
> 
> 
> _______________________________________________
> Xen-devel mailing list
> Xen-devel@lists.xen.org
> http://lists.xen.org/xen-devel