[PATCH v2 0/3] trace: Add a trace backend for the recorder library

[PATCH v2 0/3] trace: Add a trace backend for the recorder library

[Christophe de Dinechin]

The recorder library implements low-cost always-on tracing, with three
usage models:

1. Flight recorder: Dump information on recent events in case of crash
2. Tracing: Individual traces can be enabled using environment variables
3. Real-time graphing / control, using the recorder_scope application

This short series introduces a new "recorder" back-end which connects
to the recorder. Traces using the recorder are intentionally "always on".
An example is given of how the recorder can also be used separately
from generated traces. This can be useful if you want to enable
multiple related traces for a particular topic.

This series requires a small makefile fix submitted earlier, included
here for convenience.

Christophe de Dinechin (3):
  Makefile: Compute libraries for libqemuutil.a and libvhost-user.a
  trace: Add support for recorder back-end
  trace: Example of "centralized" recorder tracing

 Makefile                              |  2 ++
 configure                             |  5 +++
 hmp-commands.hx                       | 19 ++++++++--
 monitor/misc.c                        | 27 ++++++++++++++
 scripts/tracetool/backend/recorder.py | 51 +++++++++++++++++++++++++++
 trace/Makefile.objs                   |  2 ++
 trace/control.c                       |  7 ++++
 trace/recorder.c                      | 22 ++++++++++++
 trace/recorder.h                      | 34 ++++++++++++++++++
 util/module.c                         |  8 +++++
 util/qemu-thread-common.h             |  7 ++++
 11 files changed, 182 insertions(+), 2 deletions(-)
 create mode 100644 scripts/tracetool/backend/recorder.py
 create mode 100644 trace/recorder.c
 create mode 100644 trace/recorder.h

-- 
2.26.2

[PATCH v2 1/3] Makefile: Compute libraries for libqemuutil.a and libvhost-user.a

[Christophe de Dinechin]

In util/Makefile.objs, there is a setting for dbus.o-libs.
Trying to copy-paste that to add a library for module.o that was was
not otherwise linked yields link errors on a number of binaries,
e.g. qemu-ga, with unsatisfied symbols in libqemuutil.a(module.o).
The reason is that library dependencies are not propagated to the .a
files automatically.

Adding a call to extract-libs to get the libraries for the two .a
files that are used elsewhere.

Signed-off-by: Christophe de Dinechin <dinechin@redhat.com>
---
 Makefile | 2 ++
 1 file changed, 2 insertions(+)

diff --git a/Makefile b/Makefile
index a0092153af..b29b0eeefa 100644
--- a/Makefile
+++ b/Makefile
@@ -589,6 +589,8 @@ Makefile: $(version-obj-y)
 ######################################################################
 # Build libraries
 
+libqemuutil.a-libs += $(call extract-libs, $(util-obj-y) $(trace-obj-y) $(stub-obj-y))
+libvhost-user.a-libs += $(call extract-libs, $(libvhost-user-obj-y) $(util-obj-y) $(stub-obj-y))
 libqemuutil.a: $(util-obj-y) $(trace-obj-y) $(stub-obj-y)
 libvhost-user.a: $(libvhost-user-obj-y) $(util-obj-y) $(stub-obj-y)
 
-- 
2.26.2

Re: [PATCH v2 1/3] Makefile: Compute libraries for libqemuutil.a and libvhost-user.a

[Stefan Hajnoczi]

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

On Fri, Jun 26, 2020 at 06:27:04PM +0200, Christophe de Dinechin wrote:
> In util/Makefile.objs, there is a setting for dbus.o-libs.
> Trying to copy-paste that to add a library for module.o that was was
> not otherwise linked yields link errors on a number of binaries,
> e.g. qemu-ga, with unsatisfied symbols in libqemuutil.a(module.o).
> The reason is that library dependencies are not propagated to the .a
> files automatically.
> 
> Adding a call to extract-libs to get the libraries for the two .a
> files that are used elsewhere.
> 
> Signed-off-by: Christophe de Dinechin <dinechin@redhat.com>
> ---
>  Makefile | 2 ++
>  1 file changed, 2 insertions(+)
> 
> diff --git a/Makefile b/Makefile
> index a0092153af..b29b0eeefa 100644
> --- a/Makefile
> +++ b/Makefile
> @@ -589,6 +589,8 @@ Makefile: $(version-obj-y)
>  ######################################################################
>  # Build libraries
>  
> +libqemuutil.a-libs += $(call extract-libs, $(util-obj-y) $(trace-obj-y) $(stub-obj-y))
> +libvhost-user.a-libs += $(call extract-libs, $(libvhost-user-obj-y) $(util-obj-y) $(stub-obj-y))
>  libqemuutil.a: $(util-obj-y) $(trace-obj-y) $(stub-obj-y)
>  libvhost-user.a: $(libvhost-user-obj-y) $(util-obj-y) $(stub-obj-y)

Please see https://patchwork.kernel.org/patch/11608247/#23440227.

If this change causes all libraries from .a object files to be linked
then this patch is incomplete. The purpose of the .a file is to link
only the subset of .o files required by the program. Unused .o files in
the .a file are not linked into the program. The libraries must also be
linked as needed but this patch seems to extract them unconditionally.

Stefan

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

[PATCH v2 2/3] trace: Add support for recorder back-end

[Christophe de Dinechin]

The recorder library provides support for low-cost continuous
recording of events, which can then be replayed. This makes it
possible to collect data "after the fact",for example to show the
events that led to a crash.

Recorder support in qemu is implemented using the existing tracing
interface. In addition, it is possible to individually enable
recorders that are not traces, although this is probably not
recommended.

HMP COMMAND:
The 'recorder' hmp command has been added, which supports two
sub-commands:
- recorder dump: Dump the current state of the recorder. You can
- recorder trace: Set traces using the recorder_trace_set() syntax.
  You can use "recorder trace help" to list all available recorders.

Signed-off-by: Christophe de Dinechin <dinechin@redhat.com>
---
 configure                             |  5 +++
 hmp-commands.hx                       | 19 ++++++++--
 monitor/misc.c                        | 27 ++++++++++++++
 scripts/tracetool/backend/recorder.py | 51 +++++++++++++++++++++++++++
 trace/Makefile.objs                   |  2 ++
 trace/control.c                       |  7 ++++
 trace/recorder.c                      | 22 ++++++++++++
 trace/recorder.h                      | 34 ++++++++++++++++++
 util/module.c                         |  8 +++++
 9 files changed, 173 insertions(+), 2 deletions(-)
 create mode 100644 scripts/tracetool/backend/recorder.py
 create mode 100644 trace/recorder.c
 create mode 100644 trace/recorder.h

diff --git a/configure b/configure
index ae8737d5a2..130630b98f 100755
--- a/configure
+++ b/configure
@@ -7702,6 +7702,11 @@ fi
 if have_backend "log"; then
   echo "CONFIG_TRACE_LOG=y" >> $config_host_mak
 fi
+if have_backend "recorder"; then
+  echo "CONFIG_TRACE_RECORDER=y" >> $config_host_mak
+  # This is a bit brutal, but there is currently a bug in the makefiles
+  LIBS="$LIBS -lrecorder"
+fi
 if have_backend "ust"; then
   echo "CONFIG_TRACE_UST=y" >> $config_host_mak
 fi
diff --git a/hmp-commands.hx b/hmp-commands.hx
index 60f395c276..565f518d4b 100644
--- a/hmp-commands.hx
+++ b/hmp-commands.hx
@@ -297,6 +297,22 @@ ERST
         .cmd        = hmp_trace_file,
     },
 
+SRST
+``trace-file on|off|flush``
+  Open, close, or flush the trace file.  If no argument is given, the
+  status of the trace file is displayed.
+ERST
+#endif
+
+#if defined(CONFIG_TRACE_RECORDER)
+    {
+        .name       = "recorder",
+        .args_type  = "op:s?,arg:F?",
+        .params     = "trace|dump [arg]",
+        .help       = "trace selected recorders or print recorder dump",
+        .cmd        = hmp_recorder,
+    },
+
 SRST
 ``trace-file on|off|flush``
   Open, close, or flush the trace file.  If no argument is given, the
@@ -1120,7 +1136,7 @@ ERST
 
 SRST
 ``dump-guest-memory [-p]`` *filename* *begin* *length*
-  \ 
+  \
 ``dump-guest-memory [-z|-l|-s|-w]`` *filename*
   Dump guest memory to *protocol*. The file can be processed with crash or
   gdb. Without ``-z|-l|-s|-w``, the dump format is ELF.
@@ -1828,4 +1844,3 @@ ERST
         .sub_table  = hmp_info_cmds,
         .flags      = "p",
     },
-
diff --git a/monitor/misc.c b/monitor/misc.c
index 89bb970b00..0094b1860f 100644
--- a/monitor/misc.c
+++ b/monitor/misc.c
@@ -61,6 +61,9 @@
 #ifdef CONFIG_TRACE_SIMPLE
 #include "trace/simple.h"
 #endif
+#ifdef CONFIG_TRACE_RECORDER
+#include "trace/recorder.h"
+#endif
 #include "exec/memory.h"
 #include "exec/exec-all.h"
 #include "qemu/option.h"
@@ -227,6 +230,30 @@ static void hmp_trace_file(Monitor *mon, const QDict *qdict)
 }
 #endif
 
+#ifdef CONFIG_TRACE_RECORDER
+static void hmp_recorder(Monitor *mon, const QDict *qdict)
+{
+    const char *op = qdict_get_try_str(qdict, "op");
+    const char *arg = qdict_get_try_str(qdict, "arg");
+
+    if (!op) {
+        monitor_printf(mon, "missing recorder command\"%s\"\n", op);
+        help_cmd(mon, "recorder");
+    } else if (!strcmp(op, "trace")) {
+        recorder_trace_set(arg);
+    } else if (!strcmp(op, "dump")) {
+        if (!arg || !*arg) {
+            recorder_dump();
+        } else {
+            recorder_dump_for(arg);
+        }
+    } else {
+        monitor_printf(mon, "unexpected recorder command \"%s\"\n", op);
+        help_cmd(mon, "recorder");
+    }
+}
+#endif
+
 static void hmp_info_help(Monitor *mon, const QDict *qdict)
 {
     help_cmd(mon, "info");
diff --git a/scripts/tracetool/backend/recorder.py b/scripts/tracetool/backend/recorder.py
new file mode 100644
index 0000000000..79cc6f5b03
--- /dev/null
+++ b/scripts/tracetool/backend/recorder.py
@@ -0,0 +1,51 @@
+# -*- coding: utf-8 -*-
+
+"""
+Trace back-end for recorder library
+"""
+
+__author__     = "Christophe de Dinechin <christophe@dinechin.org>"
+__copyright__  = "Copyright 2020, Christophe de Dinechin and Red Hat"
+__license__    = "GPL version 2 or (at your option) any later version"
+
+__maintainer__ = "Christophe de Dinechin"
+__email__      = "christophe@dinechin.org"
+
+
+from tracetool import out
+
+PUBLIC = True
+
+def generate_h_begin(events, group):
+    out('#include <recorder/recorder.h>', '')
+
+    for event in events:
+        out('RECORDER_DECLARE(%(name)s);', name=event.name)
+
+
+def generate_h(event, group):
+    argnames = ", ".join(event.args.names())
+    if len(event.args) > 0:
+        argnames = ", " + argnames
+
+    out('    record(%(event)s, %(fmt)s %(argnames)s);',
+        event=event.name,
+        fmt=event.fmt.rstrip("\n"),
+        argnames=argnames)
+
+
+def generate_h_backend_dstate(event, group):
+    out('    RECORDER_TWEAK(%(event_id)s) || \\', event_id=event.name)
+
+def generate_c_begin(events, group):
+    out('#include "qemu/osdep.h"',
+        '#include "trace/control.h"',
+        '#include "trace/simple.h"',
+        '#include <recorder/recorder.h>',
+        '')
+
+    for event in events:
+        out('RECORDER_DEFINE(%(name)s, 8, "Tracetool recorder for %(api)s(%(args)s)");',
+            name=event.name,
+            api=event.api(),
+            args=event.args)
diff --git a/trace/Makefile.objs b/trace/Makefile.objs
index c544509adf..9e347640c2 100644
--- a/trace/Makefile.objs
+++ b/trace/Makefile.objs
@@ -54,6 +54,8 @@ $(obj)/generated-tcg-tracers.h-timestamp: $(SRC_PATH)/trace-events $(BUILD_DIR)/
 
 util-obj-$(CONFIG_TRACE_SIMPLE) += simple.o
 util-obj-$(CONFIG_TRACE_FTRACE) += ftrace.o
+util-obj-$(CONFIG_TRACE_RECORDER) += recorder.o
+recorder.o-libs = -lrecorder
 util-obj-y += control.o
 obj-y += control-target.o
 util-obj-y += qmp.o
diff --git a/trace/control.c b/trace/control.c
index 2ffe000818..15e5293eec 100644
--- a/trace/control.c
+++ b/trace/control.c
@@ -23,6 +23,9 @@
 #ifdef CONFIG_TRACE_SYSLOG
 #include <syslog.h>
 #endif
+#ifdef CONFIG_TRACE_RECORDER
+#include "trace/recorder.h"
+#endif
 #include "qapi/error.h"
 #include "qemu/error-report.h"
 #include "qemu/config-file.h"
@@ -282,6 +285,10 @@ bool trace_init_backends(void)
     openlog(NULL, LOG_PID, LOG_DAEMON);
 #endif
 
+#ifdef CONFIG_TRACE_RECORDER
+    recorder_trace_init();
+#endif
+
     return true;
 }
 
diff --git a/trace/recorder.c b/trace/recorder.c
new file mode 100644
index 0000000000..cbc22ee2d5
--- /dev/null
+++ b/trace/recorder.c
@@ -0,0 +1,22 @@
+/*
+ * Recorder-based trace backend
+ *
+ * Copyright Red Hat 2020
+ *
+ * This work is licensed under the terms of the GNU GPL, version 2.  See
+ * the COPYING file in the top-level directory.
+ *
+ */
+
+#include "trace/recorder.h"
+
+RECORDER_CONSTRUCTOR
+void recorder_trace_init(void)
+{
+    recorder_trace_set(getenv("RECORDER_TRACES"));
+
+    // Allow a dump in case we receive some unhandled signal
+    // For example, send USR2 to a hung process to get a dump
+    if (getenv("RECORDER_TRACES"))
+        recorder_dump_on_common_signals(0,0);
+}
diff --git a/trace/recorder.h b/trace/recorder.h
new file mode 100644
index 0000000000..00b11a2d2f
--- /dev/null
+++ b/trace/recorder.h
@@ -0,0 +1,34 @@
+/*
+ * Recorder-based trace backend
+ *
+ * Copyright Red Hat 2020
+ *
+ * This work is licensed under the terms of the GNU GPL, version 2.  See
+ * the COPYING file in the top-level directory.
+ *
+ */
+
+#ifndef TRACE_RECORDER_H
+#define TRACE_RECORDER_H
+
+#include "qemu/osdep.h"
+
+#ifdef CONFIG_TRACE_RECORDER
+
+#include <recorder/recorder.h>
+
+extern void recorder_trace_init(void);
+
+#else
+
+// Disable recorder macros
+#define RECORDER(Name, Size, Description)
+#define RECORDER_DEFINE(Name, Size, Description)
+#define RECORDER_DECLARE(Name)
+#define RECORD(Name, ...)
+#define record(Name, ...)
+#define recorder_trace_init()
+
+#endif // CONFIG_TRACE_RECORDER
+
+#endif // TRACE_RECORDER_H
diff --git a/util/module.c b/util/module.c
index e48d9aacc0..2fa93561fe 100644
--- a/util/module.c
+++ b/util/module.c
@@ -22,6 +22,10 @@
 #ifdef CONFIG_MODULE_UPGRADES
 #include "qemu-version.h"
 #endif
+#ifdef CONFIG_TRACE_RECORDER
+#include "trace/recorder.h"
+#endif
+
 
 typedef struct ModuleEntry
 {
@@ -150,6 +154,10 @@ static int module_load_file(const char *fname)
         g_module_close(g_module);
         ret = -EINVAL;
     } else {
+#ifdef CONFIG_TRACE_RECORDER
+        // New recorders may have been pulled in, activate them if necessary
+        recorder_trace_init();
+#endif
         QTAILQ_FOREACH(e, &dso_init_list, node) {
             e->init();
             register_module_init(e->init, e->type);
-- 
2.26.2

Re: [PATCH v2 2/3] trace: Add support for recorder back-end

[Dr. David Alan Gilbert]

* Christophe de Dinechin (dinechin@redhat.com) wrote:
> The recorder library provides support for low-cost continuous
> recording of events, which can then be replayed. This makes it
> possible to collect data "after the fact",for example to show the
> events that led to a crash.
> 
> Recorder support in qemu is implemented using the existing tracing
> interface. In addition, it is possible to individually enable
> recorders that are not traces, although this is probably not
> recommended.
> 
> HMP COMMAND:
> The 'recorder' hmp command has been added, which supports two
> sub-commands:
> - recorder dump: Dump the current state of the recorder. You can
                                                          ^^^^^^^^
is that intended?

> - recorder trace: Set traces using the recorder_trace_set() syntax.
>   You can use "recorder trace help" to list all available recorders.
> 
> Signed-off-by: Christophe de Dinechin <dinechin@redhat.com>
> ---
>  configure                             |  5 +++
>  hmp-commands.hx                       | 19 ++++++++--
>  monitor/misc.c                        | 27 ++++++++++++++
>  scripts/tracetool/backend/recorder.py | 51 +++++++++++++++++++++++++++
>  trace/Makefile.objs                   |  2 ++
>  trace/control.c                       |  7 ++++
>  trace/recorder.c                      | 22 ++++++++++++
>  trace/recorder.h                      | 34 ++++++++++++++++++
>  util/module.c                         |  8 +++++
>  9 files changed, 173 insertions(+), 2 deletions(-)
>  create mode 100644 scripts/tracetool/backend/recorder.py
>  create mode 100644 trace/recorder.c
>  create mode 100644 trace/recorder.h
> 
> diff --git a/configure b/configure
> index ae8737d5a2..130630b98f 100755
> --- a/configure
> +++ b/configure
> @@ -7702,6 +7702,11 @@ fi
>  if have_backend "log"; then
>    echo "CONFIG_TRACE_LOG=y" >> $config_host_mak
>  fi
> +if have_backend "recorder"; then
> +  echo "CONFIG_TRACE_RECORDER=y" >> $config_host_mak
> +  # This is a bit brutal, but there is currently a bug in the makefiles
> +  LIBS="$LIBS -lrecorder"
> +fi
>  if have_backend "ust"; then
>    echo "CONFIG_TRACE_UST=y" >> $config_host_mak
>  fi
> diff --git a/hmp-commands.hx b/hmp-commands.hx
> index 60f395c276..565f518d4b 100644
> --- a/hmp-commands.hx
> +++ b/hmp-commands.hx
> @@ -297,6 +297,22 @@ ERST
>          .cmd        = hmp_trace_file,
>      },
>  
> +SRST
> +``trace-file on|off|flush``
> +  Open, close, or flush the trace file.  If no argument is given, the
> +  status of the trace file is displayed.
> +ERST
> +#endif
> +
> +#if defined(CONFIG_TRACE_RECORDER)
> +    {
> +        .name       = "recorder",
> +        .args_type  = "op:s?,arg:F?",

Having 'arg' as a filename is a bit odd; using op/arg is very generic
for adding extra commands; but it suddenly becomes less generic if
arg is always a filename.

> +        .params     = "trace|dump [arg]",
> +        .help       = "trace selected recorders or print recorder dump",
> +        .cmd        = hmp_recorder,
> +    },
> +
>  SRST
>  ``trace-file on|off|flush``
>    Open, close, or flush the trace file.  If no argument is given, the

I think this SRST chunk is the one that needs updating for recorder.
(The diff has made a bit of a mess, but I think you've copy pasted the
trace-file chunk, but forgotten to update the SRST section).

> @@ -1120,7 +1136,7 @@ ERST
>  
>  SRST
>  ``dump-guest-memory [-p]`` *filename* *begin* *length*
> -  \ 
> +  \
>  ``dump-guest-memory [-z|-l|-s|-w]`` *filename*
>    Dump guest memory to *protocol*. The file can be processed with crash or
>    gdb. Without ``-z|-l|-s|-w``, the dump format is ELF.
> @@ -1828,4 +1844,3 @@ ERST
>          .sub_table  = hmp_info_cmds,
>          .flags      = "p",
>      },
> -
> diff --git a/monitor/misc.c b/monitor/misc.c
> index 89bb970b00..0094b1860f 100644
> --- a/monitor/misc.c
> +++ b/monitor/misc.c
> @@ -61,6 +61,9 @@
>  #ifdef CONFIG_TRACE_SIMPLE
>  #include "trace/simple.h"
>  #endif
> +#ifdef CONFIG_TRACE_RECORDER
> +#include "trace/recorder.h"
> +#endif
>  #include "exec/memory.h"
>  #include "exec/exec-all.h"
>  #include "qemu/option.h"
> @@ -227,6 +230,30 @@ static void hmp_trace_file(Monitor *mon, const QDict *qdict)
>  }
>  #endif
>  
> +#ifdef CONFIG_TRACE_RECORDER
> +static void hmp_recorder(Monitor *mon, const QDict *qdict)
> +{
> +    const char *op = qdict_get_try_str(qdict, "op");
> +    const char *arg = qdict_get_try_str(qdict, "arg");
> +
> +    if (!op) {
> +        monitor_printf(mon, "missing recorder command\"%s\"\n", op);
> +        help_cmd(mon, "recorder");
> +    } else if (!strcmp(op, "trace")) {
> +        recorder_trace_set(arg);
> +    } else if (!strcmp(op, "dump")) {
> +        if (!arg || !*arg) {
> +            recorder_dump();
> +        } else {
> +            recorder_dump_for(arg);
> +        }
> +    } else {
> +        monitor_printf(mon, "unexpected recorder command \"%s\"\n", op);
> +        help_cmd(mon, "recorder");
> +    }
> +}

Consider whether just doing two separate commands would be easier;
a recorder-trace and recorder-dump for example; that's fine from a HMP
point of view and I think you'll find it's less code.

Dave

