[Qemu-devel] [PATCH 0/4] Remove trailing double quote limitation and add virtio_set_status trace event

[Qemu-devel] [PATCH 0/4] Remove trailing double quote limitation and add virtio_set_status trace event

[Stefan Hajnoczi]

This series removes the tracetool parser limitation that format strings must
begin and end with double quotes.  In practice this means we need to work
around PRI*64 usage by adding dummy "" at the end of the line.  It's fairly
easy to solve this parser limitation and do away with the workarounds.

While we're at it, also add the virtio_set_status() trace event to properly
follow the lifecycle of virtio devices.

 docs/tracing.txt  |    5 +----
 hw/virtio.c       |   10 ++++++++++
 hw/virtio.h       |    9 +--------
 scripts/tracetool |   20 +++++++++++++-------
 trace-events      |   37 +++++++++++++++++++------------------
 5 files changed, 44 insertions(+), 37 deletions(-)

[Qemu-devel] [PATCH 1/4] trace: remove newline from grlib_irqmp_check_irqs format string

[Stefan Hajnoczi]

There is no need to put a newline in trace event format strings.  The
backend may use the format string within some context and takes care of
how to display the event.  The stderr backend automatically appends "\n"
whereas the ust backend does not want a newline at all.

Signed-off-by: Stefan Hajnoczi <stefanha@linux.vnet.ibm.com>
---
 trace-events |    2 +-
 1 files changed, 1 insertions(+), 1 deletions(-)

diff --git a/trace-events b/trace-events
index a8e7684..cfcdc9b 100644
--- a/trace-events
+++ b/trace-events
@@ -327,7 +327,7 @@ grlib_gptimer_readl(int id, uint64_t addr, uint32_t val) "timer:%d addr 0x%"PRIx
 grlib_gptimer_writel(int id, uint64_t addr, uint32_t val) "timer:%d addr 0x%"PRIx64" 0x%x"
 
 # hw/grlib_irqmp.c
-grlib_irqmp_check_irqs(uint32_t pend, uint32_t force, uint32_t mask, uint32_t lvl1, uint32_t lvl2) "pend:0x%04x force:0x%04x mask:0x%04x lvl1:0x%04x lvl0:0x%04x\n"
+grlib_irqmp_check_irqs(uint32_t pend, uint32_t force, uint32_t mask, uint32_t lvl1, uint32_t lvl2) "pend:0x%04x force:0x%04x mask:0x%04x lvl1:0x%04x lvl0:0x%04x"
 grlib_irqmp_ack(int intno) "interrupt:%d"
 grlib_irqmp_set_irq(int irq) "Raise CPU IRQ %d"
 grlib_irqmp_readl_unknown(uint64_t addr) "addr 0x%"PRIx64""
-- 
1.7.5.4

[Qemu-devel] [PATCH 2/4] trace: allow PRI*64 at beginning and ending of format string

[Stefan Hajnoczi]

The tracetool parser only picks up PRI*64 and other format string macros
when enclosed between double quoted strings.  Lift this restriction by
extracting everything after the closing ')' as the format string:

  cpu_set_apic_base(uint64_t val) "%016"PRIx64
                                  ^^        ^^

One trick here: it turns out that backslashes in the format string like
"\n" were being interpreted by echo(1).  Fix this by using the POSIX
printf(1) command instead.  Although it normally does not make sense to
include backslashes in trace event format strings, an injected newline
causes tracetool to emit a broken header file and I want to eliminate
cases where broken output is emitted, even if the input was bad.

Signed-off-by: Stefan Hajnoczi <stefanha@linux.vnet.ibm.com>
---
 docs/tracing.txt  |    5 +----
 scripts/tracetool |   20 +++++++++++++-------
 2 files changed, 14 insertions(+), 11 deletions(-)

diff --git a/docs/tracing.txt b/docs/tracing.txt
index e130a61..2c33a62 100644
--- a/docs/tracing.txt
+++ b/docs/tracing.txt
@@ -75,10 +75,7 @@ Trace events should use types as follows:
 
 Format strings should reflect the types defined in the trace event.  Take
 special care to use PRId64 and PRIu64 for int64_t and uint64_t types,
