[Qemu-devel] [PATCHv2 0/4] qxl: debug related fixes

[Qemu-devel] [PATCHv2 0/4] qxl: debug related fixes

[Alon Levy]

These patches contain three small fixes, and one patch requiring more
review that adds support for using chardevs for specific debug information:
one for guest debug prints, and another for qxl command ring logging. This
allows easier parsing and logging of this data for debugging.

v1->v2:
 use qemu_get_clock_ns, replaced qemu_get_clock
 last patch (allow QXL_IO_LOG) fixed to use existing switch cases (and fixed the
 redundant parenthesis in the process).

Alon Levy (4):
  qxl: interface_get_command: fix reported mode
  qxl: add mode to debugprint on destroy primary
  qxl: add debug_cs and cmdlog_cs
  qxl: allow QXL_IO_LOG also in vga

 hw/qxl-logger.c |   62 ++++++++++++++++++++++++++++++++++--------------------
 hw/qxl.c        |   35 +++++++++++++++++++++++++++---
 hw/qxl.h        |    2 +
 3 files changed, 72 insertions(+), 27 deletions(-)

-- 
1.7.4.4

[Qemu-devel] [PATCHv2 1/4] qxl: interface_get_command: fix reported mode

[Alon Levy]

report correct mode when in undefined mode.
---
 hw/qxl.c |   18 ++++++++++++++++--
 1 files changed, 16 insertions(+), 2 deletions(-)

diff --git a/hw/qxl.c b/hw/qxl.c
index fe4212b..63e295b 100644
--- a/hw/qxl.c
+++ b/hw/qxl.c
@@ -336,6 +336,21 @@ static void interface_get_init_info(QXLInstance *sin, QXLDevInitInfo *info)
     info->n_surfaces = NUM_SURFACES;
 }
 