> +#endif
> +
>  static void hmp_info_help(Monitor *mon, const QDict *qdict)
>  {
>      help_cmd(mon, "info");
> diff --git a/scripts/tracetool/backend/recorder.py b/scripts/tracetool/backend/recorder.py
> new file mode 100644
> index 0000000000..79cc6f5b03
> --- /dev/null
> +++ b/scripts/tracetool/backend/recorder.py
> @@ -0,0 +1,51 @@
> +# -*- coding: utf-8 -*-
> +
> +"""
> +Trace back-end for recorder library
> +"""
> +
> +__author__     = "Christophe de Dinechin <christophe@dinechin.org>"
> +__copyright__  = "Copyright 2020, Christophe de Dinechin and Red Hat"
> +__license__    = "GPL version 2 or (at your option) any later version"
> +
> +__maintainer__ = "Christophe de Dinechin"
> +__email__      = "christophe@dinechin.org"
> +
> +
> +from tracetool import out
> +
> +PUBLIC = True
> +
> +def generate_h_begin(events, group):
> +    out('#include <recorder/recorder.h>', '')
> +
> +    for event in events:
> +        out('RECORDER_DECLARE(%(name)s);', name=event.name)
> +
> +
> +def generate_h(event, group):
> +    argnames = ", ".join(event.args.names())
> +    if len(event.args) > 0:
> +        argnames = ", " + argnames
> +
> +    out('    record(%(event)s, %(fmt)s %(argnames)s);',
> +        event=event.name,
> +        fmt=event.fmt.rstrip("\n"),
> +        argnames=argnames)
> +
> +
> +def generate_h_backend_dstate(event, group):
> +    out('    RECORDER_TWEAK(%(event_id)s) || \\', event_id=event.name)
> +
> +def generate_c_begin(events, group):
> +    out('#include "qemu/osdep.h"',
> +        '#include "trace/control.h"',
> +        '#include "trace/simple.h"',
> +        '#include <recorder/recorder.h>',
> +        '')
> +
> +    for event in events:
> +        out('RECORDER_DEFINE(%(name)s, 8, "Tracetool recorder for %(api)s(%(args)s)");',
> +            name=event.name,
> +            api=event.api(),
> +            args=event.args)
> diff --git a/trace/Makefile.objs b/trace/Makefile.objs
> index c544509adf..9e347640c2 100644
> --- a/trace/Makefile.objs
> +++ b/trace/Makefile.objs
> @@ -54,6 +54,8 @@ $(obj)/generated-tcg-tracers.h-timestamp: $(SRC_PATH)/trace-events $(BUILD_DIR)/
>  
>  util-obj-$(CONFIG_TRACE_SIMPLE) += simple.o
>  util-obj-$(CONFIG_TRACE_FTRACE) += ftrace.o
> +util-obj-$(CONFIG_TRACE_RECORDER) += recorder.o
> +recorder.o-libs = -lrecorder
>  util-obj-y += control.o
>  obj-y += control-target.o
>  util-obj-y += qmp.o
> diff --git a/trace/control.c b/trace/control.c
> index 2ffe000818..15e5293eec 100644
> --- a/trace/control.c
> +++ b/trace/control.c
> @@ -23,6 +23,9 @@
>  #ifdef CONFIG_TRACE_SYSLOG
>  #include <syslog.h>
>  #endif
> +#ifdef CONFIG_TRACE_RECORDER
> +#include "trace/recorder.h"
> +#endif
>  #include "qapi/error.h"
>  #include "qemu/error-report.h"
>  #include "qemu/config-file.h"
> @@ -282,6 +285,10 @@ bool trace_init_backends(void)
>      openlog(NULL, LOG_PID, LOG_DAEMON);
>  #endif
>  
> +#ifdef CONFIG_TRACE_RECORDER
> +    recorder_trace_init();
> +#endif
> +
>      return true;
>  }
>  
> diff --git a/trace/recorder.c b/trace/recorder.c
> new file mode 100644
> index 0000000000..cbc22ee2d5
> --- /dev/null
> +++ b/trace/recorder.c
> @@ -0,0 +1,22 @@
> +/*
> + * Recorder-based trace backend
> + *
> + * Copyright Red Hat 2020
> + *
> + * This work is licensed under the terms of the GNU GPL, version 2.  See
> + * the COPYING file in the top-level directory.
> + *
> + */
> +
> +#include "trace/recorder.h"
> +
> +RECORDER_CONSTRUCTOR
> +void recorder_trace_init(void)
> +{
> +    recorder_trace_set(getenv("RECORDER_TRACES"));
> +
> +    // Allow a dump in case we receive some unhandled signal
> +    // For example, send USR2 to a hung process to get a dump
> +    if (getenv("RECORDER_TRACES"))
> +        recorder_dump_on_common_signals(0,0);
> +}
> diff --git a/trace/recorder.h b/trace/recorder.h
> new file mode 100644
> index 0000000000..00b11a2d2f
> --- /dev/null
> +++ b/trace/recorder.h
> @@ -0,0 +1,34 @@
> +/*
> + * Recorder-based trace backend
> + *
> + * Copyright Red Hat 2020
> + *
> + * This work is licensed under the terms of the GNU GPL, version 2.  See
> + * the COPYING file in the top-level directory.
> + *
> + */
> +
> +#ifndef TRACE_RECORDER_H
> +#define TRACE_RECORDER_H
> +
> +#include "qemu/osdep.h"
> +
> +#ifdef CONFIG_TRACE_RECORDER
> +
> +#include <recorder/recorder.h>
> +
> +extern void recorder_trace_init(void);
> +
> +#else
> +
> +// Disable recorder macros
> +#define RECORDER(Name, Size, Description)
> +#define RECORDER_DEFINE(Name, Size, Description)
> +#define RECORDER_DECLARE(Name)
> +#define RECORD(Name, ...)
> +#define record(Name, ...)
> +#define recorder_trace_init()
> +
> +#endif // CONFIG_TRACE_RECORDER
> +
> +#endif // TRACE_RECORDER_H
> diff --git a/util/module.c b/util/module.c
> index e48d9aacc0..2fa93561fe 100644
> --- a/util/module.c
> +++ b/util/module.c
> @@ -22,6 +22,10 @@
>  #ifdef CONFIG_MODULE_UPGRADES
>  #include "qemu-version.h"
>  #endif
> +#ifdef CONFIG_TRACE_RECORDER
> +#include "trace/recorder.h"
> +#endif
> +
>  
>  typedef struct ModuleEntry
>  {
> @@ -150,6 +154,10 @@ static int module_load_file(const char *fname)
>          g_module_close(g_module);
>          ret = -EINVAL;
>      } else {
> +#ifdef CONFIG_TRACE_RECORDER
> +        // New recorders may have been pulled in, activate them if necessary
> +        recorder_trace_init();
> +#endif
>          QTAILQ_FOREACH(e, &dso_init_list, node) {
>              e->init();
>              register_module_init(e->init, e->type);
> -- 
> 2.26.2
> 
--
Dr. David Alan Gilbert / dgilbert@redhat.com / Manchester, UK

Re: [PATCH v2 2/3] trace: Add support for recorder back-end

[Christophe de Dinechin]

On 2020-06-30 at 11:05 CEST, Dr. David Alan Gilbert wrote...
> * Christophe de Dinechin (dinechin@redhat.com) wrote:
>> The recorder library provides support for low-cost continuous
>> recording of events, which can then be replayed. This makes it
>> possible to collect data "after the fact",for example to show the
>> events that led to a crash.
>>
>> Recorder support in qemu is implemented using the existing tracing
>> interface. In addition, it is possible to individually enable
>> recorders that are not traces, although this is probably not
>> recommended.
>>
>> HMP COMMAND:
>> The 'recorder' hmp command has been added, which supports two
>> sub-commands:
>> - recorder dump: Dump the current state of the recorder. You can
>                                                           ^^^^^^^^
> is that intended?

No. I think the intent was to indicate that you could pass the name of a
recorder to dump as an arg. I'll fix.

>
>> - recorder trace: Set traces using the recorder_trace_set() syntax.
>>   You can use "recorder trace help" to list all available recorders.
>>
>> Signed-off-by: Christophe de Dinechin <dinechin@redhat.com>
>> ---
>>  configure                             |  5 +++
>>  hmp-commands.hx                       | 19 ++++++++--
>>  monitor/misc.c                        | 27 ++++++++++++++
>>  scripts/tracetool/backend/recorder.py | 51 +++++++++++++++++++++++++++
>>  trace/Makefile.objs                   |  2 ++
>>  trace/control.c                       |  7 ++++
>>  trace/recorder.c                      | 22 ++++++++++++
>>  trace/recorder.h                      | 34 ++++++++++++++++++
>>  util/module.c                         |  8 +++++
>>  9 files changed, 173 insertions(+), 2 deletions(-)
>>  create mode 100644 scripts/tracetool/backend/recorder.py
>>  create mode 100644 trace/recorder.c
>>  create mode 100644 trace/recorder.h
>>
>> diff --git a/configure b/configure
>> index ae8737d5a2..130630b98f 100755
>> --- a/configure

>> +++ b/configure
>> @@ -7702,6 +7702,11 @@ fi
>>  if have_backend "log"; then
>>    echo "CONFIG_TRACE_LOG=y" >> $config_host_mak
>>  fi
>> +if have_backend "recorder"; then
>> +  echo "CONFIG_TRACE_RECORDER=y" >> $config_host_mak
>> +  # This is a bit brutal, but there is currently a bug in the makefiles
>> +  LIBS="$LIBS -lrecorder"
>> +fi
>>  if have_backend "ust"; then
>>    echo "CONFIG_TRACE_UST=y" >> $config_host_mak
>>  fi
>> diff --git a/hmp-commands.hx b/hmp-commands.hx
>> index 60f395c276..565f518d4b 100644
>> --- a/hmp-commands.hx
>> +++ b/hmp-commands.hx
>> @@ -297,6 +297,22 @@ ERST
>>          .cmd        = hmp_trace_file,
>>      },
>>
>> +SRST
>> +``trace-file on|off|flush``
>> +  Open, close, or flush the trace file.  If no argument is given, the
>> +  status of the trace file is displayed.
>> +ERST
>> +#endif
>> +
>> +#if defined(CONFIG_TRACE_RECORDER)
>> +    {
>> +        .name       = "recorder",
>> +        .args_type  = "op:s?,arg:F?",
>
> Having 'arg' as a filename is a bit odd; using op/arg is very generic
> for adding extra commands; but it suddenly becomes less generic if
> arg is always a filename.
>
>> +        .params     = "trace|dump [arg]",
>> +        .help       = "trace selected recorders or print recorder dump",
>> +        .cmd        = hmp_recorder,
>> +    },
>> +
>>  SRST
>>  ``trace-file on|off|flush``
>>    Open, close, or flush the trace file.  If no argument is given, the
>
> I think this SRST chunk is the one that needs updating for recorder.
> (The diff has made a bit of a mess, but I think you've copy pasted the
> trace-file chunk, but forgotten to update the SRST section).

Indeed. I had forgotten to get back to the .hx file and add the documentation.

>
>> @@ -1120,7 +1136,7 @@ ERST
>>
>>  SRST
>>  ``dump-guest-memory [-p]`` *filename* *begin* *length*
>> -  \
>> +  \
>>  ``dump-guest-memory [-z|-l|-s|-w]`` *filename*
>>    Dump guest memory to *protocol*. The file can be processed with crash or
>>    gdb. Without ``-z|-l|-s|-w``, the dump format is ELF.
>> @@ -1828,4 +1844,3 @@ ERST
>>          .sub_table  = hmp_info_cmds,
>>          .flags      = "p",
>>      },
>> -
>> diff --git a/monitor/misc.c b/monitor/misc.c
>> index 89bb970b00..0094b1860f 100644
>> --- a/monitor/misc.c
>> +++ b/monitor/misc.c
>> @@ -61,6 +61,9 @@
>>  #ifdef CONFIG_TRACE_SIMPLE
>>  #include "trace/simple.h"
>>  #endif
>> +#ifdef CONFIG_TRACE_RECORDER
>> +#include "trace/recorder.h"
>> +#endif
>>  #include "exec/memory.h"
>>  #include "exec/exec-all.h"
>>  #include "qemu/option.h"
>> @@ -227,6 +230,30 @@ static void hmp_trace_file(Monitor *mon, const QDict *qdict)
>>  }
>>  #endif
>>
>> +#ifdef CONFIG_TRACE_RECORDER
>> +static void hmp_recorder(Monitor *mon, const QDict *qdict)
>> +{
>> +    const char *op = qdict_get_try_str(qdict, "op");
>> +    const char *arg = qdict_get_try_str(qdict, "arg");
>> +
>> +    if (!op) {
>> +        monitor_printf(mon, "missing recorder command\"%s\"\n", op);
>> +        help_cmd(mon, "recorder");
>> +    } else if (!strcmp(op, "trace")) {
>> +        recorder_trace_set(arg);
>> +    } else if (!strcmp(op, "dump")) {
>> +        if (!arg || !*arg) {
>> +            recorder_dump();
>> +        } else {
>> +            recorder_dump_for(arg);
>> +        }
>> +    } else {
>> +        monitor_printf(mon, "unexpected recorder command \"%s\"\n", op);
>> +        help_cmd(mon, "recorder");
>> +    }
>> +}
>
> Consider whether just doing two separate commands would be easier;
> a recorder-trace and recorder-dump for example; that's fine from a HMP
> point of view and I think you'll find it's less code.

Hmmm. Looking back at the code, I see that I should also probably name the
commands something beginning with trace. Maybe trace-record and trace-dump?


>
> Dave
>
>> +#endif
>> +
>>  static void hmp_info_help(Monitor *mon, const QDict *qdict)
>>  {
>>      help_cmd(mon, "info");
>> diff --git a/scripts/tracetool/backend/recorder.py b/scripts/tracetool/backend/recorder.py
>> new file mode 100644
>> index 0000000000..79cc6f5b03
>> --- /dev/null
>> +++ b/scripts/tracetool/backend/recorder.py
>> @@ -0,0 +1,51 @@
>> +# -*- coding: utf-8 -*-
>> +
>> +"""
>> +Trace back-end for recorder library
>> +"""
>> +
>> +__author__     = "Christophe de Dinechin <christophe@dinechin.org>"
>> +__copyright__  = "Copyright 2020, Christophe de Dinechin and Red Hat"
>> +__license__    = "GPL version 2 or (at your option) any later version"
>> +
>> +__maintainer__ = "Christophe de Dinechin"
>> +__email__      = "christophe@dinechin.org"
>> +
>> +
>> +from tracetool import out
>> +
>> +PUBLIC = True
>> +
>> +def generate_h_begin(events, group):
>> +    out('#include <recorder/recorder.h>', '')
>> +
>> +    for event in events:
>> +        out('RECORDER_DECLARE(%(name)s);', name=event.name)
>> +
>> +
>> +def generate_h(event, group):
>> +    argnames = ", ".join(event.args.names())
>> +    if len(event.args) > 0:
>> +        argnames = ", " + argnames
>> +
>> +    out('    record(%(event)s, %(fmt)s %(argnames)s);',
>> +        event=event.name,
>> +        fmt=event.fmt.rstrip("\n"),
>> +        argnames=argnames)
>> +
>> +
>> +def generate_h_backend_dstate(event, group):
>> +    out('    RECORDER_TWEAK(%(event_id)s) || \\', event_id=event.name)
>> +
>> +def generate_c_begin(events, group):
>> +    out('#include "qemu/osdep.h"',
>> +        '#include "trace/control.h"',
>> +        '#include "trace/simple.h"',
>> +        '#include <recorder/recorder.h>',
>> +        '')
>> +
>> +    for event in events:
>> +        out('RECORDER_DEFINE(%(name)s, 8, "Tracetool recorder for %(api)s(%(args)s)");',
>> +            name=event.name,
>> +            api=event.api(),
>> +            args=event.args)
>> diff --git a/trace/Makefile.objs b/trace/Makefile.objs
>> index c544509adf..9e347640c2 100644
>> --- a/trace/Makefile.objs
>> +++ b/trace/Makefile.objs
>> @@ -54,6 +54,8 @@ $(obj)/generated-tcg-tracers.h-timestamp: $(SRC_PATH)/trace-events $(BUILD_DIR)/
>>
>>  util-obj-$(CONFIG_TRACE_SIMPLE) += simple.o
>>  util-obj-$(CONFIG_TRACE_FTRACE) += ftrace.o
>> +util-obj-$(CONFIG_TRACE_RECORDER) += recorder.o
>> +recorder.o-libs = -lrecorder
>>  util-obj-y += control.o
>>  obj-y += control-target.o
>>  util-obj-y += qmp.o
>> diff --git a/trace/control.c b/trace/control.c
>> index 2ffe000818..15e5293eec 100644
>> --- a/trace/control.c
>> +++ b/trace/control.c
>> @@ -23,6 +23,9 @@
>>  #ifdef CONFIG_TRACE_SYSLOG
>>  #include <syslog.h>
>>  #endif
>> +#ifdef CONFIG_TRACE_RECORDER
>> +#include "trace/recorder.h"
>> +#endif
>>  #include "qapi/error.h"
>>  #include "qemu/error-report.h"
>>  #include "qemu/config-file.h"
>> @@ -282,6 +285,10 @@ bool trace_init_backends(void)
>>      openlog(NULL, LOG_PID, LOG_DAEMON);
>>  #endif
>>
>> +#ifdef CONFIG_TRACE_RECORDER
>> +    recorder_trace_init();
>> +#endif
>> +
>>      return true;
>>  }
>>
>> diff --git a/trace/recorder.c b/trace/recorder.c
>> new file mode 100644
>> index 0000000000..cbc22ee2d5
>> --- /dev/null
>> +++ b/trace/recorder.c
>> @@ -0,0 +1,22 @@
>> +/*
>> + * Recorder-based trace backend
>> + *
>> + * Copyright Red Hat 2020
>> + *
>> + * This work is licensed under the terms of the GNU GPL, version 2.  See
>> + * the COPYING file in the top-level directory.
>> + *
>> + */
>> +
>> +#include "trace/recorder.h"
>> +
>> +RECORDER_CONSTRUCTOR
>> +void recorder_trace_init(void)
>> +{
>> +    recorder_trace_set(getenv("RECORDER_TRACES"));
>> +
>> +    // Allow a dump in case we receive some unhandled signal
>> +    // For example, send USR2 to a hung process to get a dump
>> +    if (getenv("RECORDER_TRACES"))
>> +        recorder_dump_on_common_signals(0,0);
>> +}
>> diff --git a/trace/recorder.h b/trace/recorder.h
>> new file mode 100644
>> index 0000000000..00b11a2d2f
>> --- /dev/null
>> +++ b/trace/recorder.h
>> @@ -0,0 +1,34 @@
>> +/*
>> + * Recorder-based trace backend
>> + *
>> + * Copyright Red Hat 2020
>> + *
>> + * This work is licensed under the terms of the GNU GPL, version 2.  See
>> + * the COPYING file in the top-level directory.
>> + *
>> + */
>> +
>> +#ifndef TRACE_RECORDER_H
>> +#define TRACE_RECORDER_H
>> +
>> +#include "qemu/osdep.h"
>> +
>> +#ifdef CONFIG_TRACE_RECORDER
>> +
>> +#include <recorder/recorder.h>
>> +
>> +extern void recorder_trace_init(void);
>> +
>> +#else
>> +
>> +// Disable recorder macros
>> +#define RECORDER(Name, Size, Description)
>> +#define RECORDER_DEFINE(Name, Size, Description)
>> +#define RECORDER_DECLARE(Name)
>> +#define RECORD(Name, ...)
>> +#define record(Name, ...)
>> +#define recorder_trace_init()
>> +
>> +#endif // CONFIG_TRACE_RECORDER
>> +
>> +#endif // TRACE_RECORDER_H
>> diff --git a/util/module.c b/util/module.c
>> index e48d9aacc0..2fa93561fe 100644
>> --- a/util/module.c
>> +++ b/util/module.c
>> @@ -22,6 +22,10 @@
>>  #ifdef CONFIG_MODULE_UPGRADES
>>  #include "qemu-version.h"
>>  #endif
>> +#ifdef CONFIG_TRACE_RECORDER
>> +#include "trace/recorder.h"
>> +#endif
>> +
>>
>>  typedef struct ModuleEntry
>>  {
>> @@ -150,6 +154,10 @@ static int module_load_file(const char *fname)
>>          g_module_close(g_module);
>>          ret = -EINVAL;
>>      } else {
>> +#ifdef CONFIG_TRACE_RECORDER
>> +        // New recorders may have been pulled in, activate them if necessary
>> +        recorder_trace_init();
>> +#endif
>>          QTAILQ_FOREACH(e, &dso_init_list, node) {
>>              e->init();
>>              register_module_init(e->init, e->type);
>> --
>> 2.26.2
>>


--
Cheers,
Christophe de Dinechin (IRC c3d)

Re: [PATCH v2 2/3] trace: Add support for recorder back-end

[Dr. David Alan Gilbert]

* Christophe de Dinechin (dinechin@redhat.com) wrote:
> 
> On 2020-06-30 at 11:05 CEST, Dr. David Alan Gilbert wrote...
> > * Christophe de Dinechin (dinechin@redhat.com) wrote:
> >> The recorder library provides support for low-cost continuous
> >> recording of events, which can then be replayed. This makes it
> >> possible to collect data "after the fact",for example to show the
> >> events that led to a crash.
> >>
> >> Recorder support in qemu is implemented using the existing tracing
> >> interface. In addition, it is possible to individually enable
> >> recorders that are not traces, although this is probably not
> >> recommended.
> >>
> >> HMP COMMAND:
> >> The 'recorder' hmp command has been added, which supports two
> >> sub-commands:
> >> - recorder dump: Dump the current state of the recorder. You can
> >                                                           ^^^^^^^^
> > is that intended?
> 
> No. I think the intent was to indicate that you could pass the name of a
> recorder to dump as an arg. I'll fix.
> 
> >
> >> - recorder trace: Set traces using the recorder_trace_set() syntax.
> >>   You can use "recorder trace help" to list all available recorders.
> >>
> >> Signed-off-by: Christophe de Dinechin <dinechin@redhat.com>
> >> ---
> >>  configure                             |  5 +++
> >>  hmp-commands.hx                       | 19 ++++++++--
> >>  monitor/misc.c                        | 27 ++++++++++++++
> >>  scripts/tracetool/backend/recorder.py | 51 +++++++++++++++++++++++++++
> >>  trace/Makefile.objs                   |  2 ++
> >>  trace/control.c                       |  7 ++++
> >>  trace/recorder.c                      | 22 ++++++++++++
> >>  trace/recorder.h                      | 34 ++++++++++++++++++
> >>  util/module.c                         |  8 +++++
> >>  9 files changed, 173 insertions(+), 2 deletions(-)
> >>  create mode 100644 scripts/tracetool/backend/recorder.py
> >>  create mode 100644 trace/recorder.c
> >>  create mode 100644 trace/recorder.h
> >>
> >> diff --git a/configure b/configure
> >> index ae8737d5a2..130630b98f 100755
> >> --- a/configure
> 
> >> +++ b/configure
> >> @@ -7702,6 +7702,11 @@ fi
> >>  if have_backend "log"; then
> >>    echo "CONFIG_TRACE_LOG=y" >> $config_host_mak
> >>  fi
> >> +if have_backend "recorder"; then
> >> +  echo "CONFIG_TRACE_RECORDER=y" >> $config_host_mak
> >> +  # This is a bit brutal, but there is currently a bug in the makefiles
> >> +  LIBS="$LIBS -lrecorder"
> >> +fi
> >>  if have_backend "ust"; then
> >>    echo "CONFIG_TRACE_UST=y" >> $config_host_mak
> >>  fi
> >> diff --git a/hmp-commands.hx b/hmp-commands.hx
> >> index 60f395c276..565f518d4b 100644
> >> --- a/hmp-commands.hx
> >> +++ b/hmp-commands.hx
> >> @@ -297,6 +297,22 @@ ERST
> >>          .cmd        = hmp_trace_file,
> >>      },
> >>
> >> +SRST
> >> +``trace-file on|off|flush``
> >> +  Open, close, or flush the trace file.  If no argument is given, the
> >> +  status of the trace file is displayed.
> >> +ERST
> >> +#endif
> >> +
> >> +#if defined(CONFIG_TRACE_RECORDER)
> >> +    {
> >> +        .name       = "recorder",
> >> +        .args_type  = "op:s?,arg:F?",
> >
> > Having 'arg' as a filename is a bit odd; using op/arg is very generic
> > for adding extra commands; but it suddenly becomes less generic if
> > arg is always a filename.
> >
> >> +        .params     = "trace|dump [arg]",
> >> +        .help       = "trace selected recorders or print recorder dump",
> >> +        .cmd        = hmp_recorder,
> >> +    },
> >> +
> >>  SRST
> >>  ``trace-file on|off|flush``
> >>    Open, close, or flush the trace file.  If no argument is given, the
> >
> > I think this SRST chunk is the one that needs updating for recorder.
> > (The diff has made a bit of a mess, but I think you've copy pasted the
> > trace-file chunk, but forgotten to update the SRST section).
> 
> Indeed. I had forgotten to get back to the .hx file and add the documentation.
> 
> >
> >> @@ -1120,7 +1136,7 @@ ERST
> >>
> >>  SRST
> >>  ``dump-guest-memory [-p]`` *filename* *begin* *length*
> >> -  \
> >> +  \
> >>  ``dump-guest-memory [-z|-l|-s|-w]`` *filename*
> >>    Dump guest memory to *protocol*. The file can be processed with crash or
> >>    gdb. Without ``-z|-l|-s|-w``, the dump format is ELF.
> >> @@ -1828,4 +1844,3 @@ ERST
> >>          .sub_table  = hmp_info_cmds,
> >>          .flags      = "p",
> >>      },
> >> -
> >> diff --git a/monitor/misc.c b/monitor/misc.c
> >> index 89bb970b00..0094b1860f 100644
> >> --- a/monitor/misc.c
> >> +++ b/monitor/misc.c
> >> @@ -61,6 +61,9 @@
> >>  #ifdef CONFIG_TRACE_SIMPLE
> >>  #include "trace/simple.h"
> >>  #endif
> >> +#ifdef CONFIG_TRACE_RECORDER
> >> +#include "trace/recorder.h"
> >> +#endif
> >>  #include "exec/memory.h"
> >>  #include "exec/exec-all.h"
> >>  #include "qemu/option.h"
> >> @@ -227,6 +230,30 @@ static void hmp_trace_file(Monitor *mon, const QDict *qdict)
> >>  }
> >>  #endif
> >>
> >> +#ifdef CONFIG_TRACE_RECORDER
> >> +static void hmp_recorder(Monitor *mon, const QDict *qdict)
> >> +{
> >> +    const char *op = qdict_get_try_str(qdict, "op");
> >> +    const char *arg = qdict_get_try_str(qdict, "arg");
> >> +
> >> +    if (!op) {
> >> +        monitor_printf(mon, "missing recorder command\"%s\"\n", op);
> >> +        help_cmd(mon, "recorder");
> >> +    } else if (!strcmp(op, "trace")) {
> >> +        recorder_trace_set(arg);
> >> +    } else if (!strcmp(op, "dump")) {
> >> +        if (!arg || !*arg) {
> >> +            recorder_dump();
> >> +        } else {
> >> +            recorder_dump_for(arg);
> >> +        }
> >> +    } else {
> >> +        monitor_printf(mon, "unexpected recorder command \"%s\"\n", op);
> >> +        help_cmd(mon, "recorder");
> >> +    }
> >> +}
> >
> > Consider whether just doing two separate commands would be easier;
> > a recorder-trace and recorder-dump for example; that's fine from a HMP
> > point of view and I think you'll find it's less code.
> 
> Hmmm. Looking back at the code, I see that I should also probably name the
> commands something beginning with trace. Maybe trace-record and trace-dump?

This depends; Stefan: As tracing owner do you have a preference on the
names?  This isn't genering tracing, this is your recorder special, so
I'm not sure.

Dave

