[Qemu-devel] [PULL 00/11] Tracing patches

[Qemu-devel] [PULL 00/11] Tracing patches

[Stefan Hajnoczi]

The following changes since commit e280ff5e9159ed227a117339c1157143627cab96:

  spice-qemu-char: Drop hackish vmc_register on spice_chr_write (2013-03-27 10:26:50 -0500)

are available in the git repository at:

  git://github.com/stefanha/qemu.git tracing

for you to fetch changes up to 7e8660032cd21c1bdc4160b8fab7deec62e1aa12:

  vl: add runstate_set tracepoint (2013-03-28 14:20:58 +0100)

----------------------------------------------------------------
Kazuya Saito (1):
      vl: add runstate_set tracepoint

Lluís Vilanova (7):
      trace: [tracetool] Explicitly identify public backends
      trace: Provide a generic tracing event descriptor
      trace: Provide a detailed event control interface
      trace: [monitor] Use new event control interface
      trace: [default] Port to generic event information and new control interface
      trace: [simple] Port to generic event information and new control interface
      trace: [stderr] Port to generic event information and new control interface

Stefan Hajnoczi (3):
      trace: rebuild generated-events.o when configuration changes
      .gitignore: add trace/generated-events.[ch]
      .gitignore: rename trace/generated-tracers.dtrace

 .gitignore                            |   4 +-
 Makefile                              |   3 +
 docs/tracing.txt                      |  44 ++++----
 monitor.c                             |  13 ++-
 scripts/tracetool.py                  |   4 +-
 scripts/tracetool/backend/__init__.py |  16 ++-
 scripts/tracetool/backend/dtrace.py   |   3 +
 scripts/tracetool/backend/events.py   |  23 ++++
 scripts/tracetool/backend/simple.py   |  22 ++--
 scripts/tracetool/backend/stderr.py   |  28 ++---
 scripts/tracetool/backend/ust.py      |   3 +
 scripts/tracetool/format/events_c.py  |  39 +++++++
 scripts/tracetool/format/events_h.py  |  50 +++++++++
 scripts/tracetool/format/h.py         |   9 +-
 trace-events                          |   1 +
 trace/Makefile.objs                   |  24 ++++-
 trace/control-internal.h              |  67 ++++++++++++
 trace/control.c                       | 106 ++++++++++++++++---
 trace/control.h                       | 190 ++++++++++++++++++++++++++++++----
 trace/default.c                       |   5 +-
 trace/event-internal.h                |  33 ++++++
 trace/simple.c                        |  35 ++-----
 trace/simple.h                        |   6 +-
 trace/stderr.c                        |  34 ++----
 trace/stderr.h                        |  11 --
 vl.c                                  |   2 +-
 26 files changed, 595 insertions(+), 180 deletions(-)
 create mode 100644 scripts/tracetool/backend/events.py
 create mode 100644 scripts/tracetool/format/events_c.py
 create mode 100644 scripts/tracetool/format/events_h.py
 create mode 100644 trace/control-internal.h
 create mode 100644 trace/event-internal.h
 delete mode 100644 trace/stderr.h

-- 
1.8.1.4

[Qemu-devel] [PULL 00/11] Tracing patches

[Stefan Hajnoczi]

The following changes since commit 609ef9f451759151d0bfe7c3843410ab94d68f18:

  Merge remote-tracking branch 'remotes/berrange/tags/qio-next-pull-request' into staging (2018-06-28 17:53:31 +0100)

are available in the Git repository at:

  git://github.com/stefanha/qemu.git tags/tracing-pull-request

for you to fetch changes up to 13019f1fd6c683b243120b7eb999f1b50a224940:

  hw/block/pflash_cfi: Convert from DPRINTF() macro to trace events (2018-06-29 15:04:18 +0100)

----------------------------------------------------------------
Pull request

 * Python 3 support in simpletrace.py
 * Convert DPRINTF() to trace events

----------------------------------------------------------------

Eduardo Habkost (1):
  simpletrace: Convert name from mapping record to str

Philippe Mathieu-Daudé (10):
  trace: Fix format string for the struct timeval members casted to
    size_t
  sdcard: Reduce sdcard_set_blocklen() trace digits
  hw/char/serial: Convert from DPRINTF macro to trace events
  hw/char/parallel: Convert from pdebug() macro to trace events
  hw/input/tsc2005: Convert a fprintf() call to trace events
  hw/net/ne2000: Add trace events
  hw/net/ne2000: Convert printf() calls to trace events
  hw/net/etraxfs_eth: Convert printf() calls to trace events
  hw/block/fdc: Convert from FLOPPY_DPRINTF() macro to trace events
  hw/block/pflash_cfi: Convert from DPRINTF() macro to trace events

 hw/block/fdc.c                   |  6 ++---
 hw/block/pflash_cfi01.c          | 42 ++++++++++++--------------------
 hw/block/pflash_cfi02.c          | 18 +++++++-------
 hw/char/parallel.c               | 16 +++++++++---
 hw/char/serial.c                 |  5 ++--
 hw/input/tsc2005.c               |  7 +++---
 hw/net/etraxfs_eth.c             |  8 +++---
 hw/net/ne2000.c                  | 25 ++++++++++---------
 hw/block/trace-events            | 17 +++++++++++++
 hw/char/trace-events             |  8 ++++++
 hw/input/trace-events            |  3 +++
 hw/net/trace-events              | 11 +++++++++
 hw/sd/trace-events               |  2 +-
 scripts/simpletrace.py           |  2 +-
 scripts/tracetool/backend/log.py |  2 +-
 15 files changed, 106 insertions(+), 66 deletions(-)

-- 
2.17.1

[Qemu-devel] [PULL 01/11] simpletrace: Convert name from mapping record to str

[Stefan Hajnoczi]

From: Eduardo Habkost <ehabkost@redhat.com>

The rest of the code assumes that idtoname is a (int -> str)
dictionary, so convert the data accordingly.

This is necessary to make the script work with Python 3 (where
reads from a binary file return 'bytes' objects, not 'str').

