Merge remote-tracking branch 'remotes/stefanha/tags/tracing-pull-request' into staging

Pull request

# gpg: Signature made Wed 18 Sep 2019 14:17:59 BST
# gpg:                using RSA key 8695A8BFD3F97CDAAC35775A9CA4ABB381AB73C8
# gpg: Good signature from "Stefan Hajnoczi <stefanha@redhat.com>" [full]
# gpg:                 aka "Stefan Hajnoczi <stefanha@gmail.com>" [full]
# Primary key fingerprint: 8695 A8BF D3F9 7CDA AC35  775A 9CA4 ABB3 81AB 73C8

* remotes/stefanha/tags/tracing-pull-request:
  trace: Forbid event format ending with newline character
  trace: Remove trailing newline in events
  loader: Trace loaded images

Signed-off-by: Peter Maydell <peter.maydell@linaro.org>

10 files changed, 23 insertions, 12 deletions

diff --git a/Makefile.objs b/Makefile.objs
index 6a143dcd57..abcbd89654 100644
--- a/Makefile.objs
+++ b/Makefile.objs
@@ -203,6 +203,7 @@ trace-events-subdirs += target/riscv
 trace-events-subdirs += target/s390x
 trace-events-subdirs += target/sparc
 trace-events-subdirs += util
+trace-events-subdirs += hw/core
 
 trace-events-files = $(SRC_PATH)/trace-events $(trace-events-subdirs:%=$(SRC_PATH)/%/trace-events)
 
diff --git a/docs/devel/tracing.txt b/docs/devel/tracing.txt
index 76e492a489..8231bbf5d1 100644
--- a/docs/devel/tracing.txt
+++ b/docs/devel/tracing.txt
@@ -112,6 +112,8 @@ 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.
+Format strings must not end with a newline character.  It is the responsibility
+of backends to adapt line ending for proper logging.
 
 Each event declaration will start with the event name, then its arguments,
 finally a format string for pretty-printing. For example:
diff --git a/hw/core/loader.c b/hw/core/loader.c
index 75eb56ddbb..0d60219364 100644
--- a/hw/core/loader.c
+++ b/hw/core/loader.c
@@ -45,6 +45,7 @@
 #include "qemu/osdep.h"
 #include "qemu-common.h"
 #include "qapi/error.h"
+#include "trace.h"
 #include "hw/hw.h"
 #include "disas/disas.h"
 #include "migration/vmstate.h"
@@ -1151,6 +1152,8 @@ static void rom_reset(void *unused)
          * CPU definitely fetches its instructions from the just written data.
          */
         cpu_flush_icache_range(rom->addr, rom->datasize);
+
+        trace_loader_write_rom(rom->name, rom->addr, rom->datasize, rom->isrom);
     }
 }
 
diff --git a/hw/core/trace-events b/hw/core/trace-events
new file mode 100644
index 0000000000..fe47a9c8cb
--- /dev/null
+++ b/hw/core/trace-events
@@ -0,0 +1,2 @@
+# loader.c
+loader_write_rom(const char *name, uint64_t gpa, uint64_t size, bool isrom) "%s: @0x%"PRIx64" size=0x%"PRIx64" ROM=%d"
diff --git a/hw/misc/trace-events b/hw/misc/trace-events
index c1ea1aa437..74276225f8 100644
--- a/hw/misc/trace-events
+++ b/hw/misc/trace-events
@@ -118,11 +118,11 @@ iotkit_secctl_ns_read(uint32_t offset, uint64_t data, unsigned size) "IoTKit Sec
 iotkit_secctl_ns_write(uint32_t offset, uint64_t data, unsigned size) "IoTKit SecCtl NS regs write: offset 0x%x data 0x%" PRIx64 " size %u"
 
 # imx6ul_ccm.c