> 
> >
> > Dave
> >
> >> +#endif
> >> +
> >>  static void hmp_info_help(Monitor *mon, const QDict *qdict)
> >>  {
> >>      help_cmd(mon, "info");
> >> diff --git a/scripts/tracetool/backend/recorder.py b/scripts/tracetool/backend/recorder.py
> >> new file mode 100644
> >> index 0000000000..79cc6f5b03
> >> --- /dev/null
> >> +++ b/scripts/tracetool/backend/recorder.py
> >> @@ -0,0 +1,51 @@
> >> +# -*- coding: utf-8 -*-
> >> +
> >> +"""
> >> +Trace back-end for recorder library
> >> +"""
> >> +
> >> +__author__     = "Christophe de Dinechin <christophe@dinechin.org>"
> >> +__copyright__  = "Copyright 2020, Christophe de Dinechin and Red Hat"
> >> +__license__    = "GPL version 2 or (at your option) any later version"
> >> +
> >> +__maintainer__ = "Christophe de Dinechin"
> >> +__email__      = "christophe@dinechin.org"
> >> +
> >> +
> >> +from tracetool import out
> >> +
> >> +PUBLIC = True
> >> +
> >> +def generate_h_begin(events, group):
> >> +    out('#include <recorder/recorder.h>', '')
> >> +
> >> +    for event in events:
> >> +        out('RECORDER_DECLARE(%(name)s);', name=event.name)
> >> +
> >> +
> >> +def generate_h(event, group):
> >> +    argnames = ", ".join(event.args.names())
> >> +    if len(event.args) > 0:
> >> +        argnames = ", " + argnames
> >> +
> >> +    out('    record(%(event)s, %(fmt)s %(argnames)s);',
> >> +        event=event.name,
> >> +        fmt=event.fmt.rstrip("\n"),
> >> +        argnames=argnames)
> >> +
> >> +
> >> +def generate_h_backend_dstate(event, group):
> >> +    out('    RECORDER_TWEAK(%(event_id)s) || \\', event_id=event.name)
> >> +
> >> +def generate_c_begin(events, group):
> >> +    out('#include "qemu/osdep.h"',
> >> +        '#include "trace/control.h"',
> >> +        '#include "trace/simple.h"',
> >> +        '#include <recorder/recorder.h>',
> >> +        '')
> >> +
> >> +    for event in events:
> >> +        out('RECORDER_DEFINE(%(name)s, 8, "Tracetool recorder for %(api)s(%(args)s)");',
> >> +            name=event.name,
> >> +            api=event.api(),
> >> +            args=event.args)
> >> diff --git a/trace/Makefile.objs b/trace/Makefile.objs
> >> index c544509adf..9e347640c2 100644
> >> --- a/trace/Makefile.objs
> >> +++ b/trace/Makefile.objs
> >> @@ -54,6 +54,8 @@ $(obj)/generated-tcg-tracers.h-timestamp: $(SRC_PATH)/trace-events $(BUILD_DIR)/
> >>
> >>  util-obj-$(CONFIG_TRACE_SIMPLE) += simple.o
> >>  util-obj-$(CONFIG_TRACE_FTRACE) += ftrace.o
> >> +util-obj-$(CONFIG_TRACE_RECORDER) += recorder.o
> >> +recorder.o-libs = -lrecorder
> >>  util-obj-y += control.o
> >>  obj-y += control-target.o
> >>  util-obj-y += qmp.o
> >> diff --git a/trace/control.c b/trace/control.c
> >> index 2ffe000818..15e5293eec 100644
> >> --- a/trace/control.c
> >> +++ b/trace/control.c
> >> @@ -23,6 +23,9 @@
> >>  #ifdef CONFIG_TRACE_SYSLOG
> >>  #include <syslog.h>
> >>  #endif
> >> +#ifdef CONFIG_TRACE_RECORDER
> >> +#include "trace/recorder.h"
> >> +#endif
> >>  #include "qapi/error.h"
> >>  #include "qemu/error-report.h"
> >>  #include "qemu/config-file.h"
> >> @@ -282,6 +285,10 @@ bool trace_init_backends(void)
> >>      openlog(NULL, LOG_PID, LOG_DAEMON);
> >>  #endif
> >>
> >> +#ifdef CONFIG_TRACE_RECORDER
> >> +    recorder_trace_init();
> >> +#endif
> >> +
> >>      return true;
> >>  }
> >>
> >> diff --git a/trace/recorder.c b/trace/recorder.c
> >> new file mode 100644
> >> index 0000000000..cbc22ee2d5
> >> --- /dev/null
> >> +++ b/trace/recorder.c
> >> @@ -0,0 +1,22 @@
> >> +/*
> >> + * Recorder-based trace backend
> >> + *
> >> + * Copyright Red Hat 2020
> >> + *
> >> + * This work is licensed under the terms of the GNU GPL, version 2.  See
> >> + * the COPYING file in the top-level directory.
> >> + *
> >> + */
> >> +
> >> +#include "trace/recorder.h"
> >> +
> >> +RECORDER_CONSTRUCTOR
> >> +void recorder_trace_init(void)
> >> +{
> >> +    recorder_trace_set(getenv("RECORDER_TRACES"));
> >> +
> >> +    // Allow a dump in case we receive some unhandled signal
> >> +    // For example, send USR2 to a hung process to get a dump
> >> +    if (getenv("RECORDER_TRACES"))
> >> +        recorder_dump_on_common_signals(0,0);
> >> +}
> >> diff --git a/trace/recorder.h b/trace/recorder.h
> >> new file mode 100644
> >> index 0000000000..00b11a2d2f
> >> --- /dev/null
> >> +++ b/trace/recorder.h
> >> @@ -0,0 +1,34 @@
> >> +/*
> >> + * Recorder-based trace backend
> >> + *
> >> + * Copyright Red Hat 2020
> >> + *
> >> + * This work is licensed under the terms of the GNU GPL, version 2.  See
> >> + * the COPYING file in the top-level directory.
> >> + *
> >> + */
> >> +
> >> +#ifndef TRACE_RECORDER_H
> >> +#define TRACE_RECORDER_H
> >> +
> >> +#include "qemu/osdep.h"
> >> +
> >> +#ifdef CONFIG_TRACE_RECORDER
> >> +
> >> +#include <recorder/recorder.h>
> >> +
> >> +extern void recorder_trace_init(void);
> >> +
> >> +#else
> >> +
> >> +// Disable recorder macros
> >> +#define RECORDER(Name, Size, Description)
> >> +#define RECORDER_DEFINE(Name, Size, Description)
> >> +#define RECORDER_DECLARE(Name)
> >> +#define RECORD(Name, ...)
> >> +#define record(Name, ...)
> >> +#define recorder_trace_init()
> >> +
> >> +#endif // CONFIG_TRACE_RECORDER
> >> +
> >> +#endif // TRACE_RECORDER_H
> >> diff --git a/util/module.c b/util/module.c
> >> index e48d9aacc0..2fa93561fe 100644
> >> --- a/util/module.c
> >> +++ b/util/module.c
> >> @@ -22,6 +22,10 @@
> >>  #ifdef CONFIG_MODULE_UPGRADES
> >>  #include "qemu-version.h"
> >>  #endif
> >> +#ifdef CONFIG_TRACE_RECORDER
> >> +#include "trace/recorder.h"
> >> +#endif
> >> +
> >>
> >>  typedef struct ModuleEntry
> >>  {
> >> @@ -150,6 +154,10 @@ static int module_load_file(const char *fname)
> >>          g_module_close(g_module);
> >>          ret = -EINVAL;
> >>      } else {
> >> +#ifdef CONFIG_TRACE_RECORDER
> >> +        // New recorders may have been pulled in, activate them if necessary
> >> +        recorder_trace_init();
> >> +#endif
> >>          QTAILQ_FOREACH(e, &dso_init_list, node) {
> >>              e->init();
> >>              register_module_init(e->init, e->type);
> >> --
> >> 2.26.2
> >>
> 
> 
> --
> Cheers,
> Christophe de Dinechin (IRC c3d)
--
Dr. David Alan Gilbert / dgilbert@redhat.com / Manchester, UK

Re: [PATCH v2 2/3] trace: Add support for recorder back-end

[Stefan Hajnoczi]

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

On Fri, Jun 26, 2020 at 06:27:05PM +0200, Christophe de Dinechin wrote:

Please run scripts/checkpatch.pl if you haven't already.

> diff --git a/configure b/configure
> index ae8737d5a2..130630b98f 100755
> --- a/configure
> +++ b/configure
> @@ -7702,6 +7702,11 @@ fi
>  if have_backend "log"; then
>    echo "CONFIG_TRACE_LOG=y" >> $config_host_mak
>  fi
> +if have_backend "recorder"; then
> +  echo "CONFIG_TRACE_RECORDER=y" >> $config_host_mak
> +  # This is a bit brutal, but there is currently a bug in the makefiles
> +  LIBS="$LIBS -lrecorder"

Outdated? Patch 1 was supposed to fix this.

> diff --git a/hmp-commands.hx b/hmp-commands.hx
> index 60f395c276..565f518d4b 100644
> --- a/hmp-commands.hx
> +++ b/hmp-commands.hx
> @@ -297,6 +297,22 @@ ERST
>          .cmd        = hmp_trace_file,
>      },
>  
> +SRST
> +``trace-file on|off|flush``
> +  Open, close, or flush the trace file.  If no argument is given, the
> +  status of the trace file is displayed.
> +ERST
> +#endif
> +
> +#if defined(CONFIG_TRACE_RECORDER)
> +    {
> +        .name       = "recorder",
> +        .args_type  = "op:s?,arg:F?",
> +        .params     = "trace|dump [arg]",
> +        .help       = "trace selected recorders or print recorder dump",
> +        .cmd        = hmp_recorder,
> +    },
> +
>  SRST
>  ``trace-file on|off|flush``
>    Open, close, or flush the trace file.  If no argument is given, the

This is the same trace-file command documentation that was added above.
Should this be the documentation for the recorder command?

> @@ -1120,7 +1136,7 @@ ERST
>  
>  SRST
>  ``dump-guest-memory [-p]`` *filename* *begin* *length*
> -  \ 
> +  \
>  ``dump-guest-memory [-z|-l|-s|-w]`` *filename*
>    Dump guest memory to *protocol*. The file can be processed with crash or
>    gdb. Without ``-z|-l|-s|-w``, the dump format is ELF.

Spurious change. Please drop.

> @@ -1828,4 +1844,3 @@ ERST
>          .sub_table  = hmp_info_cmds,
>          .flags      = "p",
>      },
> -

Spurious change. Please drop.

