[Spice-devel] RFC: Lightweight tracing mechanism

Tue Jun 6 14:44:16 UTC 2017

On Tue, 2017-06-06 at 15:17 +0200, Christophe de Dinechin wrote:
> 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? 

mingw client has an issue with --spice-debug, it enables it only for
spice glib library, not for spice gtk lib. Using the envar avoids the
issue

> > > 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.co
> > > m> 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 redha
> > t.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.co
> m/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
> > 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/3f80dbf0/attachment.html>