libxl: events: debugging improvements

libxl: events: debugging improvements

[Ian Jackson]

These four patches may help people who are working with the libxl
event machinery:

 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: STATE_AO_GC checks ao is still valid

The first three are not intended to cause any change other than the
new debug messages.  The last one should simply cause erroneous code
to crash sooner.

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

[Ian Jackson]

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

diff --git a/tools/libxl/libxl_event.c b/tools/libxl/libxl_event.c
index 03d0498..3956f00 100644
--- a/tools/libxl/libxl_event.c
+++ b/tools/libxl/libxl_event.c
@@ -169,6 +169,14 @@ 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)
+{
+    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);
+}
 
 int libxl__ev_time_register_abs(libxl__gc *gc, libxl__ev_time *ev,
                                 libxl__ev_time_callback *func,
@@ -178,6 +186,9 @@ int libxl__ev_time_register_abs(libxl__gc *gc, libxl__ev_time *ev,
 
     CTX_LOCK;
 
+    LOG(DEBUG, "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 +196,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 +211,8 @@ int libxl__ev_time_register_rel(libxl__gc *gc, libxl__ev_time *ev,
 
     CTX_LOCK;
 
+    LOG(DEBUG, "ev_time=%p register ms=%d", ev, milliseconds);
+
     if (milliseconds < 0) {
         ev->infinite = 1;
     } else {
@@ -213,6 +227,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 +239,9 @@ int libxl__ev_time_modify_abs(libxl__gc *gc, libxl__ev_time *ev,
 
     CTX_LOCK;
 
+    LOG(DEBUG, "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 +258,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 +271,8 @@ int libxl__ev_time_modify_rel(libxl__gc *gc, libxl__ev_time *ev,
 
     CTX_LOCK;
 
+    LOG(DEBUG, "ev_time=%p modify ms=%d", ev, milliseconds);
+
     assert(libxl__ev_time_isregistered(ev));
 
     if (milliseconds < 0) {
@@ -269,6 +290,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 +299,8 @@ void libxl__ev_time_deregister(libxl__gc *gc, libxl__ev_time *ev)
 {
     CTX_LOCK;
 
+    LOG(DEBUG, "ev_time=%p deregister", ev);
+
     if (!libxl__ev_time_isregistered(ev))
         goto out;
 
@@ -284,6 +308,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 +881,10 @@ static void afterpoll_internal(libxl__egc *egc, libxl__poller *poller,
 
         time_deregister(gc, etime);
 
+        LOG(DEBUG, "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 3956f00..4d31b3c 100644
--- a/tools/libxl/libxl_event.c
+++ b/tools/libxl/libxl_event.c
@@ -406,9 +406,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;
         }
 
@@ -426,16 +425,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:
@@ -488,7 +485,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;
@@ -520,7 +521,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. */
@@ -530,6 +535,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>
---
 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 4d31b3c..0f9ea41 100644
--- a/tools/libxl/libxl_event.c
+++ b/tools/libxl/libxl_event.c
@@ -58,6 +58,8 @@ int libxl__ev_fd_register(libxl__gc *gc, libxl__ev_fd *ev,
 
     CTX_LOCK;
 
+    LOG(DEBUG, "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;
 
@@ -81,6 +83,8 @@ int libxl__ev_fd_modify(libxl__gc *gc, libxl__ev_fd *ev, short events)
     CTX_LOCK;
     assert(libxl__ev_fd_isregistered(ev));
 
+    LOG(DEBUG, "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;
 
@@ -96,8 +100,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)) {
+        LOG(DEBUG, "ev_fd=%p deregister unregistered",ev);
         goto out;
+    }
+
+    LOG(DEBUG, "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);
@@ -859,8 +867,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) {
+            LOG(DEBUG,"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: STATE_AO_GC checks ao is still valid

[Ian Jackson]

This will catch earlier the mistake where an ao is completed while it
still has events registered: when the event callback happens for the
long-gone ao, we will crash before attempting to execute any of the
operation-specific code.

Signed-off-by: Ian Jackson <ian.jackson@eu.citrix.com>
---
 tools/libxl/libxl_event.c    |    7 +++++++
 tools/libxl/libxl_internal.h |    3 ++-
 2 files changed, 9 insertions(+), 1 deletions(-)

diff --git a/tools/libxl/libxl_event.c b/tools/libxl/libxl_event.c
index 0f9ea41..bdbbdd4 100644
--- a/tools/libxl/libxl_event.c
+++ b/tools/libxl/libxl_event.c
@@ -1399,6 +1399,13 @@ void libxl__ao_abort(libxl__ao *ao)
     libxl__ao__destroy(CTX, ao);
 }
 
+libxl__gc *libxl__ao_inprogress_gc(libxl__ao *ao)
+{
+    assert(ao->magic == LIBXL__AO_MAGIC);
+    assert(!ao->complete);
+    return &ao->gc;
+}
+
 void libxl__ao_complete(libxl__egc *egc, libxl__ao *ao, int rc)
 {
     assert(ao->magic == LIBXL__AO_MAGIC);
diff --git a/tools/libxl/libxl_internal.h b/tools/libxl/libxl_internal.h
index b2fe8bb..73b9915 100644
--- a/tools/libxl/libxl_internal.h
+++ b/tools/libxl/libxl_internal.h
@@ -1575,7 +1575,7 @@ _hidden void libxl__egc_cleanup(libxl__egc *egc);
 
 #define STATE_AO_GC(op_ao)                      \
     libxl__ao *const ao = (op_ao);              \
-    AO_GC
+    libxl__gc *const gc __attribute__((unused)) = libxl__ao_inprogress_gc(ao)
 
 
 /* All of these MUST be called with the ctx locked.
@@ -1585,6 +1585,7 @@ _hidden libxl__ao *libxl__ao_create(libxl_ctx*, uint32_t domid,
 _hidden int libxl__ao_inprogress(libxl__ao *ao); /* 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);
 
 /* Can be called at any time.  Use is essential for any aop user. */
 _hidden void libxl__ao_progress_gethow(libxl_asyncprogress_how *in_state,
-- 
1.7.2.5

Re: libxl: events: debugging improvements

[Ian Campbell]

On Tue, 2012-05-15 at 15:09 +0100, Ian Jackson wrote:
> These four patches may help people who are working with the libxl
> event machinery:
> 
>  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

I didn't apply these three. Together with "libxl: events: debugging
output relating to ao's" from your following series they make "xl -vvv
create -c" with pygrub unusable due to the spamminess -- they print a
page of stuff roughly every second (corresponding with the on screen
countdown).

>  4/4 libxl: events: STATE_AO_GC checks ao is still valid

I did apply this one.

> 
> The first three are not intended to cause any change other than the
> new debug messages.  The last one should simply cause erroneous code
> to crash sooner.
> 
> 
> _______________________________________________
> Xen-devel mailing list
> Xen-devel@lists.xen.org
> http://lists.xen.org/xen-devel