Re: [Xen-devel] [PATCH 1/3] libxl: events: debugging output relating to ao's

[Ian Campbell <Ian.Campbell@xxxxxxxxxx>]

On Wed, 2012-05-16 at 16:25 +0100, Ian Jackson wrote:
> Signed-off-by: Ian Jackson <ian.jackson@xxxxxxxxxxxxx>
> ---
>  tools/libxl/libxl_event.c    |   36 ++++++++++++++++++++++++++++++++++--
>  tools/libxl/libxl_internal.h |   12 ++++++++----
>  2 files changed, 42 insertions(+), 6 deletions(-)
> 
> diff --git a/tools/libxl/libxl_event.c b/tools/libxl/libxl_event.c
> index bdbbdd4..7e71a88 100644
> --- a/tools/libxl/libxl_event.c
> +++ b/tools/libxl/libxl_event.c
> @@ -1006,11 +1006,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;
> @@ -1023,6 +1026,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;
> @@ -1382,7 +1386,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);
> @@ -1392,6 +1398,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);
> @@ -1408,6 +1415,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;
> @@ -1437,6 +1446,8 @@ 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) {
> +        AO_GC;

I'd prefer that we kept these sorts of magic infrastructure macro things
at the tops of functions.


> @@ -1507,6 +1532,8 @@ int libxl__ao_inprogress(libxl__ao *ao)
>                  break;
>              }
>  
> +            LOG(DEBUG,"ao %p: not ready, waiting",ao);

This one is too verbose, with xl -vvv cr -c it spams the pygrub console
every second making it unusable. Even before that point there is a good
dozen of them printed out.

I noticed that very little of this stuff ends up
in /var/log/xen/xl-<NAME>.log. I'm not sure why though since it would
seem the obvious place for it to go. I guess it happens in the
foreground not the daemon?


Ian.


_______________________________________________
Xen-devel mailing list
Xen-devel@xxxxxxxxxxxxx
http://lists.xen.org/xen-devel