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

Wed Jun 14 17:53:04 UTC 2017

Hi

----- Original Message -----
> >> 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..
> 
> In the message above, part c) is having a flight recorder that, AFTER we
> crash, dumps something that was recorded BEFORE the crash. Below is an
> example output from my current experimental branch
> (https://github.com/c3d/spice-gtk/compare/master...c3d:recorder). What I did
> is send a SIGBUS to the process with killall while it was running (please
> check if you can figure that out from the dump :-), but of course the same
> thing would happen with a real crash.
> 
> The key point I was making with my example for (c) is is that if we had this
> amount of information in case of crash, in many cases we would not need to
> re-do a run with some debug option, or reproduce the problem. The
> information would already be right there. And I would like you to compare
> the amount of available information available today (the lines beginning
> with (spicy:78043) with the amount of information the recorder dump gives me
> (the rest).

(fwiw, I prefer the shorter version...)

> 
> ddd at ptitpuce[recorder] spice-gtk> spicy  -h turbo -p 5901
> 
> (process:78043): Gtk-WARNING **: Locale not supported by C library.
> 	Using the fallback 'C' locale.
> 2017-06-14 18:57:01.165 spicy[78043:24824016] *** WARNING: Method
> userSpaceScaleFactor in class NSView is deprecated on 10.7 and later. It
> should not be used in new applications. Use convertRectToBacking: instead.
> ** Message: main channel: opened
> 
> (spicy:78043): GSpice-CRITICAL **: spice_playback_channel_set_delay:
> assertion 'SPICE_IS_PLAYBACK_CHANNEL(channel)' failed
> 
> (spicy:78043): GLib-GObject-CRITICAL **: g_object_get: assertion 'G_IS_OBJECT
> (object)' failed
> 
> (spicy:78043): GLib-GObject-CRITICAL **: g_object_unref: assertion
> 'G_IS_OBJECT (object)' failed
> 
> (spicy:78043): GLib-GObject-CRITICAL **: g_object_get: assertion 'G_IS_OBJECT
> (object)' failed
> 
> (spicy:78043): GLib-GObject-CRITICAL **: g_object_unref: assertion
> 'G_IS_OBJECT (object)' failed
> 
> (spicy:78043): Spice-WARNING **: channel-display-gst.c:339:create_pipeline:
> GStreamer error: pas d??l?ment ??vp8dec??
> 
> (spicy:78043): Spice-WARNING **: channel-display-gst.c:339:create_pipeline:
> GStreamer error: pas d??l?ment ??vp9dec??
> 
> (spicy:78043): Spice-WARNING **: channel-display-gst.c:339:create_pipeline:
> GStreamer error: pas d??l?ment ??vp8dec??
> 
> (spicy:78043): Spice-WARNING **: channel-display-gst.c:339:create_pipeline:
> GStreamer error: pas d??l?ment ??vp9dec??
> 
> (spicy:78043): Gdk-WARNING **: GdkQuartzDisplay does not implement the
> monitor vfuncs
> Received signal 10, dumping recorder
> 0 [0.000000:0x103efd9ec] MAIN: spicy starts with 5 args
> 1 [0.000011:0x103efda17] MAIN: Installing signal handlers

(snip the long log, thanks)

> > 
> >> 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.
> 
> I’m sorry if I’m being dense here, but I insist, there are 5 different
> things, only one of them is logs:
> 
> a) logs
> b) trace selection
> c) flight recorder
> d) performance probes
> e) tweaks
> 
> Of these, my RFC addresses b and e, the “recorder” branch is WIP to address
> c, and I have yet-unpublished work for d.

Can we please focus on b) log filtering? let's avoid side-track discussions.

> 
> > 
> >> 
> >>> 
> >>> 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.
> 
> You are reasoning on one flag, the only case where it’s the same. If your hot
> path tests N categories, then it’s N cache lines versus something like
> N/512.
> 

This is unrealistic, if you trace something hot, you are in a single domain, or you make it use a single (sub)domain.

> > 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.
> 
> That’s the trade-off for DRY (don’t repeat yourself) vs. WET (write
> everything twice, or we enjoy typing).

What I propose is to have a single definition line in most cases, there is no duplication. If you need to share it in multiple units, it follows the traditional C declaration/definition. And if deemed better, we can switch to you #include trick, but I am against it, as it's better to declare the domain where it's actually used, and do not trigger whole-codebase compilation on change.

> I agree this is a bit hacky, though in my opinion less complex than, say, the
> python marshalling generators, which play a similar role of automating some
> code generation.

I hope you can make it simpler than the python generator ;)

It generates some units to build and has few invert-dependencies, it's not included in the whole code base. (a far-stretched comparison tbh)