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

[Markus Armbruster]

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

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

Makes sense.

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

We need proper integration with the existing trace UI.

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

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

We can talk about leaving gaps for later.

I recommend to start with QMP.

[...]