[PULL 00/11] Tracing patches

[PULL 00/11] Tracing patches

[Stefan Hajnoczi]

The following changes since commit 74208cd252c5da9d867270a178799abd802b9338:

  Merge remote-tracking branch 'remotes/berrange-gitlab/tags/misc-fixes-pull-request' into staging (2021-01-29 19:51:25 +0000)

are available in the Git repository at:

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

for you to fetch changes up to 0dfb3ca73c54fc105ab78e37e31ab05bed1360aa:

  trace: update docs with meson build information (2021-02-01 11:23:04 +0000)

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

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

Daniel P. Berrangé (1):
  tracetool: also strip %l and %ll from systemtap format strings

Laurent Vivier (1):
  tracetool: fix "PRI" macro decoding

Stefan Hajnoczi (8):
  trace: fix simpletrace doc mismerge
  tracing: convert documentation to rST
  trace: recommend "log" backend for getting started with tracing
  trace: add meson custom_target() depend_files for tracetool
  error: rename error_with_timestamp to message_with_timestamp
  trace: make the 'log' backend timestamp configurable
  trace: document how to specify multiple --trace patterns
  trace: update docs with meson build information

Volker Rümelin (1):
  simpletrace: build() missing 2 required positional arguments

 docs/devel/index.rst                    |   1 +
 docs/devel/{tracing.txt => tracing.rst} | 248 ++++++++++++++----------
 meson.build                             |  28 ++-
 include/qemu/error-report.h             |   2 +-
 softmmu/vl.c                            |   2 +-
 util/qemu-error.c                       |   4 +-
 scripts/simpletrace.py                  |   4 +-
 scripts/tracetool/backend/log.py        |  19 +-
 scripts/tracetool/format/log_stap.py    |   8 +-
 trace/meson.build                       |  21 +-
 10 files changed, 216 insertions(+), 121 deletions(-)
 rename docs/devel/{tracing.txt => tracing.rst} (72%)

-- 
2.29.2

[PULL 01/11] trace: fix simpletrace doc mismerge

[Stefan Hajnoczi]

The simpletrace documentation section was accidentally split when the
ftrace section was introduced. Move the simpletrace-specific
documentation back into the simpletrace section.

Fixes: e64dd5efb2c6d522a3bc9d096cd49a4e53f0ae10 ("trace: document ftrace backend")
Reviewed-by: Peter Maydell <peter.maydell@linaro.org>
Signed-off-by: Stefan Hajnoczi <stefanha@redhat.com>
Message-id: 20201216160923.722894-2-stefanha@redhat.com
Signed-off-by: Stefan Hajnoczi <stefanha@redhat.com>
---
 docs/devel/tracing.txt | 34 +++++++++++++++++-----------------
 1 file changed, 17 insertions(+), 17 deletions(-)

diff --git a/docs/devel/tracing.txt b/docs/devel/tracing.txt
index dba43fc7a4..313b8ea4e9 100644
--- a/docs/devel/tracing.txt
+++ b/docs/devel/tracing.txt
@@ -218,6 +218,23 @@ source tree.  It may not be as powerful as platform-specific or third-party
 trace backends but it is portable.  This is the recommended trace backend
 unless you have specific needs for more advanced backends.
 
+==== Monitor commands ====
+
+* trace-file on|off|flush|set <path>
+  Enable/disable/flush the trace file or set the trace file name.
+
+==== Analyzing trace files ====
+
+The "simple" backend produces binary trace files that can be formatted with the
+simpletrace.py script.  The script takes the "trace-events-all" file and the
+binary trace:
+
+    ./scripts/simpletrace.py trace-events-all trace-12345
+
+You must ensure that the same "trace-events-all" file was used to build QEMU,
+otherwise trace event declarations may have changed and output will not be
+consistent.
+
 === Ftrace ===
 
 The "ftrace" backend writes trace data to ftrace marker. This effectively
@@ -246,23 +263,6 @@ NOTE: syslog may squash duplicate consecutive trace events and apply rate
 
 Restriction: "syslog" backend is restricted to POSIX compliant OS.
 
-==== Monitor commands ====
-
-* trace-file on|off|flush|set <path>
-  Enable/disable/flush the trace file or set the trace file name.
-
-==== Analyzing trace files ====
-
-The "simple" backend produces binary trace files that can be formatted with the
-simpletrace.py script.  The script takes the "trace-events-all" file and the
-binary trace:
-
-    ./scripts/simpletrace.py trace-events-all trace-12345
-
-You must ensure that the same "trace-events-all" file was used to build QEMU,
-otherwise trace event declarations may have changed and output will not be
-consistent.
-
 === LTTng Userspace Tracer ===
 
 The "ust" backend uses the LTTng Userspace Tracer library.  There are no
-- 
2.29.2

[PULL 02/11] tracing: convert documentation to rST

[Stefan Hajnoczi]

This is a simple rST conversion of the documentation.

Reviewed-by: Peter Maydell <peter.maydell@linaro.org>
Signed-off-by: Stefan Hajnoczi <stefanha@redhat.com>
Message-id: 20201216160923.722894-3-stefanha@redhat.com
Signed-off-by: Stefan Hajnoczi <stefanha@redhat.com>
---
 docs/devel/index.rst                    |   1 +
 docs/devel/{tracing.txt => tracing.rst} | 134 ++++++++++++++----------
 2 files changed, 81 insertions(+), 54 deletions(-)
 rename docs/devel/{tracing.txt => tracing.rst} (89%)

diff --git a/docs/devel/index.rst b/docs/devel/index.rst
index ea0e1e17ae..98a7016a9b 100644
--- a/docs/devel/index.rst
+++ b/docs/devel/index.rst
@@ -28,6 +28,7 @@ Contents:
    secure-coding-practices
    tcg
    tcg-icount
+   tracing
    multi-thread-tcg
    tcg-plugins
    bitops
diff --git a/docs/devel/tracing.txt b/docs/devel/tracing.rst
similarity index 89%
rename from docs/devel/tracing.txt
rename to docs/devel/tracing.rst
index 313b8ea4e9..f7e589f67c 100644
--- a/docs/devel/tracing.txt
+++ b/docs/devel/tracing.rst
@@ -1,32 +1,38 @@
-= Tracing =
+=======
+Tracing
+=======
 
-== Introduction ==
+Introduction
+============
 
 This document describes the tracing infrastructure in QEMU and how to use it
 for debugging, profiling, and observing execution.
 
-== Quickstart ==
+Quickstart
+==========
 
-1. Build with the 'simple' trace backend:
+1. Build with the 'simple' trace backend::
 
     ./configure --enable-trace-backends=simple
     make
 
-2. Create a file with the events you want to trace:
+2. Create a file with the events you want to trace::
 
-   echo memory_region_ops_read >/tmp/events
+    echo memory_region_ops_read >/tmp/events
 
-3. Run the virtual machine to produce a trace file:
+3. Run the virtual machine to produce a trace file::
 
     qemu --trace events=/tmp/events ... # your normal QEMU invocation
 
-4. Pretty-print the binary trace file:
+4. Pretty-print the binary trace file::
 
     ./scripts/simpletrace.py trace-events-all trace-* # Override * with QEMU <pid>
 
-== Trace events ==
+Trace events
+============
 
-=== Sub-directory setup ===
+Sub-directory setup
+-------------------
 
 Each directory in the source tree can declare a set of static trace events
 in a local "trace-events" file. All directories which contain "trace-events"
@@ -50,7 +56,7 @@ In the sub-directory the following files will be automatically generated
  - trace-ust.h - UST event probe helper declarations
 
 Source files in the sub-directory should #include the local 'trace.h' file,
-without any sub-directory path prefix. eg io/channel-buffer.c would do
+without any sub-directory path prefix. eg io/channel-buffer.c would do::
 
   #include "trace.h"
 
@@ -63,9 +69,10 @@ The top level directory generates trace files with a filename prefix of
 "trace/trace-root" instead of just "trace". This is to avoid ambiguity between
 a trace.h in the current directory, vs the top level directory.
 
-=== Using trace events ===
+Using trace events
+------------------
 
-Trace events are invoked directly from source code like this:
+Trace events are invoked directly from source code like this::
 
     #include "trace.h"  /* needed for trace event prototype */
     
@@ -82,7 +89,8 @@ Trace events are invoked directly from source code like this:
         return ptr;
     }
 
-=== Declaring trace events ===
+Declaring trace events
+----------------------
 
 The "tracetool" script produces the trace.h header file which is included by
 every source file that uses trace events.  Since many source files include
@@ -116,13 +124,14 @@ 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:
+finally a format string for pretty-printing. For example::
 
     qemu_vmalloc(size_t size, void *ptr) "size %zu ptr %p"
     qemu_vfree(void *ptr) "ptr %p"
 
 
-=== Hints for adding new trace events ===
+Hints for adding new trace events
+---------------------------------
 
 1. Trace state changes in the code.  Interesting points in the code usually
    involve a state change like starting, stopping, allocating, freeing.  State
@@ -141,7 +150,8 @@ finally a format string for pretty-printing. For example:
 4. Name trace events after their function.  If there are multiple trace events
    in one function, append a unique distinguisher at the end of the name.
 