-respectively.  This ensures portability between 32- and 64-bit platforms.  Note
-that format strings must begin and end with double quotes.  When using
-portability macros, ensure they are preceded and followed by double quotes:
-"value %"PRIx64"".
+respectively.  This ensures portability between 32- and 64-bit platforms.
 
 === Hints for adding new trace events ===
 
diff --git a/scripts/tracetool b/scripts/tracetool
index 743d246..4c9951d 100755
--- a/scripts/tracetool
+++ b/scripts/tracetool
@@ -40,6 +40,15 @@ EOF
     exit 1
 }
 
+# Print a line without interpreting backslash escapes
+#
+# The built-in echo command may interpret backslash escapes without an option
+# to disable this behavior.
+puts()
+{
+    printf "%s\n" "$1"
+}
+
 # Get the name of a trace event
 get_name()
 {
@@ -111,13 +120,10 @@ get_argc()
     echo $argc
 }
 
-# Get the format string for a trace event
+# Get the format string including double quotes for a trace event
 get_fmt()
 {
-    local fmt
-    fmt=${1#*\"}
-    fmt=${fmt%\"*}
-    echo "$fmt"
+    puts "${1#*)}"
 }
 
 linetoh_begin_nop()
@@ -266,7 +272,7 @@ linetoh_stderr()
 static inline void trace_$name($args)
 {
     if (trace_list[$stderr_event_num].state != 0) {
-        fprintf(stderr, "$name $fmt\n" $argnames);
+        fprintf(stderr, "$name " $fmt "\n" $argnames);
     }
 }
 EOF
@@ -366,7 +372,7 @@ DEFINE_TRACE(ust_$name);
 
 static void ust_${name}_probe($args)
 {
-    trace_mark(ust, $name, "$fmt"$argnames);
+    trace_mark(ust, $name, $fmt$argnames);
 }
 EOF
 
-- 
1.7.5.4

[Qemu-devel] [PATCH 3/4] trace: remove trailing double quotes after PRI*64

[Stefan Hajnoczi]

Now that format strings can end in a PRI*64 macro, remove the
workarounds from the trace-events file.

Signed-off-by: Stefan Hajnoczi <stefanha@linux.vnet.ibm.com>
---
 trace-events |   34 +++++++++++++++++-----------------
 1 files changed, 17 insertions(+), 17 deletions(-)

diff --git a/trace-events b/trace-events
index cfcdc9b..9a59525 100644
--- a/trace-events
+++ b/trace-events
@@ -88,8 +88,8 @@ balloon_event(void *opaque, unsigned long addr) "opaque %p addr %lu"
 # hw/apic.c
 apic_local_deliver(int vector, uint32_t lvt) "vector %d delivery mode %d"
 apic_deliver_irq(uint8_t dest, uint8_t dest_mode, uint8_t delivery_mode, uint8_t vector_num, uint8_t trigger_mode) "dest %d dest_mode %d delivery_mode %d vector %d trigger_mode %d"
-cpu_set_apic_base(uint64_t val) "%016"PRIx64""
-cpu_get_apic_base(uint64_t val) "%016"PRIx64""
+cpu_set_apic_base(uint64_t val) "%016"PRIx64
+cpu_get_apic_base(uint64_t val) "%016"PRIx64
 apic_mem_readl(uint64_t addr, uint32_t val)  "%"PRIx64" = %08x"
 apic_mem_writel(uint64_t addr, uint32_t val) "%"PRIx64" = %08x"
 # coalescing
@@ -169,21 +169,21 @@ slavio_led_mem_readw(uint32_t ret) "Read diagnostic LED %04x"
 # hw/slavio_timer.c
 slavio_timer_get_out(uint64_t limit, uint32_t counthigh, uint32_t count) "limit %"PRIx64" count %x%08x"
 slavio_timer_irq(uint32_t counthigh, uint32_t count) "callback: count %x%08x"
-slavio_timer_mem_readl_invalid(uint64_t addr) "invalid read address %"PRIx64""
+slavio_timer_mem_readl_invalid(uint64_t addr) "invalid read address %"PRIx64
 slavio_timer_mem_readl(uint64_t addr, uint32_t ret) "read %"PRIx64" = %08x"
 slavio_timer_mem_writel(uint64_t addr, uint32_t val) "write %"PRIx64" = %08x"
-slavio_timer_mem_writel_limit(unsigned int timer_index, uint64_t count) "processor %d user timer set to %016"PRIx64""
+slavio_timer_mem_writel_limit(unsigned int timer_index, uint64_t count) "processor %d user timer set to %016"PRIx64
 slavio_timer_mem_writel_counter_invalid(void) "not user timer"
 slavio_timer_mem_writel_status_start(unsigned int timer_index) "processor %d user timer started"
 slavio_timer_mem_writel_status_stop(unsigned int timer_index) "processor %d user timer stopped"
 slavio_timer_mem_writel_mode_user(unsigned int timer_index) "processor %d changed from counter to user timer"
 slavio_timer_mem_writel_mode_counter(unsigned int timer_index) "processor %d changed from user timer to counter"
 slavio_timer_mem_writel_mode_invalid(void) "not system timer"
-slavio_timer_mem_writel_invalid(uint64_t addr) "invalid write address %"PRIx64""
+slavio_timer_mem_writel_invalid(uint64_t addr) "invalid write address %"PRIx64
 
 # hw/sparc32_dma.c
-ledma_memory_read(uint64_t addr) "DMA read addr 0x%"PRIx64""
-ledma_memory_write(uint64_t addr) "DMA write addr 0x%"PRIx64""
+ledma_memory_read(uint64_t addr) "DMA read addr 0x%"PRIx64
+ledma_memory_write(uint64_t addr) "DMA write addr 0x%"PRIx64
 sparc32_dma_set_irq_raise(void) "Raise IRQ"
 sparc32_dma_set_irq_lower(void) "Lower IRQ"
 espdma_memory_read(uint32_t addr) "DMA read addr 0x%08x"
@@ -202,12 +202,12 @@ sun4m_cpu_set_irq_lower(int level) "Lower CPU IRQ %d"
 # hw/sun4m_iommu.c
 sun4m_iommu_mem_readl(uint64_t addr, uint32_t ret) "read reg[%"PRIx64"] = %x"
 sun4m_iommu_mem_writel(uint64_t addr, uint32_t val) "write reg[%"PRIx64"] = %x"
-sun4m_iommu_mem_writel_ctrl(uint64_t iostart) "iostart = %"PRIx64""
+sun4m_iommu_mem_writel_ctrl(uint64_t iostart) "iostart = %"PRIx64
 sun4m_iommu_mem_writel_tlbflush(uint32_t val) "tlb flush %x"
 sun4m_iommu_mem_writel_pgflush(uint32_t val) "page flush %x"
 sun4m_iommu_page_get_flags(uint64_t pa, uint64_t iopte, uint32_t ret) "get flags addr %"PRIx64" => pte %"PRIx64", *pte = %x"
 sun4m_iommu_translate_pa(uint64_t addr, uint64_t pa, uint32_t iopte) "xlate dva %"PRIx64" => pa %"PRIx64" iopte = %x"
-sun4m_iommu_bad_addr(uint64_t addr) "bad addr %"PRIx64""
+sun4m_iommu_bad_addr(uint64_t addr) "bad addr %"PRIx64
 
 # hw/usb-bus.c
 usb_port_claim(int bus, const char *port) "bus %d, port %s"
@@ -278,7 +278,7 @@ scsi_req_data(int target, int lun, int tag, int len) "target %d lun %d tag %d le
 scsi_req_dequeue(int target, int lun, int tag) "target %d lun %d tag %d"
 scsi_req_continue(int target, int lun, int tag) "target %d lun %d tag %d"
 scsi_req_parsed(int target, int lun, int tag, int cmd, int mode, int xfer) "target %d lun %d tag %d command %d dir %d length %d"
-scsi_req_parsed_lba(int target, int lun, int tag, int cmd, uint64_t lba) "target %d lun %d tag %d command %d lba %"PRIu64""
+scsi_req_parsed_lba(int target, int lun, int tag, int cmd, uint64_t lba) "target %d lun %d tag %d command %d lba %"PRIu64
 scsi_req_parse_bad(int target, int lun, int tag, int cmd) "target %d lun %d tag %d command %d"
 scsi_req_build_sense(int target, int lun, int tag, int key, int asc, int ascq) "target %d lun %d tag %d key %#02x asc %#02x ascq %#02x"
 scsi_report_luns(int target, int lun, int tag) "target %d lun %d tag %d"
@@ -306,11 +306,11 @@ qed_start_need_check_timer(void *s) "s %p"
 qed_cancel_need_check_timer(void *s) "s %p"
 qed_aio_complete(void *s, void *acb, int ret) "s %p acb %p ret %d"
 qed_aio_setup(void *s, void *acb, int64_t sector_num, int nb_sectors, void *opaque, int is_write) "s %p acb %p sector_num %"PRId64" nb_sectors %d opaque %p is_write %d"
-qed_aio_next_io(void *s, void *acb, int ret, uint64_t cur_pos) "s %p acb %p ret %d cur_pos %"PRIu64""
+qed_aio_next_io(void *s, void *acb, int ret, uint64_t cur_pos) "s %p acb %p ret %d cur_pos %"PRIu64
 qed_aio_read_data(void *s, void *acb, int ret, uint64_t offset, size_t len) "s %p acb %p ret %d offset %"PRIu64" len %zu"
 qed_aio_write_data(void *s, void *acb, int ret, uint64_t offset, size_t len) "s %p acb %p ret %d offset %"PRIu64" len %zu"
-qed_aio_write_prefill(void *s, void *acb, uint64_t start, size_t len, uint64_t offset) "s %p acb %p start %"PRIu64" len %zu offset %"PRIu64""
-qed_aio_write_postfill(void *s, void *acb, uint64_t start, size_t len, uint64_t offset) "s %p acb %p start %"PRIu64" len %zu offset %"PRIu64""
+qed_aio_write_prefill(void *s, void *acb, uint64_t start, size_t len, uint64_t offset) "s %p acb %p start %"PRIu64" len %zu offset %"PRIu64
+qed_aio_write_postfill(void *s, void *acb, uint64_t start, size_t len, uint64_t offset) "s %p acb %p start %"PRIu64" len %zu offset %"PRIu64
 qed_aio_write_main(void *s, void *acb, int ret, uint64_t offset, size_t len) "s %p acb %p ret %d offset %"PRIu64" len %zu"
 
 # hw/g364fb.c
@@ -330,7 +330,7 @@ grlib_gptimer_writel(int id, uint64_t addr, uint32_t val) "timer:%d addr 0x%"PRI
 grlib_irqmp_check_irqs(uint32_t pend, uint32_t force, uint32_t mask, uint32_t lvl1, uint32_t lvl2) "pend:0x%04x force:0x%04x mask:0x%04x lvl1:0x%04x lvl0:0x%04x"
 grlib_irqmp_ack(int intno) "interrupt:%d"
 grlib_irqmp_set_irq(int irq) "Raise CPU IRQ %d"
-grlib_irqmp_readl_unknown(uint64_t addr) "addr 0x%"PRIx64""
+grlib_irqmp_readl_unknown(uint64_t addr) "addr 0x%"PRIx64
 grlib_irqmp_writel_unknown(uint64_t addr, uint32_t value) "addr 0x%"PRIx64" value 0x%x"
 
 # hw/grlib_apbuart.c
@@ -462,10 +462,10 @@ xen_ram_alloc(unsigned long ram_addr, unsigned long size) "requested: %#lx, size
 xen_client_set_memory(uint64_t start_addr, unsigned long size, unsigned long phys_offset, bool log_dirty) "%#"PRIx64" size %#lx, offset %#lx, log_dirty %i"
 
 # xen-mapcache.c
-xen_map_cache(uint64_t phys_addr) "want %#"PRIx64""
-xen_remap_bucket(uint64_t index) "index %#"PRIx64""
+xen_map_cache(uint64_t phys_addr) "want %#"PRIx64
+xen_remap_bucket(uint64_t index) "index %#"PRIx64
 xen_map_cache_return(void* ptr) "%p"
-xen_map_block(uint64_t phys_addr, uint64_t size) "%#"PRIx64", size %#"PRIx64""
+xen_map_block(uint64_t phys_addr, uint64_t size) "%#"PRIx64", size %#"PRIx64
 xen_unmap_block(void* addr, unsigned long size) "%p, size %#lx"
 
 # exec.c
-- 
1.7.5.4

[Qemu-devel] [PATCH 4/4] trace: add virtio_set_status() trace event

[Stefan Hajnoczi]

The virtio device lifecycle can be observed by looking at the sequence
of set status operations.  This is especially important for catching the
reset operation (status value 0), which resets the device and all
virtqueues.

Signed-off-by: Stefan Hajnoczi <stefanha@linux.vnet.ibm.com>
---
 hw/virtio.c  |   10 ++++++++++
 hw/virtio.h  |    9 +--------
 trace-events |    1 +
 3 files changed, 12 insertions(+), 8 deletions(-)

diff --git a/hw/virtio.c b/hw/virtio.c
index 13aa0fa..946d911 100644
--- a/hw/virtio.c
+++ b/hw/virtio.c
@@ -498,6 +498,16 @@ void virtio_update_irq(VirtIODevice *vdev)
     virtio_notify_vector(vdev, VIRTIO_NO_VECTOR);
 }
 
+void virtio_set_status(VirtIODevice *vdev, uint8_t val)
+{
+    trace_virtio_set_status(vdev, val);
+
+    if (vdev->set_status) {
+        vdev->set_status(vdev, val);
+    }
+    vdev->status = val;
+}
+
 void virtio_reset(void *opaque)
 {
     VirtIODevice *vdev = opaque;
diff --git a/hw/virtio.h b/hw/virtio.h
index c129264..666e381 100644
--- a/hw/virtio.h
+++ b/hw/virtio.h
@@ -135,14 +135,6 @@ struct VirtIODevice
     VMChangeStateEntry *vmstate;
 };
 
-static inline void virtio_set_status(VirtIODevice *vdev, uint8_t val)
-{
-    if (vdev->set_status) {
-        vdev->set_status(vdev, val);
-    }
-    vdev->status = val;
-}
-
 VirtQueue *virtio_add_queue(VirtIODevice *vdev, int queue_size,
                             void (*handle_output)(VirtIODevice *,
                                                   VirtQueue *));
@@ -190,6 +182,7 @@ int virtio_queue_get_num(VirtIODevice *vdev, int n);
 void virtio_queue_notify(VirtIODevice *vdev, int n);
 uint16_t virtio_queue_vector(VirtIODevice *vdev, int n);
 void virtio_queue_set_vector(VirtIODevice *vdev, int n, uint16_t vector);
+void virtio_set_status(VirtIODevice *vdev, uint8_t val);
 void virtio_reset(void *opaque);
 void virtio_update_irq(VirtIODevice *vdev);
 
diff --git a/trace-events b/trace-events
index 9a59525..99edc97 100644
--- a/trace-events
+++ b/trace-events
@@ -42,6 +42,7 @@ virtqueue_pop(void *vq, void *elem, unsigned int in_num, unsigned int out_num) "
 virtio_queue_notify(void *vdev, int n, void *vq) "vdev %p n %d vq %p"
 virtio_irq(void *vq) "vq %p"
 virtio_notify(void *vdev, void *vq) "vdev %p vq %p"
+virtio_set_status(void *vdev, uint8_t val) "vdev %p val %u"
 
 # hw/virtio-serial-bus.c
 virtio_serial_send_control_event(unsigned int port, uint16_t event, uint16_t value) "port %u, event %u, value %u"
-- 
1.7.5.4

Re: [Qemu-devel] [PATCH 0/4] Remove trailing double quote limitation and add virtio_set_status trace event

[Blue Swirl]

Thanks, applied all.

On Tue, Sep 13, 2011 at 12:34 PM, Stefan Hajnoczi
<stefanha@linux.vnet.ibm.com> wrote:
> This series removes the tracetool parser limitation that format strings must
> begin and end with double quotes.  In practice this means we need to work
> around PRI*64 usage by adding dummy "" at the end of the line.  It's fairly
> easy to solve this parser limitation and do away with the workarounds.
>
> While we're at it, also add the virtio_set_status() trace event to properly
> follow the lifecycle of virtio devices.
>
>  docs/tracing.txt  |    5 +----
>  hw/virtio.c       |   10 ++++++++++
>  hw/virtio.h       |    9 +--------
>  scripts/tracetool |   20 +++++++++++++-------
>  trace-events      |   37 +++++++++++++++++++------------------
>  5 files changed, 44 insertions(+), 37 deletions(-)
>
>