Re: [PATCH v2 3/3] trace: Example of "centralized" recorder tracing

[Christophe de Dinechin <dinechin@redhat.com>]

On 2020-07-03 at 15:08 CEST, Daniel P. Berrangé wrote...
> On Fri, Jul 03, 2020 at 12:12:14PM +0200, Christophe de Dinechin wrote:
>>
>> On 2020-07-02 at 15:47 CEST, Stefan Hajnoczi wrote...
>> > On Wed, Jul 01, 2020 at 05:15:01PM +0100, Daniel P. Berrangé wrote:
>> > At most it should require an
>> >> extra annotation in the trace-events file to take the extra parameter
>> >> for grouping, and other trace backends can ignore that.
>> >
>> > It's true, it may be possible to put this functionality in the
>> > trace-events.
>>
>> Let me think more about integrating these features with other trace
>> backends. See below for short-term impact.
>>
>> > Christophe: how does this differ from regular trace events and what
>> > extra information is needed?
>>
>> - Grouping, as indicated above, mostly useful in practice to make selection
>>   of tracing topics easy (e.g. "modules") but also for real-time graphing,
>>   because typically a state change occurs in different functions, which is
>>   why I used locking as an example.
>
> In many cases we already have a form of grouping via the backdoor by
> using a common string prefix on trace point names. eg
>
> qio_task_new(void *task, void *source, void *func, void *opaque) "Task new task=%p source=%p func=%p opaque=%p"
> qio_task_complete(void *task) "Task complete task=%p"
> qio_task_thread_start(void *task, void *worker, void *opaque) "Task thread start task=%p worker=%p opaque=%p"
> qio_task_thread_run(void *task) "Task thread run task=%p"
> qio_task_thread_exit(void *task) "Task thread exit task=%p"
> qio_task_thread_result(void *task) "Task thread result task=%p"
> qio_task_thread_source_attach(void *task, void *source) "Task thread source attach task=%p source=%p"
> qio_task_thread_source_cancel(void *task, void *source) "Task thread source cancel task=%p source=%p"
>
> We could turn this into an explicit multi-level grouping concept,
> using "." separator for each level of the group. eg

Interesting idea.

>
> qio.task.new(void *task, void *source, void *func, void *opaque) "Task new task=%p source=%p func=%p opaque=%p"
> qio.task.complete(void *task) "Task complete task=%p"
> qio.task.thread_start(void *task, void *worker, void *opaque) "Task thread start task=%p worker=%p opaque=%p"
> qio.task.thread_run(void *task) "Task thread run task=%p"
> qio.task.thread_exit(void *task) "Task thread exit task=%p"
> qio.task.thread_result(void *task) "Task thread result task=%p"
> qio.task.thread_source_attach(void *task, void *source) "Task thread source attach task=%p source=%p"
> qio.task.thread_source_cancel(void *task, void *source) "Task thread source cancel task=%p source=%p"
>
>
> For backends that dont support groups, the "." can be turned back
> into a "_", and everything is unchanged. For backends that do support
> groups, we now have the info required.
>
> This would be useful for the systemtap backend because that has an
> explicit grouping concept already. ie we have probes definitions
> like:
>
> probe qemu.system.x86_64.qio_task_new = process("/usr/bin/qemu-system-x86_64").mark("qio_task_new")
> {
>   task = $arg1;
>   source = $arg2;
>   func = $arg3;
>   opaque = $arg4;
> }
>
>
> which we can now turn into
>
> probe qemu.system.x86_64.qio.task.new = process("/usr/bin/qemu-system-x86_64").mark("qio_task_new")
> {
>   task = $arg1;
>   source = $arg2;
>   func = $arg3;
>   opaque = $arg4;
> }
>
>
> the generated C trace macro would still use "_" not "." of course
> so  qio_task_new(src, func, opaque)
>
>> - Self-documentation. Right now, the recorder back-end generates rather
>>   unhelpful help messages.
>
> Not sure I understand the problem here.

RECORDER_DEFINE specifies a text that is listed when you pass "help" as a
trace name. There is no equivalent concept that I'm aware of in the existing
qemu trace infrastructure.

>
>> - Trace buffer size. This is important to make post-mortem dumps usable if
>>   you record infrequent events alongside much higher-rate ones. For example,
>>   you may want a large buffer to record info about command-line option
>>   processing, the default 8 is definitely too small.
>
> Sure, that's a problem for all the trace backends. They all need to be
> good at filtering / controlling what probes are fired to avoid signal
> getting lost in noise.  The grouping feature would certainly help with
> that making it easier to control what it turned on/off.

Well, for the recorder it's a slightly different problem. When you do a
recorder post-mortem dump, entries are sorted and printed at that time. THis
makes it possible to have a number of recent traces for high-frequency
events, as well as some much older traces for low-frequency events.

For example, you can have a buffer that records command-line options, and
another that records events that occur typically once per second, and yet
another that records high-frequency events. Then, when your program crashes
and you look at a dump, you see a context that includes both recent
high-frequency stuff as well as much older low-frequency events.

See https://gitlab.com/c3d/recorder for examples.


>
>> - Support for %+s, which tells that a string is safe to print later (e.g. it
>>   is a compile-time constant, or never ever freed).
>
> Seems we should be able to support that in the trace-events format string.
> Any other backend can turn "%+s" back into a normal "%s".

Yes, but it's much more complicated than this simple patch series ;-) As is,
the goal of this series is to not touch any other back-end.

>
>> - Support for custom formats, e.g. I use %v in the XL compiler for LLVM
>>   value pointers. This is a bit more advanced, but it would be neat to be
>>   able to print out QOM objects using %q :-)
>
> Seems like a similar trick can be used here. The %v/%q could be turned
> back into a plain %p for backends which don't have the pretty-printing
> support.

Sure, but this is also touching the rest of the tracing infrastructure,
which was a definite non-goal for this specific series.

>
> Regards,
> Daniel


--
Cheers,
Christophe de Dinechin (IRC c3d)