[Qemu-devel] [PATCH] apic: convert debug printf statements to tracepoints

[Qemu-devel] [PATCH] apic: convert debug printf statements to tracepoints

[Blue Swirl]

Replace debug printf statements with tracepoints.

Cc: Stefan Hajnoczi <stefanha@linux.vnet.ibm.com>
Signed-off-by: Blue Swirl <blauwirbel@gmail.com>
---
However, when I tried to use coalescing_apic.bin (triggers coalescing
events, see [1]), simpletrace.py chokes:

./qemu -bios ./ -monitor stdio coalescing_apic.bin -trace file=foo
QEMU 0.13.50 monitor - type 'help' for more information
(qemu) info trace
Event 25 : 3 7 0 0 0
Event 25 : 3 7 0 0 0
Event 25 : 3 7 0 0 0
Event 25 : 3 7 0 0 0
Event 25 : 3 7 0 0 0
Event 25 : 3 7 0 0 0
Event 30 : 350 5700 0 0 0
Event 30 : f0 100 0 0 0
Event 26 : 0 0 0 70 0
Event 33 : 1 0 0 0 0
Event 30 : b0 0 0 0 0
Event 26 : 0 0 0 70 0
Event 33 : 2 0 0 0 0
Event 30 : b0 0 0 0 0
Event 26 : 0 0 0 70 0
Event 33 : 3 0 0 0 0
Event 30 : b0 0 0 0 0
Event 26 : 0 0 0 70 0
Event 33 : 4 0 0 0 0
Event 30 : b0 0 0 0 0
Event 26 : 0 0 0 70 0
Event 33 : 5 0 0 0 0
Event 30 : b0 0 0 0 0
Event 26 : 0 0 0 70 0
Event 33 : 6 0 0 0 0
Event 30 : b0 0 0 0 0
Event 26 : 0 0 0 70 0
Event 33 : 7 0 0 0 0
Event 30 : b0 0 0 0 0
(qemu) q
$ /src/qemu/simpletrace.py /src/qemu/trace-events foo
apic_local_deliver 0.000 vector=0x3 lvt=0x7
apic_local_deliver 23.527 vector=0x3 lvt=0x7
apic_local_deliver 3.921 vector=0x3 lvt=0x7
apic_local_deliver 2.940 vector=0x3 lvt=0x7
apic_local_deliver 2.941 vector=0x3 lvt=0x7
apic_local_deliver 4.411 vector=0x3 lvt=0x7
apic_get_irq_delivered 3706.866 apic_irq_delivered=0x350
apic_get_irq_delivered 2.450 apic_irq_delivered=0xf0
apic_deliver_irq 266872.726 dest=0x0 dest_mode=0x0 delivery_mode=0x0
vector_num=0x70 polarity=0x0 trigger_mode=0x0
Traceback (most recent call last):
  File "/src/qemu/simpletrace.py", line 93, in <module>
    print formatter.format_record(rec)
  File "/src/qemu/simpletrace.py", line 81, in format_record
    event = self.events[rec[0]]
KeyError: 33

[1] http://article.gmane.org/gmane.comp.emulators.qemu/72414

 hw/apic.c    |   48 ++++++++++++++++++------------------------------
 trace-events |   12 ++++++++++++
 2 files changed, 30 insertions(+), 30 deletions(-)

diff --git a/hw/apic.c b/hw/apic.c
index d686b51..63d62c7 100644
--- a/hw/apic.c
+++ b/hw/apic.c
@@ -21,23 +21,7 @@
 #include "qemu-timer.h"
 #include "host-utils.h"
 #include "sysbus.h"
