[Spice-devel] RFC: Lightweight tracing mechanism

Tue Jun 6 14:29:01 UTC 2017

Hi

----- Original Message -----
> Answering two emails from Frediano and Marc-André that were asking closely
> related questions, to avoid duplication…
> 
> > On 6 Jun 2017, at 13:28, Frediano Ziglio <fziglio at redhat.com> wrote:
> > 
> > Would be helpful if you had recap Pavel problems. I don't remember.
> 
> I did not find it in email, so it was probably IRC. I remember something
> about having to use --spice-debug for some debug messages, and glib
> environment variables for others. Pavel, do you remember something like
> that?
>  
> >> Would you find this useful? The most difficult part being to connect that
> >> to existing tracing mechanisms to avoid replication of traces, while at
> >> the same time ensuring that the existing enabling mechanisms work as
> >> before.
> 
> > The main questions are:
> > - what are the original problems exactly?
> 
> Getting focused debug output, which to me means “conditional, cheap, always
> there". I don’t like having an “all-or-nothing” debug proposition for Spice.
> Currently, we have SPICE_DEBUG=1 or SPICE_DEBUG=0. That’s too binary. I
> would like SPICE_TRACES=channel:memory, for example.
> 
> 
> > - why your solution is good in your opinion?
> 
> 1. Conditional tracing. Except by misusing domains to identify conditions, I
> think it’s not easy to do with glib. I may be wrong, but did not find
> anything here for example:
> https://developer.gnome.org/glib/stable/glib-Message-Logging.html.

Personally, grep conditions covers 99% of my needs.

> 
> 2. Lightweight enough tracing that you can leave it there all the time. In
> this implementation, adding a trace consumes one bit in memory, testing for
> it is one memory access (plus the conditional jump, I know ;-). By contrast,
> the cost of logging in glib is quite high, which makes little sense for
> low-level debugging messages that are intended to be thrown away under
> normal use.
> 

Well, glib logging isn't meant for tracing. So it isn't used for that, and it has no performance issue for regular debugging/logging.

> 3. Scalable, and therefore as fine-grained as we need it to be. With a
> similar mechanism, Tao-3D has about 70 traces (see
> https://github.com/c3d/tao-3D/blob/master/tao/traces.tbl for the graphic
> side traces), including in highly performance-sensitive paths.

I think we have few highly performance-sensitive paths in our code, and before introducing facilities for tracing it, it would be interesting to know what you want to have traced. My feeling is that those performance traces don't need to be in public or release code, since they are usually very specific to the problem you are studying at hand, and don't need to remain checked in code.

> 4. Can be used to conditionally enable / disable code (other than tracing).
> For example, Frediano started chasing memory leaks. Let’s say he develops a
> nice way to track leaks. It’s an investment, we want to keep it. With this
> infrastructure, we could put that under -t leakcheck, and run that if we
> have a doubt about a memory leak.

Does tracing really helps with memory leak? when you have asan and valgrind, really, no.

> 5. Can be used for non-boolean values. It makes the code only marginally more
> complicated to add “tweaks”, i.e. integer values you can configure at
> run-time easily. Currently, you’d typically use environment variables or a
> configuration file for this, which expensive and not convenient. With this
> approach, add one tweak, say “max_mem”, and tweak with -t max_mem=100 to,
> say, limit allocations to 100M and detect leaks more easily.

What has this to do with tracing?

> 6. Self-documented. Using spicy -t list gives you a list of possible tweaks.
> And all messages come with a trace name prefix, so if you later want to get
> that specific message, you know what to pass to -t.
> 

I suppose it lists the various domains? or all trace points?

For the later, it's probably hard to keep it stable and without associated documentation, it isn't of much help imho.

In any case, I don't think it make sense to provide this in a user command line. Using environment variable allows to tweak any program using your library instead, and may be changed at run time.