-ccm_entry(void) "\n"
-ccm_freq(uint32_t freq) "freq = %d\n"
-ccm_clock_freq(uint32_t clock, uint32_t freq) "(Clock = %d) = %d\n"
-ccm_read_reg(const char *reg_name, uint32_t value) "reg[%s] <= 0x%" PRIx32 "\n"
-ccm_write_reg(const char *reg_name, uint32_t value) "reg[%s] => 0x%" PRIx32 "\n"
+ccm_entry(void) ""
+ccm_freq(uint32_t freq) "freq = %d"
+ccm_clock_freq(uint32_t clock, uint32_t freq) "(Clock = %d) = %d"
+ccm_read_reg(const char *reg_name, uint32_t value) "reg[%s] <= 0x%" PRIx32
+ccm_write_reg(const char *reg_name, uint32_t value) "reg[%s] => 0x%" PRIx32
 
 # iotkit-sysinfo.c
 iotkit_sysinfo_read(uint64_t offset, uint64_t data, unsigned size) "IoTKit SysInfo read: offset 0x%" PRIx64 " data 0x%" PRIx64 " size %u"
diff --git a/hw/scsi/trace-events b/hw/scsi/trace-events
index 452b5994e6..b0820052f8 100644
--- a/hw/scsi/trace-events
+++ b/hw/scsi/trace-events
@@ -28,7 +28,7 @@ mptsas_mmio_read(void *dev, uint32_t addr, uint32_t val) "dev %p addr 0x%08x val
 mptsas_mmio_unhandled_read(void *dev, uint32_t addr) "dev %p addr 0x%08x"
 mptsas_mmio_unhandled_write(void *dev, uint32_t addr, uint32_t val) "dev %p addr 0x%08x value 0x%x"
 mptsas_mmio_write(void *dev, uint32_t addr, uint32_t val) "dev %p addr 0x%08x value 0x%x"
-mptsas_process_message(void *dev, int msg, uint32_t ctx) "dev %p cmd %d context 0x%08x\n"
+mptsas_process_message(void *dev, int msg, uint32_t ctx) "dev %p cmd %d context 0x%08x"
 mptsas_process_scsi_io_request(void *dev, int bus, int target, int lun, uint64_t len) "dev %p dev %d:%d:%d length %"PRIu64""
 mptsas_reset(void *dev) "dev %p "
 mptsas_scsi_overflow(void *dev, uint32_t ctx, uint64_t req, uint64_t found) "dev %p context 0x%08x: %"PRIu64"/%"PRIu64""
diff --git a/hw/sd/trace-events b/hw/sd/trace-events
index 52971dc033..efcff666a2 100644
--- a/hw/sd/trace-events
+++ b/hw/sd/trace-events
@@ -4,7 +4,7 @@
 bcm2835_sdhost_read(uint64_t offset, uint64_t data, unsigned size) "offset 0x%" PRIx64 " data 0x%" PRIx64 " size %u"
 bcm2835_sdhost_write(uint64_t offset, uint64_t data, unsigned size) "offset 0x%" PRIx64 " data 0x%" PRIx64 " size %u"
 bcm2835_sdhost_edm_change(const char *why, uint32_t edm) "(%s) EDM now 0x%x"
-bcm2835_sdhost_update_irq(uint32_t irq) "IRQ bits 0x%x\n"
+bcm2835_sdhost_update_irq(uint32_t irq) "IRQ bits 0x%x"
 
 # core.c
 sdbus_command(const char *bus_name, uint8_t cmd, uint32_t arg) "@%s CMD%02d arg 0x%08x"
diff --git a/nbd/trace-events b/nbd/trace-events
index f6cde96790..a955918e97 100644
--- a/nbd/trace-events
+++ b/nbd/trace-events
@@ -61,8 +61,8 @@ nbd_negotiate_begin(void) "Beginning negotiation"
 nbd_negotiate_new_style_size_flags(uint64_t size, unsigned flags) "advertising size %" PRIu64 " and flags 0x%x"
 nbd_negotiate_success(void) "Negotiation succeeded"
 nbd_receive_request(uint32_t magic, uint16_t flags, uint16_t type, uint64_t from, uint32_t len) "Got request: { magic = 0x%" PRIx32 ", .flags = 0x%" PRIx16 ", .type = 0x%" PRIx16 ", from = %" PRIu64 ", len = %" PRIu32 " }"
