[PATCH v3 0/2] trace: Add a trace backend for the recorder library

[PATCH v3 0/2] 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",
because the recorder library is primarily designed to record
information for later playback in case of crash, tracing being only a
secondary capability.

An example is given of how the recorder can also be used separately
from generated traces. The example uses locking, which can make sense
for both post-mortem and real-time graphing.

Changes in v3:
* Address coding style issues (C++ comments, wrong include, etc)
* Fix args type for HMP command (for now, still a single command)
* Add basic help for HMP command
* Use pkg-config for recorder information. This requires recorder
  1.0.10 or later.

Later patches wil address larger topics that were discussed that
would impact other tracing mechanisms, as well as GitHub / GitLab
build tests.

Christophe de Dinechin (2):
  trace: Add support for recorder back-end
  trace: Example of non-tracing recorder use

 configure                             | 14 ++++++++
 hmp-commands.hx                       | 23 +++++++++++-
 monitor/misc.c                        | 27 ++++++++++++++
 scripts/tracetool/backend/recorder.py | 52 +++++++++++++++++++++++++++
 trace/Makefile.objs                   |  1 +
 trace/control.c                       |  7 ++++
 trace/recorder.c                      | 25 +++++++++++++
 trace/recorder.h                      | 32 +++++++++++++++++
 util/module.c                         |  8 +++++
 util/qemu-thread-common.h             |  7 ++++
 10 files changed, 195 insertions(+), 1 deletion(-)
 create mode 100644 scripts/tracetool/backend/recorder.py
 create mode 100644 trace/recorder.c
 create mode 100644 trace/recorder.h

-- 
2.26.2

[PATCH v3 1/2] 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 or unexpected condition.

In this series, minimal recorder support in qemu is implemented using
the existing tracing interface. For each trace, a corresponding
recorder is created with a generic name and a default size of 8 entries.

In addition, it is possible to explicitly enable recorders that are
not qemu traces, for example in order to use actually record events
rather than trace them, or to use the real-time graphing capabilities.
For that reason, a limited set of recorder-related macros are defined
as no-ops even if the recorder trace backend is not configured.

Recorder-specific features, notably the ability to perform a
post-mortem dump and to group traces by topic, are not integrated in
this series, as doing so would require modifying the trace
infrastructure, which is a non-objective here. This may be the topic
of later series if there is any interest for it.

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
  give that command a recorder name, to only dump that recorder.
* 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                             | 14 ++++++++
 hmp-commands.hx                       | 23 +++++++++++-
 monitor/misc.c                        | 27 ++++++++++++++
 scripts/tracetool/backend/recorder.py | 52 +++++++++++++++++++++++++++
 trace/Makefile.objs                   |  1 +
 trace/control.c                       |  7 ++++
 trace/recorder.c                      | 25 +++++++++++++
 trace/recorder.h                      | 32 +++++++++++++++++
 util/module.c                         |  8 +++++
 9 files changed, 188 insertions(+), 1 deletion(-)
 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 8a65240d4a..3c30f2defd 100755
--- a/configure
+++ b/configure
@@ -7727,6 +7727,20 @@ fi
 if have_backend "log"; then
   echo "CONFIG_TRACE_LOG=y" >> $config_host_mak
 fi
+if have_backend "recorder"; then
+    recorder_minver="1.0.10"
+    if $pkg_config --atleast-version=$recorder_minver recorder ; then
+        recorder_cflags="$($pkg_config --cflags recorder)"
+        recorder_libs="$($pkg_config --libs recorder)"
+        LIBS="$recorder_libs $LIBS"
+        libs_qga="$recorder_libs $libs_qga"
+        QEMU_CFLAGS="$QEMU_CFLAGS $recorder_cflags"
+        zstd="yes"
+        echo "CONFIG_TRACE_RECORDER=y" >> $config_host_mak
+    else
+        feature_not_found "recorder" "Install recorder-devel package"
+    fi
+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 d548a3ab74..f164ff6d65 100644
--- a/hmp-commands.hx
+++ b/hmp-commands.hx
@@ -302,6 +302,28 @@ SRST
   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:s?",