-== Generic interface and monitor commands ==
+Generic interface and monitor commands
+======================================
 
 You can programmatically query and control the state of trace events through a
 backend-agnostic interface provided by the header "trace/control.h".
@@ -152,11 +162,11 @@ header "trace/control.h" to see which routines are backend-dependent).
 
 The state of events can also be queried and modified through monitor commands:
 
-* info trace-events
+* ``info trace-events``
   View available trace events and their state.  State 1 means enabled, state 0
   means disabled.
 
-* trace-event NAME on|off
+* ``trace-event NAME on|off``
   Enable/disable a given trace event or a group of events (using wildcards).
 
 The "--trace events=<file>" command line argument can be used to enable the
@@ -170,11 +180,12 @@ to enable an entire family of events but one noisy event needs to be disabled.
 Wildcard matching is supported in both the monitor command "trace-event" and the
 events list file. That means you can enable/disable the events having a common
 prefix in a batch. For example, virtio-blk trace events could be enabled using
-the following monitor command:
+the following monitor command::
 
     trace-event virtio_blk_* on
 
-== Trace backends ==
+Trace backends
+==============
 
 The "tracetool" script automates tedious trace event code generation and also
 keeps the trace event declarations independent of the trace backend.  The trace
@@ -182,7 +193,7 @@ events are not tightly coupled to a specific trace backend, such as LTTng or
 SystemTap.  Support for trace backends can be added by extending the "tracetool"
 script.
 
-The trace backends are chosen at configure time:
+The trace backends are chosen at configure time::
 
     ./configure --enable-trace-backends=simple
 
@@ -194,7 +205,8 @@ If no backends are explicitly selected, configure will default to the
 
 The following subsections describe the supported trace backends.
 
-=== Nop ===
+Nop
+---
 
 The "nop" backend generates empty trace event functions so that the compiler
 can optimize out trace events completely.  This imposes no performance
@@ -203,7 +215,8 @@ penalty.
 Note that regardless of the selected trace backend, events with the "disable"
 property will be generated with the "nop" backend.
 
-=== Log ===
+Log
+---
 
 The "log" backend sends trace events directly to standard error.  This
 effectively turns trace events into debug printfs.
@@ -211,23 +224,26 @@ effectively turns trace events into debug printfs.
 This is the simplest backend and can be used together with existing code that
 uses DPRINTF().
 
-=== Simpletrace ===
+Simpletrace
+-----------
 
 The "simple" backend supports common use cases and comes as part of the QEMU
 source tree.  It may not be as powerful as platform-specific or third-party
 trace backends but it is portable.  This is the recommended trace backend
 unless you have specific needs for more advanced backends.
 
-==== Monitor commands ====
+Monitor commands
+~~~~~~~~~~~~~~~~
 
-* trace-file on|off|flush|set <path>
+* ``trace-file on|off|flush|set <path>``
   Enable/disable/flush the trace file or set the trace file name.
 
-==== Analyzing trace files ====
+Analyzing trace files
+~~~~~~~~~~~~~~~~~~~~~
 
 The "simple" backend produces binary trace files that can be formatted with the
 simpletrace.py script.  The script takes the "trace-events-all" file and the
-binary trace:
+binary trace::
 
     ./scripts/simpletrace.py trace-events-all trace-12345
 
@@ -235,23 +251,25 @@ You must ensure that the same "trace-events-all" file was used to build QEMU,
 otherwise trace event declarations may have changed and output will not be
 consistent.
 
-=== Ftrace ===
+Ftrace
+------
 
 The "ftrace" backend writes trace data to ftrace marker. This effectively
 sends trace events to ftrace ring buffer, and you can compare qemu trace
 data and kernel(especially kvm.ko when using KVM) trace data.
 
-if you use KVM, enable kvm events in ftrace:
+if you use KVM, enable kvm events in ftrace::
 
    # echo 1 > /sys/kernel/debug/tracing/events/kvm/enable
 
-After running qemu by root user, you can get the trace:
+After running qemu by root user, you can get the trace::
 
    # cat /sys/kernel/debug/tracing/trace
 
 Restriction: "ftrace" backend is restricted to Linux only.
 
-=== Syslog ===
+Syslog
+------
 
 The "syslog" backend sends trace events using the POSIX syslog API. The log
 is opened specifying the LOG_DAEMON facility and LOG_PID option (so events
@@ -263,7 +281,8 @@ NOTE: syslog may squash duplicate consecutive trace events and apply rate
 
 Restriction: "syslog" backend is restricted to POSIX compliant OS.
 
-=== LTTng Userspace Tracer ===
+LTTng Userspace Tracer
+----------------------
 
 The "ust" backend uses the LTTng Userspace Tracer library.  There are no
 monitor commands built into QEMU, instead UST utilities should be used to list,
@@ -275,43 +294,44 @@ lttng-sessiond daemon for the current user prior to running any instance of
 QEMU.
 
 While running an instrumented QEMU, LTTng should be able to list all available
-events:
+events::
 
     lttng list -u
 
-Create tracing session:
+Create tracing session::
 
     lttng create mysession
 
-Enable events:
+Enable events::
 
     lttng enable-event qemu:g_malloc -u
 
 Where the events can either be a comma-separated list of events, or "-a" to
-enable all tracepoint events. Start and stop tracing as needed:
+enable all tracepoint events. Start and stop tracing as needed::
 
     lttng start
     lttng stop
 
-View the trace:
+View the trace::
 
     lttng view
 
-Destroy tracing session:
+Destroy tracing session::
 
     lttng destroy
 
-Babeltrace can be used at any later time to view the trace:
+Babeltrace can be used at any later time to view the trace::
 
     babeltrace $HOME/lttng-traces/mysession-<date>-<time>
 
-=== SystemTap ===
+SystemTap
+---------
 
 The "dtrace" backend uses DTrace sdt probes but has only been tested with
 SystemTap.  When SystemTap support is detected a .stp file with wrapper probes
 is generated to make use in scripts more convenient.  This step can also be
 performed manually after a build in order to change the binary name in the .stp
-probes:
+probes::
 
     scripts/tracetool.py --backends=dtrace --format=stap \
                          --binary path/to/qemu-binary \
@@ -325,12 +345,14 @@ To facilitate simple usage of systemtap where there merely needs to be printf
 logging of certain probes, a helper script "qemu-trace-stap" is provided.
 Consult its manual page for guidance on its usage.
 
-== Trace event properties ==
+Trace event properties
+======================
 
 Each event in the "trace-events-all" file can be prefixed with a space-separated
 list of zero or more of the following event properties.
 
-=== "disable" ===
+"disable"
+---------
 
 If a specific trace event is going to be invoked a huge number of times, this
 might have a noticeable performance impact even when the event is
@@ -348,6 +370,8 @@ guard such computations, so they are skipped if the event has been either
 compile-time disabled or run-time disabled. If the event is compile-time
 disabled, this check will have no performance impact.
 
+::
+
     #include "trace.h"  /* needed for trace event prototype */
     
     void *qemu_vmalloc(size_t size)
@@ -367,7 +391,8 @@ disabled, this check will have no performance impact.
         return ptr;
     }
 
-=== "tcg" ===
+"tcg"
+-----
 
 Guest code generated by TCG can be traced by defining an event with the "tcg"
 event property. Internally, this property generates two events:
@@ -384,11 +409,11 @@ mix of native and TCG types, and "trace_<eventname>_tcg" will gracefully forward
 them to the "<eventname>_trans" and "<eventname>_exec" events. Since TCG values
 are not known at translation time, these are ignored by the "<eventname>_trans"
 event. Because of this, the entry in the "trace-events" file needs two printing
-formats (separated by a comma):
+formats (separated by a comma)::
 
     tcg foo(uint8_t a1, TCGv_i32 a2) "a1=%d", "a1=%d a2=%d"
 
-For example:
+For example::
 
     #include "trace-tcg.h"
     
@@ -399,15 +424,16 @@ For example:
         trace_foo_tcg(a1, a2);
     }
 
-This will immediately call:
+This will immediately call::
 
     void trace_foo_trans(uint8_t a1);
 
-and will generate the TCG code to call:
+and will generate the TCG code to call::
 
     void trace_foo(uint8_t a1, uint32_t a2);
 
-=== "vcpu" ===
+"vcpu"
+------
 
 Identifies events that trace vCPU-specific information. It implicitly adds a
 "CPUState*" argument, and extends the tracing print format to show the vCPU
@@ -418,13 +444,13 @@ points to the vCPU when guest code is executed (usually the "cpu_env" variable).
 The "tcg" and "vcpu" properties are currently only honored in the root
 ./trace-events file.
 
-The following example events:
+The following example events::
 
     foo(uint32_t a) "a=%x"
     vcpu bar(uint32_t a) "a=%x"
     tcg vcpu baz(uint32_t a) "a=%x", "a=%x"
 
-Can be used as:
+Can be used as::
 
     #include "trace-tcg.h"
     
@@ -442,7 +468,7 @@ Can be used as:
     }
 
 If the translating vCPU has address 0xc1 and code is later executed by vCPU
-0xc2, this would be an example output:
+0xc2, this would be an example output::
 
     // at guest code translation
     foo a=0xd1
-- 
2.29.2

