[Spice-devel] RFC: Lightweight tracing mechanism

Tue Jun 6 13:17:07 UTC 2017

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.

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.

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.

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.

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.

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

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

Regards,
Christophe

> 
> Imho any improvement to logging & tracing should go to these respective projects if possible, since they have better chances to be common & maintain & with a set of tools to help you analyze with the rest of the system.
> _______________________________________________
> Spice-devel mailing list
> Spice-devel at lists.freedesktop.org <mailto:Spice-devel at lists.freedesktop.org>
> https://lists.freedesktop.org/mailman/listinfo/spice-devel <https://lists.freedesktop.org/mailman/listinfo/spice-devel>
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <https://lists.freedesktop.org/archives/spice-devel/attachments/20170606/f4bfcc5d/attachment.html>