+        .params     = "trace|dump [arg]",
+        .help       = "trace selected recorders or print recorder dump",
+        .cmd        = hmp_recorder,
+    },
+
+SRST
+``trace`` *cmds*
+  Activate or deactivate tracing for individual recorder traces.
+  See recorder_trace_set(3) for the syntax of *cmds*
+  For example, to activate trace ``foo`` and disable alll traces
+  ending in ``_warning``, use ``foo:.*_warning=0``.
+  Using ``help`` will list available traces and their current setting.
+``dump`` [*name*]
+  Dump the recorder. If *name* is given, only the specific named recorder
+  will be dumped.
+ERST
 #endif
 
     {
@@ -1828,4 +1850,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..82d983ff31
--- /dev/null
+++ b/scripts/tracetool/backend/recorder.py
@@ -0,0 +1,52 @@
+# -*- 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..13667e98d5 100644
--- a/trace/Makefile.objs
+++ b/trace/Makefile.objs
@@ -54,6 +54,7 @@ $(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
 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..e1859c2cf2
--- /dev/null
+++ b/trace/recorder.c
@@ -0,0 +1,25 @@
+/*
+ * 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 "qemu/osdep.h"
+#include "trace/recorder.h"
+
+RECORDER_CONSTRUCTOR
+void recorder_trace_init(void)
+{
+    const char *traces = getenv("RECORDER_TRACES");
+    recorder_trace_set(traces);
+
+    /* Allow a dump in case we receive some unhandled signal
+       For example, send USR2 to a hung process to get a dump */
+    if (traces) {
+        recorder_dump_on_common_signals(0, 0);
+    }
+}
diff --git a/trace/recorder.h b/trace/recorder.h
new file mode 100644
index 0000000000..a531dc284a
--- /dev/null
+++ b/trace/recorder.h
@@ -0,0 +1,32 @@
+/*
+ * 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
+
+#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

[PATCH v3 2/2] trace: Example of non-tracing recorder use

[Christophe de Dinechin]

This patch is a simple example showing how the recorder can be used to
have one "topic" covering multiple entries. Here, the topic is "lock",
the idea being to have the latest lock changes for instance in case of
a crash or hang.

Here are a few use cases:

* Tracing  lock updates:
    RECORDER_TRACES=lock qemu
* Showing lock changes prior to a hang
    RECORDER_TRACES=lock qemu &
    # Wait until hang
    killall -USR2 qemu  # This will trigger a dump
* Graphic visualization of lock states:
    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 v3 0/2] trace: Add a trace backend for the recorder library

[no-reply]

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



Hi,

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

Subject: [PATCH v3 0/2] trace: Add a trace backend for the recorder library
Type: series
Message-id: 20200706170255.1165105-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
Switched to a new branch 'test'
26ef33b trace: Example of non-tracing recorder use
64ee20b trace: Add support for recorder back-end

=== OUTPUT BEGIN ===
1/2 Checking commit 64ee20b304ab (trace: Add support for recorder back-end)
WARNING: added, moved or deleted file(s), does MAINTAINERS need updating?
#148: 
new file mode 100644

WARNING: Block comments use a leading /* on a separate line
#267: FILE: trace/recorder.c:20:
+    /* Allow a dump in case we receive some unhandled signal

WARNING: Block comments use * on subsequent lines
#268: FILE: trace/recorder.c:21:
+    /* Allow a dump in case we receive some unhandled signal
+       For example, send USR2 to a hung process to get a dump */

WARNING: Block comments use a trailing */ on a separate line
#268: FILE: trace/recorder.c:21:
+       For example, send USR2 to a hung process to get a dump */

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

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

total: 2 errors, 4 warnings, 245 lines checked

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

2/2 Checking commit 26ef33b3f9e1 (trace: Example of non-tracing recorder use)
=== OUTPUT END ===

Test command exited with code: 1


The full log is available at
http://patchew.org/logs/20200706170255.1165105-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