[PULL 03/11] trace: recommend "log" backend for getting started with tracing

[Stefan Hajnoczi]

The "simple" backend is actually more complicated to use than the "log"
backend. Update the quickstart documentation to feature the "log"
backend instead of the "simple" backend.

Suggested-by: Peter Maydell <peter.maydell@linaro.org>
Signed-off-by: Stefan Hajnoczi <stefanha@redhat.com>
Reviewed-by: Peter Maydell <peter.maydell@linaro.org>
Message-id: 20201216160923.722894-4-stefanha@redhat.com
Signed-off-by: Stefan Hajnoczi <stefanha@redhat.com>
---
 docs/devel/tracing.rst | 35 ++++++++++++++++++-----------------
 1 file changed, 18 insertions(+), 17 deletions(-)

diff --git a/docs/devel/tracing.rst b/docs/devel/tracing.rst
index f7e589f67c..4ebf8e38ea 100644
--- a/docs/devel/tracing.rst
+++ b/docs/devel/tracing.rst
@@ -11,22 +11,22 @@ for debugging, profiling, and observing execution.
 Quickstart
 ==========
 
-1. Build with the 'simple' trace backend::
+Enable tracing of ``memory_region_ops_read`` and ``memory_region_ops_write``
+events::
 
-    ./configure --enable-trace-backends=simple
-    make
+    $ qemu --trace "memory_region_ops_*" ...
+    ...
+    719585@1608130130.441188:memory_region_ops_read cpu 0 mr 0x562fdfbb3820 addr 0x3cc value 0x67 size 1
+    719585@1608130130.441190:memory_region_ops_write cpu 0 mr 0x562fdfbd2f00 addr 0x3d4 value 0x70e size 2
 
-2. Create a file with the events you want to trace::
+This output comes from the "log" trace backend that is enabled by default when
+``./configure --enable-trace-backends=BACKENDS`` was not explicitly specified.
 
-    echo memory_region_ops_read >/tmp/events
+More than one trace event pattern can be specified by providing a file
+instead::
 
-3. Run the virtual machine to produce a trace file::
-
-    qemu --trace events=/tmp/events ... # your normal QEMU invocation
-
-4. Pretty-print the binary trace file::
-
-    ./scripts/simpletrace.py trace-events-all trace-* # Override * with QEMU <pid>
+    $ echo "memory_region_ops_*" >/tmp/events
+    $ qemu --trace events=/tmp/events ...
 
 Trace events
 ============
@@ -195,7 +195,7 @@ script.
 
 The trace backends are chosen at configure time::
 
-    ./configure --enable-trace-backends=simple
+    ./configure --enable-trace-backends=simple,dtrace
 
 For a list of supported trace backends, try ./configure --help or see below.
 If multiple backends are enabled, the trace is sent to them all.
@@ -227,10 +227,11 @@ uses DPRINTF().
 Simpletrace
 -----------
 
-The "simple" backend supports common use cases and comes as part of the QEMU
-source tree.  It may not be as powerful as platform-specific or third-party
-trace backends but it is portable.  This is the recommended trace backend
-unless you have specific needs for more advanced backends.
+The "simple" backend writes binary trace logs to a file from a thread, making
+it lower overhead than the "log" backend. A Python API is available for writing
+offline trace file analysis scripts. It may not be as powerful as
+platform-specific or third-party trace backends but it is portable and has no
+special library dependencies.
 
 Monitor commands
 ~~~~~~~~~~~~~~~~
-- 
2.29.2

[PULL 04/11] tracetool: fix "PRI" macro decoding

[Stefan Hajnoczi]

From: Laurent Vivier <lvivier@redhat.com>

macro is not reset after use, so the format decoded is always the
one of the first "PRI" in the format string.

For instance:

  vhost_vdpa_set_config(void *dev, uint32_t offset, uint32_t size, \
                        uint32_t flags) "dev: %p offset: %"PRIu32" \
                        size: %"PRIu32" flags: 0x%"PRIx32

generates:

  printf("%d@%d vhost_vdpa_set_config dev: %p offset: %u size: %u \
          flags: 0x%u\n", pid(), gettimeofday_ns(), dev, offset, \
          size, flags)

for the "flags" parameter, we can see a "0x%u" rather than a "0x%x"
because the first macro was "PRIu32" (for offset).

In the loop, macro becomes "PRIu32PRIu32PRIx32", and c_macro_to_format()
returns always macro[3] ('u' in this case). This patch resets macro after
the format has been decoded.

Signed-off-by: Laurent Vivier <lvivier@redhat.com>
Reviewed-by: Philippe Mathieu-Daudé <philmd@redhat.com>
Reviewed-by: Daniel P. Berrangé <berrange@redhat.com>
Message-id: 20210105191721.120463-3-lvivier@redhat.com
Signed-off-by: Stefan Hajnoczi <stefanha@redhat.com>
---
 scripts/tracetool/format/log_stap.py | 1 +
 1 file changed, 1 insertion(+)

diff --git a/scripts/tracetool/format/log_stap.py b/scripts/tracetool/format/log_stap.py
index b486beb672..3e1186ae9c 100644
--- a/scripts/tracetool/format/log_stap.py
+++ b/scripts/tracetool/format/log_stap.py
@@ -54,6 +54,7 @@ def c_fmt_to_stap(fmt):
             else:
                 if state == STATE_MACRO:
                     bits.append(c_macro_to_format(macro))
+                    macro = ""
                 state = STATE_LITERAL
         elif fmt[i] == ' ' or fmt[i] == '\t':
             if state == STATE_MACRO:
-- 
2.29.2

[PULL 05/11] tracetool: also strip %l and %ll from systemtap format strings

[Stefan Hajnoczi]

From: Daniel P. Berrangé <berrange@redhat.com>

All variables are 64-bit and so %l / %ll are not required, and the
latter is actually invalid:

  $ sudo stap -e 'probe begin{printf ("BEGIN")}'  -I .
  parse error: invalid or missing conversion specifier
          saw: operator ',' at ./qemu-system-x86_64-log.stp:15118:101
       source:     printf("%d@%d vhost_vdpa_set_log_base dev: %p base: 0x%x size: %llu
refcnt: %d fd: %d log: %p\n", pid(), gettimeofday_ns(), dev, base, size, refcnt, fd, log)

                       ^

Signed-off-by: Daniel P. Berrangé <berrange@redhat.com>
Reviewed-by: Laurent Vivier <lvivier@redhat.com>
Reviewed-by: Philippe Mathieu-Daudé <philmd@redhat.com>
Tested-by: Laurent Vivier <lvivier@redhat.com>
Message-id: 20210106130239.1004729-1-berrange@redhat.com

[Fixed "simiarly" typo found by Laurent Vivier <lvivier@redhat.com>
--Stefan]

Signed-off-by: Stefan Hajnoczi <stefanha@redhat.com>
---
 scripts/tracetool/format/log_stap.py | 7 ++++++-
 1 file changed, 6 insertions(+), 1 deletion(-)

diff --git a/scripts/tracetool/format/log_stap.py b/scripts/tracetool/format/log_stap.py
index 3e1186ae9c..0b6549d534 100644
--- a/scripts/tracetool/format/log_stap.py
+++ b/scripts/tracetool/format/log_stap.py
@@ -78,7 +78,12 @@ def c_fmt_to_stap(fmt):
     elif state == STATE_LITERAL:
         bits.append(literal)
 
-    fmt = re.sub("%(\d*)z(x|u|d)", "%\\1\\2", "".join(bits))
+    # All variables in systemtap are 64-bit in size
+    # The "%l" integer size qualifier is thus redundant
+    # and "%ll" is not valid at all. Similarly the size_t
+    # based "%z" size qualifier is not valid. We just
+    # strip all size qualifiers for sanity.
+    fmt = re.sub("%(\d*)(l+|z)(x|u|d)", "%\\1\\3", "".join(bits))
     return fmt
 
 def generate(events, backend, group):
-- 
2.29.2

[PULL 06/11] trace: add meson custom_target() depend_files for tracetool

[Stefan Hajnoczi]

Re-generate tracetool output when the tracetool source code changes. Use
the same approach as qapi_gen_depends and introduce a tracetool_depends
files list so meson is aware of the dependencies.

Signed-off-by: Stefan Hajnoczi <stefanha@redhat.com>
Reviewed-by: Paolo Bonzini <pbonzini@redhat.com>
Message-id: 20210125110958.214017-1-stefanha@redhat.com
Signed-off-by: Stefan Hajnoczi <stefanha@redhat.com>
---
 meson.build       | 28 +++++++++++++++++++++++++++-
 trace/meson.build | 21 ++++++++++++++-------
 2 files changed, 41 insertions(+), 8 deletions(-)

diff --git a/meson.build b/meson.build
index f00b7754fd..2d8b433ff0 100644
--- a/meson.build
+++ b/meson.build
@@ -1632,6 +1632,31 @@ tracetool = [
   python, files('scripts/tracetool.py'),
    '--backend=' + config_host['TRACE_BACKENDS']
 ]
+tracetool_depends = files(
+  'scripts/tracetool/backend/log.py',
+  'scripts/tracetool/backend/__init__.py',
+  'scripts/tracetool/backend/dtrace.py',
+  'scripts/tracetool/backend/ftrace.py',
+  'scripts/tracetool/backend/simple.py',
+  'scripts/tracetool/backend/syslog.py',
+  'scripts/tracetool/backend/ust.py',
+  'scripts/tracetool/format/tcg_h.py',
+  'scripts/tracetool/format/ust_events_c.py',
+  'scripts/tracetool/format/ust_events_h.py',
+  'scripts/tracetool/format/__init__.py',
+  'scripts/tracetool/format/d.py',
+  'scripts/tracetool/format/tcg_helper_c.py',
+  'scripts/tracetool/format/simpletrace_stap.py',
+  'scripts/tracetool/format/c.py',
+  'scripts/tracetool/format/h.py',
+  'scripts/tracetool/format/tcg_helper_h.py',
+  'scripts/tracetool/format/log_stap.py',
+  'scripts/tracetool/format/stap.py',
+  'scripts/tracetool/format/tcg_helper_wrapper_h.py',
+  'scripts/tracetool/__init__.py',
+  'scripts/tracetool/transform.py',
+  'scripts/tracetool/vcpu.py'
+)
 
 qemu_version_cmd = [find_program('scripts/qemu-version.sh'),
                     meson.current_source_dir(),
@@ -2219,7 +2244,8 @@ foreach target : target_dirs
                         '--target-type=' + target_type,
                         '--probe-prefix=qemu.' + target_type + '.' + target_name,
                         '@INPUT@', '@OUTPUT@'
-                      ])
+                      ],
+                      depend_files: tracetool_depends)
       endforeach
     endif
   endforeach
