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

[Markus Armbruster]

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

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

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

Name yours trace-recorder?

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

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

>From your cover letter:

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

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

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

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

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

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

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

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

I'm ignoring this one for now.

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

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

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

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

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

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

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

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

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

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

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

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

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

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