Fixes the following error:

  $ python3 ./scripts/simpletrace.py trace-events-all trace-27445
  b'object_class_dynamic_cast_assert' event is logged but is not \
  declared in the trace events file, try using trace-events-all instead.

Signed-off-by: Eduardo Habkost <ehabkost@redhat.com>
Message-id: 20180619194549.15584-1-ehabkost@redhat.com
Signed-off-by: Stefan Hajnoczi <stefanha@redhat.com>
---
 scripts/simpletrace.py | 2 +-
 1 file changed, 1 insertion(+), 1 deletion(-)

diff --git a/scripts/simpletrace.py b/scripts/simpletrace.py
index d4a50a1e2b..4ad34f90cd 100755
--- a/scripts/simpletrace.py
+++ b/scripts/simpletrace.py
@@ -70,7 +70,7 @@ def get_record(edict, idtoname, rechdr, fobj):
 def get_mapping(fobj):
     (event_id, ) = struct.unpack('=Q', fobj.read(8))
     (len, ) = struct.unpack('=L', fobj.read(4))
-    name = fobj.read(len)
+    name = fobj.read(len).decode()
 
     return (event_id, name)
 
-- 
2.17.1

[Qemu-devel] [PULL 02/11] trace: Fix format string for the struct timeval members casted to size_t

[Stefan Hajnoczi]

From: Philippe Mathieu-Daudé <f4bug@amsat.org>