diff --git a/trace/meson.build b/trace/meson.build
index a0be8f9b0d..08f83a15c3 100644
--- a/trace/meson.build
+++ b/trace/meson.build
@@ -12,17 +12,20 @@ foreach dir : [ '.' ] + trace_events_subdirs
   trace_h = custom_target(fmt.format('trace', 'h'),
                           output: fmt.format('trace', 'h'),
                           input: trace_events_file,
-                          command: [ tracetool, group, '--format=h', '@INPUT@', '@OUTPUT@' ])
+                          command: [ tracetool, group, '--format=h', '@INPUT@', '@OUTPUT@' ],
+                          depend_files: tracetool_depends)
   genh += trace_h
   trace_c = custom_target(fmt.format('trace', 'c'),
                           output: fmt.format('trace', 'c'),
                           input: trace_events_file,
-                          command: [ tracetool, group, '--format=c', '@INPUT@', '@OUTPUT@' ])
+                          command: [ tracetool, group, '--format=c', '@INPUT@', '@OUTPUT@' ],
+                          depend_files: tracetool_depends)
   if 'CONFIG_TRACE_UST' in config_host
     trace_ust_h = custom_target(fmt.format('trace-ust', 'h'),
                                 output: fmt.format('trace-ust', 'h'),
                                 input: trace_events_file,
-                                command: [ tracetool, group, '--format=ust-events-h', '@INPUT@', '@OUTPUT@' ])
+                                command: [ tracetool, group, '--format=ust-events-h', '@INPUT@', '@OUTPUT@' ],
+                                depend_files: tracetool_depends)
     trace_ss.add(trace_ust_h, lttng, urcubp)
     genh += trace_ust_h
   endif
@@ -31,7 +34,8 @@ foreach dir : [ '.' ] + trace_events_subdirs
     trace_dtrace = custom_target(fmt.format('trace-dtrace', 'dtrace'),
                                  output: fmt.format('trace-dtrace', 'dtrace'),
                                  input: trace_events_file,
-                                 command: [ tracetool, group, '--format=d', '@INPUT@', '@OUTPUT@' ])
+                                 command: [ tracetool, group, '--format=d', '@INPUT@', '@OUTPUT@' ],
+                                 depend_files: tracetool_depends)
     trace_dtrace_h = custom_target(fmt.format('trace-dtrace', 'h'),
                                    output: fmt.format('trace-dtrace', 'h'),
                                    input: trace_dtrace,
@@ -66,7 +70,8 @@ foreach d : [
   gen = custom_target(d[0],
                 output: d[0],
                 input: meson.source_root() / 'trace-events',
-                command: [ tracetool, '--group=root', '--format=@0@'.format(d[1]), '@INPUT@', '@OUTPUT@' ])
+                command: [ tracetool, '--group=root', '--format=@0@'.format(d[1]), '@INPUT@', '@OUTPUT@' ],
+                depend_files: tracetool_depends)
   specific_ss.add(when: 'CONFIG_TCG', if_true: gen)
 endforeach
 
@@ -74,11 +79,13 @@ if 'CONFIG_TRACE_UST' in config_host
   trace_ust_all_h = custom_target('trace-ust-all.h',
                                   output: 'trace-ust-all.h',
                                   input: trace_events_files,
-                                  command: [ tracetool, '--group=all', '--format=ust-events-h', '@INPUT@', '@OUTPUT@' ])
+                                  command: [ tracetool, '--group=all', '--format=ust-events-h', '@INPUT@', '@OUTPUT@' ],
+                                  depend_files: tracetool_depends)
   trace_ust_all_c = custom_target('trace-ust-all.c',
                                   output: 'trace-ust-all.c',
                                   input: trace_events_files,
-                                  command: [ tracetool, '--group=all', '--format=ust-events-c', '@INPUT@', '@OUTPUT@' ])
+                                  command: [ tracetool, '--group=all', '--format=ust-events-c', '@INPUT@', '@OUTPUT@' ],
+                                  depend_files: tracetool_depends)
   trace_ss.add(trace_ust_all_h, trace_ust_all_c)
   genh += trace_ust_all_h
 endif
-- 
2.29.2

[PULL 07/11] error: rename error_with_timestamp to message_with_timestamp

[Stefan Hajnoczi]

The -msg timestamp=on|off option controls whether a timestamp is printed
with error_report() messages. The "-msg" name suggests that this option
has a wider effect than just error_report(). The next patch extends it
to the 'log' trace backend, so rename the variable from
error_with_timestamp to message_with_timestamp.

Signed-off-by: Stefan Hajnoczi <stefanha@redhat.com>
Tested-by: Philippe Mathieu-Daudé <philmd@redhat.com>
Tested-by: BALATON Zoltan <balaton@eik.bme.hu>
Reviewed-by: Philippe Mathieu-Daudé <philmd@redhat.com>
Message-id: 20210125113507.224287-2-stefanha@redhat.com
Signed-off-by: Stefan Hajnoczi <stefanha@redhat.com>
---
 include/qemu/error-report.h | 2 +-
 softmmu/vl.c                | 2 +-
 util/qemu-error.c           | 4 ++--
 3 files changed, 4 insertions(+), 4 deletions(-)

diff --git a/include/qemu/error-report.h b/include/qemu/error-report.h
index a5ad95ff1b..9d197daca3 100644
--- a/include/qemu/error-report.h
+++ b/include/qemu/error-report.h
@@ -74,7 +74,7 @@ void error_init(const char *argv0);
 
 const char *error_get_progname(void);
 
-extern bool error_with_timestamp;
+extern bool message_with_timestamp;
 extern bool error_with_guestname;
 extern const char *error_guest_name;
 
diff --git a/softmmu/vl.c b/softmmu/vl.c
index a8876b8965..bd55468669 100644
--- a/softmmu/vl.c
+++ b/softmmu/vl.c
@@ -737,7 +737,7 @@ static void realtime_init(void)
 
 static void configure_msg(QemuOpts *opts)
 {
-    error_with_timestamp = qemu_opt_get_bool(opts, "timestamp", false);
+    message_with_timestamp = qemu_opt_get_bool(opts, "timestamp", false);
     error_with_guestname = qemu_opt_get_bool(opts, "guest-name", false);
 }
 
diff --git a/util/qemu-error.c b/util/qemu-error.c
index aa30f03564..52a9e013c4 100644
--- a/util/qemu-error.c
+++ b/util/qemu-error.c
@@ -25,7 +25,7 @@ typedef enum {
 } report_type;
 
 /* Prepend timestamp to messages */
-bool error_with_timestamp;
+bool message_with_timestamp;
 bool error_with_guestname;
 const char *error_guest_name;
 
@@ -208,7 +208,7 @@ static void vreport(report_type type, const char *fmt, va_list ap)
     GTimeVal tv;
     gchar *timestr;
 
