[libvirt] [PATCH 00/13] Add multiple trace backend function and add new ftrace backend for libvirt

[Daniel P. Berrange]

On Mon, Mar 10, 2014 at 08:17:21AM +0000, yangzy.fnst at cn.fujitsu.com wrote:
> Backgroud:
> The existing trace mechanism in libvirt is dtrace. Although the dtrace
> can work, it's not work well enough. Every time we want get information
> from the trace point we must write a systemtap script and run it
> together with libvirt.
> 
> That's really unpractical on some occasion, especially on production
> server since the systemtap script can't be executed automatically.
> And some problems may be not easy to reproduce, then it will cost a
> lot of time to get the trace information again.
> 
> So I think it is essential to add supporting for record the trace
> information automatically in libvirt to satisfy the user's requirement.
> That's why I implemented multiple trace backend function and ftrace 
> support in libvirt.

I've looked through what this patchset does and I'm not really happy
with any of it. Comparing what we have today with what is proposed.
The current code being probed just calls a single macro unconditionally:

    PROBE(EVENT_POLL_ADD_HANDLE,
          "watch=%d fd=%d events=%d cb=%p opaque=%p ff=%p",
          watch, fd, events, cb, opaque, ff);


In src/util/virprobe.h this expands to 

    VIR_DEBUG(...fmt string..., ... and args...)
    if (LIBVIRT_EVENT_POLL_ADD_HANDLE_ENABLED())
        LIBVIRT_EVENT_POLL_ADD_HANDLE(....args...)

The upshot is that even when probes are compiled into libvirt, the
only overhead is a single call to virLogMessage, and a check of a
boolean flag to see if that probe point is enabled currently or not.
The virLogMessage function only has overhead of 2 integer comparisons
unless logging is turned on.  So our overhead with probes disabled
is 3 integer comparisons and 1 function call. This is about as low
as we can practically get, which is a good thing. The inclusion of
VIR_DEBUG statement means we can see the probe in normal debug
logs too, even if systemtap/dtrace is disabled at compile time
which is also a good thing.

With this proposed patchset the code being probed now will do a
conditional function call

#ifdef WITH_TRACE_PROBES
    trace_event_poll_add_handle(watch, fd, events, cb, opaque, ff);
#endif

So already we have cluttered up the code with #ifdef conditional
checks at every single probe location. It has all lost debug logs
when tracing is disabled at compile time which is very bad.

Now the generated function implementations are something like this:

void trace_event_poll_update_handle(int watch, int events) {
#ifdef WITH_FTRACE_PROBES
    char ftrace_buf[MAX_TRACE_STRLEN];
    int unused __attribute__ ((unused));
    int trlen;
    trlen = snprintf(ftrace_buf, MAX_TRACE_STRLEN,
                     "event_poll_update_handle " "watch=%d events=%d" "\n" , watch, events);
    trlen = MIN(trlen, MAX_TRACE_STRLEN - 1);
    unused = write(trace_marker_fd, ftrace_buf, trlen);
#endif

#ifdef WITH_DTRACE_PROBES
    LIBVIRT_EVENT_POLL_UPDATE_HANDLE(watch, events);
#endif
}


So the ftrace backend is not doing any kind of dynamic tracing at all.
It is unconditionally formatting the string + args every single time,
then writing it into a file descriptor. This is way more overhead than
we have today. I've just got to great lengths to remove all the logging
overhead when not in use, and this just goes and does something just as
bad as the old logging code we just killed. You've also lost the checks
to see if the dtrace/systemtap probes are enabled too.

AFAICT the ftrace system has no facility to dyanamically control whether
probe points are enabled or not, in userspace and no way to get at structed
data as we do with dtrace - a ring buffer of printed strings is all it
offers. If all you care about is a printable formatted string for the
probe, then libvirt already provides this by just enabling debug logs,
with the added advantage that our debug code now has almost no overhead
unless explicitly enabled. 

In addition you've copied a bunch of code out of QEMU which is licensed
under GPLv2 only. Libvirt is LGPLv2+ licensed, so this is not compatible.

I'm afraid I just don't see any compelling reason to include this ftrace
code, at least not in anything like the format it is proposed in here.

If you just want the ability to record a printable formatted string for
probes, then I'd much rather just see us improve our logging code, so
we can request that the libvirt logging system were able to ouput only
log statements associated with probe points. That's be far simpler to
do and avoid all the problems with this patchset.

Regards,
Daniel
-- 
|: http://berrange.com      -o-    http://www.flickr.com/photos/dberrange/ :|
|: http://libvirt.org              -o-             http://virt-manager.org :|
|: http://autobuild.org       -o-         http://search.cpan.org/~danberr/ :|
|: http://entangle-photo.org       -o-       http://live.gnome.org/gtk-vnc :|