[Qemu-devel] [PATCHv1 0/4] Timers: add timer debugging through -timer-debug-log

[Qemu-devel] [PATCHv1 0/4] Timers: add timer debugging through -timer-debug-log

[Alex Bligh]

This patch set adds facilities for debugging timers using the additional
command line option -timer-debug-log=FILE. If this option is selected,
a debugging file will be written showing information about the current
state of timers in the system, which the author feels will be useful for
debugging in the field.

Note that the option is a command line option rather than a configure
time option. This is because users in the field having issues are unlikely
to have a compile time option enabled.

It would be useful to get this feature in prior to 1.7 as it has little
impact other than making a major change to a subsystem more debuggable.
This patch has been lightly test.

Impact of changes whether or not -timer-debug-log is specified:

1. QEMUTimer is expanded to hold additional debugging information. Some
   of this is unused when the command line option is unspecified.

2. The file and line number of the caller that allocated the timer are
   recorded. This is useful for debugging in gdb.

It is felt these are minimal in nature.

Additional impact of changes only when -timer-debug-log is specified:

1. On every timer modification, the current clock time for that timer
   is read, and the additional debug information filled in.

2. Every second (roughly) a file is written (atomically) containing the
   timer debug information.

The debug information includes information on the number of timer
expiries since the timer was created, the average expiry time (in
nanoseconds), and the number of short expiries, being the number of
times the timer was asked to expire in less than one microsecond
(these usually but not always indicate a bug).

The file format is designed to be useful both to a mailing list and
to a user armed with gdb. An example of the output follows:

Timer list at 0x7f4d6cf0d6e0 clock 0:
           Address       Expiries      AvgLength       NumShort Source

Timer list at 0x7f4d6cf0cbc0 clock 0:
           Address       Expiries      AvgLength       NumShort Source

Timer list at 0x7f4d6cf0d750 clock 1:
           Address       Expiries      AvgLength       NumShort Source

Timer list at 0x7f4d6cf0cc30 clock 1:
           Address       Expiries      AvgLength       NumShort Source
    0x7f4d6cf51550              1       27462700              0 i8254.c:333

Timer list at 0x7f4d6cf0d7c0 clock 2:
           Address       Expiries      AvgLength       NumShort Source

Timer list at 0x7f4d6cf0cca0 clock 2:
           Address       Expiries      AvgLength       NumShort Source
    0x7f4d6cf6eed0              1      999997000              0 mc146818rtc.c:858

Note that the somewhat strange choice to output to a file has been taken
because the tracing infrastructure is unlikely to be enabled in a distro
environment.

Alex Bligh (4):
  Timers: add debugging macros wrapping timer functions and debug
    structures
  Timers: add command line option -timer-debug-log
  Timers: Instrument timer_mod
  Timers: produce timer-debug-log file

 include/block/aio.h  |   20 ++++++---
 include/qemu/timer.h |   70 ++++++++++++++++++++++--------
 qemu-options.hx      |   11 +++++
 qemu-timer.c         |  118 ++++++++++++++++++++++++++++++++++++++++++++++++--
 vl.c                 |    3 ++
 5 files changed, 194 insertions(+), 28 deletions(-)

-- 
1.7.9.5

[Qemu-devel] [PATCHv1 1/4] Timers: add debugging macros wrapping timer functions and debug structures

[Alex Bligh]

Add debugging versions of functions creating timers to record the
file and line number that they were called from. Add macros to
call these transparently. Add fields to timer struct to store
debugging information.

Note this patch contains one checkpatch.pl warning (space before
parenthesis) and a rather arcane double stringify macro. These
are copied from audio_int.h and I believe are to work around
compiler incompatibilities.

Signed-off-by: Alex Bligh <alex@alex.org.uk>
---
 include/block/aio.h  |   20 ++++++++++-----
 include/qemu/timer.h |   69 ++++++++++++++++++++++++++++++++++++--------------
 qemu-timer.c         |    8 +++---
 3 files changed, 69 insertions(+), 28 deletions(-)