+static const char *qxl_mode_to_string(int mode)
+{
+    switch (mode) {
+    case QXL_MODE_COMPAT:
+        return "compat";
+    case QXL_MODE_NATIVE:
+        return "native";
+    case QXL_MODE_UNDEFINED:
+        return "undefined";
+    case QXL_MODE_VGA:
+        return "vga";
+    }
+    return "unknown";
+}
+
 /* called from spice server thread context only */
 static int interface_get_command(QXLInstance *sin, struct QXLCommandExt *ext)
 {
@@ -358,8 +373,7 @@ static int interface_get_command(QXLInstance *sin, struct QXLCommandExt *ext)
     case QXL_MODE_COMPAT:
     case QXL_MODE_NATIVE:
     case QXL_MODE_UNDEFINED:
-        dprint(qxl, 2, "%s: %s\n", __FUNCTION__,
-               qxl->cmdflags ? "compat" : "native");
+        dprint(qxl, 2, "%s: %s\n", __FUNCTION__, qxl_mode_to_string(qxl->mode));
         ring = &qxl->ram->cmd_ring;
         if (SPICE_RING_IS_EMPTY(ring)) {
             return false;
-- 
1.7.4.4

[Qemu-devel] [PATCHv2 2/4] qxl: add mode to debugprint on destroy primary

[Alon Levy]

---
 hw/qxl.c |    2 +-
 1 files changed, 1 insertions(+), 1 deletions(-)

diff --git a/hw/qxl.c b/hw/qxl.c
index 63e295b..ccd820c 100644
--- a/hw/qxl.c
+++ b/hw/qxl.c
@@ -1009,7 +1009,7 @@ static void ioport_write(void *opaque, uint32_t addr, uint32_t val)
         break;
     case QXL_IO_DESTROY_PRIMARY:
         PANIC_ON(val != 0);
-        dprint(d, 1, "QXL_IO_DESTROY_PRIMARY\n");
+        dprint(d, 1, "QXL_IO_DESTROY_PRIMARY (%s)\n", qxl_mode_to_string(d->mode));
         qxl_destroy_primary(d);
         break;
     case QXL_IO_DESTROY_SURFACE_WAIT:
-- 
1.7.4.4

[Qemu-devel] [PATCHv2 3/4] qxl: add debug_cs and cmdlog_cs

[Alon Levy]

With this you can output the command log and/or the guest debug (driver)
output to a chardev instead of stderr:

-global qxl-vga.cmdlog_chardev=qxl_cmdlog_chardev
-global qxl-vga.debug_chardev=qxl_debug_chardev

useful for debugging. if no chardev is specified prints to stderr like the old
code.
---
 hw/qxl-logger.c |   62 ++++++++++++++++++++++++++++++++++--------------------
 hw/qxl.c        |   14 +++++++++++-
 hw/qxl.h        |    2 +
 3 files changed, 54 insertions(+), 24 deletions(-)

diff --git a/hw/qxl-logger.c b/hw/qxl-logger.c
index 76f43e6..df6e78b 100644
--- a/hw/qxl-logger.c
+++ b/hw/qxl-logger.c
@@ -99,6 +99,22 @@ static const char *qxl_v2n(const char *n[], size_t l, int v)
 }
 #define qxl_name(_list, _value) qxl_v2n(_list, ARRAY_SIZE(_list), _value)
 
+static void qxl_log_printf(PCIQXLDevice *qxl, const char *format, ...)
+{
+    va_list ap;
+    uint8_t buf[4096];
+
+    va_start(ap, format);
+    if (qxl->cmdlog_cs) {
+        vsnprintf((char *)buf, sizeof(buf), format, ap);
+        buf[sizeof(buf) - 1] = '\0';
+        qemu_chr_write(qxl->cmdlog_cs, buf, strlen((char*)buf));
+    } else {
+        vfprintf(stderr, format, ap);
+    }
+    va_end(ap);
+}
+
 static void qxl_log_image(PCIQXLDevice *qxl, QXLPHYSICAL addr, int group_id)
 {
     QXLImage *image;
@@ -106,11 +122,11 @@ static void qxl_log_image(PCIQXLDevice *qxl, QXLPHYSICAL addr, int group_id)
 
     image = qxl_phys2virt(qxl, addr, group_id);
     desc = &image->descriptor;
-    fprintf(stderr, " (id %" PRIx64 " type %d flags %d width %d height %d",
+    qxl_log_printf(qxl, " (id %" PRIx64 " type %d flags %d width %d height %d",
             desc->id, desc->type, desc->flags, desc->width, desc->height);
     switch (desc->type) {
     case SPICE_IMAGE_TYPE_BITMAP:
-        fprintf(stderr, ", fmt %d flags %d x %d y %d stride %d"
+        qxl_log_printf(qxl, ", fmt %d flags %d x %d y %d stride %d"
                 " palette %" PRIx64 " data %" PRIx64,
                 image->bitmap.format, image->bitmap.flags,
                 image->bitmap.x, image->bitmap.y,
@@ -118,12 +134,12 @@ static void qxl_log_image(PCIQXLDevice *qxl, QXLPHYSICAL addr, int group_id)
                 image->bitmap.palette, image->bitmap.data);
         break;
     }
-    fprintf(stderr, ")");
+    qxl_log_printf(qxl, ")");
 }
 
-static void qxl_log_rect(QXLRect *rect)
+static void qxl_log_rect(PCIQXLDevice *qxl, QXLRect *rect)
 {
-    fprintf(stderr, " %dx%d+%d+%d",
+    qxl_log_printf(qxl, " %dx%d+%d+%d",
             rect->right - rect->left,
             rect->bottom - rect->top,
             rect->left, rect->top);
@@ -131,17 +147,17 @@ static void qxl_log_rect(QXLRect *rect)
 
 static void qxl_log_cmd_draw_copy(PCIQXLDevice *qxl, QXLCopy *copy, int group_id)
 {
-    fprintf(stderr, " src %" PRIx64,
+    qxl_log_printf(qxl, " src %" PRIx64,
             copy->src_bitmap);
     qxl_log_image(qxl, copy->src_bitmap, group_id);
-    fprintf(stderr, " area");
-    qxl_log_rect(&copy->src_area);
-    fprintf(stderr, " rop %d", copy->rop_descriptor);
+    qxl_log_printf(qxl, " area");
+    qxl_log_rect(qxl, &copy->src_area);
+    qxl_log_printf(qxl, " rop %d", copy->rop_descriptor);
 }
 
 static void qxl_log_cmd_draw(PCIQXLDevice *qxl, QXLDrawable *draw, int group_id)
 {
-    fprintf(stderr, ": surface_id %d type %s effect %s",
+    qxl_log_printf(qxl, ": surface_id %d type %s effect %s",
             draw->surface_id,
             qxl_name(qxl_draw_type, draw->type),
             qxl_name(qxl_draw_effect, draw->effect));
@@ -155,13 +171,13 @@ static void qxl_log_cmd_draw(PCIQXLDevice *qxl, QXLDrawable *draw, int group_id)
 static void qxl_log_cmd_draw_compat(PCIQXLDevice *qxl, QXLCompatDrawable *draw,
                                     int group_id)
 {
-    fprintf(stderr, ": type %s effect %s",
+    qxl_log_printf(qxl, ": type %s effect %s",
             qxl_name(qxl_draw_type, draw->type),
             qxl_name(qxl_draw_effect, draw->effect));
     if (draw->bitmap_offset) {
-        fprintf(stderr, ": bitmap %d",
+        qxl_log_printf(qxl, ": bitmap %d",
                 draw->bitmap_offset);
-        qxl_log_rect(&draw->bitmap_area);
+        qxl_log_rect(qxl, &draw->bitmap_area);
     }
     switch (draw->type) {
     case QXL_DRAW_COPY:
@@ -172,11 +188,11 @@ static void qxl_log_cmd_draw_compat(PCIQXLDevice *qxl, QXLCompatDrawable *draw,
 
 static void qxl_log_cmd_surface(PCIQXLDevice *qxl, QXLSurfaceCmd *cmd)
 {
-    fprintf(stderr, ": %s id %d",
+    qxl_log_printf(qxl, ": %s id %d",
             qxl_name(qxl_surface_cmd, cmd->type),
             cmd->surface_id);
     if (cmd->type == QXL_SURFACE_CMD_CREATE) {
-        fprintf(stderr, " size %dx%d stride %d format %s (count %d, max %d)",
+        qxl_log_printf(qxl, " size %dx%d stride %d format %s (count %d, max %d)",
                 cmd->u.surface_create.width,
                 cmd->u.surface_create.height,
                 cmd->u.surface_create.stride,
@@ -184,7 +200,7 @@ static void qxl_log_cmd_surface(PCIQXLDevice *qxl, QXLSurfaceCmd *cmd)
                 qxl->guest_surfaces.count, qxl->guest_surfaces.max);
     }
     if (cmd->type == QXL_SURFACE_CMD_DESTROY) {
-        fprintf(stderr, " (count %d)", qxl->guest_surfaces.count);
+        qxl_log_printf(qxl, " (count %d)", qxl->guest_surfaces.count);
     }
 }
 
@@ -192,17 +208,17 @@ void qxl_log_cmd_cursor(PCIQXLDevice *qxl, QXLCursorCmd *cmd, int group_id)
 {
     QXLCursor *cursor;
 
-    fprintf(stderr, ": %s",
+    qxl_log_printf(qxl, ": %s",
             qxl_name(qxl_cursor_cmd, cmd->type));
     switch (cmd->type) {
     case QXL_CURSOR_SET:
-        fprintf(stderr, " +%d+%d visible %s, shape @ 0x%" PRIx64,
+        qxl_log_printf(qxl, " +%d+%d visible %s, shape @ 0x%" PRIx64,
                 cmd->u.set.position.x,
                 cmd->u.set.position.y,
                 cmd->u.set.visible ? "yes" : "no",
                 cmd->u.set.shape);
         cursor = qxl_phys2virt(qxl, cmd->u.set.shape, group_id);
-        fprintf(stderr, " type %s size %dx%d hot-spot +%d+%d"
+        qxl_log_printf(qxl, " type %s size %dx%d hot-spot +%d+%d"
                 " unique 0x%" PRIx64 " data-size %d",
                 qxl_name(spice_cursor_type, cursor->header.type),
                 cursor->header.width, cursor->header.height,
@@ -210,7 +226,7 @@ void qxl_log_cmd_cursor(PCIQXLDevice *qxl, QXLCursorCmd *cmd, int group_id)
                 cursor->header.unique, cursor->data_size);
         break;
     case QXL_CURSOR_MOVE:
-        fprintf(stderr, " +%d+%d", cmd->u.position.x, cmd->u.position.y);
+        qxl_log_printf(qxl, " +%d+%d", cmd->u.position.x, cmd->u.position.y);
         break;
     }
 }
@@ -223,8 +239,8 @@ void qxl_log_command(PCIQXLDevice *qxl, const char *ring, QXLCommandExt *ext)
     if (!qxl->cmdlog) {
         return;
     }
-    fprintf(stderr, "qxl-%d/%s:", qxl->id, ring);
-    fprintf(stderr, " cmd @ 0x%" PRIx64 " %s%s", ext->cmd.data,
+    qxl_log_printf(qxl, "qxl-%d/%s:", qxl->id, ring);
+    qxl_log_printf(qxl, " cmd @ 0x%" PRIx64 " %s%s", ext->cmd.data,
             qxl_name(qxl_type, ext->cmd.type),
             compat ? "(compat)" : "");
 
@@ -244,5 +260,5 @@ void qxl_log_command(PCIQXLDevice *qxl, const char *ring, QXLCommandExt *ext)
         qxl_log_cmd_cursor(qxl, data, ext->group_id);
         break;
     }
-    fprintf(stderr, "\n");
+    qxl_log_printf(qxl, "\n");
 }
diff --git a/hw/qxl.c b/hw/qxl.c
index ccd820c..ecab001 100644
--- a/hw/qxl.c
+++ b/hw/qxl.c
@@ -933,6 +933,7 @@ static void ioport_write(void *opaque, uint32_t addr, uint32_t val)
 {
     PCIQXLDevice *d = opaque;
     uint32_t io_port = addr - d->io_base;
+    uint8_t guest_debug_cs_buf[QXL_LOG_BUF_SIZE];
 
     switch (io_port) {
     case QXL_IO_RESET:
@@ -984,8 +985,15 @@ static void ioport_write(void *opaque, uint32_t addr, uint32_t val)
         qxl_set_mode(d, val, 0);
         break;
     case QXL_IO_LOG:
+        d->ram->log_buf[QXL_LOG_BUF_SIZE - 1] = '\0';
         if (d->guestdebug) {
-            fprintf(stderr, "qxl/guest: %s", d->ram->log_buf);
+            if (d->debug_cs) {
+                snprintf((char*)guest_debug_cs_buf, QXL_LOG_BUF_SIZE, "%ld %s",
+                         qemu_get_clock_ns(vm_clock), d->ram->log_buf);
+                qemu_chr_write(d->debug_cs, guest_debug_cs_buf, strlen((char*)guest_debug_cs_buf));
+            } else {
+                fprintf(stderr, "qxl/guest: %s", d->ram->log_buf);
+            }
         }
         break;
     case QXL_IO_RESET:
@@ -1514,6 +1522,8 @@ static PCIDeviceInfo qxl_info_primary = {
         DEFINE_PROP_UINT32("debug", PCIQXLDevice, debug, 0),
         DEFINE_PROP_UINT32("guestdebug", PCIQXLDevice, guestdebug, 0),
         DEFINE_PROP_UINT32("cmdlog", PCIQXLDevice, cmdlog, 0),
+        DEFINE_PROP_CHR("debug_chardev", PCIQXLDevice, debug_cs),
+        DEFINE_PROP_CHR("cmdlog_chardev", PCIQXLDevice, cmdlog_cs),
         DEFINE_PROP_END_OF_LIST(),
     }
 };
@@ -1532,6 +1542,8 @@ static PCIDeviceInfo qxl_info_secondary = {
         DEFINE_PROP_UINT32("debug", PCIQXLDevice, debug, 0),
         DEFINE_PROP_UINT32("guestdebug", PCIQXLDevice, guestdebug, 0),
         DEFINE_PROP_UINT32("cmdlog", PCIQXLDevice, cmdlog, 0),
+        DEFINE_PROP_CHR("debug_chardev", PCIQXLDevice, debug_cs),
+        DEFINE_PROP_CHR("cmdlog_chardev", PCIQXLDevice, cmdlog_cs),
         DEFINE_PROP_END_OF_LIST(),
     }
 };
diff --git a/hw/qxl.h b/hw/qxl.h
index f6c450d..2384c4e 100644
--- a/hw/qxl.h
+++ b/hw/qxl.h
@@ -22,6 +22,8 @@ typedef struct PCIQXLDevice {
     uint32_t           debug;
     uint32_t           guestdebug;
     uint32_t           cmdlog;
+    CharDriverState   *debug_cs;
+    CharDriverState   *cmdlog_cs;
     enum qxl_mode      mode;
     uint32_t           cmdflags;
     int                generation;
-- 
1.7.4.4

[Qemu-devel] [PATCHv2 4/4] qxl: allow QXL_IO_LOG also in vga

[Alon Levy]

The driver may change us to vga mode and still issue a QXL_IO_LOG,
which we can easily support.
---
 hw/qxl.c |    1 +
 1 files changed, 1 insertions(+), 0 deletions(-)

diff --git a/hw/qxl.c b/hw/qxl.c
index ecab001..d55f96a 100644
--- a/hw/qxl.c
+++ b/hw/qxl.c
@@ -941,6 +941,7 @@ static void ioport_write(void *opaque, uint32_t addr, uint32_t val)
     case QXL_IO_MEMSLOT_ADD:
     case QXL_IO_MEMSLOT_DEL:
     case QXL_IO_CREATE_PRIMARY:
+    case QXL_IO_LOG:
         break;
     default:
         if (d->mode == QXL_MODE_NATIVE || d->mode == QXL_MODE_COMPAT)
-- 
1.7.4.4

Re: [Qemu-devel] [PATCHv2 1/4] qxl: interface_get_command: fix reported mode

[Gerd Hoffmann]

> +static const char *qxl_mode_to_string(int mode)
> +{
> +    switch (mode) {
> +    case QXL_MODE_COMPAT:
> +        return "compat";
> +    case QXL_MODE_NATIVE:
> +        return "native";
> +    case QXL_MODE_UNDEFINED:
> +        return "undefined";
> +    case QXL_MODE_VGA:
> +        return "vga";
> +    }
> +    return "unknown";

Make that "INVALID"?  There never ever should be another move value ...

cheers,
   Gerd

Re: [Qemu-devel] [PATCHv2 2/4] qxl: add mode to debugprint on destroy primary

[Gerd Hoffmann]

On 04/28/11 10:29, Alon Levy wrote:
> ---
>   hw/qxl.c |    2 +-
>   1 files changed, 1 insertions(+), 1 deletions(-)
>
> diff --git a/hw/qxl.c b/hw/qxl.c
> index 63e295b..ccd820c 100644
> --- a/hw/qxl.c
> +++ b/hw/qxl.c
> @@ -1009,7 +1009,7 @@ static void ioport_write(void *opaque, uint32_t addr, uint32_t val)
>           break;
>       case QXL_IO_DESTROY_PRIMARY:
>           PANIC_ON(val != 0);
> -        dprint(d, 1, "QXL_IO_DESTROY_PRIMARY\n");
> +        dprint(d, 1, "QXL_IO_DESTROY_PRIMARY (%s)\n", qxl_mode_to_string(d->mode));
>           qxl_destroy_primary(d);
>           break;
>       case QXL_IO_DESTROY_SURFACE_WAIT:

Squash into the first?  Maybe there are a few more places where a 
pretty-printed mode would be useful?

cheers,
   Gerd

Re: [Qemu-devel] [PATCHv2 3/4] qxl: add debug_cs and cmdlog_cs

[Gerd Hoffmann]

On 04/28/11 10:29, Alon Levy wrote:
> With this you can output the command log and/or the guest debug (driver)
> output to a chardev instead of stderr:
>
> -global qxl-vga.cmdlog_chardev=qxl_cmdlog_chardev
> -global qxl-vga.debug_chardev=qxl_debug_chardev
>
> useful for debugging. if no chardev is specified prints to stderr like the old
> code.

Hmm.  That is a bit too much ad-hoc debug hacking IMHO.  Also I'm not 
sure I like the idea to send debug stuff through chardev instead of just 
writing them to stderr or some logfile.

I do see why you are doing that though.  Unfortunaly qemu has no sane 
debug logging infrastructure.  This is long overdue IMHO, so we don't 
need hacks like this one and also don't reinvent stuff over and over.

cheers,
   Gerd

Re: [Qemu-devel] [PATCHv2 1/4] qxl: interface_get_command: fix reported mode

[Alon Levy]

On Fri, Apr 29, 2011 at 02:01:16PM +0200, Gerd Hoffmann wrote:
> >+static const char *qxl_mode_to_string(int mode)
> >+{
> >+    switch (mode) {
> >+    case QXL_MODE_COMPAT:
> >+        return "compat";
> >+    case QXL_MODE_NATIVE:
> >+        return "native";
> >+    case QXL_MODE_UNDEFINED:
> >+        return "undefined";
> >+    case QXL_MODE_VGA:
> >+        return "vga";
> >+    }
> >+    return "unknown";
> 
> Make that "INVALID"?  There never ever should be another move value ...
True, will do.

> 
> cheers,
>   Gerd

Re: [Qemu-devel] [PATCHv2 2/4] qxl: add mode to debugprint on destroy primary

[Alon Levy]

On Fri, Apr 29, 2011 at 02:01:57PM +0200, Gerd Hoffmann wrote:
> On 04/28/11 10:29, Alon Levy wrote:
> >---
> >  hw/qxl.c |    2 +-
> >  1 files changed, 1 insertions(+), 1 deletions(-)
> >
> >diff --git a/hw/qxl.c b/hw/qxl.c
> >index 63e295b..ccd820c 100644
> >--- a/hw/qxl.c
> >+++ b/hw/qxl.c
> >@@ -1009,7 +1009,7 @@ static void ioport_write(void *opaque, uint32_t addr, uint32_t val)
> >          break;
> >      case QXL_IO_DESTROY_PRIMARY:
> >          PANIC_ON(val != 0);
> >-        dprint(d, 1, "QXL_IO_DESTROY_PRIMARY\n");
> >+        dprint(d, 1, "QXL_IO_DESTROY_PRIMARY (%s)\n", qxl_mode_to_string(d->mode));
> >          qxl_destroy_primary(d);
> >          break;
> >      case QXL_IO_DESTROY_SURFACE_WAIT:
> 
> Squash into the first?  Maybe there are a few more places where a
> pretty-printed mode would be useful?
ok, I'll look for more usage ops and do the squash.

> 
> cheers,
>   Gerd

Re: [Qemu-devel] [PATCHv2 3/4] qxl: add debug_cs and cmdlog_cs

[Alon Levy]

On Fri, Apr 29, 2011 at 02:09:54PM +0200, Gerd Hoffmann wrote:
> On 04/28/11 10:29, Alon Levy wrote:
> >With this you can output the command log and/or the guest debug (driver)
> >output to a chardev instead of stderr:
> >
> >-global qxl-vga.cmdlog_chardev=qxl_cmdlog_chardev
> >-global qxl-vga.debug_chardev=qxl_debug_chardev
> >
> >useful for debugging. if no chardev is specified prints to stderr like the old
> >code.
> 
> Hmm.  That is a bit too much ad-hoc debug hacking IMHO.  Also I'm
> not sure I like the idea to send debug stuff through chardev instead
> of just writing them to stderr or some logfile.
> 
> I do see why you are doing that though.  Unfortunaly qemu has no
> sane debug logging infrastructure.  This is long overdue IMHO, so we
> don't need hacks like this one and also don't reinvent stuff over
> and over.

The bigger hack called "qxl_terse" I didn't even send :) ok, so now I get
to either keep this in my closet or think of how to do a minimal acceptable
qemu logging infrastructure that would let me register a logging handle and
use that to redirect to a chardev (they would all default to being muxed over
stdio?)

QemuLogger *qemu_create_logger(const char *logger_id);
 - logger_id is used to match to the chardev given on the command line
 - need to prevent collision, so probably easier to have a logger_id be an int
 and have that looked up to a string in an automatically generated table?

struct QemuLogger {
  CharDriverState *chr;
};

And command line would be:
 -chardev bla,id=myid -debug qxl,myid

qxl->logger = qemu_create_logger("qxl");
qemu_chr_write(qxl->logger->chr, ..)

logger creation would have to happen before command line parsing, so in the device initialization.

Sounds right?

> 
> cheers,
>   Gerd
> 

[Qemu-devel] debug logging (was: Re: [PATCHv2 3/4] qxl: add debug_cs and cmdlog_cs)

[Gerd Hoffmann]

   Hi,

> The bigger hack called "qxl_terse" I didn't even send :) ok, so now I get
> to either keep this in my closet or think of how to do a minimal acceptable
> qemu logging infrastructure that would let me register a logging handle and
> use that to redirect to a chardev (they would all default to being muxed over
> stdio?)
>
> QemuLogger *qemu_create_logger(const char *logger_id);
>   - logger_id is used to match to the chardev given on the command line
>   - need to prevent collision, so probably easier to have a logger_id be an int
>   and have that looked up to a string in an automatically generated table?

What I have in mind is a simple dbg_print() function, integrated with 
qdev and simliar to what the linux kernel has, i.e. something like:

int dbg_print(DeviceState *qdev, int loglevel, const char *fmt, ...);

This can basically be used that as drop-in replacement for the 
fprintf(stderr, fmt, ...) style found in many drivers.

dbg_print would get the driver name via qdev->info->name, get the 
instance via qdev->parent_bus->info->get_dev_path(), get a timestamp, 
then create a standard prefix for all messages for easy grepping.  It 
would also check qdev->loglevel to figure whenever the message should be 
printed or not.  All devices get a property to set qdev->loglevel, so 
all logging can be configured at runtime per device.

Messages go to stderr by default.  A -debug switch could be added to 
route them another way.

Comments in the idea?

cheers,
   Gerd

Re: [Qemu-devel] debug logging (was: Re: [PATCHv2 3/4] qxl: add debug_cs and cmdlog_cs)

[Alon Levy]

On Mon, May 02, 2011 at 11:02:22AM +0200, Gerd Hoffmann wrote:
>   Hi,
> 
> >The bigger hack called "qxl_terse" I didn't even send :) ok, so now I get
> >to either keep this in my closet or think of how to do a minimal acceptable
> >qemu logging infrastructure that would let me register a logging handle and
> >use that to redirect to a chardev (they would all default to being muxed over
> >stdio?)
> >
> >QemuLogger *qemu_create_logger(const char *logger_id);
> >  - logger_id is used to match to the chardev given on the command line
> >  - need to prevent collision, so probably easier to have a logger_id be an int
> >  and have that looked up to a string in an automatically generated table?
> 
> What I have in mind is a simple dbg_print() function, integrated
> with qdev and simliar to what the linux kernel has, i.e. something
> like:
> 
> int dbg_print(DeviceState *qdev, int loglevel, const char *fmt, ...);
> 
> This can basically be used that as drop-in replacement for the
> fprintf(stderr, fmt, ...) style found in many drivers.
> 
> dbg_print would get the driver name via qdev->info->name, get the
> instance via qdev->parent_bus->info->get_dev_path(), get a
> timestamp, then create a standard prefix for all messages for easy
> grepping.  It would also check qdev->loglevel to figure whenever the
> message should be printed or not.  All devices get a property to set
> qdev->loglevel, so all logging can be configured at runtime per
> device.
> 
> Messages go to stderr by default.  A -debug switch could be added to
> route them another way.
> 
> Comments in the idea?

The thing with grepping is that it conflicts with using the monitor on stdout,
which is why I wanted to use a chardev. And of course a chardev solves the
need for grep (at least to get a coarse level - of course you still need to
grep later).

dbg_print takes care of making it standard to have a loglevel and prefix, sounds
good, but I'd still like to know if it is acceptable to also redirect with -debug,
I guess reusing the DeviceState then, instead of my added struct, so just letting
DeviceState.debug_chardev == NULL by default, and settable with
-debug <devname>,id=<chardev_id>

> 
> cheers,
>   Gerd
> 
> 

Re: [Qemu-devel] debug logging

[Gerd Hoffmann]

   Hi,

> dbg_print takes care of making it standard to have a loglevel and prefix, sounds
> good, but I'd still like to know if it is acceptable to also redirect with -debug,
> I guess reusing the DeviceState then, instead of my added struct, so just letting
> DeviceState.debug_chardev == NULL by default, and settable with
> -debug<devname>,id=<chardev_id>

Making dbg_print use DeviceState.debug_chardev (if present, stderr 
otherwise) looks sane to me.  Buf I'd use standard properties then to 
set it instead of a separate -debug switch, i.e.

   -chardev file,id=messages,path=... \
   -device foo,dbg=1,dbglog=messages

cheers,
   Gerd

Re: [Qemu-devel] debug logging

[Alon Levy]

On Mon, May 02, 2011 at 12:25:30PM +0200, Gerd Hoffmann wrote:
>   Hi,
> 
> >dbg_print takes care of making it standard to have a loglevel and prefix, sounds
> >good, but I'd still like to know if it is acceptable to also redirect with -debug,
> >I guess reusing the DeviceState then, instead of my added struct, so just letting
> >DeviceState.debug_chardev == NULL by default, and settable with
> >-debug<devname>,id=<chardev_id>
> 
> Making dbg_print use DeviceState.debug_chardev (if present, stderr
> otherwise) looks sane to me.  Buf I'd use standard properties then
> to set it instead of a separate -debug switch, i.e.
> 
>   -chardev file,id=messages,path=... \
>   -device foo,dbg=1,dbglog=messages
> 

Sounds good. I'll try to make it so.

> cheers,
>   Gerd
> 

Re: [Qemu-devel] debug logging

[Jan Kiszka]

On 2011-05-02 12:33, Alon Levy wrote:
> On Mon, May 02, 2011 at 12:25:30PM +0200, Gerd Hoffmann wrote:
>>   Hi,
>>
>>> dbg_print takes care of making it standard to have a loglevel and prefix, sounds
>>> good, but I'd still like to know if it is acceptable to also redirect with -debug,
>>> I guess reusing the DeviceState then, instead of my added struct, so just letting
>>> DeviceState.debug_chardev == NULL by default, and settable with
>>> -debug<devname>,id=<chardev_id>
>>
>> Making dbg_print use DeviceState.debug_chardev (if present, stderr
>> otherwise) looks sane to me.  Buf I'd use standard properties then
>> to set it instead of a separate -debug switch, i.e.
>>
>>   -chardev file,id=messages,path=... \
>>   -device foo,dbg=1,dbglog=messages
>>
> 
> Sounds good. I'll try to make it so.

We have a tracing infrastructure for such use cases today. Better invest
in adding missing features there.

Jan

-- 
Siemens AG, Corporate Technology, CT T DE IT 1
Corporate Competence Center Embedded Linux

Re: [Qemu-devel] debug logging

[Markus Armbruster]

Jan Kiszka <jan.kiszka@siemens.com> writes:

> On 2011-05-02 12:33, Alon Levy wrote:
>> On Mon, May 02, 2011 at 12:25:30PM +0200, Gerd Hoffmann wrote:
>>>   Hi,
>>>
>>>> dbg_print takes care of making it standard to have a loglevel and prefix, sounds
>>>> good, but I'd still like to know if it is acceptable to also redirect with -debug,
>>>> I guess reusing the DeviceState then, instead of my added struct, so just letting
>>>> DeviceState.debug_chardev == NULL by default, and settable with
>>>> -debug<devname>,id=<chardev_id>
>>>
>>> Making dbg_print use DeviceState.debug_chardev (if present, stderr
>>> otherwise) looks sane to me.  Buf I'd use standard properties then
>>> to set it instead of a separate -debug switch, i.e.
>>>
>>>   -chardev file,id=messages,path=... \
>>>   -device foo,dbg=1,dbglog=messages
>>>
>> 
>> Sounds good. I'll try to make it so.
>
> We have a tracing infrastructure for such use cases today. Better invest
> in adding missing features there.

Start with docs/tracing.txt

Re: [Qemu-devel] debug logging

[Alon Levy]

On Mon, May 02, 2011 at 01:00:01PM +0200, Markus Armbruster wrote:
> Jan Kiszka <jan.kiszka@siemens.com> writes:
> 
> > On 2011-05-02 12:33, Alon Levy wrote:
> >> On Mon, May 02, 2011 at 12:25:30PM +0200, Gerd Hoffmann wrote:
> >>>   Hi,
> >>>
> >>>> dbg_print takes care of making it standard to have a loglevel and prefix, sounds
> >>>> good, but I'd still like to know if it is acceptable to also redirect with -debug,
> >>>> I guess reusing the DeviceState then, instead of my added struct, so just letting
> >>>> DeviceState.debug_chardev == NULL by default, and settable with
> >>>> -debug<devname>,id=<chardev_id>
> >>>
> >>> Making dbg_print use DeviceState.debug_chardev (if present, stderr
> >>> otherwise) looks sane to me.  Buf I'd use standard properties then
> >>> to set it instead of a separate -debug switch, i.e.
> >>>
> >>>   -chardev file,id=messages,path=... \
> >>>   -device foo,dbg=1,dbglog=messages
> >>>
> >> 
> >> Sounds good. I'll try to make it so.
> >
> > We have a tracing infrastructure for such use cases today. Better invest
> > in adding missing features there.
> 
> Start with docs/tracing.txt

ok, I see that the file starts by saying it is meant to be used for debugging as
well. Am I correct in the following?
1. to change tracing backends requires a recompile
2. can't have two tracing backends at the same time (i.e. either everything goes
to stdout or everything is visible via systemtap etc.)
3. quoting:
         Do not pass in string arguments.
   how does that help debugging then?
4. the equivalent of setting a loglevel is?

If I want to achieve my original intend, namely easily changing the target of specific
qxl debug statements from stderr to a separate file, to view at runtime, I will need to:
1. turn all of them to trace calls
2. do one of:
 2.a turn the stderr backend into a debug_chardev backend, defaulting to stderr
 (this sounds simplest to me) and add this option
 2.b augment the simpletrace backend in the same way.

Any comments?

Alon

Re: [Qemu-devel] debug logging

[Jan Kiszka]

On 2011-05-02 13:50, Alon Levy wrote:
> On Mon, May 02, 2011 at 01:00:01PM +0200, Markus Armbruster wrote:
>> Jan Kiszka <jan.kiszka@siemens.com> writes:
>>
>>> On 2011-05-02 12:33, Alon Levy wrote:
>>>> On Mon, May 02, 2011 at 12:25:30PM +0200, Gerd Hoffmann wrote:
>>>>>   Hi,
>>>>>
>>>>>> dbg_print takes care of making it standard to have a loglevel and prefix, sounds
>>>>>> good, but I'd still like to know if it is acceptable to also redirect with -debug,
>>>>>> I guess reusing the DeviceState then, instead of my added struct, so just letting
>>>>>> DeviceState.debug_chardev == NULL by default, and settable with
>>>>>> -debug<devname>,id=<chardev_id>
>>>>>
>>>>> Making dbg_print use DeviceState.debug_chardev (if present, stderr
>>>>> otherwise) looks sane to me.  Buf I'd use standard properties then
>>>>> to set it instead of a separate -debug switch, i.e.
>>>>>
>>>>>   -chardev file,id=messages,path=... \
>>>>>   -device foo,dbg=1,dbglog=messages
>>>>>
>>>>
>>>> Sounds good. I'll try to make it so.
>>>
>>> We have a tracing infrastructure for such use cases today. Better invest
>>> in adding missing features there.
>>
>> Start with docs/tracing.txt
> 
> ok, I see that the file starts by saying it is meant to be used for debugging as
> well. Am I correct in the following?
> 1. to change tracing backends requires a recompile

Right. I mostly work with stderr backend as it can be redirected
wherever you want it (console, file, ftrace trace_marker).

> 2. can't have two tracing backends at the same time (i.e. either everything goes
> to stdout or everything is visible via systemtap etc.)
> 3. quoting:
>          Do not pass in string arguments.
>    how does that help debugging then?

This needs to be fixed, the infrastructure should be able to record
fixed sized strings (not kilobytes, but 32 bytes or so).

> 4. the equivalent of setting a loglevel is?

Right now either the use of systemtap or ust which allow per-tracepoint
enabling/disabling or enable simpletrace and use the trace-event monitor
command. On top you need local grouping of the tracepoints.

At least the latter needs fixing so that the developer of some module
can tag tracepoints in-tree. But I also think we should be tracepoint
control a generic feature, independent of the tracer backend as far as
possible (ust and systemtap likely provide interfaces to forward control
commands).

> 
> If I want to achieve my original intend, namely easily changing the target of specific
> qxl debug statements from stderr to a separate file, to view at runtime, I will need to:
> 1. turn all of them to trace calls
> 2. do one of:
>  2.a turn the stderr backend into a debug_chardev backend, defaulting to stderr
>  (this sounds simplest to me) and add this option

You should avoid using too much of qemu's infrastructure in the tracer,
specifically if holds some state. Or am I misunderstanding your plans?

>  2.b augment the simpletrace backend in the same way.
> 
> Any comments?
> 
> Alon

Jan

-- 
Siemens AG, Corporate Technology, CT T DE IT 1
Corporate Competence Center Embedded Linux

Re: [Qemu-devel] debug logging

[Alon Levy]

On Mon, May 02, 2011 at 02:43:34PM +0200, Jan Kiszka wrote:
> On 2011-05-02 13:50, Alon Levy wrote:
> > On Mon, May 02, 2011 at 01:00:01PM +0200, Markus Armbruster wrote:
> >> Jan Kiszka <jan.kiszka@siemens.com> writes:
> >>
> >>> On 2011-05-02 12:33, Alon Levy wrote:
> >>>> On Mon, May 02, 2011 at 12:25:30PM +0200, Gerd Hoffmann wrote:
> >>>>>   Hi,
> >>>>>
> >>>>>> dbg_print takes care of making it standard to have a loglevel and prefix, sounds
> >>>>>> good, but I'd still like to know if it is acceptable to also redirect with -debug,
> >>>>>> I guess reusing the DeviceState then, instead of my added struct, so just letting
> >>>>>> DeviceState.debug_chardev == NULL by default, and settable with
> >>>>>> -debug<devname>,id=<chardev_id>
> >>>>>
> >>>>> Making dbg_print use DeviceState.debug_chardev (if present, stderr
> >>>>> otherwise) looks sane to me.  Buf I'd use standard properties then
> >>>>> to set it instead of a separate -debug switch, i.e.
> >>>>>
> >>>>>   -chardev file,id=messages,path=... \
> >>>>>   -device foo,dbg=1,dbglog=messages
> >>>>>
> >>>>
> >>>> Sounds good. I'll try to make it so.
> >>>
> >>> We have a tracing infrastructure for such use cases today. Better invest
> >>> in adding missing features there.
> >>
> >> Start with docs/tracing.txt
> > 
> > ok, I see that the file starts by saying it is meant to be used for debugging as
> > well. Am I correct in the following?
> > 1. to change tracing backends requires a recompile
> 
> Right. I mostly work with stderr backend as it can be redirected
> wherever you want it (console, file, ftrace trace_marker).
> 
> > 2. can't have two tracing backends at the same time (i.e. either everything goes
> > to stdout or everything is visible via systemtap etc.)
> > 3. quoting:
> >          Do not pass in string arguments.
> >    how does that help debugging then?
> 
> This needs to be fixed, the infrastructure should be able to record
> fixed sized strings (not kilobytes, but 32 bytes or so).
> 
> > 4. the equivalent of setting a loglevel is?
> 
> Right now either the use of systemtap or ust which allow per-tracepoint
> enabling/disabling or enable simpletrace and use the trace-event monitor
> command. On top you need local grouping of the tracepoints.
> 
> At least the latter needs fixing so that the developer of some module
> can tag tracepoints in-tree. But I also think we should be tracepoint
> control a generic feature, independent of the tracer backend as far as
> possible (ust and systemtap likely provide interfaces to forward control
> commands).
> 
> > 
> > If I want to achieve my original intend, namely easily changing the target of specific
> > qxl debug statements from stderr to a separate file, to view at runtime, I will need to:
> > 1. turn all of them to trace calls
> > 2. do one of:
> >  2.a turn the stderr backend into a debug_chardev backend, defaulting to stderr
> >  (this sounds simplest to me) and add this option
> 
> You should avoid using too much of qemu's infrastructure in the tracer,
> specifically if holds some state. Or am I misunderstanding your plans?
> 

My original patch allowed logging of qxl debug output to a chardev of my choice. I'm
trying to achieve the same thing using the tracing framework. The way is I think to
add a DeviceState.debug_chardev that is settable when the device is created (no state
in the tracing framework) and use that from the stderr framework.

This seems to be a little bit difficult with the current stderr backend implementation
which never has any handle to a DeviceState. I'll have to fix that, and then it can
be something like:

static inline void trace_$name(DeviceState *dev, $args)
{
    if (!dev || !dev->debug_chardev) {
        fprintf(stderr, "$name $fmt\n" $argnames);
    else {
        qemu_chr_print("$name $fmt\n" $argnames);
    }
}



> >  2.b augment the simpletrace backend in the same way.
> > 
> > Any comments?
> > 
> > Alon
> 
> Jan
> 
> -- 
> Siemens AG, Corporate Technology, CT T DE IT 1
> Corporate Competence Center Embedded Linux

Re: [Qemu-devel] debug logging

[Paolo Bonzini]

On 05/02/2011 02:43 PM, Jan Kiszka wrote:
>> >  4. the equivalent of setting a loglevel is?
> Right now either the use of systemtap or ust which allow per-tracepoint
> enabling/disabling or enable simpletrace and use the trace-event monitor
> command. On top you need local grouping of the tracepoints.

There is a pending patch series for -trace events, which will do 99% of 
what you need and in some cases is even better than loglevels.

Paolo