This fixes when using GCC with -Wformat-signedness:

    migration/trace.h: In function ‘_nocheck__trace_dirty_bitmap_load_success’:
    migration/trace.h:6368:24: error: format ‘%zd’ expects argument of type ‘signed size_t’, but argument 3 has type ‘long unsigned int’ [-Werror=format=]
      qemu_log("%d@%zd.%06zd:dirty_bitmap_load_success " "" "\n",
                   ~~^
                   %ld
    migration/trace.h:6370:18:
               (size_t)_now.tv_sec, (size_t)_now.tv_usec
               ~~~~~~~~~~~~~~~~~~~
    migration/trace.h:6368:30: error: format ‘%zd’ expects argument of type ‘signed size_t’, but argument 4 has type ‘long unsigned int’ [-Werror=format=]
      qemu_log("%d@%zd.%06zd:dirty_bitmap_load_success " "" "\n",
                       ~~~~^
                       %06ld
    migration/trace.h:6370:39:
               (size_t)_now.tv_sec, (size_t)_now.tv_usec
                                    ~~~~~~~~~~~~~~~~~~~~

Signed-off-by: Philippe Mathieu-Daudé <f4bug@amsat.org>
Signed-off-by: Stefan Hajnoczi <stefanha@redhat.com>
---
 scripts/tracetool/backend/log.py | 2 +-
 1 file changed, 1 insertion(+), 1 deletion(-)

diff --git a/scripts/tracetool/backend/log.py b/scripts/tracetool/backend/log.py
index 78933d03ad..6751f41bc5 100644
--- a/scripts/tracetool/backend/log.py
+++ b/scripts/tracetool/backend/log.py
@@ -38,7 +38,7 @@ def generate_h(event, group):
     out('    if (%(cond)s && qemu_loglevel_mask(LOG_TRACE)) {',
         '        struct timeval _now;',
         '        gettimeofday(&_now, NULL);',
-        '        qemu_log("%%d@%%zd.%%06zd:%(name)s " %(fmt)s "\\n",',
+        '        qemu_log("%%d@%%zu.%%06zu:%(name)s " %(fmt)s "\\n",',
         '                 getpid(),',
         '                 (size_t)_now.tv_sec, (size_t)_now.tv_usec',
         '                 %(argnames)s);',
-- 
2.17.1

[Qemu-devel] [PULL 03/11] sdcard: Reduce sdcard_set_blocklen() trace digits

[Stefan Hajnoczi]

From: Philippe Mathieu-Daudé <f4bug@amsat.org>

Per the Physical Layer Simplified Spec. "5.3 CSD Register":

  "The maximum block length might therefore be in the range 512...2048 bytes"

Therefore 3 hexdigits are enough to report the block length.

Signed-off-by: Philippe Mathieu-Daudé <f4bug@amsat.org>
Signed-off-by: Stefan Hajnoczi <stefanha@redhat.com>
---
 hw/sd/trace-events | 2 +-
 1 file changed, 1 insertion(+), 1 deletion(-)

diff --git a/hw/sd/trace-events b/hw/sd/trace-events
index bfd1d62efc..d7880bcea5 100644
--- a/hw/sd/trace-events
+++ b/hw/sd/trace-events
@@ -37,7 +37,7 @@ sdcard_powerup(void) ""
 sdcard_inquiry_cmd41(void) ""
 sdcard_set_enable(bool current_state, bool new_state) "%u -> %u"
 sdcard_reset(void) ""
-sdcard_set_blocklen(uint16_t length) "0x%04x"
+sdcard_set_blocklen(uint16_t length) "0x%03x"
 sdcard_inserted(bool readonly) "read_only: %u"
 sdcard_ejected(void) ""
 sdcard_erase(void) ""
-- 
2.17.1

[Qemu-devel] [PULL 04/11] hw/char/serial: Convert from DPRINTF macro to trace events

[Stefan Hajnoczi]

From: Philippe Mathieu-Daudé <f4bug@amsat.org>

Signed-off-by: Philippe Mathieu-Daudé <f4bug@amsat.org>
Signed-off-by: Stefan Hajnoczi <stefanha@redhat.com>
---
 hw/char/serial.c     | 5 +++--
 hw/char/trace-events | 4 ++++
 2 files changed, 7 insertions(+), 2 deletions(-)

diff --git a/hw/char/serial.c b/hw/char/serial.c
index 605b0d02f9..26f53ba02f 100644
--- a/hw/char/serial.c
+++ b/hw/char/serial.c
@@ -29,6 +29,7 @@
 #include "qapi/error.h"
 #include "qemu/timer.h"
 #include "qemu/error-report.h"
+#include "trace.h"
 
 //#define DEBUG_SERIAL
 
@@ -335,7 +336,7 @@ static void serial_ioport_write(void *opaque, hwaddr addr, uint64_t val,
     SerialState *s = opaque;
 
     addr &= 7;
-    DPRINTF("write addr=0x%" HWADDR_PRIx " val=0x%" PRIx64 "\n", addr, val);
+    trace_serial_ioport_write(addr, val);
     switch(addr) {
     default:
     case 0:
@@ -548,7 +549,7 @@ static uint64_t serial_ioport_read(void *opaque, hwaddr addr, unsigned size)
         ret = s->scr;
         break;
     }
-    DPRINTF("read addr=0x%" HWADDR_PRIx " val=0x%02x\n", addr, ret);
+    trace_serial_ioport_read(addr, ret);
     return ret;
 }
 
diff --git a/hw/char/trace-events b/hw/char/trace-events
index ebd8a92450..158957627e 100644
--- a/hw/char/trace-events
+++ b/hw/char/trace-events
@@ -1,5 +1,9 @@
 # See docs/devel/tracing.txt for syntax documentation.
 
+# hw/char/serial.c
+serial_ioport_read(uint16_t addr, uint8_t value) "read addr 0x%02x val 0x%02x"
+serial_ioport_write(uint16_t addr, uint8_t value) "write addr 0x%02x val 0x%02x"
+
 # hw/char/virtio-serial-bus.c
 virtio_serial_send_control_event(unsigned int port, uint16_t event, uint16_t value) "port %u, event %u, value %u"
 virtio_serial_throttle_port(unsigned int port, bool throttle) "port %u, throttle %d"
-- 
2.17.1

[Qemu-devel] [PULL 05/11] hw/char/parallel: Convert from pdebug() macro to trace events

[Stefan Hajnoczi]

From: Philippe Mathieu-Daudé <f4bug@amsat.org>

Signed-off-by: Philippe Mathieu-Daudé <f4bug@amsat.org>
Signed-off-by: Stefan Hajnoczi <stefanha@redhat.com>
---
 hw/char/parallel.c   | 16 +++++++++++++---
 hw/char/trace-events |  4 ++++
 2 files changed, 17 insertions(+), 3 deletions(-)

diff --git a/hw/char/parallel.c b/hw/char/parallel.c
index 35748e6c1b..a80da47ecf 100644
--- a/hw/char/parallel.c
+++ b/hw/char/parallel.c
@@ -30,6 +30,7 @@
 #include "hw/isa/isa.h"
 #include "hw/char/parallel.h"
 #include "sysemu/sysemu.h"
+#include "trace.h"
 
 //#define DEBUG_PARALLEL
 
@@ -110,9 +111,8 @@ parallel_ioport_write_sw(void *opaque, uint32_t addr, uint32_t val)
 {
     ParallelState *s = opaque;
 
-    pdebug("write addr=0x%02x val=0x%02x\n", addr, val);
-
     addr &= 7;
+    trace_parallel_ioport_write("SW", addr, val);
     switch(addr) {
     case PARA_REG_DATA:
         s->dataw = val;
@@ -157,6 +157,7 @@ static void parallel_ioport_write_hw(void *opaque, uint32_t addr, uint32_t val)
     s->last_read_offset = ~0U;
 
     addr &= 7;
+    trace_parallel_ioport_write("HW", addr, val);
     switch(addr) {
     case PARA_REG_DATA:
         if (s->dataw == val)
@@ -230,6 +231,8 @@ parallel_ioport_eppdata_write_hw2(void *opaque, uint32_t addr, uint32_t val)
     struct ParallelIOArg ioarg = {
         .buffer = &eppdata, .count = sizeof(eppdata)
     };
+
+    trace_parallel_ioport_write("EPP", addr, val);
     if ((s->control & (PARA_CTR_DIR|PARA_CTR_SIGNAL)) != PARA_CTR_INIT) {
         /* Controls not correct for EPP data cycle, so do nothing */
         pdebug("we%04x s\n", val);
@@ -253,6 +256,8 @@ parallel_ioport_eppdata_write_hw4(void *opaque, uint32_t addr, uint32_t val)
     struct ParallelIOArg ioarg = {
         .buffer = &eppdata, .count = sizeof(eppdata)
     };
+
+    trace_parallel_ioport_write("EPP", addr, val);
     if ((s->control & (PARA_CTR_DIR|PARA_CTR_SIGNAL)) != PARA_CTR_INIT) {
         /* Controls not correct for EPP data cycle, so do nothing */
         pdebug("we%08x s\n", val);
@@ -299,7 +304,7 @@ static uint32_t parallel_ioport_read_sw(void *opaque, uint32_t addr)
         ret = s->control;
         break;
     }
-    pdebug("read addr=0x%02x val=0x%02x\n", addr, ret);
+    trace_parallel_ioport_read("SW", addr, ret);
     return ret;
 }
 
@@ -371,6 +376,7 @@ static uint32_t parallel_ioport_read_hw(void *opaque, uint32_t addr)
         }
         break;
     }
+    trace_parallel_ioport_read("HW", addr, ret);
     s->last_read_offset = addr;
     return ret;
 }
@@ -399,6 +405,7 @@ parallel_ioport_eppdata_read_hw2(void *opaque, uint32_t addr)
     }
     else
         pdebug("re%04x\n", ret);
+    trace_parallel_ioport_read("EPP", addr, ret);
     return ret;
 }
 
@@ -426,11 +433,13 @@ parallel_ioport_eppdata_read_hw4(void *opaque, uint32_t addr)
     }
     else
         pdebug("re%08x\n", ret);
+    trace_parallel_ioport_read("EPP", addr, ret);
     return ret;
 }
 
 static void parallel_ioport_ecp_write(void *opaque, uint32_t addr, uint32_t val)
 {
+    trace_parallel_ioport_write("ECP", addr & 7, val);
     pdebug("wecp%d=%02x\n", addr & 7, val);
 }
 