diff --git a/include/block/aio.h b/include/block/aio.h
index 2efdf41..199728f 100644
--- a/include/block/aio.h
+++ b/include/block/aio.h
@@ -262,13 +262,17 @@ void qemu_aio_set_fd_handler(int fd,
  *
  * Returns: a pointer to the new timer
  */
-static inline QEMUTimer *aio_timer_new(AioContext *ctx, QEMUClockType type,
-                                       int scale,
-                                       QEMUTimerCB *cb, void *opaque)
+static inline QEMUTimer *aio_timer_new_dbg(AioContext *ctx, QEMUClockType type,
+                                           int scale,
+                                           QEMUTimerCB *cb, void *opaque,
+                                           const char *dbg)
 {
-    return timer_new_tl(ctx->tlg.tl[type], scale, cb, opaque);
+    return timer_new_tl_dbg(ctx->tlg.tl[type], scale, cb, opaque, dbg);
 }
 
+#define aio_timer_new(ctx, type, scale, opaque) \
+    aio_timer_new_dbg(ctx, type, scale, opaque, TIMER_DBG)
+
 /**
  * aio_timer_init:
  * @ctx: the aio context
@@ -284,9 +288,13 @@ static inline QEMUTimer *aio_timer_new(AioContext *ctx, QEMUClockType type,
 static inline void aio_timer_init(AioContext *ctx,
                                   QEMUTimer *ts, QEMUClockType type,
                                   int scale,
-                                  QEMUTimerCB *cb, void *opaque)
+                                  QEMUTimerCB *cb, void *opaque,
+                                  const char *dbg)
 {
-    timer_init(ts, ctx->tlg.tl[type], scale, cb, opaque);
+    timer_init_dbg(ts, ctx->tlg.tl[type], scale, cb, opaque, dbg);
 }
 
+#define aio_timer_init(ctx, ts, type, scale, cb, opaque) \
+    aio_timer_init(ctx, ts, type, scale, cb, opaque, TIMER_DBG)
+
 #endif
diff --git a/include/qemu/timer.h b/include/qemu/timer.h
index 5afcffc..d3ab5b0 100644
--- a/include/qemu/timer.h
+++ b/include/qemu/timer.h
@@ -11,6 +11,11 @@
 #define SCALE_US 1000
 #define SCALE_NS 1
 
+/* debugging macros */
+#define TIMER_STRINGIFY_(n) #n
+#define TIMER_STRINGIFY(n) TIMER_STRINGIFY_(n)
+#define TIMER_DBG __FILE__ ":" TIMER_STRINGIFY (__LINE__)
+
 /**
  * QEMUClockType:
  *
@@ -61,6 +66,12 @@ struct QEMUTimer {
     void *opaque;
     QEMUTimer *next;
     int scale;
+
+    /* these items are only used when debugging */
+    const char *dbg;
+    int64_t tot_deltas;
+    int64_t num_deltas;
+    int64_t num_short;
 };
 
 extern QEMUTimerListGroup main_loop_tlg;
@@ -415,9 +426,13 @@ int64_t timerlistgroup_deadline_ns(QEMUTimerListGroup *tlg);
  * You need not call an explicit deinit call. Simply make
  * sure it is not on a list with timer_del.
  */
-void timer_init(QEMUTimer *ts,
-                QEMUTimerList *timer_list, int scale,
-                QEMUTimerCB *cb, void *opaque);
+void timer_init_dbg(QEMUTimer *ts,
+                    QEMUTimerList *timer_list, int scale,
+                    QEMUTimerCB *cb, void *opaque,
+                    const char *dbg);
+
+#define timer_init(ts, timer_list, scale, cb, opaque) \
+    timer_init_dbg(ts, timer_list, scale, cb, opaque, TIMER_DBG)
 
 /**
  * timer_new_tl:
@@ -434,16 +449,20 @@ void timer_init(QEMUTimer *ts,
  *
  * Returns: a pointer to the timer
  */
