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

["Daniel P. Berrangé" <berrange@redhat.com>]

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

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.

> - 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.

> - 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".

> - 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.

Regards,
Daniel
-- 
|: https://berrange.com      -o-    https://www.flickr.com/photos/dberrange :|
|: https://libvirt.org         -o-            https://fstop138.berrange.com :|
|: https://entangle-photo.org    -o-    https://www.instagram.com/dberrange :|