> diff --git a/monitor/misc.c b/monitor/misc.c
> index 89bb970b00..0094b1860f 100644
> --- a/monitor/misc.c
> +++ b/monitor/misc.c
> @@ -61,6 +61,9 @@
>  #ifdef CONFIG_TRACE_SIMPLE
>  #include "trace/simple.h"
>  #endif
> +#ifdef CONFIG_TRACE_RECORDER
> +#include "trace/recorder.h"
> +#endif
>  #include "exec/memory.h"
>  #include "exec/exec-all.h"
>  #include "qemu/option.h"
> @@ -227,6 +230,30 @@ static void hmp_trace_file(Monitor *mon, const QDict *qdict)
>  }
>  #endif
>  
> +#ifdef CONFIG_TRACE_RECORDER
> +static void hmp_recorder(Monitor *mon, const QDict *qdict)
> +{
> +    const char *op = qdict_get_try_str(qdict, "op");
> +    const char *arg = qdict_get_try_str(qdict, "arg");
> +
> +    if (!op) {
> +        monitor_printf(mon, "missing recorder command\"%s\"\n", op);

op is NULL, why print it?

> diff --git a/trace/recorder.c b/trace/recorder.c
> new file mode 100644
> index 0000000000..cbc22ee2d5
> --- /dev/null
> +++ b/trace/recorder.c
> @@ -0,0 +1,22 @@
> +/*
> + * Recorder-based trace backend
> + *
> + * Copyright Red Hat 2020
> + *
> + * This work is licensed under the terms of the GNU GPL, version 2.  See
> + * the COPYING file in the top-level directory.
> + *
> + */
> +
> +#include "trace/recorder.h"
> +
> +RECORDER_CONSTRUCTOR
> +void recorder_trace_init(void)
> +{
> +    recorder_trace_set(getenv("RECORDER_TRACES"));
> +
> +    // Allow a dump in case we receive some unhandled signal
> +    // For example, send USR2 to a hung process to get a dump

CODING_STYLE.rst says:

  We use traditional C-style /``*`` ``*``/ comments and avoid //
  comments.

There are other instances in this patch series that I haven't pointed
out.

> +    if (getenv("RECORDER_TRACES"))
> +        recorder_dump_on_common_signals(0,0);

CODING_STYLE.rst says:

  We use traditional C-style /``*`` ``*``/ comments and avoid //
  comments.

> +}
> diff --git a/trace/recorder.h b/trace/recorder.h
> new file mode 100644
> index 0000000000..00b11a2d2f
> --- /dev/null
> +++ b/trace/recorder.h
> @@ -0,0 +1,34 @@
> +/*
> + * Recorder-based trace backend
> + *
> + * Copyright Red Hat 2020
> + *
> + * This work is licensed under the terms of the GNU GPL, version 2.  See
> + * the COPYING file in the top-level directory.
> + *
> + */
> +
> +#ifndef TRACE_RECORDER_H
> +#define TRACE_RECORDER_H
> +
> +#include "qemu/osdep.h"

CODING_STYLE.rst says:

  Do not include "qemu/osdep.h" from header files since the .c file will
  have already included it.

Please either follow that or document the reason for the exception.

> +
> +#ifdef CONFIG_TRACE_RECORDER

Files including trace/recorder.h do this:

  #ifdef CONFIG_TRACE_RECORDER
  #include "trace/recorder.h"
  #endif

Either CONFIG_TRACE_RECORDER should be checked before including the
header or inside the header, but doing both is confusing.

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

Re: [PATCH v2 2/3] trace: Add support for recorder back-end

[Daniel P. Berrangé]

On Fri, Jun 26, 2020 at 06:27:05PM +0200, Christophe de Dinechin wrote:
> The recorder library provides support for low-cost continuous
> recording of events, which can then be replayed. This makes it
> possible to collect data "after the fact",for example to show the
> events that led to a crash.
> 
> Recorder support in qemu is implemented using the existing tracing
> interface. In addition, it is possible to individually enable
> recorders that are not traces, although this is probably not
> recommended.
> 
> HMP COMMAND:
> The 'recorder' hmp command has been added, which supports two
> sub-commands:
> - recorder dump: Dump the current state of the recorder. You can
> - recorder trace: Set traces using the recorder_trace_set() syntax.
>   You can use "recorder trace help" to list all available recorders.
> 
> Signed-off-by: Christophe de Dinechin <dinechin@redhat.com>
> ---
>  configure                             |  5 +++
>  hmp-commands.hx                       | 19 ++++++++--
>  monitor/misc.c                        | 27 ++++++++++++++
>  scripts/tracetool/backend/recorder.py | 51 +++++++++++++++++++++++++++
>  trace/Makefile.objs                   |  2 ++
>  trace/control.c                       |  7 ++++
>  trace/recorder.c                      | 22 ++++++++++++
>  trace/recorder.h                      | 34 ++++++++++++++++++
>  util/module.c                         |  8 +++++
>  9 files changed, 173 insertions(+), 2 deletions(-)
>  create mode 100644 scripts/tracetool/backend/recorder.py
>  create mode 100644 trace/recorder.c
>  create mode 100644 trace/recorder.h

> +RECORDER_CONSTRUCTOR
> +void recorder_trace_init(void)
> +{
> +    recorder_trace_set(getenv("RECORDER_TRACES"));
> +
> +    // Allow a dump in case we receive some unhandled signal
> +    // For example, send USR2 to a hung process to get a dump
> +    if (getenv("RECORDER_TRACES"))
> +        recorder_dump_on_common_signals(0,0);
> +}

What is the syntax of this RECORDER_TRACES env variable, and perhaps
more importantly should we have this modelled as a command line arg
instead of an env variable. We've generally been aiming to get rid
of env variables and have QAPI modelled CLI. QAPI modelling would be
particularly important if we want to expose the ablity to change
settings on the fly via QMP.


> diff --git a/trace/recorder.h b/trace/recorder.h
> new file mode 100644
> index 0000000000..00b11a2d2f
> --- /dev/null
> +++ b/trace/recorder.h
> @@ -0,0 +1,34 @@
> +/*
> + * Recorder-based trace backend
> + *
> + * Copyright Red Hat 2020
> + *
> + * This work is licensed under the terms of the GNU GPL, version 2.  See
> + * the COPYING file in the top-level directory.

Why "version 2" (only), instead of "version 2 or later" ? QEMU generally
expects the latter for any new code, unless it is derived from existing
v2-only code in QEMU.

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: [PATCH v2 2/3] trace: Add support for recorder back-end

[Christophe de Dinechin]

On 2020-06-30 at 15:02 CEST, Daniel P. Berrangé wrote...
> On Fri, Jun 26, 2020 at 06:27:05PM +0200, Christophe de Dinechin wrote:
>> The recorder library provides support for low-cost continuous
>> recording of events, which can then be replayed. This makes it
>> possible to collect data "after the fact",for example to show the
>> events that led to a crash.
>>
>> Recorder support in qemu is implemented using the existing tracing
>> interface. In addition, it is possible to individually enable
>> recorders that are not traces, although this is probably not
>> recommended.
>>
>> HMP COMMAND:
>> The 'recorder' hmp command has been added, which supports two
>> sub-commands:
>> - recorder dump: Dump the current state of the recorder. You can
>> - recorder trace: Set traces using the recorder_trace_set() syntax.
>>   You can use "recorder trace help" to list all available recorders.
>>
>> Signed-off-by: Christophe de Dinechin <dinechin@redhat.com>
>> ---
>>  configure                             |  5 +++
>>  hmp-commands.hx                       | 19 ++++++++--
>>  monitor/misc.c                        | 27 ++++++++++++++
>>  scripts/tracetool/backend/recorder.py | 51 +++++++++++++++++++++++++++
>>  trace/Makefile.objs                   |  2 ++
>>  trace/control.c                       |  7 ++++
>>  trace/recorder.c                      | 22 ++++++++++++
>>  trace/recorder.h                      | 34 ++++++++++++++++++
>>  util/module.c                         |  8 +++++
>>  9 files changed, 173 insertions(+), 2 deletions(-)
>>  create mode 100644 scripts/tracetool/backend/recorder.py
>>  create mode 100644 trace/recorder.c
>>  create mode 100644 trace/recorder.h
>
>> +RECORDER_CONSTRUCTOR
>> +void recorder_trace_init(void)
>> +{
>> +    recorder_trace_set(getenv("RECORDER_TRACES"));
>> +
>> +    // Allow a dump in case we receive some unhandled signal
>> +    // For example, send USR2 to a hung process to get a dump
>> +    if (getenv("RECORDER_TRACES"))
>> +        recorder_dump_on_common_signals(0,0);
>> +}
>
> What is the syntax of this RECORDER_TRACES env variable,

It's basically a colon-separated list of regexps,
e.g. ".*_error:.*_warning", with special syntax for some additional
functionality such as real-time graphing.

Here are a few examples:

- Activate the foo, bar and baz traces:
      foo:bar:baz

- Activate all traces that contain "lock", as well as "recorder" trace:
      *lock.*:recorder

- Deactivate traces ending in _error
      .*_error=0

There are also a few tweaks and special names, for example you can adjust
the output to show the function name and source code location as follows::

- Show source information in the traces
      recorder_function:recorder_location

  As is not very useful in qemu because it sohws the wrapper location:
     % RECORDER_TRACES=vm_state_notify qemu-system-x86_64
     [35225 7.092175] vm_state_notify: running 1 reason 9 (running)

     % RECORDER_TRACES=vm_state_notify:recorder_function:recorder_location qemu-system-x86_64
     /home/ddd/Work/qemu/trace-root.h:346:_nocheck__trace_vm_state_notify:[94277 0.294906] vm_state_notify: running 1 reason 9 (running)

  This is not as good as what you get with "real" record entries:
     % RECORDER_TRACES=recorder_function:recorder_location:recorder qemu-system-x86_64
     recorder.c:2036:recorder_allocate_alt_stack:[29561 0.006434] recorder: Set alt stack to 0x7fc567b87000 size 8192

- Get some help on available traces:
      help

- Enable real-time graphing for trace "perfdata"
      perfdata=bytes,loops

The last one assumes that you would have a record that looks like:

     record(perfdata, "Transferred %lu bytes in %lu iterations",
            bytes, itercount);

You could then have a real-time graph of the values for variables "bytes"
and "itercount" using the recorder_scope program, and using the names you
gave to the channels in your RECORDER_TRACES variable, i.e. bytes and loops:

     recorder_scope bytes loops

See man recorder_trace_set(3), recorder_scope(1) or
https://github.com/c3d/recorder#recorder-tracing for more information.


> and perhaps more importantly should we have this modelled as a command
> line arg instead of an env variable. We've generally been aiming to get
> rid of env variables and have QAPI modelled CLI. QAPI modelling would be
> particularly important if we want to expose the ablity to change settings
> on the fly via QMP.

The rationale for the recorder using an environment variable is that it was
initially designed to be able to trace libraries, notably SPICE or the
recorder library itself. A single environment variable can be used to
activate traces in the main binary as well as in the libraries.

I'm certainly not against adding a command-line option to activate recorder
options specifically, but as I understand, the option -trace already exists,
and its semantics is sufficiently different from the one in recorder
patterns that I decided to not connect the two for now. For example, to
disable trace foo, you'd pass "-foo" to the -trace option, but "foo=0" to
RECORDER_TRACES. The parsing of graphing options and other related
recorder-specific stuff is a bit difficult to integrate with -trace too.

>
>
>> diff --git a/trace/recorder.h b/trace/recorder.h
>> new file mode 100644
>> index 0000000000..00b11a2d2f
>> --- /dev/null
>> +++ b/trace/recorder.h
>> @@ -0,0 +1,34 @@
>> +/*
>> + * Recorder-based trace backend
>> + *
>> + * Copyright Red Hat 2020
>> + *
>> + * This work is licensed under the terms of the GNU GPL, version 2.  See
>> + * the COPYING file in the top-level directory.
>
> Why "version 2" (only), instead of "version 2 or later" ? QEMU generally
> expects the latter for any new code, unless it is derived from existing
> v2-only code in QEMU.

Good catch. I copied that straight from trace/simple.h. No problem changing
it as you suggest. I don't think that whatever inspiration I took from the
existing trace code is sufficient to stick to 2-only.

>
> Regards,
> Daniel


--
Cheers,
Christophe de Dinechin (IRC c3d)

Re: [PATCH v2 2/3] trace: Add support for recorder back-end

[Markus Armbruster]

Christophe de Dinechin <dinechin@redhat.com> writes:

> On 2020-06-30 at 15:02 CEST, Daniel P. Berrangé wrote...
>> On Fri, Jun 26, 2020 at 06:27:05PM +0200, Christophe de Dinechin wrote:
>>> The recorder library provides support for low-cost continuous
>>> recording of events, which can then be replayed. This makes it
>>> possible to collect data "after the fact",for example to show the
>>> events that led to a crash.
>>>
>>> Recorder support in qemu is implemented using the existing tracing
>>> interface. In addition, it is possible to individually enable
>>> recorders that are not traces, although this is probably not
>>> recommended.
>>>
>>> HMP COMMAND:
>>> The 'recorder' hmp command has been added, which supports two
>>> sub-commands:
>>> - recorder dump: Dump the current state of the recorder. You can
>>> - recorder trace: Set traces using the recorder_trace_set() syntax.
>>>   You can use "recorder trace help" to list all available recorders.
>>>
>>> Signed-off-by: Christophe de Dinechin <dinechin@redhat.com>
>>> ---
>>>  configure                             |  5 +++
>>>  hmp-commands.hx                       | 19 ++++++++--
>>>  monitor/misc.c                        | 27 ++++++++++++++
>>>  scripts/tracetool/backend/recorder.py | 51 +++++++++++++++++++++++++++
>>>  trace/Makefile.objs                   |  2 ++
>>>  trace/control.c                       |  7 ++++
>>>  trace/recorder.c                      | 22 ++++++++++++
>>>  trace/recorder.h                      | 34 ++++++++++++++++++
>>>  util/module.c                         |  8 +++++
>>>  9 files changed, 173 insertions(+), 2 deletions(-)
>>>  create mode 100644 scripts/tracetool/backend/recorder.py
>>>  create mode 100644 trace/recorder.c
>>>  create mode 100644 trace/recorder.h
>>
>>> +RECORDER_CONSTRUCTOR
>>> +void recorder_trace_init(void)
>>> +{
>>> +    recorder_trace_set(getenv("RECORDER_TRACES"));
>>> +
>>> +    // Allow a dump in case we receive some unhandled signal
>>> +    // For example, send USR2 to a hung process to get a dump
>>> +    if (getenv("RECORDER_TRACES"))
>>> +        recorder_dump_on_common_signals(0,0);
>>> +}
>>
>> What is the syntax of this RECORDER_TRACES env variable,
>
> It's basically a colon-separated list of regexps,
> e.g. ".*_error:.*_warning", with special syntax for some additional
> functionality such as real-time graphing.
>
> Here are a few examples:
>
> - Activate the foo, bar and baz traces:
>       foo:bar:baz
>
> - Activate all traces that contain "lock", as well as "recorder" trace:
>       *lock.*:recorder
>
> - Deactivate traces ending in _error
>       .*_error=0
>
> There are also a few tweaks and special names, for example you can adjust
> the output to show the function name and source code location as follows::
>
> - Show source information in the traces
>       recorder_function:recorder_location
>
>   As is not very useful in qemu because it sohws the wrapper location:
>      % RECORDER_TRACES=vm_state_notify qemu-system-x86_64
>      [35225 7.092175] vm_state_notify: running 1 reason 9 (running)
>
>      % RECORDER_TRACES=vm_state_notify:recorder_function:recorder_location qemu-system-x86_64
>      /home/ddd/Work/qemu/trace-root.h:346:_nocheck__trace_vm_state_notify:[94277 0.294906] vm_state_notify: running 1 reason 9 (running)
>
>   This is not as good as what you get with "real" record entries:
>      % RECORDER_TRACES=recorder_function:recorder_location:recorder qemu-system-x86_64
>      recorder.c:2036:recorder_allocate_alt_stack:[29561 0.006434] recorder: Set alt stack to 0x7fc567b87000 size 8192
>
> - Get some help on available traces:
>       help
>
> - Enable real-time graphing for trace "perfdata"
>       perfdata=bytes,loops
>
> The last one assumes that you would have a record that looks like:
>
>      record(perfdata, "Transferred %lu bytes in %lu iterations",
>             bytes, itercount);
>
> You could then have a real-time graph of the values for variables "bytes"
> and "itercount" using the recorder_scope program, and using the names you
> gave to the channels in your RECORDER_TRACES variable, i.e. bytes and loops:
>
>      recorder_scope bytes loops
>
> See man recorder_trace_set(3), recorder_scope(1) or
> https://github.com/c3d/recorder#recorder-tracing for more information.
>
>
>> and perhaps more importantly should we have this modelled as a command
>> line arg instead of an env variable. We've generally been aiming to get
>> rid of env variables and have QAPI modelled CLI. QAPI modelling would be
>> particularly important if we want to expose the ablity to change settings
>> on the fly via QMP.
>
> The rationale for the recorder using an environment variable is that it was
> initially designed to be able to trace libraries, notably SPICE or the
> recorder library itself. A single environment variable can be used to
> activate traces in the main binary as well as in the libraries.

Makes sense.

> I'm certainly not against adding a command-line option to activate recorder
> options specifically, but as I understand, the option -trace already exists,
> and its semantics is sufficiently different from the one in recorder
> patterns that I decided to not connect the two for now. For example, to
> disable trace foo, you'd pass "-foo" to the -trace option, but "foo=0" to
> RECORDER_TRACES. The parsing of graphing options and other related
> recorder-specific stuff is a bit difficult to integrate with -trace too.

We need proper integration with the existing trace UI.

In particular, the ability to enable and disable trace events
dynamically provided by QMP commands trace-event-get-state,
trace-event-set-state, and HMP command trace-event is really useful.

Integration need not mean implement the existing interface slavishly!
Feel free to evolve it.  For instance, the QMP commands provide
"case-sensitive glob", while you have full regexps.  You could extend
the commands to also accept regexps.

We can talk about leaving gaps for later.

I recommend to start with QMP.

[...]

Re: [PATCH v2 2/3] trace: Add support for recorder back-end

[Christophe de Dinechin]

On 2020-07-23 at 16:06 CEST, Markus Armbruster wrote...
> Christophe de Dinechin <dinechin@redhat.com> writes:
>
>> On 2020-06-30 at 15:02 CEST, Daniel P. Berrangé wrote...
>>> On Fri, Jun 26, 2020 at 06:27:05PM +0200, Christophe de Dinechin wrote:
>>>> The recorder library provides support for low-cost continuous
>>>> recording of events, which can then be replayed. This makes it
>>>> possible to collect data "after the fact",for example to show the
>>>> events that led to a crash.
>>>>
>>>> Recorder support in qemu is implemented using the existing tracing
>>>> interface. In addition, it is possible to individually enable
>>>> recorders that are not traces, although this is probably not
>>>> recommended.
>>>>
>>>> HMP COMMAND:
>>>> The 'recorder' hmp command has been added, which supports two
>>>> sub-commands:
>>>> - recorder dump: Dump the current state of the recorder. You can
>>>> - recorder trace: Set traces using the recorder_trace_set() syntax.
>>>>   You can use "recorder trace help" to list all available recorders.
>>>>
>>>> Signed-off-by: Christophe de Dinechin <dinechin@redhat.com>
>>>> ---
>>>>  configure                             |  5 +++
>>>>  hmp-commands.hx                       | 19 ++++++++--
>>>>  monitor/misc.c                        | 27 ++++++++++++++
>>>>  scripts/tracetool/backend/recorder.py | 51 +++++++++++++++++++++++++++
>>>>  trace/Makefile.objs                   |  2 ++
>>>>  trace/control.c                       |  7 ++++
>>>>  trace/recorder.c                      | 22 ++++++++++++
>>>>  trace/recorder.h                      | 34 ++++++++++++++++++
>>>>  util/module.c                         |  8 +++++
>>>>  9 files changed, 173 insertions(+), 2 deletions(-)
>>>>  create mode 100644 scripts/tracetool/backend/recorder.py
>>>>  create mode 100644 trace/recorder.c
>>>>  create mode 100644 trace/recorder.h
>>>
>>>> +RECORDER_CONSTRUCTOR
>>>> +void recorder_trace_init(void)
>>>> +{
>>>> +    recorder_trace_set(getenv("RECORDER_TRACES"));
>>>> +
>>>> +    // Allow a dump in case we receive some unhandled signal
>>>> +    // For example, send USR2 to a hung process to get a dump
>>>> +    if (getenv("RECORDER_TRACES"))
>>>> +        recorder_dump_on_common_signals(0,0);
>>>> +}
>>>
>>> What is the syntax of this RECORDER_TRACES env variable,
>>
>> It's basically a colon-separated list of regexps,
>> e.g. ".*_error:.*_warning", with special syntax for some additional
>> functionality such as real-time graphing.
>>
>> Here are a few examples:
>>
>> - Activate the foo, bar and baz traces:
>>       foo:bar:baz
>>
>> - Activate all traces that contain "lock", as well as "recorder" trace:
>>       *lock.*:recorder
>>
>> - Deactivate traces ending in _error
>>       .*_error=0
>>
>> There are also a few tweaks and special names, for example you can adjust
>> the output to show the function name and source code location as follows::
>>
>> - Show source information in the traces
>>       recorder_function:recorder_location
>>
>>   As is not very useful in qemu because it sohws the wrapper location:
>>      % RECORDER_TRACES=vm_state_notify qemu-system-x86_64
>>      [35225 7.092175] vm_state_notify: running 1 reason 9 (running)
>>
>>      % RECORDER_TRACES=vm_state_notify:recorder_function:recorder_location qemu-system-x86_64
>>      /home/ddd/Work/qemu/trace-root.h:346:_nocheck__trace_vm_state_notify:[94277 0.294906] vm_state_notify: running 1 reason 9 (running)
>>
>>   This is not as good as what you get with "real" record entries:
>>      % RECORDER_TRACES=recorder_function:recorder_location:recorder qemu-system-x86_64
>>      recorder.c:2036:recorder_allocate_alt_stack:[29561 0.006434] recorder: Set alt stack to 0x7fc567b87000 size 8192
>>
>> - Get some help on available traces:
>>       help
>>
>> - Enable real-time graphing for trace "perfdata"
>>       perfdata=bytes,loops
>>
>> The last one assumes that you would have a record that looks like:
>>
>>      record(perfdata, "Transferred %lu bytes in %lu iterations",
>>             bytes, itercount);
>>
>> You could then have a real-time graph of the values for variables "bytes"
>> and "itercount" using the recorder_scope program, and using the names you
>> gave to the channels in your RECORDER_TRACES variable, i.e. bytes and loops:
>>
>>      recorder_scope bytes loops
>>
>> See man recorder_trace_set(3), recorder_scope(1) or
>> https://github.com/c3d/recorder#recorder-tracing for more information.
>>
>>
>>> and perhaps more importantly should we have this modelled as a command
>>> line arg instead of an env variable. We've generally been aiming to get
>>> rid of env variables and have QAPI modelled CLI. QAPI modelling would be
>>> particularly important if we want to expose the ablity to change settings
>>> on the fly via QMP.
>>
>> The rationale for the recorder using an environment variable is that it was
>> initially designed to be able to trace libraries, notably SPICE or the
>> recorder library itself. A single environment variable can be used to
>> activate traces in the main binary as well as in the libraries.
>
> Makes sense.
>
>> I'm certainly not against adding a command-line option to activate recorder
>> options specifically, but as I understand, the option -trace already exists,
>> and its semantics is sufficiently different from the one in recorder
>> patterns that I decided to not connect the two for now. For example, to
>> disable trace foo, you'd pass "-foo" to the -trace option, but "foo=0" to
>> RECORDER_TRACES. The parsing of graphing options and other related
>> recorder-specific stuff is a bit difficult to integrate with -trace too.
>
> We need proper integration with the existing trace UI.

I agree, but I don't think this belongs to this particular patch series.
See below why.

>
> In particular, the ability to enable and disable trace events
> dynamically provided by QMP commands trace-event-get-state,
> trace-event-set-state, and HMP command trace-event is really useful.

That ability exists, but given the many differences between the
recorder and other tracing mechanisms, I found it useful to add a specific
"recorder" command.

For example, assuming I built with both recorder and log trace backends,
from the monitor, I can type:

  trace-event kvm_run_exit on

What I get then is something like that:

  2091091@1595518935.441273:kvm_run_exit cpu_index 0, reason 2
  2091091@1595518935.441292:kvm_run_exit cpu_index 0, reason 2
  2091091@1595518935.441301:kvm_run_exit cpu_index 0, reason 2
  2091091@1595518935.441309:kvm_run_exit cpu_index 0, reason 2
  2091091@1595518935.441254:kvm_run_exit cpu_index 0, reason 2

It would not be very useful to activate recorder traces as well when that
happens, which would have the undesired side effect of purging any
corresponding entry from a following recorder dump.

There are, however, new monitor commands, so now I can do:

  recorder trace kvm_run_exit

I now get an output where each trace shows up twice.

  [120139718 137.127269] kvm_run_exit: cpu_index 0, reason 2
  2091091@1595518954.209803:kvm_run_exit cpu_index 0, reason 2
  [120139734 137.127281] kvm_run_exit: cpu_index 0, reason 2
  2091091@1595518954.209814:kvm_run_exit cpu_index 0, reason 2
  [120139751 137.127293] kvm_run_exit: cpu_index 0, reason 2

 I don't find particularly useful, so I don't think having that as the
normal behaviour would qualify as what you called proper integration.

Having a separate recorder command, OTOH, allows me to also do things
that are not possible with other trace back-ends, and presumably never will
be, like:

    recorder trace kvm_run_exit=cpu,reason

That configures things so that I can now do real-time graphing using
recorder-scope. The only output from qemu will be:

  Creating new /tmp/recorder_share

But I can now run somewhere else:

   recorder_scope cpu reason

and have a real-time view of what is happening in my qemu. Not particularly
interesting with existing instrumentation, which was not designed for
graphing, but that's easily changed.

Another key feature I get from the new monitor command is

  recorder dump

Now the output will be something like (cut for brevity)

  [150261271 461.814366] lock: Locked state 2 for 0x55d842d66d18
  [150261272 461.814366] qemu_mutex_unlock: released mutex 0x55d842d66d18 (0x55d840d032c0:119)
  [150261273 461.814366] lock: Unkocked state 0 for 0x55d842d66d18
  [150261274 461.814367] lockcnt_fast_path_attempt: lockcnt 0x55d842b630ec fast path 0->4
  [150261275 461.814367] lockcnt_fast_path_success: lockcnt 0x55d842b630ec fast path 0->4 succeeded
  [150261276 461.814515] qemu_mutex_lock: waiting on mutex 0x55d842ded590 (0x55d840c63019:161)
  [150261277 461.814515] lock: Locking state 1 for 0x55d842ded590
  [150261278 461.814515] qemu_mutex_locked: taken mutex 0x55d842ded590 (0x55d840c63019:161)
  [150261279 461.814515] lock: Locked state 2 for 0x55d842ded590
  [150261280 461.814517] object_class_dynamic_cast_assert: 0x55d842dea5e0->0x55d840cdfcc0 (0x55d840cdfcb1:114:0x55d840ce02a0)
  [150261281 461.814518] qemu_mutex_lock: waiting on mutex 0x55d842db27b8 (0x55d840cdfcb1:118)
  [150261282 461.814518] lock: Locking state 1 for 0x55d842db27b8
  [150261283 461.814518] qemu_mutex_locked: taken mutex 0x55d842db27b8 (0x55d840cdfcb1:118)
  [150261284 461.814518] lock: Locked state 2 for 0x55d842db27b8
  [150261285 461.814518] object_dynamic_cast_assert: 0x55d842dea5e0->0x7f7f88f304d9 (0x7f7f88f304d0:1668:0x7f7f88f308c0)
  [150261286 461.814521] qemu_mutex_unlock: released mutex 0x55d842db27b8 (0x55d840cdfcb1:143)
  [150261287 461.814521] lock: Unkocked state 0 for 0x55d842db27b8
  [150261288 461.814523] qemu_mutex_unlock: released mutex 0x55d842ded590 (0x55d840c63019:172)
  [150261289 461.814523] lock: Unkocked state 0 for 0x55d842ded590
  [150261290 461.814524] monitor_suspend: mon 0x55d842ded530: 1
  [150261291 461.814525] handle_hmp_command: mon 0x55d842ded530 cmdline: 0x55d842e18d50
  [150261292 461.814537] recorder: Recorder dump

Of course, in general, you will probably want to focus on some particular
trace after an event happened, e.g.

  recorder dump qemu_mutex_unlock

which will get you:

  [150617808 508.134486] qemu_mutex_unlock: released mutex 0x55d842d66898 (0x55d840d032c0:119)
  [150617814 508.134487] qemu_mutex_unlock: released mutex 0x55d842d66918 (0x55d840d032c0:119)
  [150617820 508.134489] qemu_mutex_unlock: released mutex 0x55d842d66d18 (0x55d840d032c0:119)
  [150617822 508.134494] qemu_mutex_unlock: released mutex 0x55d841360500 (0x55d840b85f40:1790)
  [150617834 508.136546] qemu_mutex_unlock: released mutex 0x55d842d66d18 (0x55d840d032c0:119)
  [150617848 508.136630] qemu_mutex_unlock: released mutex 0x55d842db27b8 (0x55d840cdfcb1:143)
  [150617850 508.136631] qemu_mutex_unlock: released mutex 0x55d842ded590 (0x55d840c63019:172)

So as you can see, the usage pattern is IMO sufficiently different from the
existing tracing mechanism that slightly different commands and usage models
may be warranted.

Does that interface make sense?


As an aside, if you have activated the recorder sharing mechanism by using
some "recorder_name=recorder_field,recorder_field" option, then you can
remote-control some aspects of qemu as well using recorder_scope. For
example, instead of using the monitor, you can use:

  recorder_scope -c qemu_mutex_unlock

Or

  recorder_scope -c dump

>
> Integration need not mean implement the existing interface slavishly!
> Feel free to evolve it.  For instance, the QMP commands provide
> "case-sensitive glob", while you have full regexps.  You could extend
> the commands to also accept regexps.

Yes, as I have indicated in the cover letter, further integration is a topic
of interest. This is likely to require some relatively "minor" changes like
the one you mentioned, as well as more significant ones.

What I want to avoid is shooting for some "lowest common denominator" by
constraining the recorder library to just tracing. If this was just
functionally equivalent to the log trace backend, the recorder trace backend
would add very little value and not be worth integrating.

>
> We can talk about leaving gaps for later.
>
> I recommend to start with QMP.

Does the existing qmp integration work for you, or do you have suggestions
for reworking it?

>
> [...]


--
Cheers,
Christophe de Dinechin (IRC c3d)

Re: [PATCH v2 2/3] trace: Add support for recorder back-end

[Markus Armbruster]

Christophe de Dinechin <dinechin@redhat.com> writes:

> On 2020-07-23 at 16:06 CEST, Markus Armbruster wrote...
>> Christophe de Dinechin <dinechin@redhat.com> writes:
>>
>>> On 2020-06-30 at 15:02 CEST, Daniel P. Berrangé wrote...
>>>> On Fri, Jun 26, 2020 at 06:27:05PM +0200, Christophe de Dinechin wrote:
>>>>> The recorder library provides support for low-cost continuous
>>>>> recording of events, which can then be replayed. This makes it
>>>>> possible to collect data "after the fact",for example to show the
>>>>> events that led to a crash.
>>>>>
>>>>> Recorder support in qemu is implemented using the existing tracing
>>>>> interface. In addition, it is possible to individually enable
>>>>> recorders that are not traces, although this is probably not
>>>>> recommended.
>>>>>
>>>>> HMP COMMAND:
>>>>> The 'recorder' hmp command has been added, which supports two
>>>>> sub-commands:
>>>>> - recorder dump: Dump the current state of the recorder. You can
>>>>> - recorder trace: Set traces using the recorder_trace_set() syntax.
>>>>>   You can use "recorder trace help" to list all available recorders.
>>>>>
>>>>> Signed-off-by: Christophe de Dinechin <dinechin@redhat.com>
>>>>> ---
>>>>>  configure                             |  5 +++
>>>>>  hmp-commands.hx                       | 19 ++++++++--
>>>>>  monitor/misc.c                        | 27 ++++++++++++++
>>>>>  scripts/tracetool/backend/recorder.py | 51 +++++++++++++++++++++++++++
>>>>>  trace/Makefile.objs                   |  2 ++
>>>>>  trace/control.c                       |  7 ++++
>>>>>  trace/recorder.c                      | 22 ++++++++++++
>>>>>  trace/recorder.h                      | 34 ++++++++++++++++++
>>>>>  util/module.c                         |  8 +++++
>>>>>  9 files changed, 173 insertions(+), 2 deletions(-)
>>>>>  create mode 100644 scripts/tracetool/backend/recorder.py
>>>>>  create mode 100644 trace/recorder.c
>>>>>  create mode 100644 trace/recorder.h
>>>>
>>>>> +RECORDER_CONSTRUCTOR
>>>>> +void recorder_trace_init(void)
>>>>> +{
>>>>> +    recorder_trace_set(getenv("RECORDER_TRACES"));
>>>>> +
>>>>> +    // Allow a dump in case we receive some unhandled signal
>>>>> +    // For example, send USR2 to a hung process to get a dump
>>>>> +    if (getenv("RECORDER_TRACES"))
>>>>> +        recorder_dump_on_common_signals(0,0);
>>>>> +}
>>>>
>>>> What is the syntax of this RECORDER_TRACES env variable,
>>>
>>> It's basically a colon-separated list of regexps,
>>> e.g. ".*_error:.*_warning", with special syntax for some additional
>>> functionality such as real-time graphing.
>>>
>>> Here are a few examples:
>>>
>>> - Activate the foo, bar and baz traces:
>>>       foo:bar:baz
>>>
>>> - Activate all traces that contain "lock", as well as "recorder" trace:
>>>       *lock.*:recorder
>>>
>>> - Deactivate traces ending in _error
>>>       .*_error=0
>>>
>>> There are also a few tweaks and special names, for example you can adjust
>>> the output to show the function name and source code location as follows::
>>>
>>> - Show source information in the traces
>>>       recorder_function:recorder_location
>>>
>>>   As is not very useful in qemu because it sohws the wrapper location:
>>>      % RECORDER_TRACES=vm_state_notify qemu-system-x86_64
>>>      [35225 7.092175] vm_state_notify: running 1 reason 9 (running)
>>>
>>>      % RECORDER_TRACES=vm_state_notify:recorder_function:recorder_location qemu-system-x86_64
>>>      /home/ddd/Work/qemu/trace-root.h:346:_nocheck__trace_vm_state_notify:[94277 0.294906] vm_state_notify: running 1 reason 9 (running)
>>>
>>>   This is not as good as what you get with "real" record entries:
>>>      % RECORDER_TRACES=recorder_function:recorder_location:recorder qemu-system-x86_64
>>>      recorder.c:2036:recorder_allocate_alt_stack:[29561 0.006434] recorder: Set alt stack to 0x7fc567b87000 size 8192
>>>
>>> - Get some help on available traces:
>>>       help
>>>
>>> - Enable real-time graphing for trace "perfdata"
>>>       perfdata=bytes,loops
>>>
>>> The last one assumes that you would have a record that looks like:
>>>
>>>      record(perfdata, "Transferred %lu bytes in %lu iterations",
>>>             bytes, itercount);
>>>
>>> You could then have a real-time graph of the values for variables "bytes"
>>> and "itercount" using the recorder_scope program, and using the names you
>>> gave to the channels in your RECORDER_TRACES variable, i.e. bytes and loops:
>>>
>>>      recorder_scope bytes loops
>>>
>>> See man recorder_trace_set(3), recorder_scope(1) or
>>> https://github.com/c3d/recorder#recorder-tracing for more information.
>>>
>>>
>>>> and perhaps more importantly should we have this modelled as a command
>>>> line arg instead of an env variable. We've generally been aiming to get
>>>> rid of env variables and have QAPI modelled CLI. QAPI modelling would be
>>>> particularly important if we want to expose the ablity to change settings
>>>> on the fly via QMP.
>>>
>>> The rationale for the recorder using an environment variable is that it was
>>> initially designed to be able to trace libraries, notably SPICE or the
>>> recorder library itself. A single environment variable can be used to
>>> activate traces in the main binary as well as in the libraries.
>>
>> Makes sense.
>>
>>> I'm certainly not against adding a command-line option to activate recorder
>>> options specifically, but as I understand, the option -trace already exists,
>>> and its semantics is sufficiently different from the one in recorder
>>> patterns that I decided to not connect the two for now. For example, to
>>> disable trace foo, you'd pass "-foo" to the -trace option, but "foo=0" to
>>> RECORDER_TRACES. The parsing of graphing options and other related
>>> recorder-specific stuff is a bit difficult to integrate with -trace too.
>>
>> We need proper integration with the existing trace UI.
>
> I agree, but I don't think this belongs to this particular patch series.
> See below why.
>
>>
>> In particular, the ability to enable and disable trace events
>> dynamically provided by QMP commands trace-event-get-state,
>> trace-event-set-state, and HMP command trace-event is really useful.
>
> That ability exists, but given the many differences between the
> recorder and other tracing mechanisms, I found it useful to add a specific
> "recorder" command.

Precedence for commands specific to a trace backend: trace-file.

Name yours trace-recorder?

> For example, assuming I built with both recorder and log trace backends,
> from the monitor, I can type:
>
>   trace-event kvm_run_exit on
>
> What I get then is something like that:
>
>   2091091@1595518935.441273:kvm_run_exit cpu_index 0, reason 2
>   2091091@1595518935.441292:kvm_run_exit cpu_index 0, reason 2
>   2091091@1595518935.441301:kvm_run_exit cpu_index 0, reason 2
>   2091091@1595518935.441309:kvm_run_exit cpu_index 0, reason 2
>   2091091@1595518935.441254:kvm_run_exit cpu_index 0, reason 2
>
> It would not be very useful to activate recorder traces as well when that
> happens, which would have the undesired side effect of purging any
> corresponding entry from a following recorder dump.

I'm afraid I don't understand, because the gaps in my understanding of
what the recorder can do are just too big.

From your cover letter:

    1. Flight recorder: Dump information on recent events in case of crash

Define "recent events", please.  Is it all trace events (except for the
ones disabled at build time, of course)?

"Flight recorder" hints at recording in some ring buffer.  True?

Can you explain the difference to trace backend "ftrace"?

    2. Tracing: Individual traces can be enabled using environment variables

I guess "individual traces" means "individual trace events".

What does it mean to enable a trace event?  How does this affect the
recorder's behavior?

    3. Real-time graphing / control, using the recorder_scope application

I'm ignoring this one for now.

> There are, however, new monitor commands, so now I can do:
>
>   recorder trace kvm_run_exit
>
> I now get an output where each trace shows up twice.
>
>   [120139718 137.127269] kvm_run_exit: cpu_index 0, reason 2
>   2091091@1595518954.209803:kvm_run_exit cpu_index 0, reason 2
>   [120139734 137.127281] kvm_run_exit: cpu_index 0, reason 2
>   2091091@1595518954.209814:kvm_run_exit cpu_index 0, reason 2
>   [120139751 137.127293] kvm_run_exit: cpu_index 0, reason 2
>
>  I don't find particularly useful, so I don't think having that as the
> normal behaviour would qualify as what you called proper integration.

Well, I asked for it by configuring two trace backends, didn't I?

If I configured just the recorder backend, would I get a useful trace?

If yes, what's wrong with letting me control what's being traced with
the common trace-event command in addition to a backend-specific
command?

> Having a separate recorder command, OTOH, allows me to also do things
> that are not possible with other trace back-ends, and presumably never will

I'm not arguing against an additional recorder command to control things
only the recorder backend can do.

> be, like:
>
>     recorder trace kvm_run_exit=cpu,reason
>
> That configures things so that I can now do real-time graphing using
> recorder-scope. The only output from qemu will be:
>
>   Creating new /tmp/recorder_share
>
> But I can now run somewhere else:
>
>    recorder_scope cpu reason
>
> and have a real-time view of what is happening in my qemu. Not particularly
> interesting with existing instrumentation, which was not designed for
> graphing, but that's easily changed.
>
> Another key feature I get from the new monitor command is
>
>   recorder dump
>
> Now the output will be something like (cut for brevity)
>
>   [150261271 461.814366] lock: Locked state 2 for 0x55d842d66d18
>   [150261272 461.814366] qemu_mutex_unlock: released mutex 0x55d842d66d18 (0x55d840d032c0:119)
>   [150261273 461.814366] lock: Unkocked state 0 for 0x55d842d66d18
>   [150261274 461.814367] lockcnt_fast_path_attempt: lockcnt 0x55d842b630ec fast path 0->4
>   [150261275 461.814367] lockcnt_fast_path_success: lockcnt 0x55d842b630ec fast path 0->4 succeeded
>   [150261276 461.814515] qemu_mutex_lock: waiting on mutex 0x55d842ded590 (0x55d840c63019:161)
>   [150261277 461.814515] lock: Locking state 1 for 0x55d842ded590
>   [150261278 461.814515] qemu_mutex_locked: taken mutex 0x55d842ded590 (0x55d840c63019:161)
>   [150261279 461.814515] lock: Locked state 2 for 0x55d842ded590
>   [150261280 461.814517] object_class_dynamic_cast_assert: 0x55d842dea5e0->0x55d840cdfcc0 (0x55d840cdfcb1:114:0x55d840ce02a0)
>   [150261281 461.814518] qemu_mutex_lock: waiting on mutex 0x55d842db27b8 (0x55d840cdfcb1:118)
>   [150261282 461.814518] lock: Locking state 1 for 0x55d842db27b8
>   [150261283 461.814518] qemu_mutex_locked: taken mutex 0x55d842db27b8 (0x55d840cdfcb1:118)
>   [150261284 461.814518] lock: Locked state 2 for 0x55d842db27b8
>   [150261285 461.814518] object_dynamic_cast_assert: 0x55d842dea5e0->0x7f7f88f304d9 (0x7f7f88f304d0:1668:0x7f7f88f308c0)
>   [150261286 461.814521] qemu_mutex_unlock: released mutex 0x55d842db27b8 (0x55d840cdfcb1:143)
>   [150261287 461.814521] lock: Unkocked state 0 for 0x55d842db27b8
>   [150261288 461.814523] qemu_mutex_unlock: released mutex 0x55d842ded590 (0x55d840c63019:172)
>   [150261289 461.814523] lock: Unkocked state 0 for 0x55d842ded590
>   [150261290 461.814524] monitor_suspend: mon 0x55d842ded530: 1
>   [150261291 461.814525] handle_hmp_command: mon 0x55d842ded530 cmdline: 0x55d842e18d50
>   [150261292 461.814537] recorder: Recorder dump
>
> Of course, in general, you will probably want to focus on some particular
> trace after an event happened, e.g.
>
>   recorder dump qemu_mutex_unlock
>
> which will get you:
>
>   [150617808 508.134486] qemu_mutex_unlock: released mutex 0x55d842d66898 (0x55d840d032c0:119)
>   [150617814 508.134487] qemu_mutex_unlock: released mutex 0x55d842d66918 (0x55d840d032c0:119)
>   [150617820 508.134489] qemu_mutex_unlock: released mutex 0x55d842d66d18 (0x55d840d032c0:119)
>   [150617822 508.134494] qemu_mutex_unlock: released mutex 0x55d841360500 (0x55d840b85f40:1790)
>   [150617834 508.136546] qemu_mutex_unlock: released mutex 0x55d842d66d18 (0x55d840d032c0:119)
>   [150617848 508.136630] qemu_mutex_unlock: released mutex 0x55d842db27b8 (0x55d840cdfcb1:143)
>   [150617850 508.136631] qemu_mutex_unlock: released mutex 0x55d842ded590 (0x55d840c63019:172)
>
> So as you can see, the usage pattern is IMO sufficiently different from the
> existing tracing mechanism that slightly different commands and usage models
> may be warranted.

Separate commands for sufficiently different usage patterns may make
sense.  My question is whether the recorder backend can also support the
same old usage patterns.

Supporting the same old usage patterns is nice, because then I don't
have to configure two trace backends, one for old usage patterns, and
recorder for the recorder usage patterns.

But then I'd like to be able to use the same old commands, too.

> Does that interface make sense?
>
>
> As an aside, if you have activated the recorder sharing mechanism by using
> some "recorder_name=recorder_field,recorder_field" option, then you can
> remote-control some aspects of qemu as well using recorder_scope. For
> example, instead of using the monitor, you can use:
>
>   recorder_scope -c qemu_mutex_unlock
>
> Or
>
>   recorder_scope -c dump
>
>>
>> Integration need not mean implement the existing interface slavishly!
>> Feel free to evolve it.  For instance, the QMP commands provide
>> "case-sensitive glob", while you have full regexps.  You could extend
>> the commands to also accept regexps.
>
> Yes, as I have indicated in the cover letter, further integration is a topic
> of interest. This is likely to require some relatively "minor" changes like
> the one you mentioned, as well as more significant ones.
>
> What I want to avoid is shooting for some "lowest common denominator" by
> constraining the recorder library to just tracing. If this was just
> functionally equivalent to the log trace backend, the recorder trace backend
> would add very little value and not be worth integrating.

The point of integrating the recorder backends is of course gaining
features the other backends don't already provide.  Additional features
taking additional UI is fine.

>> We can talk about leaving gaps for later.
>>
>> I recommend to start with QMP.
>
> Does the existing qmp integration work for you, or do you have suggestions
> for reworking it?

I'm afraid I need to learn a bit more before I can answer this.

Re: [PATCH v2 2/3] trace: Add support for recorder back-end

[Christophe de Dinechin]

On 2020-07-27 at 10:23 CEST, Markus Armbruster wrote...
> Christophe de Dinechin <dinechin@redhat.com> writes:
>
>> On 2020-07-23 at 16:06 CEST, Markus Armbruster wrote...
>>> Christophe de Dinechin <dinechin@redhat.com> writes:
>>>
>>>> On 2020-06-30 at 15:02 CEST, Daniel P. Berrangé wrote...
>>>>> On Fri, Jun 26, 2020 at 06:27:05PM +0200, Christophe de Dinechin wrote:
>>>>>> The recorder library provides support for low-cost continuous
>>>>>> recording of events, which can then be replayed. This makes it
>>>>>> possible to collect data "after the fact",for example to show the
>>>>>> events that led to a crash.
>>>>>>
>>>>>> Recorder support in qemu is implemented using the existing tracing
>>>>>> interface. In addition, it is possible to individually enable
>>>>>> recorders that are not traces, although this is probably not
>>>>>> recommended.
>>>>>>
>>>>>> HMP COMMAND:
>>>>>> The 'recorder' hmp command has been added, which supports two
>>>>>> sub-commands:
>>>>>> - recorder dump: Dump the current state of the recorder. You can
>>>>>> - recorder trace: Set traces using the recorder_trace_set() syntax.
>>>>>>   You can use "recorder trace help" to list all available recorders.
>>>>>>
>>>>>> Signed-off-by: Christophe de Dinechin <dinechin@redhat.com>
>>>>>> ---
>>>>>>  configure                             |  5 +++
>>>>>>  hmp-commands.hx                       | 19 ++++++++--
>>>>>>  monitor/misc.c                        | 27 ++++++++++++++
>>>>>>  scripts/tracetool/backend/recorder.py | 51 +++++++++++++++++++++++++++
>>>>>>  trace/Makefile.objs                   |  2 ++
>>>>>>  trace/control.c                       |  7 ++++
>>>>>>  trace/recorder.c                      | 22 ++++++++++++
>>>>>>  trace/recorder.h                      | 34 ++++++++++++++++++
>>>>>>  util/module.c                         |  8 +++++
>>>>>>  9 files changed, 173 insertions(+), 2 deletions(-)
>>>>>>  create mode 100644 scripts/tracetool/backend/recorder.py
>>>>>>  create mode 100644 trace/recorder.c
>>>>>>  create mode 100644 trace/recorder.h
>>>>>
>>>>>> +RECORDER_CONSTRUCTOR
>>>>>> +void recorder_trace_init(void)
>>>>>> +{
>>>>>> +    recorder_trace_set(getenv("RECORDER_TRACES"));
>>>>>> +
>>>>>> +    // Allow a dump in case we receive some unhandled signal
>>>>>> +    // For example, send USR2 to a hung process to get a dump
>>>>>> +    if (getenv("RECORDER_TRACES"))
>>>>>> +        recorder_dump_on_common_signals(0,0);
>>>>>> +}
>>>>>
>>>>> What is the syntax of this RECORDER_TRACES env variable,
>>>>
>>>> It's basically a colon-separated list of regexps,
>>>> e.g. ".*_error:.*_warning", with special syntax for some additional
>>>> functionality such as real-time graphing.
>>>>
>>>> Here are a few examples:
>>>>
>>>> - Activate the foo, bar and baz traces:
>>>>       foo:bar:baz
>>>>
>>>> - Activate all traces that contain "lock", as well as "recorder" trace:
>>>>       *lock.*:recorder
>>>>
>>>> - Deactivate traces ending in _error
>>>>       .*_error=0
>>>>
>>>> There are also a few tweaks and special names, for example you can adjust
>>>> the output to show the function name and source code location as follows::
>>>>
>>>> - Show source information in the traces
>>>>       recorder_function:recorder_location
>>>>
>>>>   As is not very useful in qemu because it sohws the wrapper location:
>>>>      % RECORDER_TRACES=vm_state_notify qemu-system-x86_64
>>>>      [35225 7.092175] vm_state_notify: running 1 reason 9 (running)
>>>>
>>>>      % RECORDER_TRACES=vm_state_notify:recorder_function:recorder_location qemu-system-x86_64
>>>>      /home/ddd/Work/qemu/trace-root.h:346:_nocheck__trace_vm_state_notify:[94277 0.294906] vm_state_notify: running 1 reason 9 (running)
>>>>
>>>>   This is not as good as what you get with "real" record entries:
>>>>      % RECORDER_TRACES=recorder_function:recorder_location:recorder qemu-system-x86_64
>>>>      recorder.c:2036:recorder_allocate_alt_stack:[29561 0.006434] recorder: Set alt stack to 0x7fc567b87000 size 8192
>>>>
>>>> - Get some help on available traces:
>>>>       help
>>>>
>>>> - Enable real-time graphing for trace "perfdata"
>>>>       perfdata=bytes,loops
>>>>
>>>> The last one assumes that you would have a record that looks like:
>>>>
>>>>      record(perfdata, "Transferred %lu bytes in %lu iterations",
>>>>             bytes, itercount);
>>>>
>>>> You could then have a real-time graph of the values for variables "bytes"
>>>> and "itercount" using the recorder_scope program, and using the names you
>>>> gave to the channels in your RECORDER_TRACES variable, i.e. bytes and loops:
>>>>
>>>>      recorder_scope bytes loops
>>>>
>>>> See man recorder_trace_set(3), recorder_scope(1) or
>>>> https://github.com/c3d/recorder#recorder-tracing for more information.
>>>>
>>>>
>>>>> and perhaps more importantly should we have this modelled as a command
>>>>> line arg instead of an env variable. We've generally been aiming to get
>>>>> rid of env variables and have QAPI modelled CLI. QAPI modelling would be
>>>>> particularly important if we want to expose the ablity to change settings
>>>>> on the fly via QMP.
>>>>
>>>> The rationale for the recorder using an environment variable is that it was
>>>> initially designed to be able to trace libraries, notably SPICE or the
>>>> recorder library itself. A single environment variable can be used to
>>>> activate traces in the main binary as well as in the libraries.
>>>
>>> Makes sense.
>>>
>>>> I'm certainly not against adding a command-line option to activate recorder
>>>> options specifically, but as I understand, the option -trace already exists,
>>>> and its semantics is sufficiently different from the one in recorder
>>>> patterns that I decided to not connect the two for now. For example, to
>>>> disable trace foo, you'd pass "-foo" to the -trace option, but "foo=0" to
>>>> RECORDER_TRACES. The parsing of graphing options and other related
>>>> recorder-specific stuff is a bit difficult to integrate with -trace too.
>>>
>>> We need proper integration with the existing trace UI.
>>
>> I agree, but I don't think this belongs to this particular patch series.
>> See below why.
>>
>>>
>>> In particular, the ability to enable and disable trace events
>>> dynamically provided by QMP commands trace-event-get-state,
>>> trace-event-set-state, and HMP command trace-event is really useful.
>>
>> That ability exists, but given the many differences between the
>> recorder and other tracing mechanisms, I found it useful to add a specific
>> "recorder" command.
>
> Precedence for commands specific to a trace backend: trace-file.
>
> Name yours trace-recorder?

But then "recorder dump" does not fit with any "trace" concept.

>
>> For example, assuming I built with both recorder and log trace backends,
>> from the monitor, I can type:
>>
>>   trace-event kvm_run_exit on
>>
>> What I get then is something like that:
>>
>>   2091091@1595518935.441273:kvm_run_exit cpu_index 0, reason 2
>>   2091091@1595518935.441292:kvm_run_exit cpu_index 0, reason 2
>>   2091091@1595518935.441301:kvm_run_exit cpu_index 0, reason 2
>>   2091091@1595518935.441309:kvm_run_exit cpu_index 0, reason 2
>>   2091091@1595518935.441254:kvm_run_exit cpu_index 0, reason 2
>>
>> It would not be very useful to activate recorder traces as well when that
>> happens, which would have the undesired side effect of purging any
>> corresponding entry from a following recorder dump.
>
> I'm afraid I don't understand, because the gaps in my understanding of
> what the recorder can do are just too big.

There is a video at the top of https://github.com/c3d/recorder, or direct
link https://www.youtube.com/watch?v=kEnQY1zFa0Y. Hope this helps.


>
> From your cover letter:
>
>     1. Flight recorder: Dump information on recent events in case of crash
>
> Define "recent events", please.  Is it all trace events (except for the
> ones disabled at build time, of course)?

For event categories only known through qemu trace definitions, by default,
it's the last 8 events. If you manually declare a recorder, then you can
specify any size.

(The difference between this manual recorder usage and the recorder backend
generated code is similar to the difference between the log backend and
"DPRINTF")

>
> "Flight recorder" hints at recording in some ring buffer.  True?

Yes.

>
> Can you explain the difference to trace backend "ftrace"?

- It's not recording function calls nor stack traces.
- It's faster (no fd write, no % parameter expansion)
- It works on non-Linux platforms
- It's always on

>
>     2. Tracing: Individual traces can be enabled using environment variables
>
> I guess "individual traces" means "individual trace events".

Maybe I'm unwittingly opposing some well-established qemu habits here, as
indicated by the "trace-event" command, but to me, a "trace" reports multiple
"events" of the same class (distinguished e.g. by their timestamps). So I
would say that I am indeed enabling a trace in order to be shown all the
events associated to this trace.

Does that make sense?

But then I understand that the existing command is called "trace-event".
So there's that. I don't mind changing the text that much.

>
> What does it mean to enable a trace event?  How does this affect the
> recorder's behavior?

For a given recorder instrumentation point, three things can happen:
- It is recorded in a circular buffer (always)
- If tracing is active, then a trace message is displayed
- If sharing is active, then it is copied in shared memory for use by some
  external program, e.g. recorder_scope.


>
>     3. Real-time graphing / control, using the recorder_scope application
>
> I'm ignoring this one for now.
>
>> There are, however, new monitor commands, so now I can do:
>>
>>   recorder trace kvm_run_exit
>>
>> I now get an output where each trace shows up twice.
>>
>>   [120139718 137.127269] kvm_run_exit: cpu_index 0, reason 2
>>   2091091@1595518954.209803:kvm_run_exit cpu_index 0, reason 2
>>   [120139734 137.127281] kvm_run_exit: cpu_index 0, reason 2
>>   2091091@1595518954.209814:kvm_run_exit cpu_index 0, reason 2
>>   [120139751 137.127293] kvm_run_exit: cpu_index 0, reason 2
>>
>>  I don't find particularly useful, so I don't think having that as the
>> normal behaviour would qualify as what you called proper integration.
>
> Well, I asked for it by configuring two trace backends, didn't I?

Not really IMO. By configuring two trace backends, what you requested was to
have two different kinds of instrumentation active at the same time. It does
not imply (at least to me) that these two kinds of instrumentation have to
react to *run-time* configuration identically, in particular if that means
in a way that happens to not be helpful.

If you configure log and ftrace, you are not requesting them to behave
identically at run time.


>
> If I configured just the recorder backend, would I get a useful trace?

Yes, but not the full functionality that "recorder" gives you.
Notably, there is nothing in the existing trace-event command that would
allow me to configure recorder sharing or trace output format, whereas the
proposed patch allows me to do that.

>
> If yes, what's wrong with letting me control what's being traced with
> the common trace-event command in addition to a backend-specific
> command?

This would force that code to a lower common denominator that would remove a
lot of useful functionality specific to the recorder, even assuming we keep
both the "recorder" and "trace-event" commands to configure the recorder.

There is a problem with the semantics of the underlying API. For example,
disabling trace foo is "-foo" in qemu, "foo=0" in the recorder API. I don't
really like the idea of adding some string manipulation code to transform
"-foo" into "foo=0". I would prefer to extend the recorder API to accept
-foo, but that's not the case today.

Things get worse for multiple traces. In qemu, you would have
"virtio_blk_*", for the recorder it is "virtio_blk_.*" (it's a true regexp).
So examples from the recorder documentation such as ".*_(error|warning)"
will not work with trace-enable, and you'd have to convert the qemu syntax
to true regexps to pass them to the recorder API, which is borderline
insanity.


>
>> Having a separate recorder command, OTOH, allows me to also do things
>> that are not possible with other trace back-ends, and presumably never will
>
> I'm not arguing against an additional recorder command to control things
> only the recorder backend can do.

I am also favorable to trying to see if a better integration would make
sense, but that would be a much more intrusive patch, with an impact on
other trace backends, e.g. add some back-end specific callback to parse the
parameter of "trace-event" to allow for more than "on|off", and possibly to
switch to true regexps or something like that for multiple traces, which
undoubtedly would break many a script.


>
>> be, like:
>>
>>     recorder trace kvm_run_exit=cpu,reason
>>
>> That configures things so that I can now do real-time graphing using
>> recorder-scope. The only output from qemu will be:
>>
>>   Creating new /tmp/recorder_share
>>
>> But I can now run somewhere else:
>>
>>    recorder_scope cpu reason
>>
>> and have a real-time view of what is happening in my qemu. Not particularly
>> interesting with existing instrumentation, which was not designed for
>> graphing, but that's easily changed.
>>
>> Another key feature I get from the new monitor command is
>>
>>   recorder dump
>>
>> Now the output will be something like (cut for brevity)
>>
>>   [150261271 461.814366] lock: Locked state 2 for 0x55d842d66d18
>>   [150261272 461.814366] qemu_mutex_unlock: released mutex 0x55d842d66d18 (0x55d840d032c0:119)
>>   [150261273 461.814366] lock: Unkocked state 0 for 0x55d842d66d18
>>   [150261274 461.814367] lockcnt_fast_path_attempt: lockcnt 0x55d842b630ec fast path 0->4
>>   [150261275 461.814367] lockcnt_fast_path_success: lockcnt 0x55d842b630ec fast path 0->4 succeeded
>>   [150261276 461.814515] qemu_mutex_lock: waiting on mutex 0x55d842ded590 (0x55d840c63019:161)
>>   [150261277 461.814515] lock: Locking state 1 for 0x55d842ded590
>>   [150261278 461.814515] qemu_mutex_locked: taken mutex 0x55d842ded590 (0x55d840c63019:161)
>>   [150261279 461.814515] lock: Locked state 2 for 0x55d842ded590
>>   [150261280 461.814517] object_class_dynamic_cast_assert: 0x55d842dea5e0->0x55d840cdfcc0 (0x55d840cdfcb1:114:0x55d840ce02a0)
>>   [150261281 461.814518] qemu_mutex_lock: waiting on mutex 0x55d842db27b8 (0x55d840cdfcb1:118)
>>   [150261282 461.814518] lock: Locking state 1 for 0x55d842db27b8
>>   [150261283 461.814518] qemu_mutex_locked: taken mutex 0x55d842db27b8 (0x55d840cdfcb1:118)
>>   [150261284 461.814518] lock: Locked state 2 for 0x55d842db27b8
>>   [150261285 461.814518] object_dynamic_cast_assert: 0x55d842dea5e0->0x7f7f88f304d9 (0x7f7f88f304d0:1668:0x7f7f88f308c0)
>>   [150261286 461.814521] qemu_mutex_unlock: released mutex 0x55d842db27b8 (0x55d840cdfcb1:143)
>>   [150261287 461.814521] lock: Unkocked state 0 for 0x55d842db27b8
>>   [150261288 461.814523] qemu_mutex_unlock: released mutex 0x55d842ded590 (0x55d840c63019:172)
>>   [150261289 461.814523] lock: Unkocked state 0 for 0x55d842ded590
>>   [150261290 461.814524] monitor_suspend: mon 0x55d842ded530: 1
>>   [150261291 461.814525] handle_hmp_command: mon 0x55d842ded530 cmdline: 0x55d842e18d50
>>   [150261292 461.814537] recorder: Recorder dump
>>
>> Of course, in general, you will probably want to focus on some particular
>> trace after an event happened, e.g.
>>
>>   recorder dump qemu_mutex_unlock
>>
>> which will get you:
>>
>>   [150617808 508.134486] qemu_mutex_unlock: released mutex 0x55d842d66898 (0x55d840d032c0:119)
>>   [150617814 508.134487] qemu_mutex_unlock: released mutex 0x55d842d66918 (0x55d840d032c0:119)
>>   [150617820 508.134489] qemu_mutex_unlock: released mutex 0x55d842d66d18 (0x55d840d032c0:119)
>>   [150617822 508.134494] qemu_mutex_unlock: released mutex 0x55d841360500 (0x55d840b85f40:1790)
>>   [150617834 508.136546] qemu_mutex_unlock: released mutex 0x55d842d66d18 (0x55d840d032c0:119)
>>   [150617848 508.136630] qemu_mutex_unlock: released mutex 0x55d842db27b8 (0x55d840cdfcb1:143)
>>   [150617850 508.136631] qemu_mutex_unlock: released mutex 0x55d842ded590 (0x55d840c63019:172)
>>
>> So as you can see, the usage pattern is IMO sufficiently different from the
>> existing tracing mechanism that slightly different commands and usage models
>> may be warranted.
>
> Separate commands for sufficiently different usage patterns may make
> sense.  My question is whether the recorder backend can also support the
> same old usage patterns.

Not easily. Long-term, with intrusive changes that affect other back-ends, yes.

>
> Supporting the same old usage patterns is nice, because then I don't
> have to configure two trace backends, one for old usage patterns, and
> recorder for the recorder usage patterns.
>
> But then I'd like to be able to use the same old commands, too.
>
>> Does that interface make sense?

It does, but as part of a later discussion IMO. For example, is it OK to
have backends specify some extended syntax for trace-enable? Can we somehow
accept different regexp syntax for trace-event? etc.

>>
>>
>> As an aside, if you have activated the recorder sharing mechanism by using
>> some "recorder_name=recorder_field,recorder_field" option, then you can
>> remote-control some aspects of qemu as well using recorder_scope. For
>> example, instead of using the monitor, you can use:
>>
>>   recorder_scope -c qemu_mutex_unlock
>>
>> Or
>>
>>   recorder_scope -c dump
>>
>>>
>>> Integration need not mean implement the existing interface slavishly!
>>> Feel free to evolve it.  For instance, the QMP commands provide
>>> "case-sensitive glob", while you have full regexps.  You could extend
>>> the commands to also accept regexps.
>>
>> Yes, as I have indicated in the cover letter, further integration is a topic
>> of interest. This is likely to require some relatively "minor" changes like
>> the one you mentioned, as well as more significant ones.
>>
>> What I want to avoid is shooting for some "lowest common denominator" by
>> constraining the recorder library to just tracing. If this was just
>> functionally equivalent to the log trace backend, the recorder trace backend
>> would add very little value and not be worth integrating.
>
> The point of integrating the recorder backends is of course gaining
> features the other backends don't already provide.  Additional features
> taking additional UI is fine.
>
>>> We can talk about leaving gaps for later.
>>>
>>> I recommend to start with QMP.
>>
>> Does the existing qmp integration work for you, or do you have suggestions
>> for reworking it?
>
> I'm afraid I need to learn a bit more before I can answer this.

OK. Thanks.



--
Cheers,
Christophe de Dinechin (IRC c3d)

Re: [PATCH v2 2/3] trace: Add support for recorder back-end

[Markus Armbruster]

Christophe de Dinechin <dinechin@redhat.com> writes:

> On 2020-07-27 at 10:23 CEST, Markus Armbruster wrote...
>> Christophe de Dinechin <dinechin@redhat.com> writes:
>>
>>> On 2020-07-23 at 16:06 CEST, Markus Armbruster wrote...
>>>> Christophe de Dinechin <dinechin@redhat.com> writes:
[...]
>>>>> I'm certainly not against adding a command-line option to activate recorder
>>>>> options specifically, but as I understand, the option -trace already exists,
>>>>> and its semantics is sufficiently different from the one in recorder
>>>>> patterns that I decided to not connect the two for now. For example, to
>>>>> disable trace foo, you'd pass "-foo" to the -trace option, but "foo=0" to
>>>>> RECORDER_TRACES. The parsing of graphing options and other related
>>>>> recorder-specific stuff is a bit difficult to integrate with -trace too.
>>>>
>>>> We need proper integration with the existing trace UI.
>>>
>>> I agree, but I don't think this belongs to this particular patch series.
>>> See below why.
>>>
>>>>
>>>> In particular, the ability to enable and disable trace events
>>>> dynamically provided by QMP commands trace-event-get-state,
>>>> trace-event-set-state, and HMP command trace-event is really useful.
>>>
>>> That ability exists, but given the many differences between the
>>> recorder and other tracing mechanisms, I found it useful to add a specific
>>> "recorder" command.
>>
>> Precedence for commands specific to a trace backend: trace-file.
>>
>> Name yours trace-recorder?
>
> But then "recorder dump" does not fit with any "trace" concept.

Once you make the recorder a trace backend, whatever the recorder does
becomes a trace concept :)

>>> For example, assuming I built with both recorder and log trace backends,
>>> from the monitor, I can type:
>>>
>>>   trace-event kvm_run_exit on
>>>
>>> What I get then is something like that:
>>>
>>>   2091091@1595518935.441273:kvm_run_exit cpu_index 0, reason 2
>>>   2091091@1595518935.441292:kvm_run_exit cpu_index 0, reason 2
>>>   2091091@1595518935.441301:kvm_run_exit cpu_index 0, reason 2
>>>   2091091@1595518935.441309:kvm_run_exit cpu_index 0, reason 2
>>>   2091091@1595518935.441254:kvm_run_exit cpu_index 0, reason 2
>>>
>>> It would not be very useful to activate recorder traces as well when that
>>> happens, which would have the undesired side effect of purging any
>>> corresponding entry from a following recorder dump.
>>
>> I'm afraid I don't understand, because the gaps in my understanding of
>> what the recorder can do are just too big.
>
> There is a video at the top of https://github.com/c3d/recorder, or direct
> link https://www.youtube.com/watch?v=kEnQY1zFa0Y. Hope this helps.
>
>
>>
>> From your cover letter:
>>
>>     1. Flight recorder: Dump information on recent events in case of crash
>>
>> Define "recent events", please.  Is it all trace events (except for the
>> ones disabled at build time, of course)?
>
> For event categories only known through qemu trace definitions, by default,

Right now, there are no others, aren't there?

> it's the last 8 events. If you manually declare a recorder, then you can
> specify any size.
>
> (The difference between this manual recorder usage and the recorder backend
> generated code is similar to the difference between the log backend and
> "DPRINTF")

I'm not sure I get the parenthesis.

>> "Flight recorder" hints at recording in some ring buffer.  True?
>
> Yes.
>
>>
>> Can you explain the difference to trace backend "ftrace"?
>
> - It's not recording function calls nor stack traces.
> - It's faster (no fd write, no % parameter expansion)

I guess "simple" doesn't format either, but it still writes to disk.

> - It works on non-Linux platforms
> - It's always on

The combination of "always on" and "minimal overhead" is obviously
useful.

>>
>>     2. Tracing: Individual traces can be enabled using environment variables
>>
>> I guess "individual traces" means "individual trace events".
>
> Maybe I'm unwittingly opposing some well-established qemu habits here, as
> indicated by the "trace-event" command, but to me, a "trace" reports multiple
> "events" of the same class (distinguished e.g. by their timestamps). So I
> would say that I am indeed enabling a trace in order to be shown all the
> events associated to this trace.
>
> Does that make sense?
>
> But then I understand that the existing command is called "trace-event".
> So there's that. I don't mind changing the text that much.

I'm hardly an expert on tracing in QEMU, I merely use it from time to
time.  I am the QMP maintainer, though.  Adding new commands for every
new thing is easy.  Proper integration takes thought.  And that's what
we're doing.

As far as I can tell, QEMU has no concept of a "trace" in the sense of
your definition.  There are only individual trace events.  Enabled trace
events emit via the enabled trace backends.  Simple & stupid.

>> What does it mean to enable a trace event?  How does this affect the
>> recorder's behavior?
>
> For a given recorder instrumentation point, three things can happen:
> - It is recorded in a circular buffer (always)
> - If tracing is active, then a trace message is displayed
> - If sharing is active, then it is copied in shared memory for use by some
>   external program, e.g. recorder_scope.

Enabled trace events get emitted to the configured backends, which can
do whatever they want with the events.

Current trace backends emit to a single destination (log: stderr,
simple: a file, ftrace: the kernel, nop: the bit bucket, you get the
idea), but that's detail.

My (possibly naive) expecation for a recorder backend: as always, only
the enabled trace events get emitted to the recorder backend.  All of
"circular buffer (always), display if tracing is active, copy if sharing
is active" happens within the backend.  In particular, enabling a trace
event cannot control the "tracing is active" bit.  It effectively
controls the "is recorded in a circular buffer" bit.  Correct?

I guess much of the confusion comes from the fact that trace backends
are just that, but the recorder is more.

Trace backends emit trace events.

The recorder can *also* emit trace events.  But it primarily records.  I
figure users commonly record more events than they trace.

If you do the recorder as a trace backend, then the existing UI to
control what's being traced becomes UI to control what's being recorded
by the recorder and traced by everything else.  Confusing, and we're
short one UI to control what's being traced by the recorder.

Perhaps doing the recorder as a trace backend is simply a bad idea.
Perhaps it should be integrated in the trace subsystem differently, so
that trace-enable continues to control what's being traced for all
backends.

Perhaps the recorder should emit the events it traces to a trace
backend.

>>     3. Real-time graphing / control, using the recorder_scope application
>>
>> I'm ignoring this one for now.
>>
>>> There are, however, new monitor commands, so now I can do:
>>>
>>>   recorder trace kvm_run_exit
>>>
>>> I now get an output where each trace shows up twice.
>>>
>>>   [120139718 137.127269] kvm_run_exit: cpu_index 0, reason 2
>>>   2091091@1595518954.209803:kvm_run_exit cpu_index 0, reason 2
>>>   [120139734 137.127281] kvm_run_exit: cpu_index 0, reason 2
>>>   2091091@1595518954.209814:kvm_run_exit cpu_index 0, reason 2
>>>   [120139751 137.127293] kvm_run_exit: cpu_index 0, reason 2
>>>
>>>  I don't find particularly useful, so I don't think having that as the
>>> normal behaviour would qualify as what you called proper integration.
>>
>> Well, I asked for it by configuring two trace backends, didn't I?
>
> Not really IMO. By configuring two trace backends, what you requested was to
> have two different kinds of instrumentation active at the same time. It does
> not imply (at least to me) that these two kinds of instrumentation have to
> react to *run-time* configuration identically, in particular if that means
> in a way that happens to not be helpful.
>
> If you configure log and ftrace, you are not requesting them to behave
> identically at run time.

No, but by configuring two trace backends, you ask each one to do its
thing.  If "its thing" includes printing to stderr for both, then
getting events printed twice is exactly what you asked for.

>> If I configured just the recorder backend, would I get a useful trace?
>
> Yes, but not the full functionality that "recorder" gives you.
> Notably, there is nothing in the existing trace-event command that would
> allow me to configure recorder sharing or trace output format, whereas the
> proposed patch allows me to do that.

Christophe, leave that windmill alone!  I'm over here!  ;)

I'm not trying to shoot down commands specific to trace backends.  I'm
trying to understand how the proposed recorder backend interacts with
the existing tracing UI and infrastructure, so I can figure out how to
best fit it with the existing UI and infrastructure.

QEMU's tracing subsystem consists of a common, backend-independent part
and backends.

Command trace-event controls one aspect of the common part: whether to
hand the trace event to the backend or not.  The backend has no say in
that.

Command trace-file controls one aspect of the backend: writing output to
a file.  Only the simple backend makes use of it, but that's detail.

You tell me the recorder backend needs to expose more configuration to
really make sense.  The question isn't whether that's true (I trust you
on that), it's how to best integrate it with what we have.

>> If yes, what's wrong with letting me control what's being traced with
>> the common trace-event command in addition to a backend-specific
>> command?
>
> This would force that code to a lower common denominator that would remove a
> lot of useful functionality specific to the recorder, even assuming we keep
> both the "recorder" and "trace-event" commands to configure the recorder.
>
> There is a problem with the semantics of the underlying API. For example,
> disabling trace foo is "-foo" in qemu, "foo=0" in the recorder API. I don't
> really like the idea of adding some string manipulation code to transform
> "-foo" into "foo=0". I would prefer to extend the recorder API to accept
> -foo, but that's not the case today.

You're talking about the configuration file specified with trace
events=...

The existing UI for the recorder library is different.  Hardly a
surprise.

Consistency between the existing UI for the common part and the new UI
for the recorder backend is quite desirable.  I'm not making it a hard
requirement.  I would like to see concrete ideas on how to get it,
though.

[,,,]

Re: [PATCH v2 2/3] trace: Add support for recorder back-end

[Christophe de Dinechin]

On 2020-07-29 at 13:53 CEST, Markus Armbruster wrote...
> Christophe de Dinechin <dinechin@redhat.com> writes:
>
>> On 2020-07-27 at 10:23 CEST, Markus Armbruster wrote...
>>> Christophe de Dinechin <dinechin@redhat.com> writes:
>>>
>>>> On 2020-07-23 at 16:06 CEST, Markus Armbruster wrote...
>>>>> Christophe de Dinechin <dinechin@redhat.com> writes:
> [...]
>>>>>> I'm certainly not against adding a command-line option to activate recorder
>>>>>> options specifically, but as I understand, the option -trace already exists,
>>>>>> and its semantics is sufficiently different from the one in recorder
>>>>>> patterns that I decided to not connect the two for now. For example, to
>>>>>> disable trace foo, you'd pass "-foo" to the -trace option, but "foo=0" to
>>>>>> RECORDER_TRACES. The parsing of graphing options and other related
>>>>>> recorder-specific stuff is a bit difficult to integrate with -trace too.
>>>>>
>>>>> We need proper integration with the existing trace UI.
>>>>
>>>> I agree, but I don't think this belongs to this particular patch series.
>>>> See below why.
>>>>
>>>>>
>>>>> In particular, the ability to enable and disable trace events
>>>>> dynamically provided by QMP commands trace-event-get-state,
>>>>> trace-event-set-state, and HMP command trace-event is really useful.
>>>>
>>>> That ability exists, but given the many differences between the
>>>> recorder and other tracing mechanisms, I found it useful to add a specific
>>>> "recorder" command.
>>>
>>> Precedence for commands specific to a trace backend: trace-file.
>>>
>>> Name yours trace-recorder?
>>
>> But then "recorder dump" does not fit with any "trace" concept.
>
> Once you make the recorder a trace backend, whatever the recorder does
> becomes a trace concept :)

I understand your point, but I want to make a distinction between recorder
tracing and other recorder features. Does that make sense?


>
>>>> For example, assuming I built with both recorder and log trace backends,
>>>> from the monitor, I can type:
>>>>
>>>>   trace-event kvm_run_exit on
>>>>
>>>> What I get then is something like that:
>>>>
>>>>   2091091@1595518935.441273:kvm_run_exit cpu_index 0, reason 2
>>>>   2091091@1595518935.441292:kvm_run_exit cpu_index 0, reason 2
>>>>   2091091@1595518935.441301:kvm_run_exit cpu_index 0, reason 2
>>>>   2091091@1595518935.441309:kvm_run_exit cpu_index 0, reason 2
>>>>   2091091@1595518935.441254:kvm_run_exit cpu_index 0, reason 2
>>>>
>>>> It would not be very useful to activate recorder traces as well when that
>>>> happens, which would have the undesired side effect of purging any
>>>> corresponding entry from a following recorder dump.
>>>
>>> I'm afraid I don't understand, because the gaps in my understanding of
>>> what the recorder can do are just too big.
>>
>> There is a video at the top of https://github.com/c3d/recorder, or direct
>> link https://www.youtube.com/watch?v=kEnQY1zFa0Y. Hope this helps.
>>
>>
>>>
>>> From your cover letter:
>>>
>>>     1. Flight recorder: Dump information on recent events in case of crash
>>>
>>> Define "recent events", please.  Is it all trace events (except for the
>>> ones disabled at build time, of course)?
>>
>> For event categories only known through qemu trace definitions, by default,
>
> Right now, there are no others, aren't there?

There is one in the second patch, the example. That was actually the whole
point of that second patch, which is not otherwise particularly exciting.

>
>> it's the last 8 events. If you manually declare a recorder, then you can
>> specify any size.
>>
>> (The difference between this manual recorder usage and the recorder backend
>> generated code is similar to the difference between the log backend and
>> "DPRINTF")
>
> I'm not sure I get the parenthesis.

I took that example because it's mentioned in docs/devel/tracing.txt:

    === Log ===

    The "log" backend sends trace events directly to standard error.  This
    effectively turns trace events into debug printfs.

    This is the simplest backend and can be used together with existing code that
    uses DPRINTF().

Just the same way, the recorder back-end can both use existing trace points,
using the recorder back-end, but you can also add explicit record()
statements much like you can add DPRINTF() statements.

Whether this is a good idea or not is debatable. I would argue that in some
cases, it's a good idea, or at least, probably a better idea than DPRINTF ;-)

>
>>> "Flight recorder" hints at recording in some ring buffer.  True?
>>
>> Yes.
>>
>>>
>>> Can you explain the difference to trace backend "ftrace"?
>>
>> - It's not recording function calls nor stack traces.
>> - It's faster (no fd write, no % parameter expansion)
>
> I guess "simple" doesn't format either, but it still writes to disk.
>
>> - It works on non-Linux platforms
>> - It's always on
>
> The combination of "always on" and "minimal overhead" is obviously
> useful.
>
>>>
>>>     2. Tracing: Individual traces can be enabled using environment variables
>>>
>>> I guess "individual traces" means "individual trace events".
>>
>> Maybe I'm unwittingly opposing some well-established qemu habits here, as
>> indicated by the "trace-event" command, but to me, a "trace" reports multiple
>> "events" of the same class (distinguished e.g. by their timestamps). So I
>> would say that I am indeed enabling a trace in order to be shown all the
>> events associated to this trace.
>>
>> Does that make sense?
>>
>> But then I understand that the existing command is called "trace-event".
>> So there's that. I don't mind changing the text that much.
>
> I'm hardly an expert on tracing in QEMU, I merely use it from time to
> time.  I am the QMP maintainer, though.  Adding new commands for every
> new thing is easy.  Proper integration takes thought.  And that's what
> we're doing.
>
> As far as I can tell, QEMU has no concept of a "trace" in the sense of
> your definition.  There are only individual trace events.  Enabled trace
> events emit via the enabled trace backends.  Simple & stupid.

I understand this terminology, and I was pointing out that it sounds really
a strange use of the words. To me, an event is definitely a single point in
time. However, I don't mind aligning the patch terminology where necessary
for consistency.

>
>>> What does it mean to enable a trace event?  How does this affect the
>>> recorder's behavior?
>>
>> For a given recorder instrumentation point, three things can happen:
>> - It is recorded in a circular buffer (always)
>> - If tracing is active, then a trace message is displayed
>> - If sharing is active, then it is copied in shared memory for use by some
>>   external program, e.g. recorder_scope.
>
> Enabled trace events get emitted to the configured backends, which can
> do whatever they want with the events.
>
> Current trace backends emit to a single destination (log: stderr,
> simple: a file, ftrace: the kernel, nop: the bit bucket, you get the
> idea), but that's detail.
>
> My (possibly naive) expecation for a recorder backend: as always, only
> the enabled trace events get emitted to the recorder backend.  All of
> "circular buffer (always), display if tracing is active, copy if sharing
> is active" happens within the backend.  In particular, enabling a trace
> event cannot control the "tracing is active" bit.  It effectively
> controls the "is recorded in a circular buffer" bit.  Correct?

Actually, not in the patches as sent, no. IMO, this would defeat the whole
purpose of always-on instrumentation. It's possible to disable recording,
but by default, it's on.

>
> I guess much of the confusion comes from the fact that trace backends
> are just that, but the recorder is more.
>
> Trace backends emit trace events.
>
> The recorder can *also* emit trace events.  But it primarily records.  I
> figure users commonly record more events than they trace.

Yes. The normal state for a trace point is to be off, the normal state for a
record point is to be recording but not tracing.

>
> If you do the recorder as a trace backend, then the existing UI to
> control what's being traced becomes UI to control what's being recorded
> by the recorder and traced by everything else.  Confusing, and we're
> short one UI to control what's being traced by the recorder.
>
> Perhaps doing the recorder as a trace backend is simply a bad idea.
> Perhaps it should be integrated in the trace subsystem differently, so
> that trace-enable continues to control what's being traced for all
> backends.

That means you don't benefit from any of the existing trace points.

As an aside, the existing tracing system has the trace points in a different
file than the actual code. In other words, we have something like:

    # ioport.c
    cpu_in(unsigned int addr, char size, unsigned int val) "addr 0x%x(%c) value %u"
    cpu_out(unsigned int addr, char size, unsigned int val) "addr 0x%x(%c) value %u"

and in ioport.c we have:

    trace_cpu_in(addr, 'b', val);

The recorder native approach would be something like:

    trace(cpu_in, "addr 0x%x(%c) value %u", addr, 'b', val);

Is the current syntax an artifact of how tracetool works, or is it intentional?

>
> Perhaps the recorder should emit the events it traces to a trace
> backend.

Ah, interesting. The recorder has a configurable output, so it is somewhat
trivial to connect to some generated function that calls the various trace
backends.

>
>>>     3. Real-time graphing / control, using the recorder_scope application
>>>
>>> I'm ignoring this one for now.
>>>
>>>> There are, however, new monitor commands, so now I can do:
>>>>
>>>>   recorder trace kvm_run_exit
>>>>
>>>> I now get an output where each trace shows up twice.
>>>>
>>>>   [120139718 137.127269] kvm_run_exit: cpu_index 0, reason 2
>>>>   2091091@1595518954.209803:kvm_run_exit cpu_index 0, reason 2
>>>>   [120139734 137.127281] kvm_run_exit: cpu_index 0, reason 2
>>>>   2091091@1595518954.209814:kvm_run_exit cpu_index 0, reason 2
>>>>   [120139751 137.127293] kvm_run_exit: cpu_index 0, reason 2
>>>>
>>>>  I don't find particularly useful, so I don't think having that as the
>>>> normal behaviour would qualify as what you called proper integration.
>>>
>>> Well, I asked for it by configuring two trace backends, didn't I?
>>
>> Not really IMO. By configuring two trace backends, what you requested was to
>> have two different kinds of instrumentation active at the same time. It does
>> not imply (at least to me) that these two kinds of instrumentation have to
>> react to *run-time* configuration identically, in particular if that means
>> in a way that happens to not be helpful.
>>
>> If you configure log and ftrace, you are not requesting them to behave
>> identically at run time.
>
> No, but by configuring two trace backends, you ask each one to do its
> thing.  If "its thing" includes printing to stderr for both, then
> getting events printed twice is exactly what you asked for.

I think that you are arguing that since trace-event currently activates or
disables all trace back-ends at once, then that's necessarily what I asked
for.

There is a nice ambiguity about the word "asked for" here, but that's
definitely not what I would like. I described this behavior as unhelpful.

However, addressing that correctly may indeed belong to the common code
rather than to individual backends, I'll certainly grant you that.


>
>>> If I configured just the recorder backend, would I get a useful trace?
>>
>> Yes, but not the full functionality that "recorder" gives you.
>> Notably, there is nothing in the existing trace-event command that would
>> allow me to configure recorder sharing or trace output format, whereas the
>> proposed patch allows me to do that.
>
> Christophe, leave that windmill alone!  I'm over here!  ;)

;-)


> I'm not trying to shoot down commands specific to trace backends.  I'm
> trying to understand how the proposed recorder backend interacts with
> the existing tracing UI and infrastructure, so I can figure out how to
> best fit it with the existing UI and infrastructure.
>
> QEMU's tracing subsystem consists of a common, backend-independent part
> and backends.
>
> Command trace-event controls one aspect of the common part: whether to
> hand the trace event to the backend or not.  The backend has no say in
> that.

This is the part I changed in the patch, because there is already a
mechanism to activate / deactivate tracing in the recorder, so having two
'if(condition)' testing essentially the same condition using two different
flags seems useless.

>
> Command trace-file controls one aspect of the backend: writing output to
> a file.  Only the simple backend makes use of it, but that's detail.
>
> You tell me the recorder backend needs to expose more configuration to
> really make sense.  The question isn't whether that's true (I trust you
> on that), it's how to best integrate it with what we have.

You gave me a number of interesting ideas. Let me get back to you with a new
spin. You can tell me which one you prefer. I also made a couple of changes
to the recorder itself to make future qemu integration easier.

>
>>> If yes, what's wrong with letting me control what's being traced with
>>> the common trace-event command in addition to a backend-specific
>>> command?
>>
>> This would force that code to a lower common denominator that would remove a
>> lot of useful functionality specific to the recorder, even assuming we keep
>> both the "recorder" and "trace-event" commands to configure the recorder.
>>
>> There is a problem with the semantics of the underlying API. For example,
>> disabling trace foo is "-foo" in qemu, "foo=0" in the recorder API. I don't
>> really like the idea of adding some string manipulation code to transform
>> "-foo" into "foo=0". I would prefer to extend the recorder API to accept
>> -foo, but that's not the case today.
>
> You're talking about the configuration file specified with trace
> events=...
>
> The existing UI for the recorder library is different.  Hardly a
> surprise.
>
> Consistency between the existing UI for the common part and the new UI
> for the recorder backend is quite desirable.  I'm not making it a hard
> requirement.  I would like to see concrete ideas on how to get it,
> though.

Here what can be done, but it's a larger undertaking:

- Convert named trace entry points to anonymous trace(...) calls following a
  syntax similar to record(...), so that traces are readable in one place.

- Have a mechanism for trace activation / deactivation that delegates to the
  trace back-end. That way, any ugly recorder-specific string manipulation
  converting regexps and such will be in the back-end, not in common code.

- When multiple trace back-ends are configured, make it possible to
  configure them independently, ideally using back-end specific options

- Add some notion of back-end specific option, to implement back-end
  specific configurations like trace-file or recorder_dump_on_signal.

- Split the notion of "trace" and "record", and add some "record"
  semantics. Some existing backends already are closer to record semantics,
  e.g. ftrace.

- Convert the existing DPRINTF stuff to trace().

--
Cheers,
Christophe de Dinechin (IRC c3d)

Re: [PATCH v2 2/3] trace: Add support for recorder back-end

[Markus Armbruster]

Christophe de Dinechin <dinechin@redhat.com> writes:

> On 2020-07-29 at 13:53 CEST, Markus Armbruster wrote...
>> Christophe de Dinechin <dinechin@redhat.com> writes:
>>
>>> On 2020-07-27 at 10:23 CEST, Markus Armbruster wrote...
>>>> Christophe de Dinechin <dinechin@redhat.com> writes:
>>>>
>>>>> On 2020-07-23 at 16:06 CEST, Markus Armbruster wrote...
>>>>>> Christophe de Dinechin <dinechin@redhat.com> writes:
>> [...]
>>>>>>> I'm certainly not against adding a command-line option to activate recorder
>>>>>>> options specifically, but as I understand, the option -trace already exists,
>>>>>>> and its semantics is sufficiently different from the one in recorder
>>>>>>> patterns that I decided to not connect the two for now. For example, to
>>>>>>> disable trace foo, you'd pass "-foo" to the -trace option, but "foo=0" to
>>>>>>> RECORDER_TRACES. The parsing of graphing options and other related
>>>>>>> recorder-specific stuff is a bit difficult to integrate with -trace too.
>>>>>>
>>>>>> We need proper integration with the existing trace UI.
>>>>>
>>>>> I agree, but I don't think this belongs to this particular patch series.
>>>>> See below why.
>>>>>
>>>>>>
>>>>>> In particular, the ability to enable and disable trace events
>>>>>> dynamically provided by QMP commands trace-event-get-state,
>>>>>> trace-event-set-state, and HMP command trace-event is really useful.
>>>>>
>>>>> That ability exists, but given the many differences between the
>>>>> recorder and other tracing mechanisms, I found it useful to add a specific
>>>>> "recorder" command.
>>>>
>>>> Precedence for commands specific to a trace backend: trace-file.
>>>>
>>>> Name yours trace-recorder?
>>>
>>> But then "recorder dump" does not fit with any "trace" concept.
>>
>> Once you make the recorder a trace backend, whatever the recorder does
>> becomes a trace concept :)
>
> I understand your point, but I want to make a distinction between recorder
> tracing and other recorder features. Does that make sense?

Maybe :)  My thoughts haven't settled, yet.

>>>>> For example, assuming I built with both recorder and log trace backends,
>>>>> from the monitor, I can type:
>>>>>
>>>>>   trace-event kvm_run_exit on
>>>>>
>>>>> What I get then is something like that:
>>>>>
>>>>>   2091091@1595518935.441273:kvm_run_exit cpu_index 0, reason 2
>>>>>   2091091@1595518935.441292:kvm_run_exit cpu_index 0, reason 2
>>>>>   2091091@1595518935.441301:kvm_run_exit cpu_index 0, reason 2
>>>>>   2091091@1595518935.441309:kvm_run_exit cpu_index 0, reason 2
>>>>>   2091091@1595518935.441254:kvm_run_exit cpu_index 0, reason 2
>>>>>
>>>>> It would not be very useful to activate recorder traces as well when that
>>>>> happens, which would have the undesired side effect of purging any
>>>>>> corresponding entry from a following recorder dump.
>>>>
>>>> I'm afraid I don't understand, because the gaps in my understanding of
>>>> what the recorder can do are just too big.
>>>
>>> There is a video at the top of https://github.com/c3d/recorder, or direct
>>> link https://www.youtube.com/watch?v=kEnQY1zFa0Y. Hope this helps.
>>>
>>>
>>>>
>>>> From your cover letter:
>>>>
>>>>     1. Flight recorder: Dump information on recent events in case of crash
>>>>
>>>> Define "recent events", please.  Is it all trace events (except for the
>>>> ones disabled at build time, of course)?
>>>
>>> For event categories only known through qemu trace definitions, by default,
>>
>> Right now, there are no others, aren't there?
>
> There is one in the second patch, the example. That was actually the whole
> point of that second patch, which is not otherwise particularly exciting.
>
>>
>>> it's the last 8 events. If you manually declare a recorder, then you can
>>> specify any size.
>>>
>>> (The difference between this manual recorder usage and the recorder backend
>>> generated code is similar to the difference between the log backend and
>>> "DPRINTF")
>>
>> I'm not sure I get the parenthesis.
>
> I took that example because it's mentioned in docs/devel/tracing.txt:
>
>     === Log ===
>
>     The "log" backend sends trace events directly to standard error.  This
>     effectively turns trace events into debug printfs.
>
>     This is the simplest backend and can be used together with existing code that
>     uses DPRINTF().
>
> Just the same way, the recorder back-end can both use existing trace points,
> using the recorder back-end, but you can also add explicit record()
> statements much like you can add DPRINTF() statements.

Got it.

> Whether this is a good idea or not is debatable. I would argue that in some
> cases, it's a good idea, or at least, probably a better idea than DPRINTF ;-)

No need to convince me a low-overhead flight recorder can be useful.
I've improvised special-purpose flight recorders many times when
printf-like tracing interfered enough with the timing to make the
interesting behavior go away.

I doubt having both trace points and record() makes sense in QEMU except
for ad hoc debugging.

>>>> "Flight recorder" hints at recording in some ring buffer.  True?
>>>
>>> Yes.
>>>
>>>>
>>>> Can you explain the difference to trace backend "ftrace"?
>>>
>>> - It's not recording function calls nor stack traces.
>>> - It's faster (no fd write, no % parameter expansion)
>>
>> I guess "simple" doesn't format either, but it still writes to disk.
>>
>>> - It works on non-Linux platforms
>>> - It's always on
>>
>> The combination of "always on" and "minimal overhead" is obviously
>> useful.
>>
>>>>
>>>>     2. Tracing: Individual traces can be enabled using environment variables
>>>>
>>>> I guess "individual traces" means "individual trace events".
>>>
>>> Maybe I'm unwittingly opposing some well-established qemu habits here, as
>>> indicated by the "trace-event" command, but to me, a "trace" reports multiple
>>> "events" of the same class (distinguished e.g. by their timestamps). So I
>>> would say that I am indeed enabling a trace in order to be shown all the
>>> events associated to this trace.
>>>
>>> Does that make sense?
>>>
>>> But then I understand that the existing command is called "trace-event".
>>> So there's that. I don't mind changing the text that much.
>>
>> I'm hardly an expert on tracing in QEMU, I merely use it from time to
>> time.  I am the QMP maintainer, though.  Adding new commands for every
>> new thing is easy.  Proper integration takes thought.  And that's what
>> we're doing.
>>
>> As far as I can tell, QEMU has no concept of a "trace" in the sense of
>> your definition.  There are only individual trace events.  Enabled trace
>> events emit via the enabled trace backends.  Simple & stupid.
>
> I understand this terminology, and I was pointing out that it sounds really
> a strange use of the words. To me, an event is definitely a single point in
> time. However, I don't mind aligning the patch terminology where necessary
> for consistency.

I think we use "trace event" (one trace record) and "trace point" (the
point in code where a certain kind of event gets emitted) the same way,
and the terminology isn't strange at all.

You additionally use "trace".  Also not strange, once you defined it.

>>>> What does it mean to enable a trace event?  How does this affect the
>>>> recorder's behavior?
>>>
>>> For a given recorder instrumentation point, three things can happen:
>>> - It is recorded in a circular buffer (always)
>>> - If tracing is active, then a trace message is displayed
>>> - If sharing is active, then it is copied in shared memory for use by some
>>>   external program, e.g. recorder_scope.
>>
>> Enabled trace events get emitted to the configured backends, which can
>> do whatever they want with the events.
>>
>> Current trace backends emit to a single destination (log: stderr,
>> simple: a file, ftrace: the kernel, nop: the bit bucket, you get the
>> idea), but that's detail.
>>
>> My (possibly naive) expecation for a recorder backend: as always, only
>> the enabled trace events get emitted to the recorder backend.  All of
>> "circular buffer (always), display if tracing is active, copy if sharing
>> is active" happens within the backend.  In particular, enabling a trace
>> event cannot control the "tracing is active" bit.  It effectively
>> controls the "is recorded in a circular buffer" bit.  Correct?
>
> Actually, not in the patches as sent, no. IMO, this would defeat the whole
> purpose of always-on instrumentation. It's possible to disable recording,
> but by default, it's on.

I misread the tracing infrastructure.  Honoring the enabled bit is
actually up to the backend.  Some backends open-code it in the generated
_nocheck__trace_FOO() for speed.

>> I guess much of the confusion comes from the fact that trace backends
>> are just that, but the recorder is more.
>>
>> Trace backends emit trace events.
>>
>> The recorder can *also* emit trace events.  But it primarily records.  I
>> figure users commonly record more events than they trace.
>
> Yes. The normal state for a trace point is to be off, the normal state for a
> record point is to be recording but not tracing.
>
>>
>> If you do the recorder as a trace backend, then the existing UI to
>> control what's being traced becomes UI to control what's being recorded
>> by the recorder and traced by everything else.  Confusing, and we're
>> short one UI to control what's being traced by the recorder.
>>
>> Perhaps doing the recorder as a trace backend is simply a bad idea.
>> Perhaps it should be integrated in the trace subsystem differently, so
>> that trace-enable continues to control what's being traced for all
>> backends.
>
> That means you don't benefit from any of the existing trace points.
>
> As an aside, the existing tracing system has the trace points in a different
> file than the actual code. In other words, we have something like:
>
>     # ioport.c
>     cpu_in(unsigned int addr, char size, unsigned int val) "addr 0x%x(%c) value %u"
>     cpu_out(unsigned int addr, char size, unsigned int val) "addr 0x%x(%c) value %u"
>
> and in ioport.c we have:
>
>     trace_cpu_in(addr, 'b', val);
>
> The recorder native approach would be something like:
>
>     trace(cpu_in, "addr 0x%x(%c) value %u", addr, 'b', val);
>
> Is the current syntax an artifact of how tracetool works, or is it intentional?

I'm not sure.  A bit of both?

The separate trace-events file makes generating code for events simple
and easy.

Some backends heavily rely on code generation.  The recorder backend
seems not to.  Code generation includes the .dtrace generated with
backend dtrace.

>> Perhaps the recorder should emit the events it traces to a trace
>> backend.
>
> Ah, interesting. The recorder has a configurable output, so it is somewhat
> trivial to connect to some generated function that calls the various trace
> backends.
>
>>
>>>>     3. Real-time graphing / control, using the recorder_scope application
>>>>
>>>> I'm ignoring this one for now.
>>>>
>>>>> There are, however, new monitor commands, so now I can do:
>>>>>
>>>>>   recorder trace kvm_run_exit
>>>>>
>>>>> I now get an output where each trace shows up twice.
>>>>>
>>>>>   [120139718 137.127269] kvm_run_exit: cpu_index 0, reason 2
>>>>>   2091091@1595518954.209803:kvm_run_exit cpu_index 0, reason 2
>>>>>   [120139734 137.127281] kvm_run_exit: cpu_index 0, reason 2
>>>>>   2091091@1595518954.209814:kvm_run_exit cpu_index 0, reason 2
>>>>>   [120139751 137.127293] kvm_run_exit: cpu_index 0, reason 2
>>>>>
>>>>>  I don't find particularly useful, so I don't think having that as the
>>>>> normal behaviour would qualify as what you called proper integration.
>>>>
>>>> Well, I asked for it by configuring two trace backends, didn't I?
>>>
>>> Not really IMO. By configuring two trace backends, what you requested was to
>>> have two different kinds of instrumentation active at the same time. It does
>>> not imply (at least to me) that these two kinds of instrumentation have to
>>> react to *run-time* configuration identically, in particular if that means
>>> in a way that happens to not be helpful.
>>>
>>> If you configure log and ftrace, you are not requesting them to behave
>>> identically at run time.
>>
>> No, but by configuring two trace backends, you ask each one to do its
>> thing.  If "its thing" includes printing to stderr for both, then
>> getting events printed twice is exactly what you asked for.
>
> I think that you are arguing that since trace-event currently activates or
> disables all trace back-ends at once, then that's necessarily what I asked
> for.
>
> There is a nice ambiguity about the word "asked for" here, but that's
> definitely not what I would like. I described this behavior as unhelpful.
>
> However, addressing that correctly may indeed belong to the common code
> rather than to individual backends, I'll certainly grant you that.
>
>
>>
>>>> If I configured just the recorder backend, would I get a useful trace?
>>>
>>> Yes, but not the full functionality that "recorder" gives you.
>>> Notably, there is nothing in the existing trace-event command that would
>>> allow me to configure recorder sharing or trace output format, whereas the
>>> proposed patch allows me to do that.
>>
>> Christophe, leave that windmill alone!  I'm over here!  ;)
>
> ;-)
>
>
>> I'm not trying to shoot down commands specific to trace backends.  I'm
>> trying to understand how the proposed recorder backend interacts with
>> the existing tracing UI and infrastructure, so I can figure out how to
>> best fit it with the existing UI and infrastructure.
>>
>> QEMU's tracing subsystem consists of a common, backend-independent part
>> and backends.
>>
>> Command trace-event controls one aspect of the common part: whether to
>> hand the trace event to the backend or not.  The backend has no say in
>> that.

I was confused.  Honoring the enabled bit is actually up to the backend.

> This is the part I changed in the patch, because there is already a
> mechanism to activate / deactivate tracing in the recorder, so having two
> 'if(condition)' testing essentially the same condition using two different
> flags seems useless.
>
>>
>> Command trace-file controls one aspect of the backend: writing output to
>> a file.  Only the simple backend makes use of it, but that's detail.
>>
>> You tell me the recorder backend needs to expose more configuration to
>> really make sense.  The question isn't whether that's true (I trust you
>> on that), it's how to best integrate it with what we have.
>
> You gave me a number of interesting ideas. Let me get back to you with a new
> spin. You can tell me which one you prefer. I also made a couple of changes
> to the recorder itself to make future qemu integration easier.
>
>>
>>>> If yes, what's wrong with letting me control what's being traced with
>>>> the common trace-event command in addition to a backend-specific
>>>> command?
>>>
>>> This would force that code to a lower common denominator that would remove a
>>> lot of useful functionality specific to the recorder, even assuming we keep
>>> both the "recorder" and "trace-event" commands to configure the recorder.
>>>
>>> There is a problem with the semantics of the underlying API. For example,
>>> disabling trace foo is "-foo" in qemu, "foo=0" in the recorder API. I don't
>>> really like the idea of adding some string manipulation code to transform
>>> "-foo" into "foo=0". I would prefer to extend the recorder API to accept
>>> -foo, but that's not the case today.
>>
>> You're talking about the configuration file specified with trace
>> events=...
>>
>> The existing UI for the recorder library is different.  Hardly a
>> surprise.
>>
>> Consistency between the existing UI for the common part and the new UI
>> for the recorder backend is quite desirable.  I'm not making it a hard
>> requirement.  I would like to see concrete ideas on how to get it,
>> though.
>
> Here what can be done, but it's a larger undertaking:
>
> - Convert named trace entry points to anonymous trace(...) calls following a
>   syntax similar to record(...), so that traces are readable in one place.
>
> - Have a mechanism for trace activation / deactivation that delegates to the
>   trace back-end. That way, any ugly recorder-specific string manipulation
>   converting regexps and such will be in the back-end, not in common code.
>
> - When multiple trace back-ends are configured, make it possible to
>   configure them independently, ideally using back-end specific options
>
> - Add some notion of back-end specific option, to implement back-end
>   specific configurations like trace-file or recorder_dump_on_signal.
>
> - Split the notion of "trace" and "record", and add some "record"
>   semantics. Some existing backends already are closer to record semantics,
>   e.g. ftrace.
>
> - Convert the existing DPRINTF stuff to trace().

Plenty of ideas.  I'd recommend to wait for Stefan's opinion before you
run with them.

Re: [PATCH v2 2/3] trace: Add support for recorder back-end

[Christophe de Dinechin]

On 2020-07-30 at 10:13 CEST, Markus Armbruster wrote...
> Christophe de Dinechin <dinechin@redhat.com> writes:
>
>> On 2020-07-29 at 13:53 CEST, Markus Armbruster wrote...
>>> Christophe de Dinechin <dinechin@redhat.com> writes:
>>>
>>>> On 2020-07-27 at 10:23 CEST, Markus Armbruster wrote...
>>>>> Christophe de Dinechin <dinechin@redhat.com> writes:
>>>>>
>>>>>> On 2020-07-23 at 16:06 CEST, Markus Armbruster wrote...
>>>>>>> Christophe de Dinechin <dinechin@redhat.com> writes:
>>> [...]
>>>>>>>> I'm certainly not against adding a command-line option to activate recorder
>>>>>>>> options specifically, but as I understand, the option -trace already exists,
>>>>>>>> and its semantics is sufficiently different from the one in recorder
>>>>>>>> patterns that I decided to not connect the two for now. For example, to
>>>>>>>> disable trace foo, you'd pass "-foo" to the -trace option, but "foo=0" to
>>>>>>>> RECORDER_TRACES. The parsing of graphing options and other related
>>>>>>>> recorder-specific stuff is a bit difficult to integrate with -trace too.
>>>>>>>
>>>>>>> We need proper integration with the existing trace UI.
>>>>>>
>>>>>> I agree, but I don't think this belongs to this particular patch series.
>>>>>> See below why.
>>>>>>
>>>>>>>
>>>>>>> In particular, the ability to enable and disable trace events
>>>>>>> dynamically provided by QMP commands trace-event-get-state,
>>>>>>> trace-event-set-state, and HMP command trace-event is really useful.
>>>>>>
>>>>>> That ability exists, but given the many differences between the
>>>>>> recorder and other tracing mechanisms, I found it useful to add a specific
>>>>>> "recorder" command.
>>>>>
>>>>> Precedence for commands specific to a trace backend: trace-file.
>>>>>
>>>>> Name yours trace-recorder?
>>>>
>>>> But then "recorder dump" does not fit with any "trace" concept.
>>>
>>> Once you make the recorder a trace backend, whatever the recorder does
>>> becomes a trace concept :)
>>
>> I understand your point, but I want to make a distinction between recorder
>> tracing and other recorder features. Does that make sense?
>
> Maybe :)  My thoughts haven't settled, yet.
>
>>>>>> For example, assuming I built with both recorder and log trace backends,
>>>>>> from the monitor, I can type:
>>>>>>
>>>>>>   trace-event kvm_run_exit on
>>>>>>
>>>>>> What I get then is something like that:
>>>>>>
>>>>>>   2091091@1595518935.441273:kvm_run_exit cpu_index 0, reason 2
>>>>>>   2091091@1595518935.441292:kvm_run_exit cpu_index 0, reason 2
>>>>>>   2091091@1595518935.441301:kvm_run_exit cpu_index 0, reason 2
>>>>>>   2091091@1595518935.441309:kvm_run_exit cpu_index 0, reason 2
>>>>>>   2091091@1595518935.441254:kvm_run_exit cpu_index 0, reason 2
>>>>>>
>>>>>> It would not be very useful to activate recorder traces as well when that
>>>>>> happens, which would have the undesired side effect of purging any
>>>>>>> corresponding entry from a following recorder dump.
>>>>>
>>>>> I'm afraid I don't understand, because the gaps in my understanding of
>>>>> what the recorder can do are just too big.
>>>>
>>>> There is a video at the top of https://github.com/c3d/recorder, or direct
>>>> link https://www.youtube.com/watch?v=kEnQY1zFa0Y. Hope this helps.
>>>>
>>>>
>>>>>
>>>>> From your cover letter:
>>>>>
>>>>>     1. Flight recorder: Dump information on recent events in case of crash
>>>>>
>>>>> Define "recent events", please.  Is it all trace events (except for the
>>>>> ones disabled at build time, of course)?
>>>>
>>>> For event categories only known through qemu trace definitions, by default,
>>>
>>> Right now, there are no others, aren't there?
>>
>> There is one in the second patch, the example. That was actually the whole
>> point of that second patch, which is not otherwise particularly exciting.
>>
>>>
>>>> it's the last 8 events. If you manually declare a recorder, then you can
>>>> specify any size.
>>>>
>>>> (The difference between this manual recorder usage and the recorder backend
>>>> generated code is similar to the difference between the log backend and
>>>> "DPRINTF")
>>>
>>> I'm not sure I get the parenthesis.
>>
>> I took that example because it's mentioned in docs/devel/tracing.txt:
>>
>>     === Log ===
>>
>>     The "log" backend sends trace events directly to standard error.  This
>>     effectively turns trace events into debug printfs.
>>
>>     This is the simplest backend and can be used together with existing code that
>>     uses DPRINTF().
>>
>> Just the same way, the recorder back-end can both use existing trace points,
>> using the recorder back-end, but you can also add explicit record()
>> statements much like you can add DPRINTF() statements.
>
> Got it.
>
>> Whether this is a good idea or not is debatable. I would argue that in some
>> cases, it's a good idea, or at least, probably a better idea than DPRINTF ;-)
>
> No need to convince me a low-overhead flight recorder can be useful.
> I've improvised special-purpose flight recorders many times when
> printf-like tracing interfered enough with the timing to make the
> interesting behavior go away.
>
> I doubt having both trace points and record() makes sense in QEMU except
> for ad hoc debugging.
>
>>>>> "Flight recorder" hints at recording in some ring buffer.  True?
>>>>
>>>> Yes.
>>>>
>>>>>
>>>>> Can you explain the difference to trace backend "ftrace"?
>>>>
>>>> - It's not recording function calls nor stack traces.
>>>> - It's faster (no fd write, no % parameter expansion)
>>>
>>> I guess "simple" doesn't format either, but it still writes to disk.
>>>
>>>> - It works on non-Linux platforms
>>>> - It's always on
>>>
>>> The combination of "always on" and "minimal overhead" is obviously
>>> useful.
>>>
>>>>>
>>>>>     2. Tracing: Individual traces can be enabled using environment variables
>>>>>
>>>>> I guess "individual traces" means "individual trace events".
>>>>
>>>> Maybe I'm unwittingly opposing some well-established qemu habits here, as
>>>> indicated by the "trace-event" command, but to me, a "trace" reports multiple
>>>> "events" of the same class (distinguished e.g. by their timestamps). So I
>>>> would say that I am indeed enabling a trace in order to be shown all the
>>>> events associated to this trace.
>>>>
>>>> Does that make sense?
>>>>
>>>> But then I understand that the existing command is called "trace-event".
>>>> So there's that. I don't mind changing the text that much.
>>>
>>> I'm hardly an expert on tracing in QEMU, I merely use it from time to
>>> time.  I am the QMP maintainer, though.  Adding new commands for every
>>> new thing is easy.  Proper integration takes thought.  And that's what
>>> we're doing.
>>>
>>> As far as I can tell, QEMU has no concept of a "trace" in the sense of
>>> your definition.  There are only individual trace events.  Enabled trace
>>> events emit via the enabled trace backends.  Simple & stupid.
>>
>> I understand this terminology, and I was pointing out that it sounds really
>> a strange use of the words. To me, an event is definitely a single point in
>> time. However, I don't mind aligning the patch terminology where necessary
>> for consistency.
>
> I think we use "trace event" (one trace record) and "trace point" (the
> point in code where a certain kind of event gets emitted) the same way,
> and the terminology isn't strange at all.
>
> You additionally use "trace".  Also not strange, once you defined it.
>
>>>>> What does it mean to enable a trace event?  How does this affect the
>>>>> recorder's behavior?
>>>>
>>>> For a given recorder instrumentation point, three things can happen:
>>>> - It is recorded in a circular buffer (always)
>>>> - If tracing is active, then a trace message is displayed
>>>> - If sharing is active, then it is copied in shared memory for use by some
>>>>   external program, e.g. recorder_scope.
>>>
>>> Enabled trace events get emitted to the configured backends, which can
>>> do whatever they want with the events.
>>>
>>> Current trace backends emit to a single destination (log: stderr,
>>> simple: a file, ftrace: the kernel, nop: the bit bucket, you get the
>>> idea), but that's detail.
>>>
>>> My (possibly naive) expecation for a recorder backend: as always, only
>>> the enabled trace events get emitted to the recorder backend.  All of
>>> "circular buffer (always), display if tracing is active, copy if sharing
>>> is active" happens within the backend.  In particular, enabling a trace
>>> event cannot control the "tracing is active" bit.  It effectively
>>> controls the "is recorded in a circular buffer" bit.  Correct?
>>
>> Actually, not in the patches as sent, no. IMO, this would defeat the whole
>> purpose of always-on instrumentation. It's possible to disable recording,
>> but by default, it's on.
>
> I misread the tracing infrastructure.  Honoring the enabled bit is
> actually up to the backend.  Some backends open-code it in the generated
> _nocheck__trace_FOO() for speed.
>
>>> I guess much of the confusion comes from the fact that trace backends
>>> are just that, but the recorder is more.
>>>
>>> Trace backends emit trace events.
>>>
>>> The recorder can *also* emit trace events.  But it primarily records.  I
>>> figure users commonly record more events than they trace.
>>
>> Yes. The normal state for a trace point is to be off, the normal state for a
>> record point is to be recording but not tracing.
>>
>>>
>>> If you do the recorder as a trace backend, then the existing UI to
>>> control what's being traced becomes UI to control what's being recorded
>>> by the recorder and traced by everything else.  Confusing, and we're
>>> short one UI to control what's being traced by the recorder.
>>>
>>> Perhaps doing the recorder as a trace backend is simply a bad idea.
>>> Perhaps it should be integrated in the trace subsystem differently, so
>>> that trace-enable continues to control what's being traced for all
>>> backends.
>>
>> That means you don't benefit from any of the existing trace points.
>>
>> As an aside, the existing tracing system has the trace points in a different
>> file than the actual code. In other words, we have something like:
>>
>>     # ioport.c
>>     cpu_in(unsigned int addr, char size, unsigned int val) "addr 0x%x(%c) value %u"
>>     cpu_out(unsigned int addr, char size, unsigned int val) "addr 0x%x(%c) value %u"
>>
>> and in ioport.c we have:
>>
>>     trace_cpu_in(addr, 'b', val);
>>
>> The recorder native approach would be something like:
>>
>>     trace(cpu_in, "addr 0x%x(%c) value %u", addr, 'b', val);
>>
>> Is the current syntax an artifact of how tracetool works, or is it intentional?
>
> I'm not sure.  A bit of both?
>
> The separate trace-events file makes generating code for events simple
> and easy.
>
> Some backends heavily rely on code generation.  The recorder backend
> seems not to.  Code generation includes the .dtrace generated with
> backend dtrace.
>
>>> Perhaps the recorder should emit the events it traces to a trace
>>> backend.
>>
>> Ah, interesting. The recorder has a configurable output, so it is somewhat
>> trivial to connect to some generated function that calls the various trace
>> backends.
>>
>>>
>>>>>     3. Real-time graphing / control, using the recorder_scope application
>>>>>
>>>>> I'm ignoring this one for now.
>>>>>
>>>>>> There are, however, new monitor commands, so now I can do:
>>>>>>
>>>>>>   recorder trace kvm_run_exit
>>>>>>
>>>>>> I now get an output where each trace shows up twice.
>>>>>>
>>>>>>   [120139718 137.127269] kvm_run_exit: cpu_index 0, reason 2
>>>>>>   2091091@1595518954.209803:kvm_run_exit cpu_index 0, reason 2
>>>>>>   [120139734 137.127281] kvm_run_exit: cpu_index 0, reason 2
>>>>>>   2091091@1595518954.209814:kvm_run_exit cpu_index 0, reason 2
>>>>>>   [120139751 137.127293] kvm_run_exit: cpu_index 0, reason 2
>>>>>>
>>>>>>  I don't find particularly useful, so I don't think having that as the
>>>>>> normal behaviour would qualify as what you called proper integration.
>>>>>
>>>>> Well, I asked for it by configuring two trace backends, didn't I?
>>>>
>>>> Not really IMO. By configuring two trace backends, what you requested was to
>>>> have two different kinds of instrumentation active at the same time. It does
>>>> not imply (at least to me) that these two kinds of instrumentation have to
>>>> react to *run-time* configuration identically, in particular if that means
>>>> in a way that happens to not be helpful.
>>>>
>>>> If you configure log and ftrace, you are not requesting them to behave
>>>> identically at run time.
>>>
>>> No, but by configuring two trace backends, you ask each one to do its
>>> thing.  If "its thing" includes printing to stderr for both, then
>>> getting events printed twice is exactly what you asked for.
>>
>> I think that you are arguing that since trace-event currently activates or
>> disables all trace back-ends at once, then that's necessarily what I asked
>> for.
>>
>> There is a nice ambiguity about the word "asked for" here, but that's
>> definitely not what I would like. I described this behavior as unhelpful.
>>
>> However, addressing that correctly may indeed belong to the common code
>> rather than to individual backends, I'll certainly grant you that.
>>
>>
>>>
>>>>> If I configured just the recorder backend, would I get a useful trace?
>>>>
>>>> Yes, but not the full functionality that "recorder" gives you.
>>>> Notably, there is nothing in the existing trace-event command that would
>>>> allow me to configure recorder sharing or trace output format, whereas the
>>>> proposed patch allows me to do that.
>>>
>>> Christophe, leave that windmill alone!  I'm over here!  ;)
>>
>> ;-)
>>
>>
>>> I'm not trying to shoot down commands specific to trace backends.  I'm
>>> trying to understand how the proposed recorder backend interacts with
>>> the existing tracing UI and infrastructure, so I can figure out how to
>>> best fit it with the existing UI and infrastructure.
>>>
>>> QEMU's tracing subsystem consists of a common, backend-independent part
>>> and backends.
>>>
>>> Command trace-event controls one aspect of the common part: whether to
>>> hand the trace event to the backend or not.  The backend has no say in
>>> that.
>
> I was confused.  Honoring the enabled bit is actually up to the backend.
>
>> This is the part I changed in the patch, because there is already a
>> mechanism to activate / deactivate tracing in the recorder, so having two
>> 'if(condition)' testing essentially the same condition using two different
>> flags seems useless.
>>
>>>
>>> Command trace-file controls one aspect of the backend: writing output to
>>> a file.  Only the simple backend makes use of it, but that's detail.
>>>
>>> You tell me the recorder backend needs to expose more configuration to
>>> really make sense.  The question isn't whether that's true (I trust you
>>> on that), it's how to best integrate it with what we have.
>>
>> You gave me a number of interesting ideas. Let me get back to you with a new
>> spin. You can tell me which one you prefer. I also made a couple of changes
>> to the recorder itself to make future qemu integration easier.
>>
>>>
>>>>> If yes, what's wrong with letting me control what's being traced with
>>>>> the common trace-event command in addition to a backend-specific
>>>>> command?
>>>>
>>>> This would force that code to a lower common denominator that would remove a
>>>> lot of useful functionality specific to the recorder, even assuming we keep
>>>> both the "recorder" and "trace-event" commands to configure the recorder.
>>>>
>>>> There is a problem with the semantics of the underlying API. For example,
>>>> disabling trace foo is "-foo" in qemu, "foo=0" in the recorder API. I don't
>>>> really like the idea of adding some string manipulation code to transform
>>>> "-foo" into "foo=0". I would prefer to extend the recorder API to accept
>>>> -foo, but that's not the case today.
>>>
>>> You're talking about the configuration file specified with trace
>>> events=...
>>>
>>> The existing UI for the recorder library is different.  Hardly a
>>> surprise.
>>>
>>> Consistency between the existing UI for the common part and the new UI
>>> for the recorder backend is quite desirable.  I'm not making it a hard
>>> requirement.  I would like to see concrete ideas on how to get it,
>>> though.
>>
>> Here what can be done, but it's a larger undertaking:
>>
>> - Convert named trace entry points to anonymous trace(...) calls following a
>>   syntax similar to record(...), so that traces are readable in one place.
>>
>> - Have a mechanism for trace activation / deactivation that delegates to the
>>   trace back-end. That way, any ugly recorder-specific string manipulation
>>   converting regexps and such will be in the back-end, not in common code.
>>
>> - When multiple trace back-ends are configured, make it possible to
>>   configure them independently, ideally using back-end specific options
>>
>> - Add some notion of back-end specific option, to implement back-end
>>   specific configurations like trace-file or recorder_dump_on_signal.
>>
>> - Split the notion of "trace" and "record", and add some "record"
>>   semantics. Some existing backends already are closer to record semantics,
>>   e.g. ftrace.
>>
>> - Convert the existing DPRINTF stuff to trace().
>
> Plenty of ideas.  I'd recommend to wait for Stefan's opinion before you
> run with them.

Yes. And not just Stefan's.

My point is I agree with you better integration is desirable, but it's a
relatively long process. It looks to me, for example, like other back-ends
also have recording features. So we could really expose the two features,
and slowly shift towards tracing/recording back=ends.

--
Cheers,
Christophe de Dinechin (IRC c3d)

[PATCH v2 3/3] trace: Example of "centralized" recorder tracing

[Christophe de Dinechin]

This is an example showing how the recorder can be used to have one
"topic" covering multiple entries. Here, the topic is "lock".

Here are a few use cases:

- Checking locks:
    RECORDER_TRACES=lock qemu
- Graphic visualization of locks:
    RECORDER_TRACES="lock=state,id" qemu &
    recorder_scope state
    <Hit the 't' key to toggle timing display>
    <Hit the 'c' key to dump the screen data as CSV>
    cat recorder_scope_data-1.csv

Signed-off-by: Christophe de Dinechin <dinechin@redhat.com>
---
 util/qemu-thread-common.h | 7 +++++++
 1 file changed, 7 insertions(+)

diff --git a/util/qemu-thread-common.h b/util/qemu-thread-common.h
index 2af6b12085..0de07a471f 100644
--- a/util/qemu-thread-common.h
+++ b/util/qemu-thread-common.h
@@ -15,6 +15,9 @@
 
 #include "qemu/thread.h"
 #include "trace.h"
+#include "trace/recorder.h"
+
+RECORDER_DEFINE(lock, 16, "Lock state");
 
 static inline void qemu_mutex_post_init(QemuMutex *mutex)
 {
@@ -23,12 +26,14 @@ static inline void qemu_mutex_post_init(QemuMutex *mutex)
     mutex->line = 0;
 #endif
     mutex->initialized = true;
+    record(lock, "Init state %d for %p", -1, mutex);
 }
 
 static inline void qemu_mutex_pre_lock(QemuMutex *mutex,
                                        const char *file, int line)
 {
     trace_qemu_mutex_lock(mutex, file, line);
+    record(lock, "Locking state %d for %p", 1, mutex);
 }
 
 static inline void qemu_mutex_post_lock(QemuMutex *mutex,
@@ -39,6 +44,7 @@ static inline void qemu_mutex_post_lock(QemuMutex *mutex,
     mutex->line = line;
 #endif
     trace_qemu_mutex_locked(mutex, file, line);
+    record(lock, "Locked state %d for %p", 2, mutex);
 }
 
 static inline void qemu_mutex_pre_unlock(QemuMutex *mutex,
@@ -49,6 +55,7 @@ static inline void qemu_mutex_pre_unlock(QemuMutex *mutex,
     mutex->line = 0;
 #endif
     trace_qemu_mutex_unlock(mutex, file, line);
+    record(lock, "Unkocked state %d for %p", 0, mutex);
 }
 
 #endif
-- 
2.26.2

Re: [PATCH v2 3/3] trace: Example of "centralized" recorder tracing

[Daniel P. Berrangé]

On Fri, Jun 26, 2020 at 06:27:06PM +0200, Christophe de Dinechin wrote:
> This is an example showing how the recorder can be used to have one
> "topic" covering multiple entries. Here, the topic is "lock".
> 
> Here are a few use cases:
> 
> - Checking locks:
>     RECORDER_TRACES=lock qemu
> - Graphic visualization of locks:
>     RECORDER_TRACES="lock=state,id" qemu &
>     recorder_scope state
>     <Hit the 't' key to toggle timing display>
>     <Hit the 'c' key to dump the screen data as CSV>
>     cat recorder_scope_data-1.csv
> 
> Signed-off-by: Christophe de Dinechin <dinechin@redhat.com>
> ---
>  util/qemu-thread-common.h | 7 +++++++
>  1 file changed, 7 insertions(+)
> 
> diff --git a/util/qemu-thread-common.h b/util/qemu-thread-common.h
> index 2af6b12085..0de07a471f 100644
> --- a/util/qemu-thread-common.h
> +++ b/util/qemu-thread-common.h
> @@ -15,6 +15,9 @@
>  
>  #include "qemu/thread.h"
>  #include "trace.h"
> +#include "trace/recorder.h"
> +
> +RECORDER_DEFINE(lock, 16, "Lock state");
>  
>  static inline void qemu_mutex_post_init(QemuMutex *mutex)
>  {
> @@ -23,12 +26,14 @@ static inline void qemu_mutex_post_init(QemuMutex *mutex)
>      mutex->line = 0;
>  #endif
>      mutex->initialized = true;
> +    record(lock, "Init state %d for %p", -1, mutex);
>  }
>  
>  static inline void qemu_mutex_pre_lock(QemuMutex *mutex,
>                                         const char *file, int line)
>  {
>      trace_qemu_mutex_lock(mutex, file, line);
> +    record(lock, "Locking state %d for %p", 1, mutex);
>  }
>  
>  static inline void qemu_mutex_post_lock(QemuMutex *mutex,
> @@ -39,6 +44,7 @@ static inline void qemu_mutex_post_lock(QemuMutex *mutex,
>      mutex->line = line;
>  #endif
>      trace_qemu_mutex_locked(mutex, file, line);
> +    record(lock, "Locked state %d for %p", 2, mutex);
>  }
>  
>  static inline void qemu_mutex_pre_unlock(QemuMutex *mutex,
> @@ -49,6 +55,7 @@ static inline void qemu_mutex_pre_unlock(QemuMutex *mutex,
>      mutex->line = 0;
>  #endif
>      trace_qemu_mutex_unlock(mutex, file, line);
> +    record(lock, "Unkocked state %d for %p", 0, mutex);
>  }

IMHO the whole point of having the pluggable trace backend impls, is
precisely that we don't have to add multiple different calls in the
code. A single trace_qemu_mutex_unlock() is supposed to work with
any backend.

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: [PATCH v2 3/3] trace: Example of "centralized" recorder tracing

[Stefan Hajnoczi]

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

On Tue, Jun 30, 2020 at 01:41:36PM +0100, Daniel P. Berrangé wrote:
> On Fri, Jun 26, 2020 at 06:27:06PM +0200, Christophe de Dinechin wrote:
> IMHO the whole point of having the pluggable trace backend impls, is
> precisely that we don't have to add multiple different calls in the
> code. A single trace_qemu_mutex_unlock() is supposed to work with
> any backend.

I think an exception is okay when the other trace backends do not offer
equivalent functionality.

Who knows if anyone other than Christophe will use this functionality,
but it doesn't cost much to allow it.

Stefan

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

Re: [PATCH v2 3/3] trace: Example of "centralized" recorder tracing

[Daniel P. Berrangé]

On Wed, Jul 01, 2020 at 05:09:06PM +0100, Stefan Hajnoczi wrote:
> On Tue, Jun 30, 2020 at 01:41:36PM +0100, Daniel P. Berrangé wrote:
> > On Fri, Jun 26, 2020 at 06:27:06PM +0200, Christophe de Dinechin wrote:
> > IMHO the whole point of having the pluggable trace backend impls, is
> > precisely that we don't have to add multiple different calls in the
> > code. A single trace_qemu_mutex_unlock() is supposed to work with
> > any backend.
> 
> I think an exception is okay when the other trace backends do not offer
> equivalent functionality.
> 
> Who knows if anyone other than Christophe will use this functionality,
> but it doesn't cost much to allow it.

This patch is just an example though, suggesting this kind of usage is
expected to done in other current trace probe locations. The trace wrapper
has most of the information required already including a format string,
so I'd think it could be wired up to the generator so we don't add extra
record() statements through the codebase. At most it should require an
extra annotation in the trace-events file to take the extra parameter
for grouping, and other trace backends can ignore that.

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: [PATCH v2 3/3] trace: Example of "centralized" recorder tracing

[Stefan Hajnoczi]

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

On Wed, Jul 01, 2020 at 05:15:01PM +0100, Daniel P. Berrangé wrote:
> On Wed, Jul 01, 2020 at 05:09:06PM +0100, Stefan Hajnoczi wrote:
> > On Tue, Jun 30, 2020 at 01:41:36PM +0100, Daniel P. Berrangé wrote:
> > > On Fri, Jun 26, 2020 at 06:27:06PM +0200, Christophe de Dinechin wrote:
> > > IMHO the whole point of having the pluggable trace backend impls, is
> > > precisely that we don't have to add multiple different calls in the
> > > code. A single trace_qemu_mutex_unlock() is supposed to work with
> > > any backend.
> > 
> > I think an exception is okay when the other trace backends do not offer
> > equivalent functionality.
> > 
> > Who knows if anyone other than Christophe will use this functionality,
> > but it doesn't cost much to allow it.
> 
> This patch is just an example though, suggesting this kind of usage is
> expected to done in other current trace probe locations. The trace wrapper
> has most of the information required already including a format string,
> so I'd think it could be wired up to the generator so we don't add extra
> record() statements through the codebase. At most it should require an
> extra annotation in the trace-events file to take the extra parameter
> for grouping, and other trace backends can ignore that.

It's true, it may be possible to put this functionality in the
trace-events.

Christophe: how does this differ from regular trace events and what
extra information is needed?

Stefan

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

Re: [PATCH v2 3/3] trace: Example of "centralized" recorder tracing

[Christophe de Dinechin]

On 2020-07-02 at 15:47 CEST, Stefan Hajnoczi wrote...
> On Wed, Jul 01, 2020 at 05:15:01PM +0100, Daniel P. Berrangé wrote:
>> On Wed, Jul 01, 2020 at 05:09:06PM +0100, Stefan Hajnoczi wrote:
>> > On Tue, Jun 30, 2020 at 01:41:36PM +0100, Daniel P. Berrangé wrote:
>> > > On Fri, Jun 26, 2020 at 06:27:06PM +0200, Christophe de Dinechin wrote:
>> > > IMHO the whole point of having the pluggable trace backend impls, is
>> > > precisely that we don't have to add multiple different calls in the
>> > > code. A single trace_qemu_mutex_unlock() is supposed to work with
>> > > any backend.
>> >
>> > I think an exception is okay when the other trace backends do not offer
>> > equivalent functionality.
>> >
>> > Who knows if anyone other than Christophe will use this functionality,
>> > but it doesn't cost much to allow it.
>>
>> This patch is just an example though, suggesting this kind of usage is
>> expected to done in other current trace probe locations. The trace wrapper
>> has most of the information required already including a format string,
>> so I'd think it could be wired up to the generator so we don't add extra
>> record() statements through the codebase.

The primary purpose of the recorder is post-mortem dumps, flight recorder
style. Tracing is only a secondary benefit. Not sure if it's worth making a
distinction between events you want to record and those you want to trace.
(Example: You might want to record all command line options, but almost
never trace them)

> At most it should require an
>> extra annotation in the trace-events file to take the extra parameter
>> for grouping, and other trace backends can ignore that.
>
> It's true, it may be possible to put this functionality in the
> trace-events.

Let me think more about integrating these features with other trace
backends. See below for short-term impact.

> Christophe: how does this differ from regular trace events and what
> extra information is needed?

- Grouping, as indicated above, mostly useful in practice to make selection
  of tracing topics easy (e.g. "modules") but also for real-time graphing,
  because typically a state change occurs in different functions, which is
  why I used locking as an example.

- Self-documentation. Right now, the recorder back-end generates rather
  unhelpful help messages.

- Trace buffer size. This is important to make post-mortem dumps usable if
  you record infrequent events alongside much higher-rate ones. For example,
  you may want a large buffer to record info about command-line option
  processing, the default 8 is definitely too small.

- Support for %+s, which tells that a string is safe to print later (e.g. it
  is a compile-time constant, or never ever freed).

- Support for custom formats, e.g. I use %v in the XL compiler for LLVM
  value pointers. This is a bit more advanced, but it would be neat to be
  able to print out QOM objects using %q :-)

For the short term, what about providing trace-named wrappers around these
additional recorder features?

--
Cheers,
Christophe de Dinechin (IRC c3d)

Re: [PATCH v2 3/3] trace: Example of "centralized" recorder tracing

[Daniel P. Berrangé]

On Fri, Jul 03, 2020 at 12:12:14PM +0200, Christophe de Dinechin wrote:
> 
> On 2020-07-02 at 15:47 CEST, Stefan Hajnoczi wrote...
> > On Wed, Jul 01, 2020 at 05:15:01PM +0100, Daniel P. Berrangé wrote:
> > At most it should require an
> >> extra annotation in the trace-events file to take the extra parameter
> >> for grouping, and other trace backends can ignore that.
> >
> > It's true, it may be possible to put this functionality in the
> > trace-events.
> 
> Let me think more about integrating these features with other trace
> backends. See below for short-term impact.
> 
> > Christophe: how does this differ from regular trace events and what
> > extra information is needed?
> 
> - Grouping, as indicated above, mostly useful in practice to make selection
>   of tracing topics easy (e.g. "modules") but also for real-time graphing,
>   because typically a state change occurs in different functions, which is
>   why I used locking as an example.

In many cases we already have a form of grouping via the backdoor by
using a common string prefix on trace point names. eg

qio_task_new(void *task, void *source, void *func, void *opaque) "Task new task=%p source=%p func=%p opaque=%p"
qio_task_complete(void *task) "Task complete task=%p"
qio_task_thread_start(void *task, void *worker, void *opaque) "Task thread start task=%p worker=%p opaque=%p"
qio_task_thread_run(void *task) "Task thread run task=%p"
qio_task_thread_exit(void *task) "Task thread exit task=%p"
qio_task_thread_result(void *task) "Task thread result task=%p"
qio_task_thread_source_attach(void *task, void *source) "Task thread source attach task=%p source=%p"
qio_task_thread_source_cancel(void *task, void *source) "Task thread source cancel task=%p source=%p"

We could turn this into an explicit multi-level grouping concept,
using "." separator for each level of the group. eg

qio.task.new(void *task, void *source, void *func, void *opaque) "Task new task=%p source=%p func=%p opaque=%p"
qio.task.complete(void *task) "Task complete task=%p"
qio.task.thread_start(void *task, void *worker, void *opaque) "Task thread start task=%p worker=%p opaque=%p"
qio.task.thread_run(void *task) "Task thread run task=%p"
qio.task.thread_exit(void *task) "Task thread exit task=%p"
qio.task.thread_result(void *task) "Task thread result task=%p"
qio.task.thread_source_attach(void *task, void *source) "Task thread source attach task=%p source=%p"
qio.task.thread_source_cancel(void *task, void *source) "Task thread source cancel task=%p source=%p"


For backends that dont support groups, the "." can be turned back
into a "_", and everything is unchanged. For backends that do support
groups, we now have the info required.

This would be useful for the systemtap backend because that has an
explicit grouping concept already. ie we have probes definitions
like:

probe qemu.system.x86_64.qio_task_new = process("/usr/bin/qemu-system-x86_64").mark("qio_task_new")
{
  task = $arg1;
  source = $arg2;
  func = $arg3;
  opaque = $arg4;
}


which we can now turn into

probe qemu.system.x86_64.qio.task.new = process("/usr/bin/qemu-system-x86_64").mark("qio_task_new")
{
  task = $arg1;
  source = $arg2;
  func = $arg3;
  opaque = $arg4;
}


the generated C trace macro would still use "_" not "." of course
so  qio_task_new(src, func, opaque)

> - Self-documentation. Right now, the recorder back-end generates rather
>   unhelpful help messages.

Not sure I understand the problem here.

> - Trace buffer size. This is important to make post-mortem dumps usable if
>   you record infrequent events alongside much higher-rate ones. For example,
>   you may want a large buffer to record info about command-line option
>   processing, the default 8 is definitely too small.

Sure, that's a problem for all the trace backends. They all need to be
good at filtering / controlling what probes are fired to avoid signal
getting lost in noise.  The grouping feature would certainly help with
that making it easier to control what it turned on/off.

> - Support for %+s, which tells that a string is safe to print later (e.g. it
>   is a compile-time constant, or never ever freed).

Seems we should be able to support that in the trace-events format string.
Any other backend can turn "%+s" back into a normal "%s".

> - Support for custom formats, e.g. I use %v in the XL compiler for LLVM
>   value pointers. This is a bit more advanced, but it would be neat to be
>   able to print out QOM objects using %q :-)

Seems like a similar trick can be used here. The %v/%q could be turned
back into a plain %p for backends which don't have the pretty-printing
support.

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: [PATCH v2 3/3] trace: Example of "centralized" recorder tracing

[Christophe de Dinechin]

On 2020-07-03 at 15:08 CEST, Daniel P. Berrangé wrote...
> On Fri, Jul 03, 2020 at 12:12:14PM +0200, Christophe de Dinechin wrote:
>>
>> On 2020-07-02 at 15:47 CEST, Stefan Hajnoczi wrote...
>> > On Wed, Jul 01, 2020 at 05:15:01PM +0100, Daniel P. Berrangé wrote:
>> > At most it should require an
>> >> extra annotation in the trace-events file to take the extra parameter
>> >> for grouping, and other trace backends can ignore that.
>> >
>> > It's true, it may be possible to put this functionality in the
>> > trace-events.
>>
>> Let me think more about integrating these features with other trace
>> backends. See below for short-term impact.
>>
>> > Christophe: how does this differ from regular trace events and what
>> > extra information is needed?
>>
>> - Grouping, as indicated above, mostly useful in practice to make selection
>>   of tracing topics easy (e.g. "modules") but also for real-time graphing,
>>   because typically a state change occurs in different functions, which is
>>   why I used locking as an example.
>
> In many cases we already have a form of grouping via the backdoor by
> using a common string prefix on trace point names. eg
>
> qio_task_new(void *task, void *source, void *func, void *opaque) "Task new task=%p source=%p func=%p opaque=%p"
> qio_task_complete(void *task) "Task complete task=%p"
> qio_task_thread_start(void *task, void *worker, void *opaque) "Task thread start task=%p worker=%p opaque=%p"
> qio_task_thread_run(void *task) "Task thread run task=%p"
> qio_task_thread_exit(void *task) "Task thread exit task=%p"
> qio_task_thread_result(void *task) "Task thread result task=%p"
> qio_task_thread_source_attach(void *task, void *source) "Task thread source attach task=%p source=%p"
> qio_task_thread_source_cancel(void *task, void *source) "Task thread source cancel task=%p source=%p"
>
> We could turn this into an explicit multi-level grouping concept,
> using "." separator for each level of the group. eg

Interesting idea.

>
> qio.task.new(void *task, void *source, void *func, void *opaque) "Task new task=%p source=%p func=%p opaque=%p"
> qio.task.complete(void *task) "Task complete task=%p"
> qio.task.thread_start(void *task, void *worker, void *opaque) "Task thread start task=%p worker=%p opaque=%p"
> qio.task.thread_run(void *task) "Task thread run task=%p"
> qio.task.thread_exit(void *task) "Task thread exit task=%p"
> qio.task.thread_result(void *task) "Task thread result task=%p"
> qio.task.thread_source_attach(void *task, void *source) "Task thread source attach task=%p source=%p"
> qio.task.thread_source_cancel(void *task, void *source) "Task thread source cancel task=%p source=%p"
>
>
> For backends that dont support groups, the "." can be turned back
> into a "_", and everything is unchanged. For backends that do support
> groups, we now have the info required.
>
> This would be useful for the systemtap backend because that has an
> explicit grouping concept already. ie we have probes definitions
> like:
>
> probe qemu.system.x86_64.qio_task_new = process("/usr/bin/qemu-system-x86_64").mark("qio_task_new")
> {
>   task = $arg1;
>   source = $arg2;
>   func = $arg3;
>   opaque = $arg4;
> }
>
>
> which we can now turn into
>
> probe qemu.system.x86_64.qio.task.new = process("/usr/bin/qemu-system-x86_64").mark("qio_task_new")
> {
>   task = $arg1;
>   source = $arg2;
>   func = $arg3;
>   opaque = $arg4;
> }
>
>
> the generated C trace macro would still use "_" not "." of course
> so  qio_task_new(src, func, opaque)
>
>> - Self-documentation. Right now, the recorder back-end generates rather
>>   unhelpful help messages.
>
> Not sure I understand the problem here.

RECORDER_DEFINE specifies a text that is listed when you pass "help" as a
trace name. There is no equivalent concept that I'm aware of in the existing
qemu trace infrastructure.

>
>> - Trace buffer size. This is important to make post-mortem dumps usable if
>>   you record infrequent events alongside much higher-rate ones. For example,
>>   you may want a large buffer to record info about command-line option
>>   processing, the default 8 is definitely too small.
>
> Sure, that's a problem for all the trace backends. They all need to be
> good at filtering / controlling what probes are fired to avoid signal
> getting lost in noise.  The grouping feature would certainly help with
> that making it easier to control what it turned on/off.

Well, for the recorder it's a slightly different problem. When you do a
recorder post-mortem dump, entries are sorted and printed at that time. THis
makes it possible to have a number of recent traces for high-frequency
events, as well as some much older traces for low-frequency events.

For example, you can have a buffer that records command-line options, and
another that records events that occur typically once per second, and yet
another that records high-frequency events. Then, when your program crashes
and you look at a dump, you see a context that includes both recent
high-frequency stuff as well as much older low-frequency events.

See https://gitlab.com/c3d/recorder for examples.


>
>> - Support for %+s, which tells that a string is safe to print later (e.g. it
>>   is a compile-time constant, or never ever freed).
>
> Seems we should be able to support that in the trace-events format string.
> Any other backend can turn "%+s" back into a normal "%s".

Yes, but it's much more complicated than this simple patch series ;-) As is,
the goal of this series is to not touch any other back-end.

>
>> - Support for custom formats, e.g. I use %v in the XL compiler for LLVM
>>   value pointers. This is a bit more advanced, but it would be neat to be
>>   able to print out QOM objects using %q :-)
>
> Seems like a similar trick can be used here. The %v/%q could be turned
> back into a plain %p for backends which don't have the pretty-printing
> support.

Sure, but this is also touching the rest of the tracing infrastructure,
which was a definite non-goal for this specific series.

>
> Regards,
> Daniel


--
Cheers,
Christophe de Dinechin (IRC c3d)

Re: [PATCH v2 3/3] trace: Example of "centralized" recorder tracing

[Stefan Hajnoczi]

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

On Fri, Jun 26, 2020 at 06:27:06PM +0200, Christophe de Dinechin wrote:
> This is an example showing how the recorder can be used to have one
> "topic" covering multiple entries. Here, the topic is "lock".
> 
> Here are a few use cases:
> 
> - Checking locks:
>     RECORDER_TRACES=lock qemu
> - Graphic visualization of locks:
>     RECORDER_TRACES="lock=state,id" qemu &
>     recorder_scope state
>     <Hit the 't' key to toggle timing display>
>     <Hit the 'c' key to dump the screen data as CSV>
>     cat recorder_scope_data-1.csv
> 
> Signed-off-by: Christophe de Dinechin <dinechin@redhat.com>
> ---
>  util/qemu-thread-common.h | 7 +++++++
>  1 file changed, 7 insertions(+)

Reviewed-by: Stefan Hajnoczi <stefanha@redhat.com>

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

Re: [PATCH v2 0/3] trace: Add a trace backend for the recorder library

[no-reply]

Patchew URL: https://patchew.org/QEMU/20200626162706.3304357-1-dinechin@redhat.com/



Hi,

This series seems to have some coding style problems. See output below for
more information:

Subject: [PATCH v2 0/3] trace: Add a trace backend for the recorder library
Type: series
Message-id: 20200626162706.3304357-1-dinechin@redhat.com

=== TEST SCRIPT BEGIN ===
#!/bin/bash
git rev-parse base > /dev/null || exit 0
git config --local diff.renamelimit 0
git config --local diff.renames True
git config --local diff.algorithm histogram
./scripts/checkpatch.pl --mailback base..
=== TEST SCRIPT END ===

Updating 3c8cf5a9c21ff8782164d1def7f44bd888713384
From https://github.com/patchew-project/qemu
   10f7ffa..87fb952  master     -> master
 - [tag update]      patchew/20200626151424.30117-1-peter.maydell@linaro.org -> patchew/20200626151424.30117-1-peter.maydell@linaro.org
 * [new tag]         patchew/20200626162706.3304357-1-dinechin@redhat.com -> patchew/20200626162706.3304357-1-dinechin@redhat.com
Switched to a new branch 'test'
850bed5 trace: Example of "centralized" recorder tracing
1f9a8da trace: Add support for recorder back-end
76dd7c6 Makefile: Compute libraries for libqemuutil.a and libvhost-user.a

=== OUTPUT BEGIN ===
1/3 Checking commit 76dd7c67fe5e (Makefile: Compute libraries for libqemuutil.a and libvhost-user.a)
2/3 Checking commit 1f9a8daea6eb (trace: Add support for recorder back-end)
WARNING: added, moved or deleted file(s), does MAINTAINERS need updating?
#130: 
new file mode 100644

WARNING: line over 80 characters
#182: FILE: scripts/tracetool/backend/recorder.py:48:
+        out('RECORDER_DEFINE(%(name)s, 8, "Tracetool recorder for %(api)s(%(args)s)");',

ERROR: do not use C99 // comments
#247: FILE: trace/recorder.c:18:
+    // Allow a dump in case we receive some unhandled signal

ERROR: do not use C99 // comments
#248: FILE: trace/recorder.c:19:
+    // For example, send USR2 to a hung process to get a dump

ERROR: braces {} are necessary for all arms of this statement
#249: FILE: trace/recorder.c:20:
+    if (getenv("RECORDER_TRACES"))
[...]

ERROR: space required after that ',' (ctx:VxV)
#250: FILE: trace/recorder.c:21:
+        recorder_dump_on_common_signals(0,0);
                                          ^

ERROR: do not use C99 // comments
#281: FILE: trace/recorder.h:24:
+// Disable recorder macros

ERROR: do not use C99 // comments
#289: FILE: trace/recorder.h:32:
+#endif // CONFIG_TRACE_RECORDER

ERROR: do not use C99 // comments
#291: FILE: trace/recorder.h:34:
+#endif // TRACE_RECORDER_H

ERROR: do not use C99 // comments
#312: FILE: util/module.c:158:
+        // New recorders may have been pulled in, activate them if necessary

total: 8 errors, 2 warnings, 237 lines checked

Patch 2/3 has style problems, please review.  If any of these errors
are false positives report them to the maintainer, see
CHECKPATCH in MAINTAINERS.

3/3 Checking commit 850bed523e63 (trace: Example of "centralized" recorder tracing)
=== OUTPUT END ===

Test command exited with code: 1


The full log is available at
http://patchew.org/logs/20200626162706.3304357-1-dinechin@redhat.com/testing.checkpatch/?type=message.
---
Email generated automatically by Patchew [https://patchew.org/].
Please send your feedback to patchew-devel@redhat.com

Re: [PATCH v2 0/3] trace: Add a trace backend for the recorder library

[Stefan Hajnoczi]

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

On Fri, Jun 26, 2020 at 06:27:03PM +0200, Christophe de Dinechin wrote:
> The recorder library implements low-cost always-on tracing, with three
> usage models:
> 
> 1. Flight recorder: Dump information on recent events in case of crash
> 2. Tracing: Individual traces can be enabled using environment variables
> 3. Real-time graphing / control, using the recorder_scope application
> 
> This short series introduces a new "recorder" back-end which connects
> to the recorder. Traces using the recorder are intentionally "always on".
> An example is given of how the recorder can also be used separately
> from generated traces. This can be useful if you want to enable
> multiple related traces for a particular topic.
> 
> This series requires a small makefile fix submitted earlier, included
> here for convenience.
> 
> Christophe de Dinechin (3):
>   Makefile: Compute libraries for libqemuutil.a and libvhost-user.a
>   trace: Add support for recorder back-end
>   trace: Example of "centralized" recorder tracing

Please add a build to .travis.yml that enables recorder. That way we'll
catch build failures.

Thanks,
Stefan

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

Re: [PATCH v2 0/3] trace: Add a trace backend for the recorder library

[Christophe de Dinechin]

On 2020-06-30 at 14:59 CEST, Stefan Hajnoczi wrote...
> On Fri, Jun 26, 2020 at 06:27:03PM +0200, Christophe de Dinechin wrote:
>> The recorder library implements low-cost always-on tracing, with three
>> usage models:
>>
>> 1. Flight recorder: Dump information on recent events in case of crash
>> 2. Tracing: Individual traces can be enabled using environment variables
>> 3. Real-time graphing / control, using the recorder_scope application
>>
>> This short series introduces a new "recorder" back-end which connects
>> to the recorder. Traces using the recorder are intentionally "always on".
>> An example is given of how the recorder can also be used separately
>> from generated traces. This can be useful if you want to enable
>> multiple related traces for a particular topic.
>>
>> This series requires a small makefile fix submitted earlier, included
>> here for convenience.
>>
>> Christophe de Dinechin (3):
>>   Makefile: Compute libraries for libqemuutil.a and libvhost-user.a
>>   trace: Add support for recorder back-end
>>   trace: Example of "centralized" recorder tracing
>
> Please add a build to .travis.yml that enables recorder. That way we'll
> catch build failures.

There is no recorder package in Xenial.

>
> Thanks,
> Stefan



--
Cheers,
Christophe de Dinechin (IRC c3d)

Re: [PATCH v2 0/3] trace: Add a trace backend for the recorder library

[Daniel P. Berrangé]

On Fri, Jul 03, 2020 at 12:37:02PM +0200, Christophe de Dinechin wrote:
> 
> On 2020-06-30 at 14:59 CEST, Stefan Hajnoczi wrote...
> > On Fri, Jun 26, 2020 at 06:27:03PM +0200, Christophe de Dinechin wrote:
> >> The recorder library implements low-cost always-on tracing, with three
> >> usage models:
> >>
> >> 1. Flight recorder: Dump information on recent events in case of crash
> >> 2. Tracing: Individual traces can be enabled using environment variables
> >> 3. Real-time graphing / control, using the recorder_scope application
> >>
> >> This short series introduces a new "recorder" back-end which connects
> >> to the recorder. Traces using the recorder are intentionally "always on".
> >> An example is given of how the recorder can also be used separately
> >> from generated traces. This can be useful if you want to enable
> >> multiple related traces for a particular topic.
> >>
> >> This series requires a small makefile fix submitted earlier, included
> >> here for convenience.
> >>
> >> Christophe de Dinechin (3):
> >>   Makefile: Compute libraries for libqemuutil.a and libvhost-user.a
> >>   trace: Add support for recorder back-end
> >>   trace: Example of "centralized" recorder tracing
> >
> > Please add a build to .travis.yml that enables recorder. That way we'll
> > catch build failures.
> 
> There is no recorder package in Xenial.

Our .gitlab-ci.yml is going to start using the containers built from
tests/docker/dockerfiles. So if you add the package to the dockerfiles
that support it we can get coverage that way. I presume it'll need the
.gitlab-ci.yml modified to add the extra configure arg too.


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 :|