@@ -438,6 +447,7 @@ static uint32_t parallel_ioport_ecp_read(void *opaque, uint32_t addr)
 {
     uint8_t ret = 0xff;
 
+    trace_parallel_ioport_read("ECP", addr & 7, ret);
     pdebug("recp%d:%02x\n", addr & 7, ret);
     return ret;
 }
diff --git a/hw/char/trace-events b/hw/char/trace-events
index 158957627e..b64213d4dd 100644
--- a/hw/char/trace-events
+++ b/hw/char/trace-events
@@ -1,5 +1,9 @@
 # See docs/devel/tracing.txt for syntax documentation.
 
+# hw/char/parallel.c
+parallel_ioport_read(const char *desc, uint16_t addr, uint8_t value) "read [%s] addr 0x%02x val 0x%02x"
+parallel_ioport_write(const char *desc, uint16_t addr, uint8_t value) "write [%s] addr 0x%02x val 0x%02x"
+
 # hw/char/serial.c
 serial_ioport_read(uint16_t addr, uint8_t value) "read addr 0x%02x val 0x%02x"
 serial_ioport_write(uint16_t addr, uint8_t value) "write addr 0x%02x val 0x%02x"
-- 
2.17.1

[Qemu-devel] [PULL 06/11] hw/input/tsc2005: Convert a fprintf() call to trace events

[Stefan Hajnoczi]

From: Philippe Mathieu-Daudé <f4bug@amsat.org>

Signed-off-by: Philippe Mathieu-Daudé <f4bug@amsat.org>
Signed-off-by: Stefan Hajnoczi <stefanha@redhat.com>
---
 hw/input/tsc2005.c    | 7 +++----
 hw/input/trace-events | 3 +++
 2 files changed, 6 insertions(+), 4 deletions(-)

diff --git a/hw/input/tsc2005.c b/hw/input/tsc2005.c
index 4dd95596ab..2b9108a193 100644
--- a/hw/input/tsc2005.c
+++ b/hw/input/tsc2005.c
@@ -24,6 +24,7 @@
 #include "qemu/timer.h"
 #include "ui/console.h"
 #include "hw/devices.h"
+#include "trace.h"
 
 #define TSC_CUT_RESOLUTION(value, p)	((value) >> (16 - (p ? 12 : 10)))
 
