* [PATCH 1/4] libxl: events: debugging output for timeouts
2012-05-15 14:09 libxl: events: debugging improvements Ian Jackson
@ 2012-05-15 14:09 ` Ian Jackson
2012-05-15 14:09 ` [PATCH 2/4] libxl: events: improve debugging output for xs watches Ian Jackson
` (3 subsequent siblings)
4 siblings, 0 replies; 7+ messages in thread
From: Ian Jackson @ 2012-05-15 14:09 UTC (permalink / raw)
To: xen-devel; +Cc: 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
^ permalink raw reply related [flat|nested] 7+ messages in thread* [PATCH 2/4] libxl: events: improve debugging output for xs watches
2012-05-15 14:09 libxl: events: debugging improvements Ian Jackson
2012-05-15 14:09 ` [PATCH 1/4] libxl: events: debugging output for timeouts Ian Jackson
@ 2012-05-15 14:09 ` Ian Jackson
2012-05-15 14:09 ` [PATCH 3/4] libxl: events: debugging output for fds Ian Jackson
` (2 subsequent siblings)
4 siblings, 0 replies; 7+ messages in thread
From: Ian Jackson @ 2012-05-15 14:09 UTC (permalink / raw)
To: xen-devel; +Cc: 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
^ permalink raw reply related [flat|nested] 7+ messages in thread* [PATCH 3/4] libxl: events: debugging output for fds
2012-05-15 14:09 libxl: events: debugging improvements Ian Jackson
2012-05-15 14:09 ` [PATCH 1/4] libxl: events: debugging output for timeouts Ian Jackson
2012-05-15 14:09 ` [PATCH 2/4] libxl: events: improve debugging output for xs watches Ian Jackson
@ 2012-05-15 14:09 ` Ian Jackson
2012-05-15 14:09 ` [PATCH 4/4] libxl: events: STATE_AO_GC checks ao is still valid Ian Jackson
2012-05-17 13:46 ` libxl: events: debugging improvements Ian Campbell
4 siblings, 0 replies; 7+ messages in thread
From: Ian Jackson @ 2012-05-15 14:09 UTC (permalink / raw)
To: xen-devel; +Cc: 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
^ permalink raw reply related [flat|nested] 7+ messages in thread* [PATCH 4/4] libxl: events: STATE_AO_GC checks ao is still valid
2012-05-15 14:09 libxl: events: debugging improvements Ian Jackson
` (2 preceding siblings ...)
2012-05-15 14:09 ` [PATCH 3/4] libxl: events: debugging output for fds Ian Jackson
@ 2012-05-15 14:09 ` Ian Jackson
2012-05-17 13:46 ` libxl: events: debugging improvements Ian Campbell
4 siblings, 0 replies; 7+ messages in thread
From: Ian Jackson @ 2012-05-15 14:09 UTC (permalink / raw)
To: xen-devel; +Cc: 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
^ permalink raw reply related [flat|nested] 7+ messages in thread* Re: libxl: events: debugging improvements
2012-05-15 14:09 libxl: events: debugging improvements Ian Jackson
` (3 preceding siblings ...)
2012-05-15 14:09 ` [PATCH 4/4] libxl: events: STATE_AO_GC checks ao is still valid Ian Jackson
@ 2012-05-17 13:46 ` Ian Campbell
4 siblings, 0 replies; 7+ messages in thread
From: Ian Campbell @ 2012-05-17 13:46 UTC (permalink / raw)
To: Ian Jackson; +Cc: xen-devel@lists.xen.org
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
^ permalink raw reply [flat|nested] 7+ messages in thread
* [PATCH 2/4] libxl: events: improve debugging output for xs watches
2012-05-18 18:20 [PATCH v2 0/4] libxl: events: debugging output Ian Jackson
@ 2012-05-18 18:20 ` Ian Jackson
0 siblings, 0 replies; 7+ messages in thread
From: Ian Jackson @ 2012-05-18 18:20 UTC (permalink / raw)
To: xen-devel; +Cc: 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
^ permalink raw reply related [flat|nested] 7+ messages in thread