-static inline QEMUTimer *timer_new_tl(QEMUTimerList *timer_list,
-                                      int scale,
-                                      QEMUTimerCB *cb,
-                                      void *opaque)
+static inline QEMUTimer *timer_new_tl_dbg(QEMUTimerList *timer_list,
+                                          int scale,
+                                          QEMUTimerCB *cb,
+                                          void *opaque,
+                                          const char *dbg)
 {
     QEMUTimer *ts = g_malloc0(sizeof(QEMUTimer));
-    timer_init(ts, timer_list, scale, cb, opaque);
+    timer_init_dbg(ts, timer_list, scale, cb, opaque, dbg);
     return ts;
 }
 
+#define timer_new_tl(timer_list, scale, cb, opaque) \
+    timer_new_tl_dbg(timer_list, scale, cb, opaque, TIMER_DBG)
+
 /**
  * timer_new:
  * @type: the clock type to use
@@ -456,12 +475,16 @@ static inline QEMUTimer *timer_new_tl(QEMUTimerList *timer_list,
  *
  * Returns: a pointer to the timer
  */
-static inline QEMUTimer *timer_new(QEMUClockType type, int scale,
-                                   QEMUTimerCB *cb, void *opaque)
+static inline QEMUTimer *timer_new_dbg(QEMUClockType type, int scale,
+                                       QEMUTimerCB *cb, void *opaque,
+                                       const char *dbg)
 {
-    return timer_new_tl(main_loop_tlg.tl[type], scale, cb, opaque);
+    return timer_new_tl_dbg(main_loop_tlg.tl[type], scale, cb, opaque, dbg);
 }
 
+#define timer_new(type, scale, cb, opaque) \
+    timer_new_dbg(type, scale, cb, opaque, TIMER_DBG)
+
 /**
  * timer_new_ns:
  * @clock: the clock to associate with the timer
@@ -473,12 +496,15 @@ static inline QEMUTimer *timer_new(QEMUClockType type, int scale,
  *
  * Returns: a pointer to the newly created timer
  */
-static inline QEMUTimer *timer_new_ns(QEMUClockType type, QEMUTimerCB *cb,
-                                      void *opaque)
+static inline QEMUTimer *timer_new_ns_dbg(QEMUClockType type, QEMUTimerCB *cb,
+                                          void *opaque, const char *dbg)
 {
-    return timer_new(type, SCALE_NS, cb, opaque);
+    return timer_new_dbg(type, SCALE_NS, cb, opaque, dbg);
 }
 
+#define timer_new_ns(type, cb, opaque) \
+    timer_new_ns_dbg(type, cb, opaque, TIMER_DBG)
+
 /**
  * timer_new_us:
  * @clock: the clock to associate with the timer
@@ -491,11 +517,14 @@ static inline QEMUTimer *timer_new_ns(QEMUClockType type, QEMUTimerCB *cb,
  * Returns: a pointer to the newly created timer
  */
 static inline QEMUTimer *timer_new_us(QEMUClockType type, QEMUTimerCB *cb,
-                                      void *opaque)
+                                      void *opaque, const char *dbg)
 {
-    return timer_new(type, SCALE_US, cb, opaque);
+    return timer_new_dbg(type, SCALE_US, cb, opaque, dbg);
 }
 
+#define timer_new_us(type, cb, opaque) \
+    timer_new_us_dbg(type, cb, opaque, TIMER_DBG)
+
 /**
  * timer_new_ms:
  * @clock: the clock to associate with the timer
@@ -507,11 +536,13 @@ static inline QEMUTimer *timer_new_us(QEMUClockType type, QEMUTimerCB *cb,
  *
  * Returns: a pointer to the newly created timer
  */
-static inline QEMUTimer *timer_new_ms(QEMUClockType type, QEMUTimerCB *cb,
-                                      void *opaque)
+static inline QEMUTimer *timer_new_ms_dbg(QEMUClockType type, QEMUTimerCB *cb,
+                                          void *opaque, const char *dbg)
 {
-    return timer_new(type, SCALE_MS, cb, opaque);
+    return timer_new_dbg(type, SCALE_MS, cb, opaque, dbg);
 }