> I don’t think glib does any of these 6 points. I may be wrong, and I am
> willing to use glib instead where it provides a sufficiently good solution.
> 
> 
> > - did you try other options (like Marc-andre' suggested) ?
> 
> Yes. Christophe F already suggested them:
> 
> >> On 23 May 2017, at 11:51, Christophe Fergeau <cfergeau at redhat.com> wrote:
> > 
> >> I think we have SPICE_DEBUG already which might make
> >> sense, another alternative would be to have a --enable-alignment-debug,
> >> or something like glib (SPICE_XXX_DEBUG=alignment:foo:bar)
> >> 
> 
> I did not find where the existing code does anything that would correspond to
> this
> SPICE_XXX_DEBUG=alignment:foo:bar (I did ask). Any pointer? In any case,
> what I saw in glib did not respond to my needs.
> 
> 
> > 
> > Reading the code is not clear where exactly you implemented the different
> > domains
> > suggested by the bug report.
> 
> I didn’t. I propose that we do something finer-grained.
> 
> 
> > Did you just coded SSL as an example?
> 
> Yes. I don’t want to convert everything if I sense that the team does not
> like it at all.
> So I only did two in common (ssl and rect) and one in gtk (channel, by
> modifying CHANNEL_DEBUG)
> 
> > Also you introduced a new "TRACE" logging level; why DEBUG was not enough?
> 
> This is transitional, to be able to distinguish preserve existing behavior
> for existing debug code
> (always go to the glib log) while TRACE code can also go to standard error.
> 
> 
> 
> > On 6 Jun 2017, at 12:54, Marc-André Lureau <marcandre.lureau at redhat.com>
> > wrote:
> > 
> > I would rather stick to glib structured logging (and have compatibility
> > code for glib < 2.50),
> 
> This does not address my problem. The structured logging is “how to log”
> (i.e. it is a replacement for “printf”). My patch set is intended to define

"structured logging" is not about "how" or "where" to log. It is about "structured" logs, that is having named fields & value that you can later filter/query. One way is through the journal, but you can implement other handlers. I don't know if your solution could fit. If it does, it would be great to propose it to glib instead.

> *what* to log and *when* (i.e. it is a special form of command-line driven
> “if”). Ultimately, my implementation uses either stderr or glib old log or
> both, but adding a structured-log option would be relatively easy (although
> in a different patch series).
> 
> I don’t think glib has command-line driven conditional logging today, beyond
> the debug, info, warning and error levels. Christophe F’s message (quoted
> above) hints at such a facility, but I did not find it.
> 

gtk+ has probably more debug and tracing needs than spice-gtk (and perhaps spice-server), yet they seem to be fine with glib facilities for now.

fwiw, gtk+ uses a simple bitflag and a macro GDK_DEBUG_CHECK() / GTK_DEBUG_CHECK() to provide conditional debugging information (only with --enable-debug iirc).

> 
> > or try to find a way to use qemu tracing facility (ftrace/lttng etc).
> 
> While it does offer some (ultra-complicated) way to do conditional logging,

but problably more powerful :) and more importantly commonly available, used and maintained. So there are probably more documentation available for those than a new solution.

Also, when tracing, you often need to consider what's happening outside of your domain, so it's quite important that the tracing facility is used by others. This is a great argument to keep using glog/glib, obviously for the gtk+ client, but also for the server that uses more and more glib/gobject/gst etc. ftrace/lttng is quite more low level and linux-specific, so probably not the best userspace solution.

> this is a kernel / server-side logging facility. I want to instrument spice
> itself (client also, not just server). I think using this kind of
> infrastructure could be done, but we are talking about something that, at
> first sight, looks two orders of magnitude more complicated to write and to
> use, only addresses some of my use-cases, and probably several times slower.
> 
> BTW, these tools also address post-mortem logging. I also have something in
> the pipe, see https://github.com/c3d/spice-gtk/compare/master...c3d:recorder
> and the associated submodule https://github.com/c3d/recorder/. But that’s
> for a later RFC. If only Linux had control-T, you would know the joy of
> hitting Control-T at your terminal window right after Spicy does something
> funny, and getting a dump of what it just did, as if you had SPICE_DEBUG to
> start with :-)
> 
> (that other patch series has a problem, that the recorder does not like
> dynamic strings, so batch-converting existing messages is more challenging).

As you can see, I am quite reluctant to adding yet another logging/tracing framework to our already (very) long list of tools/libraries. In fact, I am very happy that we killed a dependency on log4cpp some time ago in favour of glib (we were the only users in rhel at that time, and it was quite a pain to use tbh :).

thanks