-nbd_blk_aio_attached(const char *name, void *ctx) "Export %s: Attaching clients to AIO context %p\n"
-nbd_blk_aio_detach(const char *name, void *ctx) "Export %s: Detaching clients from AIO context %p\n"
+nbd_blk_aio_attached(const char *name, void *ctx) "Export %s: Attaching clients to AIO context %p"
+nbd_blk_aio_detach(const char *name, void *ctx) "Export %s: Detaching clients from AIO context %p"
 nbd_co_send_simple_reply(uint64_t handle, uint32_t error, const char *errname, int len) "Send simple reply: handle = %" PRIu64 ", error = %" PRIu32 " (%s), len = %d"
 nbd_co_send_structured_done(uint64_t handle) "Send structured reply done: handle = %" PRIu64
 nbd_co_send_structured_read(uint64_t handle, uint64_t offset, void *data, size_t size) "Send structured read data reply: handle = %" PRIu64 ", offset = %" PRIu64 ", data = %p, len = %zu"
diff --git a/net/trace-events b/net/trace-events
index ac57056497..02c13fd0ba 100644
--- a/net/trace-events
+++ b/net/trace-events
@@ -17,9 +17,9 @@ colo_compare_icmp_miscompare(const char *sta, int size) ": %s = %d"
 colo_compare_ip_info(int psize, const char *sta, const char *stb, int ssize, const char *stc, const char *std) "ppkt size = %d, ip_src = %s, ip_dst = %s, spkt size = %d, ip_src = %s, ip_dst = %s"
 colo_old_packet_check_found(int64_t old_time) "%" PRId64
 colo_compare_miscompare(void) ""
-colo_compare_tcp_info(const char *pkt, uint32_t seq, uint32_t ack, int hdlen, int pdlen, int offset, int flags) "%s: seq/ack= %u/%u hdlen= %d pdlen= %d offset= %d flags=%d\n"
+colo_compare_tcp_info(const char *pkt, uint32_t seq, uint32_t ack, int hdlen, int pdlen, int offset, int flags) "%s: seq/ack= %u/%u hdlen= %d pdlen= %d offset= %d flags=%d"
 
 # filter-rewriter.c
 colo_filter_rewriter_debug(void) ""
-colo_filter_rewriter_pkt_info(const char *func, const char *src, const char *dst, uint32_t seq, uint32_t ack, uint32_t flag) "%s: src/dst: %s/%s p: seq/ack=%u/%u  flags=0x%x\n"
-colo_filter_rewriter_conn_offset(uint32_t offset) ": offset=%u\n"
+colo_filter_rewriter_pkt_info(const char *func, const char *src, const char *dst, uint32_t seq, uint32_t ack, uint32_t flag) "%s: src/dst: %s/%s p: seq/ack=%u/%u  flags=0x%x"
+colo_filter_rewriter_conn_offset(uint32_t offset) ": offset=%u"
diff --git a/scripts/tracetool/__init__.py b/scripts/tracetool/__init__.py
index 6fca674936..04279fa62e 100644
--- a/scripts/tracetool/__init__.py
+++ b/scripts/tracetool/__init__.py
@@ -277,6 +277,9 @@ class Event(object):
         if fmt.find("%m") != -1 or fmt_trans.find("%m") != -1:
             raise ValueError("Event format '%m' is forbidden, pass the error "
                              "as an explicit trace argument")
+        if fmt.endswith(r'\n"'):
+            raise ValueError("Event format must not end with a newline "
+                             "character")
 
         if len(fmt_trans) > 0:
             fmt = [fmt_trans, fmt]