+#define timer_new_ms(type, cb, opaque) \
+    timer_new_ms_dbg(type, cb, opaque, TIMER_DBG)
 
 /**
  * timer_free:
diff --git a/qemu-timer.c b/qemu-timer.c
index e15ce47..0e358ac 100644
--- a/qemu-timer.c
+++ b/qemu-timer.c
@@ -321,15 +321,17 @@ int qemu_poll_ns(GPollFD *fds, guint nfds, int64_t timeout)
 }
 
 
-void timer_init(QEMUTimer *ts,
-                QEMUTimerList *timer_list, int scale,
-                QEMUTimerCB *cb, void *opaque)
+void timer_init_dbg(QEMUTimer *ts,
+                    QEMUTimerList *timer_list, int scale,
+                    QEMUTimerCB *cb, void *opaque,
+                    const char *dbg)
 {
     ts->timer_list = timer_list;
     ts->cb = cb;
     ts->opaque = opaque;
     ts->scale = scale;
     ts->expire_time = -1;
+    ts->dbg = dbg;
 }
 
 void timer_free(QEMUTimer *ts)
-- 
1.7.9.5

[Qemu-devel] [PATCHv1 2/4] Timers: add command line option -timer-debug-log

[Alex Bligh]

Add a command line option -timer-debug-log which takes the name
of a file to which periodic timer debugging information will be
written.

Signed-off-by: Alex Bligh <alex@alex.org.uk>
---
 include/qemu/timer.h |    1 +
 qemu-options.hx      |   11 +++++++++++
 qemu-timer.c         |    1 +
 vl.c                 |    3 +++
 4 files changed, 16 insertions(+)

diff --git a/include/qemu/timer.h b/include/qemu/timer.h
index d3ab5b0..1f7c5e4 100644
--- a/include/qemu/timer.h
+++ b/include/qemu/timer.h
@@ -75,6 +75,7 @@ struct QEMUTimer {
 };
 
 extern QEMUTimerListGroup main_loop_tlg;
+extern const char *timer_debug_log;
 
 /*
  * QEMUClockType
diff --git a/qemu-options.hx b/qemu-options.hx
index 5dc8b75..605c1b9 100644
--- a/qemu-options.hx
+++ b/qemu-options.hx
@@ -3116,6 +3116,17 @@ STEXI
 prepend a timestamp to each log message.(default:on)
 ETEXI
 
+DEF("timer-debug-log", HAS_ARG, QEMU_OPTION_timer_debug_log,
+    "-timer-debug-log FILE\n"
+    "                write timer debug log to FILE (default: don't write)",
+    QEMU_ARCH_ALL)
+STEXI
+@item -timer-debug-log @var{file}
+@findex -timer-debug-log
+Write timer debug output periodically to file @var{file}. By default,
+no timer debug logging is written.
+ETEXI
+
 HXCOMM This is the last statement. Insert new options before this line!
 STEXI
 @end table
diff --git a/qemu-timer.c b/qemu-timer.c
index 0e358ac..84a8932 100644
--- a/qemu-timer.c
+++ b/qemu-timer.c
@@ -57,6 +57,7 @@ typedef struct QEMUClock {
 
 QEMUTimerListGroup main_loop_tlg;
 QEMUClock qemu_clocks[QEMU_CLOCK_MAX];
+const char *timer_debug_log;
 
 /* A QEMUTimerList is a list of timers attached to a clock. More
  * than one QEMUTimerList can be attached to each clock, for instance
diff --git a/vl.c b/vl.c
index b42ac67..4564207 100644
--- a/vl.c
+++ b/vl.c
@@ -3794,6 +3794,9 @@ int main(int argc, char **argv, char **envp)
                 }
                 configure_msg(opts);
                 break;
+            case QEMU_OPTION_timer_debug_log:
+                timer_debug_log = optarg;
+                break;
             default:
                 os_parse_cmd_args(popt->index, optarg);
             }
-- 
1.7.9.5

[Qemu-devel] [PATCHv1 3/4] Timers: Instrument timer_mod

[Alex Bligh]

Add instrumentation for timer_mod to allow measurement of the
average time delta to expiry plus the number of short delta
periods. This is only run when logging to a file because
getting the clock value may add appreciable expense.

Signed-off-by: Alex Bligh <alex@alex.org.uk>
---
 qemu-timer.c |   17 +++++++++++++++++
 1 file changed, 17 insertions(+)

diff --git a/qemu-timer.c b/qemu-timer.c
index 84a8932..16eaa1f 100644
--- a/qemu-timer.c
+++ b/qemu-timer.c
@@ -376,6 +376,23 @@ static bool timer_mod_ns_locked(QEMUTimerList *timer_list,
     ts->next = *pt;
     *pt = ts;
 
+    if (timer_debug_log) {
+        int64_t delta;
+
+        delta = ts->expire_time -
+            qemu_clock_get_ns(ts->timer_list->clock->type);
+        if (delta <= 0) {
+            delta = 0;
+        }
+
+        ts->tot_deltas += delta;
+        ts->num_deltas++;
+
+        if (delta < SCALE_US) {
+            ts->num_short++;
+        }
+    }
+
     return pt == &timer_list->active_timers;
 }
 
-- 
1.7.9.5

[Qemu-devel] [PATCHv1 4/4] Timers: produce timer-debug-log file

[Alex Bligh]

Write a timer-debug-log file if enabled containing data about the
currently existing timers.

Signed-off-by: Alex Bligh <alex@alex.org.uk>
---
 qemu-timer.c |   92 ++++++++++++++++++++++++++++++++++++++++++++++++++++++++++
 1 file changed, 92 insertions(+)

diff --git a/qemu-timer.c b/qemu-timer.c
index 16eaa1f..cbce7ba 100644
--- a/qemu-timer.c
+++ b/qemu-timer.c
@@ -58,6 +58,7 @@ typedef struct QEMUClock {
 QEMUTimerListGroup main_loop_tlg;
 QEMUClock qemu_clocks[QEMU_CLOCK_MAX];
 const char *timer_debug_log;
+static int64_t timer_last_debug;
 
 /* A QEMUTimerList is a list of timers attached to a clock. More
  * than one QEMUTimerList can be attached to each clock, for instance
@@ -396,6 +397,93 @@ static bool timer_mod_ns_locked(QEMUTimerList *timer_list,
     return pt == &timer_list->active_timers;
 }
 
+static void timer_debug(void)
+{
+    GString *debug_text;
+    GString *tmpfile;
+    QEMUClockType type;
+    FILE *f;
+    uint64_t now;
+
+    if (!timer_debug_log) {
+        return;
+    }
+
+    /* In order not to avoid influencing the output, we don't use a timer
+     * here, but use this disappointingly manual method.
+     */
+    now = qemu_clock_get_ns(QEMU_CLOCK_REALTIME);
+    if ((now - timer_last_debug) < 1000 * SCALE_MS) {
+        return;
+    }
+    timer_last_debug = now;
+
+    debug_text = g_string_new("");
+    tmpfile = g_string_new(timer_debug_log);
+    g_string_append(tmpfile, ".tmp");
+
+    for (type = 0; type < QEMU_CLOCK_MAX; type++) {
+        QEMUTimerList *timer_list;
+        QEMUClock *clock = qemu_clock_ptr(type);
+
+        /* Iteration through timerlists means we need the BQL held to
+         * call this safely.
+         */
+        QLIST_FOREACH(timer_list, &clock->timerlists, list) {
+            QEMUTimer *ts;
+
+            g_string_append_printf(debug_text, "\nTimer list at %p clock %d:\n",
+                                   timer_list, (int) type);
+            g_string_append_printf(debug_text, "%18s %14s %14s %14s %s\n",
+                                   "Address",
+                                   "Expiries",
+                                   "AvgLength",
+                                   "NumShort",
+                                   "Source");
+            qemu_mutex_lock(&timer_list->active_timers_lock);
+            ts = timer_list->active_timers;
+            for (ts = timer_list->active_timers; ts; ts = ts->next) {
+                int64_t avg = -1;
+                if (ts->num_deltas) {
+                    avg = (ts->tot_deltas + (ts->num_deltas/2)) /
+                        ts->num_deltas;
+                }
+                const char *src = "unknown";
+                if (ts->dbg) {
+                    const char *slash;
+                    src = ts->dbg;
+                    slash = strrchr(src, '/');
+                    if (!slash) {
+                        slash = strrchr(src, '\\');
+                    }
+                    if (slash) {
+                        src = slash+1;
+                    }
+                }
+
+                g_string_append_printf(debug_text, "%18p %14" PRId64 " %14"
+                                       PRId64 " %14" PRId64" %s\n",
+                                       ts,
+                                       ts->num_deltas,
+                                       avg,
+                                       ts->num_short,
+                                       src);
+            }
+            qemu_mutex_unlock(&timer_list->active_timers_lock);
+        }
+    }
+
+    f = fopen(tmpfile->str, "w");
+    if (f) {
+        fprintf(f, "%s", debug_text->str);
+        fclose(f);
+        rename(tmpfile->str, timer_debug_log);
+    }
+
+    g_string_free(tmpfile, true);
+    g_string_free(debug_text, true);
+}
+
 static void timerlist_rearm(QEMUTimerList *timer_list)
 {
     /* Interrupt execution to force deadline recalculation.  */
@@ -621,6 +709,10 @@ bool qemu_clock_run_all_timers(void)
     bool progress = false;
     QEMUClockType type;
 
+    if (timer_debug_log) {
+        timer_debug();
+    }
+
     for (type = 0; type < QEMU_CLOCK_MAX; type++) {
         progress |= qemu_clock_run_timers(type);
     }
-- 
1.7.9.5

Re: [Qemu-devel] [PATCHv1 0/4] Timers: add timer debugging through -timer-debug-log

[Paolo Bonzini]

Il 25/10/2013 23:30, Alex Bligh ha scritto:
> This patch set adds facilities for debugging timers using the additional
> command line option -timer-debug-log=FILE. If this option is selected,
> a debugging file will be written showing information about the current
> state of timers in the system, which the author feels will be useful for
> debugging in the field.
> 
> Note that the option is a command line option rather than a configure
> time option. This is because users in the field having issues are unlikely
> to have a compile time option enabled.
> 
> It would be useful to get this feature in prior to 1.7 as it has little
> impact other than making a major change to a subsystem more debuggable.
> This patch has been lightly test.
> 
> Impact of changes whether or not -timer-debug-log is specified:
> 
> 1. QEMUTimer is expanded to hold additional debugging information. Some
>    of this is unused when the command line option is unspecified.
> 
> 2. The file and line number of the caller that allocated the timer are
>    recorded. This is useful for debugging in gdb.
> 
> It is felt these are minimal in nature.
> 
> Additional impact of changes only when -timer-debug-log is specified:
> 
> 1. On every timer modification, the current clock time for that timer
>    is read, and the additional debug information filled in.
> 
> 2. Every second (roughly) a file is written (atomically) containing the
>    timer debug information.
> 
> The debug information includes information on the number of timer
> expiries since the timer was created, the average expiry time (in
> nanoseconds), and the number of short expiries, being the number of
> times the timer was asked to expire in less than one microsecond
> (these usually but not always indicate a bug).
> 
> The file format is designed to be useful both to a mailing list and
> to a user armed with gdb. An example of the output follows:
> 
> Timer list at 0x7f4d6cf0d6e0 clock 0:
>            Address       Expiries      AvgLength       NumShort Source
> 
> Timer list at 0x7f4d6cf0cbc0 clock 0:
>            Address       Expiries      AvgLength       NumShort Source
> 
> Timer list at 0x7f4d6cf0d750 clock 1:
>            Address       Expiries      AvgLength       NumShort Source
> 
> Timer list at 0x7f4d6cf0cc30 clock 1:
>            Address       Expiries      AvgLength       NumShort Source
>     0x7f4d6cf51550              1       27462700              0 i8254.c:333
> 
> Timer list at 0x7f4d6cf0d7c0 clock 2:
>            Address       Expiries      AvgLength       NumShort Source
> 
> Timer list at 0x7f4d6cf0cca0 clock 2:
>            Address       Expiries      AvgLength       NumShort Source
>     0x7f4d6cf6eed0              1      999997000              0 mc146818rtc.c:858
> 
> Note that the somewhat strange choice to output to a file has been taken
> because the tracing infrastructure is unlikely to be enabled in a distro
> environment.

This is a bug in the distro, if it is Linux.  There is no reason not to
enable the stap trace format when running on Linux (Fedora does for
other packages than QEMU, too---most notably glib and glibc).

If it is useful, adding debugging information to timer_new_ns (please
make file and line two separate arguments, though) can definitely be
done unconditionally and added to the traces.  I think adding a
tracepoint in timerlist_run_timers would provide very similar
information to that in your file.

Paolo

Re: [Qemu-devel] [PATCHv1 0/4] Timers: add timer debugging through -timer-debug-log

[Alex Bligh]

On 26 Oct 2013, at 00:00, Paolo Bonzini wrote:

> his is a bug in the distro, if it is Linux.  There is no reason not to
> enable the stap trace format when running on Linux (Fedora does for
> other packages than QEMU, too---most notably glib and glibc).
> 
> If it is useful, adding debugging information to timer_new_ns (please
> make file and line two separate arguments, though) can definitely be
> done unconditionally and added to the traces.  I think adding a
> tracepoint in timerlist_run_timers would provide very similar
> information to that in your file.

I read the tracepoint information. Doesn't that require the end
user to have far more skills (and far more stuff installed) to
get things like "average expiry delta"? Especially as that's
not something we'd normally calculate as we don't get the clock
value when setting a timer normally.

-- 
Alex Bligh

Re: [Qemu-devel] [PATCHv1 0/4] Timers: add timer debugging through -timer-debug-log

[Paolo Bonzini]

Il 26/10/2013 06:52, Alex Bligh ha scritto:
> 
> On 26 Oct 2013, at 00:00, Paolo Bonzini wrote:
> 
>> his is a bug in the distro, if it is Linux.  There is no reason not to
>> enable the stap trace format when running on Linux (Fedora does for
>> other packages than QEMU, too---most notably glib and glibc).
>>
>> If it is useful, adding debugging information to timer_new_ns (please
>> make file and line two separate arguments, though) can definitely be
>> done unconditionally and added to the traces.  I think adding a
>> tracepoint in timerlist_run_timers would provide very similar
>> information to that in your file.
> 
> I read the tracepoint information. Doesn't that require the end
> user to have far more skills (and far more stuff installed) to
> get things like "average expiry delta"? Especially as that's
> not something we'd normally calculate as we don't get the clock
> value when setting a timer normally.

The simple trace backend includes a nanosecond value that is the same as
rt_clock, so you can correlate the last timer_mod with the next
iteration in timerlist_run_timers (I would put the tracepoint inside the
loop, just before the callback is done).  Similarly, in systemtap you
can just use the builtin gettimeofday_ns() function

All clocks are basically in nanoseconds (the only difference between
vm_clock and rt_clock is that the former stops when the VM is stopped),
so you can get the average expiry delta from there.

Of course it requires some postprocessing or a systemtap script, but we
can put that into scripts/ or give it to the user.  See
https://sourceware.org/ml/systemtap/2011-q3/txt00003.txt for an example,
I suppose the "expiry time" computation would look like this:

global modtime, expirytot, firedcnt

probe qemu.system.x86_64.timer_mod {
   loc = sprintf("%s:%d", timer_file, timer_line)
   modtime[pid(), loc] = gettimeofday_ns()
}
probe qemu.system.x86_64.timer_run {
   loc = sprintf("%s:%d", timer_file, timer_line)
   expirytot[pid(), loc] += gettimeofday_ns() - modtime[pid(), loc]
   firedcnt[pid(), loc]++
}

probe end
{
  printf("\n%8s %28s %8s %8s\n", "pid", "loc", "avg expiry", "cnt")
  foreach([p+, loc] in firedcnt) {
    printf("%8d %28s %8d %8d\n", p, loc,
        expirytot[p, loc] / firedcnt[p, loc],
        firedcnt[p, loc])
  }
}

which I wrote based on the example at
http://cygwin.com/ml/systemtap/2011-q3/msg00316.html

I understand your usecase, but it's not really feasible to add a logging
option for each tracing need; it's much better to add new tracepoints
and distribute sample systemtap scripts.  And please "lobby" your distro
for enabling systemtap support and distributing the .stp file!

Paolo

Re: [Qemu-devel] [PATCHv1 0/4] Timers: add timer debugging through -timer-debug-log

[Alex Bligh]

Paolo,

On 26 Oct 2013, at 08:18, Paolo Bonzini wrote:

> The simple trace backend includes a nanosecond value that is the same as
> rt_clock, so you can correlate the last timer_mod with the next
> iteration in timerlist_run_timers (I would put the tracepoint inside the
> loop, just before the callback is done).  Similarly, in systemtap you
> can just use the builtin gettimeofday_ns() function
> 
> All clocks are basically in nanoseconds (the only difference between
> vm_clock and rt_clock is that the former stops when the VM is stopped),
> so you can get the average expiry delta from there.
> 
> Of course it requires some postprocessing or a systemtap script, but we
> can put that into scripts/ or give it to the user.  See
> https://sourceware.org/ml/systemtap/2011-q3/txt00003.txt for an example,
> I suppose the "expiry time" computation would look like this:

OK I need to look at the tracepoint stuff a bit more it seems :-)

