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.
Ian Jackson
2012-May-15 14:09 UTC
[PATCH 1/4] libxl: events: debugging output for timeouts
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
Ian Jackson
2012-May-15 14:09 UTC
[PATCH 2/4] libxl: events: improve debugging output for xs watches
* 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
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
Ian Jackson
2012-May-15 14:09 UTC
[PATCH 4/4] libxl: events: STATE_AO_GC checks ao is still valid
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
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 fdsI 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 validI 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