@@ -201,8 +202,7 @@ static void tsc2005_write(TSC2005State *s, int reg, uint16_t data)
         s->host_mode = (data >> 15) != 0;
         if (s->enabled != !(data & 0x4000)) {
             s->enabled = !(data & 0x4000);
-            fprintf(stderr, "%s: touchscreen sense %sabled\n",
-                            __func__, s->enabled ? "en" : "dis");
+            trace_tsc2005_sense(s->enabled ? "enabled" : "disabled");
             if (s->busy && !s->enabled)
                 timer_del(s->timer);
             s->busy = s->busy && s->enabled;
@@ -340,8 +340,7 @@ static uint8_t tsc2005_txrx_word(void *opaque, uint8_t value)
                 s->nextprecision = (value >> 2) & 1;
                 if (s->enabled != !(value & 1)) {
                     s->enabled = !(value & 1);
-                    fprintf(stderr, "%s: touchscreen sense %sabled\n",
-                                    __func__, s->enabled ? "en" : "dis");
+                    trace_tsc2005_sense(s->enabled ? "enabled" : "disabled");
                     if (s->busy && !s->enabled)
                         timer_del(s->timer);
                     s->busy = s->busy && s->enabled;
diff --git a/hw/input/trace-events b/hw/input/trace-events
index db72484a25..3965a842ae 100644
--- a/hw/input/trace-events
+++ b/hw/input/trace-events
@@ -41,5 +41,8 @@ milkymist_softusb_pulse_irq(void) "Pulse IRQ"
 hid_kbd_queue_full(void) "queue full"
 hid_kbd_queue_empty(void) "queue empty"
 
+# hw/input/tsc2005.c
+tsc2005_sense(const char *state) "touchscreen sense %s"
+
 # hw/input/virtio
 virtio_input_queue_full(void) "queue full"
-- 
2.17.1

[Qemu-devel] [PULL 07/11] hw/net/ne2000: Add trace events

[Stefan Hajnoczi]

From: Philippe Mathieu-Daudé <f4bug@amsat.org>

Signed-off-by: Philippe Mathieu-Daudé <f4bug@amsat.org>
Signed-off-by: Stefan Hajnoczi <stefanha@redhat.com>
---
 hw/net/ne2000.c     | 17 ++++++++++++-----
 hw/net/trace-events |  4 ++++
 2 files changed, 16 insertions(+), 5 deletions(-)

diff --git a/hw/net/ne2000.c b/hw/net/ne2000.c
index 3a9fc89e48..26b234b7eb 100644
--- a/hw/net/ne2000.c
+++ b/hw/net/ne2000.c
@@ -26,6 +26,7 @@
 #include "net/eth.h"
 #include "ne2000.h"
 #include "sysemu/sysemu.h"
+#include "trace.h"
 
 /* debug NE2000 card */
 //#define DEBUG_NE2000
@@ -662,19 +663,24 @@ static uint64_t ne2000_read(void *opaque, hwaddr addr,
                             unsigned size)
 {
     NE2000State *s = opaque;
+    uint64_t val;
 
     if (addr < 0x10 && size == 1) {
-        return ne2000_ioport_read(s, addr);
+        val = ne2000_ioport_read(s, addr);
     } else if (addr == 0x10) {
         if (size <= 2) {
-            return ne2000_asic_ioport_read(s, addr);
+            val = ne2000_asic_ioport_read(s, addr);
         } else {
-            return ne2000_asic_ioport_readl(s, addr);
+            val = ne2000_asic_ioport_readl(s, addr);
         }
     } else if (addr == 0x1f && size == 1) {
-        return ne2000_reset_ioport_read(s, addr);
+        val = ne2000_reset_ioport_read(s, addr);
+    } else {
+        val = ((uint64_t)1 << (size * 8)) - 1;
     }
-    return ((uint64_t)1 << (size * 8)) - 1;
+    trace_ne2000_read(addr, val);
+
+    return val;
 }
 
 static void ne2000_write(void *opaque, hwaddr addr,
@@ -682,6 +688,7 @@ static void ne2000_write(void *opaque, hwaddr addr,
 {
     NE2000State *s = opaque;
 
+    trace_ne2000_write(addr, data);
     if (addr < 0x10 && size == 1) {
         ne2000_ioport_write(s, addr, data);
     } else if (addr == 0x10) {
diff --git a/hw/net/trace-events b/hw/net/trace-events
index 45c4e9fba0..95a1de01e9 100644
--- a/hw/net/trace-events
+++ b/hw/net/trace-events
@@ -23,6 +23,10 @@ mipsnet_read(uint64_t addr, uint32_t val) "read addr=0x%" PRIx64 " val=0x%x"
 mipsnet_write(uint64_t addr, uint64_t val) "write addr=0x%" PRIx64 " val=0x%" PRIx64
 mipsnet_irq(uint32_t isr, uint32_t intctl) "set irq to %d (0x%02x)"
 
+# hw/net/ne2000.c
+ne2000_read(uint64_t addr, uint64_t val) "read addr=0x%" PRIx64 " val=0x%" PRIx64
+ne2000_write(uint64_t addr, uint64_t val) "write addr=0x%" PRIx64 " val=0x%" PRIx64
+
 # hw/net/opencores_eth.c
 open_eth_mii_write(unsigned idx, uint16_t v) "MII[0x%02x] <- 0x%04x"
 open_eth_mii_read(unsigned idx, uint16_t v) "MII[0x%02x] -> 0x%04x"
-- 
2.17.1

[Qemu-devel] [PULL 08/11] hw/net/ne2000: Convert printf() calls to trace events

[Stefan Hajnoczi]

From: Philippe Mathieu-Daudé <f4bug@amsat.org>

Signed-off-by: Philippe Mathieu-Daudé <f4bug@amsat.org>
Signed-off-by: Stefan Hajnoczi <stefanha@redhat.com>
---
 hw/net/ne2000.c     | 8 ++------
 hw/net/trace-events | 2 ++
 2 files changed, 4 insertions(+), 6 deletions(-)

diff --git a/hw/net/ne2000.c b/hw/net/ne2000.c
index 26b234b7eb..07d79e317f 100644
--- a/hw/net/ne2000.c
+++ b/hw/net/ne2000.c
@@ -277,9 +277,7 @@ static void ne2000_ioport_write(void *opaque, uint32_t addr, uint32_t val)
     int offset, page, index;
 
     addr &= 0xf;
-#ifdef DEBUG_NE2000
-    printf("NE2000: write addr=0x%x val=0x%02x\n", addr, val);
-#endif
+    trace_ne2000_ioport_write(addr, val);
     if (addr == E8390_CMD) {
         /* control register */
         s->cmd = val;
@@ -442,9 +440,7 @@ static uint32_t ne2000_ioport_read(void *opaque, uint32_t addr)
             break;
         }
     }
-#ifdef DEBUG_NE2000
-    printf("NE2000: read addr=0x%x val=%02x\n", addr, ret);
-#endif
+    trace_ne2000_ioport_read(addr, ret);
     return ret;
 }
 
diff --git a/hw/net/trace-events b/hw/net/trace-events
index 95a1de01e9..f57010df37 100644
--- a/hw/net/trace-events
+++ b/hw/net/trace-events
@@ -26,6 +26,8 @@ mipsnet_irq(uint32_t isr, uint32_t intctl) "set irq to %d (0x%02x)"
 # hw/net/ne2000.c
 ne2000_read(uint64_t addr, uint64_t val) "read addr=0x%" PRIx64 " val=0x%" PRIx64
 ne2000_write(uint64_t addr, uint64_t val) "write addr=0x%" PRIx64 " val=0x%" PRIx64
+ne2000_ioport_read(uint64_t addr, uint64_t val) "io read addr=0x%02" PRIx64 " val=0x%02" PRIx64
+ne2000_ioport_write(uint64_t addr, uint64_t val) "io write addr=0x%02" PRIx64 " val=0x%02" PRIx64
 
 # hw/net/opencores_eth.c
 open_eth_mii_write(unsigned idx, uint16_t v) "MII[0x%02x] <- 0x%04x"
-- 
2.17.1

[Qemu-devel] [PULL 09/11] hw/net/etraxfs_eth: Convert printf() calls to trace events

[Stefan Hajnoczi]

From: Philippe Mathieu-Daudé <f4bug@amsat.org>

Suggested-by: Alistair Francis <alistair@alistair23.me>
Signed-off-by: Philippe Mathieu-Daudé <f4bug@amsat.org>
Signed-off-by: Stefan Hajnoczi <stefanha@redhat.com>
---
 hw/net/etraxfs_eth.c | 8 ++++----
 hw/net/trace-events  | 5 +++++
 2 files changed, 9 insertions(+), 4 deletions(-)

diff --git a/hw/net/etraxfs_eth.c b/hw/net/etraxfs_eth.c
index 013c8d0a41..a6932432b1 100644
--- a/hw/net/etraxfs_eth.c
+++ b/hw/net/etraxfs_eth.c
@@ -27,6 +27,7 @@
 #include "net/net.h"
 #include "hw/cris/etraxfs.h"
 #include "qemu/error-report.h"
+#include "trace.h"
 
 #define D(x)
 
@@ -106,7 +107,7 @@ static unsigned int tdk_read(struct qemu_phy *phy, unsigned int req)
         r = phy->regs[regnum];
         break;
     }
-    D(printf("\n%s %x = reg[%d]\n", __func__, r, regnum));
+    trace_mdio_phy_read(regnum, r);
     return r;
 }
 
@@ -116,7 +117,7 @@ tdk_write(struct qemu_phy *phy, unsigned int req, unsigned int data)
     int regnum;
 
     regnum = req & 0x1f;
-    D(printf("%s reg[%d] = %x\n", __func__, regnum, data));
+    trace_mdio_phy_write(regnum, data);
     switch (regnum) {
     default:
         phy->regs[regnum] = data;
@@ -206,8 +207,7 @@ static void mdio_cycle(struct qemu_mdio *bus)
 {
     bus->cnt++;
 
-    D(printf("mdc=%d mdio=%d state=%d cnt=%d drv=%d\n",
-        bus->mdc, bus->mdio, bus->state, bus->cnt, bus->drive));
+    trace_mdio_bitbang(bus->mdc, bus->mdio, bus->state, bus->cnt, bus->drive);
 #if 0
     if (bus->mdc) {
         printf("%d", bus->mdio);
diff --git a/hw/net/trace-events b/hw/net/trace-events
index f57010df37..663bea1b74 100644
--- a/hw/net/trace-events
+++ b/hw/net/trace-events
@@ -1,5 +1,10 @@
 # See docs/devel/tracing.txt for syntax documentation.
 
+# hw/net/etraxfs_eth.c
+mdio_phy_read(int regnum, uint16_t value) "read phy_reg:%d value:0x%04x"
+mdio_phy_write(int regnum, uint16_t value) "write phy_reg:%d value:0x%04x"
+mdio_bitbang(bool mdc, bool mdio, int state, uint16_t cnt, unsigned int drive) "bitbang mdc=%u mdio=%u state=%d cnt=%u drv=%d"
+
 # hw/net/lance.c
 lance_mem_readw(uint64_t addr, uint32_t ret) "addr=0x%"PRIx64"val=0x%04x"
 lance_mem_writew(uint64_t addr, uint32_t val) "addr=0x%"PRIx64"val=0x%04x"
-- 
2.17.1

[Qemu-devel] [PULL 10/11] hw/block/fdc: Convert from FLOPPY_DPRINTF() macro to trace events

[Stefan Hajnoczi]

From: Philippe Mathieu-Daudé <f4bug@amsat.org>

Signed-off-by: Philippe Mathieu-Daudé <f4bug@amsat.org>
Reviewed-by: John Snow <jsnow@redhat.com>
Signed-off-by: Stefan Hajnoczi <stefanha@redhat.com>
---
 hw/block/fdc.c        | 6 +++---
 hw/block/trace-events | 4 ++++
 2 files changed, 7 insertions(+), 3 deletions(-)

diff --git a/hw/block/fdc.c b/hw/block/fdc.c
index cd29e27d8f..c7b4fe9b3e 100644
--- a/hw/block/fdc.c
+++ b/hw/block/fdc.c
@@ -40,6 +40,7 @@
 #include "sysemu/blockdev.h"
 #include "sysemu/sysemu.h"
 #include "qemu/log.h"
+#include "trace.h"
 
 /********************************************************/
 /* debug Floppy devices */
@@ -934,7 +935,7 @@ static uint32_t fdctrl_read (void *opaque, uint32_t reg)
         retval = (uint32_t)(-1);
         break;
     }
-    FLOPPY_DPRINTF("read reg%d: 0x%02x\n", reg & 7, retval);
+    trace_fdc_ioport_read(reg, retval);
 
     return retval;
 }
@@ -943,9 +944,8 @@ static void fdctrl_write (void *opaque, uint32_t reg, uint32_t value)
 {
     FDCtrl *fdctrl = opaque;
 
-    FLOPPY_DPRINTF("write reg%d: 0x%02x\n", reg & 7, value);
-
     reg &= 7;
+    trace_fdc_ioport_write(reg, value);
     switch (reg) {
     case FD_REG_DOR:
         fdctrl_write_dor(fdctrl, value);
diff --git a/hw/block/trace-events b/hw/block/trace-events
index 6b9e733412..d842c45409 100644
--- a/hw/block/trace-events
+++ b/hw/block/trace-events
@@ -1,5 +1,9 @@
 # See docs/devel/tracing.txt for syntax documentation.
 
+# hw/block/fdc.c
+fdc_ioport_read(uint8_t reg, uint8_t value) "read reg 0x%02x val 0x%02x"
+fdc_ioport_write(uint8_t reg, uint8_t value) "write reg 0x%02x val 0x%02x"
+
 # hw/block/virtio-blk.c
 virtio_blk_req_complete(void *vdev, void *req, int status) "vdev %p req %p status %d"
 virtio_blk_rw_complete(void *vdev, void *req, int ret) "vdev %p req %p ret %d"
-- 
2.17.1

[Qemu-devel] [PULL 11/11] hw/block/pflash_cfi: Convert from DPRINTF() macro to trace events

[Stefan Hajnoczi]

From: Philippe Mathieu-Daudé <f4bug@amsat.org>

Signed-off-by: Philippe Mathieu-Daudé <f4bug@amsat.org>
[Fixed lx -> PRIx64 as suggested by Philippe.
--Stefan]
Signed-off-by: Stefan Hajnoczi <stefanha@redhat.com>
---
 hw/block/pflash_cfi01.c | 42 +++++++++++++++--------------------------
 hw/block/pflash_cfi02.c | 18 +++++++++---------
 hw/block/trace-events   | 13 +++++++++++++
 3 files changed, 37 insertions(+), 36 deletions(-)

diff --git a/hw/block/pflash_cfi01.c b/hw/block/pflash_cfi01.c
index e4b5b3c273..bffb4c40e7 100644
--- a/hw/block/pflash_cfi01.c
+++ b/hw/block/pflash_cfi01.c
@@ -47,6 +47,7 @@
 #include "qemu/log.h"
 #include "hw/sysbus.h"
 #include "sysemu/sysemu.h"
+#include "trace.h"
 
 #define PFLASH_BUG(fmt, ...) \
 do { \
@@ -120,7 +121,7 @@ static void pflash_timer (void *opaque)
 {
     pflash_t *pfl = opaque;
 
-    DPRINTF("%s: command %02x done\n", __func__, pfl->cmd);
+    trace_pflash_timer_expired(pfl->cmd);
     /* Reset flash */
     pfl->status ^= 0x80;
     memory_region_rom_device_set_romd(&pfl->mem, true);
@@ -218,15 +219,14 @@ static uint32_t pflash_devid_query(pflash_t *pfl, hwaddr offset)
     switch (boff & 0xFF) {
     case 0:
         resp = pfl->ident0;
-        DPRINTF("%s: Manufacturer Code %04x\n", __func__, resp);
+        trace_pflash_manufacturer_id(resp);
         break;
     case 1:
         resp = pfl->ident1;
-        DPRINTF("%s: Device ID Code %04x\n", __func__, resp);
+        trace_pflash_device_id(resp);
         break;
     default:
-        DPRINTF("%s: Read Device Information offset=%x\n", __func__,
-                (unsigned)offset);
+        trace_pflash_device_info(offset);
         return 0;
         break;
     }
@@ -251,8 +251,7 @@ static uint32_t pflash_data_read(pflash_t *pfl, hwaddr offset,
     switch (width) {
     case 1:
         ret = p[offset];
-        DPRINTF("%s: data offset " TARGET_FMT_plx " %02x\n",
-                __func__, offset, ret);
+        trace_pflash_data_read8(offset, ret);
         break;
     case 2:
         if (be) {
@@ -262,8 +261,7 @@ static uint32_t pflash_data_read(pflash_t *pfl, hwaddr offset,
             ret = p[offset];
             ret |= p[offset + 1] << 8;
         }
-        DPRINTF("%s: data offset " TARGET_FMT_plx " %04x\n",
-                __func__, offset, ret);
+        trace_pflash_data_read16(offset, ret);
         break;
     case 4:
         if (be) {
@@ -277,8 +275,7 @@ static uint32_t pflash_data_read(pflash_t *pfl, hwaddr offset,
             ret |= p[offset + 2] << 16;
             ret |= p[offset + 3] << 24;
         }
-        DPRINTF("%s: data offset " TARGET_FMT_plx " %08x\n",
-                __func__, offset, ret);
+        trace_pflash_data_read32(offset, ret);
         break;
     default:
         DPRINTF("BUG in %s\n", __func__);
@@ -294,11 +291,7 @@ static uint32_t pflash_read (pflash_t *pfl, hwaddr offset,
     uint32_t ret;
 
     ret = -1;
-
-#if 0
-    DPRINTF("%s: reading offset " TARGET_FMT_plx " under cmd %02x width %d\n",
-            __func__, offset, pfl->cmd, width);
-#endif
+    trace_pflash_read(offset, pfl->cmd, width, pfl->wcycle);
     switch (pfl->cmd) {
     default:
         /* This should never happen : reset state & treat it as a read */
@@ -349,15 +342,14 @@ static uint32_t pflash_read (pflash_t *pfl, hwaddr offset,
             switch (boff) {
             case 0:
                 ret = pfl->ident0 << 8 | pfl->ident1;
-                DPRINTF("%s: Manufacturer Code %04x\n", __func__, ret);
+                trace_pflash_manufacturer_id(ret);
                 break;
             case 1:
                 ret = pfl->ident2 << 8 | pfl->ident3;
-                DPRINTF("%s: Device ID Code %04x\n", __func__, ret);
+                trace_pflash_device_id(ret);
                 break;
             default:
-                DPRINTF("%s: Read Device Information boff=%x\n", __func__,
-                        (unsigned)boff);
+                trace_pflash_device_info(boff);
                 ret = 0;
                 break;
             }
@@ -425,9 +417,7 @@ static inline void pflash_data_write(pflash_t *pfl, hwaddr offset,
 {
     uint8_t *p = pfl->storage;
 
-    DPRINTF("%s: block write offset " TARGET_FMT_plx
-            " value %x counter %016" PRIx64 "\n",
-            __func__, offset, value, pfl->counter);
+    trace_pflash_data_write(offset, value, width, pfl->counter);
     switch (width) {
     case 1:
         p[offset] = value;
@@ -466,9 +456,7 @@ static void pflash_write(pflash_t *pfl, hwaddr offset,
 
     cmd = value;
 
-    DPRINTF("%s: writing offset " TARGET_FMT_plx " value %08x width %d wcycle 0x%x\n",
-            __func__, offset, value, width, pfl->wcycle);
-
+    trace_pflash_write(offset, value, width, pfl->wcycle);
     if (!pfl->wcycle) {
         /* Set the device in I/O access mode */
         memory_region_rom_device_set_romd(&pfl->mem, false);
@@ -656,8 +644,8 @@ static void pflash_write(pflash_t *pfl, hwaddr offset,
                   "\n", __func__, offset, pfl->wcycle, pfl->cmd, value);
 
  reset_flash:
+    trace_pflash_reset();
     memory_region_rom_device_set_romd(&pfl->mem, true);
-
     pfl->wcycle = 0;
     pfl->cmd = 0;
 }
diff --git a/hw/block/pflash_cfi02.c b/hw/block/pflash_cfi02.c
index 6c18e5e578..0f8b7b8c7b 100644
--- a/hw/block/pflash_cfi02.c
+++ b/hw/block/pflash_cfi02.c
@@ -43,6 +43,7 @@
 #include "sysemu/block-backend.h"
 #include "qemu/host-utils.h"
 #include "hw/sysbus.h"
+#include "trace.h"
 
 //#define PFLASH_DEBUG
 #ifdef PFLASH_DEBUG
@@ -124,7 +125,7 @@ static void pflash_timer (void *opaque)
 {
     pflash_t *pfl = opaque;
 
-    DPRINTF("%s: command %02x done\n", __func__, pfl->cmd);
+    trace_pflash_timer_expired(pfl->cmd);
     /* Reset flash */
     pfl->status ^= 0x80;
     if (pfl->bypass) {
@@ -143,8 +144,8 @@ static uint32_t pflash_read (pflash_t *pfl, hwaddr offset,
     uint32_t ret;
     uint8_t *p;
 
-    DPRINTF("%s: offset " TARGET_FMT_plx "\n", __func__, offset);
     ret = -1;
+    trace_pflash_read(offset, pfl->cmd, width, pfl->wcycle);
     /* Lazy reset to ROMD mode after a certain amount of read accesses */
     if (!pfl->rom_mode && pfl->wcycle == 0 &&
         ++pfl->read_counter > PFLASH_LAZY_ROMD_THRESHOLD) {
@@ -172,7 +173,7 @@ static uint32_t pflash_read (pflash_t *pfl, hwaddr offset,
         switch (width) {
         case 1:
             ret = p[offset];
-//            DPRINTF("%s: data offset %08x %02x\n", __func__, offset, ret);
+            trace_pflash_data_read8(offset, ret);
             break;
         case 2:
             if (be) {
@@ -182,7 +183,7 @@ static uint32_t pflash_read (pflash_t *pfl, hwaddr offset,
                 ret = p[offset];
                 ret |= p[offset + 1] << 8;
             }
-//            DPRINTF("%s: data offset %08x %04x\n", __func__, offset, ret);
+            trace_pflash_data_read16(offset, ret);
             break;
         case 4:
             if (be) {
@@ -196,7 +197,7 @@ static uint32_t pflash_read (pflash_t *pfl, hwaddr offset,
                 ret |= p[offset + 2] << 16;
                 ret |= p[offset + 3] << 24;
             }
-//            DPRINTF("%s: data offset %08x %08x\n", __func__, offset, ret);
+            trace_pflash_data_read32(offset, ret);
             break;
         }
         break;
@@ -274,8 +275,7 @@ static void pflash_write (pflash_t *pfl, hwaddr offset,
 #endif
         goto reset_flash;
     }
-    DPRINTF("%s: offset " TARGET_FMT_plx " %08x %d %d\n", __func__,
-            offset, value, width, pfl->wcycle);
+    trace_pflash_write(offset, value, width, pfl->wcycle);
     offset &= pfl->chip_len - 1;
 
     DPRINTF("%s: offset " TARGET_FMT_plx " %08x %d\n", __func__,
@@ -345,8 +345,7 @@ static void pflash_write (pflash_t *pfl, hwaddr offset,
             /* We need another unlock sequence */
             goto check_unlock0;
         case 0xA0:
-            DPRINTF("%s: write data offset " TARGET_FMT_plx " %08x %d\n",
-                    __func__, offset, value, width);
+            trace_pflash_data_write(offset, value, width, 0);
             p = pfl->storage;
             if (!pfl->ro) {
                 switch (width) {
@@ -483,6 +482,7 @@ static void pflash_write (pflash_t *pfl, hwaddr offset,
 
     /* Reset flash */
  reset_flash:
+    trace_pflash_reset();
     pfl->bypass = 0;
     pfl->wcycle = 0;
     pfl->cmd = 0;
diff --git a/hw/block/trace-events b/hw/block/trace-events
index d842c45409..335c092450 100644
--- a/hw/block/trace-events
+++ b/hw/block/trace-events
@@ -4,6 +4,19 @@
 fdc_ioport_read(uint8_t reg, uint8_t value) "read reg 0x%02x val 0x%02x"
 fdc_ioport_write(uint8_t reg, uint8_t value) "write reg 0x%02x val 0x%02x"
 
+# hw/block/pflash_cfi0?.c
+pflash_reset(void) "reset"
+pflash_read(uint64_t offset, uint8_t cmd, int width, uint8_t wcycle) "offset:0x%04"PRIx64" cmd:0x%02x width:%d wcycle:%u"
+pflash_write(uint64_t offset, uint32_t value, int width, uint8_t wcycle) "offset:0x%04"PRIx64" value:0x%03x width:%d wcycle:%u"
+pflash_timer_expired(uint8_t cmd) "command 0x%02x done"
+pflash_data_read8(uint64_t offset, uint32_t value) "data offset:0x%04"PRIx64" value:0x%02x"
+pflash_data_read16(uint64_t offset, uint32_t value) "data offset:0x%04"PRIx64" value:0x%04x"
+pflash_data_read32(uint64_t offset, uint32_t value) "data offset:0x%04"PRIx64" value:0x%08x"
+pflash_data_write(uint64_t offset, uint32_t value, int width, uint64_t counter) "data offset:0x%04"PRIx64" value:0x%08x width:%d counter:0x%016"PRIx64
+pflash_manufacturer_id(uint16_t id) "Read Manufacturer ID: 0x%04x"
+pflash_device_id(uint16_t id) "Read Device ID: 0x%04x"
+pflash_device_info(uint64_t offset) "Read Device Information offset:0x%04"PRIx64
+
 # hw/block/virtio-blk.c
 virtio_blk_req_complete(void *vdev, void *req, int status) "vdev %p req %p status %d"
 virtio_blk_rw_complete(void *vdev, void *req, int ret) "vdev %p req %p ret %d"
-- 
2.17.1

Re: [Qemu-devel] [PULL 00/11] Tracing patches

[Peter Maydell]

On 29 June 2018 at 18:53, Stefan Hajnoczi <stefanha@redhat.com> wrote:
> The following changes since commit 609ef9f451759151d0bfe7c3843410ab94d68f18:
>
>   Merge remote-tracking branch 'remotes/berrange/tags/qio-next-pull-request' into staging (2018-06-28 17:53:31 +0100)
>
> are available in the Git repository at:
>
>   git://github.com/stefanha/qemu.git tags/tracing-pull-request
>
> for you to fetch changes up to 13019f1fd6c683b243120b7eb999f1b50a224940:
>
>   hw/block/pflash_cfi: Convert from DPRINTF() macro to trace events (2018-06-29 15:04:18 +0100)
>
> ----------------------------------------------------------------
> Pull request
>
>  * Python 3 support in simpletrace.py
>  * Convert DPRINTF() to trace events

Applied, thanks.

-- PMM