| Message ID | 20200626162706.3304357-3-dinechin@redhat.com (mailing list archive) |
|---|---|
| State | New, archived |
| Headers | show |
| Series | trace: Add a trace backend for the recorder library | expand |
* 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
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.
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
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)
* 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
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)
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. [...]
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)
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.
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)
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. [,,,]
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)
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.
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)
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);
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