-
-//#define DEBUG_APIC
-//#define DEBUG_COALESCING
-
-#ifdef DEBUG_APIC
-#define DPRINTF(fmt, ...)                                       \
-    do { printf("apic: " fmt , ## __VA_ARGS__); } while (0)
-#else
-#define DPRINTF(fmt, ...)
-#endif
-
-#ifdef DEBUG_COALESCING
-#define DPRINTF_C(fmt, ...)                                     \
-    do { printf("apic: " fmt , ## __VA_ARGS__); } while (0)
-#else
-#define DPRINTF_C(fmt, ...)
-#endif
+#include "trace.h"

 /* APIC Local Vector Table */
 #define APIC_LVT_TIMER   0
@@ -168,8 +152,8 @@ static void apic_local_deliver(APICState *s, int vector)
     uint32_t lvt = s->lvt[vector];
     int trigger_mode;

-    DPRINTF("%s: vector %d delivery mode %d\n", __func__, vector,
-            (lvt >> 8) & 7);
+    trace_apic_local_deliver(vector, (lvt >> 8) & 7);
+
     if (lvt & APIC_LVT_MASKED)
         return;

@@ -300,9 +284,9 @@ void apic_deliver_irq(uint8_t dest, uint8_t dest_mode,
 {
     uint32_t deliver_bitmask[MAX_APIC_WORDS];

-    DPRINTF("%s: dest %d dest_mode %d delivery_mode %d vector %d"
-            " polarity %d trigger_mode %d\n", __func__, dest, dest_mode,
-            delivery_mode, vector_num, polarity, trigger_mode);
+    trace_apic_deliver_irq(dest, dest_mode, delivery_mode, vector_num,
+                           polarity, trigger_mode);
+
     apic_get_delivery_bitmask(deliver_bitmask, dest, dest_mode);
     apic_bus_deliver(deliver_bitmask, delivery_mode, vector_num, polarity,
                      trigger_mode);
@@ -312,7 +296,8 @@ void cpu_set_apic_base(DeviceState *d, uint64_t val)
 {
     APICState *s = DO_UPCAST(APICState, busdev.qdev, d);

-    DPRINTF("cpu_set_apic_base: %016" PRIx64 "\n", val);
+    trace_cpu_set_apic_base(val);
+
     if (!s)
         return;
     s->apicbase = (val & 0xfffff000) |
@@ -329,8 +314,8 @@ uint64_t cpu_get_apic_base(DeviceState *d)
 {
     APICState *s = DO_UPCAST(APICState, busdev.qdev, d);

-    DPRINTF("cpu_get_apic_base: %016" PRIx64 "\n",
-            s ? (uint64_t)s->apicbase: 0);
+    trace_cpu_get_apic_base(s ? (uint64_t)s->apicbase: 0);
+
     return s ? s->apicbase : 0;
 }

@@ -402,20 +387,23 @@ static void apic_update_irq(APICState *s)

 void apic_reset_irq_delivered(void)
 {
-    DPRINTF_C("%s: old coalescing %d\n", __func__, apic_irq_delivered);
+    trace_apic_reset_irq_delivered(apic_irq_delivered);
+
     apic_irq_delivered = 0;
 }

 int apic_get_irq_delivered(void)
 {
-    DPRINTF_C("%s: returning coalescing %d\n", __func__, apic_irq_delivered);
+    trace_apic_get_irq_delivered(apic_irq_delivered);
+
     return apic_irq_delivered;
 }

 static void apic_set_irq(APICState *s, int vector_num, int trigger_mode)
 {
     apic_irq_delivered += !get_bit(s->irr, vector_num);
-    DPRINTF_C("%s: coalescing %d\n", __func__, apic_irq_delivered);
+
+    trace_apic_set_irq(apic_irq_delivered);

     set_bit(s->irr, vector_num);
     if (trigger_mode)
@@ -769,7 +757,7 @@ static uint32_t apic_mem_readl(void *opaque,
target_phys_addr_t addr)
         val = 0;
         break;
     }
-    DPRINTF("read: " TARGET_FMT_plx " = %08x\n", addr, val);
+    trace_apic_mem_readl(addr, val);
     return val;
 }

@@ -805,7 +793,7 @@ static void apic_mem_writel(void *opaque,
target_phys_addr_t addr, uint32_t val)
     }
     s = DO_UPCAST(APICState, busdev.qdev, d);

-    DPRINTF("write: " TARGET_FMT_plx " = %08x\n", addr, val);
+    trace_apic_mem_writel(addr, val);

     switch(index) {
     case 0x02:
diff --git a/trace-events b/trace-events
index 4300178..1cac99a 100644
--- a/trace-events
+++ b/trace-events
@@ -69,3 +69,15 @@ disable cpu_out(unsigned int addr, unsigned int
val) "addr %#x value %u"
 # balloon.c
 # Since requests are raised via monitor, not many tracepoints are needed.
 disable 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 polarity, uint8_t
trigger_mode) "dest %d dest_mode %d delivery_mode %d vector %d
polarity %d trigger_mode %d"
+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
+apic_reset_irq_delivered(int apic_irq_delivered) "old coalescing %d"
+apic_get_irq_delivered(int apic_irq_delivered) "returning coalescing %d"
+apic_set_irq(int apic_irq_delivered) "coalescing %d"
-- 
1.6.2.4

[Qemu-devel] Re: [PATCH] apic: convert debug printf statements to tracepoints

[Stefan Hajnoczi]

Thanks for pointing out this problem with simpletrace.py.  There are two
issues:

1. The regular expression used by simpletrace.py to parse trace event
   declarations cannot cope with concatenated string literals.
2. Format strings must begin and end with double quotes.  This was previously
   undocumented but is necessary because cpp is not run over trace-events, so
   parsing the strings and portability macros is non-trivial.

The follow-up patches fix the regex, add documentation for the format string
double quotes requirement, and update your patch.

simpletrace.py should work for the coalesced apic trace events now.

Stefan

[Qemu-devel] [PATCH 1/3] trace: Relax trace-events parsing regex in simpletrace.py

[Stefan Hajnoczi]

The regular expression to parse trace event definitions assumed the
format string would be a simple double-quoted string.  However, we now
use PRI?64 for portability which splits string literals.  The regular
expression can disregard the format string entirely since simpletrace.py
never needs to use it.

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

diff --git a/simpletrace.py b/simpletrace.py
index c2cf168..553a727 100755
--- a/simpletrace.py
+++ b/simpletrace.py
@@ -19,7 +19,7 @@ header_version  = 0
 
 trace_fmt = '=QQQQQQQQ'
 trace_len = struct.calcsize(trace_fmt)
-event_re  = re.compile(r'(disable\s+)?([a-zA-Z0-9_]+)\(([^)]*)\)\s+"([^"]*)"')
+event_re  = re.compile(r'(disable\s+)?([a-zA-Z0-9_]+)\(([^)]*)\).*')
 
 def err(msg):
     sys.stderr.write(msg + '\n')
@@ -39,7 +39,7 @@ def parse_events(fobj):
         if m is None:
             continue
 
-        disable, name, args, fmt = m.groups()
+        disable, name, args = m.groups()
         events[event_num] = (name,) + get_argnames(args)
         event_num += 1
     return events
-- 
1.7.1

[Qemu-devel] Re: [PATCH 1/3] trace: Relax trace-events parsing regex in simpletrace.py

[Blue Swirl]

Thanks, applied all.

On Mon, Oct 18, 2010 at 12:42 PM, Stefan Hajnoczi
<stefanha@linux.vnet.ibm.com> wrote:
> The regular expression to parse trace event definitions assumed the
> format string would be a simple double-quoted string.  However, we now
> use PRI?64 for portability which splits string literals.  The regular
> expression can disregard the format string entirely since simpletrace.py
> never needs to use it.
>
> Signed-off-by: Stefan Hajnoczi <stefanha@linux.vnet.ibm.com>
> ---
>  simpletrace.py |    4 ++--
>  1 files changed, 2 insertions(+), 2 deletions(-)
>
> diff --git a/simpletrace.py b/simpletrace.py
> index c2cf168..553a727 100755
> --- a/simpletrace.py
> +++ b/simpletrace.py
> @@ -19,7 +19,7 @@ header_version  = 0
>
>  trace_fmt = '=QQQQQQQQ'
>  trace_len = struct.calcsize(trace_fmt)
> -event_re  = re.compile(r'(disable\s+)?([a-zA-Z0-9_]+)\(([^)]*)\)\s+"([^"]*)"')
> +event_re  = re.compile(r'(disable\s+)?([a-zA-Z0-9_]+)\(([^)]*)\).*')
>
>  def err(msg):
>     sys.stderr.write(msg + '\n')
> @@ -39,7 +39,7 @@ def parse_events(fobj):
>         if m is None:
>             continue
>
> -        disable, name, args, fmt = m.groups()
> +        disable, name, args = m.groups()
>         events[event_num] = (name,) + get_argnames(args)
>         event_num += 1
>     return events
> --
> 1.7.1
>
>

[Qemu-devel] [PATCH 2/3] trace: Format strings must begin/end with double quotes

[Stefan Hajnoczi]

Document the restriction that format strings must begin and end with
double quotes.  This is for easy parsing since we don't run cpp over
trace-events.

Signed-off-by: Stefan Hajnoczi <stefanha@linux.vnet.ibm.com>
---
 docs/tracing.txt |    5 ++++-
 1 files changed, 4 insertions(+), 1 deletions(-)

diff --git a/docs/tracing.txt b/docs/tracing.txt
index 5504850..963c504 100644
--- a/docs/tracing.txt
+++ b/docs/tracing.txt
@@ -74,7 +74,10 @@ 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.
+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"".
 
 === Hints for adding new trace events ===
 
-- 
1.7.1

[Qemu-devel] [PATCH 3/3] apic: convert debug printf statements to tracepoints

[Stefan Hajnoczi]

From: Blue Swirl <blauwirbel@gmail.com>

Replace debug printf statements with tracepoints.

Signed-off-by: Blue Swirl <blauwirbel@gmail.com>
Signed-off-by: Stefan Hajnoczi <stefanha@linux.vnet.ibm.com>
---
 hw/apic.c    |   48 ++++++++++++++++++------------------------------
 trace-events |   12 ++++++++++++
 2 files changed, 30 insertions(+), 30 deletions(-)

diff --git a/hw/apic.c b/hw/apic.c
index d686b51..63d62c7 100644
--- a/hw/apic.c
+++ b/hw/apic.c
@@ -21,23 +21,7 @@
 #include "qemu-timer.h"
 #include "host-utils.h"
 #include "sysbus.h"
-
-//#define DEBUG_APIC
-//#define DEBUG_COALESCING
-
-#ifdef DEBUG_APIC
-#define DPRINTF(fmt, ...)                                       \
-    do { printf("apic: " fmt , ## __VA_ARGS__); } while (0)
-#else
-#define DPRINTF(fmt, ...)
-#endif
-
-#ifdef DEBUG_COALESCING
-#define DPRINTF_C(fmt, ...)                                     \
-    do { printf("apic: " fmt , ## __VA_ARGS__); } while (0)
-#else
-#define DPRINTF_C(fmt, ...)
-#endif
+#include "trace.h"
 
 /* APIC Local Vector Table */
 #define APIC_LVT_TIMER   0
@@ -168,8 +152,8 @@ static void apic_local_deliver(APICState *s, int vector)
     uint32_t lvt = s->lvt[vector];
     int trigger_mode;
 
-    DPRINTF("%s: vector %d delivery mode %d\n", __func__, vector,
-            (lvt >> 8) & 7);
+    trace_apic_local_deliver(vector, (lvt >> 8) & 7);
+
     if (lvt & APIC_LVT_MASKED)
         return;
 
@@ -300,9 +284,9 @@ void apic_deliver_irq(uint8_t dest, uint8_t dest_mode,
 {
     uint32_t deliver_bitmask[MAX_APIC_WORDS];
 
-    DPRINTF("%s: dest %d dest_mode %d delivery_mode %d vector %d"
-            " polarity %d trigger_mode %d\n", __func__, dest, dest_mode,
-            delivery_mode, vector_num, polarity, trigger_mode);
+    trace_apic_deliver_irq(dest, dest_mode, delivery_mode, vector_num,
+                           polarity, trigger_mode);
+
     apic_get_delivery_bitmask(deliver_bitmask, dest, dest_mode);
     apic_bus_deliver(deliver_bitmask, delivery_mode, vector_num, polarity,
                      trigger_mode);
@@ -312,7 +296,8 @@ void cpu_set_apic_base(DeviceState *d, uint64_t val)
 {
     APICState *s = DO_UPCAST(APICState, busdev.qdev, d);
 
-    DPRINTF("cpu_set_apic_base: %016" PRIx64 "\n", val);
+    trace_cpu_set_apic_base(val);
+
     if (!s)
         return;
     s->apicbase = (val & 0xfffff000) |
@@ -329,8 +314,8 @@ uint64_t cpu_get_apic_base(DeviceState *d)
 {
     APICState *s = DO_UPCAST(APICState, busdev.qdev, d);
 
-    DPRINTF("cpu_get_apic_base: %016" PRIx64 "\n",
-            s ? (uint64_t)s->apicbase: 0);
+    trace_cpu_get_apic_base(s ? (uint64_t)s->apicbase: 0);
+
     return s ? s->apicbase : 0;
 }
 
@@ -402,20 +387,23 @@ static void apic_update_irq(APICState *s)
 
 void apic_reset_irq_delivered(void)
 {
-    DPRINTF_C("%s: old coalescing %d\n", __func__, apic_irq_delivered);
+    trace_apic_reset_irq_delivered(apic_irq_delivered);
+
     apic_irq_delivered = 0;
 }
 
 int apic_get_irq_delivered(void)
 {
-    DPRINTF_C("%s: returning coalescing %d\n", __func__, apic_irq_delivered);
+    trace_apic_get_irq_delivered(apic_irq_delivered);
+
     return apic_irq_delivered;
 }
 
 static void apic_set_irq(APICState *s, int vector_num, int trigger_mode)
 {
     apic_irq_delivered += !get_bit(s->irr, vector_num);
-    DPRINTF_C("%s: coalescing %d\n", __func__, apic_irq_delivered);
+
+    trace_apic_set_irq(apic_irq_delivered);
 
     set_bit(s->irr, vector_num);
     if (trigger_mode)
@@ -769,7 +757,7 @@ static uint32_t apic_mem_readl(void *opaque, target_phys_addr_t addr)
         val = 0;
         break;
     }
-    DPRINTF("read: " TARGET_FMT_plx " = %08x\n", addr, val);
+    trace_apic_mem_readl(addr, val);
     return val;
 }
 
@@ -805,7 +793,7 @@ static void apic_mem_writel(void *opaque, target_phys_addr_t addr, uint32_t val)
     }
     s = DO_UPCAST(APICState, busdev.qdev, d);
 
-    DPRINTF("write: " TARGET_FMT_plx " = %08x\n", addr, val);
+    trace_apic_mem_writel(addr, val);
 
     switch(index) {
     case 0x02:
diff --git a/trace-events b/trace-events
index 4300178..7857bcb 100644
--- a/trace-events
+++ b/trace-events
@@ -69,3 +69,15 @@ disable cpu_out(unsigned int addr, unsigned int val) "addr %#x value %u"
 # balloon.c
 # Since requests are raised via monitor, not many tracepoints are needed.
 disable 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 polarity, uint8_t trigger_mode) "dest %d dest_mode %d delivery_mode %d vector %d polarity %d trigger_mode %d"
+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
+apic_reset_irq_delivered(int apic_irq_delivered) "old coalescing %d"
+apic_get_irq_delivered(int apic_irq_delivered) "returning coalescing %d"
+apic_set_irq(int apic_irq_delivered) "coalescing %d"
-- 
1.7.1