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

[Christophe de Dinechin]

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)