-    if (error_with_timestamp && !monitor_cur()) {
+    if (message_with_timestamp && !monitor_cur()) {
         g_get_current_time(&tv);
         timestr = g_time_val_to_iso8601(&tv);
         error_printf("%s ", timestr);
-- 
2.29.2

[PULL 08/11] trace: make the 'log' backend timestamp configurable

[Stefan Hajnoczi]

Timestamps in tracing output can be distracting. Make it possible to
control tid/timestamp printing with -msg timestamp=on|off. The default
is no tid/timestamps. Previously they were always printed.

Suggested-by: BALATON Zoltan <balaton@eik.bme.hu>
Signed-off-by: Stefan Hajnoczi <stefanha@redhat.com>
Tested-by: Philippe Mathieu-Daudé <philmd@redhat.com>
Tested-by: BALATON Zoltan <balaton@eik.bme.hu>
Reviewed-by: Philippe Mathieu-Daudé <philmd@redhat.com>
Message-id: 20210125113507.224287-3-stefanha@redhat.com
Signed-off-by: Stefan Hajnoczi <stefanha@redhat.com>
---
 docs/devel/tracing.rst           |  3 +++
 scripts/tracetool/backend/log.py | 19 +++++++++++++------
 2 files changed, 16 insertions(+), 6 deletions(-)

diff --git a/docs/devel/tracing.rst b/docs/devel/tracing.rst
index 4ebf8e38ea..af395e957d 100644
--- a/docs/devel/tracing.rst
+++ b/docs/devel/tracing.rst
@@ -224,6 +224,9 @@ effectively turns trace events into debug printfs.
 This is the simplest backend and can be used together with existing code that
 uses DPRINTF().
 
+The -msg timestamp=on|off command-line option controls whether or not to print
+the tid/timestamp prefix for each trace event.
+
 Simpletrace
 -----------
 
diff --git a/scripts/tracetool/backend/log.py b/scripts/tracetool/backend/log.py
index bc43dbb4f4..17ba1cd90e 100644
--- a/scripts/tracetool/backend/log.py
+++ b/scripts/tracetool/backend/log.py
@@ -20,6 +20,7 @@ PUBLIC = True
 
 def generate_h_begin(events, group):
     out('#include "qemu/log-for-trace.h"',
+        '#include "qemu/error-report.h"',
         '')
 
 
@@ -35,14 +36,20 @@ def generate_h(event, group):
         cond = "trace_event_get_state(%s)" % ("TRACE_" + event.name.upper())
 
     out('    if (%(cond)s && qemu_loglevel_mask(LOG_TRACE)) {',
-        '        struct timeval _now;',
-        '        gettimeofday(&_now, NULL);',
+        '        if (message_with_timestamp) {',
+        '            struct timeval _now;',
+        '            gettimeofday(&_now, NULL);',
         '#line %(event_lineno)d "%(event_filename)s"',
-        '        qemu_log("%%d@%%zu.%%06zu:%(name)s " %(fmt)s "\\n",',
-        '                 qemu_get_thread_id(),',
-        '                 (size_t)_now.tv_sec, (size_t)_now.tv_usec',
-        '                 %(argnames)s);',
+        '            qemu_log("%%d@%%zu.%%06zu:%(name)s " %(fmt)s "\\n",',
+        '                     qemu_get_thread_id(),',
+        '                     (size_t)_now.tv_sec, (size_t)_now.tv_usec',
+        '                     %(argnames)s);',
         '#line %(out_next_lineno)d "%(out_filename)s"',
+        '        } else {',
+        '#line %(event_lineno)d "%(event_filename)s"',
+        '            qemu_log("%(name)s " %(fmt)s "\\n"%(argnames)s);',
+        '#line %(out_next_lineno)d "%(out_filename)s"',
+        '        }',
         '    }',
         cond=cond,
         event_lineno=event.lineno,
-- 
2.29.2

[PULL 09/11] simpletrace: build() missing 2 required positional arguments

[Stefan Hajnoczi]

From: Volker Rümelin <vr_qemu@t-online.de>

Commit 4e66c9ef64 "tracetool: add input filename and line number to
Event" forgot to add a line number and a filename argument at one
build method call site.

Traceback (most recent call last):
  File "./scripts/simpletrace.py", line 261, in <module>
    run(Formatter())
  File "./scripts/simpletrace.py", line 236, in run
    process(events, sys.argv[2], analyzer, read_header=read_header)
  File "./scripts/simpletrace.py", line 177, in process
    dropped_event =
      Event.build("Dropped_Event(uint64_t num_events_dropped)")
TypeError: build() missing 2 required positional arguments:
  'lineno' and 'filename'

Add the missing arguments.

Signed-off-by: Volker Rümelin <vr_qemu@t-online.de>
Reviewed-by: Philippe Mathieu-Daudé <f4bug@amsat.org>
Message-id: 20210131173415.3392-1-vr_qemu@t-online.de
Signed-off-by: Stefan Hajnoczi <stefanha@redhat.com>
---
 scripts/simpletrace.py | 4 +++-
 1 file changed, 3 insertions(+), 1 deletion(-)

diff --git a/scripts/simpletrace.py b/scripts/simpletrace.py
index 20f0026066..d61fb0bd87 100755
--- a/scripts/simpletrace.py
+++ b/scripts/simpletrace.py
@@ -174,7 +174,9 @@ def process(events, log, analyzer, read_header=True):
     if read_header:
         read_trace_header(log)
 
-    dropped_event = Event.build("Dropped_Event(uint64_t num_events_dropped)")
+    frameinfo = inspect.getframeinfo(inspect.currentframe())
+    dropped_event = Event.build("Dropped_Event(uint64_t num_events_dropped)",
+                                frameinfo.lineno + 1, frameinfo.filename)
     edict = {"dropped": dropped_event}
     idtoname = {dropped_event_id: "dropped"}
 
-- 
2.29.2

[PULL 10/11] trace: document how to specify multiple --trace patterns

[Stefan Hajnoczi]

It is possible to repeat the --trace option to specify multiple
patterns. This may be preferrable to users who do not want to create a
file with a list of patterns.

Suggested-by: BALATON Zoltan <balaton@eik.bme.hu>
Signed-off-by: Stefan Hajnoczi <stefanha@redhat.com>
Reviewed-by: Philippe Mathieu-Daudé <philmd@redhat.com>
Message-id: 20210112165859.225534-2-stefanha@redhat.com
Signed-off-by: Stefan Hajnoczi <stefanha@redhat.com>
---
 docs/devel/tracing.rst | 9 +++++++--
 1 file changed, 7 insertions(+), 2 deletions(-)

diff --git a/docs/devel/tracing.rst b/docs/devel/tracing.rst
index af395e957d..e8f9b82c5e 100644
--- a/docs/devel/tracing.rst
+++ b/docs/devel/tracing.rst
@@ -22,10 +22,15 @@ events::
 This output comes from the "log" trace backend that is enabled by default when
 ``./configure --enable-trace-backends=BACKENDS`` was not explicitly specified.
 
-More than one trace event pattern can be specified by providing a file
-instead::
+Multiple patterns can be specified by repeating the ``--trace`` option::
+
+    $ qemu --trace "kvm_*" --trace "virtio_*" ...
+
+When patterns are used frequently it is more convenient to store them in a
+file to avoid long command-line options::
 
     $ echo "memory_region_ops_*" >/tmp/events
+    $ echo "kvm_*" >>/tmp/events
     $ qemu --trace events=/tmp/events ...
 
 Trace events
-- 
2.29.2

[PULL 11/11] trace: update docs with meson build information

[Stefan Hajnoczi]

The documentation still refers to the makefile and the old sub-directory
layout. Meson works differently: tracetool output is placed into the
builddir with mangled filenames like <builddir>/trace/trace-accel_kvm.h
for the accel/kvm/ trace.h definition.

This meson setup also requires a manually-created accel/kvm/trace.h file
that #includes the <builddir>/trace/trace-accel_kvm.h file. Document
this!

Reported-by: Peter Maydell <peter.maydell@linaro.org>
Signed-off-by: Stefan Hajnoczi <stefanha@redhat.com>
Message-id: 20210112165859.225534-3-stefanha@redhat.com
Signed-off-by: Stefan Hajnoczi <stefanha@redhat.com>
---
 docs/devel/tracing.rst | 57 +++++++++++++++++++++++++-----------------
 1 file changed, 34 insertions(+), 23 deletions(-)

diff --git a/docs/devel/tracing.rst b/docs/devel/tracing.rst
index e8f9b82c5e..ba83954899 100644
--- a/docs/devel/tracing.rst
+++ b/docs/devel/tracing.rst
@@ -39,40 +39,51 @@ Trace events
 Sub-directory setup
 -------------------
 
-Each directory in the source tree can declare a set of static trace events
-in a local "trace-events" file. All directories which contain "trace-events"
-files must be listed in the "trace-events-subdirs" make variable in the top
-level Makefile.objs. During build, the "trace-events" file in each listed
-subdirectory will be processed by the "tracetool" script to generate code for
-the trace events.
+Each directory in the source tree can declare a set of trace events in a local
+"trace-events" file. All directories which contain "trace-events" files must be
+listed in the "trace_events_subdirs" variable in the top level meson.build
+file. During build, the "trace-events" file in each listed subdirectory will be
+processed by the "tracetool" script to generate code for the trace events.
 
 The individual "trace-events" files are merged into a "trace-events-all" file,
 which is also installed into "/usr/share/qemu" with the name "trace-events".
 This merged file is to be used by the "simpletrace.py" script to later analyse
 traces in the simpletrace data format.
 
-In the sub-directory the following files will be automatically generated
+The following files are automatically generated in <builddir>/trace/ during the
+build:
 
- - trace.c - the trace event state declarations
- - trace.h - the trace event enums and probe functions
- - trace-dtrace.h - DTrace event probe specification
- - trace-dtrace.dtrace - DTrace event probe helper declaration
- - trace-dtrace.o - binary DTrace provider (generated by dtrace)
- - trace-ust.h - UST event probe helper declarations
+ - trace-<subdir>.c - the trace event state declarations
+ - trace-<subdir>.h - the trace event enums and probe functions
+ - trace-dtrace-<subdir>.h - DTrace event probe specification
+ - trace-dtrace-<subdir>.dtrace - DTrace event probe helper declaration
+ - trace-dtrace-<subdir>.o - binary DTrace provider (generated by dtrace)
+ - trace-ust-<subdir>.h - UST event probe helper declarations
 
-Source files in the sub-directory should #include the local 'trace.h' file,
-without any sub-directory path prefix. eg io/channel-buffer.c would do::
+Here <subdir> is the sub-directory path with '/' replaced by '_'. For example,
+"accel/kvm" becomes "accel_kvm" and the final filename for "trace-<subdir>.c"
+becomes "trace-accel_kvm.c".
+
+Source files in the source tree do not directly include generated files in
+"<builddir>/trace/". Instead they #include the local "trace.h" file, without
+any sub-directory path prefix. eg io/channel-buffer.c would do::
 
   #include "trace.h"
 
-To access the 'io/trace.h' file. While it is possible to include a trace.h
-file from outside a source file's own sub-directory, this is discouraged in
-general. It is strongly preferred that all events be declared directly in
-the sub-directory that uses them. The only exception is where there are some
-shared trace events defined in the top level directory trace-events file.
-The top level directory generates trace files with a filename prefix of
-"trace/trace-root" instead of just "trace". This is to avoid ambiguity between
-a trace.h in the current directory, vs the top level directory.
+The "io/trace.h" file must be created manually with an #include of the
+corresponding "trace/trace-<subdir>.h" file that will be generated in the
+builddir::
+
+  $ echo '#include "trace/trace-io.h"' >io/trace.h
+
+While it is possible to include a trace.h file from outside a source file's own
+sub-directory, this is discouraged in general. It is strongly preferred that
+all events be declared directly in the sub-directory that uses them. The only
+exception is where there are some shared trace events defined in the top level
+directory trace-events file.  The top level directory generates trace files
+with a filename prefix of "trace/trace-root" instead of just "trace". This is
+to avoid ambiguity between a trace.h in the current directory, vs the top level
+directory.
 
 Using trace events
 ------------------
-- 
2.29.2

Re: [PULL 10/11] trace: document how to specify multiple --trace patterns

[BALATON Zoltan]

[-- Attachment #1: Type: text/plain, Size: 1622 bytes --]

On Mon, 1 Feb 2021, Stefan Hajnoczi wrote:
> It is possible to repeat the --trace option to specify multiple
> patterns. This may be preferrable to users who do not want to create a
> file with a list of patterns.
>
> Suggested-by: BALATON Zoltan <balaton@eik.bme.hu>
> Signed-off-by: Stefan Hajnoczi <stefanha@redhat.com>
> Reviewed-by: Philippe Mathieu-Daudé <philmd@redhat.com>
> Message-id: 20210112165859.225534-2-stefanha@redhat.com
> Signed-off-by: Stefan Hajnoczi <stefanha@redhat.com>
> ---
> docs/devel/tracing.rst | 9 +++++++--
> 1 file changed, 7 insertions(+), 2 deletions(-)
>
> diff --git a/docs/devel/tracing.rst b/docs/devel/tracing.rst
> index af395e957d..e8f9b82c5e 100644
> --- a/docs/devel/tracing.rst
> +++ b/docs/devel/tracing.rst
> @@ -22,10 +22,15 @@ events::
> This output comes from the "log" trace backend that is enabled by default when
> ``./configure --enable-trace-backends=BACKENDS`` was not explicitly specified.
> 
> -More than one trace event pattern can be specified by providing a file
> -instead::
> +Multiple patterns can be specified by repeating the ``--trace`` option::
> +
> +    $ qemu --trace "kvm_*" --trace "virtio_*" ...

Does that actually work? I've always used -trace enable="pattern1" -trace 
enable="pattern2" Not sure if omitting enable= is the same.

Regards,
BALATON Zoltan

> +
> +When patterns are used frequently it is more convenient to store them in a
> +file to avoid long command-line options::
>
>     $ echo "memory_region_ops_*" >/tmp/events
> +    $ echo "kvm_*" >>/tmp/events
>     $ qemu --trace events=/tmp/events ...
> 
> Trace events
> -- 
> 2.29.2

Re: [PULL 10/11] trace: document how to specify multiple --trace patterns

[Kevin Wolf]

Am 01.02.2021 um 17:05 hat BALATON Zoltan geschrieben:
> On Mon, 1 Feb 2021, Stefan Hajnoczi wrote:
> > It is possible to repeat the --trace option to specify multiple
> > patterns. This may be preferrable to users who do not want to create a
> > file with a list of patterns.
> > 
> > Suggested-by: BALATON Zoltan <balaton@eik.bme.hu>
> > Signed-off-by: Stefan Hajnoczi <stefanha@redhat.com>
> > Reviewed-by: Philippe Mathieu-Daudé <philmd@redhat.com>
> > Message-id: 20210112165859.225534-2-stefanha@redhat.com
> > Signed-off-by: Stefan Hajnoczi <stefanha@redhat.com>
> > ---
> > docs/devel/tracing.rst | 9 +++++++--
> > 1 file changed, 7 insertions(+), 2 deletions(-)
> > 
> > diff --git a/docs/devel/tracing.rst b/docs/devel/tracing.rst
> > index af395e957d..e8f9b82c5e 100644
> > --- a/docs/devel/tracing.rst
> > +++ b/docs/devel/tracing.rst
> > @@ -22,10 +22,15 @@ events::
> > This output comes from the "log" trace backend that is enabled by default when
> > ``./configure --enable-trace-backends=BACKENDS`` was not explicitly specified.
> > 
> > -More than one trace event pattern can be specified by providing a file
> > -instead::
> > +Multiple patterns can be specified by repeating the ``--trace`` option::
> > +
> > +    $ qemu --trace "kvm_*" --trace "virtio_*" ...
> 
> Does that actually work? I've always used -trace enable="pattern1" -trace
> enable="pattern2" Not sure if omitting enable= is the same.

qemu_trace_opts has .implied_opt_name = "enable", so without having
tested it, I assume this works.

Kevin

Re: [PULL 10/11] trace: document how to specify multiple --trace patterns

[Philippe Mathieu-Daudé]

On 2/1/21 5:13 PM, Kevin Wolf wrote:
> Am 01.02.2021 um 17:05 hat BALATON Zoltan geschrieben:
>> On Mon, 1 Feb 2021, Stefan Hajnoczi wrote:
>>> It is possible to repeat the --trace option to specify multiple
>>> patterns. This may be preferrable to users who do not want to create a
>>> file with a list of patterns.
>>>
>>> Suggested-by: BALATON Zoltan <balaton@eik.bme.hu>
>>> Signed-off-by: Stefan Hajnoczi <stefanha@redhat.com>
>>> Reviewed-by: Philippe Mathieu-Daudé <philmd@redhat.com>
>>> Message-id: 20210112165859.225534-2-stefanha@redhat.com
>>> Signed-off-by: Stefan Hajnoczi <stefanha@redhat.com>
>>> ---
>>> docs/devel/tracing.rst | 9 +++++++--
>>> 1 file changed, 7 insertions(+), 2 deletions(-)
>>>
>>> diff --git a/docs/devel/tracing.rst b/docs/devel/tracing.rst
>>> index af395e957d..e8f9b82c5e 100644
>>> --- a/docs/devel/tracing.rst
>>> +++ b/docs/devel/tracing.rst
>>> @@ -22,10 +22,15 @@ events::
>>> This output comes from the "log" trace backend that is enabled by default when
>>> ``./configure --enable-trace-backends=BACKENDS`` was not explicitly specified.
>>>
>>> -More than one trace event pattern can be specified by providing a file
>>> -instead::
>>> +Multiple patterns can be specified by repeating the ``--trace`` option::
>>> +
>>> +    $ qemu --trace "kvm_*" --trace "virtio_*" ...
>>
>> Does that actually work? I've always used -trace enable="pattern1" -trace
>> enable="pattern2" Not sure if omitting enable= is the same.
> 
> qemu_trace_opts has .implied_opt_name = "enable", so without having
> tested it, I assume this works.

I use -trace \*pci\* -trace memory\*, and Kevin said -trace and --trace
are the same.

Re: [PULL 10/11] trace: document how to specify multiple --trace patterns

[BALATON Zoltan]

[-- Attachment #1: Type: text/plain, Size: 2096 bytes --]

On Mon, 1 Feb 2021, Kevin Wolf wrote:
> Am 01.02.2021 um 17:05 hat BALATON Zoltan geschrieben:
>> On Mon, 1 Feb 2021, Stefan Hajnoczi wrote:
>>> It is possible to repeat the --trace option to specify multiple
>>> patterns. This may be preferrable to users who do not want to create a
>>> file with a list of patterns.
>>>
>>> Suggested-by: BALATON Zoltan <balaton@eik.bme.hu>
>>> Signed-off-by: Stefan Hajnoczi <stefanha@redhat.com>
>>> Reviewed-by: Philippe Mathieu-Daudé <philmd@redhat.com>
>>> Message-id: 20210112165859.225534-2-stefanha@redhat.com
>>> Signed-off-by: Stefan Hajnoczi <stefanha@redhat.com>
>>> ---
>>> docs/devel/tracing.rst | 9 +++++++--
>>> 1 file changed, 7 insertions(+), 2 deletions(-)
>>>
>>> diff --git a/docs/devel/tracing.rst b/docs/devel/tracing.rst
>>> index af395e957d..e8f9b82c5e 100644
>>> --- a/docs/devel/tracing.rst
>>> +++ b/docs/devel/tracing.rst
>>> @@ -22,10 +22,15 @@ events::
>>> This output comes from the "log" trace backend that is enabled by default when
>>> ``./configure --enable-trace-backends=BACKENDS`` was not explicitly specified.
>>>
>>> -More than one trace event pattern can be specified by providing a file
>>> -instead::
>>> +Multiple patterns can be specified by repeating the ``--trace`` option::
>>> +
>>> +    $ qemu --trace "kvm_*" --trace "virtio_*" ...
>>
>> Does that actually work? I've always used -trace enable="pattern1" -trace
>> enable="pattern2" Not sure if omitting enable= is the same.
>
> qemu_trace_opts has .implied_opt_name = "enable", so without having
> tested it, I assume this works.

How does this option parsing work? Would then multiple patterns separated 
by comma as in -trace pattern1,pattern2 also work? (Although quoting * in 
that may be a challenge don't know if it should be "a*,b*" "a*","b*" or 
a\*,b\* or any of these would be OK.) I've just found one way by repeating 
-trace options that worked and then used that without ever trying to 
explore other ways but if we're about to document it maybe somebody who 
actually knows how it works could tell what is the best way.

Regards,
BALATON Zoltan

Re: [PULL 10/11] trace: document how to specify multiple --trace patterns

[Kevin Wolf]

Am 01.02.2021 um 17:29 hat BALATON Zoltan geschrieben:
> On Mon, 1 Feb 2021, Kevin Wolf wrote:
> > Am 01.02.2021 um 17:05 hat BALATON Zoltan geschrieben:
> > > On Mon, 1 Feb 2021, Stefan Hajnoczi wrote:
> > > > It is possible to repeat the --trace option to specify multiple
> > > > patterns. This may be preferrable to users who do not want to create a
> > > > file with a list of patterns.
> > > > 
> > > > Suggested-by: BALATON Zoltan <balaton@eik.bme.hu>
> > > > Signed-off-by: Stefan Hajnoczi <stefanha@redhat.com>
> > > > Reviewed-by: Philippe Mathieu-Daudé <philmd@redhat.com>
> > > > Message-id: 20210112165859.225534-2-stefanha@redhat.com
> > > > Signed-off-by: Stefan Hajnoczi <stefanha@redhat.com>
> > > > ---
> > > > docs/devel/tracing.rst | 9 +++++++--
> > > > 1 file changed, 7 insertions(+), 2 deletions(-)
> > > > 
> > > > diff --git a/docs/devel/tracing.rst b/docs/devel/tracing.rst
> > > > index af395e957d..e8f9b82c5e 100644
> > > > --- a/docs/devel/tracing.rst
> > > > +++ b/docs/devel/tracing.rst
> > > > @@ -22,10 +22,15 @@ events::
> > > > This output comes from the "log" trace backend that is enabled by default when
> > > > ``./configure --enable-trace-backends=BACKENDS`` was not explicitly specified.
> > > > 
> > > > -More than one trace event pattern can be specified by providing a file
> > > > -instead::
> > > > +Multiple patterns can be specified by repeating the ``--trace`` option::
> > > > +
> > > > +    $ qemu --trace "kvm_*" --trace "virtio_*" ...
> > > 
> > > Does that actually work? I've always used -trace enable="pattern1" -trace
> > > enable="pattern2" Not sure if omitting enable= is the same.
> > 
> > qemu_trace_opts has .implied_opt_name = "enable", so without having
> > tested it, I assume this works.
> 
> How does this option parsing work? Would then multiple patterns separated by
> comma as in -trace pattern1,pattern2 also work?

This would be interpreted as an implied "enable" option with a value of
"pattern1,pattern2". I don't think anything splits that string at the
comma, so it would look for a trace event matching that string.

Kevin

Re: [PULL 10/11] trace: document how to specify multiple --trace patterns

[Paolo Bonzini]

On 01/02/21 17:54, Kevin Wolf wrote:
>> How does this option parsing work? Would then multiple patterns separated by
>> comma as in -trace pattern1,pattern2 also work?
> This would be interpreted as an implied "enable" option with a value of
> "pattern1,pattern2". I don't think anything splits that string at the
> comma, so it would look for a trace event matching that string.

Even worse, it would be interpreted as "-trace 
enable=pattern1,pattern2=on" (and raise a warning since recently).

Paolo

Re: [PULL 10/11] trace: document how to specify multiple --trace patterns

[BALATON Zoltan]

On Mon, 1 Feb 2021, Paolo Bonzini wrote:
> On 01/02/21 17:54, Kevin Wolf wrote:
>>> How does this option parsing work? Would then multiple patterns separated 
>>> by
>>> comma as in -trace pattern1,pattern2 also work?
>> This would be interpreted as an implied "enable" option with a value of
>> "pattern1,pattern2". I don't think anything splits that string at the
>> comma, so it would look for a trace event matching that string.
>
> Even worse, it would be interpreted as "-trace enable=pattern1,pattern2=on" 
> (and raise a warning since recently).

Not very intuitive... What would -trace enable=pattern1,enable=pattern2 do 
then?

Re: [PULL 10/11] trace: document how to specify multiple --trace patterns

[Daniel P. Berrangé]

On Mon, Feb 01, 2021 at 06:25:33PM +0100, Paolo Bonzini wrote:
> On 01/02/21 17:54, Kevin Wolf wrote:
> > > How does this option parsing work? Would then multiple patterns separated by
> > > comma as in -trace pattern1,pattern2 also work?
> > This would be interpreted as an implied "enable" option with a value of
> > "pattern1,pattern2". I don't think anything splits that string at the
> > comma, so it would look for a trace event matching that string.
> 
> Even worse, it would be interpreted as "-trace enable=pattern1,pattern2=on"
> (and raise a warning since recently).

Maybe we're trying to solve the problem at the wrong level.

The pattern is currently matched using the GLib glob matching APIs.

If we switched to use the GLib regex matching APIs, then we don't need
to repeat the args at all. We could just use regex syntax:

  -trace 'enable=(kvm|virtio)*'

It is a little tedious to have to quote the args to avoid shell
expansion, but as a tradeoff you get much stronger ability todo
complex matches to filter out irrelevant cruft.

If we want to maintain back compat for glob syntax, then we should
support both in parallel and accept a different parameter name
for the regex style.


Regards,
Daniel
-- 
|: https://berrange.com      -o-    https://www.flickr.com/photos/dberrange :|
|: https://libvirt.org         -o-            https://fstop138.berrange.com :|
|: https://entangle-photo.org    -o-    https://www.instagram.com/dberrange :|

Re: [PULL 10/11] trace: document how to specify multiple --trace patterns

[BALATON Zoltan]

[-- Attachment #1: Type: text/plain, Size: 1952 bytes --]

On Mon, 1 Feb 2021, Daniel P. Berrangé wrote:
> On Mon, Feb 01, 2021 at 06:25:33PM +0100, Paolo Bonzini wrote:
>> On 01/02/21 17:54, Kevin Wolf wrote:
>>>> How does this option parsing work? Would then multiple patterns separated by
>>>> comma as in -trace pattern1,pattern2 also work?
>>> This would be interpreted as an implied "enable" option with a value of
>>> "pattern1,pattern2". I don't think anything splits that string at the
>>> comma, so it would look for a trace event matching that string.
>>
>> Even worse, it would be interpreted as "-trace enable=pattern1,pattern2=on"
>> (and raise a warning since recently).
>
> Maybe we're trying to solve the problem at the wrong level.

There's no problem to solve, just trying to understand better what are the 
valid options. It's already possible to enable multiple patterns with 
either events=file or repeating -trace options (with or without enable=) 
so that's already sufficient, I was just curious what other options are 
there and if there's a simpler way that we could document. If not, using 
the current ways that are now documented is OK I think.

> The pattern is currently matched using the GLib glob matching APIs.
>
> If we switched to use the GLib regex matching APIs, then we don't need
> to repeat the args at all. We could just use regex syntax:
>
>  -trace 'enable=(kvm|virtio)*'
>
> It is a little tedious to have to quote the args to avoid shell
> expansion, but as a tradeoff you get much stronger ability todo
> complex matches to filter out irrelevant cruft.

I guess we have enough expressiveness with current pattern matching and 
globs are more easily understood by mere users so regex may not be needed 
here.

> If we want to maintain back compat for glob syntax, then we should
> support both in parallel and accept a different parameter name
> for the regex style.

That would be (even more) confusing so better to just stay with globs.

Regards,
BALATON Zoltan

Re: [PULL 00/11] Tracing patches

[Peter Maydell]

On Mon, 1 Feb 2021 at 15:48, Stefan Hajnoczi <stefanha@redhat.com> wrote:
>
> The following changes since commit 74208cd252c5da9d867270a178799abd802b9338:
>
>   Merge remote-tracking branch 'remotes/berrange-gitlab/tags/misc-fixes-pull-request' into staging (2021-01-29 19:51:25 +0000)
>
> are available in the Git repository at:
>
>   https://gitlab.com/stefanha/qemu.git tags/tracing-pull-request
>
> for you to fetch changes up to 0dfb3ca73c54fc105ab78e37e31ab05bed1360aa:
>
>   trace: update docs with meson build information (2021-02-01 11:23:04 +0000)
>
> ----------------------------------------------------------------
> Pull request
>
> ----------------------------------------------------------------


Applied, thanks.

Please update the changelog at https://wiki.qemu.org/ChangeLog/6.0
for any user-visible changes.

-- PMM

Re: [PULL 10/11] trace: document how to specify multiple --trace patterns

[Markus Armbruster]

BALATON Zoltan <balaton@eik.bme.hu> writes:

> On Mon, 1 Feb 2021, Paolo Bonzini wrote:
>> On 01/02/21 17:54, Kevin Wolf wrote:
>>>> How does this option parsing work? Would then multiple patterns
>>>> separated by
>>>> comma as in -trace pattern1,pattern2 also work?
>>> This would be interpreted as an implied "enable" option with a value of
>>> "pattern1,pattern2". I don't think anything splits that string at the
>>> comma, so it would look for a trace event matching that string.
>>
>> Even worse, it would be interpreted as "-trace
>> enable=pattern1,pattern2=on" (and raise a warning since recently).
>
> Not very intuitive... What would -trace
> enable=pattern1,enable=pattern2 do then?

Welcome to the QemuOpts swamp.  Bring your own mosquito net.

The argument of -trace is parsed with QemuOpts.

The option argument is specified in trace/control.c:

    QemuOptsList qemu_trace_opts = {
        .name = "trace",
        .implied_opt_name = "enable",
        .head = QTAILQ_HEAD_INITIALIZER(qemu_trace_opts.head),
        .desc = {
            {
                .name = "enable",
                .type = QEMU_OPT_STRING,
            },
            {
                .name = "events",
                .type = QEMU_OPT_STRING,
            },{
                .name = "file",
                .type = QEMU_OPT_STRING,
            },
            { /* end of list */ }
        },
    };

We generally refer to QemuOptsList by name.  This one's name is "trace".

The non-empty .desc[] enumerates the recognized parameters.
Additionally, special parameter "id" is recognized.

.implied_opt_name enables "omitted first key defaults to implied key"
sugar.  This is what makes "-trace PATTERN" shorthand for -trace
enable=PATTERN", where PATTERN contains neither '=' nor unescaped ','.

The QemuOpts parser parses an option argument string into a QemuOpts,
stores it for later use, and also returns it for immediate use.

Code can do whatever it wants with the stored parameters.  This is a
wellspring of inconsistency and confusion.

Let's look at the code for -trace.  In qemu_init(), we have:

                case QEMU_OPTION_trace:
                    trace_opt_parse(optarg);
                    break;

This calls trace_opt_parse() for every -trace, in order.  @optarg is the
argument string.

    void trace_opt_parse(const char *optarg)
    {
        QemuOpts *opts = qemu_opts_parse_noisily(qemu_find_opts("trace"),
                                                 optarg, true);

qemu_opts_parse_noisily() parses @optarg into a QemuOpts, stores it for
later use, and also returns it for immediate use.

        if (!opts) {
            exit(1);
        }

        if (qemu_opt_get(opts, "enable")) {
            trace_enable_events(qemu_opt_get(opts, "enable"));
        }

Pass the last enable=PATTERN in @optarg to trace_enable_events().

        trace_init_events(qemu_opt_get(opts, "events"));

Pass the the last events=FILENAME to trace_init_events(), which parses
patterns from file FILENAME and passes them to trace_enable_events().

Non-last enable=... ane events=... are silently ignored.

        init_trace_on_startup = true;

Set a flag for trace_init_file().

        qemu_opts_del(opts);

Delete the stored QemuOpts.  We'll get back to this in jiffie.

    }

Later in qemu_init(), we call trace_init_file().  Here it is:

    void trace_init_file(void)
    {
        QemuOpts *opts = qemu_find_opts_singleton("trace");

This gets the first QemuOpts stored in the QemuOptsList named "trace"
without "id".  If there is none, it creates an empty one for us.

Since trace_opt_parse() deletes, this always creates an empty one.

        const char *file = qemu_opt_get(opts, "file");

This is always null.

    #ifdef CONFIG_TRACE_SIMPLE
        st_set_trace_file(file);
        if (init_trace_on_startup) {
            st_set_trace_file_enabled(true);
        }
    #elif defined CONFIG_TRACE_LOG
        /*
         * If both the simple and the log backends are enabled, "--trace file"
         * only applies to the simple backend; use "-D" for the log
         * backend. However we should only override -D if we actually have
         * something to override it with.
         */
        if (file) {
            qemu_set_log_filename(file, &error_fatal);
        }
    #else
        if (file) {
            fprintf(stderr, "error: --trace file=...: "
                    "option not supported by the selected tracing backends\n");
            exit(1);
        }
    #endif
    }

Bug: option parameter "file" has no effect.  I suspect this was broken
in commit 92eecfff32 "trace: remove argument from trace_init_file",
2020-11-11.

And now I'm ready to answer your question:

    -trace enable=pattern1,enable=pattern2

is a confusing way to say

    -trace enable=pattern2

To specify both patterns, use

    -trace enable=pattern1 -trace enable=pattern2

Lovely, isn't it?

Re: [PULL 10/11] trace: document how to specify multiple --trace patterns

[BALATON Zoltan]

On Tue, 2 Feb 2021, Markus Armbruster wrote:
> And now I'm ready to answer your question:
>
>    -trace enable=pattern1,enable=pattern2
>
> is a confusing way to say
>
>    -trace enable=pattern2
>
> To specify both patterns, use
>
>    -trace enable=pattern1 -trace enable=pattern2
>
> Lovely, isn't it?

OK, interesting. The conclusion is then that the doc change in this patch 
_is_ the simplest way to enable multiple traces as only repeating the 
-trace option works and enable= is optional in this case. Thank you for 
the detailed explanation.

Regards,
BALATON Zoltan

Re: [PULL 10/11] trace: document how to specify multiple --trace patterns

[Paolo Bonzini]

On 02/02/21 13:41, Markus Armbruster wrote:
> Since trace_opt_parse() deletes, this always creates an empty one.
> 
>          const char *file = qemu_opt_get(opts, "file");
> 
> This is always null.
> 
>      #ifdef CONFIG_TRACE_SIMPLE
>          st_set_trace_file(file);
>          if (init_trace_on_startup) {
>              st_set_trace_file_enabled(true);
>          }
>      #elif defined CONFIG_TRACE_LOG
>          /*
>           * If both the simple and the log backends are enabled, "--trace file"
>           * only applies to the simple backend; use "-D" for the log
>           * backend. However we should only override -D if we actually have
>           * something to override it with.
>           */
>          if (file) {
>              qemu_set_log_filename(file, &error_fatal);
>          }
>      #else
>          if (file) {
>              fprintf(stderr, "error: --trace file=...: "
>                      "option not supported by the selected tracing backends\n");
>              exit(1);
>          }
>      #endif
>      }
> 
> Bug: option parameter "file" has no effect.  I suspect this was broken
> in commit 92eecfff32 "trace: remove argument from trace_init_file",
> 2020-11-11.

Indeed, and I'll fix it.

Paolo

Re: [PULL 10/11] trace: document how to specify multiple --trace patterns

[Stefan Hajnoczi]

[-- Attachment #1: Type: text/plain, Size: 1415 bytes --]

On Mon, Feb 01, 2021 at 07:13:27PM +0100, BALATON Zoltan wrote:
> On Mon, 1 Feb 2021, Daniel P. Berrangé wrote:
> > On Mon, Feb 01, 2021 at 06:25:33PM +0100, Paolo Bonzini wrote:
> > > On 01/02/21 17:54, Kevin Wolf wrote:
> > > > > How does this option parsing work? Would then multiple patterns separated by
> > > > > comma as in -trace pattern1,pattern2 also work?
> > > > This would be interpreted as an implied "enable" option with a value of
> > > > "pattern1,pattern2". I don't think anything splits that string at the
> > > > comma, so it would look for a trace event matching that string.
> > > 
> > > Even worse, it would be interpreted as "-trace enable=pattern1,pattern2=on"
> > > (and raise a warning since recently).
> > 
> > Maybe we're trying to solve the problem at the wrong level.
> 
> There's no problem to solve, just trying to understand better what are the
> valid options. It's already possible to enable multiple patterns with either
> events=file or repeating -trace options (with or without enable=) so that's
> already sufficient, I was just curious what other options are there and if
> there's a simpler way that we could document. If not, using the current ways
> that are now documented is OK I think.

The enable=PATTERN syntax is very limited. Repeating the --trace option
is currently the only way to enter multiple patterns on the
command-line.

Stefan

[-- Attachment #2: signature.asc --]
[-- Type: application/pgp-signature, Size: 488 bytes --]