If we can do this without a patch (save to put some tracepoints in),
that's obviously better than doing it with a patch. I don't like
the file particularly either.

> global modtime, expirytot, firedcnt
> 
> probe qemu.system.x86_64.timer_mod {
>   loc = sprintf("%s:%d", timer_file, timer_line)

How do timer_file and timer_line get filled in? If those still
need to be put in through code changes, how about taking
patch 1 of the series (that fills in timer->dbg with this
information), save for the unnecessary additions to the structure,
plus whatever is necessary to put the tracepoints in?

Alex

>   modtime[pid(), loc] = gettimeofday_ns()
> }
> probe qemu.system.x86_64.timer_run {
>   loc = sprintf("%s:%d", timer_file, timer_line)
>   expirytot[pid(), loc] += gettimeofday_ns() - modtime[pid(), loc]
>   firedcnt[pid(), loc]++
> }
> 
> probe end
> {
>  printf("\n%8s %28s %8s %8s\n", "pid", "loc", "avg expiry", "cnt")
>  foreach([p+, loc] in firedcnt) {
>    printf("%8d %28s %8d %8d\n", p, loc,
>        expirytot[p, loc] / firedcnt[p, loc],
>        firedcnt[p, loc])
>  }
> }

-- 
Alex Bligh

Re: [Qemu-devel] [PATCHv1 0/4] Timers: add timer debugging through -timer-debug-log

[Paolo Bonzini]

Il 26/10/2013 10:24, Alex Bligh ha scritto:
> How do timer_file and timer_line get filled in? If those still
> need to be put in through code changes, how about taking
> patch 1 of the series (that fills in timer->dbg with this
> information), save for the unnecessary additions to the structure,
> plus whatever is necessary to put the tracepoints in?

Sure!

Paolo