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

[Ian Jackson <ian.jackson@eu.citrix.com>]

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