[Spice-devel] [PATCH spice-common 0/4] RFC: add structured logging and log category

Wed Jun 14 15:06:15 UTC 2017

On Wed, Jun 14, 2017 at 10:44:49AM +0200, Christophe de Dinechin wrote:
> 
> > On 13 Jun 2017, at 12:17, Marc-André Lureau <marcandre.lureau at redhat.com> wrote:
> > 
> 
> >> - Better memory locality (not wasting a whole cache line for a single flag)
> > 
> > minor, because log is not for hot traces.
> 
> My experience differs from yours, and as a result, the idea that “log is not for hot traces" seems particularly wrong to me. In a real-time system, if your logging system cannot properly instrument the hot paths, then your logging system is at fault, not the idea of instrumenting the hot paths, and even less the idea of designing a mechanism capable of efficiently instrumenting hot paths.
> 
> Since Spice is a real-time system, it would have expected (and I really want, sooner better than later):
> 
> a) a logging system that knows how to record stuff and print it out efficiently.
> b) a tracing system that lets me view selected things as they happen, including in hot paths
> c) a flight-recorder recording information continuously and dumping useful data after specific events, e.g. crash, signal, assert, etc.
> d) performance probes, to continuously measure key things and report them
> e) a tuning / tweaking system, to adjust internal parameters, ideally on a running system, and observe the effect
> 
> As far as I can tell, only (a) logging exists today. Why don’t we have the rest? And why is there such a strong push-back from you when I suggest we add it?
> 
> If you really believe this is useless, then I have to disagree with you. To support my opinion for each category above:
> 
> a) Being able to improve logging is obviously a hot topic, meaning the current state is not considered satisfactory.
> b) commented-out calls to spice_msg_in_hexdump. Ask yourself, why is this code commented out?

I would blame that on the lack of an easy way to hide at runtime this
verbose dump by default, and reenable it when needed. Which both your
proposal and Marc André's solve.

> c) Bugs which we have to be able to reproduce, because there is no
> useful information in the debug log, e.g.
> https://bugzilla.redhat.com/show_bug.cgi?id=1017261. Here, we know an
> assertion failed, but nothing about what happened to get there, so you
> can only guess and try to reproduce. Reported in 2013, not solved, and
> probably not much progress made since then.

We can switch to Marc-André's suggestion, or we can switch to yours,
none of them will help us to solve this bug ;)
More/better logs is what _may_ help, which we could even have with the
current logging system..

> d) Performance bugs, e.g.
> https://beta-bugzilla.redhat.com/show_bug.cgi?id=1363940#c1 states
> “please provide supporting data”, but there is no easy way for the
> customer to collect objective data
> e) Frediano having to commit code adding a magic 2000 in the server to
> “try to reduce lag”, see
> https://cgit.freedesktop.org/~fziglio/spice-server/commit/?h=nvidia&id=855849d7a2b8e1968a14dcce3dd84d05f25bc702.
> 
> All these examples (only a sample, I can easily find dozen more) show
> that the need for the tools I am talking about exist.

I mostly read these examples as "our debug logs are bad", and most of
these would be helped by more logs, which filtered output facilitates
as you are not overwhelmed with too much stuff.

> 
> > 
> > This argument is probably only valid if you have a mix of categories in a very tiny context. If you switch to a single category, there shouldn't be much performance difference locally and globally.
> 
> Actually, this argument is valid for any mechanism designed to also
> instrument hot paths. The first level cache is a very precious
> commodity. Say we have 50 categories in the normal run path. With your
> approche, we use 50 unrelated cache lines with nothing else of
> interest in them (the name and description of the category being
> largely uninteresting at run time). With mine, it’s one cache line,
> with the first category test priming the cache for subsequent category
> tests, ensuring they don’t stall.
> 
> Let’s design a tracing selection mechanism that can instrument hot
> paths at minimal cost, rather than rationalize why we don’t need to
> instrument hot paths.

If it's a hot path, then the needed flag will be in a cache-line
regardless of the approach taken. If it's an actual issue, then we can
always move from one approach to the other.

At this point, I would say that any of the 2 approaches are an
improvement over the current code. I'm also unconvinced that we have to
have support for tweaks, and Marc-André's approach has the advantage
(to me) of not needing #define MAGIC_FOO(x) ... #include "foo.defs"
which I'm not a big fan of.

Once again, any of the 2 approaches would allow you to add the logs you
need with the filtering you need. And not getting tweaks/centralized
categories now does not prevent that from changing later when a concrete
compelling use case shows up ("This patch is adding XXX which we really
want to have, this cannot be done with the current infrastructure, so
this other patch is changing that", or "While debugging YYY, I needed
the logs but performance was not appropriate, this patch fixes it").

Christophe
-------------- next part --------------
A non-text attachment was scrubbed...
Name: signature.asc
Type: application/pgp-signature
Size: 801 bytes
Desc: not available
URL: <https://lists.freedesktop.org/archives/spice-devel/attachments/20170614/7221ff1f/attachment.sig>