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

[Markus Armbruster]

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

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

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

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

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

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

I'm not sure I get the parenthesis.

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

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

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

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

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

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

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

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

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

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

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

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

Trace backends emit trace events.

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

[,,,]